Basic personligt

Daniels personliga blogg

Värsta buggen

Det här inlägget kanske hör bättre hemma på min teknikblogg, men det börjar bli ganska många tekniskt lagda inlägg här ändå.

I höstas så var det en kund som började få problem med vår applikation. Helt plötsligt så slutade den svara, och enda sättet att få igång trafiken igen var att döda processen och starta om den. I vår värld är sådant helt oacceptabelt (och kallas hånfullt för en ”microsoftlösning”), så jag bad om logfiler och började analysera. Den stannade flera gånger, så jag fick många logfiler att gräva i. Tyvärr så gav det ingenting. De hade alla stannat på helt olika ställen. Några meddelanden hade blivit nekade, men det berodde på andra saker. Ibland var det sista meddelandet ok, och ibland med en felkod. Ibland stannade den efter att ha fått in ett meddelande, och ibland efter att ha fått svar att det kommit fram. Det fanns helt enkelt inga likheter som kunde ge någon ledtråd till vad som hade hänt. Det enda vi kunde rekommendera var en automatisk övervakare som startade om programmet vid behov.

Tiden gick, den fortsatte stanna emellanåt, alltid utan några gemensamma faktorer. Precis efter nyår fick jag några nya logfiler, och då började jag upptäcka ett mönster. Vårt program består av massor med olika delar som körs parallellt, dvs det är rejält multitrådat. Några av trådarna hör ihop i par, och kommunicerar väldigt mycket mellan varandra. I samtliga fall så var det en av dessa trådar som verkade ha försvunnit. Jag gjorde några ändringar så att den skulle upptäcka det här av sig själv och i så fall skapa en ny tråd.

Det gjorde ingen som helst skillnad. Den stannade numera istället minst en gång om dagen, så nu började kunden bli lite olycklig.

När jag höll på att gräva i en av de senaste logfilerna upptäckte jag äntligen en gemensam faktor. Den hade alltid varit mitt uppe i en databasoperation. För att göra livet lite enklare för databasen, framför allt för tidiga versioner av MySQL, kör vi bara en databasfråga i taget. Alla andra får vänta tills svaret har kommit tillbaka. Fördelen är att databasen bara behöver göra en sak i taget, men nackdelen är att de andra trådarna ibland behöver vänta i onödan. I praktiken gör det här ingenting eftersom MySQL svarar så pass snabbt på våra enkla operationer. Nu, av någon anledning, tog det plötsligt flera minuter innan det kom något svar. Vid det laget hade programmet tröttnat och ansett att något var fel, och struntat i svaret. Svaret kom tyvärr till slut, men när den försökte skicka tillbaka det så skrev den på ställen i minnet som den inte fick, och därefter dog hela programmet ganska snabbt. I ett fall tog det över en halvtimme innan svaret kom, och på den tiden hade det genererats en logfil på uppåt 100 MB. Logfilen är en textfil, och 100 MB motsvarar ungefär 1,3 miljoner rader, eller närmare 20 tusen fulla A4-sidor. Att se kopplingen mellan två händelser så långt ifrån varandra tog sin lilla tid.

Jag ändrade några saker till, varvid det blev ännu värre. Nu hann den knappt starta innan den dog, så det började bli panik. Jag loggade in på servern för att själv kunna experimentera med inställningar och se vad som hände i logfilen, men blev inte så mycket klokare för det. Jag körde två olika debuggers, vilket till slut visade vad som gick fel när det där superlångsamma svaret från databasen kom tillbaka och bekräftade min teori.

Frågan blev då varför det tog så lång tid ibland. Programmet kördes på en rejält snabb maskin, utan överdrivet mycket trafik, men ändå var den fullt belastad. Dessutom var databasen extremt långsam. Någonting var helt enkelt bara fel.

Jag kollade runt lite i filsystemet, varpå svaret blir uppenbart. De körde gamla ISAM-tabeller, istället för de nyare InnoDB. Även InnoDB är nu i äldsta laget, för jag tror att det finns åtminstone en eller kanske två olika tabelltyper som är ännu modernare och snabbare. ISAM lagrar varje tabell i en fil, och en av dem var vid det här laget 4.5 GB stor. Sådant är inte speciellt bra, för det gjorde att stackars ISAM-motorn var tvungen att flytta runt saker och ha sig för varje ny post som skulle in, eftersom vi har ganska många fält som ska indexeras. Till slut gick det helt enkelt inte längre.

Som en första fix så kopplades databasen bort, varpå trafiken flöt hur bra som helst. När tabellerna är flyttade till InnoDB ska databasen få vara med och leka igen.

De flesta andra buggar som dyker upp kan man framtidssäkra sig mot genom att skriva ett litet testprogram som försöker provocera fram buggen, och sedan köra alla sådana med jämna mellanrum och speciellt före en ny release. Men sådant här ligger ju på en helt annan nivå.

Andra bloggar om: , .

Annonser

februari 9, 2008 - Posted by | problemlösning, teknik

1 kommentar »

  1. Vad bra du förklarar. Jag förstod allt, och jag är sjukt dålig på både logik och teknik 🙂

    Kommentar av Linda Mpili | februari 9, 2008 | Svara


Kommentera

Fyll i dina uppgifter nedan eller klicka på en ikon för att logga in:

WordPress.com Logo

Du kommenterar med ditt WordPress.com-konto. Logga ut / Ändra )

Twitter-bild

Du kommenterar med ditt Twitter-konto. Logga ut / Ändra )

Facebook-foto

Du kommenterar med ditt Facebook-konto. Logga ut / Ändra )

Google+ photo

Du kommenterar med ditt Google+-konto. Logga ut / Ändra )

Ansluter till %s