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
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æseren forventes at have kendskab til National Sundheds-IT's platform NSP, samt generelt kendskab til WildFly applikation server, MariaDB, Kafka og java.
Version | Dato | Ansvarlig | Beskrivelse |
1.0 | 14-12-2020 | KvalitetsIT | Performance test 2 |
Definition | Beskrivelse |
NSP | Den nationale service platform (inden for sundheds-IT) |
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 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:
Iteration | Tråde | Nodes | Starttid | Sluttid | Throughput (kald per sekund) | Faktisk forbedring | Mål forbedring |
|---|---|---|---|---|---|---|---|
| 1 | 5 | 2 | 2020-12-09_13-00-42 | 2020-12-09_13-15-46 | 18,1 | ||
| 2 | 8 | 2 | 2020-12-09_13-16-39 | 2020-12-09_13-31-44 | 23,18 | 28% | 36% |
| 3 | 8 | 3 | 2020-12-09_13-32-57 | 2020-12-09_13-48-01 | 34,44 | 48% | 30% |
| 4 | 8 | 4 | 2020-12-09_13-49-21 | 2020-12-09_14-04-26 | 46,78 | 35% | 19% |
| 5 | 8 | 5 | 2020-12-09_14-05-51 | 2020-12-09_14-20-56 | 56,17 | 20% | 15% |
| 6 | 8 | 6 | 2020-12-09_14-22-36 | 2020-12-09_14-37-40 | 67,9 | 20% | 12% |
| 7 | 8 | 7 | 2020-12-09_14-39-30 | 2020-12-09_14-54-34 | 79,31 | 16% | 9% |
| 8 | 8 | 8 | 2020-12-09_14-56-26 | 2020-12-09_15-11-30 | 90,31 | 13% | 8% |
| 9 | 8 | 9 | 2020-12-09_15-13-21 | 2020-12-09_15-28-24 | 103,9 | 15% | 7% |
| 10 | 8 | 10 | 2020-12-09_15-30-08 | 2020-12-09_15-45-13 | 112,02 | 7% | 6% |
Test kørslen nåede aldrig sit maksimum, da test frameworket løb tør for nodes at starte op.
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 ikke ændrer på svartiderne.
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
Vi er inden for performance kravene i testens fulde køretid.
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.
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-test900-run3.tar.gz).
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 |
|---|---|---|---|---|---|---|---|---|
| 1 | 5 | 2 | 2020-12-10_13-15-38 | 2020-12-10_13-20-49 | 2,76 | - | ||
| 2 | 8 | 2 | 2020-12-10_13-21-55 | 2020-12-10_13-27-03 | 4,19 | 51 % | 36 % | 0,08 % |
| 3 | 11 | 2 | 2020-12-10_13-27-57 | 2020-12-10_13-33-07 | 4,24 | 1 % | 22 % | 0,47 % |
| 4 | 11 | 3 | 2020-12-10_13-34-14 | 2020-12-10_13-39-21 | 7,2 | 69 % | 30 % | 0,05 % |
| 5 | 11 | 4 | 2020-12-10_13-40-20 | 2020-12-10_13-45-30 | 6,25 | -13 % | 19 % | - |
Det fremgår også af filen, at den endelige måling af throughput er 6,25 kald per sekund.
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 sekund | Kald >=15,5 sekund |
|---|---|---|---|---|---|---|
| docker01.cnsp.stage.nsp.netic.dk | 1 | 419 | 1,40 | 3,25 | 10 = 2,39 % | 0 = 0 % |
| 2 | 634 | 2,11 | 3,42 | 15 = 2,37 % | 0 = 0 % | |
| 3 | 640 | 2,13 | 4,69 | 94 = 14,69 % | 0 = 0 % | |
| 4 | 1089 | 3,63 | 4,12 | 20 = 1,84 % | 0 = 0 % | |
| 5 | 954 | 3,18 | 6,23 | 372 = 38,99 % | 0 = 0 % | |
| docker02.cnsp.stage.nsp.netic.dk | 1 | 418 | 1,39 | 3,26 | 8 = 1,91 % | 0 = 0 % |
| 2 | 634 | 2,11 | 3,45 | 11 = 1,74 % | 0 = 0 % | |
| 3 | 644 | 2,15 | 4,68 | 91 = 14,13 % | 0 = 0 % | |
| 4 | 1090 | 3,63 | 4,16 | 17 = 1,56 % | 0 = 0 % | |
| 5 | 955 | 3,18 | 6,38 | 412 = 43,14 % | 0 = 0 % | |
| Total | 7477 | 4,57 | 1050 = 14,04 % | 0 = 0 % |
Udtræk af svartid og antal kald fordelt over testens løbetid vises i følgende grafer:
Data serier i grafen er:
Data serier i grafen er:
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å talene, kan det ses, at sætter man en grænse på 9,2 sekund per kald er der under 5 %, der overskrider dette.
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:
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.
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:
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.
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:
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.
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.
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.