Page History
| Navitabs | ||||||
|---|---|---|---|---|---|---|
| ||||||
Indhold
| Table of Contents |
|---|
Indledning
Leverancen indeholder unit tests, integrationstest og performance/endurancetests.
Unittests bør afvikles som en del af byggeprocessen, mens integrationstesten bør afvikles mod den deployede komponent. Begge disse tests kan afvikles med maven.
Endurancetesten bør afvikles med jmeter mod den deployede komponent.
Indeværende dokument et sammendrag af dokumentet MinLog2-Testvejledning og performance
Læsevejledning
Dette dokument indeholder analyse af log data fra den første performance test, som er kørt for Minlog2. Testene er kørt forår 2020. Analysen dækker
- MinLog2 - Performancetest rapport borger lookup
- MinLog2 - Performancetest rapport medhjælper lookup
- MinLog2 - Performancetest rapport minlog1 lookup
- MinLog 2 - Performancetest rapport registration
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 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 | 10-10-2019 | Openminds |
| 1.1 | 26-03-2020 | KvalitetsIT | Performance test rapport lookup | |||
| 1.2 | 27-05-2020 | KvalitetsIT | Performance test rapport registration |
Definitioner og forkortelser
...
Definition
...
Beskrivelse
...
NSP
...
Den nationale service platform (inden for sundheds-IT)
Unit tests
Unit tests bliver afviklet som en del af bygget, med mindre man eksplicit angivet, at det ikke ønskes.
Kør 'mvn clean install' eller 'mvn clean test'
Coverage report
Cobertura benyttes til – via maven – at danne en coverage rapport:
...
- Kør fra projektets rod i en kommandolinje:
- mvn install
- mvn site
- mvn site:stage
- Vis det generede site ved at åbne /target/staging/index.html i en browser
- Vælg 'Cobertura Test Coverage' under 'Project documentation'-'Project Reports' i menuen til venstre
Beskrivelse | |||
1.0 | 14-12-2020 | KvalitetsIT | Dokument oprettet som en kopi af test rapport Tekst, som ikke har med performance test er fjernet Test vejledning er fjernet, da dette findes andetsteds |
Definitioner og forkortelser
Definition | Beskrivelse |
NSP | Den nationale service platform (inden for sundheds-IT) |
...
Bemærkninger
Det er et krav, at der skal være en coverage på 80 %. Dog kan fx genereret kode afvige fra dette.
Nedenfor er beskrevet, hvilke pakker, der vurderes ikke at leve op til coverage kravet.
Følgende pakker indeholder genereret kode eller 3. part:
- dk.medcom.dgws.*
- oasis.*
- org.*
- dk.sundhedsdatastyrelsen.minlog.xml_schema.*
Derudover kode uden forretningslogik
Performance
Det følgende beskriver performance test og analyse for
- MinLog2 - Performancetest rapport borger lookup
- MinLog2 - Performancetest rapport medhjælper lookup
- MinLog2 - Performancetest rapport minlog1 lookup
- MinLog 2 - Performancetest rapport registration
Først beskrives de forskellige typer test data output, og hvordan de anvendes i analysen. Herefter skitseres scope og afvikling af testene samt performance kravene. Og endelig analyseres data for hver enkelt test.
Se iøvrigt krav til performance test og rapport på siden https://www.nspop.dk/display/public/web/Performancekrav
Performance analyse
For alle test gælder følgende:
Udover de fremsatte performance krav på svartid, 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
- Kafka Consumer Lag
Undersøgelserne foregår 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 antal test iteration kørt
- Throughput
- (Ex: docker01.bo.stage.nsp.netic.dk-perflogs/minlog_listlogstatements_borger_stress01.nsp-test.netic.dk_master_20200309_110341.tar.gz.log)
- Access log (applikations server information) belyser
- Antal kald per sekund
- Svartid
- For rapporten vedr. forespørgsler gælder
- De nedenstående grafer som er dannet fra denne log er lavet i splunk af Arosii.
- (Denne log er ikke inkluderet da den indeholder personfølsomme data)
- vmstat log (system information) belyser
- cpu status
- skrivning til disk
- Logning sker hver 10. sekund
- (Ex: docker01.bo.stage.nsp.netic.dk/docker01.bo.stage.nsp.netic.dk-vmstat-20200309101455.log)
- jstat log (JVM information) belyser
- Hukommelse (heap) forbrug
- Garbage collection
- Der er tidsstempel per log linie
- (Ex: docker01.bo.stage.nsp.netic.dk/docker01.bo.stage.nsp.netic.dk-docker-jstat-gc-stage_bo_comp_minlog_backend_lookup.log)
- docker stats log (container information) belyser
- Hukommelse
- io på netværk
- Der er ikke noget fast logningsinterval
- (Ex: docker01.bo.stage.nsp.netic.dk/docker01.bo.stage.nsp.netic.dk-docker-jstat-gc-stage_bo_comp_minlog_backend_lookup.log)
- Kafka Consumer lag
- Relevant ved registrering af data
- Offsets og lag fordelt per topic og partition
- Der er tidsstempel per log linie
- (Ex kafka01.stage.nsp.netic.dk-kafka-consumer-group/minlog-kafka-backend.log)
Hver kørsel/iteration (ø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 iteration. Filen vmstat har ikke tidstempel. Men da den er startet samtidig med jstat loggen og logintervallet er kendt på 10 sekunder, kan iterationernes placering i data beregnes. Docker stats loggen har hverken tidsstempel eller fast logninginterval, hvorfor tallene/graferne kun kan bruges som en generel betragtning over hele test perioden.
I det nedenstående kan man klikke på de enkelte grafer for større billede. De enkelte iterationer er tegnet ind som lodrette mørke streger; 2 streger per iteration (start og slut tidspunkt).
Scope og afvikling
Scope
Testene involverer følgende komponenter
- MinLog 2 service
- NSP kafka
- Galera MariaDB cluster
- NSP standard performance test framework
Versionen af MinLog2 og test frameworket varierer for hver test og fremgår nedenfor.
MinLog 2's overordnede arkitektur ses af følgende figur (kilde: arkitektur dokumentet)
Lookup/forespørgsler test vedrører kun "lookup" komponenten, da der ingen opdateringer (registration ) foregår imens, og der dermed heller ingen aktivitet er på "consumer" komponenten. Dette betyder konkret, at de tilsendte log filer, som vedrører "consumer" komponenten ikke analyseres for lookup rapporterne.
Registration består af 2 komponenter: registration komponenten, som modtager input og gemmer data ned i sin "lokale" kafka. Data herfra flyttes af mirrorMaker over på den centrale kafka i backoffice. Og den anden komponent kafka-consumer, der tager fra den centrale kafka og flytter data i databasen.
Der er ikke målinger på database serveren (MariaDB).
Afvikling
Performance testen er afviklet på følgende måde
- Testen er kørt på et test system opsat at Netic
- Testen er lavet i standard NSP performance frameworket, 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.
- Testplanerne kører 15 minutter per iteration og for læsning hentes 30 entries per side.
- System under test er kørt på 2 docker containere for lookup, og 4 containere for registration (docker01 og docker02 henholdsvis docker01, docker02, docker03 og docker04 i nedenstående)
Se iøvrigt MinLog 2 test performancetestvejledning for detaljer.
Performance krav
Performance krav til MinLog 2 Performance test er som følger:
| Service | Servicemål |
|---|---|
| Svartider opdatering | 95 % af tilfældene ≤ 6,5 sek |
| 98 % af tilfældene ≤ 15,5 sek | |
Svartider forespørgsler | 95 % af tilfældene ≤ 2,5 sek |
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.
...
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 kan ses, at der er kørt 10 iterationer med test, deres tidsinterval , throughput og fejlprocent for hver.
...
Samt at fejlprocentet på den fulde kørsel er 0 %.
Access log
Denne log findes for hver applikations server (docker container).
...
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.
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.
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 2 sekund
- under 5,5 sekund for 98 % af tilfældende; dette overstiges ifølge "98 % percentil grafen" ikke. Max svartiden er her under 2,6 sekunder
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:
...
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, og sammenligner man graferne fra før på cpu forbrug, ses det, at de få store udsving i skrivninger falder sammen med at cpuKernal går op og cpuIdle går ned.
Vurdering
Der er intet negativt at bemærke omkring cpu forbruget eller io.
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:
...
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:
...
Cpu og hukommelse procent:
Data serier i grafen er:
...
Servicen viser et stabilt forbrug af hukommelse. Den envendte cpu er svagt stigende som servicen bliver presset.
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
Der er intet at bemærke som kan påvirke servicens performance i negativ retning.
Konklusion
Efter at have analyseres data fra performance testen kan følgende trækkes frem:
...
Analysen af performance test data har ikke givet anledning til bekymring eller identificering af flaskehalse.
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.
...
Indledningsvis skal siges, at servicen kørende på docker1 gik i fejl sidst i testen pga memory problemer. Der mangler derfor access log data for ca. 10 minutter i slutningen af testen.
JMeter log
JMeter hoved filen beskriver overordnet testens resultat. Her kan kan ses, at der er kørt 12 iterationer med test, deres tidsinterval , throughput og fejlprocent for hver.
...
Throughput falder mellem iteration 11 og 12. Og der er en forøgning af fejl i den sidste iteration.
Access log
Denne log findes for hver applikations server (docker container).
...
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. Først til sidst i testen går den op.
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 et faldende antal request i sidste 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 2,1 sekunder
- under 5,5 sekund for 98 % af tilfældende; dette overstiges ifølge "98 % percentil grafen" ikke. Max svartiden er her under 2,5 sekunder
Vi er inden for performance kravene i testen fulde køretid, selv i den test iteration, hvor den ene testede service stoppede.
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:
...
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, og sammenligner man graferne fra før på cpu forbrug, ses det, at de få store udsving i skrivninger falder sammen med at cpuKernal går op og cpuIdle går ned. Dog ses en markant stigning i antal af skriv til disk i samme periode som cpuNonKernel stiger.
Vurdering
Cpu forbruget i 10. 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:
...
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:
...
Cpu og hukommelse procent:
Data serier i grafen er:
...
Den envendte cpu er svagt stigende som servicen bliver presset. Og fra 10. iteration laver både docker1 og docker2 nogle 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.
Vurdering
Disse log data viser igen den øgede cpu og hukommelsesforbrug sidst i testen. Det ser dog ud til at containeren har masser af hukommelse og ikke i sig selv er ved at løbe tør.
Konklusion
Efter at have analyseres data fra performance testen kan følgende trækkes frem:
...
De mange fejl, der ses i jmeter loggen kan skyldes at servicen på docker1 stopper med at svare og dermed melder "Internal Server Error" tilbage.
MinLog2 - Performancetest rapport minlog1 lookup
Performance testen består af en række kald til opslag efter logninger på forskellige cpr numre. Denne test er samme type som borger lookup. Den anvender dog istedet minlog1 formatet.
...
De rå test resultater er vedhæftet denne side (minlog2_minlog1_listlogstatements_borger_run1.tar.gz)
JMeter log
JMeter hoved filen beskriver overordnet testens resultat. Her kan kan ses, at der er kørt 4 iterationer med test, deres tidsinterval , throughput og fejlprocent for hver.
...
Samt at fejlprocentet på den fulde kørsel er 0 %.
Access log
Denne log findes for hver applikations server (docker container).
...
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.
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.
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,1 sekunder
- under 5,5 sekund for 98 % af tilfældende; dette overstiges ifølge "98 % percentil grafen" ikke. Max svartiden er her under 1,4 sekunder
Vi er inden for performance kravene i testen 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:
...
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, og sammenligner man graferne fra før på cpu forbrug, ses det, at de store udsving i skrivninger falder sammen med at cpuKernal går op og cpuIdle går ned.
Vurdering
Der er intet negativt at bemærke omkring cpu forbruget eller io.
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:
...
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:
...
Cpu og hukommelse procent:
Data serier i grafen er:
...
Servicen viser et stabilt forbrug af hukommelse. Den envendte cpu er svagt stigende som servicen bliver presset.
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. netIn stiger mest.
Vurdering
Der er intet at bemærke som kan påvirke servicens performance i negativ retning.
Konklusion
Efter at have analyseres data fra performance testen kan følgende trækkes frem:
...
Analysen af performance test data har ikke givet anledning til bekymring eller identificering af flaskehalse.
MinLog2 - Performancetest rapport registration
Performance testen består af en række kald til registrering af minlog2 data med forskellige cpr numre.
...
De rå test resultater er vedhæftet denne side (minlog2-registration-test900-run3.tar.gz).
JMeter log data
JMeter hoved filen beskriver overordnet testens resultat. Her kan ses, at der er kørt 8 iterationer med test, belastningen i form af tråde og nodes, deres tidsinterval , throughput og fejlprocent for hver:
...
Samt at fejlprocentet på den fulde kørsel er 0,49 %.
Access log data
Denne log findes for hver applikations server (docker container) hvor registration komponenten har kørt.
...
Udtræk af svartid og antal kald fordelt over testens løbetid vises i følgende grafer:
Data serier i grafen er:
- DurationAverage (rød): den gennemsnitlige svartid (ms) for hvert minut
- NoOfCalls (blå): det gennemsnitlige antal kald hvert minut
- De 8 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.
...
Og disse overholdes fint qua ovenstående tabeloversigt. I iteration 8 på docker02, hvor tallene er højest, er 99,5 % under 6,5 og 15,5 sekunder.
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:
...
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, og igen falder de få store udsving i skrivninger falder sammen med at cpuKernal går op og cpuIdle går ned.
Vurdering
Der er intet negativt at bemærke omkring cpu forbruget eller disk io.
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:
...
- 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.
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). 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:
...
Cpu og hukommelse procent:
Data serier i grafen er:
...
- Både forbruget af hukommelse og cpu er stabilt igennem testen.
Netværk:
Data serier i grafen er:
...
- De 2 grafer for ind- og udsendt data stiger svagt og følges ad.
Vurdering
Intet at bemærke.
Kafka consumer lag
Denne log findes for hver applikations server (docker container). Både for registration og kafka-consumer.
...
Udtræk omkring registerings komponentens kafka og lag i løbet af testen:
Data serier i grafen er:
...
Udtræk omkring den centrale kafka og lag i løbet af testen:
Data serier i grafen er:
...
Den centrale kafka har 6 partitioner, og man kan se, at lag stiger som testen skrider frem.
Vurdering
Både registrering komponentens kafka og den centrale kafka har det bedst før iteration 7. Herefter kan læsningen ikke rigtig følge med input. Registreringskomponentens kafka er den, som har de største peaks inden iteration 7, og kunne gøres mere effektiv, ved at tilføje flere partitioner til den ene, den har nu.
Konklusion
Efter at have analyseres data fra performance testen kan følgende trækkes frem:
...