D2000 DBManager - vyhodnocovanie logov

Základné informácie o logovaní procesu D2000 DBManager nájdete v tomto popise.

Tento dokument slúži na podrobnejší popis logovacích výpisov a ich použitie na:

  1. Hľadanie chýb v konfigurácii objektov typu Tabuľka v D2000 (chyba v definícii štruktúry)
  2. Hľadanie aplikačných chýb v ESL
  3. Vyladenie výkonnosti (nastavenie počtu spojení podľa potrieb aplikácie)
  4. Zisťovanie momentálneho stavu DBManagera TELL príkazmi

Väčšina nasledujúcich postupov predpokladá, že objekty typu Databáza sú nakonfigurované so zapnutou voľbou Debug. Odporúčame (pre D2000 verzie 7.01.022 a vyššie) zadať aj veľkosť logovacieho súboru (MB) pri voľbe Debug a nakonfigurovať tak logovanie akcií do separátneho súboru pre každú databázu. Veľkosť logovacieho súboru je potrebné nastaviť na dostatočne veľkú hodnotu, aby sa získali logovacie údaje pre dostatočne dlhé obdobie (logovací súbor DBManager.log má maximálnu veľkosť 10 MB). Je potrebné nechať DBManager bežať dostatočne dlhé obdobie, ktoré obsahuje aj dobu maximálnej záťaže systému (t.j. napr. 24 hodín počas bežného pracovného dňa). Takisto odporúčame nakonfigurovať pre proces SELF.DBM štartovací parameter /E+DBG.DBMANAGER na logovanie podrobností o vykonávaných operáciách.

1. Hľadanie chýb v konfigurácii objektov typu tabuľka

Z logov je možné zistiť nasledovné chyby:

  • tabuľka s daným názvom neexistuje
  • stĺpec v SQL tabuľke je textový a stĺpec v definícii štruktúry v D2000 je nie je textový
  • stĺpec v SQL tabuľke je nečíselný a stĺpec v definícii štruktúry v D2000 je číselný (pre D2000 verziu 7.01.022 a vyššie)

Okrem detekcie z logov DBManager-a je možné ručne otestovať funkčnosť tabuľky kliknutím na tlačidlo Test v konfigurácii objektu typu Tabuľka.

Predpoklad: DBManager beží dostatočne dlhú dobu, počas ktorej pristupoval (čítanie alebo zápis) ku všetkým tabuľkám, ktoré sa majú skontrolovať.

Hľadaný reťazec: Cannot get any result from SQLColumns

Príklad: 

13:42:28.960 08.02 *** Error in con 1:
13:42:28.962 08.02 con 1:[GetColumnDescript]
13:42:28.964 08.02 con 1:<HI ws1phum1 browser>
13:42:28.967 08.02 con 1:Cannot get any result from SQLColumns. Possible causes are: table "dba"."MAT_SKUPINAxx" 
does not exist in SQL database; table is not visible by defined user; table has not any column with name matching 
its structure definition in D2000

Riešenie: Skontrolovať, či:

  • tabuľka v SQL databáze existuje
  • je prístupná pod užívateľom, nakonfigurovaným na objekte typu Databáza, ktorý je rodičom objektu typu Tabuľka, ktorého sa chybová správa týka
  • má aspoň jeden stĺpec s rovnakým menom, ako definícia štruktúry pripojená v konfigurácii objektu typu Tabuľka (niektoré SQL databázy môžu rozlišovať veľké a malé písmená)
  • meno tabuľky v SQL databáze je zhodné s parametrom Tabuľka nakonfigurovaným na objekte typu Tabuľka (opäť pozor na prípadnú môžu rozlišovať veľké a malé písmená)

Hľadaný reťazec: text data mapped to non-text columns

Príklad: 

14:05:36.496 08.02 Table MAT_SKUPINA (DB.MAT_SKUPINA) text data mapped to non-text columns:NAZOV

Riešenie: Zjednotiť typ stĺpca v SQL databáze a v definícii štruktúry pripojenej v konfigurácii objektu typu Tabuľka. Stĺpec v SQL databáze je textového typu, stĺpec definície štruktúry v D2000 nie je typu Text. V takejto konfigurácii závisí od dát v konkrétnom stĺpci v tabuľke v SQL databáze, či sú skonvertovateľné na príslušný netextový typ (Celočíselný, Reálny a pod.) pri čítaní. Dôsledkom chýb pri konverzii môže byť napr.

  • pre OCI verziu DBManager-a: chýbanie hodnôt v stĺpci s chybnou hodnotou a vo všetkých nasledujúcich stĺpcoch pri čítaní tabuľky cez browser alebo pri stránkovom prístupe
  • pre ODBC verziu DBManager-a a databázu Sybase SQL Anywhere: neplatné hodnoty vo všetkých bunkách riadku, v ktorom sa vyskytuje chybná hodnota

Hľadaný reťazec: non-number data mapped to number columns

Príklad: 

15:47:29.976 08.02 Table Time_Test (DB.Cas) non-number data mapped to number columns:Cas,

Riešenie: Zjednotiť typ stĺpca v SQL databáze a v definícii štruktúry pripojenej v konfigurácii objektu typu Tabuľka. Stĺpec v SQL databáze je nečíselný, stĺpec definície štruktúry v D2000 je číselný (Celočíselný, Reálny alebo Relatívny čas). V takejto konfigurácii závisí od dát v konkrétnom stĺpci v tabuľke v SQL databáze, či sú skonvertovateľné na príslušný netextový typ (Celočíselný, Reálny a pod.) pri čítaní.

2. Hľadanie aplikačných chýb v ESL

Z logov je možné zistiť nasledovné chyby, ktoré sa prejavili ako ODBC alebo OCI chyba.

Hľadaný reťazec: *** Error in

Príklad:

OCI verzia:

21:00:11.961 07.02 *** Error in con 2:
21:00:11.962 07.02 con 2:<E.IOPT_Export: 95;  3624><E.IOPT_Scheduler: 32>
21:00:11.962 07.02 con 2:[InsertRecord] Execute: INSERT INTO "ROVE_IOPT"."S_IF_USER" ("IU_ID","IU_PERS_ID","IU_FS_ID","IU_DB_USER","IU_FIRSTNAME","IU_SURNAME","IU_APPL",
"IU_PWD_PERMANENT","IU_PWD_KONTO","IU_STATUS","IU_DELETE","IU_TADI_ID") VALUES (:1,:2,:3,:4,:5,:6,:7,:8,:9,:10,:11,:12) ,row 1,Exception name: 
OCI.THICK.LIB_ERROR
Message: ORA-01400: cannot insert NULL do ("IOPT"."IF_USER"."IU_FIRSTNAME")
ORA-06512: at line "IOPT.G_IF_USER_TB"
Call stack traceback locations:    0x51ae1e 0x51af63 0x5142c3 0x76e54b 0x772065 0x7d0536 0x7e2230 0x8219fa 0x77e64827

ODBC verzia:

16:22:18.474 08.02 *** Error in con 3:
16:22:18.475 08.02 con 3:[PrepareSqlStmt] SQLExecDirect: SELECT ID_MATERIAL FROM materialXX 
16:22:18.477 08.02 con 3:<S.sql_Test_Evil: 106>
16:22:18.478 08.02 con 3:(S0002) [Sybase][ODBC Driver][Adaptive Server Anywhere]Table 'materialXX' not found ErrorCode= -141

Riešenie: Analýza chyby (napr. vyhľadanie ORA-xxxxx chybovej správy, zistenie príčiny a odstránenie). Pokiaľ chyba vznikla napr. pri vkladaní konkrétnych hodnôt, odporúčame nakonfigurovať štartovací parameter /E+DBG.DBMANAGER.DATA pre proces SELF.DBM (logovanie hodnôt).

Príklad použitia:

15:20:21.659 08.02 Db SKEI_MES, con 2:PageInsert BEG
15:20:21.660 08.02 PositionedInsert: INSERT INTO "MES"."SOURCE_PLACE" ("ID","IDVECT","KOD","ADDR","NAME","SV_IDX", "WHX","SIMAODB","NTYP","ID_T")
VALUES (:1,:2,:3,:4,:5,:6,:7,:8,:9,:10,:11,:12,:13,:14,:15)
15:20:21.661 08.02 PositionedInsert time displayed in pure UTC (configured offset +0)
15:20:21.661 08.02 PositionedInsert data: 88; NULL; 'gsdaf.GPS'; NULL; 'fsgdfd.GPS'; 28; 1.00E+00; NULL; 10;  5;
15:20:21.667 08.02 *** Error in Db SKEI_MES, con 2:
15:20:21.668 08.02 Db SKEI_MES, con 2:<E.Max_ID: 133; 15><[] S.SchemeOM: 19; 135; 153>
15:20:21.668 08.02 Db SKEI_MES, con 2:[PositionedInsert] Execute/Commit "ROVE_MES"."ODBERNE_MIESTO":Exception name: OCI.THICK.LIB_ERROR
Message: ORA-01438: value larger than specified precision allowed for this column
Call stack traceback locations:
0x51b0ce 0x51b213 0x514573 0x767089 0x7ca8db 0x7cab31 0x7e01f8 0x81f71a 0x77e64827     
15:20:21.669 08.02 PositionedInsert end
15:20:21.669 08.02 Db SKEI_MES, con 2:PageInsert END

V tomto konkrétnom prípade pomohlo otvoriť browser a pokúsiť sa ručne vložiť to tabuľky vypisované hodnoty. Ukladanie prebehlo bez chyby až vtedy, keď hodnota v stĺpci "NTYP" bola menšia ako 10. Cez Oracle Enterprise Manager sa následne zistilo, že tento stĺpec bol omylom vytvorený v SQL databáze ako Number(1), t.j. číslo s rozsahom 1 číslice.

Hľadaný reťazec: timeout expired

Príklad:

10:03:44.597 17.02 WD: con 3: timeout expired 1 times in U_EXECDIRECT1/D_EXECDIRECT2

Spojenie číslo 3 vykonáva nejakú akciu (detailné výpisy U_EXECDIRECT1/D_EXECDIRECT2 sú určené pre vývojárov D2000, ale naznačujú, že pôjde asi o SQL_EXEC_DIRECT).
Po vyhľadaní prvého výskytu reťazca con 3 smerom dozadu od varovania vidieť, že posledný príkaz, ktorý sa začal vykonávať, bol 

10:02:16.864 17.02 con 3:SQL_EXEC_DIRECT BEG

Pokiaľ je zapnutá debug kategória DBG.DBMANAGER, vo výpise je aj konkrétny príkaz, ktorý sa vykonáva: 

10:02:16.865 17.02 ExecDirect: Delete from EDA_Vektor v WHERE ID_Vektor >= 2000000 AND id_vektor not in (select id_vektor from EDA_VEKTOR_SCENAR) AND not exists (SELECT f.id_vektor FROM EDA_Predpis_Funkcie f WHERE f.funkcia like '%' || v.meno || '%' )

3. Vyladenie výkonnosti (nastavenie počtu spojení podľa potrieb aplikácie)

Pri zapnutej voľbe Debug zapisuje DBManager do logu aj informácie o vytváraní, využívaní a ukončovaní spojení. Spojenie sa vytvára alebo prideľuje ako dôsledok nasledovných akcií:

Ostatné akcie používajú handle získané volaním akcií DB_TRANS_OPEN, DB_CONNECT, PG_CONNECT a SQL_CONNECT a musia prebiehať na tom spojení, s ktorým je handle zviazaný. Akcie DBS_* (včítane DBS_BLOB_*) spojenie použijú a hneď aj uvoľnia.
Existujú nasledovné hlášky týkajúce sa vytvárania a prideľovania automatických spojení:

Správa Popis
(X1) got free NTC Bolo použité automatické spojenie, ktoré je voľné (neexistuje žiaden handle zviazaný s týmto spojením).
(X2) has 3/7 NTC,reusing T con 4 Počet automatických spojení nedosiahol hodnotu nadefinovanú v konfigurácii Databázy a je k dispozícii voľné spojenie označené ako transakčné. Toto spojenie sa zmení na automatické (netransakčné) a použije sa.
(X3) has 3/7 NTC,creating new Počet automatických spojení nedosiahol hodnotu nadefinovanú v konfigurácii Databázy. Žiadne iné voľné spojenie (ani transakčné) nie je k dispozícii, a preto sa vytvára nové spojenie na databázu.
(X4) has 7/7 NTC,reusing con 5 Počet automatických spojení dosiahol hodnotu nadefinovanú v konfigurácii Databázy. Bude použité jedno z automatických spojení (aj keď žiadne nie je voľné, t.j. na každé je naviazaný aspoň jeden handle). Použije sa to spojenie, ktoré má najmenej požiadaviek vo fronte a prípadne má príznak not_busy (práve nespracúva žiadnu požiadavku).
(X5) has 7/7 NTC,not found any good, hardpanic! Napriek tomu, že počet automatických spojení dosiahol hodnotu nadefinovanú v konfigurácii Databázy, nenašlo sa žiadne použiteľné.
Tento stav sa mohol objaviť do verzie 7.01.023 hneď po reštarte DBManager-a, pokiaľ začali prichádzať požiadavky skôr, ako sa predpripravené spojenia stihli pripojiť k databáze (napr. pre Oracle databázu pripájanie môže trvať až niekoľko sekúnd) alebo pokiaľ je databáza nedostupná a pripojenie sa opakovane nedarí nadviazať.
Ďalšia možnosť výskytu je, ak je pri štarte DBManagera niektorá databáza vypnutá a následne počas behu DBManagera zapnutá a požiadavky na túto databázu prídu skôr, ako sa predpripravené spojenia pripoja na databázu (ak je databáza pri štarte DBManagera vypnutá, predpripravené spojenia s databázou sa nenadväzujú, ale čakajú, až databáza nebude vypnutá).
(X6) has 7 cons,limit is 7,can't create NTC, reusing con 1 Počet automatických spojení nedosiahol hodnotu nadefinovanú v konfigurácii Databázy, ale nie je možné vytvoriť nové spojenie, pretože počet všetkých spojení sa rovná Maximu spojení (t.j. ostatné spojenia sú použité ako transakčné). Bude použité jedno z automatických spojení podľa rovnakých pravidel ako v prípade X4.
(X7) has 7 cons,limit is 7,can't create NTC, not found any good, hardpanic! Počet automatických spojení nedosiahol hodnotu nadefinovanú v konfigurácii Databázy, ale nie je možné vytvoriť nové spojenie, pretože počet všetkých spojení sa rovná Maximu spojení. Zároveň sú všetky spojenia použité ako transakčné. Takýto prípad by nemal nastať, keďže jedno spojenie je vždy rezervované ako automatické.

Správy X4 a X6 neznamenajú, že požiadavky v DBManageri musia na seba čakať. Aj keď napr. niekoľko browserov používa to isté automatické spojenie, väčšinu času sa toto spojenie nevyužíva (kým užívateľ nedá načítať novú stránku alebo vykonať zmeny). Takže je tu iba možnosť, že viaceré akcie prídu tak tesne po sebe, že jedna bude čakať na vykonanie druhej.
Či k čakaniu dochádza, je možné sledovať pomocou štartovacieho parametra /DBD<pocet_poziadaviek>. Odporúčaný postup je nasledovný:

  • Spustite DBManager so štartovacím parametrom /DBD<pocet_poziadaviek>.
  • Nechajte ho bežať dostatočne reprezentatívnu dobu (jeden deň/týždeň) počas bežnej prevádzky systému.
  • Hľadajte v logovacích súboroch reťazec performance warning. Ak sa tam nachádza, dochádza k čakaniu požiadaviek a pokiaľ je možné, zvýšte počet automatických spojení. Ak sa tam nenachádza, môžete počet automatických spojení znížiť bez zhoršenia užívateľskej odozvy.

4. Zisťovanie momentálneho stavu DBManagera TELL príkazmi

Tell príkazmi SHOW_HANDLE a SHOW_CONNECT je možné vypísať stav všetkých spojení na databáze a analyzovať ich využitie a prípadné problémy:

  • zabudnuté transakcie/transakcie otvorené dlhšie, ako je nevyhnutne potrebné 
    ->Db DBC_ROVE_EDA con 6:normal, 2 handles, transact 301747, idle 02:53:44.316
->Db DBC_ROVE_EDA con 6:trans   DBC_ROVE_EDA: <[] S.EDA_Komp_TreeData_Vektor: 531;  567>
->Db DBC_ROVE_EDA con 6:dbase   DBC_ROVE_EDA: <[] S.EDA_Komp_TreeData_Vektor: 532;  567>
    Na takéto transakcie sa môže zabudnúť (po DB_TRANS_COMMIT resp. DB_TRANS_ROLLBACK nebolo volané DB_TRANS_CLOSE) a ukončia sa až zavretím schémy (pokiaľ sa nachádzajú v skripte schémy) alebo ukončením/uložením eventu (pokiaľ sa jedná o serverovský event, tak až ukončením procesu .EVH).
Napíšte komentár