...

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

...

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, med undtagelse af accesslog, som har personfølsomme data (minlog2_lookupidws_test900_500_run1.tar.gz)

JMeter log

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

...

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. 

...

Cpu forbruget på docker02 bør tjekkes, hvorfor det ikke falder igen.

Konklusion

MinLog2 - Performancetest rapport medhjælper lookup

Performance testen består af en række kald til opslag efter logninger på forskellige cpr numre i medhjælper loggen. Et sådant enkelt opslag vil svare til en læge, der vil verificere, hvilke logninger en given medhjælper har givet anledning til.

Testen udført er komponent "minlog2", testplan "lookup_onbehalfof" og distribution "test900_500".

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

De rå test resultater er vedhæftet denne side (minlog2-lookup_onbehalfof_test900_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 log

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

...

Iteration

...

Tråde

...

Nodes

...

Starttid

...

Sluttid

...

Throughput 

(kald per sekund)

...

Faktisk

forbedring

...

Mål

forbedring

...

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

• Througput for servicen:
  • max throughput på testen blev aldrig nået. Så det bedste tal er 112.02 kald per sekund
  • servicen kører bedst ved iteration 9, med et throughput på 103, 9 kald per sekund
• Svartid for servicen:
  • for 95 % percentil: under 0,8 sekund
  • for 98 % percentil: under under 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. Den ene server tager et spring i sidste iteration, men ellers ser det fornuftigt ud.
• io på netværk:
  • stiger over tid, hvilket er forventet
• Hukommelses forbrug:
  • servicen håndterer brug af hukommelse fint.
  • 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 og dermed stiger hukommelses forbruget ikke over tid. Dette er et tegn på, at vi ikke har memory leaks.

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

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

Analysen har et enkelt punkt, der eventuelt skal undersøges nærmere. I iteration 10, viser den ene server lidt afvigende opførsel på cpu forbrug. Den stiger mere end tidligere og falder ikke til samme lave niveau, som tidligere efter endt iteration.

MinLog2 - Performancetest rapport medhjælper lookup

Performance testen består af en række kald til opslag efter logninger på forskellige cpr numre i medhjælper loggen. Et sådant enkelt opslag vil svare til en læge, der vil verificere, hvilke logninger en given medhjælper har givet anledning til.

Testen udført er komponent "minlog2", testplan "lookup_onbehalfof" og distribution "test900_500".

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 log

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

Det fremgår også af filen, at den endelige måling af throughput er 50,03 kald per sekund.

Samt at fejlprocentet på den fulde kørsel er 0,02 %. 

Throughput falder mellem iteration 4 og 5 samt 6 og 7. Og der er en forøgning af fejl i iteration 5.

Access log

Denne log findes for hver applikations server (docker container).

Her findes data for hvert enkelt kald, der er lavet til minlog servicen, herunder hvor lang tid et kald har taget (Duration), samt hvornår kaldet er udført. Ud fra loggens data kan man også beregne, hvor mange kald der udføres i en given periode. 

De følgende 2 grafer viser 95 % hendholdsvis 98 % percentil for kaldende. Grupperingen er 10 minutter:

Image AddedImage Added

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

Den næste graf viser antal kald per sekund:

Image Added

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å Docker01, som fik problemer  ved iteration 5 har dog ingen kald i de sidste 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 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.

...

Det fremgår også af filen, at den endelige måling af throughput er 50,03 kald per sekund.

Samt at fejlprocentet på den fulde kørsel er 0,02 %. 

Throughput falder mellem iteration 4 og 5 samt 6 og 7. Og der er en forøgning af fejl i iteration 5.

Access log

Denne log findes for hver applikations server (docker container).

Her findes data for hvert enkelt kald, der er lavet til minlog servicen, herunder hvor lang tid et kald har taget (Duration), samt hvornår kaldet er udført. Ud fra loggens data kan man også beregne, hvor mange kald der udføres i en given periode. 

De følgende 2 grafer viser 95 % hendholdsvis 98 % percentil for kaldende. Grupperingen er 10 minutter:

Image RemovedImage Removed

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

Den næste graf viser antal kald per sekund:

Image Removed

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å Docker1, som fik problemer sidst i testen har dog ingen kald i de siste 3 iterationer.

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

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.

...

• Througput for servicen:
  • max throughput på testen er 6,25 kald per sekund (dvs 3125 registreringer per sekund, da et kald indeholder 500 registreringer)
  • servicen kører bedst ved et throughput på 4,19 kald per sekund (2095 registreringer per sekund).
• Svartid for servicen:
  • kravet er 95% skal være under 6,5 sekund og 98 % under 15,5 sekund. Dette
  • dette opnåes i iteration 1, 2 og 4.
• Cpu status:
  • cpu forbruget stiger lidt over test perioden, som registration servicen presses mere.
• io på netværk:
  • stiger over tid, hvilket er forventet. input på docker02 for kafka consumer stiger dog rigtig meget
• Hukommelses forbrug:
  • servicen håndterer brug af hukommelse fint.
  • at der er dobbelt så meget hukommelse på kafka-consumer docker02 end på docker01 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 og dermed stiger hukommelses forbruget ikke over tid. Dette er et tegn på, at vi ikke har memory leaks.
• Kafka Consumer Lag:
  • for hver iteration viser de lokale kafka instancer tegn på, at lag stiger. Den centrale kafka opbygger en del lag.

...