margin-top: 125px; border: 1px solid gray; } -->

Logování aneb po stopách bugu #424

Jiří Sláma , 20. srpen 2013 09:00 9 komentářů
Logování aneb po stopách bugu #424

"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 AUTONOMOUS_TRANSACTION), abychom zajistili perzistenci v případě rollbacku. Dojde-li k výjimce, zalogujeme výstupy funkcí DBMS_UTILITY.FORMAT_ERROR_BACKTRACE, DBMS_UTILITY.FORMAT_CALL_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é dbms_utility.current_instance), 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.

Jiří Sláma

Autor pracuje jako Development Team Leader ve společnosti Arbes Technologies s. r. o.


Komentáře

Mirek #1
Mirek 20. srpen 2013 09:56

To je moc pěknej článek. Občas to jsou detektivky. :-)

Pavel #2
Pavel 21. srpen 2013 10:27

Skvelý článok, ďakujem p. Slámovi.

Ivan #3
Ivan 21. srpen 2013 10:44

A predpokladám, že článok si napísal počas čakania na select :)

Pepino #4
Pepino 28. srpen 2013 11:08

... cloveka potesi, kdyz zjisti ze neni sam ;-)

BrainLess #5
BrainLess 06. září 2013 12:56

Ty ON UPDATE/INSERT triggery to bude peformance boost jako prase :-) za to bych vam utrhl hlavu.

Honza #6
Honza 02. říjen 2013 00:05

Jirko, hlavně zůstaň programátorem. Popelář to má asi jednodušší, ale zase musí vztávat v 5 ráno a od oběda nemá do čeho píchnout :-)

Honza #7
Honza 02. říjen 2013 00:06

Sorry, oprava "vstávat"

<>"';! #8
<>"';! 30. říjen 2013 11:17

<>"';!

asdasd #9
asdasd 30. říjen 2013 11:18

';!--<you suck>=&{()}


RSS 

Komentujeme

Chatbot mluví za mrtvého – od nápadu k realizaci

Pavel Houser , 30. listopad 2016 13:00
Pavel Houser

Na webu The Verge popsala Casey Newton příběh dvou přátel (Eugenia Kuyda a Roman Mazurenko). Peripet...

Více





Kalendář

20. 03.

24. 03.
CeBIT 2017
RSS 

Zprávičky

Nový zákon o výzkumu chystá "blacklist" příjemců i ministerstvo

ČTK , 09. prosinec 2016 16:31

Velké změny ve fungování Grantové a Technologické agentury, novou vědeckou radu ČR i takzvaný "black...

Více 0 komentářů

Fitbit koupil průkopníka chytrých hodinek Pebble

ČTK , 09. prosinec 2016 15:00

Americký výrobce chytrých náramků a hodinek Fitbit koupil software, patenty a další aktiva duševního...

Více 0 komentářů

Američané možná umožní v letadlech telefonování přes wi-fi

ČTK , 09. prosinec 2016 13:00

Aerolinky ve Spojených státech by v budoucnu mohly umožňovat telefonování v letadle s použitím wi-fi...

Více 2 komentářů

Starší zprávičky

Česká pošta od ledna zdraží posílání do zahraničí o pět až 20 Kč

ČTK , 09. prosinec 2016 11:39

Česká pošta od ledna zvýší ceny za posílání listovních zásilek do zahraničí o pět korun, balíky podr...

Více 0 komentářů

Za vzněcováním smartphonu iPhone 6 jsou vnější vlivy, tvrdí Apple

ČTK , 08. prosinec 2016 11:30

Firma Apple odmítla podezření čínských uživatelů svého chytrého telefonu iPhone 6, že za problémy s ...

Více 0 komentářů

Verizon prodá firmě Equinix datová centra za 3,6 miliardy USD

ČTK , 08. prosinec 2016 10:00

Největší americký mobilní operátor Verizon Communications prodá specializované společnosti Equinix 2...

Více 0 komentářů

Tchajwanský Foxconn jedná o rozšíření svých aktivit v USA

ČTK , 07. prosinec 2016 15:00

Tchajwanská společnost Foxconn jedná o rozšíření svých aktivit ve Spojených státech. Oznámila to dne...

Více 0 komentářů