-
Notifications
You must be signed in to change notification settings - Fork 1
Ingres DBMS Server Query Tracing
This document describes the DBMS Server Query Tracing facility which is implemented by the SC930 trace point.
- Introduction
-
How to Enable Query Tracing
2.1 II_SC930_LOC
2.2 SET TRACE RECORD
2.3 Enabling Tracing Itself
2.4 Disabling Tracing -
Output Files
3.1 Sample Output - Error Reporting and Other Considerations
- Security Implications
-
How to Tell If SC930 is Available
6.1 Quick Test 1: Try the Trace Point!
6.2 Quick Test 2: SC1000
6.3 Check Output Version - Other SC930 Wiki Pages
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'.
As of Ingres 11.0 DBMS Query Tracing has become fully supported via the SET SERVER_TRACE and SESSION_TRACE SQL statements. See the Ingres 11.0 documentation for more details. The SC930 trace point still works but the SERVER_TRACE/SESSION_TRACE is preferred going forward.
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 can be set either as a local environment variable or by ingsetenv. It takes effect the next time a DBMS server is started.
ingsetenv II_SC930_LOC /tmp
ingstop
ingstart
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.
Once the trace directory is set to enable tracing itself issue trace point SC930 with parameter 1, 2, 3, 4 or 5.
SET TRACE POINT SC930 1
enables query tracing. If tracing is enabled for a single database or all but a single database (see 4 & 5 below) then it will be enabled for all databases.
SET TRACE POINT SC930 2 [1|2|3|4]
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 = tree, 4 = concise and 3 = off. See SC930_Output_Format for examples of this. If tracing is enabled for a single database then this will not change the scope of the tracing it will just turn on QEP output.
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. As with 2 this does not change the scope of tracing if already on just the style of the output.
SET TRACE POINT SC930 4 [N]
enables query tracing for the database with id N only. The database id is shown in the output of infodb or can be queried from the iidbdb table iidatabase. If N is not given then the current database (the one attached to when issuing the trace point) is the one for which tracing is enabled. If N=0 and tracing is on it will revert to all databases.
SET TRACE POINT SC930 5 [N]
enables query tracing for all databases apart from the one with id N. If N is not given then the current database is the one for which tracing is excluded. If N=0 and tracing is on it will revert to all databases.
To disable SC930 tracing either issue
SET TRACE POINT SC930 0
or
SET NOTRACE POINT SC930
This immediately stops recording for that DBMS.
As mentioned a file is created for each session. Filenames are of the format
sess__
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.
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 :: or :. 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.
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.
It's important to note that SC930 dumps all the query text that is processed by the DBMS server. This could include potentially sensitive information. For example an INSERT statement with the VALUES clause may include actual data to be inserted in the query text itself, if so this will appear in the SC930 trace files. If this was data being inserted into an encrypted column you would be able to read it in its unencrypted form. Also MODIFY TO ENCRYPT or a CREATE TABLE with encryption would suffer from this vulnerability.
This behaviour is in line with the parameters of encryption of "data at rest" but the user needs to be aware of the implications. The recommendations are to not give the trace point privilege to any untrusted person and to place the SC930 logs in a suitably secure location, possibly on an encrypted filesystem.
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.2, 10 10S (10.1) and 10.2. SC930 with limited features is available in later patches for Ingres 2.6, 2006 (9.0.4), 2006r2 (9.1) and 9.3
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.
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.
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.
Wiki page for the Dynamic Playback tool Dynamic_Playback.
Output Format (including history): SC930 Output Format.
A program to convert output files to a more readable format: SC930_Human_Readable_Format.
A script to find long-running queries: SC930_Long-Running_Queries
A python program to find long-running queries: SC930_LRQ