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 with parameter 1, 2, 3, 4 or 5, as follows:
SET TRACE POINT SC930 N [n]
where N and n are:
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.)