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