Indhold

Indledning

Dette dokument indeholder analyse af log data fra den anden performance test, som er kørt for Minlog2. Testene er kørt december 2020. Analysen dækker

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

Minlog1 lookup er denne gang undladt da dette interface udfases.

Detaljer omkring performance test vejledningen findes  her. Her kan læses omkring de log filer, som ligger til grund for analysen, hvilket scope testen er kørt i, hvordan test er kørt og hvilke krav, der er til komponenten under test.

Se iøvrigt krav til performance test og rapport på siden https://www.nspop.dk/display/public/web/Performancekrav

Læsevejledning

Læseren forventes at have kendskab til National Sundheds-IT's platform NSP, samt generelt kendskab til WildFly applikation server, MariaDB, Kafka og java.

Dokumenthistorik

Definitioner og forkortelser

MinLog2 - Performancetest rapport borger lookup

Performance testen består af en række kald til opslag efter logninger på forskellige cpr numre. Et sådant enkelt opslag vil svare til, hvad en borger vil udføre, skulle han ville se, hvad der er registreret om ham.

Testen udført er komponent "minlog2", testplan "lookupidws" 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, 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 10 iterationer med test, belastningen i form af tråde og nodes, deres tidsinterval , throughput og forbedring for hver:

Test kørslen nåede aldrig sit maksimum, da test frameworket løb tør for nodes at starte op.

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:

Det ses af graferne, at svartiden ikke ændrer sig med flere nodes/tråde.

Den næste graf viser antal kald per sekund:

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. 

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 0,8 sekund (800 ms)
• under 5,5 sekund for 98 % af tilfældende; dette overstiges ifølge "98 % percentil grafen" ikke. Max svartiden er her under 1 sekund (1000 ms)

Vi er inden for performance kravene i testens fulde køretid.

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:

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. Den generelle flyt af kurverne er dog ikke faretruende, taget i betragtning det load, der er kørt med over 10 iterationer. Dog skal noteres at docker02 i sidste iteration laver et hop i forbrug af cpu.

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

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 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. 

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

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

Det kan være lidt svært at se graferne for full garbage collection (FGC). Kigger man nærmere på datagrundlaget bag graferne, ses det, at der er kørt full garbage collection for servicen 2 gange under testen. 

Der er en meget svag stigende tendens på den ældre hukommelse (OU_MB). Man må gå ud fra, at kommer den op på en kritisk grænse, da vil systemet køre en full garbage collection (FGC).

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

Den yngre forbrugte hukommelse eskalerer ikke. Garbage collecteren gør sit arbejde.

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:

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. Det ser dog ud til, at docker01 har dobbelt så meget hukommelse til rådighed som docker02.

Cpu og hukommelse procent:

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. Den envendte cpu er stigende som servicen bliver presset. Og docker02, tager et større hop i den sidste iteration. Og samme server falder aldrig til niveau det lave niveau igen. Men bliver svingende mellem 150 og 100 %. Også hvis man kigger i loggens data længere frem end ovenstående graf.

Netværk:

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.

Vurdering

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

Konklusion

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:

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:

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:

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:

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:

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:

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:

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:

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

Performance testen består af en række kald til registrering af minlog2 data med forskellige cpr numre. I den kørte test, er der 500 registreringer per kald. Sidst, der blev kørt performance test for registration, var der kun een registrering per kald. Så for hvert kald der laves, er der mere arbejde at udføre denne gang.

Testen, som er udført, er komponent "minlog2", testplan "registration" og distribution "test300_500".

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

Der analyseres access og stats log fra registration komponenten, samt stats log fra kafka-consumer komponenten. Derudover ses der på kafka consumer lag for begge.

Der har kørt 2 servere med registration komponenten (cnsp), og 2 servere med consumer komponenten (backoffice - bo). Kafka har kørt med 12 partitioner både lokalt og centralt. Der har kørt 12 consumers på hver server (se iøvrigt figur i performance testvejledningen afsnit 2.2.2.1).

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

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:

Det fremgår også af loggen, at den endelige måling af throughput er 6,25 kald per sekund.

Access log data

Denne log findes for hver applikations server (docker container) hvor registration komponenten har kørt.

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. 

Følgende tabel viser en række beregnede data fra access loggen fordelt på applikations server (container) og test iteration. Nederst i tabellen er tallene for hver applikations server lagt sammen. Test iteration er beregnet ved at sammenligne tidstempel fra access log med start og sluttidspunktet for iterationen. 

De beregnede data er antal kald, kald per sekund i gennemsnit (hver iteration er 300 sekunder) samt tidsforbrug per kald i millisekunder. Derudover er antal kald der tager 6,5 sekund eller mere samt 15,5 sekund eller mere talt sammen for at kunne vurdere performance kravene.

Udtræk af antal kald fordelt over testens løbetid vises i følgende grafer:

Data serier i grafen er:

• NoOfCalls (rød): det gennemsnitlige antal kald hvert minut
• De 5 iterationer (sort) er baseret på det tidstempel, som findes i access loggen

Udtræk af svartid fordelt over testens løbetid vises i følgende grafer:

Data serier i grafen er:

• DurationAverage (rød): den gennemsnitlige svartid (sekund) for hvert minut
• De 5 iterationer (sort) er baseret på det tidstempel, som findes i access loggen

Vurdering

Af tabel og grafer fremgår det, at jo flere nodes og tråde (disse øges per iteration) jo flere kald kommer der igennem per tidsenhed. 

Der er en stigende tendens af svartiden som antallet af nodes/tråde øges. Og i den sidste iteration (5) er den meget højere end i starten af kørslen.

Performance kravene er

• under 6,50 sekund for 95 % af tilfældende, dvs. maks 5 % over
• under 15,5 sekund for 98 % af tilfældende, dvs. maks 2 % over

Kravet med maks 2 % over 15,5 sekund overholdes. Der er ingen med så høj en svartid. Derimod overholdes kravet omkring maks 5 % over 6,5 sekund ikke i flere af iterationerne. Iteration 3 har 14 % over 6,5 sekund i svartid, og iteration 5 er helt oppe på næsten 40 % over 6,5 sekund svartid. Regnes der lidt på tallene, kan det ses, at sætter man en grænse på 9,2 sekund per kald, er der under 5 %, der overskrider dette.

Vmstat log

Denne log findes for hver applikations server (docker container). Både for registration og kafka-consumer. Den viser resultatet af kommandoen vmstat.

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

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

Registration:

• cpuIdle og cpuNonKernel påvirkes lidt som servicen presses mere. cpuIdle ligger lavere over tid, mens cpuNonKernel grafen ligger en smule højere over tid.
• Der er en del udsving på kurverne undervejs.

Kafka-consumer:

• cpuIdle og cpuNonKernel ligger nogenlunde konstant over iterationerne.

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

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

Registration:

• Der er løbende skriv til disken mens testen kører, og i iteration 2-4 mest. 

Kafka-consumer:

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

Vurdering

Registration komponenten er i de sidste iterationer oppe at bruge 75-80 % af CPU’en. Og sammenligner man med den sidste performance test, ligger den noget højere. Men der skal også for hvert kald nu håndteres 500 registreringer mod før 1. Men der er stadig processer kraft til overs.

Jstat log

Denne log findes for hver applikations server (docker container). Både for registration og kafka-consumer. 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:

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

Registration: 

• Der er en svag stigning i full garbage collection (FGC). Kigger man nærmere på datagrundlaget bag graferne, ses det, at der kørt full garbage collection for servicen under testen 32 (docker01) henholdsvis 33 (docker02) gange i starten af første iteration.
• Den ældre hukommelse (OU_MB) ligger og svinger op og ned mens garbage collectoren holder den i skak, så den aldrig når sit maks (OC_MB)
• 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. 

Kafka-consumer:

• Her er der ikke kørt fuld garbage collecion (FGC) under testen.
• Der er ikke brug for at køre meget garbage collection på den yngre hukommelse, og den yngre hukommelse (HeapU) holdes nede. Der ses dog et forskelligt mønster for de 2 servers yngre hukommelse, hvor der køres dobbelt så meget carbage collection på docker02, med dertilhørende oftere udsving i HeapU.

Vurdering

Både den yngre og ældre forbrugte hukommelse eksalerer ikke. Garbage collecterne gør sit arbejde. Noget kunne tyde på, at kafka-consumer docker02  laver noget mere end docker01.

Docker stats log

Denne log findes for hver applikations server (docker container). Både for registration og kafka-consumer. Loggen viser resultatet af kommandoen docker stats. Docker stats siger noget om, hvordan containeren forbruger sine ressourcer.

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

Hukommelse:

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

Registration:

• Den forbrugte hukommelse er meget stabil, dog med et lille udsving ca. ¼ henne i testen

Kafka-consumer:

• Den forbrugte hukommelse er meget stabil. Det ser dog ud til, at docker01 har dobbelt så meget hukommelse til rådighed som docker02

Cpu og hukommelse procent:

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

Registration:

• Servicen viser stabilt forbrug af hukommelse, igen med et lille hop ca. ¼ henne i testen.
• Den envendte cpu er stigende som servicen bliver presset. Der sker en større forøgning mellem iteration 3 og 4. Inden for en iteration ser cpu belastningen ud til at være størst først i iteratioen.

Kafka-consumer:

• Både forbruget af hukommelse og cpu er stabilt igennem testen. Dog har docker02 klart mest at lave.

Netværk:

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

Registration:

• De 2 grafer for ind- og udsendt data stiger. Indkommen trafik stiger mest

Kafka-consumer:

• For docker01 stiger de 2 grafer for ind- og udsendt data svagt og følges ad. På docker02 stiger begge grafer noget mere, og netIn stiger enddag rigtig meget.

Vurdering

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

Kafka consumer lag

Denne log findes for hver applikations server (docker container). Både for registration og kafka-consumer. 

For registration fortæller loggen noget om, hvor hurtigt mirrorMaker  er til at tage fra på den "lokale" kafka og lægge ting over i  den centrale kafka på backoffice. For kafka-consumer fortæller den noget om, hvor hurtigt, der tages fra på den centrale kafka og ned i databasen.  Lag er forskellen mellem de data, som bliver produceret (producer) til kafka og forbrugt (consumer) fra kafka køen.

Udtræk omkring registerings komponentens kafka og lag i løbet af testen:

Data serier i grafen er lag fordelt per partition 0-11.

Registeringskomponentens kafka har 12 partitioner, og man kan se at lag stiger som testen skrider frem. Især i de senerer iterationer når lag ikke at komme ned inden ny data får den til at stige igen. Dog falder den hurtigt til 0, når testen er overstået.

Udtræk omkring den centrale kafka og lag i løbet af testen:

Data serier i grafen er lag fordelt per partition 0-11.

Den centrale kafka har 12 partitioner, og man kan se, at lag stiger som testen skrider frem. Det tager over en time før det sidste lag er væk efter testen.

Vurdering

Registrering komponentens kafka har det bedst før iteration 4. Herefter kan læsningen ikke rigtig følge med input. Den centrale kafka er generelt presset og er længe om at få det sidst lag væk.

Konklusion

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

• 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 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.

Denne rapport viser resultatet, når der sendes 500 registreringer ind per kald. Ændres dette antal, kan konklusionerne ændre sig.

Der ses en tendens til, at kafka-consumer docker02 har arbejdet hårdest. Kafka er sat op med 12 partitioner. Og der har været sat 12 consumers op i minlog per server. Dvs 24 ialt. Der har derfor været rigeligt consumers til rådighed, og dem på docker 02 er så blevet valgt. At sætte 6 consumers op per servere ville nok fordele workloaded bedre på de 2 backoffice servere.

Ser man på graferne over de forskellige iterationer, er iteration 2 den, som ser sundest ud. Den overholder kravene til svartider, belastning på cpu og memory ser fornuftigt ud. Og kafka både lokal og central har ikke så stor consumer lag.

Iteration 2 har 4,19 kald per sekund (2095 registrering per sekund). Dette bliver til ca. 2,5 mio kald på en uge (1267 mio registreringer). Det er hvad test setup’et kunne håndtere uden at vise tegn på problemer.