20210415 Samordna Opptak nedetid

SO nede i kritisk periode pga database timeout

Avviksrapport for Samordna opptak

Dato: 2021-04-15
Skrevet av: Audun Lea Hansen

Samordna opptak gikk ned kl 21:55 til kl 23:58 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

Ut fra problemene som også oppstod i fjor, ble DB-serveren dbpg-so-
prod01 oppskalert i forkant av årets opptak ut fra de erfaringene vi
hadde gjort oss fra tidligere opptak, se
https://rt.uio.no/Ticket/Display.html?id=4307482

Minnet på dbpg-so-prod01 ble økt til 32GB på 22.03.21 og noen Linux og
PostgreSQL innstillinger ble endret/tuned i forhold til dette.

12.04.21 ble CPUene på maskinen økt fra 16 til 24 for å forberede til
fristen denne uken. Dette viste seg ikke å være nok i forhold til
trykket som kom mot databasen.

Beskrivelse av avviket og feilrettingsprosess

Load på dbpg-so-prod01.uio.no postgres-server dagen før og under hendelsen:

Load på server onsdag 14/4 og torsdag 15/4

Litt tidshistorikk fra UNIT sin Slack chat og USIT Mattermost chat.

Load på server økte utover kvelden 15/4 og DBD-vakt var pålogget UNIT sin Slack chat fra morgenen av.

Torsdag 15. april
17:51 DBD-vakt sjekker - status OK
21:47 UNIT pinger DBD-vakt på slack chat om status; Høy last, load på 43.99 men ser ok ut.
21:55 Problemene starter. UNIT får ikke åpnet søknader gjennom applikasjonen.
22:09 Antall cpu ble økt fra 24 til 32 - ikke synlig hjelp av betydning.
22:16 SO i praksis nede, PG restartes for økning/endring på minne. wait
events av typen buffer_mapping LWLock tyder på problemer med
shared_buffers og linux-cache. shared_buffers økt til 10GB
22:20 Minne økt til 40GB, shared_buffers økt til 12GB. PG restartet, wal_buffers ble økt til 128MB pga noen få påkoblinger som var låst i "WALWriteLock"
22:24 SO oppe igjen
22:27 Gikk i metning igjen
22:30 DBD-vakt jobber videre.
22:37 UNIT tar opp til vurdering å utsette fristen med 12 timer.
22:37 Følgende info fra UNIT:  Det virker som den spørringen som henter
søknader er tung. Men det får vi ikke gjort noe med i en fei
22:50 PG restartes
22:56 PG tilgjengelig igjen, går rett i metning på cpu
23:10 USIT jobber på VMware siden, DB-serveren får ikke aktivert mer
minne som vi har tildelt via virtprov (56GB) Blir fikset via vSphere.
23:15 Esx-hosten bruker nesten all cpu, USIT flytter bort andre VMer for å minske load på fysisk node (redusere CPU wait time for VMen dbpg-so-prod01)
23:32 PG restartet med 56GB minne
23:35 SO sliter igjen.
23:48 Må reboote VMen for å tildele mer enn 64GB minne. OK fra UNIT
23:58 PG oppe igjen med 512GB minne - 32 CPU.  Postgres sin buffer_cache er satt til 64GB, som er større enn so_app_prod akkurat nå.
00:01  CPU-forbruket har gått ned til ~15cpu. Hele basen er nå i buffer_cache og buffer_mapping LWLock wait eventene er nå borte.
00:04 Flaskehalsen ser nå ut til å være latency på disk. Noen CPU-kjerner har i perioder disk I/O-wait på  ~80%. Dette er ikke nødvendigvis et problem, men USIT flytter disker over på flash-disker for å være på den sikre siden.
00:10 I/O-wait borte, latency har ligget på ~1-5ms med peaks på opp mot 10-15ms, nå ligger vi mellom 0 og 1ms med peaks opp mot 5ms. Responsen ser nå bra ut, og grafene ser bedre ut igjen (noe usikkerhet rundt hvor mye tuningen har å si vs. at vi har passert midnatt og antall brukere antageligvis er synkende).
01:18 USIT logger av og klargjør for morgendagen.
01:21 USIT-DBD sender foreløpig logg/avviksrapport på epost internt på USIT.

Load gjennom ettermiddagen

Fredag 16. april
10:48 UNIT gjør en kodeendring i systemet for å unngå unødvendige tunge jobber fram mot fristen
12:00 Utsatt frist passert, uten problemer

Konsekvenser

Samordna opptak har opptaksfrist noen få faste datoer i året hvor et høyt antall søkere til høyere utdanning legger inn sine søknader og ønsker.

Feilen som oppstod var kategori A, alvorlig feil hvor hele applikasjonen var nede for sluttbrukere i en viktig fase opp mot frist for søknad. UNIT hadde mulighet til, og utsatte fristen i 12 timer.

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 ut fra 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 opptaket i stor nok skala kunne ha avdekket problemene. Slike stresstester har blitt gjort tidligere år, men ikke de siste årene.

Hva kunne USIT gjort bedre?

Overvåknings- og varslingsrutiner fungerte godt når hendelsen inntraff

Tiltak

Møte med UNIT SO for å gå gjennom tiltak.

Anbefale at UNIT gjenopptar stresstesting for å avdekke flaskehalser.

Ut fra analyser som er gjort, er work_mem økt for de jobbene som refresher og analyserer  2 Materialized View. I tillegg bør spørringer kjørt av dbsync brukeren analyseres nærmere. Disse jobbene bør vurderes om kan utsettes akkurat under opptaket

Se på mulighetene for bruk av connection pooling ved hjelp av eks. pgBouncer for å minske trykket på oppkobling av nye sesjoner mot databasen

Plan for oppsettsendringer ut fra erfaringene er oppdatert på DBD sine interne sider, innebefatter CPU og minneendringer.

 

 

 

 

Av audunle
Publisert 23. apr. 2021 11:12 - Sist endret 12. jan. 2023 10:06