Dekompilering och felsökning i Oslo

Jag fick ett meddelande från min chef:

Jens, we need you in Oslo. The customer cannot scale their new banking system, which is scheduled for deployment next month. Jump on a plane, go by train, ride on a horse or just hitchhike; but get your ass there A.S.A.P. and help them out.

Det här var för samma företag, jag berättat om i tidigare nyhetsbrev/bloggartiklar. Saken var den att vår produkt utförde systemövervakning i real-tid av stora Java EE applikationer. Kunderna fanns primärt inom bank, finans, tele-operatörer och andra internationella företag med mycket stora Java system. Mitt jobb var att bygga kundanpassade lösningar (då standard inte fungerade), samt utföra problemanalyser av krånglande system hos både befintliga och tilltänkta kunder.

Jag gjorde ett snabbt överslag och insåg att lifta från Stockholm till Oslo, skulle ta för lång tid och någon häst hade jag inte heller..., så det fick i stället bli ARN till OSL i tre kvart.

Var försvann svarstiden på väg från en server till nästa?

Efter en kort introduktion hos kunden, där de förklarade att de inte kunde öka antalet samtidiga HTTP anrop till tjänsten vid last-testning utan det stannade på en orimligt låg nivå, så installerade jag vår programvara och vi började belasta systemet med syntetisk trafik.

Topologin för testmiljön var två WLS applikationsservrar, en front-end kallat Portal och en back-end kallat CMS. Jag hade instrumenterat mätpunkter på båda servrarna. Ganska snart kunde vi se ett märkligt mönster i responstiden.

Bilden ovan plottar tiden för utgående anrop från Portal till CMS (svart), samt svarstiden för inkommande anrop hos CMS (rosa). Min första hypotes var att problemet låg i nätverket, eftersom servrarna låg i olika subnets. Efter en smörgåslunch (ja, så äter man lunch i Norge) och omkonfigurering, kunde jag avfärda den hypotesen.

Hur kunde en oansenlig funktion tas så mycket tid?

Jag började då analysera vilka Java metoder som tog för lång tid, genom att sätta ett tröskelvärde på svarstiden för alla metoder och filtrera fram dem som tog längre tid än 20 sekunder.

Bilden ovan visar svarstiden för några metoder som tar lång tid. Det som var förbluffande och oväntat i diagrammet var den metod som stack ut mest; nämligen hashCode(). Denna anropas enbart vid access i en java.util.HashMap (eller HashSet) och förväntas ta någon millisekund eller så.

Klassen med hashCode() tillhörde ett bibliotek för anrop av klassiska webbtjänster (SOAP Web Services Client), som i sin tur var en liten komponent i ett CMS system back-end servern använde.

Problemets kärna - Serialiserad åtkomst

Jag fiskade fram bibliotekets JAR fil och dekompilerade klassen i fråga, samt studerade den genererade källkoden. Så här såg själva metod-deklarationen ut.

public synchronized int hashCode() {...}

Att den är markerad som synchronized betyder att högst en tråd (thread) i taget kan exekvera koden. Inuti metoden fanns en for-loop som itererade över en byte array, där storleken vanligtvis var några kilobyte eller enstaka megabyte.

byte[] item = getBinaryitem()
for(int j = 0; j < Array.getLength(item); j++) {
    Object obj = Array.get(item, j); //(*)
    if (obj != null && !obj.getClass().isArray()) 
        i += obj.hashCode(); //(**)
}
return i

Raden ovan märkt med (*) har effekten

Object obj = new java.lang.Byte( item[j] );

Raden ovan märkt med (**) har effekten

i += (int)item[j]

Klassen koden kommer ifrån representerade innehållet i ett hämtat dokument, såsom PDF eller liknande. Koden ovan, således itererade över cirka en miljon bytes och skapade lika många Byte object, för att sen summera ihop de numeriska värdena och använda summan som hash-värde.

När hundratals trådar försöker utföra samma operation och de tvingas göra detta en i taget, så skapas en så kallad synchronization hot-spot. Detta var alltså källan till prestanda problemet.

Temporär fix

För att testa denna hypotes, uppdaterade jag implementation av hashCode(), så att ett slumptalsvärde genererades i konstruktorn och användes som hash-värde. Detta var enbart tänkt som eliminering av den minnes-slösande och tidskrävande loopen, inte som förbättrad kod då den nya koden inte tog hänsyn till vilken fil som cachades.

Med den patchade JAR-filen på plats, körde vi lasttestet på nytt. Denna gång kunde vi skruva upp antalet simulerade anrop med flera hundra!

Med detta analysarbete som grund, kunde kunden efter mitt besök kontakta leverantören med en buggrapport och indikation om vad som behövde fixas. Med tiden blev detta verktyg/bibliotek populärt och framgångsrikt, samt blev förvärvat av Oracle flera år senare.

Lärdomar

De lärdomar man kan dra av detta är att aldrig underskatta problem som uppstår i fler-trådade (multi-threaded) system vid hög trafik-belastning och att testa både korrekt funktionalitet och hur systemet beter sig vid ökad trafiklast. Det man gör är att öka trafiken tills systemet börjar "krokna" och sen avgöra om detta är tillräcklig kapacitet eller ej.