Mangler:

• container grafer skal skiftes ud. interval skal være enten 900 (1 linie pr sek) eller 1896 (hele loggen fordelt ud på 3 intervaller). Men ingen af dem kommer til at matche. What to do? Afventer svar fra jacob om interval på 1 sek er korrekt
• vurderinger for hver log fil
• konklusion for hvert punkt nævnt først i afsnit "performance tal"
• ??? i kommentarer på performance krav. 

.

Scope

Performancetesten består af et antal kald til læsning af allergier for en liste af 50.000 personer (cpr numre). 

Testen involverer følgende komponenter

• LAR service som første led (v. 1.0.2)
• CAVE service som andet led (v. 1.0.2)
• FHIR database som tredie led (v. 3.7.0)
• Derforuden har integrationen til minlog, MinSpæring og behandler relation check være aktiveret under kørslen (Herefter benævnt som MSB)

Performance krav

Kravene fra fra kravspecifikationen lyder som følger:

1. Systemets svartider måles på en klient i umiddelbar nærhed af LAR service snitfladen, således at der medregnes et netværkskald mellem klient og service.
2. Systemets gennemsnitlige svartid ved læsning skal ligge under 200ms.
3. Forudsætninger for ovenstående svartider er, at:
   1. systemet anvendes af 10 samtidige brugere, der udfører et kald pr. sekund med 1000ms tidsmæssig forskydning på forskellige CPR numre.
   2. databasen indeholder 50.000 allergi-registreringer på et tilsvarende antal patienter.
   3. eksterne servicekald er deaktiveret
   4. der er ikke andre services der anvender infrastrukturen.
   5. der anvendes to applikationsservere til hver service, svarende til en NSP med to søjler til LAR servicen og to Back-End servere til CAVE servicen. Servicekald fordeles efter Round-Robin princippet mellem hver af de to servere.
   6. Serverne er hardwaremæssigt konfigureret svarende til NSP applikationsservere.

Kommentarer

1. ???
2. Dette vil bleve vurderet med udgangspunkt i test resultaterne
3. Forudsætnigner
   1. NSP standard test framework vil blive brugt. Belasningen vil derfor lægge højere end 10 samtidige brugere. Der startes med 2 noder med 7 tråde. Dvs. 14 brugere.
   2. inden testen startes er en database med 50.000 allergier fordelt på 50.000 patiener klargjort
   3. de eksterne servicekald var aktiveret under kørslen. Da svartiderne for disse kan findes i log filerne kan der laves en beregning, der viser svartiderne uden de eksterne servicekald.
   4. ???
   5. der er ialt anvendt 4 søjler, hvor LAR og CAVE har kørt på alle 4.
   6. ???

Afvikling

Performance testen er afviklet på følgende måde

• der er anvendt et test certifikat. Og der trækkes et idkort i setup fasen af testen, dvs hver gang en node startes på. Den del er holdt ude af performance målingen
• testen er kørt på test system opsat at Netic: cstag-lb.cnsp.netic.dk:8080  
• testen er lavet i standard NSP performance frameworket (v.2.0.0), udviklet af Arosii i JMeter.
• Der er kørt en testplan med stadig øget belastning ved at øge antallet af tråde og noder indtil det målte throughput ikke længere vokser med tilsvarende mængde.
• Testplanen der er kørt er test900, og den er kører 15 minutter per iteration.
• System under test (LAR og CAVE servicen) er kørt på på 4 docker containere
• Kald til de 3 eksterne service MSB har været aktiveret under testen

Se iøvrigt LAR test vejledning afsnit 2.3 performance test for detaljer.

De rå test resultater er vedhæftet denne side (lar-cave-perftest.tgz)

Performance tal

Udover det fremsatte performance krav med en svartid på under 200 ms, er der en række andre punkter som bør analyseres for at vurdere servicens sundhed.

Følgende punkter bliver derfor undersøgt:

• Svartid per kald
• Antal kald per sekund
• Cpu status
• io på netværk
• Hukommelses forbrug
• Garbage collection

Disse undersøges vha. de forskellige log filer, som er genereret under performance testen. De følgende afsnit gennemgår de vigtigste tal fra disse filer:

• JMeter log data belyser
  • Faktisk test runder kørt
  • Throughput
  • (/stress01.nsp-test.netic.dk-lar/lar_listallergy_test900_stress01.nsp-test.netic.dk_master_20190513_114050.tar.gz.log)
• Access log og sla log (applikations server information) belyser
  • Antal kald per sekund
  • Svartid per kald
  • (Ex: docker01.cnsp.stage.nsp.netic.dk-lar/logs/lar/access.log)
• vmstat log (system information) belyser
  • cpu status
  • Logning sker hver 10. sekund
  • (Ex: docker01.cnsp.stage.nsp.netic.dk-lar/stats/docker01.cnsp.stage.nsp.netic.dk-cpu-20190513110936.log)
• jstat log (JVM information) belyser
  • Hukommelse (heap)  forbrug 
  • Garbage collection
  • Tidsstempel per log linie
  • (Ex: docker01.cnsp.stage.nsp.netic.dk-lar/stats/docker01.cnsp.stage.nsp.netic.dk-cave-jstat-20190513110936.log)
• docker stats log (container information) belyser
  • Hukommelse
  • io på netværk
  • Logning sker hvert sekund
  • (Ex: docker01.cnsp.stage.nsp.netic.dk-lar/stats/docker01.cnsp.stage.nsp.netic.dk-cave-container-20190513110936.log)

Hver kørsel/runde (øgning af belastning) har en start og slut tid. Filerne access.log og jstat.log indeholder tidstempler. Dette muliggør at de kan mappes til en given runde. Filerne vmstat og docker stats har ikke tidstempler. Men da disse er startet samtidig med jstat loggen og logintervallet er kendt, kan runderne placering i data beregnes.

Hvor der i nedenstående er grupper af 4 grafer, skal de læses fra venstre mod højre og ned og mod højre: dette viser app server 1, 2, 3 og 4. Klik på den enkelt graf for større billede. De enkelte runder er tegnet ind som lodrette mørke streger; 4 streger der sympolisere de 3 runder start og slut.

JMeter log data

JMeter hoved filen beskriver overordnet testens resultet.

Her kan  kan ses, at der er kørt 3 runder med test, deres tidsinterval og throughput for hver.

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

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

Vurdering

Kravet til testen er, at der skal køres med 10 samtidige brugere med hver et kald per sekund. NSP's test framework fungerer med en bestemt belastning i testen som gradvis øges.  

Testen har kørt med i første runde 14 samtidige brugere, anden runde 20 brugere og sidste runde 30 brugere. Hvilket ligger over kravet til testen. Da testen også har kørt med MSB servicen aktiveret har det lagt yderligere pres på testen. 

Derfor konkluderes at ud fra JMeter loggens data ser testens resultat fornuftig ud i forhold til performance kravet.

Access log data

Denne log findes for hver applikations server (docker container) for både LAR og CAVE servicen.

Her findes data for hvert enkelt kald, der er lavet til de 2 LAR og CAVE services, herunder hvor lang tid et kald har taget (Duration). Ved at kigge på de kald, der er foretaget til LAR servicen kan den gennemsnitlige tid et kald tager beregnes. 

Desuden kan tidsforbruget for kald til MSB servicene findes via via servicenes sla logs (nsputil-sla-lar.log)  og messageid, og på den måde trækkes fra LAR servicens tid for at få netto tiden. 

Følgende tabel viser en række beregnede data fra access loggen fordelt på applikations server (container), testrunde og http kode. Nederst i tabellen er tallene for hver applikations server lagt sammen. Testrunde er beregnet ved at sammenligne tidstempel fra access log med start og sluttidspunktet for runden. http koden findes i access loggen (kald returnerede med fejl (500) eller ingen fejl(200)).

De beregnede data er antal kald, kald per sekund i gennemsnit (hver runde er 900 sekunder), tidsforbrug per kald i millisekunder. 

Vurdering

Af tabellen fremgår det, at jo flere brugere (brugere øges per runde) jo flere kald kommer der igennem per sekund. Tallene svarer overens med de tal JMeter kom frem til som throughput.

Det ses, at jo flere brugere jo højere bliver svar tiden.  Performance kravet er 200 ms ved 10 brugere uden MSB services slået til. Ovenstående tabel viser, at ved 14 brugere (runde 1) er svartiden 155 ms. Vi er inden for performance kravet.

Man kan undres over, hvorfor det skal tages så meget mere tid når MSB servicene medtages. Det har vist sig at kaldet til BRS er lavet uhensigtmæssigt, hvilket bliver rettet på Jira CAVE-78. Dette burde give bedre performance.

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

De 4 data serier i grafen er:

• cpuNonKernel: tid brugt på non-kernel opgaver
• cpyKernel: tid brugt på kernel opgaver
• cpuIdle: tid brugt på ingenting
• cpuWaitIO: tid brugt på at vente på i/o
• De 3 runder er en cirka placering, da wmstat loggen ikke indeholder tidstempel

De 4 dataserier i graferne er meget stabile. Man fornemmer aktivitet omkring start og slut af de 3 runder. Størst udsving er der ved opstart af testen, hvor den cpu der bliver brugt af applikationen (cpuNonKernel) striger meget og idle cpu tilsvarende falder. Men det er kun kortvarigt.

Vurdering

Graferne ser fornuftige ud. Der er intet at bemærke omkring cpu forbrug.

Jstat log

Denne log findes for hver applikations server (docker container) - en for LAR og en for CAVE. 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 4 grafer for henholdsvis LAR og CAVE.

LAR servicen: 

CAVE servicen:

De 5 data serier i grafen er:

• YGC: young generation garbage collection events, antal af "ung" garbage collection siden start
• FGC: full garbage collection events, antal af fuldstændig garbage collection siden start
• HeapU: består af S0U+S1U+EU fra jstat loggen. Young generation memory utilization. "Ung" hukommelses forbrug
• HeapC: består af S0C+S1C+EC fra jstat loggen. Young generation memory capacity. "Ung" hukommelses kapacitet
• OU_MB: old space utilization. "Ældre" hukommelses forbrug
• OC: old space capacity. "Ældre" hukommelses kapacitet er ikke en del af grafen men er konstant på 1.398.272 KB for både LAR og CAVE.
• De 3 runder er baseret på det tidstempel, som findes i jstatloggen

For LAR kan man se, at der er kørt et par enkle fuld garbage collections. Ved start af runde 1 og midt i runde 3. For CAVE kan man se, at der ikke er kørt fuld garbage collection. Der køres også oftere garbage collection på den yngre hukommelse på LAR servicen end der gør på CAVE. 

Den brugte yngre hukommelse svinger noget for både LAR og CAVE, men dog i et konstant interval.

Vurdering

Den yngre forbrugte hukommelse eskalerer ikke for hverken LAR eller CAVE. Garbage collecteren holder det i skak.

Docker stats log

Denne log findes for hver applikations server (docker container) - en for LAR og en for CAVE. 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 3 * 4 grafer.

LAR service - Hukommelse:

CAVE service - Hukommelse:

De 2 data serier i grafen er:

• memoryUsage: den totale mængde hukommelse containeren bruger
• memoryLimit: den totale mængde hukommelse contaneren kan bruge
• De 3 runder er en cirka placering, da docker stats loggen ikke indeholder tidstempel

Den forbrugte hukommelse for CAVE servicen er meget stabil. For LAR servicen er den svagt stigende, men da jstat statistikken ikke indikerer at selve applikationen øger forbruget af hukommelse, anses det ikke som et problem.

LAR service - Cpu og hukommelse procent:

CAVE service - Cpu og hukommelse procent:

De 2 data serier i grafen er:

• cpuPct: hvor mange procent af hostens cpu containeren bruger
• memoryPct: hvor mange procent af hostens hukommelse containeren bruger
• de 3 runder er en cirka placering, da docker stats loggen ikke indeholder tidstempel

Begge procenter er stabil for CAVE servicen. LAR servicen viser et stigende forbrug af hukommelse, men som skrevet for forrige graf anses det ikke som et problem.  

LAR service - netværk:

CAVE service - Netværk:

De 2 data serier i grafen er:

• netIn - den mængde data som er modtaget af containeren over netværket
• netOut - den mænde data som er sendt ud af containeren over netværket
• de 3 runder er en cirka placering, da docker stats loggen ikke indeholder tidstempel

De 2 grafer for ind- og udsendt data følges pænt, hvilket er forventeligt

Vurdering

Placeringen af rundernes markering kunne umiddelbart godt se forkert ud når man generelt ser på graferne. Der er ændret adfærd ca. 150 enheder før den angivne markering første gang, og den bliver længere og længere til venstre.

Derforuden...

Konklusion

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

• Svartid per kald til servicen: 155 ms for 14 brugere
  Kravet var at et kald skal tage mindre end 200 ms
  Dette opfyldes, endda under øget belastning med flere brugere.
  
  
• Antal kald per sekund til servicen: 20,4 med 14 brugere
  
  
• Cpu status: for både LAR og CAVE  er cpu forbruget nogenlunde konstant over test perioden. Det svinger inden for et interval og rammer aldrig i nærheden af loftet.
  
  
• io på netværk: for både LAR og CAVE er der er en jævn strøm af læs og skriv via netværket
  
  
• Hukommelses forbrug: både LAR og CAVE håndterer brug af hukommelse fint
  
  
• Garbage collection: både LAR og CAVE servicen kører jævnligt garbage collection, hvilket holder forbruget af hukommelsen i skak.

TBD:

Fejlprocess vurdering,

tjek evt. de 500 kald, hvorfor de optod

stigende memory for lar service, dog viser jstat at selve applikationen ikke øger forbruget af af memory.