Cursor “no parse” execution trace

 

There are approximately 4 “types” of SQL cursor execution in Oracle.

hard parse
soft parse
softer soft parse
no parse

See http://alexzeng.wordpress.com/2012/12/31/oracle-core-hard-parse-soft-parse-soft-soft-parse-no-parse-at-all/
for instance.

However I was always wondering what is going under the hood for “no parse” case.
Your client (JDBC or whatever) should communicate somehow with your Oracle server.
It can’t be SQL statement itself otherwise some kind of parsing is unavoidable.
So it seems natural that you need to exchange some kind of identifier.

But what exact identifier/s are used in Oracle vs. client  communication.
I’ve read/heard several times that some kind of Oracle handles exists in sessions PGA area, etc. but never seen the details.

So I decided to trace it by myself.

It seems Wireshark is an ultimate tool to see what is going on on networking layer.

My Java testcase look like:

Connection con = dataSource.getConnection();
PreparedStatement ps = con.prepareStatement(SQL);
PreparedStatement ps2 = con.prepareStatement(SQL2);
for (int j=1; j<30; j++) {   //traverse 1st 30 param sets
..... set bind variables
for (int l=1;l<=8;l++) {
   ResultSet rs= ps.executeQuery();
   ResultSet rs2= ps2.executeQuery();
    while (rs.next()){
        System.out.print('.');
    }
    while (rs2.next()){
        System.out.print('.');
    }
   rs.close();
   rs2.close();
}
...
}

First of all no network round trip on  con.prepareStatement(SQL) step (it seems postponed to make simultaneously  prepare and execute phase)

1st execution of  ResultSet rs= ps.executeQuery() looks like below:
You easily can see text of my SELECT query here:cursor0

According to TNS protocol spec here:
http://thesprawl.org/research/oracle-tns-protocol/
0x03 is a code of TTI function call and ox5e is a subcode for query (SELECT) operation.

However the most interesting part is 2nd and all consequent executions (they should go as “no parse” variant)

Let’s compare 2nd and 3rd execution of:

ResultSet rs= ps.executeQuery();
ResultSet rs2= ps2.executeQuery();

2nd execution
cursor_comp1

3rd execution:

cursor_comp2

You can see 2 interesting parts here:

  • 1st part just after 0x03 ox53  – looks like a counter of consequent SQL executions for your session ( 0x07, 0x08, 0x09, 0x0a)
  • 2nd part 0x03 for one query and 2nd one 0x05  are repeatable for all executions (I have shown only 2 of them here)

So it seems our desirable cursor identifier and it is definitely not a sql_id or sql handler (as been claimed somewhere).
The most interesting question however what does it mean exactly.

Let’s do a CURSORDUMP as described here:
http://blog.tanelpoder.com/2009/07/09/identify-the-sql-statement-causing-those-wait-x-lines-in-a-top-truncated-sql-tracefile/
oradebug setospid 1820
oradebug dump cursordump 1

And the extract of result looks like:

Cursor#3(0xffff80ffbde11c48) state=BOUND curiob=0xffff80ffbde28a40
 curflg=4e fl2=0 par=0x0 ses=0x1fcbd8db0
----- Dump Cursor sql_id=6ndm9d5b9vg1t xsc=0xffff80ffbde28a40 cur=0xffff80ffbde11c48 -----

LibraryHandle:  Address=1fb2d5ae8 Hash=569dbc39 LockMode=N PinMode=0 LoadLockMode=0 Status=VALD
  ObjectName:  Name=SELECT /* NoParse_40Issue */ * FROM YYTEST WHERE (f1,f2,f3,f4,f5,f6,f7,f8,f9,f10,f11,f12,f13,f14,f15,f16,f17,f18,f19,f20,f21,f22,f23,f24,f25,f26,f27,f28,f29,f30,f31,f32,f33,f34,f35,f36,f37,f38,f39,f40) IN ((:f1,:f2,:f3,:f4,:f5,:f6,:f7,:f8,:f9,:f10,:f11,:f12,:f13,:f14,:f15,:f16,:f17,:f18,:f19,:f20,:f21,:f22,:f23,:f24,:f25,:f26,:f27,:f28,:f29,:f30,:f31,:f32,:f33,:f34,:f35,:f36,:f37,:f38,:f39,:f40))
    FullHashValue=258bfcabddf89e5c6a366969569dbc39 Namespace=SQL AREA(00) Type=CURSOR(00) Identifier=1453177913 OwnerIdn=85
  Statistics:  InvalidationCount=4 ExecutionCount=30 LoadCount=6 ActiveLocks=2 TotalLockCount=2 TotalPinCount=1
  Counters:  BrokenCount=1 RevocablePointer=1 KeepDependency=5 BucketInUse=1 HandleInUse=1 HandleReferenceCount=0
  Concurrency:  DependencyMutex=1fb2d5b98(0, 6, 0, 0) Mutex=1fb2d5c18(164, 99, 0, 6)
  Flags=RON/PIN/TIM/PN0/DBN/[10012841]
...............................
...................................
................................
Cursor#5(0xffff80ffbde11d68) state=BOUND curiob=0xffff80ffbdca1f80
 curflg=4e fl2=0 par=0x0 ses=0x1fcbd8db0
----- Dump Cursor sql_id=84mwtcmy0b3za xsc=0xffff80ffbdca1f80 cur=0xffff80ffbde11d68 -----

LibraryHandle:  Address=1fb2ce130 Hash=fc058fea LockMode=N PinMode=0 LoadLockMode=0 Status=VALD
  ObjectName:  Name=SELECT /* NoParse_40Issue */ * FROM YYTEST WHERE (f1,f2,f3,f4,f5,f6,f7,f8,f9,f10,f11,f12,f13,f14,f15,f16,f17,f18,f19,f20) IN ((:f1,:f2,:f3,:f4,:f5,:f6,:f7,:f8,:f9,:f10,:f11,:f12,:f13,:f14,:f15,:f16,:f17,:f18,:f19,:f20))
    FullHashValue=fa2532489a58f35a824f9964fc058fea Namespace=SQL AREA(00) Type=CURSOR(00) Identifier=4228222954 OwnerIdn=85
  Statistics:  InvalidationCount=4 ExecutionCount=29 LoadCount=6 ActiveLocks=2 TotalLockCount=2 TotalPinCount=1
  Counters:  BrokenCount=1 RevocablePointer=1 KeepDependency=5 BucketInUse=1 HandleInUse=1 HandleReferenceCount=0
  Concurrency:  DependencyMutex=1fb2ce1e0(0, 6, 0, 0) Mutex=1fb2ce260(164, 91, 0, 6)
  Flags=RON/PIN/TIM/PN0/DBN/[10012841]

 

So you can see that JDBC client  passes “slot number in open cursor array in UGA” for “no parse” execution
(see again : http://blog.tanelpoder.com/2009/07/09/identify-the-sql-statement-causing-those-wait-x-lines-in-a-top-truncated-sql-tracefile/)

 

 

 

 

 

Advertisements

Something for free (serverside variables on JDBC client)

Two code pieces below give the same result,
The 1st one doesn’t require network round-trip/additional SQL execution at all.

  • String sidKey = (((oracle.jdbc.driver.OracleConnection) connection)).getServerSessionInfo().getProperty(“AUTH_SESSION_ID”);
  • ResultSet rsSid = connection.createStatement().executeQuery(“select SYS_CONTEXT(‘USERENV’, ‘SID’) from dual”);
    int sid = 0;
    if (rsSid.next()) {
    sid = rsSid.getInt(1);
    }
  • A full list as of 11.2.0.4 Oracle database and ojdbc6.jar JDBC driver
"INSTANCE_NAME"
"AUTH_NLS_LXCSTMPFM"
"AUTH_VERSION_STATUS"
"AUTH_SC_SERVER_HOST"
"SESSION_NLS_LXCNCHAREXCP"
"SERVER_HOST"
"AUTH_NLS_LXCTTZNFM"
"AUTH_SVR_RESPONSE"
"AUTH_FAILOVER_ID"
"AUTH_SERIAL_NUM"
"AUTH_NLS_LXLAN"
"AUTH_SC_INSTANCE_START_TIME"
"AUTH_SC_INSTANCE_NAME"
"AUTH_DBNAME"
"AUTH_SC_DB_DOMAIN"
"SESSION_NLS_LXCCHARSET"
"AUTH_DB_ID"
"AUTH_INSTANCENAME"
"AUTH_VERSION_SQL"
"AUTH_NLS_LXCTERRITORY"
"SESSION_TIME_ZONE"
"AUTH_INSTANCE_NO"
"DATABASE_NAME"
"AUTH_SC_SERVICE_NAME"
"AUTH_SERVER_PID"
"AUTH_NLS_LXCSORT"
"AUTH_NLS_LXCISOCURR"
"AUTH_VERSION_NO"
"AUTH_NLS_LXCDATELANG"
"SERVICE_NAME"
"AUTH_NLS_LXCSTZNFM"
"AUTH_SC_DBUNIQUE_NAME"
"AUTH_NLS_LXCDATEFM"
"AUTH_NLS_LXCUNIONCUR"
"AUTH_VERSION_STRING"
"AUTH_SESSION_ID"
"SESSION_NLS_LXCNLSLENSEM"
"AUTH_NLS_LXCNUMERICS"
"AUTH_XACTION_TRAITS"
"AUTH_SC_INSTANCE_ID"
"AUTH_SC_SVC_FLAGS"
"AUTH_NLS_LXCTIMEFM"
"AUTH_DB_MOUNT_ID"
"AUTH_CAPABILITY_TABLE"
"AUTH_USER_ID"
"AUTH_NLS_LXCCURRENCY"
"AUTH_NLS_LXCCALENDAR"

Oracle 12c pluggable and “common” directory recreation issue.

Recently I did a stupid thing

DROP DIRECTORY DATA_PUMP_DIR; -- issues from CDB$ROOT

before that my PDBs was able to see this standard directory:

SELECT directory_name FROM dba_directories WHERE directory_name='DATA_PUMP_DIR';

I’ve almost immediate recreate the directory as:

CREATE DIRECTORY DATA_PUMP_DIR as '/tmp';

but

GRANT READ,WRITE ON DIRECTORY DATA_PUMP_DIR TO IMP_FULL_DATABASE CONTAINER=ALL;

ERROR at line 1:
ORA-65033: a common privilege may not be granted or revoked on a local object

I even not been able to recreate it as a “local” PDB object:

DROP DIRECTORY DATA_PUMP_DIR; -- on CDB$ROOT

on pluggable database

CREATE DIRECTORY DATA_PUMP_DIR as '/u01/data/data_pump'
 *
ERROR at line 1:
ORA-00955: name is already used by an existing object

as metadata link object is still here (I believe that is Oracle’s bug).

After a bit googling I found an excellent blog:
http://blog.dbi-services.com/oracle-12c-cdb-metadata-a-object-links-internals/
that gave me an idea how to fix the issue (as usual ALTER SESSION SET “_oracle_script”=true  is our best frient with container database).

So on CDB$ROOT:

ALTER SESSION SET "_oracle_script"=true;
CREATE DIRECTORY DATA_PUMP_DIR sharing=metadata  as '/tmp';
GRANT READ,WRITE ON DIRECTORY DATA_PUMP_DIR TO IMP_FULL_DATABASE CONTAINER=ALL;

And can see again my DATA_PUMP_DIR in the pluggable database

SELECT directory_name FROM dba_directories WHERE directory_name='DATA_PUMP_DIR'; --in pluggable

 

 

 

 

 

 

 

 

Oracle optimizer limitation with bitmap indexes operations

Recently I stumbled with an issue when trying to access quite big tables with bitmap indexes.
I had two big segments (table partitions): one with 1e10+ rows another one an order of magnitude smaller.
Both tables have bitmap indexed column. The column have quite a big amount of repeatable values (~10000 rows per key) so corresponding bitmap index segments were pretty small 1. I don’t need any other column from the table
2. and I only need distinct values of those keys (not the amount of the corresponding rows).

But I’ve got unexpected result: after dozens and dozen minutes of execution I had to stop the query as it had produced ~0.5TB of temp on BITMAP CONVERSION TO ROWIDS operation.

Let me reproduce the issue and the solution with a simplified example.

First of all let’s prepare tables:

DROP TABLE IDXMAIN;
DROP TABLE IDXAUX;

CREATE TABLE IDXMAIN AS SELECT rownum id, trunc(rownum/100)*100 unit_id,rpad('a',1000,'v') filler from dual connect by level <=1e4;

ALTER TABLE IDXMAIN MODIFY unit_id NOT NULL;

CREATE BITMAP INDEX IDXMAIN_IX1 ON IDXMAIN (unit_id);

CREATE TABLE IDXAUX AS
 SELECT id2*mult id2, unit_id*mult unit_id, filler FROM (SELECT rownum id2, trunc(1 + rownum/1000)*100 unit_id,rpad('b',10,'z') filler from dual connect by level <=1e6),
 (select rownum mult from dual connect by level<=10);

ALTER TABLE IDXAUX MODIFY unit_id NOT NULL;

CREATE BITMAP INDEX IDXAUX_IX1 ON IDXAUX(unit_id);

exec dbms_stats.gather_table_stats(NULL, 'IDXMAIN');

exec dbms_stats.gather_table_stats(NULL, 'IDXAUX');

so I prepared 2 tables with 1e4 and 1e7 records, both of them have unit_id column with 100 records per key.

let’s start with a simplest case:

SQL_ID	ckpbc1z9cgw95, child number 0
-------------------------------------
select distinct unit_id from IDXMAIN m WHERE EXISTS (select 1 from
IDXAUX a WHERE a.unit_id=m.unit_id)

Plan hash value: 1340588278

-------------------------------------------------------------------------------------------------------------------------------------------------------------------
| Id  | Operation		       | Name	     | Starts | E-Rows |E-Bytes| Cost (%CPU)| E-Time   | A-Rows |   A-Time   | Buffers |  OMem |  1Mem | Used-Mem |
-------------------------------------------------------------------------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT	       |	     |	    1 |        |       |  2062 (100)|	       |    100 |00:00:55.51 |	  2281 |       |       |	  |
|   1 |  HASH UNIQUE		       |	     |	    1 |    101 |   707 |  2062	 (2)| 00:00:42 |    100 |00:00:55.51 |	  2281 |  1518K|  1518K| 1360K (0)|
|*  2 |   HASH JOIN SEMI	       |	     |	    1 |   9900 | 69300 |  2061	 (2)| 00:00:42 |   9901 |00:00:55.49 |	  2281 |  1594K|  1594K| 2220K (0)|
|   3 |    BITMAP CONVERSION TO ROWIDS |	     |	    1 |  10000 | 30000 |     1	 (0)| 00:00:01 |  10000 |00:00:00.01 |	     3 |       |       |	  |
|   4 |     BITMAP INDEX FAST FULL SCAN| IDXMAIN_IX1 |	    1 |        |       |	    |	       |    101 |00:00:00.01 |	     3 |       |       |	  |
|   5 |    BITMAP CONVERSION TO ROWIDS |	     |	    1 |     10M|    38M|  2037	 (0)| 00:00:41 |     10M|00:00:14.06 |	  2278 |       |       |	  |
|   6 |     BITMAP INDEX FAST FULL SCAN| IDXAUX_IX1  |	    1 |        |       |	    |	       |   6426 |00:00:00.02 |	  2278 |       |       |	  |
-------------------------------------------------------------------------------------------------------------------------------------------------------------------

I see 2 “BITMAP CONVERSION TO ROWIDS” operations which are unnecessary I believe
as finally I need only distinct unit_id
It seems optimizer put HASH UNIQUE operation above HASH SEMI-JOIN itself(looks like missing of some useful transformation). OK I appreciate optimizer’s hard work and decided to help it a bit.

SQL_ID	0n848w015ck2m, child number 0
-------------------------------------
select * FROM (select distinct unit_id from IDXMAIN ) m WHERE EXISTS
(select 1 from IDXAUX a WHERE a.unit_id=m.unit_id)

Plan hash value: 2273114039

-------------------------------------------------------------------------------------------------------------------------------------------------------------------
| Id  | Operation		       | Name	     | Starts | E-Rows |E-Bytes| Cost (%CPU)| E-Time   | A-Rows |   A-Time   | Buffers |  OMem |  1Mem | Used-Mem |
-------------------------------------------------------------------------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT	       |	     |	    1 |        |       |   204 (100)|	       |    100 |00:00:00.01 |	   213 |       |       |	  |
|   1 |  NESTED LOOPS SEMI	       |	     |	    1 |    100 |  1700 |   204	 (1)| 00:00:05 |    100 |00:00:00.01 |	   213 |       |       |	  |
|   2 |   VIEW			       |	     |	    1 |    101 |  1313 |     2	(50)| 00:00:01 |    101 |00:00:00.01 |	     3 |       |       |	  |
|   3 |    HASH UNIQUE		       |	     |	    1 |    101 |   303 |     2	(50)| 00:00:01 |    101 |00:00:00.01 |	     3 |  1518K|  1518K| 1392K (0)|
|   4 |     BITMAP INDEX FAST FULL SCAN| IDXMAIN_IX1 |	    1 |  10000 | 30000 |     1	 (0)| 00:00:01 |    101 |00:00:00.01 |	     3 |       |       |	  |
|   5 |   BITMAP CONVERSION TO ROWIDS  |	     |	  101 |   9900K|    37M|   204	 (1)| 00:00:05 |    100 |00:00:00.01 |	   210 |       |       |	  |
|*  6 |    BITMAP INDEX SINGLE VALUE   | IDXAUX_IX1  |	  101 |        |       |	    |	       |    100 |00:00:00.01 |	   210 |       |       |	  |
-------------------------------------------------------------------------------------------------------------------------------------------------------------------

Well we get rid of one of BITMAP CONVERSION TO ROWIDS,
However on this phase I would expect optimizer guess that the second BITMAP CONVERSION TO ROWIDS is unnecessary, we have a semi join, right? So we need to check only a single value and don’t need to know how many exact row would join.
But it seems again some optimizer limitation.

Let’s try our trick (extract a distinct part in inline view) again:

SQL_ID	9kwurxu63zz82, child number 0
-------------------------------------
select /*+ LEADING(m) USE_HASH(a@i) */ distinct unit_id FROM (select
/*+ no_merge */ distinct unit_id from IDXMAIN) m where unit_id IN
(SELECT /*+ qb_name(i) no_merge */ distinct unit_id from IDXAUX a)

Plan hash value: 2793925139

--------------------------------------------------------------------------------------------------------------------------------------------------------------------
| Id  | Operation			| Name	      | Starts | E-Rows |E-Bytes| Cost (%CPU)| E-Time	| A-Rows |   A-Time   | Buffers |  OMem |  1Mem | Used-Mem |
--------------------------------------------------------------------------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT		|	      |      1 |	|	|  2066 (100)|		|    100 |00:00:54.40 |    2281 |	|	|	   |
|   1 |  HASH UNIQUE			|	      |      1 |    101 |   707 |  2066   (2)| 00:00:42 |    100 |00:00:54.40 |    2281 |  1518K|  1518K| 1363K (0)|
|*  2 |   HASH JOIN			|	      |      1 |    203K|  1391K|  2062   (2)| 00:00:42 |    290K|00:00:53.95 |    2281 |  1594K|  1594K| 1555K (0)|
|   3 |    VIEW 			|	      |      1 |    101 |   303 |     2  (50)| 00:00:01 |    101 |00:00:00.01 |       3 |	|	|	   |
|   4 |     HASH UNIQUE 		|	      |      1 |    101 |   303 |     2  (50)| 00:00:01 |    101 |00:00:00.01 |       3 |  1518K|  1518K| 1360K (0)|
|   5 |      BITMAP INDEX FAST FULL SCAN| IDXMAIN_IX1 |      1 |  10000 | 30000 |     1   (0)| 00:00:01 |    101 |00:00:00.01 |       3 |	|	|	   |
|   6 |    BITMAP CONVERSION TO ROWIDS	|	      |      1 |     10M|    38M|  2037   (0)| 00:00:41 |     10M|00:00:13.58 |    2278 |	|	|	   |
|   7 |     BITMAP INDEX FAST FULL SCAN | IDXAUX_IX1  |      1 |	|	|	     |		|   6426 |00:00:00.02 |    2278 |	|	|	   |
--------------------------------------------------------------------------------------------------------------------------------------------------------------------

but the trick doesn’t work

and finally …

Small PID oneliner

Here is a small dtrace oneliner which I believe good to start to investigate what is doing your oracle session:

 

dtrace -n ‘profile-497/pid == $target/ { @u[ustack(40, 2000)] = count(); } tick-5s {printa ( @u);} tick-60s { exit(0); }’ -p PID

it’s just print user stack (sampled 497 times per second) each 5 second and exit after 1 minute.

One more oneliner: count calls for all Oracle internal functions by pattern “kgl*”

dtrace -n ‘pid$target::kgl*:entry { @u[probefunc] = count(); } tick-5s {printa ( @u);} tick-60s { exit(0); }’ -p PID

A few words about query notification internals

There is a good alternative to the database “polling” anti-pattern. It is a database/query change notification available for OCI clients for a while and for JDBC thin drivers quite recently. I decided to go deep into the OS level to see how smart the underlying   implementation in Oracle code itself and what is a related overhead for regular DML operations.

A little bit about test environment: Oracle 11.2.0.4/Solaris 11 on VirtualBox.

The idea is pretty simple: to compare the process of a simple insert with/and with out QCN.

Here is a Java code snippet to set up a Query Change Notification:

OracleConnection dataSourceListenConnection = (OracleConnection) dataSourceListen.getConnection();
instrumentOracleConnection(dataSourceListenConnection);
Properties prop = new Properties();

prop.setProperty(OracleConnection.DCN_NOTIFY_ROWIDS, "true");
prop.setProperty(OracleConnection.DCN_NOTIFY_CHANGELAG,"0");
prop.setProperty(OracleConnection.NTF_LOCAL_TCP_PORT,"40000");

DatabaseChangeRegistration dcr = dataSourceListenConnection.registerDatabaseChangeNotification(prop);
Thread.currentThread().sleep(1000* DELAY);
dcr.addListener(new DatabaseChangeListener() {
    @Override
    public void onDatabaseChangeNotification(DatabaseChangeEvent databaseChangeEvent) {
        System.out.println("=============================================================");
        System.out.println("=================="+ "notified:" + databaseChangeEvent.getEventType().name() + "   " + Thread.currentThread().getId() + "===========================================");
        System.out.println("=============================================================");
        QueryChangeDescription[] qChangeDescriptions = databaseChangeEvent.getQueryChangeDescription();
        if (qChangeDescriptions != null) {
            for (int i = 0; i < qChangeDescriptions.length; i++) {
                System.out.print(qChangeDescriptions[i].getQueryChangeEventType().name());
            }
        }
        TableChangeDescription[] tableChangeDescription = databaseChangeEvent.getTableChangeDescription();
        if (tableChangeDescription !=null) {
            for (int i = 0; i < tableChangeDescription.length; i++) {
                System.out.print("tblCD:" + tableChangeDescription[i]);
            }
        }
    }
});
Thread.currentThread().sleep(1000* INTDELAY);
Statement stmt = dataSourceListenConnection.createStatement();
// associate the statement with the registration:
((OracleStatement) stmt).setDatabaseChangeRegistration(dcr);
Thread.currentThread().sleep(1000* INTDELAY);
ResultSet rs = stmt.executeQuery("select * from QN1 where f1=4");

I started with a pretty simple dtrace script:

dtrace -n 'profile-497/pid == $target/ { @[ustack(40, 2000)] = count(); } tick-20s { exit(0); }' -p 1876 > insout_no.out

and soon found that the main difference is on-commit process described very well in Frits Hoogland’s blog

Here is my final dtrace script that shows the main difference between “QCN inserts” and “simple inserts”.

#!/usr/sbin/dtrace -CFZs

pid$1::kpon*:entry,
pid$1::kcrf_commit*:entry,
pid$1::ktcccDeleteCommitCallbacks:entry,
pid$1::xctCommitTxn:entry,
pid$1::ktcCommitTxn:entry
{
 printf("%s(%d,%d,%d,%d) \n",probefunc,arg0,arg1,arg2,arg3);
}


pid$1::kpon*:return,
pid$1::kcrf_commit*:return,
pid$1::ktcccDeleteCommitCallbacks:return,
pid$1::xctCommitTxn:return,
pid$1::ktcCommitTxn:return
{
 /*ustack();*/
 printf("%s(%d,%d,%d,%d) \n",probefunc,arg0,arg1,arg2,arg3);
}

and finally my results:

“Simple” insert:

  3  -> xctCommitTxn                          xctCommitTxn(0,0,216432960,59)

  3    -> ktcCommitTxn                        ktcCommitTxn(6339042896,0,0,0)

  3      -> kcrf_commit_force                 kcrf_commit_force(-139639050494144,0,0,6340341424)

  3      <- kcrf_commit_force                 kcrf_commit_force(1379,0,-69268715635744,0)

  3    <- ktcCommitTxn                        ktcCommitTxn(1146,0,-139639050491408,0)

  3  <- xctCommitTxn                          xctCommitTxn(755,29720,221535760,0)

 

“QCN” inserts

4  -> xctCommitTxn                          xctCommitTxn(0,0,216432960,59)

4    -> kponprp                             kponprp(1,-139639086618624,2,23)

4    <- kponprp                             kponprp(384,6377417808,-139639086618572,0)

4    -> ktcCommitTxn                        ktcCommitTxn(6339045472,0,0,0)

4      -> kcrf_commit_force                 kcrf_commit_force(-139639050508016,0,0,6340341424)

4      <- kcrf_commit_force                 kcrf_commit_force(1379,0,-69268715635744,0)

4      -> ktcccDeleteCommitCallbacks        ktcccDeleteCommitCallbacks(6339045472,6339991856,1,0)

4        -> kponcmtcbk                      kponcmtcbk(6376984944,6339045472,-1,1)

4          -> kponpst                       kponpst(6377401960,8,23,6377413256)

4          <- kponpst                       kponpst(1239,0,-139639050500336,0)

4        <- kponcmtcbk                      kponcmtcbk(347,1,0,0)

4      <- ktcccDeleteCommitCallbacks        ktcccDeleteCommitCallbacks(1670,1,6339991984,0)

4    <- ktcCommitTxn                        ktcCommitTxn(1146,0,0,0)

4  <- xctCommitTxn

 

You can easily see that setting up query/database change notification establish a kind of Callback into commit process (call to ktcccDeleteCommitCallbacks), kponpst function inside seems related to AQ (guessed based on bugs review on MOS) and may mean “post into a queue”.