D2000 DBManager - debugging
Debug information and error information of process process D2000 DBManager is shown in the process text console and written to the log file in the subdirectory TRACE of the application directory as well. If the process D2000 DBManager is started as SELF.DBM, it creates the DBManager.log and DBManager_ERR.log files. If this process is started as name.DBM, it creates the DBManager_name.log and DBManager_meno_ERR.log.
If the size of log file reaches the predefined value of 10 MB, it will be renamed to DBManager_name_prev.log (DBManager_meno_ERR_prev.log) and a new log file will be created. Previous DBManager_name_prev.log (DBManager_meno_ERR_prev.log) will be deleted.
...
- Error logs
- Action listing
- Listing the actions, duration of which is longer than entered number of seconds
- Logs with DBG.DBMANAGER debug category enabled
- Logs with DBG.DBMANAGER.DATA debug category enabled
- Logs with DBG.DBMANAGER.DBCTX debug category enabled
- Logs with DBG.DBMANAGER.DBCTX.CSV debug category enabled
- Logs with DBG.DBMANAGER.SQL_CONNECT debug category enabled
- Logs with startup parameter /DBD<number_of_requests>
- Tell command SHOW_HANDLE
- Tell command SHOW_CONNECT
- Tell command SET_WATCHDOG
- Tell command SET_WATCHDOG_QUEUE
- Tell command TIME_STATISTICS
- Optimization and debugging
Kotva | ||||
---|---|---|---|---|
|
...
Errors are always written to the log file which ends with _ERR.log. Error log usually contains the SQL command that caused the error.
...
Note 2: Each ESL action for work with database (through D2000 DBManager) saves the information about the position in ESL code from which it was called. If some error occurs, both the information about found error and about position is written up (see the begin of example).
Kotva | ||||
---|---|---|---|---|
|
...
Detailed debug information is written to the log file if the option Debug is checked off in the configuration of object of Database type. The log includes the information on individual ESL actions (action name, begin and end), database and connection that the action uses.
...
All possible states are listed in the table below:
Kotva | ||||
---|---|---|---|---|
|
Status | Description |
---|---|
Init | Connection is in initial phase (it is being created). Transient status. |
Avail | Connection is free (available). |
Normal | Connection is used. |
Live | Connection is passing from Avail status to Normal status. Transient status. |
Die | Connection is being closed. Transient status. |
Zombie | Connection is closed, service thread is finished. Transient status. |
Handles indicates the number of descriptors that are opened by D2000 DBManager. There are 4 types of descriptors: Kotva handles handles
...
10:29:32.068 11.08 Db TestDB table Time_Test periodic delete BEG
10:29:32.162 11.08 Db TestDB table Time_Test periodic delete END
Kotva | ||||
---|---|---|---|---|
|
...
Debug information about operations, duration of which is longer than entered number of seconds, is written to log file after setting the parameter Log operations longer than (sec) to nonzero value in the configuration Databaze object. Log contains the information about connection, on which the action was executed, localization of action in ESL script, the calling message from DbManager and duration of action in milliseconds.
...
19:27:37.286 01.07 con 1:DBS_READ BEG
19:27:37.297 01.07 con 1:DBS_READ END
19:27:37.298 01.07 con 1:DBS_READ
SELF.EVH;E.Test( 1934) 1230;: 16
- M.DB.CDB_CTRLMSG - 122[ms]
Kotva | ||||
---|---|---|---|---|
|
...
Detailed debug information is written to the log file after enabling the DBG.DBMANAGER debug category in the process D2000 System Console - Debug info window. Each log of action contains also information on procedures called in process D2000 DBManager (that may be useful for developers) and texts of executed SQL commands.
...
The examples of logs with differences between ODBC and OCI version of D2000 DBManager are in the chapter Example - logs for process D2000 DBManager.
Kotva | ||||
---|---|---|---|---|
|
...
Detailed debug information written in the log file after enabling the DBG.DBMANAGER.DATA debug category through the process D2000 System Console - Debug info window. Each log of action contains also a list of values that were written to or read from database.
...
The examples of logs with differences between ODBC and OCI version of D2000 DBManager are in the chapter Example - logs for process D2000 DBManager.
Kotva | ||||
---|---|---|---|---|
|
...
Detailed debug information written into the log file after enabling the DBG.DBMANAGER.DBCTX debug category through the process D2000 System Console - Debug info window.
...
15:01:14.114 01.08 con 1:SQL_SELECT BEG 15:01:14.121 01.08 con 1: D2000_PROCESS_PARAMS - SET PARAMS "NAME=VERSION27" of dbCtxId = 55 15:01:14.125 01.08 con 1:SQL_SELECT END
Kotva | ||||
---|---|---|---|---|
|
...
Detailed CSV information written into the log file after enabling the DBG.DBMANAGER.DBCTX.CSV debug category by the process D2000 System Console - Debug info window. This information is written after enabling the parameter Debug in the configuration of Database object. Log contains the structured CVS information about single parameters that are set in context of given client which starts DB actions through D2000 DBManager.
...
15:28:22.051 01.08 con 1:SQL_SELECT BEG 15:28:22.054 01.08 ;D2000_PROCESS_PARAMS;1;SQL_SELECT;1006;tdb_task_000000000905BB40;55;TRUE;1;2;set;TRUE 15:28:22.056 01.08 con 1:SQL_SELECT END
Kotva | ||||
---|---|---|---|---|
|
...
Enabling the debug category has the same effect as inserting "DEBUG" into the connectString parameter in all calls of the SQL_CONNECT action, i.e. the writing debug information of the SQL_CONNECT action and all other actions using this connection into the log file of D2000 DBManager.
Note: The DBG.DBMANAGER.SQL_CONNECT debug category has no effect on the SQL_CONNECT actions which contain the reference to an object of Database or Database Table types, because these actions are influenced by the parameter parameter Debug in the configuration dialog box of respective Database type object. The category affects only the SQL_CONNECT actions using the parameter connectString for their connection, i.e. the text connect string, debugging of which cannot be enabled in process D2000 CNF and it needs to be enabled by inserting the DEBUG parameter into the connectString parameter.
Kotva | ||||
---|---|---|---|---|
|
...
Starting from version 7.01.023 a performance tuning feature for reporting performance problems in automatic (non-transactional) connections is available. If DBManager is run with parameter /DBD<number_of_requests>, it will write the following information to its log file during startup:
Performance logging is ON.
...
Note 2: Transactional connection does not need this kind of performance tuning, because it is currently being used only sequentially from one event.
Kotva | ||||
---|---|---|---|---|
|
...
Interactive query of open descriptors with the helpo of SHOW_HANDLE Tell command. The syntax of command is:
...
If the SHOW_HANDLE command is called with no parameters, information on all open descriptors will be written to the log file.
For each descriptor, log contains database name, connection number, descriptor type, descriptor name and information from where the descriptor was open.
Displayed type and name of descriptor varies depending on descriptor types as the following table states:
Descriptor type | Displayed type | Descriptor name |
---|---|---|
table descriptor | table | Name of object of Database table type. |
transaction descriptor | trans | Name of object of Database type, in which the transaction is open. |
connection descriptor | connect | The parameter connectString of the SQL_CONNECT action. |
database descriptor | dbase | Name of object of Database type, that represented the parameter dbObjIdent in the action SQL_CONNECT. |
Example:
CONO connection established (IPC_TCPIP)
Receiv TELL Command : SHOW_HANDLE
===================================================================
->Db TestDB con 1:table MAT_GROUP: <HI mycomp,S.Test_DBmanager>
->Db TestDB con 2:trans TestDB: <S.Test_DBmanager: 220>
===================================================================
D2000 DBManager has two open descriptors. The first one is on the connection nr. 1. It is a table descriptor, which is opened in the Browser MAT_GROUPopen. The descriptor is open from the picture S.Test_DBmanager in process D2000 HI running on the computer with the name of mycomp.
The second descriptor is on the connection nr. 2, a transaction descriptor that is open from 220th script row of the picture S.Test_DBmanager.
Kotva | ||||
---|---|---|---|---|
|
...
Interactive query for open connection by using the SHOW_CONNECT Tell command. The syntax of command is:
...
Example of log (connection in all databases the names of which start with Te along with descriptors log):
Receive TELL Command : SHOW_CONNECT Te* DETAIL
===================================================================
->Db TestDB 2 cons
->Db TestDB con 1:normal, 1 handles, idle 04:24:682, non-transact
->Db TestDB con 1:table MAT_GROUP: <HI mycomp,S.Test_DBmanager>
->Db TestDB con 2:normal, 2 handles, idle 20:037, transact 1053
->Db TestDB con 2:trans TestDB: <S.Test_DBmanager: 220>
->Db TestDB con 2:table MAT_GROUP: <S.Test_DBmanager: 109>
Note: Information whether the connection is transactional or non-transactional along with transaction number gives outdated value (transaction has already been finished) for connections in the Avail status . Such connections will be recycled in transactional or non-transactional mode if needed.
Kotva | ||||
---|---|---|---|---|
|
...
SQL operations execution of which took a longer time can be monitored by a tell command SET_WATCHDOG. The syntax of command is:
...
Example of log (from database log, so the database name is not written):
16:45:28.763 24.11 Performance WD: con 3: operation lasts 27 sec in U_EXECDIRECT1/D_EXECDIRECT6
16:45:29.767 24.11 Performance WD: con 3: operation lasts 28 sec in U_EXECDIRECT1/D_EXECDIRECT6
16:45:30.782 24.11 Performance WD: con 3: operation lasts 29 sec in U_EXECDIRECT1/D_EXECDIRECT6
16:45:31.798 24.11 Performance WD: con 3: operation lasts 30 sec in U_EXECDIRECT1/D_EXECDIRECT6
16:45:34.829 24.11 Performance WD: con 3: operation lasts 2 sec in U_EXECDIRECT1/D_EXECDIRECT6
After the SQL operation is finished, a detailed info is written into error log file. Examples:
17:54:00.116 16.02 con 1:Query execution duration 00:00:01.103 SQL_CONNECT TransactId 10319, dbTransId 0, Handle 1104492764, connectString {}, DbTableId 1473 {DB.MATERIAL}, Comment {NS1PHUM3_HI.HIS;S.sql_TEST( 9473) 10864;BT_connect_OnClick: 248}
17:54:18.926 16.02 con 1:Query execution duration 00:00:01.105 SQL_PREPARE TransactId 10320, dbTransId-1, Handle 10319, Statment {SELECT ID_MATERIAL FROM material }, bBindIn FALSE, FetchSize 1, colNr 17, Comment {NS1PHUM3_HI.HIS;S.sql_TEST( 9473) 10864;BT_prepare_OnClick: 279}
17:55:59.113 16.02 con 2:Query execution duration 00:00:01.110 DB_TRANS_OPEN TransactId 10325, Comment {NS1PHUM3_HI.HIS;S.sql_TEST( 9473) 10864;BT_db_trans_open_OnClick: 543}
...
Note: Start up of SQL operation monitoring is written in DBManager log. The log contains the list of databases that match the specified mask database_mask. The log also contains the information on start up of watchdog at first calling the tell command SET_WATCHDOG.
16:45:27.735 24.11 ===================================================================
16:45:27.736 24.11 ->Db DBC_ROVE_OD 2 cons
16:45:27.737 24.11 ->Db DBC_KOMP_OD 3 cons
16:45:27.742 24.11 Starting performance watchdog task for database operations
16:45:27.743 24.11 ===================================================================
If value of parameter seconds is 0 in all databases, the watchdog stops database monitoring and the following information appears in log:
17:37:41.588 24.11 Performance watchdog: going to sleep (no more databases to monitor)
The watchdog is running so it is not necessary to start it up at next activating of the monitoring and only information about activation appears in log:
18:45:28.749 24.11 Performance watchdog: starting monitoring
Kotva | ||||
---|---|---|---|---|
|
...
Database actions execution of which - including time spent in queues of DBManager - took a longer time can be monitored by a tell command SET_WATCHDOG_QUEUE. The syntax of command is:
...
After the database action is finished, a detailed info is written into error log file. Examples:
18:01:21.579 16.02 con 1:Query total duration 00:00:01.130, execution 00:00:00.105 SQL_EXEC_PROC TransactId 10331, dbTransId-1, Statement {{ call TESTF_IN_OUT (?) }}, Comment {NS1PHUM3_HI.HIS;S.sql_TEST( 9473) 11332;BT_exec_proc_OnClick: 626}
18:02:39.149 16.02 con 1:Query total duration 00:00:01.103, execution 00:00:00.202 SQL_CONNECT TransactId 10335, dbTransId 0, Handle 1104492765, connectString {}, DbTableId 1473 {DB.MATERIAL}, Comment {NS1PHUM3_HI.HIS;S.sql_TEST( 9473) 11453;BT_connect_OnClick: 248}
18:02:42.437 16.02 con 1:Query total duration 00:00:01.103, execution 00:00:00.035 SQL_DISCONNECT TransactId 10335, dbTransId-1, Comment {NS1PHUM3_HI.HIS;S.sql_TEST( 9473) 11453;BT_connect_OnClick: 248}
18:02:51.163 16.02 con 1:Query total duration 00:00:01.105, execution 00:00:00.654 SQL_PREPARE TransactId 10337, dbTransId-1, Handle 10336, Statement {SELECT ID_MATERIAL FROM material }, bBindIn FALSE, FetchSize 1, colNr 17, Comment {NS1PHUM3_HI.HIS;S.sql_TEST( 9473) 11453;BT_prepare_OnClick: 279}
18:02:54.275 16.02 con 1:Query total duration 00:00:01.110, execution 00:00:00.239 SQL_FETCH TransactId 10338, dbTransId-1, Handle 10336, MaxRows 100, Comment {NS1PHUM3_HI.HIS;S.sql_TEST( 9473) 11453;BT_fetch_OnClick: 299}
18:02:57.009 16.02 con 1:Query total duration 00:00:01.104, execution 00:00:00.109 SQL_FREE Handle 10336, Comment {NS1PHUM3_HI.HIS;S.sql_TEST( 9473) 11453;BT_free_OnClick: 325}
Meaning of individual items: see a description in section SET_WATCHDOG.
Kotva | ||||
---|---|---|---|---|
|
...
Tell command displays statistics of execution of individual database action types per-database or per-table (if a parameter DETAIL is specified). For every type of database action (browser open, transaction start, DB_* and DBS_* actions etc) printout contains total number of executed action, total and average duration and duration of longest action together with a comment (ESL call chain).
Statistics with zero execution counts are discarded.
If a parameter DETAIL is specified, after the printout of database statistics follows a printout of per-table statistics of all child tables.
Example of a printout:
09:36:28.023 21.02 ===================================================================
09:36:28.026 21.02 ->Db MesDB total time 000 00:00:40.572
09:36:28.029 21.02 Operation BROWSER_OPEN executions 3 total duration 000 00:00:03.686, average 000 00:00:01.229, maximum 000 00:00:01.468 by
09:36:28.032 21.02 Operation DB_CONNECT executions 2 total duration 000 00:00:02.207, average 000 00:00:01.104, maximum 000 00:00:01.104 by NS1PHUM3_HI.HIS;S.Test_DBmanagera( 9424) 10510;DB_CONNECT_OnClick: 109
09:36:28.034 21.02 Operation DB_CONTROL executions 15 total duration 000 00:00:16.589, average 000 00:00:01.106, maximum 000 00:00:01.129 by con 1:DBS_READ
NS1PHUM3_HI.HIS;S.TestDbRefresh( 10105) 10429;StressTest_OnClick: 20
09:36:28.037 21.02 Operation DB_REFRESH_TABLE executions 2 total duration 000 00:00:02.526, average 000 00:00:01.263, maximum 000 00:00:01.266 by Triggered by commit of NS1PHUM3_HI.HIS;S.TestDbRefresh( 10105) 10429;StressTest_OnClick: 10
09:36:28.040 21.02 Operation DB_TRANS_OPEN executions 4 total duration 000 00:00:04.426, average 000 00:00:01.106, maximum 000 00:00:01.107 by NS1PHUM3_HI.HIS;S.Test_DBmanagera( 9424) 10479;TRANS_OPEN_OnClick: 227
09:36:28.043 21.02 Operation DB_TRANS_CONTROL executions 2 total duration 000 00:00:02.301, average 000 00:00:01.150, maximum 000 00:00:01.197 by NS1PHUM3_HI.HIS;S.TestDbRefresh( 10105) 10429;StressTest_OnClick: 35
09:36:28.046 21.02 Operation DB_TRANSACT_ABORT executions 8 total duration 000 00:00:08.837, average 000 00:00:01.105, maximum 000 00:00:01.107 by
09:36:28.049 21.02 ->Table DB.MAT_GROUP total time 000 00:00:04.420
09:36:28.052 21.02 Operation BROWSER_OPEN executions 1 total duration 000 00:00:01.107, average 000 00:00:01.107, maximum 000 00:00:01.107 by
09:36:28.054 21.02 Operation DB_CONTROL executions 3 total duration 000 00:00:03.313, average 000 00:00:01.104, maximum 000 00:00:01.105 by NS1PHUM3_HI.HIS;S.Test_DBmanagera( 9424) 10479;DB_CONNECT_OnClick: 109
09:36:28.057 21.02 ->Table DB.MATERIAL total time 000 00:00:16.913
09:36:28.060 21.02 Operation BROWSER_OPEN executions 1 total duration 000 00:00:01.111, average 000 00:00:01.111, maximum 000 00:00:01.111 by
09:36:28.063 21.02 Operation DB_CONTROL executions 12 total duration 000 00:00:13.276, average 000 00:00:01.106, maximum 000 00:00:01.129 by con 1:DBS_READ
NS1PHUM3_HI.HIS;S.TestDbRefresh( 10105) 10429;StressTest_OnClick: 20
09:36:28.065 21.02 Operation DB_REFRESH_TABLE executions 2 total duration 000 00:00:02.526, average 000 00:00:01.263, maximum 000 00:00:01.266 by Triggered by commit of NS1PHUM3_HI.HIS;S.TestDbRefresh( 10105) 10429;StressTest_OnClick: 10
09:36:28.069 21.02 ===================================================================
Kotva | ||||
---|---|---|---|---|
|
...
The database parameters can be set in process D2000 CNF. A connection created by the action SQL_CONNECT contains these parameters in its connect string.
Parameter name in CNF | Parameter name in connect string |
---|---|
Precreated connections | PRE=... |
Maximum connections | MAX=... |
Maximum automatic connections | NTC=... |
Reserved browser connections | BRC=... |
Close unused connections after (sec) | CLOSE=... |
Close DBManager after timeout (min) | WDC=... |
Debug | DEBUG |
Off | OFF |
Maximum returned rows | MR=... |
Empty operations after inactivity period | EO=... |
Example: settings of database additional parameters in its connect string:
DEBUG;PRE=10;MAX=120;CLOSE=300;NTC=20;WDC=7;MR=1000
...
- For reasons of the speed optimization and mutual client non-blocking, process D2000 DBManager creates more than one automatic connection to database. Automatic connections can be created immediately after starting process D2000 DBManager, so they are prepared to be used (e.g. creating a connection in case of the database of Oracle type may take 1 second or more and it causes delaying in ESL scripts). Number of the precreated connections can be adjusted in process D2000 CNF the object of Database type using the parameter Precreated connections. Maximal number of connections can be limited by parameter Maximum connections, while the value 0 disables the limitation. If process D2000 DBManager uses all connections, then next call to create connection (DB_TRANS_OPEN) will return the error DBM_MAX_CONNECTIONS.
- Using the parameter Maximum automatic connections allows to set a maximum number of connections created automatically. When the parameter is not set, then:
- at most 1/4 of Max connections will be used for automatic connections
- if Max<4, only 1 automatic connection will be created
- if Max=0, at most 5 automatic connections will be created (default value)
If process D2000 DBManager uses the maximum number of automatic connections, then a new connection will not be created as a result of the next request (e.g. non-transactional SQL_CONNECT, PG_CONNECT or DB_CONNECT), but one of the existing will be used. The parameter Maximum automatic connections is important for the database to not exceed the defined number of connections. - For time optimalisation reasons the process D2000 DBManager "recycles" existing connections. If a connection is closed (e.g. DB_TRANS_CLOSE) or is not used (it is the result of SQL_CONNECT and SQL_DISCONNECT performed), then it is signed as available. Available connections can be repeatedly used; it saves time to connect to the database and accelerates execution of scripts. The available connections, that do not belong to prepared ones and are not used, will be terminated after expiration of the time defined in the parameter Close unused connections in seconds(precreated connections are not being terminated). Adjusting the parameter to a negative value will tell process D2000 DBManager not to terminate available connections - in this case their number will increase and it will reflect the status of D2000 DBManager during the maximum system load.
To speed-up the operations of browser displayer it is possible to reserve a pool of connections for these operations (browser opening, changing pages and the action DB_REFRESH_TABLE) using the parameter BRC - Reserved browser connections. This feature is supported starting with D2000 version 8.00.009.Kotva brc brc
The advantage is that no other non-transactional operations (which can last several seconds or more) will be executed by these reserved connections and the action DB_REFRESH_TABLE as well as changing pages can be faster than in default configuration when the browser operations are executed by automatic connections.
Note: if the value of parameter BRC - Reserved browser connections is zero, the browser operations are executed by automatic connections, which was default before this parameter was implemented.
Debug and information logs: process D2000 DBManager enables to display several levels of debugging logs which are in closer detail described in this document.Kotva logovaci_subor logovaci_subor - Termination of process D2000 DBManager in consequence of "frozen " connections: D2000 DBManager contains the internal watchdog, which detects every minute, whether some connection to the database is not "frozen" (i.e. service thread did not return from calling of ODBC interface). In this case, process D2000 DBManager will write into a log file. If the watchdog detects such a situation n-times in a consecutive sequence (while n can be adjusted in the parameter Close DBManager after timeout), it will terminate process D2000 DBManager. Default value 0 means that D2000 DBManager will not be terminated.
- Parameters for the connections created by means of the command SQL_CONNECT using so-called connect string: as these connections are not related to objects of Database type, but DSN is directly defined in the connect string, setting of the parameters can be performed directly in the connect string.
Example:
UID=name;PWD=user's password;DSN=DSN name;ACD;Debug;CLOSE=300
Debug information for the created connection will be written to file. Unused connection will be closed up after 300 seconds.
Available connection can be "recycled" if its connect string is the same as the connect string of the connection being created.
Debug and information logs of these connections that are "independent" on the object of Database type:
08:59:45.710 Indep# 3 DSN=TestX:SQL_FETCH BEG
08:59:45.710 Indep# 3 DSN=TestX:SQL_FETCH END
the log informs us that "independent" connection no. 3, DSN of which is "TestX", performed the action SQL_FETCH.
If parameter Debug is set on at least one independent connection, then the log also contains periodical information about the independent connections (written to log once a minute):
09:14:27.752 Db Independent connects WD: 1 (1/0/0) cons:normal- 1
the log informs us that there exists only one independent connection and is currently in use.
Numbers in brackets give numbers of non-transactional, transactional and browser connections.
Kotva | ||||
---|---|---|---|---|
|
...
From above mentioned, it results that there exist three groups of connections (database connections along with the service tasks) for each object of Database type in every time, but their quantity within a group is limited in some way (or it is not according to settings).
...