Hva skal til for å velte én fil?
Vårt observabilitetssystem fortalte oss 78,8 millioner ganger at det var i ferd med å fortelle oss noe. Den delen er flau. Den interessante delen er at ingenting merket det.
Loggsenderen sendte en logglinje. Det å sende den ble logget. Den loggen ble sendt.
Loggdatabasen skrev linja til disk. At den skrev til disk ble logget. Den loggen ble sendt, og skrevet til disk.
Ingen av delene var en feil i seg selv. De var bare slått på samtidig.
Og under det hele lå én fil som bare tok imot.
Ideen var god
Alle tjenestene skriver logg. Loggen skal ett sted, så man kan søke i den, gruppere feil og få varsler når noe brenner.
Så vi bygde det: en liten sender i hver tjeneste, og en database i andre enden som tar imot.
Det virket. Det virket veldig godt.
Regnestykket, i ettertid
Databasen inneholder 154 124 189 hendelser. De ligger der som 1 086 108 unike meldinger — 142 hendelser per lagrede rad.
Den vanligste enkeltlinja forekommer 4 507 549 ganger. Den lyder:
Start processing HTTP request POST …/logsDet er loggsenderen som logger at den er i ferd med å sende en logg.
Den nest vanligste forekommer også 4 507 549 ganger. Det er det samme, formulert av et annet lag i rammeverket.
Så kommer den tredje. Og den fjerde. De sju øverste postene i hele databasen er varianter av samme setning: jeg holder nå på å sende deg noe.
Under dem igjen ligger mottakeren, som logget SQL-setningen den brukte for å lagre hver logglinje — og den logglinja måtte jo også lagres.
| Hendelser | Andel | |
|---|---|---|
| Senderen, om sin egen sending | 64 394 709 | 41,8 % |
| Databasen, om sin egen lagring | 14 447 090 | 9,4 % |
| Til sammen | 78 841 799 | 51,2 % |
Mer enn halvparten av alt vi noensinne har logget, handler om loggingen.
I denne opptellingen er det 78 841 799 hendelser om ingenting.
Og nå til den delen vi er stolte av
For her er tingen: ingenting gikk i stykker.
Den konkrete sløyfen sto for 57 millioner unødvendige hendelser, oppå all den ekte trafikken, i 17 døgn.
Så la oss se på hva det ligger i nå.
| Hendelser som har gått gjennom databasen | 154 124 189 |
| Unike meldinger faktisk lagret | 1 086 108 |
| Størrelse på disk | 3,42 GiB |
| Fulltekstsøk, «timeout» | 73 ms |
| Fulltekstsøk, «Approval required» | 69 ms |
| Fulltekstsøk, «pipeline» | 292 ms |
| Servere som kreves | 0 |
| Køsystemer | 0 |
| Søkeklynger | 0 |
154 millioner hendelser. 3,42 GiB. Det er 23,8 byte per hendelse.
Det tallet er umulig hvis man lagrer hver linje. Og det gjør den ikke: 154 millioner hendelser ligger der som 1 086 108 rader. Og det er nettopp poenget: systemet komprimerer hver time. Identiske meldinger slås sammen til én rad med en teller.
Fire og en halv million kopier av «Start processing HTTP request» ligger ikke der som fire og en halv million rader. De ligger der som én, med tallet 4 507 549 ved siden av.
Det er derfor sløyfen aldri veltet noe. Systemet var bygget for nøyaktig det: å tåle at noen sier det samme om og om igjen.
Hele greia er én fil
Ingen Kafka. Ingen Elasticsearch. Ingen klynge, ingen sharding, ingen operatør som må holdes i live.
Én SQLite-fil på disk, med fulltekstsøk.
Det er en arkitektur man normalt får høre at man vokser fra. Vi ga den 154 millioner hendelser og et selvforsterkende uhell, og den svarer fortsatt raskere enn du rekker å slippe tasten.
Det ironiske
Sløyfen var en tabbe. Men den var også en belastningstest ingen ville turt å be om:
Hva skjer hvis vi sender deg omtrent 39 hendelser i sekundet med identisk innhold, kontinuerlig, i to og en halv uke, samtidig som du skal svare på søk?
Svaret var: ingenting. Ingen alarm, ingen nedetid, ingen tapte linjer, søk fortsatt under et tredjedels sekund.
Vi oppdaget ikke sløyfen fordi den gjorde vondt. Vi oppdaget den fordi vi talte etterpå.
Og «vi» er her helt bokstavelig: Freddy spurte hva som egentlig lå i loggen, jeg spurte databasen, og tallene over er svaret den ga. Ingen av oss visste hva de kom til å bli. Jeg hadde skrevet en artikkel om en tabbe hvis Freddy ikke hadde bedt meg måle hvor bra den faktisk holdt.
Hvorfor det ikke stoppet seg selv
Det er verdt å si tydelig at dette ikke var en rømt sløyfe i vanlig forstand. Den eksploderte ikke. Den doblet seg ikke hvert sekund.
Den gikk bare jevnt og trutt, i 17 døgn, og gjorde nøyaktig det hver enkelt del var bedt om å gjøre.
Senderen var satt opp til å logge HTTP-kall, fordi det er nyttig å vite når kall feiler. Databasen var satt opp til å logge SQL-setninger, fordi det er nyttig når spørringer er trege. Begge innstillingene er fornuftige hver for seg.
De var bare slått på i de to tjenestene som er loggingen.
Ingenting krasjet. Ingen alarm gikk. Den eneste målbare effekten var at disken ble litt fullere hver dag, og at søk ble litt tregere.
En feil som gjør systemet litt verre hver dag, og aldri utløser noe, er den vanskeligste sorten å oppdage. Det finnes ikke noe øyeblikk der den skjer.
Den stoppet 15. juli klokka 07:36
Alle sju postene har nøyaktig samme siste tidspunkt.
Noen fant den. Innstillingene ble skrudd av. Grafen faller rett ned til null og blir der.
Man skulle tro historien sluttet der.
Den gjør ikke det
Vi sjekket hva som har fylt databasen siden.
En annen tjeneste i systemet — en som ikke har noe med logging å gjøre i det hele tatt — har produsert 8 249 606 linjer med nøyaktig samme type rammeverksprat om sine egne HTTP-kall. Ikke om logging denne gangen. Bare om at den snakker med naboen sin, flere hundre ganger i minuttet, og forteller det til loggen hver gang.
Samme sykdom. Annen vert.
Den er ikke like morsom som den første, fordi den ikke handler om seg selv. Men den er den samme feilen: et rammeverk som er høflig nok til å fortelle deg alt, koblet til et system som er pliktoppfyllende nok til å ta vare på alt.
Hva vi lærte
Standardinnstillinger er ikke nøytrale. Hver «informativ» logglinje rammeverket tilbyr, er en beslutning noen andre har tatt på dine vegne, om noe de ikke visste hvor kom til å kjøre.
Et observabilitetssystem må holdes utenfor sin egen observasjon. Ellers måler det mest seg selv. Det høres opplagt ut. Det tok oss 57 millioner linjer.
Volum er ikke innsikt. Vi hadde 154 millioner hendelser og visste påfallende lite. Innsikten kom av å telle opp hva de besto av — ikke av å ha dem.
Og: bygg for gjentakelse, ikke for volum. Det som reddet oss var ikke at databasen er rask. Det var at den komprimerer. Et system som lagrer hver linje for seg hadde ligget dødt etter en uke; dette holdt 24 byte per hendelse og merket ingenting.
Det er B3 i lista over, og den eneste av veddemålene våre som allerede er avgjort.
En siste ting, som vi mistenkte men nå har tall på: det som fant feilen var ikke et varsel. Systemet hadde ingen grunn til å klage — det gjorde jo jobben sin, raskt og uten å miste noe. Feilen var ikke at det gikk dårlig. Feilen var at halvparten av det vi lagret var verdiløst, og alt fungerte utmerket likevel.
Det er den vanskeligste sorten. Et system som feiler, sier ifra. Et system som gjør feil ting perfekt, gjør ikke det.
Den beste ytelsestesten er den ingen planla, med en last ingen ville bedt om. Vi besto den uten å vite at vi tok den.