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:

• table with the given name does not exist,
• column in SQL table is text-based and the column in structure definition in D2000 is not text-based,
• column in SQL table is not numeric and the column in structure definition in D2000 is the numeric (for D2000 version 7.01.022 and higher ones).

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

• the existence of table in SQL database,
• the table is accessible to user which was configured in object of Database type; this object is parent of the object of Table type that the error message concerns,
• the table contains at least the one column with the name identical with name of structure definition which is connected in object configuration of Table type (some of the SQL databases can be case-sensitive),
• the table name in SQL database is identical with the parameter Table configured on object of Table type (beware of possible case-sensitivity).

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:

• for OCI version of DBManager: the values absent in column with invalid value and in all following columns in reading of table through browser or in access through pages
• for ODBC version of DBManager and for database Sybase SQL Anywhere: invalid values in all cells of row in which the invalid value occurs.

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:

• browser opening above the table,
• actions DBS_* called without transaction parameter,
• actions DBS_READ_BLOB and DBS_UPDATE_BLOB called without transaction parameter,
• action DB_TRANS_OPEN.

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:

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:

• start DBManager with start-up parameter /DBD<number_of_requests>,
• DBManager must run for adequately long period (for one day/week) during common system operation,
• search the string performance warning in log files. If performance warning occurs there, the requests wait. Try to increase the number of automatic connections. If performance warning does not occur there, decrease the number of automatic connections, the user response will not be worsened.

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:

• forgotten transactions/transactions opened longer than it is necessary

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

  Above mentioned transactions can be forgotten (DB_TRANS_CLOSE was not called after DB_TRANS_COMMIT or DB_TRANS_ROLLBACK) and they will be ended after closing the picture (if they are placed in picture script) or by event ending/saving (if it concerns about the server event the transactions will be ended after process .EVH finishes).