1 Tools for Troubleshooting TimesTen

Example 1-8 SQL trace

In this example, we execute ttTraceMon to do a SQL trace at level 4 on the demo database. We direct the output from the SQL trace to the SQLtrace.txt file. We then flush the buffer so that the trace does not report past SQL statements.

% ttTraceMon demo
Trace monitor; empty line to exit
Trace > outfile SQLtrace.txt
Trace > level sql 4
Trace > flush

At this point, we execute an application that includes the following SQL statement:

SELECT * FROM departments WHERE department_id = 10;

The trace information is written to the SQLtrace.txt file:

12:19:36.582     269 SQL      2L    3C  29570P Preparing: select * from 
departments where department_id = 10
12:19:36.583     270 SQL      4L    3C  29570P sbSqlCmdCompile ()(E): (Found 
already compiled version: refCount:01, bucket:28) cmdType:100, cmdNum:1000146.
12:19:36.583     271 SQL      4L    3C  29570P Opening: select * from departments 
where department_id = 10;
12:19:36.583     272 SQL      4L    3C  29570P Fetching: select * from 
departments where department_id = 10;
12:19:36.583     273 SQL      4L    3C  29570P Closing: select * from departments 
where department_id = 10;
5 records dumped

When the application has completed, we turn off SQL tracing and exit ttTraceMon.

Trace > level sql 0
Trace > {press ENTER – blank line}

Example 1-9 API trace

In this example, we execute ttTraceMon to do a API trace at level 3 on the demo database. The output from the API trace is written to the APItrace.txt file. Before saving the API trace to the buffer, we use the flush command to empty the buffer.

% ttTraceMon demo
Trace monitor; empty line to exit
Trace> outfile APItrace.txt
Trace> level api 3
Trace > flush

At this point, we execute the application. When the application has completed, we turn off API tracing and exit ttTraceMon:

Trace > level api 0
Trace > {press ENTER – blank line}

The contents of APItrace.txt are similar to the sample output shown below. The output shows connection to the database, setting the connection character set, setting the isolation level, and committing a transaction.

11:54:26.796    1016 API      3L    2C   4848P sb_dbConnect()(X)
11:54:26.796    1017 API      3L    2C   4848P sb_dbConnCharsetSet()(E)
11:54:26.796    1018 API      3L    2C   4848P sb_dbConnSetIsoLevel()(E)
11:54:39.795    1019 API      3L    2C   4848P sb_dbConnSetIsoLevel()(E)
11:54:45.253    1020 API      3L    2C   4848P sb_xactCommitQ()(E)

Example 1-10 DEADLOCK trace

In this example, we execute ttTraceMon to do a DEADLOCK trace at level 1, which is the default, on myDSN database.

We make two connections to myDSN. For the first connection, autocommit is on. We create table test and insert two rows. Then, we set autocommit off and update the x1=1 row of table test. Because autocommit is off, the row is not inserted into the table until we commit. A lock is held until we commit or roll back the transaction.

Command> create table test (x1 int unique, y1 int);
Command> insert into test values (1,1);
1 row inserted.
Command> insert into test values (2,2);
1 row inserted.
Command> autocommit 0;
Command> update test set y1=y1 where x1=1;
1 row updated.

For the second connection to myDSN, autocommit is set to off. We update the x1=2 row of table test.

Command> autocommit 0;
Command> update test set y1=y1 where x1=2;1 row updated.

Now, we create a deadlock situation by executing update statements in both connections for rows that are locked by each other. The first connection executes an update against the row where x1=2.

Command> update test set y1=y1 where x1=2;
 6003: Lock request denied because of time-out
Details: Tran 2.1 (pid 32750) wants Un lock on rowid BMUFVUAAAAaAAAAETk, 
table ME.TEST. But tran 3.2 (pid 32731) has it in Xn (request was Xn).
Holder SQL (update t1 set y1=y1 where x1=2)
The command failed.

The second connection executes an update against the row where x1=1.

Command> update test set y1=y1 where x1=1;
 6002: Lock request denied because of deadlock
Details: Tran 3.2 (pid 32731) wants Un lock on rowid BMUFVUAAAAaAAAADzk, 
table ME.TEST. But tran 2.1 (pid 32750) has it in Xn (request was Xn). 
Holder SQL (update t1 set y1=y1 where x1=1)
The command failed.

We use the flush command to empty the buffer.

% ttTraceMon myDSN
Trace monitor; empty line to exit
Trace> flush

The trace buffer contains the following information showing all level 1 deadlock traces, as evidenced by '1L'.:

Trace> dump
09:50:26.444      13 DEADLOCK 1L 2036C   3484P edge 1: xid 3.2, cid 3, 
<Row BMUFVUAAAAaAAAADzk,0x8c5
74(574836)> 0 cnt=1 , Tbl 'T1', SQL='update t1 set y1=y1 where x1=1'
09:50:26.455      14 DEADLOCK 1L 2036C   3484P edge 0: xid 2.1, cid 2, 
<Row BMUFVUAAAAaAAAAETk,0x8c5
74(574836)> 0 cnt=1 , Tbl 'T1', SQL='update t1 set y1=y1 where x1=2'
09:50:26.455      15 DEADLOCK 1L 2036C   3484P Victim: xcb:3.2, 
SQL='update t1 set y1=y1 where x1=1'

If you want more information, set DEADLOCK tracing to a higher value. For example, the following sets DEADLOCK tracing to level 4 in ttTraceMon:

Trace > level deadlock 4

Example 1-11 LOCK trace

In this example, we execute ttTraceMon to do a LOCK trace at level 4 on myDSN database.

We make two connections to myDSN. For the first connection, we set autocommit on. We create table test and insert three rows. We create a materialized view using table test.

We turn on tracing at level 4 and use the flush command to empty the buffer.

% ttTraceMon myDSN
Trace monitor; empty line to exit
Trace> level lock 4
Trace> flush

For the second connection to myDSN, we set autocommit off. We insert a row into table test. Because autocommit is off, the row is not inserted into the table until we commit. A lock is held until we commit or roll back the transaction.

If we use the dump command to display the contents of the trace buffer, we see that there are no records in the trace buffer:

Trace> dump
0 records dumped

From the first connection, we try to drop the materialized view. We cannot drop the view because there is a transaction that has not been committed or rolled back:

Command> drop materialized view v;
 6003: Lock request denied because of time-out
Details: Tran 3.71 (pid 24524) wants Sn lock on table TTUSER.TEST. But tran 1.42 
(pid 24263) has it in IXn (request was IXn). Holder SQL (insert into test values (100);)
The command failed.

The trace buffer contains the following information:

Trace> dump
20:09:04.789  174759 LOCK     3L    3C  24524P ENQ: xcb:00003 <Tbl 0x9b894,0x0>
0+Sn=>SL activity 0 Sn cnt=0; Holder xcb:00001 IXn
20:09:04.789  174760 LOCK     3L    3C  24524P Connection 3 scheduled for sleep
20:09:04.789  174761 LOCK     3L    3C  24524P Connection 3 sleeping
20:09:14.871  174762 LOCK     3L 2047C  24237P Connection 3 timed out
20:09:14.871  174763 LOCK     3L 2047C  24237P Connection 3 woken up
20:09:14.871  174764 LOCK     3L    3C  24524P Connection 3 awake
20:09:14.871  174765 LOCK     2L    3C  24524P ENQ: xcb:00003 <Tbl 0x9b894,0x0>
0+Sn=>TM activity 0 Sn cnt=1; Holder xcb:00001 IXn
7 records dumped

When finished with the trace, we set LOCK tracing back to its default setting (0) and exit ttTraceMon:

Trace > level lock 0
Trace > {press ENTER – blank line}

Example 1-12 ERR trace

In this example, we execute ttTraceMon to do a ERR trace at level 4 on myDSN database.

First we create a table:

Command> create table test (id tt_integer);

Next we turn on tracing at level 4. Rather than direct the trace output to a file as in the previous examples, we read it directly from the trace buffer. Before saving the ERR trace to the buffer, we use the flush command to empty the buffer.

% ttTraceMon myDSN
Trace monitor; empty line to exit
Trace> level err 4
Trace> flush

Now we execute a SQL script with three errors in it. The errors are:

Example 1-13 AGING trace

In this example, we execute ttTraceMon to do an AGING trace on myDSN database. The database contains TTUSER.MYTAB table, which has a time-based aging policy. The table is described as follows:

Command> describe TTUSER.MYTAB;

Table TTUSER.MYTAB:
  Columns:
   *ID                              TT_INTEGER NOT NULL
    TS                              TIMESTAMP (6) NOT NULL
  Aging use TS lifetime 3 minutes cycle 1 minute on

1 table found.
(primary key columns are indicated with *)

The table contains the following rows before the aging cycle begins:

Command> select * from TTUSER.MYTAB;
< 1, 2007-03-21 12:54:06.000000 >
< 3, 2010-03-17 08:00:00.000000 >
< 4, 2007-03-21 12:59:40.000000 >
< 5, 2007-03-21 13:00:10.000000 >
< 6, 2007-03-21 13:01:22.000000 >
5 rows found.

We execute ttTraceMon to do an AGING trace at level 3. Rather than direct the trace output to a file, we read it directly from the trace buffer. Before saving the AGING trace to the buffer, we use the flush command to empty the buffer.

% ttTraceMon myDSN
Trace monitor; empty line to exit
Trace> level aging 3
Trace> flush

Display the trace information in the buffer by using the dump command.

Trace> dump
13:16:56.802    1247 AGING    1L 2045C  17373P Entering sbAgingTB(): curTime=78
13:16:56.803    1248 AGING    2L 2045C  17373P Entering sbAgingOneTable(): 
curTime=78, ltblid= 637140
13:16:56.804    1249 AGING    3L 2045C  17373P curTime=78, 4 deleted, 1 
remaining, tbl = TTUSER.MYTAB
13:16:56.804    1250 AGING    2L 2045C  17373P Exiting sbAgingOneTable(): 
curTime=78, reason = 'no more rows', 4 deleted, 1 remaining, tbl = TTUSER.MYTAB
13:16:56.804    1251 AGING    1L 2045C  17373P Exiting sbAgingTB(): curTime=78
5 records dumped

We set AGING tracing back to its default setting (0) and exit ttTraceMon:

Trace > level aging 0
Trace > {press ENTER – blank line}

Example 1-14 AUTOREFRESH trace

In this example, we use the ttTraceMon utility to trace autorefresh operations on the cgDSN database. When we set the trace level to 1, we see information that is similar to the output of the ttCacheAutorefreshStatsGet built-in procedure.

% tttracemon cgDSN
Trace monitor; empty line to exit
Trace> level autorefresh 1
Trace> dump

08:56:57.445 19398 AUTOREFRESH 1L 5C 32246P Autorefresh number 1415 started for interval 60000
08:56:57.883 19419 AUTOREFRESH 1L 5C 32246P Duration For Interval 60000ms: 420
08:56:57.883 19420 AUTOREFRESH 1L 5C 32246P Num Rows For Interval 60000ms: 0
08:56:57.883 19421 AUTOREFRESH 1L 5C 32246P Num Root Rows For Interval 60000ms: 0
08:56:57.883 19422 AUTOREFRESH 1L 5C 32246P Cumulative Rows for Interval 60000ms: 11587
08:56:57.883 19423 AUTOREFRESH 1L 5C 32246P Cumulative Root Rows for Interval 60000ms: 1697
08:56:57.883 19424 AUTOREFRESH 1L 5C 32246P Autorefresh number 1415 ended for interval 60000ms successfully.
7 records dumped

Tracing at level 4 produces additional information about autorefresh operation 1415. Information about autorefresh is provided for the testuser.readcache cache group, the testuser.readtab root table and the autorefresh interval.

Trace> level autorefresh 4
Trace> dump

08:56:57.445 19398 AUTOREFRESH 1L 5C 32246P Autorefresh number 1415 started for interval 60000
08:56:57.471 19399 AUTOREFRESH 2L 5C 32246P Autorefresh started for cachegroup TESTUSER.READCACHE
08:56:57.471 19400 AUTOREFRESH 3L 5C 32246P Incremental autorefresh started for table TESTUSER.READTAB
08:56:57.471 19401 AUTOREFRESH 4L 5C 32246P Autorefresh Query: SELECT L."COL_10", 
X."COL_20", X.ft$NotDelete, Z.rowid FROM (SELECT DISTINCT "COL_10" FROM 
"TESTUSER"."TT_03_454854_L" WHERE logseq >:logseq AND ft_cacheGroup <> 
100000000000*1844259679+-299200618) L,(SELECT "TESTUSER"."READTAB"."COL_10", 
"TESTUSER"."READTAB"."COL_20", 1 AS ft$NotDelete  FROM "TESTUSER"."READTAB", 
"TESTUSER"."T1" WHERE "TESTUSER"."READTAB"."COL_10" = "TESTUSER"."T1"."COL_10") 
X, "TESTUSER"."READTAB" Z WHERE L ."COL_10" = X."COL_10" (+) AND X."COL_10" = 
Z."COL_10" (+), logseq: 7
08:56:57.870 19402 AUTOREFRESH 3L 5C 32246P Duration for table TESTUSER.READTAB: 70
08:56:57.870 19403 AUTOREFRESH 3L 5C 32246P Num Rows for table TESTUSER.READTAB: 1
08:56:57.870 19404 AUTOREFRESH 3L 5C 32246P Cumulative rows for table TESTUSER.READTAB: 1559
08:56:57.870 19405 AUTOREFRESH 4L 5C 32246P Autorefresh Query Execute duration for table TESTUSER.READTAB: 60
08:56:57.870 19406 AUTOREFRESH 4L 5C 32246P Autorefresh Query Fetch duration for table TESTUSER.READTAB: 0
08:56:57.870 19407 AUTOREFRESH 4L 5C 32246P Autorefresh Query Apply duration for table TESTUSER.READTAB: 0
08:56:57.870 19408 AUTOREFRESH 4L 5C 32246P Max logseq applied for table TESTUSER.READTAB: 8
08:56:57.870 19409 AUTOREFRESH 4L 5C 32246P Autorefresh Query Execute duration for 7 child(ren) table(s): 32
08:56:57.870 19410 AUTOREFRESH 4L 5C 32246P Autorefresh Query Fetch duration for 7 child(ren) table(s): 0
08:56:57.870 19411 AUTOREFRESH 4L 5C 32246P Autorefresh Query Apply duration for 7 child(ren) table(s): 0
08:56:57.870 19412 AUTOREFRESH 3L 5C  32246P Incremental autorefresh ended for table TESTUSER.READTAB
08:56:57.872 19413 AUTOREFRESH 2L 5C 32246P Duration For Cache Group TESTUSER.READCACHE: 1020
08:56:57.872 19414 AUTOREFRESH 2L 5C 32246P Num Rows For Cache Group TESTUSER.READCACHE: 1
08:56:57.872 19415 AUTOREFRESH 2L 5C 32246P Num Root Rows For Cache Group TESTUSER.READCACHE: 0
08:56:57.872 19416 AUTOREFRESH 2L 5C 32246P Cumulative Rows for Cache Group TESTUSER.READCACHE: 11776
08:56:57.872 19417 AUTOREFRESH 2L 5C 32246P Cumulative Root Rows for Cache Group TESTUSER.READCACHE: 1697
08:56:57.872 19418 AUTOREFRESH 2L 5C 32246P Autorefresh ended for cache group TESTUSER.READCACHE
08:56:57.883 19419 AUTOREFRESH 1L 5C 32246P Duration For Interval 60000ms: 420
08:56:57.883 19420 AUTOREFRESH 1L 5C 32246P Num Rows For Interval 60000ms: 0
08:56:57.883 19421 AUTOREFRESH 1L 5C 32246P Num Root Rows For Interval 60000ms: 0
08:56:57.883 19422 AUTOREFRESH 1L 5C 32246P Cumulative Rows for Interval 60000ms: 11587
08:56:57.883 19423 AUTOREFRESH 1L 5C 32246P Cumulative Root Rows for Interval 60000ms: 1697
08:56:57.883 19424 AUTOREFRESH 1L 5C 32246P Autorefresh number 1415 ended for interval 60000ms successfully.
27 records dumped

We set AUTOREFRESH tracing back to its default setting (0) and exit ttTraceMon:

Trace > level autorefresh 0
Trace > {press ENTER – blank line}