Indhold

Indledning

Dette dokument indeholder 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ørslen. 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.

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

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.

Vurdering

Vmstat log

Vurdering

Jstat log

Vurdering

Docker stats log

Vurdering

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:

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

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

Vurdering

Jstat log

Vurdering

Docker stats log

Vurdering

Konklusion

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