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

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

Version

Dato

Ansvarlig

Beskrivelse

1.0

14-12-2020

KvalitetsIT

Performance test 2











Definitioner og forkortelser

Definition

Beskrivelse

NSP

Den nationale service platform (inden for sundheds-IT)


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:

Iteration

Tråde

Nodes

Starttid

Sluttid

Throughput 

(kald per sekund)

Faktisk

forbedring

Mål

forbedring

1522020-12-09_13-00-422020-12-09_13-15-4618,1

2822020-12-09_13-16-392020-12-09_13-31-4423,1828%36%
3832020-12-09_13-32-572020-12-09_13-48-0134,4448%30%
4842020-12-09_13-49-212020-12-09_14-04-2646,7835%19%
5852020-12-09_14-05-512020-12-09_14-20-5656,1720%15%
6862020-12-09_14-22-362020-12-09_14-37-4067,920%12%
7872020-12-09_14-39-302020-12-09_14-54-3479,3116%9%
8882020-12-09_14-56-262020-12-09_15-11-3090,3113%8%
9892020-12-09_15-13-212020-12-09_15-28-24103,915%7%
108102020-12-09_15-30-082020-12-09_15-45-13112,027%6%

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

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:

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:

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:

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:

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:

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:

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:

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:

Iteration

Tråde

Nodes

Starttid

Sluttid

Throughput 

(kald per sekund)

Faktisk

forbedring

Mål

forbedring

Fejlprocent
1522020-12-10_10-17-322020-12-10_10-32-3715,26


2822020-12-10_10-33-372020-12-10_10-48-4223,4453%36%
31122020-12-10_10-49-362020-12-10_11-04-4131,6935%22%
41422020-12-10_11-05-332020-12-10_11-20-3837,4218%16%
51722020-12-10_11-21-322020-12-10_11-36-3835,83-4%12%0,7%
61432020-12-10_11-37-512020-12-10_11-52-5750,0333%30%0,02%
71442020-12-10_11-54-122020-12-10_12-09-1843,66-12%19%

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

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:

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:

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:


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:

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:

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:

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:


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:

Iteration

Tråde

Nodes

Starttid

Sluttid

Throughput 

(kald per sekund)

Faktisk

forbedring

Mål

forbedring

Fejlprocent
1522020-12-10_13-15-382020-12-10_13-20-492,76

-
2822020-12-10_13-21-552020-12-10_13-27-034,1951 %36 %0,08 %
31122020-12-10_13-27-572020-12-10_13-33-074,241 %22 %0,47 %
41132020-12-10_13-34-142020-12-10_13-39-217,269 %30 %0,05 %
51142020-12-10_13-40-202020-12-10_13-45-306,25-13 %19 %-

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.

Application server

Iteration

Antal kald

Kald per sekund

Tidsforbrug (sekund)

Kald >= 6,5 sekundKald >=15,5 sekund
docker01.cnsp.stage.nsp.netic.dk14191,403,25

10 = 2,39 %

0 = 0 %

26342,113,4215 = 2,37 %0 = 0 %

36402,134,6994 = 14,69 %0 = 0 %

410893,634,1220 = 1,84 %0 = 0 %

59543,186,23372 = 38,99 %0 = 0 %
docker02.cnsp.stage.nsp.netic.dk14181,393,268 = 1,91 %0 = 0 %

26342,113,4511 = 1,74 %0 = 0 %

36442,154,6891 = 14,13 %0 = 0 %

410903,634,1617 = 1,56 %0 = 0 %

59553,186,38412 = 43,14 %0 = 0 %
Total
7477
4,571050 = 14,04 %0 = 0 %


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

Data serier i grafen er:


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

Data serier i grafen er:

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

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:


Registration:

Kafka-consumer:



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

Data serier i grafen er:


Registration:

Kafka-consumer:

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:


Registration: 

Kafka-consumer:

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:


Registration:

Kafka-consumer:


Cpu og hukommelse procent:

Data serier i grafen er:


Registration:

Kafka-consumer:


Netværk:

Data serier i grafen er:


Registration:

Kafka-consumer:

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:

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.