De Caribische klusketen Kooyman worstelde met een probleem. De kassasystemen vielen regelmatig uit – allemaal tegelijk, in alle megastores op 5 eilanden. Verschillende partijen hadden al geprobeerd de oorzaak te vinden. Niets hielp. Wij vonden die ene oplossing die tot nu toe aan ieders aandacht was ontsnapt.
Klusketen Kooyman is een begrip op de Caribische eilanden. In de 7 megastores verspreid over 5 eilanden werken 650 medewerkers. Een succesvol bedrijf, maar de omzet werd gedrukt door het feit dat er regelmatig lange rijen in de winkels stonden omdat er niet meer betaald kon worden. Juist op de drukste zaterdagmiddagen stonden er regelmatig volle winkelwagens verlaten in de winkel. Klanten wilden niet langer wachten en waren vertrokken.
Crisis met prio 1
Zo kwam Kooyman bij ons uit. Konden wij onderzoeken of het probleem op databaseniveau zat? Edward Dortland, medeoprichter van Twintos: “We zetten er direct een team op; dit was wat ons betrof een crisis met prio 1. Dit moest nú opgelost worden, dachten wij. We hadden nog nooit met dit kassasysteem gewerkt. Toch waren we nog maar 2 uur bezig met ons eerste onderzoek toen we merkten dat er van alles aan de hand was dat al veel langer speelde.”
Kooyman was echt radeloos en murw geraakt door de hele situatie.
Niemand kwam eruit
Klopt, zei Kooyman. Dit probleem speelde inderdaad al langer – zeker een jaar. Edward: “Wij vielen van onze stoel, dat zo’n ernstige situatie al zo lang voortduurde. Vele partijen bleken al te hebben gezocht naar de oorzaak; specialisten, adviseurs, de fabrikant van de automaten. Niemand kwam eruit. Kooyman was echt radeloos en zo murw geraakt door de hele situatie dat we niet eens direct hoorden hoe lang ze hier al mee worstelden.”
Alle informatie op slot
Een onoplosbaar probleem. Nu was het voor Twintos nog interessanter om de oorzaak te vinden. Edward: “We vermoedden al wel dat het probleem op databaseniveau zat. Sommige transacties duurden langer dan de andere; 10 à 20 seconden. We zagen dat er op bepaalde momenten tabellen gelocked werden door een kassa. In de tussentijd konden de andere kassa’s hun transacties niet wegschrijven. Dat is op zich niet gek, maar bij Kooyman zou hier weleens het probleem kunnen zitten. Onze hypothese was dat iets ervoor zorgde dat sommige transacties bijzonder lang duurden, waardoor in die tijd alle kassa’s moesten wachten.”
Maar wat?
Er bleef maar één mogelijkheid over
Al snel merkten we dat onze hypothese niet aan te tonen was met de standaardmethoden. Edward: “Alle kassasystemen in elke vestiging maakten een connectie naar een webservice. Deze service maakte gebruik van Multiple Active Result Sets (MARS), een functie van ADO.NET, wat weer een systeem van Microsoft is voor toegang tot databronnen als SQL Server.”
MARS zorgt ervoor dat meerdere requests parallel over een SQL-connectie worden uitgevoerd. Dat maakte het zeer lastig om te zien welke requests nu bleven hangen. Er bleef maar één mogelijkheid over. Edward: “We besloten om alle kassa’s 100% te loggen. Alle transacties die de kassa’s genereerden lieten we vastleggen.”
We vonden een set queries waarbij telkens een flinke pauze zat tussen het eindigen van de ene en het starten van de andere. Soms minutenlang.
We ontwikkelen een automatische analyse
Op piekmomenten kwam er wel 50 gigabyte per uur aan data binnen. Onmogelijk om met de hand te analyseren natuurlijk. Edward: “Daarom stelden we een alert in die bijhield of een kassa langer dan 10 seconden moest wachten op een transactie die geblokkeerd was. We hebben een script gemaakt dat uitgevoerd werd op het moment dat de alert afging. Het script verzamelde alle transacties met bijbehorende requests en plaatste ze in een transactioneel chronologische volgorde.”
Edward: “Na analyse bleek telkens dat geen enkel request traag was. Maar toen zagen we het patroon. Telkens als het mis ging, vonden we een set queries waarbij er tussen het eindigen van de ene en het starten van de andere een flinke pauze zat. Soms minutenlang. Deze tijden kwamen overeen met de vertraging die in de winkels werd ervaren.”
Zou het probleem kunnen zijn dat de webservice tijdens een databasetransactie iets anders deed? Edward: “Om dat te toetsen lieten we een debugger meelopen op het webserviceproces. Daarnaast maakten we een set van Extended Events, een SQL-functie voor het monitoren van processen. Deze set zorgde ervoor dat alles gelogd werd zodra er transacties werden geopend waarbij er tussen twee requests lange pauzes zaten. Ook lieten we de debugger automatisch een memory dump maken wanneer deze situatie zich voordeed.”
Dit is niet waar je mee begint, alle kassa’s loggen. We overtuigden de klant om het toch te doen door eerst systematisch heel veel andere oorzaken uit te sluiten.
Onze hypothese klopte
Daarna was het wachten op de eerstvolgende storing. Onze hypothese bleek juist te zijn. Want telkens als alle kassa’s op tilt gingen, kregen wij logbestanden uit de nieuwe Extended Events. Vervolgens haalden we de exacte start- en eindtijden van de transactie en de pauzemomenten uit de Extended Event logs. We stuurden dit samen met de dump file op naar de softwareleverancier die vervolgens zijn analyse kon doen.
Creditcheck op Kooyman HQ
Wat er gebeurde, was dat er zo nu en dan een klant tussen zat die op rekening kon betalen. Als zo’n klant afrekende, werd er eens in de zoveel tijd een creditcheck gedaan op Kooyman HQ. Dat is normaal een snel proces, maar op de Caribische eilanden kan het internet soms traag zijn.
Het probleem: de oproep naar de API voor de creditcheck werd binnen de openstaande databasetransactie uitgevoerd. Terwijl die ene kassa wachtte op de creditcheck, blokkeerde deze alle andere kassa’s, op alle eilanden en in alle vestigingen van Kooyman. En op drukke middagen kon het regelmatig voorkomen dat er verspreid over de 5 eilanden voor meerdere klanten creditchecks uitgevoerd werden, die allemaal de kassa’s tijdelijk blokkeerden.
Probleem opgelost
We hebben de developer van de kassa’s geadviseerd om de volgorde te veranderen, zodat de creditcheck niet langer het hele afrekenproces ophoudt. Daarna is dit probleem nooit meer voorgekomen.
Zulk detectivewerk kun je soms alleen maar doen als je alle data maximaal opslaat. Een ingrijpende keuze. Edward: “Dit is niet waar je mee begint, alle kassa’s loggen. Maar voor Kooyman was dit probleem inmiddels zo groot – het drukte serieus op de omzet. We overtuigden de klant van de noodzaak van logging door eerst systematisch heel veel andere oorzaken uit te sluiten en door met een solide methodiek te komen.”
Een uitzonderlijk project, en ook een erekwestie. We vonden het onacceptabel dat Kooyman al zo lang worstelde met dit probleem. Daarom wilden we dit ogenschijnlijk onoplosbare mysterie ophelderen.
Komt je organisatie krakend tot stilstand doordat informatie niet goed kan stromen?
Neem contact op met Twintos. We nemen je uitdaging graag aan.