From Ingres Community Wiki

This document describes the DBMS Server Query Tracing facility which is implemented by the SC930 trace point.

Contents 1 Introduction 2 How to Enable Query Tracing 2.1 II_SC930_LOC 2.2 SET TRACE RECORD 2.3 Enabling Tracing Itself 2.4 Disabling Tracing 3 Output Files 3.1 Sample Output 4 Error Reporting and Other Considerations 5 How to Tell If SC930 is Available 5.1 Quick Test 1: Try the Trace Point! 5.2 Quick Test 2: SC1000 5.3 Check Output Version 5.4 SIR/BUG List 6 Other SC930 Wiki Pages 7 Old Documents

Introduction

DBMS Query Tracing, or SC930 Query Tracing, is the ability to trace all queries processed by the DBMS regardless of the source. Typically in the past things like II_EMBED_SET=printqry have been used to trace individual programs. However this does not work with newer client technologies like JDBC, ODBC or .Net.

In addition, SC930 Query Tracing was designed so that queries could be recorded in a format that could be 're-played'.

How to Enable Query Tracing

Query Tracing is enabled by use of a trace point, SC930. This means that it can be enabled by anyone with the set trace point privilege. It also means that it can be enabled on a per-dbms basis.

SC930 creates output files for each connected session. So in order to enable tracing we must first set a directory where these files will be written. This is done in one of two ways either by setting the environment variable II_SC930_LOC or by using the SQL command "SET TRACE RECORD".

In earlier versions of this feature the trace directory defaulted to /tmp. This is no longer the case since the fix for bug 124531 (see below)

II_SC930_LOC

II_SC930_LOC can be set either as a local environment variable or by ingsetenv. It takes effect the next time a DBMS server is started.

 export II_SC930_LOC=/tmp
 ingstop
 ingstart

SET TRACE RECORD

SET TRACE RECORD can be used to set or change the trace directory. Provided the directory given exists and is writeable it will be changed immediately. If not it will remain unset or at the previous value.

 sql mydb
 INGRES TERMINAL MONITOR Copyright 2011 Ingres Corporation
 Ingres Linux Version II 10.1.0 (int.lnx/00)NPTL login
 Fri Jun 10 12:31:40 2011
 continue
 * SET TRACE RECORD '/tmp/this_doesnt_exist'\g
 Executing . . .
 
 E_UL0400 unable to set trace directory to '/tmp/this_doesnt_exist' - check
   directory exists and is writeable. Trace directory remains unset.
   (Fri Jun 10 12:27:02 2011)
 
 continue
 * SET TRACE RECORD '/tmp'\g
 Executing . . .
 
 continue
 * SET TRACE RECORD '/tmp/no_such_dir'\g 
 Executing . . .
 
 E_UL0401 unable to set trace directory to '/tmp/no_such_dir' - check
   directory exists and is writeable. Trace directory remains '/tmp'
   (Fri Jun 10 12:41:09 2011)
 
 continue
 *

Take care not to confuse SET TRACE RECORD with SET TRACE OUTPUT which changes the DBMS log file.

Enabling Tracing Itself

Once the trace directory is set to enable tracing itself issue trace point SC930 with parameter 1, 2 or 3.

 SET TRACE POINT SC930 1            

enables query tracing

 SET TRACE POINT SC930 2 [1|2]  

enables query tracing (if not already) and also provides QEPs for each query. The optional second parameter sets the QEP style where 1= segmented and 2 = full. See SC930_Output_Format for examples of this.

 SET TRACE POINT SC930 3 N        

enables query tracing (if not already) and sets the number of segments of blob values to output, where 0 is all. This value defaults to 16.

Disabling Tracing

To disable SC930 tracing either issue

 SET TRACE POINT SC930 0

or

 SET NOTRACE POINT SC930

This immediately stops recording for that DBMS.

Output Files

As mentioned a file is created for each session. Filenames are of the format

sess_<DBMS pid>_<session id>

When a trace record needs to be written it checks whether the file exists and either creates or appends to the file as appropriate.

A couple of important points to note about this:

• Since session ids may be re-used a single file may contain the tracing for many sessions that used the same id in turn. Each new session will have a SESSION BEGINS record so it's easy to identify but it's something to be aware of.
• If the trace directory is changed (with SET TRACE RECORD) then a session's trace could be 'split' between different files - the same name but in different directories.

Sample Output

See SC930_Output_Format for the full output specification and various examples. However here is a sample to illustrate the general style:

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 general format is <record type>:<timestamp>:<record data> or <record type>:<record data>. The SESSION BEGINS record shows the session connecting. It gives us the output format version (10 in this case). It shows us which user (ingres) and database (mydb). It would show group and role information if those connection options were used. It also shows the server class (SVRCL=INGRES).

You can see the queries being issued, the QRY records. You can also see when control was passed back to the front-end with the EQY records. These give a timestamp, the number of rows affected by the query and the last error (if any) associated with that session. So we can see for example the "drop table test" failed with E_US0AC1 - which is table does not exist. We can also see that a select * from test later on returned 3 rows. We can also work out how long queries took to execute by looking at the timestamps of QRY and EQY records.

Note that there are several queries which were executed "under the covers" by terminal monitor as part of the connection e.g. select dbmsinfo('UNICODE_NORMALIZATION'). Since SC930 shows all queries we see these too.

You can see the QEP tracing (SC930 2) is switched on and you can see a query producing a QEP. Note if there were REPEATED queries we would only see the QEP the first time it is executed.

Error Reporting and Other Considerations

When it comes to errors in SC930 itself a fairly light approach has been taken. SC930 was designed to be as low overhead as possible and we certainly don't want a problem with it to affect the normal running of the DBMS or user queries.

If there is a problem opening the output file then we do not write the trace record. This means for example if the disk the trace directory is on fills up, or permissions are changed, then the file will stop being written to. However tracing is not disabled so if the problem is resolved it will then continue to write the output files.

A limited amount of information is written to the DBMS log - when the tracing is switched on or off, when the trace directory is set or changed and if an attempt to convert a data value to an output format fails.

Note that the DBMS log is the target for various debug or diagnostic information not related to SC930 and if not already enabled you may not want to enable it simply for the SC930 messages.

How to Tell If SC930 is Available

One question which comes up frequently is how to tell is SC930, or a particular feature of it, is available in a particular Ingres version or patch.

The policy with SC930 has been to include all new features to all existing supported versions of Ingres. Which means that for currently supported versions it will be possible to get a patch with all the SC930 features. At present this means 9.1, 9.2, 9.3 and 10.0. SC930 with limited features is available in later patches for Ingres 2.6 and 2006 (9.0.4)

Quick Test 1: Try the Trace Point!

A very quick test is to try SET TRACE POINT SC930 in an sql session. If you see "E_SC0228 invalid SCF trace point specified" then SC930 is not implemented at all.

Quick Test 2: SC1000

SCF trace points have a "help" trace point, SC1000. If you issue SET TRACE POINT SC1000 it will list the SCxxx trace points. For SC930 it will also list the options with the different parameters. So if, for example, it shows SC930 but not SC930 2 then you can see that QEP tracing has not been implemented in your version.

Check Output Version

Features which cause a change in the output format cause the format version to be increased. This is the first number in brackets in the SESSION BEGINS record. Check against SC930 Output Format to see which features are available for that version.

SIR/BUG List

The following is a list of SIR/BUG numbers relating to SC930. Check the patch notes for your patch for these bugs.

126189 (GENERIC) Ingresdate absolute datetime values incorrectly show the timezone offset to be 0.

126174 (GENERIC) Display of NCHAR/NVARCHAR values in SC930 tracing was inconsistent and sometimes incorrect. Values were displayed each character in hex separated by spaces using as many digits as necessary.

After this fix values will always be displayed in 4 digits.

125591 (VECTORWISE) Add IVW record type for Vectorwise algebra of query.

The SC930 output version associated with this change is 12.

125454 (GENERIC) Add LOB Locator support to sc930 tracing.

The SC930 output version associated with this change is 11.

124943 (GENERIC) Add new SC930 record types QFETCH and QCLOSE. This indicate fetch and close operations for cursors defined using QUEL. The FETCH and CLOSE records now refer only to SQL cursor operations.

The SC930 output version associated with this change is 10.

124687 (GENERIC) SC930 tracing of two-phase commit operations requires improvement. The trace record name of SECURE has been renamed to PREPCOMMIT for clarity and the distributed transaction id is now output as part of this record The format for this is:

PREPCOMMIT:{timestamp}:{high xid}:{low xid}

e.g.

PREPCOMMIT:1288869798/704843000:4cd297a6:402f2860

The SESSION BEGINS record now also has the distributed transaction id. This allows the capture of a CONNECT ... WITH HIGHDXID=..., LOWDXID=...

The database name has also been added to this record.

The format is now:

SESSION BEGINS(9):{timestamp}:(DBID={db id})({user})({role})({group})

(SVRCL={server class})({db name})({high xid}:{low xid})

e.g.

SESSION BEGINS(9):1250194378/29603000:(DBID=1250194236)(ingres )(myRole ) (myGroup )(SVRCL=INGRES )(myDB )(4cd297a6:402f2860)

If no distributed transaction is specified the values will be 0.

The SC930 output version associated with this change is 9.

124671

(GENERIC)

Database procedure parameter values which are too large or have long datatypes may not appear in SC930 tracing.

124654

(GENERIC)

Add XA operations to the SC930 query tracing output. The new trace records are: XA_STRT for xa_start, XA_END for xa_end, XA_PREP for xa_prepare, XA_COMM for xa_commit and XA_RBCK for xa_rollback. The record format for these records is:

 {XA operation}:{timestamp}:XID({XA distr Tx id}):{XA flags}:{XA error code}

e.g.

 XA_STRT:1288362681/465849000:XID(00000064:1:1:01020000:XA):00000000:0

The SC930 output version associated with this change is 9.

124641 (GENERIC) SC930 output for varbyte, byte, nchar or nvarchar values may be missing part of the value.

124617 (GENERIC) Ingresdate values in SC930 trace output has the timezone offset in minutes instead of seconds.

124551 (GENERIC) A query involving a large byte or byte varying value executed under SC930 tracing may cause the DBMS to hang or crash.

124534 (GENERIC) Queries using batch execution will not show up fully in trace logs when SC930 tracing is enabled.

Batch execution was a DBMS feature introduced at Ingres 10.0 so this bug only applies to Ingres 10.0 and later.

124531 (GENERIC) If the directory given by SET TRACE RECORD or II_SC930_LOC does not exist or is not writeable SC930 tracing is silently disabled.

124380 (GENERIC) SC930 2 turns on QEP tracing without SC930 query tracing itself.

124346 (GENERIC) Add an end query record to the SC930 trace. This record has the format

EQY:timestamp:rowcount:error code

If the query did not directly affect a number of rows, e.g. a COMMIT, the rowcount with be -1. If there is no error code this part of the record will be blank.

The SC930 output version including this change is 8.

124345 (GENERIC) Added the new 'segmented' QEP output style to SC930 trace. This style is more readable when the QEPs are large and lines would normally wrap. This is now used when SET TRACE POINT SC930 2 is issued. It can be explicitly chosen with SET TRACE POINT SC930 2 1. The old style can be chosen with SET TRACE POINT SC930 2 2.

The SC930 output version that includes this change is 8.

124161 (GENERIC) In SC930 trace output BYTE and BYTE VARYING datatypes as a string of hex bytes values. Format is:

 length:XX XX XX XX...

An example from a parameter line:

 PARM:24:0=10:00 11 22 33 44 55 66 77 88 99

This shows parameter 0 is datatype 24 (which is BYTE VARYING) and has a value which is 10 bytes namely, 0x00112233445566778899

SC930 Version number is now 7.

123897 (GENERIC) If long datatype values are passed to the DBMS with SC930 tracing in force, e.g. as database procedure parameters, this may cause a SIGSEGV in adu_lvch_move.

The fix for this bug is to output the long values in segments and as part of this change an additional option to SC930 was added:

 SET TRACE POINT SC930 3 N

will cause the tracing to output at most N segments. The segments are roughly 2k in size and the default for N is 16. This matches previous behaviour. To ouput all segments use N=0.

The output format for SC930 has not changed.

123560 (GENERIC) Very long query text may be truncated in SC930 output

123430 (GENERIC) SC930 tracing outputs 0s and empty strings for database procedure parameters regardless of the actual values.

123293 (GENERIC) Add DBMS server_class to the SC930 trace output. The "SESSION BEGINS" line now looks like this:

SESSION BEGINS(6):1266844142/688077000:(DBID=126... )(SVRCL=INGRES  ) 

The SC930 output version number (first number in brackets above) has now been increased to 6.

123108 (GENERIC) REPEATED query involving date parameter run under SC930 tracing fails with SIGSEGV in adu_6to_dtntrl

Bug was introduced by a change made in Ingres 10 only.

123093 (GENERIC) REPEATED INSERT of date, decimal or money value with SC930 tracing on fails with SIGBUS

123056 (GENERIC) Repeated SELECT fails if SC930 tracing is on. Errlog.log reports E_CL2514, SIGSEGV with stack: SIdofrmt, IISTprintf, scsequencer, scs_input

122881 (GENERIC) SIGBUS in scs_desc_send() when running trace point sc930.

122725 (GENERIC) Added tuple descriptor output to SC930 trace. This adds two row types TDESC for the header of the tuple descriptor and COL for each column described. The fields are:

TDESC:column count:overall tuple length:result modifier bitmask COL:Column number:datatype:length:precision

The result modifier bitmask is as described in gca.h. The datatype is one of the integer constants in iicommon.h Precision is used for decimals and represents precision and scale. See the macros DB_P_DECODE_MACRO, DB_S_DECODE_MACRO in iicommon.h which are useful for interpreting these values.

Also abbreviated QUERY to QRY and removed the timestamp for TDESC, COL, PARM, PARMEXEC, QEP, UNKNOWN lines.

SC930 output format version number is now 4.

122544 (GENERIC) SC930 trace output is skipping the first parameter of EXECUTE.

122509 (GENERIC) "set trace point sc930 2" logs query plans to the sc930 tracing log.

122498 (GENERIC) SC930 tracing and security auditing fixes for ansi dates, nchar, nvarchar.

122410 (GENERIC) SC930 tracing does not print large object or long floating-point variables correctly.

122393 (GENERIC) E_LQ002D Associated to the dbms has failed. Caused by using accessdb/createdb/destroydb (the latter two only when the trace point sc930 is switched on).

122312 (GENERIC) SC930 output does not distinguish between a database procedure being created for the first time, or being re-created due to having been flushed from QSF. Added REQUEL and REQUERY for later case.

122299 (GENERIC) Date values are not correctly printing in SC930 tracing.

122172 (GENERIC) SC930 tracing issues A QUERY trace line is produced whenever a database procedure is reparsed due to being flushed from cache. A parameter of >2048 bytes causes a DBMS crash. Datetimes do not include the timezone adjustment. Duplicate output after a syntax error. Blank date - date() - appears as INTERVAL 0/0/0 0:0:0

122062 (GENERIC) When using SC930 tracing under a heavy load some messages may appear in incorrect log files, or even in log files on their own.

122024 (GENERIC) File handle leak during SC930 tracing using parameterised DB procedures.

122011 (Same as 121983) (GENERIC) SC930 amendments

Original bug description above was vague. Actual change involved support for ANSI dates and minor formatting tweaks.

121674 (GENERIC) Include database parameter names in SC930 tracing in case only some of the parameters have been included.

120571 (GENERIC) Enable use of "set trace point sc930 1" to turn on session tracing. Also allow "set trace record '<filename>'" to specify file location.

WARNING: this list of bugs was correct at time of writing and efforts will be made to make sure it is kept up to date, particularly with SIRs which add new features. However it may become out of date. If in doubt about a bug, check with Ingres Technical Support.

Other SC930 Wiki Pages

Wiki page for the Dynamic Playback tool Dynamic_Playback.

Wiki page for the Static Playback tool Static_Playback.

Page to raise/discuss features change requests Change requests for trace point SC930.

Output Format (including history) SC930 Output Format.

A program to convert output files to a more readable format SC930_Human_Readable_Format.

Old Documents

The following documents are available. They are out of date but may be useful for background.

QueryRecording1-2.doc

Capture-Playback Design.pdf

SC930.pdf