„Kritická chyba #424, přehazuji ji na tebe, musí to být opraveno ASAP!“, píše projektový manažer v pátek v 17:30. „Bude to určitě na chvilku“, dodá bodře a vy mu v duchu obouváte španělské boty. Tuto situaci jistě každý správný vývojář důvěrně zná. Nejen v tomto případě oceníte, pokud ze systému dokážete získat co nejvíce informací o okolnostech chyby, abyste následně bug překlasifikovali na enhancement/invalid a ve 23:57 odjeli vítězoslavně poslední tramvají domů.
Na následujících řádcích se pokusím shrnout, co všechno, proč a kde monitorujeme v bankovním systému, na jehož tvorbě se podílím. Získané postřehy jsou aplikovatelné nejen v bankovnictví, ale v podstatě v každé větší databázové aplikaci napsané v PL/SQL.
Custom-logging aneb – „do téhle větve se nikdy nemůžeme dostat“
Základním pomocníkem při opravě chyb jsou ladicí výpisy, které ukládáme do samostatné tabulky. Množství zapisovaných informací regulujeme globálním nastavením úrovně logování. V případě potřeby lze pomocí parametrizace nastavit logování na úrovni jednotlivých metod. Zápis probíhá v autonomní transakci (PRAGMA AUTONOMOUSTRANSACTION), abychom zajistili perzistenci v případě rollbacku. Dojde-li k výjimce, zalogujeme výstupy funkcí DBMSUTILITY.FORMATERRORBACKTRACE, DBMSUTILITY.FORMATCALL_STACK.
Tedy informací více než dost, s chutí do toho. V bugu nepříliš překvapivě není uveden čas, kdy k chybě došlo, zkusíme přílohy. První obsahuje dvě idčka v zazipovaném xlsx souboru, na což velkoryse reaguji pouze drobným tikem v obličeji. Druhou přílohu zkušený uživatel vytvořil nafocením obrazovky na mobilní telefon. Bingo – kromě obecné chybové hlášky z našeho systému a dalších dvou tabů s domácími elektrospotřebiči a facebookem jsou v rohu screenshotu i hodiny.
Pouštím jeden ze své sady archivních selectů, která dělá z junior programátorů senior programátory. Ten by měl v tabulce s ladicími výpisy dohledat logy z daného času. Po chvíli neúspěšného čekání na výsledek zkoumám pomocí příkazu explain plan exekuční plán, kterým je dotaz prováděn. Vida, fullscan – u větších klientů nad tabulkou nejsou žádné indexy kvůli zrychlení insertu (i za cenu fullscanu, tj. procházení celé tabulky při dotazování). Pokud do indexu vkládáte více za sebou následujících záznamů najednou (typicky jde o syntetický identifikátor řádků, Oracle pro jeho vytváření používá tzv. sekvence, MySQL auto increment), při zápisu může nastat problém, neboť po sobě jdoucí záznamy se budou ukládat do stejných datových bloků. Problém lze vyřešit použitím reverzního indexu, který zajistí rozprostření záznamů do více bloků. Reverzní index bohužel neumožňuje efektivně dohledávat záznamy z daného rozsahu, je použitelný pouze k hledání konkrétního záznamu, což jej pro naše účely diskvalifikuje – jeden řádek z logu nám opravdu nestačí.
Chvíli uvažuji o zrušení dotazu a přidání /*+ parallel */ hintu, pak si ale vzpomenu na smrtící pohled našeho DBA, když jsem posledně neuvedl maximální povolený stupeň paralelizace, a jdu si raději zahrát ping-pong, než select doběhne.
Select nic nenašel, vítězství v ping-pongu je mi slabou útěchou. Chvíli vzpomínám, k čemu je sloupeček instanceid. Při nasazení v RACu (tedy běží-li databáze na více strojích najednou) se úzkým hrdlem ukázal být interconnect mezi jednotlivými nody, sdílení datových bloků. Pomohlo rozdělení tabulky na partice podle toho, z jakého uzlu pochází zapisovaný záznam (informace dostupná v proměnné dbmsutility.currentinstance), každý stroj tak loguje do vlastní partice. Exportovací job běží na každém stroji zvlášť, vždy pracuje pouze s konkrétní particí, ke sdílení bloků tak nedochází (částečnou analogií je tzv. sticky session při load balancingu).
Ne že by sloupeček instanceid nějak souvisel s prázdným výsledkem selectu. No samozřejmě – bug byl zadán včera, jelikož tabulka poměrně rychle nabírá na velikosti, dochází na denní bázi k exportu na disk. Pomocí superpuTTy se připojuji na server a zkouším grepovat. Neúspěšně.
Když to nejde jinak, aneb víme všechno o všem
Co se týče monitorování změn v datech, umožňuje systém dohledat de facto cokoliv. Při buildu prostředí na základě parametrizace generujeme ON INSERT/UPDATE/DELETE triggery, které ukládají informace o změnách do auditovací tabulky. Jedná se o tzv. value-based auditing, tedy evidujeme přímo konkrétní řádky, nikoliv pouze spuštěné dotazy.
Parametrizace obsahuje black-list sloupců/tabulek, které nechceme tímto způsobem auditovat (například auditovací tabulku samotnou, jak bystrý čtenář jistě nahlédne). Bohužel i mnou hledaný sloupec nacházím na black-listu. V svn pomocí funkce blame zjišťuji autora a volám mu s poděkováním za tento skvělý commit. V průběhu vypjatého hovoru mimo jiné zjišťuji, že na mém rootnutém telefonu nefunguje mute mikrofonu, to poté, co mi kolega začne odpovídat na nadávky.
Logování pro uživatele
Chvíli trávím porovnáváním výhod práce popeláře a programátora, za stavu 4:1 si vzpomenu, že máme další logovací tabulku. Jelikož dosud zmíněné tabulky se kvůli velikosti pravidelně exportují na disk, nejsou historické záznamy pro aplikaci dostupné. Proto změny dat, které potřebujeme kvůli reportům, logujeme zvlášť. Všechny entity pohromadě, trochu jako u EAV modelu (viz např. Wikipedie zde). Zase nic.
Logování uživatelských akcí aneb „Opravdu jste na ten odkaz neklikl dvakrát?“
U každého požadavku na server evidujeme čas, uživatele, POST parametry a URL, na kterou uživatel přistupoval. Jelikož při opakovaném přístupu na stejnou URL dochází k duplicitnímu ukládání dat, adresy samotné následně jobem převádíme do samostatného číselníku, v původní tabulce zůstane pouze cizí klíč ve sloupečku idurl. Job používá pro dohledání záznamů ke zpracování sloupeček compressionneeded s hodnotami Y (ano) nebo null (ne), který po zpracování nulluje. Použití null hodnot namísto hodnoty N vede ke zmenšení velikosti indexu, alternativou by bylo použít funkční index, jehož funkce bude pro již zpracované řádky vracet hodnotu null.
Spojením dat z logů se dvěma plechovkami energetického nápoje se dobírám ke kýženému výsledku – jde o chybu uživatele. Částečně. Nemá tam co klikat. No možná to raději opravím.
„Konečně!“, úlevou vdechnu hrnek s kávou. Po čtyřech hodinách hledání následuje oprava jednoho řádku kódu, jak se říká: „Jeden dolar za utažení šroubku, 199 dolarů za to, že jsem věděl, který šroubek utáhnout“.
Postupujete u vás ve firmě při řešení chyb jinak? Podělte se o názor v diskuzi.