2026-05-21

Single Server DFO

 Another improvement similar to last post is Single Server DFO. While in previous post the serial work was done by the query coordinator, that activity can also be executed by a single member of a parallel group set. 

The SQL again: 
select -- BX_13
       /*+ OPT_PARAM('parallel_degree_policy' 'auto') parallel(4) GATHER_PLAN_STATISTICS monitor */ 
       OBJECT_TYPE, count(*) c
from A_O
where rownum < 25000000 
group by OBJECT_TYPE
fetch first 7 rows only; 
select * from dbms_xplan.display_cursor( format =>'ALLSTATS LAST +PARALLEL');

The execution plan now changes from 

Plan hash value: 3726916758
 
---------------------------------------------------------------------------------------------------
| Id  | Operation                                         | Name     |    TQ  |IN-OUT| PQ Distrib |
---------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT                                  |          |        |      |            |
|*  1 |  COUNT STOPKEY                                    |          |        |      |            |
|   2 |   PX COORDINATOR                                  |          |        |      |            |
|   3 |    PX SEND QC (RANDOM)                            | :TQ20001 |  Q2,01 | P->S | QC (RAND)  |
|*  4 |     COUNT STOPKEY                                 |          |  Q2,01 | PCWC |            |
|   5 |      VIEW                                         |          |  Q2,01 | PCWP |            |
|*  6 |       SORT GROUP BY STOPKEY                       |          |  Q2,01 | PCWP |            |
|   7 |        PX RECEIVE                                 |          |  Q2,01 | PCWP |            |
|   8 |         PX SEND HASH                              | :TQ20000 |        | S->P | HASH       |
|*  9 |          COUNT STOPKEY                            |          |        |      |            |
|  10 |           PX COORDINATOR                          |          |        |      |            |
|  11 |            PX SEND QC (RANDOM)                    | :TQ10000 |  Q1,00 | P->S | QC (RAND)  |
|* 12 |             COUNT STOPKEY                         |          |  Q1,00 | PCWC |            |
|  13 |              PX BLOCK ITERATOR                    |          |  Q1,00 | PCWC |            |
|* 14 |               TABLE ACCESS STORAGE FULL FIRST ROWS| A_O      |  Q1,00 | PCWP |            |
---------------------------------------------------------------------------------------------------
 
Predicate Information (identified by operation id):
---------------------------------------------------
 
   1 - filter(ROWNUM<=7)
   4 - filter(ROWNUM<=7)
   6 - filter(ROWNUM<=7)
   9 - filter(ROWNUM<25000000)
  12 - filter(ROWNUM<25000000)

to 

Plan hash value: 2053989564
 
----------------------------------------------------------------------------------------------------
| Id  | Operation                                          | Name     |    TQ  |IN-OUT| PQ Distrib |
----------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT                                   |          |        |      |            |
|*  1 |  COUNT STOPKEY                                     |          |        |      |            |
|   2 |   PX COORDINATOR                                   |          |        |      |            |
|   3 |    PX SEND QC (RANDOM)                             | :TQ10002 |  Q1,02 | P->S | QC (RAND)  |
|*  4 |     COUNT STOPKEY                                  |          |  Q1,02 | PCWC |            |
|   5 |      VIEW                                          |          |  Q1,02 | PCWP |            |
|*  6 |       SORT GROUP BY STOPKEY                        |          |  Q1,02 | PCWP |            |
|   7 |        PX RECEIVE                                  |          |  Q1,02 | PCWP |            |
|   8 |         PX SEND HASH                               | :TQ10001 |  Q1,01 | S->P | HASH       |
|   9 |          BUFFER SORT                               |          |  Q1,01 | SCWP |            |
|* 10 |           COUNT STOPKEY                            |          |  Q1,01 | SCWP |            |
|  11 |            PX RECEIVE                              |          |  Q1,01 | SCWP |            |
|  12 |             PX SEND 1 SLAVE                        | :TQ10000 |  Q1,00 | P->S | 1 SLAVE    |
|* 13 |              COUNT STOPKEY                         |          |  Q1,00 | PCWC |            |
|  14 |               PX BLOCK ITERATOR                    |          |  Q1,00 | PCWC |            |
|* 15 |                TABLE ACCESS STORAGE FULL FIRST ROWS| A_O      |  Q1,00 | PCWP |            |
----------------------------------------------------------------------------------------------------
 
Predicate Information (identified by operation id):
---------------------------------------------------
 
   1 - filter(ROWNUM<=7)
   4 - filter(ROWNUM<=7)
   6 - filter(ROWNUM<=7)
  10 - filter(ROWNUM<25000000)
  13 - filter(ROWNUM<25000000)

We can see 3 consecutive DFOs now: TQ10000, TQ10001 and TQ10002. But there is a new Operation in LineID:12: PX SEND 1 SLAVE. This indicates the data is sent only to 1 worker in TQ10001. There is also no 20.000 TFOs anymore. The BUFFER SORT in LineID:9 is kind of a NOOP - there is nothing to SORT or BUFFER, still it's a requirement in this type of parallel plan pieces.

The IN-OUT now shows SCWP to indicate the difference.

SQL Monitor also show these changes:
But you have to know what to look for. Only the PX SEND 1 SLAVE indicates the special treatment of  that DFO. 
In plan_table.OTHER_TAG its SINGLE_COMBINED_WITH_PARENT.







In SQL Monitors Parallel-tab it can look as if there is skew in Parallel Server activity; which is technically true but in this case it's on purpose. Don't start corrective actions in this case!

It might look as if there is no reason for this improvement: Only one process is working for this plan lines anyhow. Still, with Single Server DFO, the additional resources of the parallel worker (e.g. dedicated PGA) can be used and the QC is free for other tasks in the execution. 
Of course there is also an underscore-parameter to control this behavior individually. This feature is enabled by default but requires Back to Parallel.



2026-05-20

Back to Parallel

Recently I stumbled across a feature which exists for quite some time already. It was implemented in 12.1.

The plan showed a parallel execution which somewhere in the middle had a serializing execution. But later on there were obvious other parallel activity. 
That made me research - and then generate a testcase.
I have generated a table A_O as SELECT * FROM ALL_OBJECTS - just to get some data and keep the plan simple. 
First the SQL as it was executed pre 12.1

select -- BX_08
       /*+ OPT_PARAM('parallel_degree_policy' 'limited') parallel(4) GATHER_PLAN_STATISTICS monitor */ 
       OBJECT_TYPE, count(*) c
from A_O
where rownum < 25000000 
group by OBJECT_TYPE
fetch first 7 rows only; 
select * from dbms_xplan.display_cursor( format =>'ALLSTATS LAST +PARALLEL');
with a plan
Plan hash value: 2817860580
 
-------------------------------------------------------------------------------------------------------
| Id  | Operation                                    | Name     | E-Rows |    TQ  |IN-OUT| PQ Distrib |
-------------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT                             |          |        |        |      |            |
|*  1 |  COUNT STOPKEY                               |          |        |        |      |            |
|   2 |   VIEW                                       |          |      7 |        |      |            |
|*  3 |    SORT GROUP BY STOPKEY                     |          |      7 |        |      |            |
|*  4 |     COUNT STOPKEY                            |          |        |        |      |            |
|   5 |      PX COORDINATOR                          |          |        |        |      |            |
|   6 |       PX SEND QC (RANDOM)                    | :TQ10000 |      7 |  Q1,00 | P->S | QC (RAND)  |
|*  7 |        COUNT STOPKEY                         |          |        |  Q1,00 | PCWC |            |
|   8 |         PX BLOCK ITERATOR                    |          |      7 |  Q1,00 | PCWC |            |
|   9 |          TABLE ACCESS STORAGE FULL FIRST ROWS| A_O      |      7 |  Q1,00 | PCWP |            |
-------------------------------------------------------------------------------------------------------
 
Predicate Information (identified by operation id):
---------------------------------------------------
 
   1 - filter(ROWNUM<=7)
   3 - filter(ROWNUM<=7)
   4 - filter(ROWNUM<25000000)
   7 - filter(ROWNUM<25000000)
   
 
Note
-----
   - Degree of Parallelism is 4 because of hint
We can see in lineID:6 the P->S clearly shows: all data is delivered to the query coordinator. This does the filter for  rownum < 25000000 (this must be in serial mode), and afterwards does the GROUP BY in LineID:3 ← this could be executed in parallel again, but as the QC is already involved, no further parallel executions occur. 


This all changes with 12.1: 

Plan hash value: 3726916758
 
---------------------------------------------------------------------------------------------------
| Id  | Operation                                         | Name     |    TQ  |IN-OUT| PQ Distrib |
---------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT                                  |          |        |      |            |
|*  1 |  COUNT STOPKEY                                    |          |        |      |            |
|   2 |   PX COORDINATOR                                  |          |        |      |            |
|   3 |    PX SEND QC (RANDOM)                            | :TQ20001 |  Q2,01 | P->S | QC (RAND)  |
|*  4 |     COUNT STOPKEY                                 |          |  Q2,01 | PCWC |            |
|   5 |      VIEW                                         |          |  Q2,01 | PCWP |            |
|*  6 |       SORT GROUP BY STOPKEY                       |          |  Q2,01 | PCWP |            |
|   7 |        PX RECEIVE                                 |          |  Q2,01 | PCWP |            |
|   8 |         PX SEND HASH                              | :TQ20000 |        | S->P | HASH       |
|*  9 |          COUNT STOPKEY                            |          |        |      |            |
|  10 |           PX COORDINATOR                          |          |        |      |            |
|  11 |            PX SEND QC (RANDOM)                    | :TQ10000 |  Q1,00 | P->S | QC (RAND)  |
|* 12 |             COUNT STOPKEY                         |          |  Q1,00 | PCWC |            |
|  13 |              PX BLOCK ITERATOR                    |          |  Q1,00 | PCWC |            |
|* 14 |               TABLE ACCESS STORAGE FULL FIRST ROWS| A_O      |  Q1,00 | PCWP |            |
---------------------------------------------------------------------------------------------------
 
Predicate Information (identified by operation id):
---------------------------------------------------
 
   1 - filter(ROWNUM<=7)
   4 - filter(ROWNUM<=7)
   6 - filter(ROWNUM<=7)
   9 - filter(ROWNUM<25000000)
  12 - filter(ROWNUM<25000000)

Here we see the serial execution between lineID:10 and lineID:8, but the GROUP BY is done in TQ20002 again. You can see the top 2 TQs are 20.000+ whereas the bottom one is 10.000. 
Also the IN-OUT (P->S and S->P) column shows quite fine the switch from parallel execution to serial one. In plan_table.OTHER_TAG its PARALLEL_TO_SERIAL and  PARALLEL_FROM_SERIAL.
SQL Monitor Report reflects this behavior properly. 

This feature is enabled by default (and it's cost is calculated) with parallel_degree_policy=auto
Of course there is also an underscore-parameter to control this behavior individually. 

2025-03-05

Sessionless Transactions - the moving target

Sessionless Transactions are quite new to Oracle. 
Some might argue this is not true: XA transactions are available since Oracle 7. 
The new Sessionless Transactions seem to be quite similar to global transactions - just without any central lock manager. 

Let's have a look how these new transactions can be observed during their lifetime.

I have a small setup of 4 sessions, the last one doesn't do a lot beside observing: 


select inst_id, sid, serial#, STATUS, module, SADDR, blocking_instance, blocking_session, final_blocking_instance, final_blocking_session  
from gv$session
where module like 'Session %'
order by 5;

   INST_ID        SID    SERIAL# STATUS   MODULE         SADDR            BLOCKING_INSTANCE BLOCKING_SESSION FINAL_BLOCKING_INSTANCE FINAL_BLOCKING_SESSION
---------- ---------- ---------- -------- -------------- ---------------- ----------------- ---------------- ----------------------- ----------------------
         5      48093      13343 INACTIVE Session A      000000115E3C4D90                                                                                  
         5      49891      61877 INACTIVE Session B      00000011463D1B18                                                                                  
         5      50497      51425 INACTIVE Session C      000000113E278D10                                                                                  
         5      43280      24898 ACTIVE   Session D      0000001139BCDBF0                                                                                                                                                                   
Now in Session A, the first transaction starts:

--SET APPINFO 'Session A'
set serveroutput on;
DECLARE
    gtrid VARCHAR2(128);
BEGIN
    gtrid := DBMS_TRANSACTION.START_TRANSACTION
      ( UTL_RAW.CAST_TO_RAW('Transaction Insert 1') 
      , DBMS_TRANSACTION.TRANSACTION_TYPE_SESSIONLESS
      , 2000 
      , DBMS_TRANSACTION.TRANSACTION_NEW
      );
   dbms_output.put_line(gtrid);
END;
/

5472616E73616374696F6E20496E736572742031


insert into sessionless (id) values (1);

1 row inserted.

and the observer sees:

  INST_ID        SID    SERIAL# STATUS   MODULE         SADDR            BLOCKING_INSTANCE BLOCKING_SESSION FINAL_BLOCKING_INSTANCE FINAL_BLOCKING_SESSION
---------- ---------- ---------- -------- -------------- ---------------- ----------------- ---------------- ----------------------- ----------------------
         5      48093      13343 INACTIVE Session A      000000115E3C4D90                                                                                  
         5      49891      61877 INACTIVE Session B      00000011463D1B18                                                                                  
         5      50497      51425 INACTIVE Session C      000000113E278D10                                                                                  
         5      43280      24898 ACTIVE   Session D      0000001139BCDBF0                                                                                  


select s.inst_id, s.sid, s.module, START_DATE, START_SCN , XID ,t.SES_ADDR --, t.*
from v$transaction t, gv$session s
where t.SES_ADDR = s.saddr (+);

   INST_ID        SID MODULE         START_DATE                START_SCN XID              SES_ADDR        
---------- ---------- -------------- ------------------- --------------- ---------------- ----------------
         5      48093 Session A      2025-03-05 13:03:08  44419149767413 09002000BA170000 000000115E3C4D90
         5      54695 SQL Developer  2025-03-05 08:51:39  44419144472312 0A000E00E9680000 000000116A24BC78
  
To make things more interesting (and observable) in Session B another transaction starts:

SET APPINFO 'Session B'
insert into sessionless (id) values (1);
 
and it hangs due to the PK on sessionless.id:
  
   INST_ID        SID    SERIAL# STATUS   MODULE         SADDR            BLOCKING_INSTANCE BLOCKING_SESSION FINAL_BLOCKING_INSTANCE FINAL_BLOCKING_SESSION
---------- ---------- ---------- -------- -------------- ---------------- ----------------- ---------------- ----------------------- ----------------------
         5      48093      13343 INACTIVE Session A      000000115E3C4D90                                                                                  
         5      49891      61877 ACTIVE   Session B      00000011463D1B18                 5            48093                       5                  48093
         5      50497      51425 INACTIVE Session C      000000113E278D10                                                                                  
         5      43280      24898 ACTIVE   Session D      0000001139BCDBF0                                                                                  
         
   INST_ID        SID MODULE         START_DATE                START_SCN XID              SES_ADDR        
---------- ---------- -------------- ------------------- --------------- ---------------- ----------------
         5      48093 Session A      2025-03-05 13:03:08  44419149767413 09002000BA170000 000000115E3C4D90
         5      49891 Session B      2025-03-05 13:04:04  44419149780350 08000900AC0D0000 00000011463D1B18
         5      54695 SQL Developer  2025-03-05 08:51:39  44419144472312 0A000E00E9680000 000000116A24BC78


select sql_exec_start, event,  BLOCKING_SESSION_STATUS, BLOCKING_SESSION, BLOCKING_SESSION_SERIAL#, BLOCKING_INST_ID, min(sample_time)mist , max(sample_time) mast
from v$active_session_history ash 
where session_id = 49891
  and sample_time > '2025-03-05 12:27:56.885000000' -- previous tests
group by  sql_exec_start, event,  BLOCKING_SESSION_STATUS, BLOCKING_SESSION, BLOCKING_SESSION_SERIAL#, BLOCKING_INST_ID;

SQL_EXEC_START      EVENT                          BLOCKING_SE BLOCKING_SESSION BLOCKING_SESSION_SERIAL# BLOCKING_INST_ID MIST                          MAST                         
------------------- ------------------------------ ----------- ---------------- ------------------------ ---------------- ----------------------------- -----------------------------
2025-03-05 13:04:04 enq: TX - row lock contention  VALID                  48093                    13343                1 2025-03-05 13:04:05.645000000 2025-03-05 13:05:02.696000000
  
Note the wrong BLOCKING_INST_ID? It should be 5, not 1!

Now the tricky part begins:
Session A gets rid of its transaction:
  
exec    DBMS_TRANSACTION.SUSPEND_TRANSACTION;

PL/SQL procedure successfully completed.
with slightly changes:
 
SQL_EXEC_START      EVENT                          BLOCKING_SE BLOCKING_SESSION BLOCKING_SESSION_SERIAL# BLOCKING_INST_ID MIST                          MAST                         
------------------- ------------------------------ ----------- ---------------- ------------------------ ---------------- ----------------------------- -----------------------------
2025-03-05 13:04:04 enq: TX - row lock contention  GLOBAL                                                                 2025-03-05 13:05:22.014000000 2025-03-05 13:06:37.285000000
2025-03-05 13:04:04 enq: TX - row lock contention  VALID                  48093                    13343                5 2025-03-05 13:05:19.980000000 2025-03-05 13:05:20.998000000
2025-03-05 13:04:04 enq: TX - row lock contention  VALID                  48093                    13343                1 2025-03-05 13:04:05.645000000 2025-03-05 13:05:18.962000000
And the blocking Session changed. After some time, the INST_ID got fixed. but more important, BLOCKING_SESSION_STATUS is GLOBAL now. Do you remember the similarities? 

 
When Session A disconnects:
 
   INST_ID        SID    SERIAL# STATUS   MODULE         SADDR            BLOCKING_INSTANCE BLOCKING_SESSION FINAL_BLOCKING_INSTANCE FINAL_BLOCKING_SESSION
---------- ---------- ---------- -------- -------------- ---------------- ----------------- ---------------- ----------------------- ----------------------
         5      49891      61877 ACTIVE   Session B      00000011463D1B18                                                                                  
         5      50497      51425 INACTIVE Session C      000000113E278D10                                                                                  
         5      43280      24898 ACTIVE   Session D      0000001139BCDBF0                                                                                  


   INST_ID        SID MODULE         START_DATE                START_SCN XID              SES_ADDR        
---------- ---------- -------------- ------------------- --------------- ---------------- ----------------
         5      43280 Session D      2025-03-05 13:08:38  44419149859826 07001E00290C0000 0000001139BCDBF0
         5      49891 Session B      2025-03-05 13:04:04  44419149780350 08000900AC0D0000 00000011463D1B18
         5      54695 SQL Developer  2025-03-05 08:51:39  44419144472312 0A000E00E9680000 000000116A24BC78
                                     2025-03-05 13:03:08  44419149767413 09002000BA170000 000000115E3C4D90
                                     
SQL_EXEC_START      EVENT                          BLOCKING_SE BLOCKING_SESSION BLOCKING_SESSION_SERIAL# BLOCKING_INST_ID MIST                          MAST                         
------------------- ------------------------------ ----------- ---------------- ------------------------ ---------------- ----------------------------- -----------------------------
2025-03-05 13:04:04 enq: TX - row lock contention  GLOBAL                                                                 2025-03-05 13:05:22.014000000 2025-03-05 13:09:03.785000000
2025-03-05 13:04:04 enq: TX - row lock contention  VALID                  48093                    13343                5 2025-03-05 13:05:19.980000000 2025-03-05 13:05:20.998000000
2025-03-05 13:04:04 enq: TX - row lock contention  VALID                  48093                    13343                1 2025-03-05 13:04:05.645000000 2025-03-05 13:05:18.962000000                                     
we see v$transaction has an orphaned SADDR

Now Session C picks up:
 
  set serveroutput on;
DECLARE
    gtrid VARCHAR2(128);
BEGIN
    gtrid := DBMS_TRANSACTION.START_TRANSACTION
         (UTL_RAW.CAST_TO_RAW('Transaction Insert 1') 
        , DBMS_TRANSACTION.TRANSACTION_TYPE_SESSIONLESS
        , 2000
        , DBMS_TRANSACTION.TRANSACTION_RESUME);
END;
/

PL/SQL procedure successfully completed.
which leads to 
   
   INST_ID        SID MODULE         START_DATE                START_SCN XID              SES_ADDR        
---------- ---------- -------------- ------------------- --------------- ---------------- ----------------
         5      43280 Session D      2025-03-05 13:08:38  44419149859826 07001E00290C0000 0000001139BCDBF0
         5      49891 Session B      2025-03-05 13:04:04  44419149780350 08000900AC0D0000 00000011463D1B18
         5      54695 SQL Developer  2025-03-05 08:51:39  44419144472312 0A000E00E9680000 000000116A24BC78
                                     2025-03-05 13:03:08  44419149767413 09002000BA170000 000000115E3C4D90  

SQL_EXEC_START      EVENT                          BLOCKING_SE BLOCKING_SESSION BLOCKING_SESSION_SERIAL# BLOCKING_INST_ID MIST                          MAST                         
------------------- ------------------------------ ----------- ---------------- ------------------------ ---------------- ----------------------------- -----------------------------
2025-03-05 13:04:04 enq: TX - row lock contention  VALID                  50497                    51425                1 2025-03-05 13:09:51.587000000 2025-03-05 13:11:19.137000000
2025-03-05 13:04:04 enq: TX - row lock contention  GLOBAL                                                                 2025-03-05 13:05:22.014000000 2025-03-05 13:09:50.568000000
2025-03-05 13:04:04 enq: TX - row lock contention  VALID                  48093                    13343                5 2025-03-05 13:05:19.980000000 2025-03-05 13:05:20.998000000
2025-03-05 13:04:04 enq: TX - row lock contention  VALID                  48093                    13343                1 2025-03-05 13:04:05.645000000 2025-03-05 13:05:18.962000000
we see v$transaction still does not know about Session B now holding 09002000BA170000 . But at the same time, ASH shows multiple lines of (the same) blocking status. Of course, to release all the tension, Session B does a simple rollback - and everything is fine.

2024-09-18

Custom parameters in Method-R Workbench

 Method-R Workbench is a leading tool to analyze many aspects of Oracles SQL-Trace files. 

It can use parameters in its commands and let users fill their values there. In the picture there are even 2 parameters, properly labeled and predefined. 

But when I run my own statement which also uses a "variable" of the same format, it only generates an error message:



mrskew --name='cell single block physical read$' --where='$obj==@OBJECT-ID@' --group='sprintf("%-16s %-16s", $p1, $p2 )'   --group-label='sprintf("%-16s %-16s", "p1", "p2" )'

Array found where operator expected at (eval 26) line 1, near "ID@)"
syntax error at (eval 26) line 1, near "ID@) "

To tell the Workbench how to use my variable, some entries in a xml file are required:
In the .method-r\workbench\9.5.2.0 directory, there is the file reports.xml
(This file gets copied from Workbenchs installation directory etc\config to your users directory if it doesn't exist.) Be careful to topy your changes whenever a new version of Workbench arrives!
By default it contains only one example which is also its documentation. To make my query work with a parameter, I add this XML block:


	<diagnostic label="Response time time by p1 and p2 call name for a given OBJECT ID filtered for only 'cell single block physical read$'">	<!-- This is the name that the application will use for the report. -->
		<commandline>mrskew --name='cell single block physical read$' --where='$obj==@OBJECT-ID@' --group='sprintf("%-16s %-16s", $p1, $p2 )' --group-label='sprintf("%-16s %-16s", "p1", "p2" )'</commandline>				<!-- This is the command line. The token @SQLID@ is defined on the following line. -->
		<param token="@OBJECT-ID@" label="Object ID" hint="obj=" default="-1"/>				<!-- This element causes the app to pop a dialog using the field label, data entry tip, and default value. -->
		<sample><![CDATA[
p1               p2                DURATION       %  CALLS      MEAN       MIN       MAX
---------------------------------  --------  ------  -----  --------  --------  --------
4239709683       2452482353        0.341465    7.9%     12  0.028455  0.005255  0.209957
4239709683       560937342         0.235909    5.4%      7  0.033701  0.010636  0.122802
3429896051       3039011478        0.224350    5.2%      4  0.056088  0.008659  0.186996
4156894774       425700738         0.221344    5.1%      8  0.027668  0.010023  0.077580
437579672        4090241319        0.177895    4.1%      9  0.019766  0.000978  0.072990
3429896051       3648465545        0.166973    3.8%      8  0.020872  0.009399  0.029454
4156894774       203886304         0.164699    3.8%      7  0.023528  0.002680  0.097812
4156894774       1302812366        0.160810    3.7%      8  0.020101  0.007712  0.080382
4239709683       2857786178        0.159647    3.7%      9  0.017739  0.005672  0.068118
3429896051       2540343800        0.146400    3.4%      4  0.036600  0.018622  0.074485
                        37 others  2.340060   53.9%    157  0.014905  0.000342  0.128323
---------------------------------  --------  ------  -----  --------  --------  --------
                       TOTAL (47)  4.339552  100.0%    233  0.018625  0.000342  0.209957

		]]></sample>																<!-- This is what shows up in the Sample Output tab as you scroll through the reports list. -->
	</diagnostic>
In the current (9.5.2.0) version, there is a bug in the example: the html element tooltip is used, but it should be hint!

With this modification, now I have my own action defined and the parameter can be added as expected! 



















Special thanks to Cary and Jeff for explaining these details so I can document it. 

2024-02-08

reading a LOB in another session


 Reading a LOB in Oracle is often quite easy: it's just a column in the query and all the libraries available today are doing the work necessary to make the LOBs content appear in the desired variable. What a nice world. 

Unfortunately it is still a LOB and requires special methods to fetch the data. And especially because this is covered by libraries, LOBs can be called slow. 

If fast access to many rows with many LOBs is required, leaving all the work to a single session might not meet the requirements. But LOBs also can be fetched in other sessions - kind of in parallel. 
(this must NOT be mixed up with parallel queries - instead they are separate sessions doing the LOB interactions while the main session processes the tables queries). 

As the specific implementation might be led by the requirements, my example here only shows what's possible. 

I have a very small table with only 1 row:


create table T (id number, B clob);

insert into T values (1, 'aäoöuüsß');

commit;

A small perl program selects the row in one session and reads it content in another one.
(please do NOT use this script as a blueprint!)

the relevant parts are

my $sql = "SELECT id, B LOB_LOCATOR FROM T WHERE ROWNUM = 1";
my $sth = $dbh->prepare($sql, { ora_auto_lob => 0 })
    or die "Couldn't prepare statement: $DBI::errstr";
$sth->execute() or die "Couldn't execute statement: $DBI::errstr";

# Get the first row
my ($id, $lob_locator) = $sth->fetchrow_array();
print "id: $id \n";

# Close the first connection
$sth->finish;
$dbh->disconnect;

print "ll: $lob_locator \n";
print " --- \n";

here the content was fetched in first session and printed to stdout ... 
 and
$dbh2 = DBI->connect("dbi:Oracle:host=$hostname;port=$port;service_name=$service_name", $username, $password)
    or die "Couldn't connect to database: $DBI::errstr";

   my $chunk_size = 1034;   # Arbitrary chunk size, for example
   my $offset = 1;   # Offsets start at 1, not 0
   my $data = $dbh2->ora_lob_read( $lob_locator, $offset, $chunk_size ) ;
   print "lob: $data \n";
where the LOBs content is read and printed. the execution looks like
[oracle@localhost ~]$ perl lob.pl
id: 1
ll: OCILobLocatorPtr=SCALAR(0x2b388a8)
 ---
lob: aaoouus?
[oracle@localhost ~]$
all fine here. 

To be sure no fancy session cache ruined my testcase, I enabled sql trace before with 

 exec dbms_monitor.database_trace_enable();
and so I got 2 tracefiles: FREE_ora_70047.trc with the SELECT

=====================
PARSING IN CURSOR #140276220704640 len=48 dep=0 uid=131 oct=3 lid=131 tim=22284540551 hv=1723986746 ad='61d7dbe0' sqlid='c2zwqytmc3wtu'
SELECT id, B LOB_LOCATOR FROM T WHERE ROWNUM = 1
END OF STMT
and FREE_ora_70050.trc with the LOBREAD

LOBREAD: type=PERSISTENT LOB,bytes=8,c=1934,e=1693,p=0,cr=1,cu=0,tim=22284648543
WAIT #0: nam='SQL*Net message from client' ela=3182 driver id=1952673792 #bytes=1 p3=0 obj#=4294967295 tim=22284651786
XCTEND rlbk=0, rd_only=1, tim=22284651919
all the files can be found here.
This shows how we can read a lob locators content in another session. That somehow conflicts with the documentation which states

LOB locator points to the actual LOB contents. The locator is returned when you retrieve the LOB, not the LOB's contents. LOB locators cannot be saved in one transaction or session and used again in a later transaction or session.

 but I assume this explanation did care about session context, not clients. 

This little example shows that LOBs content CAN be read in other sessions when the lob locator was fetched in a main query and the LOB handling should be offloaded to other connections. 

2023-12-24

remote external procedure

 During the migration of an application from an older AIX onto modern Linux based database, I stumbled across a little issue: The application uses external procedure calls. This is not an issue in itself as extproc is supported and nowadays doesn't even require a listener to run the code anymore. Even security is covered if the extproc agent is run as a different user, which can be enforced in extproc.ora

But - as the application is quite old - the application responsible team could not provide any linux libraries up until now. All the oracle documenation always shows a local extproc configuration only. either using an agent process spawned directly from the instance, or a listener, addressed by  (PROTOCOL=ipc)

Still, there is hope! 


In the listener-config, basically it's just a listener which listens to some protocol and provides the extproc binary as a SID_LIST. This could enable me to run the extproc libraries on a dedicated AIX host, and leave the poor RDBMS nodes for RDBMS stuff. 
I did not find any such configuration on the internet but was made aware by a colleague about this article: 
How to call external Procedure from PL/SQL on remote Host ?
If it was promoted for Oracle 8 some years ago, let's give it a try! 

Sitting on my sandbox I only have one linux node with 23c binaries - but I'll just use a different os user to show connectivity is using SQL*Net

To keep the setting simple (and avoid some additional work) I loosely follow the MOS document 10 Steps to Create and Run a Sample External Procedure Program on Unix (Doc ID 312564.1). 

Beside the oracle user, I create a new user extproc_runner (group extproc_runner) and copied the full ORACLE_HOME there. 

my first step is to create the proper shared object file. In /home/extproc_runner 
I create a very simple shell.c


#include<stdio.h>
#include<stdlib.h>
#include<string.h>
void sh(char *command) {
  int num;
  num = system(command);
}
  
and compile it with

gcc -fPIC -c shell.c	
ld -shared -o shell.so shell.o
chmod 755 shell.so

The easy part is done!


the extproc_runners listener.ora is created as

LISTENER_EXTPROC =
  (DESCRIPTION_LIST =
    (DESCRIPTION =
      (ADDRESS = (PROTOCOL = TCP)(HOST = localhost)(PORT = 1555))
    )
  )

sid_list_listener_extproc =
 (sid_list=
    (sid_desc=
      (sid_name=extproc_run)
      (oracle_home=/home/extproc_runner/product/23c/dbhomeFree)
      (program=extproc)
    )
)

and starts without any problem:

[extproc_runner@localhost admin]$ lsnrctl start listener_extproc

LSNRCTL for Linux: Version 23.0.0.0.0 - Developer-Release on 23-DEC-2023 17:57:25

Copyright (c) 1991, 2023, Oracle.  All rights reserved.

Starting /home/extproc_runner/product/23c/dbhomeFree/bin/tnslsnr: please wait...

TNSLSNR for Linux: Version 23.0.0.0.0 - Developer-Release
System parameter file is /home/extproc_runner/product/23c/dbhomeFree/network/admin/listener.ora
Log messages written to /home/extproc_runner/base/diag/tnslsnr/localhost/listener_extproc/alert/log.xml
Listening on: (DESCRIPTION=(ADDRESS=(PROTOCOL=tcp)(HOST=localhost)(PORT=1555)))

Connecting to (DESCRIPTION=(ADDRESS=(PROTOCOL=TCP)(HOST=localhost)(PORT=1555)))
STATUS of the LISTENER
------------------------
Alias                     listener_extproc
Version                   TNSLSNR for Linux: Version 23.0.0.0.0 - Developer-Release
Start Date                23-DEC-2023 17:57:26
Uptime                    0 days 0 hr. 0 min. 0 sec
Trace Level               off
Security                  ON: Local OS Authentication
SNMP                      OFF
Listener Parameter File   /home/extproc_runner/product/23c/dbhomeFree/network/admin/listener.ora
Listener Log File         /home/extproc_runner/base/diag/tnslsnr/localhost/listener_extproc/alert/log.xml
Listening Endpoints Summary...
  (DESCRIPTION=(ADDRESS=(PROTOCOL=tcp)(HOST=localhost)(PORT=1555)))
Services Summary...
Service "extproc_run" has 1 instance(s).
  Instance "extproc_run", status UNKNOWN, has 1 handler(s) for this service...
The command completed successfully

That's the easy part. Now let's tell the instance about this available service: tnsnames.ora is extended by this entry:

extproc_run_alias =
  (description=
    (ADDRESS = (PROTOCOL = TCP)(HOST = localhost)(PORT = 1555))
    (connect_data=(sid=extproc_run))
  )

and it can be reached somehow:

[oracle@localhost admin]$ tnsping extproc_run_alias

TNS Ping Utility for Linux: Version 23.0.0.0.0 - Developer-Release on 23-DEC-2023 18:05:54

Copyright (c) 1997, 2023, Oracle.  All rights reserved.

Used parameter files:
/opt/oracle/product/23c/dbhomeFree/network/admin/sqlnet.ora


Used TNSNAMES adapter to resolve the alias
Attempting to contact (description= (ADDRESS = (PROTOCOL = TCP)(HOST = localhost)(PORT = 1555)) (connect_data=(sid=extproc_run)))
OK (0 msec)
[oracle@localhost admin]$ sqlplus x/x@extproc_run_alias

SQL*Plus: Release 23.0.0.0.0 - Developer-Release on Sat Dec 23 18:05:58 2023
Version 23.2.0.0.0

Copyright (c) 1982, 2023, Oracle.  All rights reserved.

ERROR:
ORA-28547: connection to server failed, probable Oracle Net admin error

Now onto the last part: let's tell a schema there is an extproc it can use: . . .

To keep it simple, I use SYSTEM in my PDB, but any schema with proper permissions should do. 


CREATE DATABASE LINK extproc_agent_link USING 'extproc_run_alias';

Database link EXTPROC_AGENT_LINK created.


CREATE LIBRARY shell_lib is '/home/extproc_runner/shell.so' agent 'extproc_agent_link';

Library SHELL_LIB compiled


CREATE OR REPLACE PROCEDURE shell(command IN char)
AS EXTERNAL
NAME "sh"
LIBRARY shell_lib
LANGUAGE C
PARAMETERS (command string);
/

Procedure SHELL compiled


set serveroutput on
exec shell('/usr/bin/env >/tmp/bla');

ORA-28595: Extproc agent: Invalid DLL Path
ORA-06512: at "SYSTEM.SHELL", line 1
ORA-06512: at line 1
28595. 00000 -  "Extproc agent : Invalid DLL Path"
*Cause:    The path of DLL supplied for the extproc execution is invalid.
*Action:   Check if the DLL path is set properly using the EXTPROC_DLLS
           environment variable.
that was close, but not good enough.
Some more research & reading of 
ORA-28595: Extproc&nsbp;Agent&nsbp;: Invalid DLL Path Error in 12c With Listener&nsbp;Configuration (Doc&nsbp;ID&nsbp;1669896.1)    
External Procedure Calls and ORA-28595 In Versions 9.2 through&nsbp;10gR2 (Doc&nsbp;ID&nsbp;198523.1)  
and some check of tracefiles in /home/extproc_runner/product/23c/dbhomeFree/hs/log
 (at least I kenw the extproc was somehow involved already) led to an extended listener.ora for extproc_runner

LISTENER_EXTPROC =
  (DESCRIPTION_LIST =
    (DESCRIPTION =
      (ADDRESS = (PROTOCOL = TCP)(HOST = localhost)(PORT = 1555))
    )
  )

sid_list_listener_extproc =
 (sid_list=
    (sid_desc=
      (sid_name=extproc_run)
      (oracle_home=/home/extproc_runner/product/23c/dbhomeFree)
      (program=extproc)
      (ENVS="EXTPROC_DLLS=ANY,
LD_LIBRARY_PATH=/home/extproc_runner/product/23c/dbhomeFree/lib:/home/extproc_runner")
    )
  )

With this settings, I can call my external procedure through SQL*Net: 

exec shell('/usr/bin/env >/tmp/bla');

PL/SQL procedure successfully completed.
No error anymore - and I can check the file /tmp/bla
-rw-rw-r--. 1 extproc_runner extproc_runner 4841 Dec 24 20:23 /tmp/bla

ORACLE_SID=extproc_run
ORACLE_BASE=/home/extproc_runner/base
MODULES_RUN_QUARANTINE=LD_LIBRARY_PATH LD_PRELOAD
_=/usr/bin/env
LANG=en_US.UTF-8
HISTCONTROL=ignoredups
EXTPROC_DLLS=ANY
ORACLE_HOME=/home/extproc_runner/product/23c/dbhomeFree
HOSTNAME=localhost.localdomain
JAVA_HOME=/var/opt/jdk-20.0.1
...
USER=extproc_runner
PWD=/home/extproc_runner/product/23c/dbhomeFree/hs/admin
HOME=/home/extproc_runner

LD_LIBRARY_PATH=/home/extproc_runner/product/23c/dbhomeFree/lib:/home/extproc_runner
ORA_NET2_DESC=18,21
LOADEDMODULES=
...
SHELL=/bin/bash
SHLVL=2
MANPATH=:
MODULEPATH=/etc/scl/modulefiles:/usr/share/Modules/modulefiles:/etc/modulefiles:/usr/share/modulefiles
LOGNAME=extproc_runner
MODULEPATH_modshare=/usr/share/Modules/modulefiles:2:/etc/modulefiles:2:/usr/share/modulefiles:2
PATH=/home/extproc_runner/product/23c/dbhomeFree/bin:/home/extproc_runner/.local/bin:/home/extproc_runner/bin:/usr/share/Modules/bin:/usr/local/bin:/usr/bin:/usr/local/sbin:/usr/sbin:/var/opt/jdk-20.0.1/bin:/opt/oracle/product/sqlcl/bin
MODULESHOME=/usr/share/Modules
...

This should be sufficient as a proof of concept.

2023-12-09

The cost of BIND information in SQL Trace files

 Oracle SQL Trace files are a very valuable source of information - especially when it comes to performance analysis. 

But people often are afraid of the impact of tracing to performance. 

Luckily, Oracle chose quite useful defaults - at least when using DBMS_MONITOR:

WAITS=>TRUE

BINDS=>FALSE

PLAN_STAT=>'FIRST_EXECUTION'


This still leaves the question about the impact of writing BINDS to the tracefile. 

The best information I could find is by Cary Millsap in his book Tracing Oracle - chapter 25: Why We Recommend Not Tracing BINDS:

Here’s why that matters: every time an application binds a value to a placeholder, a BINDS=>TRUE trace causes Oracle to write 5 lines (about 180 bytes) into the trace file, using one write call per line. So, an EXEC that might consume only a few hundred microseconds when BINDS=>FALSE has to write an extra 36KB to the trace file with 2,000 extra write calls when BINDS=>TRUE

200 placeholders × 180 bytes/placeholder = 36,000 bytes

200 placeholders × 5 lines/placeholder × 1 write/line = 1,000 writes

Even this is a great technical explanation, it does not tell us how much time it takes. 

While analyzing some other questions, a tracefile with a lot of BIND entries was generated - and it significantly slowed down the application. Not a problem in this case, but something worth to check. 

The tracefile I generated covers ~117 seconds - 1 minutes and 57 seconds. 

mrskew just doesn't know about some of this time:


CALL-NAME                      DURATION       %   CALLS      MEAN       MIN       MAX
---------------------------  ----------  ------  ------  --------  --------  --------
EXEC                          91.022874   89.9%   4,398  0.020696  0.000000  0.093324
SQL*Net message from client    6.423181    6.3%   4,398  0.001460  0.000334  0.518238
log file sync                  3.633550    3.6%   4,397  0.000826  0.000372  0.013874
enq: SQ - contention           0.070351    0.1%      63  0.001117  0.000007  0.003597
library cache: mutex X         0.040133    0.0%       6  0.006689  0.000022  0.015928
cursor: pin S wait on X        0.027345    0.0%       3  0.009115  0.003581  0.019512
SQL*Net message to client      0.015619    0.0%   4,398  0.000004  0.000002  0.000079
CLOSE                          0.014905    0.0%   4,405  0.000003  0.000000  0.000079
enq: TX - index contention     0.012613    0.0%      11  0.001147  0.000036  0.005059
buffer busy waits              0.008619    0.0%     184  0.000047  0.000003  0.002146
14 others                      0.019216    0.0%   4,486  0.000004  0.000000  0.007130
---------------------------  ----------  ------  ------  --------  --------  --------
TOTAL (24)                   101.288406  100.0%  26,749  0.003787  0.000000  0.518238


mrskew only aggregates waits and dbcalls but doesn't care about the time "in between". We can assume the missing 16 seconds are the amount of time used to write the binds - and call it a day. 

mrprof shows some more information in the profile:

SubroutineDurationCallsDuration per call (seconds)
secondsRmeanminmaxskew
1CPU: EXEC dbcalls92.56228078.9%17,7100.005227·0.062486▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▆█▁▁▁▁▁
2unaccounted-for within dbcalls9.0623527.7%39,8400.000227−0.0257810.026413▁▁▁▁▁▂▆▁▁▁▁▁▁▁▂█▄▁▁▁▁▁
3SQL*Net message from client6.4231815.5%4,3980.0014600.0003340.518238▁▁▁▄█▁▂▁▁▁▁
4log file sync3.6335503.1%4,3970.0008260.0003720.013874▁▁▁█▄▁▁▁▁▁▁
525 other subroutines5.6635944.8%51,2760.000110·0.019512▁▁▁▁▁▁▁▁▁▁▁▁▁▄█▂▁▁▁▁▁▁
6Total (29)117.344957100.0%117,6210.000998−0.0257810.518238


There 9 seconds are called unaccounted-for within dbcalls - the explanation how this artificial component is calculated is 

mrprof synthesizes an “unaccounted-for between calls” call when there is missing time between dep = 0 database and system calls. Every adjacent pair of such calls will define some non-zero “unaccounted-for between calls” duration


That is somehow useful, but there is also a different approach possible. 
In the tracefile, I don't have timing information for the BINDS, but at least I have some activity before and afterwards. e.g. 


PARSE #1795421110760:c=32,e=32,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,plh=0,tim=968215712176
BINDS #1795421110760:

 Bind#0
  oacdty=02 mxl=22(06) mxlc=00 mal=00 scl=00 pre=00
  oacflg=10 fl2=0001 frm=00 csi=00 siz=24 off=0
  kxsbbbfp=881f7430  bln=22  avl=06  flg=09
  value=6607304129
  ...
 Bind#2
  oacdty=02 mxl=22(22) mxlc=00 mal=00 scl=00 pre=00
  oacflg=00 fl2=1000001 frm=00 csi=00 siz=24 off=0
  kxsbbbfp=06881698  bln=22  avl=02  flg=05
  value=1
EXEC #1795421110760:c=605,e=604,p=0,cr=0,cu=4,mis=0,r=1,dep=1,og=4,plh=0,tim=968215713003  

I see the EXEC completed at 968215713003 and had a duration of  604 microseconds - so it started at 968215712399. The last call before was a PARSE at 968215712176. This leaves a gap of 223 μs. Not a lot, but worth to care. To make this time somehow visible, I have a little perl script : 


#!/usr/bin/perl -w
#bind_synt_wait.pl
# creating a synthetic bind "WAIT" for otherwise UFBCs 
use strict;

my $prev_cursor     = 0 ;
my $cursor          = 0 ;
my $prev_timestamp  = 0 ;
my $timestamp       = 0 ;
my $calc_timestamp  = 0 ;
my $ela             = 0 ;
my $calc_ela        = 0 ;
my $to_be_processed = 0 ; 
# 0 => nothing to do, 
# 1 => BIND seen, but no WAIT, 
# 2 => BIND & WAIT seen ==> process!

#my $tablespace;
#my $block;
#my $object_id;

while (<>) {
  my $line = $_;
  if ($line =~ m/.*#(\d+)[: ].*/) {
    ($cursor = $line) =~ s/.*#(\d+)[: ].*/$1/ ;
  }
  $cursor =~ tr/\n//d;

  if ($line =~ m/.*tim=(\d+).*/) {
    ($timestamp = $line) =~ s/.*tim=(\d+).*/$1/ ;
	if ($to_be_processed == 1) {
	  $to_be_processed = 2;	
	}
  }
  $timestamp =~ tr/\n//d;
#  print " ---- timestamp = $timestamp \n";

  if ($line =~ m/.*ela= (\d+) .*/) {
    ($ela = $line) =~ s/.*ela= (\d+) .*/$1/ ;
  }
  $ela =~ tr/\n//d;
  
  if ($line =~ m/.*,e=(\d+),.*/) {
    ($ela = $line) =~ s/.*,e=(\d+),.*/$1/ ;
  }
  $ela =~ tr/\n//d;
#  print " ---- ela = $ela \n";
  
  if ($line =~ m/^BINDS/) {
    $to_be_processed = 1;
  }
  
  if ($to_be_processed == 2) {
# WAIT #391723720: nam='db file scattered read' ela= 2876 file#=5 block#=129 blocks=127 obj#=71123 tim=90982740602
    $calc_ela = ($timestamp - $ela) - $prev_timestamp;
	if ( $calc_ela < 0) {
		$calc_ela = 0 ; #$timestamp - $prev_timestamp;
	}
	$calc_timestamp = $timestamp-$ela;
    print "WAIT #"; # as the hash is somethign special ...
    print "$cursor: nam='BIND to tracefile write' ela= $calc_ela tim=$calc_timestamp\n";
    $to_be_processed = 0;
  }
  print $line;
  
  # will need these when generating tim & ela for BIND
  $prev_cursor = $cursor;
  $prev_timestamp = $timestamp;
}

which does exactly this calculation and inserts an artificial line into the tracefile:

WAIT #1795421110760: nam='BIND to tracefile write' ela= 223 tim=968215712399
Now mrskew knows about this time:

    
CALL-NAME                      DURATION       %   CALLS      MEAN       MIN       MAX
---------------------------  ----------  ------  ------  --------  --------  --------
EXEC                          91.022874   66.3%   4,398  0.020696  0.000000  0.093324
BIND to tracefile write       36.088810   26.3%  13,487  0.002676  0.000000  0.031517
SQL*Net message from client    6.423181    4.7%   4,398  0.001460  0.000334  0.518238
log file sync                  3.633550    2.6%   4,397  0.000826  0.000372  0.013874
enq: SQ - contention           0.070351    0.1%      63  0.001117  0.000007  0.003597
library cache: mutex X         0.040133    0.0%       6  0.006689  0.000022  0.015928
cursor: pin S wait on X        0.027345    0.0%       3  0.009115  0.003581  0.019512
SQL*Net message to client      0.015619    0.0%   4,398  0.000004  0.000002  0.000079
CLOSE                          0.014905    0.0%   4,405  0.000003  0.000000  0.000079
enq: TX - index contention     0.012613    0.0%      11  0.001147  0.000036  0.005059
15 others                      0.027835    0.0%   4,670  0.000006  0.000000  0.007130
---------------------------  ----------  ------  ------  --------  --------  --------
TOTAL (25)                   137.377216  100.0%  40,236  0.003414  0.000000  0.518238

and also the profile shows my artificial wait event: 

SubroutineDurationCallsDuration per call (seconds)
secondsRmeanminmaxskew
1CPU: EXEC dbcalls92.56228078.9%17,7100.005227·0.062486▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▆█▁▁▁▁▁
2BIND to tracefile write36.08881030.8%13,4870.002676·0.031517▁▁▁▂▃█▁▁▁▁▁
3SQL*Net message from client6.4231815.5%4,3980.0014600.0003340.518238▁▁▁▄█▁▂▁▁▁▁
4log file sync3.6335503.1%4,3970.0008260.0003720.013874▁▁▁█▄▁▁▁▁▁▁
5unaccounted-for within dbcalls−25.605864−21.8%39,840−0.000643−0.0383240.026413▁▁▁▁▁█▇▁▁▁▁▁▁▁▁▅▁▁▁▁▁▁
625 other subroutines4.2430003.6%64,5220.000066−0.0163850.019512▁▁▁▁▁▁▁▁▁▁▁▁▁▄█▂▁▁▁▁▁▁
7Total (30)117.344957100.0%144,3540.000813−0.0383240.518238


But unfortunately, mrskews TOTAL is now bigger than 117 sec, and mrprof needs to introduce negative unaccounted-for within db calls to compensate that. 

The problem in this situation is the different dept and how their EXEC dbcalls are aggregated - and the artificial BIND to tracefile write doesn't fit well. It would required further modifications which would lead to further problems - and are probably not worth. 

At the end, it would be fine if Oracle could also instrument the code for writing BIND information to the tracefile - this could eliminate all this manual work. Until then, it might sometimes help to slightly improve a tracefile with data already hidden inside.