Felsökning på Arlanda

Jag fick ett samtal från min chef:

Jens, we need you in Hemel Hempstead. We have prospective customer with a system that keeps crashing. Get your ass up there, first thing tomorrow morning.

Det här var för samma företag, jag berättade om i mitt förra nyhetsbrev, dock cirka ett halvår senare.

Jag bokade in mig på första morgonflyget från Arlanda. Väl på terminal 2, nästa morgon fick jag veta att planet skulle be bli tre timmar försenat!

Efter att kopplat upp mig på wifi, var jag i kontakt med en kollega som bodde i närheten och kunde ta sig till kunden på morgonkvisten. Hon hade varit där redan dagen innan och samlat på sig loggfiler och annat analysmaterial. Jag bad henne maila över det hon hade så jag kunde försöka göra det bästa av situationen.

Efter att rotat runt bland de filer jag fått, började jag bilda mig en uppfattning om vad som eventuellt var fel. Med detta som utgångspunkt skapade jag en power-point, med analys och ett förslag på första åtgärd.

Så småningom kom planet iväg och några timmar senare landade det på Heathrow utan vidare missöden. På flygplatsen stod vår account manager och mötte upp, för att sen i ilfart köra på M25:an upp till Hemel Hempstead och kunden.

Väl på plats, började vi med ett introduktionsmöte där jag presenterade mina analyser och misstankar om vad som var problemet. På Arlanda hade jag noterat en befängd mängd av exceptions liknande

com.bea.p13n.rules.manager.RuleSetNotFoundException: 
The rule set with URI /portalApp/xyzportal/everyone/PortalPage/AD.xml could not be located by 
the class named com.bea.p13n.entitlements.accessdecision.internal.JDBCRuleSetRepository

Efter att kört ett last-test under en timme kunde vi konstatera att så verkligen var fallet. Bilden nedan visar en absurd mängd av exceptions.

Det hade blivit sen kväll och vi startade också ett last-test att pågå under natten. Dagen efter kunde vi konstatera att den stora mängden exceptions också skapade minnesläckage, vilket efter några dagar skulle kraschar hela systemet. Bilden nedan visar en korrelation mellan CPU Utilization %, Error Count samt Heap Size

Så här långt, visste vi att alla exceptions var kopplade till databas-anrop (JDBCRuleSetRepository). Men frågan var; Hur kunde det uppstå en sådan massiv mängd exceptions? Korrelerat med antalet anrop per tidsenhet (15 sekunder i vårt verktyg), så var det svårt att förstå.

Med hjälp av transaction-viewer verktyget kunde jag sen visa konkret hur det såg ut. Bilden nedan visar hur ett enstaka HTTP anrop tar mer än 48 sekunder (48631 ms). Alla blåa vertikala staplar utgörs av JDBC anrop, initierade av EJB objekt. Varje individuellt anrop tog några tiotal millisekunder, men tusentals av dessa adderar tillsammans en substantiell svarstid.

Den prospektiva kunden hade blivit djupt imponerad av att vi kunde identifiera deras problem så snabbt och dessutom ha en bra uppfattning om orsaken redan innan ankomst, så de skrev på. Detta kom att bli den största ordern i EMEA det året 😎