Trace Utilities
Commands are available to trace such things as disk file access, locks, user interface-to-DBMS Server communications, query plans of the Query Optimizer and various types of memory usage.
DBMS Server tracing is generally enabled by some form of the SET command, although some forms of tracing make use of Vector environment variables. SET commands used specifically for debugging and troubleshooting are discussed in this document. General SET commands are documented in the SQL Language Guide.
ODBC Call-level Interface
The Vector ODBC Call-level Interface (CLI) follows the existing convention of ODBC tracing as performed by the Linux ODBC Driver Manager and Microsoft ODBC Driver Manager. Registry or configuration files are scanned for trace and trace log settings. Tracing output is similar to what is currently provided by the Vector ODBC tracing DLL on Windows. Optionally, an application can set standard ODBC tracing using the following Vector environment variables:
II_ODBC_LOG
A string indicating the path and file name of an ODBC trace file. For example, the path and file name of an ODBC trace file for Linux is \tmp\odbc.log and for Windows is c:\temp\odbc.log. The file name specified can contain the %p and %d parameters, as described in II_DBMS_LOG.
II_ODBC_TRACE
A positive integer with a value of 1, 3, or 5. A setting of 1 provides standard ODBC tracing and is the most useful for debugging ODBC CLI applications. A setting of 3 includes ODBC function entry calls in the ODBC driver (as opposed to the ODBC CLI driver manager). A setting of 5 displays information about internal function entries in the ODBC driver.
If an ODBC application does not use the Vector ODBC CLI, the ODBC trace settings of 3 and 5 are still recognized, but the setting of 1, which belongs to the driver manager component, is not. However, the existing tracing capability for third-party driver managers is unaffected. In this case, the driver manager tracing is written to the ODBC trace log as specified in the registry (Windows) or odbcinst.ini file (Linux), but the detailed tracing information is written to the log file as specified by the II_ODBC_LOG environment variable.
SET Statement
The SET statement is used to specify a number of runtime options and has the general format:
SET [NO]option [additional parameters];
The option is set on or active by SET option or SET option ON (depending on the option). It is turned off by a corresponding SET NOOPTION or SET option OFF. Additional parameters are required, depending on the option. For syntax details, see the SQL Language Guide.
Environment Variables Commonly Used with SET
SET statements are executed as part of query language startup procedures at selected levels of scope. A SET statement is entered directly at a terminal for temporary settings or executed using a Vector environment variable/logical to establish a default option setting for all users. Several levels are shown in the following table:
Example: Set Statement Entered Directly
One or more set options can be specified using the _SET environment Vector environment variables. They can be assigned directly from the operating system shell. Separate multiple SET statements by semicolons (up to a limit of 64 characters), as shown in the following examples:
Windows:
SET ING_SET=set nojournaling;set printqry
Linux:
C Shell:
setenv ING_SET "set nojournaling; set printqry"
Bourne Shell:
ING_SET = "set nojournaling; set printqry" export ING_SET
Example: Set Statements in an Include File
SET statements can also be implemented by means of an INCLUDE statement. The INCLUDE statement allows you to place the SET statements in a file and specify the file name in the setenv (or equivalent) command. Use of the INCLUDE option also avoids the 64-character line limit.
For example:
Windows:
set ING_SET=include c:\extra\ingres\set.ing
Linux:
C Shell:
setenv ING_SET "include /extra/ingres/set.ing"
Bourne Shell:
ING_SET = "include /extra/ingres/set.ing"
export ING_SET
SET Statements in Startup Files
SET statements are automatically executed as part of query processor start up. Various startup defaults are enabled either by setting a Vector environment variable/logical (such as ING_SET or II_EMBED_SET described above) or by including these SET statements in one of the query processor startup files.
SET Options for Tracing Queries
SET options of special interest in query troubleshooting include:
• [NO]PRINTQRY—Set query display on or off.
• [NO]QEP—Set query execution plan display on or off.
• JOINOP [NO]TIMEOUT—Set optimizer timeout on or off.
• [NO]TRACE POINT OP207—Turn display of X100 algebra on or off.
The SET PRINTQRY Option
The command SET PRINTQRY prints out the query before it is optimized and executed. This is especially useful when evaluating queries for performance tuning or troubleshooting.
Example: Turn Query Display On Using ING_SET
The following command turns query display on:
Windows:
SET ING_SET=set printqry
Linux:
C Shell:
setenv ING_SET "set printqry"
Bourne Shell:
ING_SET = "set printqry"
export ING_SET
As an example, assume that QBF is started up. The following is displayed:
Query Buffer:
set Autocommit on
Query Parameters:
Query Buffer:
select cap_value, cap_capability from iidbcapabilities
Query Parameters:
Query Buffer:
select user_name, dba_name from iidbconstants
Query Parameters:
Example: Turn Query Display On Using II_EMBED_SET
The following command turns query display on through II_EMBED_SET. This is similar to the ING_SET environment variable/logical. All information is gathered in the client application and printed to the log by the library routines linked to the client application:
Windows:
SET II_EMBED_SET=printqry
Linux:
C Shell:
setenv II_EMBED_SET "printqry"
Bourne Shell:
II_EMBED_SET = "printqry"
export II_EMBED_SET
The query output with query timings is placed into a file called iiprtqry.log. Here is a sample output:
Query text:
select * from iirelation
Query Send Time: Thu Mar 26 17:20:43 2001
Query Response Time: Thu Mar 26 17:20:44 2001
Response CPU Time: 2630
Qry End CPU Time: 3370
This type of query monitoring can be useful for spotting slow-running queries in applications.
The SET QEP Option
The SET QEP option provides a display of the optimizer’s query execution plan (QEP) for the query after it has been optimized but before it is executed.
The following command turns QEP display on as the default ING_SET level:
Windows:
SET ING_SET=set qep
Linux:
C Shell:
setenv ING_SET "set qep"
Bourne Shell:
ING_SET = "set qep"
export ING_SET
The SET JOINOP NOTIMEOUT Option
The SET JOINOP NOTIMEOUT option can be used in tracing query performance. This statement turns the optimizer timeout feature off. With timeout on, the optimizer stops checking for further query execution plans when it believes that the best plan it has found takes less time to execute than the amount of time already spent searching for a plan. If you issue a SET JOINOP NOTIMEOUT statement, the optimizer continues searching query plans. This option is often used with the SET QEP option to ensure that the optimizer is picking the best possible query plan.
The SET TRACE POINT OP207 Option
The SET TRACE POINT OP207 statement displays the X100 algebra text that is passed to the X100 Engine for execution. X100 algebra is not easily interpreted by users, in general, but Actian Support may request it when troubleshooting an issue. Use SET NOTRACE POINT OP207 to turn off the display. The trace point privilege is required to use this option.
Canceling SET Options
To cancel any of the options that have been set with the SET statement, you issue the opposite SET statement (SET NOoption to turn an option off or SET option in the case of JOINOP NOTIMEOUT to restore the default behavior).
The SET SESSION WITH ON_ERROR Option
The following SET statement lets you specify how transaction errors are handled in the current session:
SET SESSION WITH ON_ERROR = ROLLBACK
STATEMENT | TRANSACTION
To direct Vector to roll back the effects of the entire current transaction if an error occurs, specify ROLLBACK TRANSACTION. To direct Vector to roll back only the current statement (the default), specify ROLLBACK STATEMENT. To determine the current status of transaction error handling, issue the SELECT DBMSINFO('ON_ERROR_STATE') statement.
Specifying ROLLBACK TRANSACTION reduces logging overhead, and help performance; the performance gain is offset by the fact that, if an error occurs, the entire transaction is rolled back, not the single statement that caused the error.
The following errors always roll back the current transaction, regardless of the current transaction error-handling setting:
• Deadlock
• Forced abort
• Lock quota exceeded
To determine if a transaction was aborted as the result of a database statement error, issue the statement SELECT DBMSINFO('ON_ERROR_STATE'). If the error aborted the transaction, this statement returns 0, indicating that the application is currently not in a transaction.
You cannot issue the SET SESSION WITH ON_ERROR statement from within a database procedure or multi-statement transaction.
I/O Tracing
SET IO_TRACE prints out information about disk I/O during the life of each query.
The following command turns I/O trace on as the default ING_SET level:
Windows:
SET ING_SET=set io_trace
Linux:
C Shell:
setenv ING_SET "set io_trace"
Bourne Shell:
ING_SET = "set io_trace"
export ING_SET
For example, given the query:
select * from iirelation;
Here is a sample output from the I/O trace. The counts are the number of pages read/written:
***************************************************************
I/O READ File: aaaaaaac.t00 (iidbdb, iirel_idx, 13) count:1
***************************************************************
***************************************************************
I/O READ File: aaaaaaab.t00 (iidbdb, iirelation, 0) count:8
***************************************************************
***************************************************************
I/O READ File: aaaaaaab.t00 (iidbdb, iirelation, 8) count:8
***************************************************************
I/O READ File: aaaaaaab.t00 (iidbdb, iirelation, 16) count:7
Note: When tracing the I/O or the locks of a parallel query (using SET IO_TRACE or SET LOCK_TRACE with SET PARALLEL n), the trace messages from child threads of the QEP are logged to the II_DBMS_LOG. The trace messages for the main thread are sent to the user session in the normal manner.
Lock Tracing
SET LOCK_TRACE prints out information about locks within a transaction.
The following command turns lock tracing on as the default ING_SET level:
Windows:
set ING_SET=set lock_trace
Linux:
C Shell:
setenv ING_SET "set lock_trace"
Bourne Shell:
ING_SET = "set lock_trace"export ING_SET
Event Tracing
The following features enable your application to display and trace events:
• To enable or disable the display of events when they are raised by the application, use the following command:
SET [NO]PRINTDBEVENTS
• To enable or disable the logging of events to the installation log file as they are raised by the application, use the following statement:
SET [NO]LOGDBEVENTS
• To enable or disable the display of events as they are received by an application, use the following statement:
SET_SQL(DBEVENTDISPLAY = 1 | 0)
Specify a value of 1 to enable the display of received events, or 0 to disable the display of received events. You can also enable this feature using II_EMBED_SET.
You can create a routine that traps all events returned to an embedded SQL application. To enable/disable an event-handling routine or function, your embedded SQL application must issue the following SET_SQL statement:
EXEC SQL SET_SQL(DBEVENTHANDLER = event_routine | 0)
To trap events to your event-handling routine, specify event_routine as a pointer to your error-handling function. For information about specifying pointers to functions, see your host language companion guide. In addition to issuing the SET_SQL statement, you must create the event-handling routine, declare it, and link it with your application.
User-Server Communications
The General Communication Facility (GCF) is composed of the GCA protocol and three communications programs: Name Server, Communications Server, and Data Access Server. These are separate processes. You can listen in on the communications between these GCF programs using the following Vector environment variables:
• II_EMBED_SET “printgca”
• II_GCA_TRACE
• II_GCN_TRACE
• II_GCC_TRACE
• II_GCD_TRACE
• II_GC_TRACE
• II_GCCCL_TRACE
• II_GCA_LOG
Trace Communication Using printgca
You can trace communications occurring in the GCA with the following command:
Windows:
set II_EMBED_SET=printgca
Linux:
C Shell:
setenv II_EMBED_SET "printgca"
Bourne Shell:
II_EMBED_SET = "printgca"
export II_EMBED_SET
This traces all GCA messages passed between Vector tools and the server. The output is placed into a file called iiprtgca.log.
Output of GCA Trace
Here is a sample output:
printgca = on session -2 (Thu Mar 26 15:50:32 2001)
GCA Service GCA_SEND
gca_association_id: 0
gca_message_type: GCA_QUERY
gca_data_length: 49
gca_end_of_data: TRUE
gca_data_area: GCA_Q_DATA
gca_language_id: 2
gca_query_modifier: 0x01
gca_qddata [0]:
gca_type: 51: DB_QTXT_TYPE
gca_precision: 0
gca_1_value: 29
gca_value: select name, gid from iiuser
End of GCA Message
GCA Service: GCA_RECEIVE
gca_association_id: 0
gca_message_type: GCA_TDESCR
gca_data_length: 55
gca_end_of_data: TRUE
gca_data_area: GCA_TD_DATA
gca_tsize: 26
gca_result_modifier: 0x01
gca_id_tdscr: 8
gca_1_col_desc: 2
gca_col_desc[0]:
gca_attdbv:
db_data: 0x00
db_length: 24
db_datatype: 20: DB_CHA_TYPE
db_prec: 0
gca_1_attname: 4
gca_attname: (4) name
gca_col_desc[1]
gca_attdbv:
db_data: 0x00
db_length: 2
db_datatype: 30: DB_INT_TYPE
db_prec: 0
gca_1_attname: 3
gca_attname: (3) gid
End of GCA Message
GCA Service: GCA_RECEIVE
gca_association_id: 0
gca_message_type: GCA_TUPLES
gca_data_length: 338
gca_end_of_data: TRUE
gca_data_area: GCA_TU_DATA not traced
End of GCA Message
Example: Level 2 Tracing Using GCA Trace Utiltiy
The syntax of GCA trace utility are as follows:
define II_GCA_TRACE [n]
define II_GCA_LOG [filename]
II_GCx_TRACE defines the level of GCA tracing, with n = 1 (lowest) through 4 (most detailed). II_GCA_LOG names the destination file of the trace output. If not specified, it defaults to standard output.
Here is an example of level 2 tracing:
!GCcm: target_id: 9062
!GCrequest 0: connecting on 9062
!GC_exchange 0: status 00000000
!GC_exchange_sm 0: status 00000000 state 0
!GCsend 0: send 528
!GC_send_comp 0: sent 528 status 00000000
!GC_exchange_sm 0: status 00000000 state 1
!GCreceive 0: want 528
!GC_recv_colmp 0: status 000000 state 0
!GCsend 0: send 65
!GC_send_comp 0: sent 65 status 00000000
!GCreceive 0: want 24
Query Tracing
Query Tracing (or trace point SC930) is the ability to trace all queries processed by the DBMS Server regardless of the source, whether it be an interactive query, or from a JDBC, ODBC, or .NET connection.
Note: Trace points are not officially supported, as Actian reserves the right to change their effect and output without notification.
SC930 Output Files
Trace point SC930 creates an output file for each connected session.
The file names are based on the DBMS Server process ID (pid) and the session ID (sid), as follows:
sess_pid_sid
For example:
sess_1246474_4029b400
Session IDs are reused by the DBMS Server so a trace file may contain SQL from more than one session. Each new session will have a SESSION BEGINS record.
Set SC930 Output Directory
Before enabling SC930 tracing, you must set the output directory.
To set the output directory
Set the environment variable II_SC930_LOC before starting Vector. For example:
Linux:
export II_SC930_LOC=/tmp/sc930files
Dynamically specify the directory using the SQL SET command. For example:
SET TRACE RECORD ‘/tmp/mytrace’\p\g
This command must be issued against every DBMS Server that has, or will have, SC930 enabled. Thus it is possible to use a different directory for each DBMS Server and switch the location while the trace is running.
Note: If the trace directory is changed then a session's trace could be split between different files with the same name but in different directories.
Files are closed after each message, so you can move files out of the directory where they are being written to, and as long as a momentary delay is allowed (in case a line is currently being written). A new file will then be created in the original directory and the file can be archived.
If a write fails, SC930 tracing is switched off. It is possible to run a simple test query against each server to determine that tracing is still operating. In addition, if II_DBMS_LOG is set, you can check that log to see if a "switching on" or "off" command has been issued.
Enabling and Disabling SC930
After the trace directory is set, SC930 tracing can be enabled.
SC930 tracing can be enabled on a per-server basis, as follows:
To enable SC930 tracing
SET TRACE POINT SC930 1\p\g
To disable SC930 tracing
SET TRACE POINT SC930 0\p\g
Enable SC930 Tracing
Tracing can be enabled by setting trace point SC930 as follows:
SET TRACE POINT SC930 N [n]
where N is 1, 2, 3, 4 or 5 as follows:
1
Enables query tracing for the current database.
2 [n]
Enables query tracing and provides QEPs for each query. The optional n parameter sets the QEP style where 1= segmented and 2 = full. If tracing is enabled for a single database then this does not change the scope of tracing; it simply turns on QEP output.
3 n
Enables query tracing and sets the number of segments of blob values to output, where 0 is all. This value defaults to 16. If tracing is already set to this level, this command simply changes the style of the output.
4 [n]
Enables query tracing for database n, where n is the ID number (db_id) of the database.
If n is not specified, then tracing is enabled for the current database. If n=0 and tracing is on, it reverts to all databases.
5 [n]
Enables query tracing for all databases except for database n, where n is the ID number (db_id) of the database.
If n is not specified, then tracing is excluded for the current database. If n=0 and tracing is on, it reverts to all databases.
The database ID (db_id) can be found by selecting from the iidatabase table in iidbdb or by viewing the summary information in the infodb output. (The ID is in hexadecimal and must be converted to decimal before using it on the SET TRACE POINT command).
Disable SC930 Tracing
To disable SC930 tracing
Issue either:
SET TRACE POINT SC930 0
or
SET NOTRACE POINT SC930
Recording is stopped for the DBMS Server.
SC930 Message Format
The messages in the file are of the form:
record type : timestamp1/timestamp2 : information
where:
record type
Indicates the type of record, such as: SESSION BEGINS, QRY, EQY, PARM, ADD-CURSORID, DELETE CURSOR, EXECUTE PROCEDURE, EXECUTE, ENDTRANS, SECURE, ABORT, ROLLBACK, ABSAVE, RLSAVE, BGNTRANS, SVEPOINT, AUTOCOMMIT, DDLCONCUR, FETCH, CLOSE.
timestamp1
Is seconds since 1-Jan-1970 00:00:00
timestamp2
Is nanoseconds
information
Is information specific to the record type, such as query text, number of rows returned, error message returned, and so on.
Note: Some records do not include a timestamp.
Example Trace Output
Excerpts from a sample trace file are shown here:
SESSION BEGINS(10):1307712787/528745000:(DBID=1307556034)(ingres )(
)( )(SVRCL=INGRES )(mydb )(00000000:00000000)
QRY:1307712787/529002000?select dbmsinfo('AUTOCOMMIT_STATE')
TDESC:17:1:66:17
COL:0:21:66:0
EQY:1307712787/529239000:1:
QRY:1307712787/529410000?select cap_value, cap_capability from iidbcapabilities
TDESC:0:2:64:17
COL:0:20:32:0
COL:1:20:32:0
EQY:1307712787/580699000:42:
QRY:1307712787/580918000?select user_name, dba_name from iidbconstants
TDESC:538976288:2:64:17
COL:0:32:32:0
COL:1:32:32:0
EQY:1307712787/611126000:1:
COMMIT:1307712787/611339000:
EQY:1307712787/611399000:-1:
QRY:1307712787/611522000?set AUTOCOMMIT on
AUTOCOMMIT:1307712787/611576000:
EQY:1307712787/611601000:-1:
QRY:1307712787/611695000?select dbmsinfo('UNICODE_NORMALIZATION')
TDESC:0:1:66:17
COL:0:21:66:0
EQY:1307712787/611886000:1:
QRY:1307712787/617804000?set AUTOCOMMIT OFF
AUTOCOMMIT:1307712787/617881000:
EQY:1307712787/617912000:-1:
QRY:1307712787/617915000?drop table test
EQY:1307712787/617940000:-1:E_US0AC1
QRY:1307712798/213087000? create table test (col1 integer)
EQY:1307712798/326125000:-1:
QRY:1307712814/814099000?insert into test values (1),(2),(3)
EQY:1307712814/814809000:3:
QRY:1307712841/255877000?set trace point sc930 2
EQY:1307712841/255986000:-1:
QRY:1307712846/616124000?select * from test
QEP:
QEP:QUERY PLAN 1,1, no timeout, of main query
QEP:
QEP: Proj-rest
QEP: Heap
QEP: Pages 1 Tups 3
QEP: D1 C0
QEP: /
QEP:test
QEP:Heap
QEP:Pages 3 Tups 3
TDESC:0:1:5:17
COL:0:-30:5:0
EQY:1307712846/616691000:3:
COMMIT:1307712856/504136000:
EQY:1307712856/504532000:-1:
The SESSION BEGINS record shows the session connection information, including:
• The output format version (10 in this case)
• User (ingres) and database (mydb)
• Server class (SVRCL=INGRES)
• Group and role information, if used
The QRY records show the queries being issued. The EQY records show when control was passed back to the front-end. They give a timestamp, the number of rows affected by the query and the last error (if any) associated with that session.
For example, we can see that the DROP TABLE TEST failed with E_US0AC1 (table does not exist). We can also see that a SELECT * FROM TEST later on returned 3 rows. We can also calculate query execution time by looking at the timestamps of QRY and EQY records.
Because SC930 shows all queries, we can see that there are several queries which were executed "under the covers" by Terminal Monitor as part of the connection—the "select dbmsinfo('UNICODE_NORMALIZATION')."
We can see the QEP tracing (SC930 2) is switched on and a query producing a QEP. (If there were REPEATED queries we would only see the QEP the first time it is executed.)
Error Tracing
Note: Trace points are not officially supported, as Actian reserves the right to change their effect and output without notification.
The DBMS can trace up to fifty errors simultaneously by using the statement:
SET TRACE POINT SC924 [errno]
The optional errno is the error code as text in the form "E_XX9999". The current and previous query text is printed to the error log every time the specified errors occur. This helps to identify the source of the error. If no error code is supplied, tracing for all errors is enabled or disabled.
Note: The DBMS Server traces the specified errors only for the server to which you are connected. If there are multiple DBMS servers running, you need to set up tracing for each one.