20210717 Samordna Opptak; overbelastet database
Dato: 2021-07-17
Skrevet av: Cameron Murdoch
Samordna opptak gikk ned eller var treg nok til å være nede i praksis kl 13:49 til kl 15:28 grunnet overbelastning mot Postgres databaseserver dbpg-so-prod01.uio.no. Webservere fungerte, men feilet pga. timeout på svar fra basen.
Forhistorikk og forberedelser i forkant av opptaket
På grunn av problemene som også oppstod i april, ble DB-serveren dbpg-so-
prod01 oppskalert i forkant av fristene i juli basert på erfaringene vi
hadde gjort oss i april. Dette ble diskutert mellom postgres-core og UNIT. Se:
https://rt.uio.no/Ticket/Display.html?id=4437112
https://rt.uio.no/Ticket/Display.html?id=4444321
Se også diskusjonen mellom postgres-core og virt-core:
https://rt.uio.no/Ticket/Display.html?id=4441430
30.06.21
- CPUene ble økt fra 16 til 20
- Minne ble økt fra 24GB til 64GB
- noen Linux og PostgreSQL innstillinger ble endret/tuned i forhold til dette.
14.07.21
- CPUene på maskinen økt fra 20 til 24
- Minne ble økt fra 64GB til 256GB
- Reservasjon for all CPU/minne ble satt på i VMWare
- noen PostgreSQL innstillinger ble endret/tuned i forhold til dette.
Beskrivelse av avviket og feilrettingsprosess
Load på dbpg-so-prod01.uio.no postgres-server dagen før og under hendelsen:
Litt tidshistorikk fra UNIT sin Slack chat og USIT Mattermost chat.
Load på serveren var lav utover fredag 16/7 og Postgresvakt sjekket lasten på serveren regelmessig frem til kl 23. Lasten økte utover lørdag 17/7 og Postgresvakt var pålogget UNIT sin Slack chat fra morgenen av.
Lørdag 17. juli
utover morgenen: cameronm sjekker - status OK
13:26 Henrik (UNIT) pinger cameronm om status; "Det begynner å bli stor last på databasen nå, men det ser ut til å gå bra enn så lenge."
13:49 Problemene starter. Henrik "Nå begynner vi å slite."
13:49 cameronm sjekker postgresql og vmware. vSphere viser CPU alarmer for VMen dbpg-so-prod01 og hosten esx-prod-c15.
13:54 UNIT stopper jobbene som publiserer svarbrev i Søkerportalen for å redusere lasten
13:55 Vegard (UNIT) "Det henger"
14:00 cameronm varser audunle via SMS.
14:12 cmstrand sjekker webservere som kjører uten problem
14:15 cameronm endrer noen PostgreSQL innstillinger (checkpoint timeout og WAL buffers) og restarter PostgreSQL tjenesten (med godkjenning fra UNIT på slack) - ikke synlig hjelp av betydning
14:29 cameronm ber audunle om å varsle werner og be om bistand fra virt-core.
14:52 audunle sender varsel til iti-sjefer og IT-direktør
14:59 cameronm øker minne fra 256GB til 384GB etter forslag fra werner. Ikke synlig hjelp av betydning.
15:04 cameronm får bistand fra odberg
15:10 odberg øker CPUene fra 24 til 32 - ikke synlig hjelp av betydning
15:19 odberg øker CPUene fra 32 til 48 - etter hvert ser det ut til å ha hjulpet litt
15:29 CPU-lasten begynner å gå ned
15:32 odberg øker CPUene fra 48 til 64 - lasten på serveren ser stabil ut selv om antall requests på frontenden fortsatt er høye
16:00 cameronm oppdaterer iti-sjefer og IT-direktør om status
16:14 Henrik (UNIT) bekrefter at problemet er løst foreløpig
16:28 cameronm oppdaterer iti-sjefer og IT-direktør om at problemet er løst
16:54 odberg øker cpu reservasjon fra 64000 til 128000
Fram til 20:00 cameronm overvåker serveren uten problemer
Søndag 18. april
10:00 - 20:00 cameronm har postgresvakten og sjekker dbpg-so-prod01 jevnlig under vakten. Det er fortsatt veldig høy CPU-last på serveren men UNIT klarer å publisere svarbrev utover dagen uten store problemer.
23:01 cameronm oppdaterer iti-sjefer og IT-direktør om status.
Mandag 19. april
Postgres-core begynner å analysere serveren for å finne ut hva som skjedde lørdag. Flere mulige årsaker blir diskutert og vurdert, f.eks. PostgreSQL innstillinger, Linux disk og minne innstillinger, mm.
09:26 cameronm ber UNIT sende en kopi av SQLen som vanligvis kjører etter at en søker har fått svarbrev. Angelapu og cameronm går gjennom spørringene.
ca 15:30 postgres-core identifiserer at en av de kritiske spørringene alltid kjører tregt.
ca 16:45 cameronm finner en feil i samme spørring. Den bruker en operatør for tekst sammenligning istedenfor et likhetstegn. Dette betyr at indeksen på tabellen aldri kan brukes og spørringen må søke gjennom omtrent 2 millioner rader hver gang. Spørringen har en utførelsestid på 200-1000ms og bruker mye HW-ressurser mens hvis den brukte likhetstegnet, ville den ha hatt en utførelsestid på ca 0.08ms.
17:19 cameronm varsler UNIT via slack om den uoptimaliserte spørringen.
Utover kvelden - UNIT utviklerne lager en fiks og planlegger en ny release til prod 08:00 tirsdag
Tirsdag 20. april
08:00 til 09:00 UNIT prøver å få buggfiksen på plass. De mislykkes pga. problemer med release prosessen. UNIT bestemmer at tjenesten må kjøre uten buggfiksen fordi tildeling av ledige studieplasser må begynne kl 9.
09:00 CPU-last på dbpg-so-prod01 er veldig høy og db-tjenesten sliter i noen minutter, men roer seg ned ganske raskt.
09:09 cameronm spør UNIT om han kan teste en midlertidig manuell løsning på dbpg-so-test01 og dbpg-so-prod01.
frem til 11:35 cameronm tester mulige løsninger
ca 11:35 cameronm lager en spesiell indeks på dbpg-so-prod01 som den uoptimaliserte spørringen kan bruke. Dette reduserer bruk av hw-ressurser og reduserer spørringens utførselstid til ca 35ms. Effekten er stor og CPU-lasten på dbpg-so-prod01 forsvinner med en gang.
Utover dagen - postgres-core overvåker serveren, og UNIT planlegger en ny release med fiksen tidlig torsdag.
Konsekvenser
Samordna opptak har frister noen få faste datoer i året hvor antall brukere er høyere enn vanlig.
Feilen som oppstod var helt klart av kategori A, alvorlig feil hvor hele applikasjonen var nede for sluttbrukere i en meget viktig fase mens UNIT publiserte svarbrev for studenter. Etter økning av hw-ressurser på lørdag, gikk resten av publiseringen uten store problemer, samt tildeling av ledige studieplasser på mandag og tirsdag.
Opprettelsen av den spesielle indeksen ser ut til å ha løst problemet med CPU-lasten.
Det virker som om den uoptimaliserte spørringen har vært brukt i lang tid og kan ha bidratt til problemet tjenesten opplevde i april.
Hva skulle vi gjort for at situasjonen ikke oppsto?
Det ble i forkant av fristen gjort endringer og oppskalering av både databaseserver og webservere basert på tidligere gjennomføringer for å takle forventet last. I tillegg var det satt opp vaktordning for både Postgres og www fra USIT sin side, samt personell fra UNIT.
En stresstest med simulering av systemet i forkant av fristene i stor nok skala burde ha avdekket problemene. Det er viktig å teste databasen med en tilsvarende datamengde som på prod-serveren i og med at dette kan ha en store påvirkning på ytelsen.
Bedre ytelsesmetrics for PostgreSQL kunne har oppdaget den uoptimaliserte spørringen tidligere. Postgres-core jobber allerede med dette som en del av generelle driftsoppdateringer.
Hva kunne USIT gjort bedre?
Overvåknings- og varslingsrutiner fungerte godt når hendelsen inntraff. Rask bistand from virt-core på lørdag var essensielt for å holde tjenesten kjørende under stor belastning.
Vi kunne ha oppdaget den trege spørringen raskere enn vi gjorde, og varslet utviklerne tidligere.
Tiltak
Anbefale at UNIT gjenopptar stresstesting for å avdekke flaskehalser.
Anbefale at UNIT gjenopptar testing av kritiske spørringer på databasen so_app_stage på dbpg-so-test01.uio.no og etablerer en ytelses-baseline som kan sammenligne endringer i forskjellige releaser. Denne databasen har samme data som den på dbpg-so-prod01 og vil trenge tilsvarende optimalisering av SQL-spørringer. Postgres-core kan bidra med database kompetanse ved behov.
Anbefale at UNIT dobbelsjekker for eventuelle trege spørringer i forkant av en SO-frist.
Innfører bedre ytelsesmetrics generelt for USITs PostgreSQL-servere.
Tilby UNIT mulighet til å kjøpe best-av-best hardware USIT har tilgjengelig i de periodene SO-fristene pågår.
Plan for oppsettsendringer basert på siste dagers erfaringer er laget på https://www.usit.uio.no/om/organisasjon/iti/dbd/dokumentasjon/postgresql/tjenester/SO/so_opptak_todo.html
Med informasjonen om SQL-buggen er laget på
https://www.usit.uio.no/om/organisasjon/iti/dbd/dokumentasjon/postgresql/tjenester/SO/problemet-juli-2021-med-ilike.html