...

Dette dokument indeholder analyse af log data fra den anden performance test, som er kørt for Minlog2. Den indeholder en analyse af de log data, som er samlet op under test kørslenTestene er kørt december 2020. Analysen dækker

• MinLog2 - Performancetest rapport borger lookup
• MinLog2 - Performancetest rapport medhjælper lookup
• MinLog 2 - Performancetest rapport registration

...

Der er lidt løbende skriv til disken mens testen kører

Vurdering

Der er generlt intet negativt at bemærke omkring cpu forbruget eller io. Dog er der lidt afvigelse i mønstret for cpu forbruget i iteration 10.

Jstat log

Denne log findes for hver applikations server (docker container). Loggen viser resultatet af kommandoen jstat. Jstat siger noget om, hvordan JVM'en har det. 

...

MinLog 2 service er version 2.0.45 og NSP standard performance test framework version 2.0.27.

Der er kørt 2 servere med lookup komponenten (se iøvrigt figur i performance testvejledningen afsnit 2.2.2.1).

De rå test resultater er vedhæftet denne side (minlog2-_lookup_onbehalfof_test900_500_run1.tar.gz)

Indledningsvis skal siges, at servicen kørende på docker01 gik i fejl i 5 iteration pga memory problemer. Der mangler derfor access log data sidste del af testen for docker01.

...

JMeter hoved filen beskriver overordnet testens resultat. Her kan ses, at der er kørt 5 iterationer med 7 iterationer med test, belastningen i form af tråde og nodes, deres tidsinterval , throughput, forbedring og fejlprocent for hver:

...

Det ses af graferne, at jo flere nodes/tråde jo højere bliver svar tiden overordnet set. Og især til sidstved iteration 5, hvor den ene server er gået i stå, stiger svartiderne for den anden, der stadig kører.

...

Af grafen fremgår det, at jo flere nodes og tråde (disse øges over tid, per iteration) jo flere kald kommer der igennem per sekund overordnet set.

Servicen kørende på Docker1Docker01, som fik problemer sidst i testen problemer  ved iteration 5 har dog ingen kald i de siste 3 iterationersidste 2,5 iteration.

Vurdering

Performance kravene

• under 2,50 sekund for 95 % af tilfældende; dette overstiges ifølge "95 % percentil grafen" ikke. Max svartiden er her under 1,8 sekund (1800 ms)
• under 5,5 sekund for 98 % af tilfældende; dette overstiges ifølge "98 % percentil grafen" ikke. Max svartiden er her under 2,1 sekunder (2100 ms)

Vi er inden for performance kravene i testen fulde køretid, selv i de test iterationer, hvor den ene af de testede service stoppede.

Vmstat log

Image RemovedImage Removed

Image RemovedImage Removed

Vurdering

Jstat log

Image RemovedImage Removed

Vurdering

Docker stats log

Image RemovedImage Removed

Image RemovedImage Removed

Image RemovedImage Removed

Vurdering

Konklusion

performance kravene i testen fulde køretid, selv i de test iterationer, hvor den ene af de testede service stoppede og den anden måtte arbejde selv..

Vmstat log

Denne log findes for hver applikations server (docker container). Den viser resultatet af kommandoen vmstat

Udtræk omkring cpu fra denne log vises i de følgende grafer:

Image AddedImage Added

Data serier i grafen er:

• cpuNonKernel (rød): tid brugt på non-kernel opgaver
• cpuKernel (blå): tid brugt på kernel opgaver
• cpuIdle (grøn): tid brugt på ingenting
• cpuWaitIO (gul): tid brugt på at vente på i/o
• iterationerne (sort) er en cirka placering, da wmstat loggen ikke indeholder tidstempel

Man kan se at cpuIdle og cpuNonKernel påvirkes som servicen presses mere. cpuIdle ligger lavere over tid, mens cpuNonKernel grafen ligger højere over tid. 

Hen ved testens 5. iteration sker der dog en stor ændring i dette mønster. Her stiger cpuNonKernal fra at ligge under 50 % til at komme over og til sidst ramme 90 %. For docker01 vedkommende stiger den meget brat og rammer næsten 100 %.

Udtræk omkring io læs og skriv fra vmstat vises i de følgende grafer:

Image AddedImage Added

Data serier i grafen er:

• ioBlockRead (rød): læsning på disk (blokke)
• ioBlockWrite (blå): skriving  på disk (blokke)
• iterationerne (sort) er en cirka placering, da wmstat loggen ikke indeholder tidstempel

Der er løbende skriv til disken mens testen kører.

Vurdering

Cpu forbruget i 5. og efterfølgende iterationer kan give grund til bekymring.

Jstat log

Denne log findes for hver applikations server (docker container). Loggen viser resultatet af kommandoen jstat. Jstat siger noget om, hvordan JVM'en har det. 

Udtræk omkring hukommelse og garbage collection fra denne log vises i de følgende grafer:

Image AddedImage Added

Data serier i grafen er:

• YGC (rød): young generation garbage collection events, antal af "ung" garbage collection siden start
• FGC (blå): full garbage collection events, antal af fuldstændig garbage collection siden start
• HeapU (gul): består af S0U+S1U+EU fra jstat loggen. Young generation memory utilization. "Ung" hukommelses forbrug
• HeapC (grøn): består af S0C+S1C+EC fra jstat loggen. Young generation memory capacity. "Ung" hukommelses kapacitet
• OU_MB (pink): old space utilization. "Ældre" hukommelses forbrug
• OC_MB (tyrkis): old space capacity. "Ældre" hukommelses kapacitet er konstant på 1.398.272 KB. 
• Iterationer (sort) er baseret på det tidstempel, som findes i jstatloggen

For docker02 er der kørt full garbage collection (FGC) 18 gange under testen. Docker01 kører  full garbage collection 513 gange.

Der er en svag stigende tendens på den ældre hukommelse (OU_MB). Og fra iteration 5, stiger den en del, især for docker01, hvor den faktisk rammer loftet på 1.398.272 KB, og ikke kører længere.

Der køres ofte garbage collection på den yngre hukommelse, hvilket holder HeapU - yngre hukommelses forbrug - nede så den kun svinger inden for et konstant interval. 

Vurdering

Det giver anledning til bekymring at den ældre hukommelse rammer loftet ved øget pres og får servicen til at gå ned.

Docker stats log

Denne log findes for hver applikations server (docker container). Loggen viser resultatet af kommandoen docker stats. Docker stats siger noget om, hvordan containeren forbruger sine ressourcer.

Udtræk omkring hukommelse, cpu og netværkstrafik vises i følgende grafer.

Hukommelse:

Image AddedImage Added

Data serier i grafen er:

• memoryUsage (rød): den totale mængde hukommelse containeren bruger
• memoryLimit (blå): den totale mængde hukommelse contaneren kan bruge

Den forbrugte hukommelse er meget stabil indtil iteration 5, hvor den stiger og derefter er stabil igen.

Cpu og hukommelse procent:

Image AddedImage Added

Data serier i grafen er:

• cpuPct (rød): hvor mange procent af hostens cpu containeren bruger
• memoryPct (blå): hvor mange procent af hostens hukommelse containeren bruger

Servicen viser et stabilt forbrug af hukommelse i starten af testen, men igen ses en stigning ved iteration 5.

Den envendte cpu er svagt stigende som servicen bliver presset. Og fra 5. iteration laver både docker01 og docker02 høje spring i cpu forbruget.

Netværk:

Image AddedImage Added

Data serier i grafen er:

• netIn (rød): den mængde data som er modtaget af containeren over netværket
• netOut (blå): den mængde data som er sendt ud af containeren over netværket

De 2 grafer for ind- og udsendt data følges ad, hvilket er forventeligt; indkomne kald skaber trafik til database og igen retur til kalder. netOut stiger mest. Dog flader docker02 ud i iteration 5 og har ikke mere trafik, efter servicen er stoppet.

Vurdering

Disse log data viser igen den øgede cpu og hukommelsesforbrug fra iteration 5 i testen. 

Konklusion

Efter at have analyseres data fra performance testen kan følgende trækkes frem:

• Througput for servicen:
  • throughput på testen er 50,03 kald per sekund.
  • servicen kører bedst ved iteration 4, med et throughput på 37,42 kald per sekund
• Svartid for servicen:
  • for 95 % percentil: under 1,8 sekund
  • for 98 % percentil: under under 2,1 sekund
  • kravene på under 2,5 henholdsvis 5,5 sekunder er overholdt
• Cpu status:
  • cpu forbruget stiger over test perioden, som servicen presses mere. I iteration 5 kommer den ene server i problemer med cpu forbruget
• io på netværk:
  • stiger over tid, hvilket er forventet
• Hukommelses forbrug:
  • servicen ser ud til at få problemer med hukommelsen når den presses
  • at der er dobbelt så meget hukommelse på på den ene server, burde ikke have nogen konsekvenser for testen, da Wildfly’en er sat op til at køre med 2 GB begge steder
• Garbage collection:
  • servicen kører jævnligt garbage collection
  • noget kunne tyde på, at når servicen bliver presset, kan garbage collection ikke helt få ryddet op

Ser man på graferne over de forskellige iterationer, er iteration 4 den, som ser sundest ud. Den overholder kravene til svartider, belastning på cpu og memory ser fornuftigt ud.

Iteration 4 har 37,42 kald per sekund . Dette bliver til ca. 23 mio kald på en uge. Det er hvad test setup’et kunne håndtere uden at vise tegn på problemer.

Performance testen er designet til at presse en service mere og mere. Medhjælper lookup viser en svaghed, når den presses og når til iteration 5, som er 17 tråde og 2 nodes. Det bør undersøges, hvordan denne belastning ligger i forhold til, hvad der forventes i drift, for at vurdere, om det vil blive et faktisk problem.

Den kraftige forøgelse af cpu og hukommelses forbrug bør undersøges. Kombinationen kunne måske tyde på loop. Dette bør undersøges nærmere i andre log filer eller en fokuseret test rettet mod dette.

Da testen bliver afbrudt i mangel på hukommelse, viser den ikke, om vi faktisk har nået det maksimale throughput den ellers ville have kunnet yde. Allokering af mere hukommelse til servicen kunne afhjælpe dette.

MinLog2 - Performancetest rapport registration

...

Det ser ud til at, kafka consumer har haft mest at lave på docker02, so så presset på de 2 servere har været skævt fordelt.

...