D2000 DBManager - logs evaluation

Document version: 1.0, 26.2.2008

Basic information about logging of process 2000 DBManager are shown in this description.

This document is used for detail description of log lists and their usage for:

  1. Errors detecting in the objects configuration of Table type in D2000 (error in structure definition)
  2. Application errors detecting in ESL
  3. Power debugging (number of connections setting according to application requests)
  4. DBManager current status detecting by TELL commands

The most of the following methods suppose that the objects of Database type have been configured with the allowed option Debug. It is recommended (for D2000 version 7.01.022 and higher ones) to set the size of log file (MB) at option Debug and to configure the actions logging into separate file for each database. The size of log file must be large enough to obtain the log data for long period (the maximum size of log file DBManager.log is 10 MB).
DBManager should be run for adequately long period including the period of maximum system load (e.g. 24 hours during working day). Also it is recommended to configure the start-up parameter/E+DBG.DBMANAGER determined for logging of details about performed operations.

1. Errors detecting in objects configuration of Table type

Following errors can be detected from logs:

Click on the button Test in the object configuration of Table type allows to test manually the table functionality besides the detection from DBManager logs.

Precondition: DBManager runs adequately long period to approach (reading or writing) to all tables which are to be checked.

Searched string: Cannot get any result from SQL Columns.

Example: 

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

Solution: to check

Searched string: text data mapped to non-text columns

Example: 

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

Solution: To integrate column type in SQL database and in structure definition connected in object configuration of Table type. The column in SQL database is text type and column of structure definition in D2000 is not text type. In this configuration it depends on if data in specific column of table in SQL database can be converted to type different from text type (integer, real, etc.) during reading.
The result of errors at conversion can be for example:

Searched string: non-number data mapped to number columns

Example: 

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

Solution: To integrate the column type in SQL database and in structure definition connected in object configuration of Table type. The column in SQL database is not numeric, the column of structure definition in D2000 is numeric (integer, real or relative time). In this configuration it depends on if data in specific column of table in SQL database can be converted  to type different from text type (integer, real, etc.) during reading.

2. Application errors detecting in ESL

Following errors, in the form of ODBC or OCI error, can be detected from logs.

Searched string: *** Error in

Example:

OCI version:

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 version:

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

Solution: Error analysis (e.g. searching of ORA-xxxxx error message, cause detection and removal). If the error occurred e.g. at specific values entering it is recommended to configure start-up parameter /E+DBG.DBMANAGER.DATA for process SELF.DBM (value logging).

Example of usage:

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

In this example you can open the browser and try to enter manually the written values into table. The saving had run without error till the value in column "NTYP" was less than 10. Oracle Enterprise Manager detected that this column was created by mistake in SQL database as Number(1), i.e. number with range of one figure.

Searched string: timeout expired

Example:

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

Connection No. 3 makes some action (detail list U_EXECDIRECT1/D_EXECDIRECT2 are determined for D2000 developers but they indicate that it concerns probably SQL_EXEC_DIRECT). After searching the first existence of string con 3 you can see that the last command, which started to perform, was:

10:02:16.864 17.02 con 3:SQL_EXEC_DIRECT BEG

If debug category DBG.DBMANAGER is switched on, the list contains also the specific command which is executed:

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. Power debugging (number of connection setting according to application requests)

If the option Debug is switched on, DBManager writes also the information about creating, using and ending of the connections into log. The connection is created or assigned as the result of following actions:

The other actions use the handle obtained by calling the actions DB_TRANS_OPEN, DB_CONNECT, PG_CONNECT and SQL_CONNECT. They must run on the connection which the handle is bounded up with. Actions SBS_* (DBS_BLOB_* including) use the connection and release it immediately.
Following messages concerning the creating and assigning of the automatic connection exist in the system:

Message Description
(X1) got free NTC Free automatic connection was used (no handle bounded with this connection exists).
(X2) has 3/7 NTC,reusing T con 4 Number of automatic connections did not reached the value defined in Database configuration. Free connection - transactional - is available. This connection will be changed into automatic and will be used.
(X3) has 3/7 NTC,creating new Number of automatic connections did not reached the value defined in Database configuration. Neither free connection nor transactional is available. That is why the new connection on database creates.
(X4) has 7/7 NTC,reusing con 5 Number of automatic connections reached the value defined in Database configuration. One of the automatic connections will be used (even though no one is free, i.e. at least one handle is bounded on each connection). The connection with the less requests in queue or with the flag not_busy (currently it processes no request) is used.
(X5) has 7/7 NTC, not found any good, hardpanic! In spite of the number of automatic connections reached the value defined in Database configuration, no one available connection was searched.
This status could occur up to version 7.01.023 immediately after restart of DBManager. If the requests came before the predefined connections was linked to database (e.g. connection to Oracle database can take several seconds) or in case of database inaccessible and connection failed repeatedly.

Another occurrence: When DBManager starts-up and some of the databases is switched off and then switch on, the requests for database come before the predefined connections linked to database (if database is switched off during DBManager starts-up, the predefined connections do not link to database but they wait until the database is switch on).
(X6) has 7 cons, limit is 7, can't create NTC, reusing con 1 Number of automatic connections has not reached the value defined in Database configuration and it is not possible to create a new connection because there is the maximum connections (i.e. other connections are used as transactional). One of the automatic connections will be used according to the same rules as it is in X4.
(X7) has 7 cons,limit is 7, can't create NTC, not found any good, hardpanic! Number of automatic connections has not reached the value defined in Database configuration and it is not possible to create a new connection because there is the maximum connections. At the same time the all connections are used as transactional. This situation should not occur as one connection is always booked as automatic.

Messages X4 and X6 do not mean that the requests must wait on each other in DBManager. Even if some of the browsers use the same automatic connection, this connection is not used most of the time (until user activates to load the new page or makes the changes). There is only one possibility - more actions come close one by one and one action will wait until another one performs.
Wait state is possible to monitor by start-up parameter /DBD<number_of_requests>. Recommended mechanism is following:

4. DBManager current status detecting by TELL commands

Using the tell commands SHOW_HANDLE and SHOW_CONNECT is possible to show the status of all connections on database and to analyze their usage and some problems: