SQL Translation Framework – Tackling ORA-04031 (Part 2)

Let’s get to presenting the entire solution

Here is the tiny and simple Java code (there is a reason why I didn’t use PL/SQL) which upon executing will create storm (10,000) of unique SQL_IDs.
The underlying SQL statement contains the offending TIMESTAMP expression which is executed in a loop producing a unique literal.
cursor_sharing is set to its default value: EXACT.

I am giving brief quick’n dirty how-to (for non-Nava experts, me included) to run it.

Replace the “<>” with your true hostname, service name, port, etc within the getConnection() method.

# cat TestSqlTranslator.java

import java.sql.Connection;
import java.sql.DriverManager;
import java.sql.Statement;
import java.time.LocalDateTime;
import java.time.format.DateTimeFormatter;

public class TestSqlTranslator {

    public static void main(String[] args) throws Exception {

        Connection conn = DriverManager.getConnection(
                "jdbc:oracle:thin:@//<your_host>:<your_port>/<your_service_name>",
                "DELME",
                "<password>"
        );

        Statement stmt = conn.createStatement();

        LocalDateTime ts =
                LocalDateTime.of(2025, 5, 31, 13, 20, 57);

        DateTimeFormatter fmt =
                DateTimeFormatter.ofPattern("yyyy-MM-dd HH:mm:ss");

        for (int i = 1; i <= 10000; i++) {

            String sql =
                    "select /* my_java_testsql */ ID " +
                    "from DELME.TEST4031 " +
                    "where BUSINESS_TS = TIMESTAMP '" +
                    ts.plusSeconds(i).format(fmt) +
                    "'";
            stmt.execute(sql);
        }
        stmt.close();
        conn.close();
    }
}

# cd $ORACLE_HOME 
# cd jdbc/lib
# cp ojdbc8.jar /mytest/JAVA/
# javac -cp /mytest/JAVA/ojdbc8.jar TestSqlTranslator.java  ( compile )
# java -cp .:/mytest/JAVA/ojdbc8.jar TestSqlTranslator    ( execute )

I will use the following SQL scripts to verify the outcome:

-------------------------------------------------------------------------
-- lssign.sql Author: Piotr Sajda (PS5)
--
-- This SQL script is intended to identify potential contributors to shared pool fragmentation.
-- It shows the number of SQL statements that share the same FORCE_MATCHING_SIGNATURE
-- but most likely differ because of literal values.
-- Optional filters can be applied; see the NVL functions used below.
-------------------------------------------------------------------------
col FORCE_MATCHING_SIGNATURE form 999999999999999999999999999999
break on inst_id

select inst_id, FORCE_MATCHING_SIGNATURE, count(FORCE_MATCHING_SIGNATURE)
from gv$sql
where
inst_id = to_number( nvl('&inst_id',inst_id) ) AND
PARSING_SCHEMA_NAME like nvl('&PARSING_SCHEMA_NAME',PARSING_SCHEMA_NAME) AND
FORCE_MATCHING_SIGNATURE like nvl('&FORCE_MATCHING_SIGNATURE',FORCE_MATCHING_SIGNATURE)
group by inst_id, FORCE_MATCHING_SIGNATURE
having count(FORCE_MATCHING_SIGNATURE) >= to_number( nvl('&limit','10') )
order by inst_id, count(FORCE_MATCHING_SIGNATURE)
/

-------------------------------------------------------------------------
-- lssqlsign.sql Author: Piotr Sajda (PS5)
-- list sql text from gv$sql based on FORCE_MATCHING_SIGNATURE
-------------------------------------------------------------------------
col SQL_TEXT form a120
col FORCE_MATCHING_SIGNATURE form 9999999999999999999999999999999

select FORCE_MATCHING_SIGNATURE, SQL_TEXT from gv$sql
where FORCE_MATCHING_SIGNATURE = '&FORCE_MATCHING_SIGNATURE' and rownum <= to_number( nvl('&min_number_rows',100) )
/

-------------------------------------------------------------------------
-- lssqlidchld.sql Author: Piotr Sajda (PS5)
-- This SQL script is intended to identify potential contributors to shared pool fragmentation.
-- It shows the number of distinct child number (child cursors) that share the same SQL_ID, so they can’t be shared.
-- Subsequent step should be looking at v$sql_shared_cursor in order to find the cause of lack of sharing
-------------------------------------------------------------------------

select inst_id,  sql_id, count(CHILD_NUMBER) 
from gv$sql 
group by inst_id,  sql_id having count(CHILD_NUMBER) >= to_number( nvl('&min_child_cursors','10') )
order by inst_id, sql_id
/

Test with cursor_sharing set to EXACT (default)

SQL> alter system flush shared_pool ;

System altered.

SQL> @altercur
SQL> alter system set cursor_sharing=&force_exact scope=both sid='*' ;
Enter value for force_exact: EXACT

System altered.

Run the Java code : 

# time java -cp .:/mytest/JAVA/ojdbc8.jar TestSqlTranslator

real    0m12.664s
user    0m3.647s
sys     0m0.607s

SQL> @lssign
HING_SIGNATURE)
Enter value for limit: 2000
old   8: having count(FORCE_MATCHING_SIGNATURE) >= to_number( nvl('&limit','10') )
new   8: having count(FORCE_MATCHING_SIGNATURE) >= to_number( nvl('2000','10') )

INST_ID        FORCE_MATCHING_SIGNATURE COUNT(FORCE_MATCHING_SIGNATURE)
------- ------------------------------- -------------------------------
      1            15011608150593212199                            6183

6183 different SQL_IDs having the same FORCE_MATCHING_SIGNATURE but differing due to literals.
Let’s retrieve some of them :

SQL> @lssqlsign
Enter value for force_matching_signature: 15011608150593212199
Enter value for min_number_rows: 10
old   2: where FORCE_MATCHING_SIGNATURE = '&FORCE_MATCHING_SIGNATURE' and rownum <= to_number( nvl('&min_number_rows',100) )
new   2: where FORCE_MATCHING_SIGNATURE = '15011608150593212199' and rownum <= to_number( nvl('10',100) )

        FORCE_MATCHING_SIGNATURE SQL_TEXT
-------------------------------- ------------------------------------------------------------------------------------------------------------------------
            15011608150593212199 select /* my_java_testsql */ ID from DELME.TEST4031 where BUSINESS_TS = TIMESTAMP '2025-05-31 15:58:37'
            15011608150593212199 select /* my_java_testsql */ ID from DELME.TEST4031 where BUSINESS_TS = TIMESTAMP '2025-05-31 14:42:33'
            15011608150593212199 select /* my_java_testsql */ ID from DELME.TEST4031 where BUSINESS_TS = TIMESTAMP '2025-05-31 14:09:53'
            15011608150593212199 select /* my_java_testsql */ ID from DELME.TEST4031 where BUSINESS_TS = TIMESTAMP '2025-05-31 14:03:45'
            15011608150593212199 select /* my_java_testsql */ ID from DELME.TEST4031 where BUSINESS_TS = TIMESTAMP '2025-05-31 15:03:56'
            15011608150593212199 select /* my_java_testsql */ ID from DELME.TEST4031 where BUSINESS_TS = TIMESTAMP '2025-05-31 13:37:06'
            15011608150593212199 select /* my_java_testsql */ ID from DELME.TEST4031 where BUSINESS_TS = TIMESTAMP '2025-05-31 15:56:06'
            15011608150593212199 select /* my_java_testsql */ ID from DELME.TEST4031 where BUSINESS_TS = TIMESTAMP '2025-05-31 14:01:01'
            15011608150593212199 select /* my_java_testsql */ ID from DELME.TEST4031 where BUSINESS_TS = TIMESTAMP '2025-05-31 16:00:06'
            15011608150593212199 select /* my_java_testsql */ ID from DELME.TEST4031 where BUSINESS_TS = TIMESTAMP '2025-05-31 14:20:11'

10 rows selected.

Indeed, the mini Java code looped through and spawned 10’000 different SQL_IDs, of which 6163 “survived” (the 3871 was flushed by the “newcomers”).

Result :
Without going into too much detail, Oracle spent most of its time traversing the shared pool hash buckets and chains, searching for matching SQL statements.
Since no matching cursors were found (nor could they be, given the distinct SQL text), this turned out to be an expensive yet ultimately futile exercise.
The inevitable hard parsing of all 10,000 unique SQL statements brought the total execution time to approximately 12.7 seconds (0m12.664s).

The underlying reason is fairly obvious: each of the 10,000 SQL statements differs in its literal value. For example (the last two), '2025-05-31 16:00:06' and '2025-05-31 14:20:11' result in two distinct SQL_IDs.

So, in good faith, let’s set CURSOR_SHARING=FORCE. After all, we want to get rid of those literals, don’t we?
Then, we’ll flush the shared pool and run my tiny Java program once again.

Test with cursor_sharing set to FORCE

SQL> alter system set cursor_sharing=&force_exact scope=both sid='*' ;
Enter value for force_exact: FORCE
old   1: alter system set cursor_sharing=&force_exact scope=both sid='*'
new   1: alter system set cursor_sharing=FORCE scope=both sid='*'

System altered.

SQL> @fs
SQL> alter system flush shared_pool ;

System altered.

# time java -cp .:/piotr/JAVA/ojdbc8.jar TestSqlTranslator

real    0m31.727s
user    0m3.684s
sys     0m0.618s

ouch.. nearly 32 seconds.

I have repeated this series several times, that is :

• Flushing shared pool
• Settings cursor_sharing to EXACT
• Execute java code (it took roughly 12 seconds)
• Flushing shared pool
• Settings cursor_sharing to FORCE
• Execute java code (it took roughly 30 seconds)

The results were very consistent.

What happened?
With CURSOR_SHARING=FORCE, if we limited our investigation to checking the number of distinct SQL_IDs, we would already be popping open a bottle of champagne – there is just one!
At first glance, it looks as though the problem has been solved (except that the execution took considerably longer).
However, if we look at things from a “vertical” perspective, that is, examining how many child cursors have been spawned under that single parent cursor, our enthusiasm quickly fades.

Here it is :

SQL> @lssqlidchld.sql
select inst_id,  sql_id, count(CHILD_NUMBER) 
from gv$sql 
group by inst_id,  sql_id having count(CHILD_NUMBER) >= to_number( nvl('&min_child_cursors','10') )
order by inst_id, sql_id
/

Enter value for min_child_cursors: 1000

INST_ID SQL_ID          COUNT(DISTINCTCHILD_NUMBER)
------- --------------- ---------------------------
      1 1d5kz05v57vkv                          2945

The SQL_ID: 1d5kz05v57vkv corresponds to this SQL_TEXT (from gv$sql):

select /* my_java_testsql */ ID from DELME.TEST4031 where BUSINESS_TS = TIMESTAMP :"SYS_B_0"

As expected, the literal has been replaced with bind variable (SYS_B_0), so in theory that SQL_ID should be shared.
Things went real bad though, since (as explained before) this time with each execution we got unique child cursor.
Out of 10,000, the 2945 is still present in the shared pool.

Running Tanel’s pivotal helper on v$sql_shared_cursor and providing the sql_id: 1d5kz05v57vkv, here’s what we can discover.

It’s just the tiny excerpt listing the child_number 4247, 4248, 4249, 4250 which were spawned on behalf of the parent cursor (0) with the sql_id: 1d5kz05v57vkv

SQL> @why
Show why existing SQL child cursors were not reused (V$SQL_SHARED_CURSOR)...

Enter value for sqlid: 1d5kz05v57vkv


SQL_ID                        : 1d5kz05v57vkv
ADDRESS                       : 00000000A8B73AC0
CHILD_ADDRESS                 : 000000020386AB68
CHILD_NUMBER                  : 4247
BIND_MISMATCH                 : Y
REASON                        : <ChildNode><ChildNumber>4247</ChildNumber><ID>39</ID><reason>Bind mismatch(31)</reason><size>5x8</size><bind_position>0</bind_position><original_oacflg>16</original_oacflg><kkslitlen>19</kkslitlen><kkslitval>3257562876196565042</kkslitval><kksllcbv>3257562876196565042</kksllcbv></ChildNode>
CON_ID                        : 0
-----------------
SQL_ID                        : 1d5kz05v57vkv
ADDRESS                       : 00000000A8B73AC0
CHILD_ADDRESS                 : 00000001725DC5E8
CHILD_NUMBER                  : 4248
BIND_MISMATCH                 : Y
REASON                        : <ChildNode><ChildNumber>4248</ChildNumber><ID>39</ID><reason>Bind mismatch(31)</reason><size>5x8</size><bind_position>0</bind_position><original_oacflg>16</original_oacflg><kkslitlen>19</kkslitlen><kkslitval>3257562876196565042</kkslitval><kksllcbv>3257562876196565042</kksllcbv></ChildNode>
CON_ID                        : 0
-----------------
SQL_ID                        : 1d5kz05v57vkv
ADDRESS                       : 00000000A8B73AC0
CHILD_ADDRESS                 : 00000001F42EB880
CHILD_NUMBER                  : 4249
BIND_MISMATCH                 : Y
REASON                        : <ChildNode><ChildNumber>4249</ChildNumber><ID>39</ID><reason>Bind mismatch(31)</reason><size>5x8</size><bind_position>0</bind_position><original_oacflg>16</original_oacflg><kkslitlen>19</kkslitlen><kkslitval>3257562876196565042</kkslitval><kksllcbv>3257562876196565042</kksllcbv></ChildNode>
CON_ID                        : 0
-----------------
SQL_ID                        : 1d5kz05v57vkv
ADDRESS                       : 00000000A8B73AC0
CHILD_ADDRESS                 : 00000001F8D2CEB0
CHILD_NUMBER                  : 4250
BIND_MISMATCH                 : Y
REASON                        : <ChildNode><ChildNumber>4250</ChildNumber><ID>39</ID><reason>Bind mismatch(31)</reason><size>5x8</size><bind_position>0</bind_position><original_oacflg>16</original_oacflg><kkslitlen>19</kkslitlen><kkslitval>3257562876196565042</kkslitval><kksllcbv>3257562876196565042</kksllcbv></ChildNode>
CON_ID                        : 0
-----------------
SQL_ID                        : 1d5kz05v57vkv
ADDRESS                       : 00000000A8B73AC0
CHILD_ADDRESS                 : 0000000209814C58
CHILD_NUMBER                  : 4251
BIND_MISMATCH                 : Y
REASON                        : <ChildNode><ChildNumber>4251</ChildNumber><ID>39</ID><reason>Bind mismatch(31)</reason><size>5x8</size><bind_position>0</bind_position><original_oacflg>16</original_oacflg><kkslitlen>19</kkslitlen><kkslitval>3257562876196565042</kkslitval><kksllcbv>3257562876196565042</kksllcbv></ChildNode>
CON_ID                        : 0
-----------------
SQL_ID                        : 1d5kz05v57vkv
ADDRESS                       : 00000000A8B73AC0
CHILD_ADDRESS                 : 00000000AC2FBF20
CHILD_NUMBER                  : 4252
BIND_MISMATCH                 : Y
REASON                        : <ChildNode><ChildNumber>4252</ChildNumber><ID>39</ID><reason>Bind mismatch(31)</reason><size>5x8</size><bind_position>0</bind_position><original_oacflg>16</original_oacflg><kkslitlen>19</kkslitlen><kkslitval>3257562876196565042</kkslitval><kksllcbv>3257562876196565042</kksllcbv></ChildNode>
CON_ID                        : 0

Upon formatting that long line (I have used Linux xmllint), here is the more readable version:

<?xml version="1.0"?>
<ChildNode>
  <ChildNumber>4252</ChildNumber>
  <ID>39</ID>
  <reason>Bind mismatch(31)</reason>
  <size>5x8</size>
  <bind_position>0</bind_position>
  <original_oacflg>16</original_oacflg>
  <kkslitlen>19</kkslitlen>
  <kkslitval>3257562876196565042</kkslitval>
  <kksllcbv>3257562876196565042</kksllcbv>
</ChildNode>

This time, BIND_MISMATCH was identified as the reason behind the scenes, with the REASON column providing further details about the underlying cause.
Regardless of what the actual root cause might be (and without attempting to “fix the bug” itself), I enabled SQL tracing (event 10046) for one such execution and took a closer look at several sections of the resulting trace file.

The SQL-Trace can be enabled as follows :

exec dbms_monitor.session_trace_enable(session_id=>&sid_to_trace,serial_num=>&serial_to_trace,binds=>true,waits=>true);

Analysis of the Raw 10046 Trace (SQL Trace) with CURSOR_SHARING=EXACT

One particularly interesting detail caught my attention.
First, let’s examine a small (yet representative) excerpt from the 10046 trace, captured while running my tiny Java program with CURSOR_SHARING=EXACT.

PARSING IN CURSOR #140323390411112 len=103 dep=0 uid=102 oct=3 lid=102 tim=48045054731804 hv=4054037258 ad='215b63498' sqlid='by34jczsu7csa'
select /* my_java_testsql */ ID from DELME.TEST4031 where BUSINESS_TS = TIMESTAMP '2025-05-31 22:28:42'
END OF STMT
PARSE #140323390411112:c=509,e=964,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,plh=557049255,tim=48045054731803
EXEC #140323390411112:c=15,e=15,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=557049255,tim=48045054731916
WAIT #140323390411112: nam='SQL*Net message to client' ela= 0 driver id=1413697536 #bytes=1 p3=0 obj#=22 tim=48045054731941
FETCH #140323390411112:c=8,e=9,p=0,cr=3,cu=0,mis=0,r=0,dep=0,og=1,plh=557049255,tim=48045054731972
STAT #140323390411112 id=1 cnt=0 pid=0 pos=1 obj=393714 op='TABLE ACCESS BY INDEX ROWID BATCHED TEST4031 (cr=3 pr=0 pw=0 str=1 time=9 us cost=476 size=43952 card=2747)'
STAT #140323390411112 id=2 cnt=0 pid=1 pos=1 obj=393715 op='INDEX RANGE SCAN IDX_TS (cr=3 pr=0 pw=0 str=1 time=8 us cost=10 size=0 card=2747)'
WAIT #140323390411112: nam='SQL*Net message from client' ela= 54 driver id=1413697536 #bytes=1 p3=0 obj#=22 tim=48045054732220
CLOSE #140323390411112:c=3,e=3,dep=0,type=0,tim=48045054732251
=====================
PARSING IN CURSOR #140323390411112 len=103 dep=0 uid=102 oct=3 lid=102 tim=48045054733262 hv=3237989124 ad='170b58358' sqlid='cr9ybfz0gzks4'
select /* my_java_testsql */ ID from DELME.TEST4031 where BUSINESS_TS = TIMESTAMP '2025-05-31 22:28:43'
END OF STMT
PARSE #140323390411112:c=1453,e=991,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,plh=557049255,tim=48045054733262
EXEC #140323390411112:c=15,e=14,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=557049255,tim=48045054733360
WAIT #140323390411112: nam='SQL*Net message to client' ela= 1 driver id=1413697536 #bytes=1 p3=0 obj#=22 tim=48045054733386
FETCH #140323390411112:c=7,e=8,p=0,cr=3,cu=0,mis=0,r=0,dep=0,og=1,plh=557049255,tim=48045054733415
STAT #140323390411112 id=1 cnt=0 pid=0 pos=1 obj=393714 op='TABLE ACCESS BY INDEX ROWID BATCHED TEST4031 (cr=3 pr=0 pw=0 str=1 time=9 us cost=476 size=43952 card=2747)'
STAT #140323390411112 id=2 cnt=0 pid=1 pos=1 obj=393715 op='INDEX RANGE SCAN IDX_TS (cr=3 pr=0 pw=0 str=1 time=8 us cost=10 size=0 card=2747)'
WAIT #140323390411112: nam='SQL*Net message from client' ela= 50 driver id=1413697536 #bytes=1 p3=0 obj#=22 tim=48045054733623
CLOSE #140323390411112:c=3,e=3,dep=0,type=0,tim=48045054733652
=====================
PARSING IN CURSOR #140323390411112 len=103 dep=0 uid=102 oct=3 lid=102 tim=48045054734651 hv=2675391422 ad='1ff16b8c8' sqlid='3bdd93kgrffxy'
select /* my_java_testsql */ ID from DELME.TEST4031 where BUSINESS_TS = TIMESTAMP '2025-05-31 22:28:44'
END OF STMT
PARSE #140323390411112:c=534,e=982,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,plh=557049255,tim=48045054734651
EXEC #140323390411112:c=14,e=14,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=557049255,tim=48045054734747
WAIT #140323390411112: nam='SQL*Net message to client' ela= 1 driver id=1413697536 #bytes=1 p3=0 obj#=22 tim=48045054734774
FETCH #140323390411112:c=8,e=8,p=0,cr=3,cu=0,mis=0,r=0,dep=0,og=1,plh=557049255,tim=48045054734804
STAT #140323390411112 id=1 cnt=0 pid=0 pos=1 obj=393714 op='TABLE ACCESS BY INDEX ROWID BATCHED TEST4031 (cr=3 pr=0 pw=0 str=1 time=9 us cost=476 size=43952 card=2747)'
STAT #140323390411112 id=2 cnt=0 pid=1 pos=1 obj=393715 op='INDEX RANGE SCAN IDX_TS (cr=3 pr=0 pw=0 str=1 time=8 us cost=10 size=0 card=2747)'
WAIT #140323390411112: nam='SQL*Net message from client' ela= 57 driver id=1413697536 #bytes=1 p3=0 obj#=22 tim=48045054735028
CLOSE #140323390411112:c=4,e=4,dep=0,type=0,tim=48045054735076

Obviously, the SQL statements which were shipped differ in the predicate sections – each and every one of them got a different literal which resulted in hard parse (see mis=1 in the PARSE database call).
The keyword “mis” stands for “missed in the shared pool – yes or no”, 1 = yes,  0 = no).

Examples:

select /* my_java_testsql */ ID from DELME.TEST4031 where BUSINESS_TS = TIMESTAMP '2025-05-31 22:28:42' with sql_id = 'by34jczsu7csa'

select /* my_java_testsql */ ID from DELME.TEST4031 where BUSINESS_TS = TIMESTAMP '2025-05-31 22:28:43' with sql_id = 'cr9ybfz0gzks4' 
– generated just a second later, which can be derived from the java code.

There is another interesting point worth mentioning, although to make this particular “oddity” truly apparent, we need to compare it with the corresponding trace excerpt presented below.
Namely, if we take any complete PARSE-EXEC-FETCH-CLOSE cycle and examine the e values (the elapsed time of each individual call), it becomes obvious that the PARSE call takes the longest.
For now, let’s set aside another curious oddity: in some cases, the reported e value (elapsed time) is actually smaller than the corresponding c value (CPU time).
This is hardly surprising once we realize that each SQL statement required a hard parse (confirmed by mis=1 marked orange).
Consequently, for each statement, the CBO (Cost-Based Optimizer) had to reach out to the available optimizer statistics and, among other things, evaluate and compare the estimated costs of alternative access paths, including INDEX RANGE SCAN and FULL TABLE SCAN, with the former ultimately winning the contest (as can be seen in the STAT section).
This becomes particularly evident when examining the contents of a 10053 (optimizer) trace.

Now, let’s examine the corresponding section of the SQL trace (again, just a small but representative excerpt), captured while executing the same Java program after changing CURSOR_SHARING to FORCE.

Analysis of the Raw 10046 Trace (SQL Trace) with CURSOR_SHARING=FORCE

Here is the Raw 10046 for cursor_sharing to FORCE:

=====================
PARSING IN CURSOR #139670608321144 len=92 dep=0 uid=102 oct=3 lid=102 tim=49840968598461 hv=1985211995 ad='209ca7d40' sqlid='1d5kz05v57vkv'
select /* my_java_testsql */ ID from DELME.TEST4031 where BUSINESS_TS = TIMESTAMP :"SYS_B_0"
END OF STMT
PARSE #139670608321144:c=97,e=97,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=557049255,tim=49840968598461
BINDS #139670608321144:
Bind#0
  oacdty=01 mxl=32(19) mxlc=00 mal=00 scl=00 pre=00
  oacflg=10 fl2=0500 frm=01 csi=873 siz=32 off=0
  kxsbbbfp=7f0799037528  bln=32  avl=19  flg=09
  value="2025-06-01 00:14:46"
EXEC #139670608321144:c=3550,e=3474,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,plh=557049255,tim=49840968601985
WAIT #139670608321144: nam='SQL*Net message to client' ela= 2 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=49840968602024
FETCH #139670608321144:c=10,e=10,p=0,cr=3,cu=0,mis=0,r=0,dep=0,og=1,plh=557049255,tim=49840968602064
STAT #139670608321144 id=1 cnt=0 pid=0 pos=1 obj=393714 op='TABLE ACCESS BY INDEX ROWID BATCHED TEST4031 (cr=3 pr=0 pw=0 str=1 time=10 us cost=476 size=43952 card=2747)'
STAT #139670608321144 id=2 cnt=0 pid=1 pos=1 obj=393715 op='INDEX RANGE SCAN IDX_TS (cr=3 pr=0 pw=0 str=1 time=9 us cost=10 size=0 card=2747)'
WAIT #139670608321144: nam='SQL*Net message from client' ela= 58 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=49840968602259
CLOSE #139670608321144:c=4,e=3,dep=0,type=0,tim=49840968602286
=====================
PARSING IN CURSOR #139670608321144 len=92 dep=0 uid=102 oct=3 lid=102 tim=49840968602398 hv=1985211995 ad='209ca7d40' sqlid='1d5kz05v57vkv'
select /* my_java_testsql */ ID from DELME.TEST4031 where BUSINESS_TS = TIMESTAMP :"SYS_B_0"
END OF STMT
PARSE #139670608321144:c=97,e=97,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=557049255,tim=49840968602398
BINDS #139670608321144:
Bind#0
  oacdty=01 mxl=32(19) mxlc=00 mal=00 scl=00 pre=00
  oacflg=10 fl2=0500 frm=01 csi=873 siz=32 off=0
  kxsbbbfp=7f0799037528  bln=32  avl=19  flg=09
  value="2025-06-01 00:14:47"
EXEC #139670608321144:c=3550,e=3529,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,plh=557049255,tim=49840968605980
WAIT #139670608321144: nam='SQL*Net message to client' ela= 2 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=49840968606015
FETCH #139670608321144:c=7,e=7,p=0,cr=3,cu=0,mis=0,r=0,dep=0,og=1,plh=557049255,tim=49840968606043
STAT #139670608321144 id=1 cnt=0 pid=0 pos=1 obj=393714 op='TABLE ACCESS BY INDEX ROWID BATCHED TEST4031 (cr=3 pr=0 pw=0 str=1 time=8 us cost=476 size=43952 card=2747)'
STAT #139670608321144 id=2 cnt=0 pid=1 pos=1 obj=393715 op='INDEX RANGE SCAN IDX_TS (cr=3 pr=0 pw=0 str=1 time=7 us cost=10 size=0 card=2747)'
WAIT #139670608321144: nam='SQL*Net message from client' ela= 57 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=49840968606235
CLOSE #139670608321144:c=3,e=3,dep=0,type=0,tim=49840968606262
=====================
PARSING IN CURSOR #139670608321144 len=92 dep=0 uid=102 oct=3 lid=102 tim=49840968606367 hv=1985211995 ad='209ca7d40' sqlid='1d5kz05v57vkv'
select /* my_java_testsql */ ID from DELME.TEST4031 where BUSINESS_TS = TIMESTAMP :"SYS_B_0"
END OF STMT
PARSE #139670608321144:c=89,e=89,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=557049255,tim=49840968606366
BINDS #139670608321144:
Bind#0
  oacdty=01 mxl=32(19) mxlc=00 mal=00 scl=00 pre=00
  oacflg=10 fl2=0500 frm=01 csi=873 siz=32 off=0
  kxsbbbfp=7f0799037528  bln=32  avl=19  flg=09
  value="2025-06-01 00:14:48"
EXEC #139670608321144:c=3816,e=4307,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,plh=557049255,tim=49840968610726
WAIT #139670608321144: nam='SQL*Net message to client' ela= 2 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=49840968610769
FETCH #139670608321144:c=9,e=9,p=0,cr=3,cu=0,mis=0,r=0,dep=0,og=1,plh=557049255,tim=49840968610799
STAT #139670608321144 id=1 cnt=0 pid=0 pos=1 obj=393714 op='TABLE ACCESS BY INDEX ROWID BATCHED TEST4031 (cr=3 pr=0 pw=0 str=1 time=11 us cost=476 size=43952 card=2747)'
STAT #139670608321144 id=2 cnt=0 pid=1 pos=1 obj=393715 op='INDEX RANGE SCAN IDX_TS (cr=3 pr=0 pw=0 str=1 time=10 us cost=10 size=0 card=2747)'
WAIT #139670608321144: nam='SQL*Net message from client' ela= 69 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=49840968610992
CLOSE #139670608321144:c=4,e=4,dep=0,type=0,tim=49840968611042
=====================

First, we can see the SQL_ID which can be (should be) shared is: ‘1d5kz05v57vkv‘.
This is confirmed by the mis=0 (so, not missed in the shared pool) entry at the PARSE call – clearly not a hard parse.
Indeed, the “e” time next to PARSE is negligible (e=97 microseconds), if compared to the “e” from the 10046 trace with cursor_sharing to EXACT.

Let’s zoom in :

PARSING IN CURSOR #139670608321144 len=92 dep=0 uid=102 oct=3 lid=102 tim=49840968598461 hv=1985211995 ad='209ca7d40' sqlid='1d5kz05v57vkv'
select /* my_java_testsql */ ID from DELME.TEST4031 where BUSINESS_TS = TIMESTAMP :"SYS_B_0"
END OF STMT
PARSE #139670608321144:c=97,e=97,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=557049255,tim=49840968598461

Next comes the BINDS section, followed by the EXEC call, which, by far, accounts for the largest portion of the elapsed time when considering the entire PARSE-BIND-EXEC-FETCH-CLOSE cycle.
Notice the e value associated with the EXEC call. It is considerably higher than the corresponding e values reported for any of the EXEC calls with CURSOR_SHARING=EXACT, as shown earlier.

BINDS #139670608321144:
Bind#0
  oacdty=01 mxl=32(19) mxlc=00 mal=00 scl=00 pre=00
  oacflg=10 fl2=0500 frm=01 csi=873 siz=32 off=0
  kxsbbbfp=7f0799037528  bln=32  avl=19  flg=09
  value="2025-06-01 00:14:46"
EXEC #139670608321144:c=3550,e=3474,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,plh=557049255,tim=49840968601985

Can we quickly quantify what I mean by “by far”?

Not with absolute precision, but to a reasonably satisfactory degree – yes.
Let’s carry out a simple comparison as follows.
Take the beginning and ending timestamps (tim) corresponding to the complete processing cycle of any single cursor.
Then, for both CURSOR_SHARING=EXACT and CURSOR_SHARING=FORCE, subtract the starting timestamp from the ending timestamp, as follows:

Raw 10046 Trace (SQL Trace) cursor_sharing set to EXACT (single cycle)

...
...
CLOSE #140323390411112:c=3,e=3,dep=0,type=0,tim=48045054733652
=====================
PARSING IN CURSOR #140323390411112 len=103 dep=0 uid=102 oct=3 lid=102 tim=48045054734651 hv=2675391422 ad='1ff16b8c8' sqlid='3bdd93kgrffxy'
select /* my_java_testsql */ ID from DELME.TEST4031 where BUSINESS_TS = TIMESTAMP '2025-05-31 22:28:44'
END OF STMT
PARSE #140323390411112:c=534,e=982,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,plh=557049255,tim=48045054734651
EXEC #140323390411112:c=14,e=14,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=557049255,tim=48045054734747
WAIT #140323390411112: nam='SQL*Net message to client' ela= 1 driver id=1413697536 #bytes=1 p3=0 obj#=22 tim=48045054734774
FETCH #140323390411112:c=8,e=8,p=0,cr=3,cu=0,mis=0,r=0,dep=0,og=1,plh=557049255,tim=48045054734804
STAT #140323390411112 id=1 cnt=0 pid=0 pos=1 obj=393714 op='TABLE ACCESS BY INDEX ROWID BATCHED TEST4031 (cr=3 pr=0 pw=0 str=1 time=9 us cost=476 size=43952 card=2747)'
STAT #140323390411112 id=2 cut=0 pid=1 pos=1 obj=393715 op='INDEX RANGE SCAN IDX_TS (cr=3 pr=0 pw=0 str=1 time=8 us cost=10 size=0 card=2747)'
WAIT #140323390411112: nam='SQL*Net message from client' ela= 57 driver id=1413697536 #bytes=1 p3=0 obj#=22 tim=48045054735028
CLOSE #140323390411112:c=4,e=4,dep=0,type=0,tim=48045054735076

End-tim:48045054735076 – Begin-tim:48045054733652 = 1424 [microseconds]

So, in theory the entire cycle from beginning of parsing up to closing of that very cursor took 1424 microseconds.
Note that, to establish the starting timestamp, I had to refer back to the previous available relevant timestamp, namely, the one associated with the completed CLOSE call of the preceding cursor.
The reason is that the tim values associated with database calls (and wait events) represent their completion timestamps, while e (and ela for WAIT events) report their elapsed durations.
Consequently, taking tim=48045054734651 as the starting timestamp would effectively exclude the time spent in the PARSE call itself.

Now, if we look at the largest contributor, it is clearly the elapsed time of the completed PARSE database call: e=982.

Clearly, when dealing with such tiny elapsed-time intervals, comparing tim timestamps does not necessarily provide an exact measurement of the database processing time.
However, for larger intervals (on the order of hundreds of milliseconds or more), this approach can still provide reasonably meaningful results.
In our case, though, we are primarily interested in relative proportions, rather than absolute timing precision.

Now let’s do the same thing for cursor_sharing set to FORCE.

Raw 10046 Trace (SQL Trace) cursor_sharing set to FORCE (single cycle)

...
...
CLOSE #139670608321144:c=4,e=3,dep=0,type=0,tim=49840968602286
=====================
PARSING IN CURSOR #139670608321144 len=92 dep=0 uid=102 oct=3 lid=102 tim=49840968602398 hv=1985211995 ad='209ca7d40' sqlid='1d5kz05v57vkv'
select /* my_java_testsql */ ID from DELME.TEST4031 where BUSINESS_TS = TIMESTAMP :"SYS_B_0"
END OF STMT
PARSE #139670608321144:c=97,e=97,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=557049255,tim=49840968602398
BINDS #139670608321144:

Bind#0
  oacdty=01 mxl=32(19) mxlc=00 mal=00 scl=00 pre=00
  oacflg=10 fl2=0500 frm=01 csi=873 siz=32 off=0
  kxsbbbfp=7f0799037528  bln=32  avl=19  flg=09
  value="2025-06-01 00:14:47"
EXEC #139670608321144:c=3550,e=3529,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,plh=557049255,tim=49840968605980
WAIT #139670608321144: nam='SQL*Net message to client' ela= 2 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=49840968606015
FETCH #139670608321144:c=7,e=7,p=0,cr=3,cu=0,mis=0,r=0,dep=0,og=1,plh=557049255,tim=49840968606043
STAT #139670608321144 id=1 cnt=0 pid=0 pos=1 obj=393714 op='TABLE ACCESS BY INDEX ROWID BATCHED TEST4031 (cr=3 pr=0 pw=0 str=1 time=8 us cost=476 size=43952 card=2747)'
STAT #139670608321144 id=2 cnt=0 pid=1 pos=1 obj=393715 op='INDEX RANGE SCAN IDX_TS (cr=3 pr=0 pw=0 str=1 time=7 us cost=10 size=0 card=2747)'
WAIT #139670608321144: nam='SQL*Net message from client' ela= 57 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=49840968606235
CLOSE #139670608321144:c=3,e=3,dep=0,type=0,tim=49840968606262

The same approach as above:
End: 49840968606262 – Begin: 49840968602286= 3976 [microseconds]
The largest contributor is the EXEC database call, taking e=3529.
No need to calculate the percentage, it’s close to 90%.

To recap.
First, let us reach out to the total elapsed time of running the Java code with cursor_sharing = EXACT/FORCE.

cursor_sharing = EXACT :

# time java -cp .:/mytest/JAVA/ojdbc8.jar TestSqlTranslator
real    0m12.664s
user    0m3.647s
sys     0m0.607s

cursor_sharing = FORCE :

# time java -cp .:/mytest/JAVA/ojdbc8.jar TestSqlTranslator
real    0m31.727s
user    0m3.684s
sys     0m0.618s

We already know that the scenario with CURSOR_SHARING=FORCE took roughly three times longer to complete. We can also identify the largest contributors to the elapsed time in both scenarios:

• With CURSOR_SHARING=EXACT, it is the PARSE database call.
• With CURSOR_SHARING=FORCE, it is the EXEC database call.

Consequently, by comparing and quantifying these two dominant contributors, we can roughly conclude that three PARSE calls under EXACT correspond to the elapsed time of one EXEC call under FORCE.

The remaining database calls, wait events, and other overheads contribute relatively little to the overall elapsed time and can largely be neglected for the purpose of this comparison.
Furthermore, the mis entry in the PARSE call indicates whether a library cache miss occurred, typically requiring a hard parse.
For example:
PARSE #139670608321144:c=97,e=97,p=0,cr=0,cu=0,mis=0
This represents a parse call without a library cache miss, generally corresponding to a soft parse.

Interestingly, the mis entry in the EXEC call may provide another clue. In our particular scenario, mis=1 appears to accompany the creation of a new child cursor, presumably because none of the existing child cursors could be reused.
For example:

EXEC #139670608321144:c=3550,e=3474,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,plh=557049255,tim=49840968601985

Could we investigate this further?
Perhaps high-frequency sampling of Oracle’s short call stacks would shed some light on what is actually happening behind the scenes (preferably not on your production database).
After all, at some point, the two scenarios must diverge in their internal C call paths. With a bit of luck, we might encounter a function whose name is sufficiently descriptive to suggest what Oracle is doing, perhaps something resembling CreateChild or the like.
For precisely this kind of investigation, I usually use a tiny shell script.
If you fancy experimenting with it yourself, feel free to give it a try. Just be warned once again: probably not on your production database.

#!/bin/bash

################
# Piotr Sajda PS5 (trss.sh)
# High frequency short stack sampling
# Usage: ./trss.sh <OSPID> [number_of_samples]
#
# Example: 
# ./trss.sh 31234 10000
# Then vi or less tmp/short_stack_for_ospid.31234
################


OSPID="${1:?Usage: $0 <OSPID> [number_of_samples]}"
how_many_times="${2:-50}"

{
    echo "set feedback off heading off pagesize 0 timing off time off"
    echo "oradebug setospid ${OSPID}"

    for ((i = 1; i <= how_many_times; i++)); do
        echo "oradebug short_stack"
        echo "prompt ==========================================="
##       echo "host sleep 0.01"
    done

    echo "exit"
} | sqlplus -s / as sysdba |
tee "/tmp/short_stack_for_ospid.${OSPID}"

For completeness, we are still missing the SQL trace (10046) from the fast (optimized) run, that is, the one executed with the SQL Translation Framework working behind the scenes.
So, without further ado, here it is :

=====================
PARSING IN CURSOR #139635562442496 len=122 dep=0 uid=102 oct=3 lid=102 tim=49600306163248 hv=733902562 ad='2185c6098' sqlid='96w3th0pvwxr2'
select /* my_java_testsql */ ID from DELME.TEST4031 where BUSINESS_TS = TO_TIMESTAMP(:"SYS_B_0" , 'YYYY-MM-DD HH24:MI:SS')
END OF STMT
PARSE #139635562442496:c=34,e=34,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=557049255,tim=49600306163248
BINDS #139635562442496:
Bind#0
  oacdty=01 mxl=32(19) mxlc=00 mal=00 scl=00 pre=00
  oacflg=10 fl2=0100 frm=01 csi=873 siz=32 off=0
  kxsbbbfp=7eff701be438  bln=32  avl=19  flg=09
  value="2025-06-01 11:09:01"
EXEC #139635562442496:c=82,e=82,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=557049255,tim=49600306163378
WAIT #139635562442496: nam='SQL*Net message to client' ela= 0 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=49600306163398
FETCH #139635562442496:c=7,e=8,p=0,cr=3,cu=0,mis=0,r=0,dep=0,og=1,plh=557049255,tim=49600306163422
STAT #139635562442496 id=1 cnt=0 pid=0 pos=1 obj=393714 op='TABLE ACCESS BY INDEX ROWID BATCHED TEST4031 (cr=3 pr=0 pw=0 str=1 time=12 us cost=476 size=43952 card=2747)'
STAT #139635562442496 id=2 cnt=0 pid=1 pos=1 obj=393715 op='INDEX RANGE SCAN IDX_TS (cr=3 pr=0 pw=0 str=1 time=11 us cost=10 size=0 card=2747)'
WAIT #139635562442496: nam='SQL*Net message from client' ela= 38 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=49600306163565
CLOSE #139635562442496:c=6,e=6,dep=0,type=1,tim=49600306163591
=====================
PARSING IN CURSOR #139635562441168 len=122 dep=0 uid=102 oct=3 lid=102 tim=49600306163628 hv=733902562 ad='2185c6098' sqlid='96w3th0pvwxr2'
select /* my_java_testsql */ ID from DELME.TEST4031 where BUSINESS_TS = TO_TIMESTAMP(:"SYS_B_0" , 'YYYY-MM-DD HH24:MI:SS')
END OF STMT
PARSE #139635562441168:c=27,e=27,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=557049255,tim=49600306163628
BINDS #139635562441168:
Bind#0
  oacdty=01 mxl=32(19) mxlc=00 mal=00 scl=00 pre=00
  oacflg=10 fl2=0100 frm=01 csi=873 siz=32 off=0
  kxsbbbfp=7eff701be438  bln=32  avl=19  flg=09
  value="2025-06-01 11:09:02"
EXEC #139635562441168:c=66,e=66,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=557049255,tim=49600306163747
WAIT #139635562441168: nam='SQL*Net message to client' ela= 0 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=49600306163765
FETCH #139635562441168:c=6,e=6,p=0,cr=3,cu=0,mis=0,r=0,dep=0,og=1,plh=557049255,tim=49600306163786
STAT #139635562441168 id=1 cnt=0 pid=0 pos=1 obj=393714 op='TABLE ACCESS BY INDEX ROWID BATCHED TEST4031 (cr=3 pr=0 pw=0 str=1 time=9 us cost=476 size=43952 card=2747)'
STAT #139635562441168 id=2 cnt=0 pid=1 pos=1 obj=393715 op='INDEX RANGE SCAN IDX_TS (cr=3 pr=0 pw=0 str=1 time=9 us cost=10 size=0 card=2747)'
WAIT #139635562441168: nam='SQL*Net message from client' ela= 35 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=49600306163933
CLOSE #139635562441168:c=6,e=6,dep=0,type=1,tim=49600306163959
=====================
PARSING IN CURSOR #139635562439840 len=122 dep=0 uid=102 oct=3 lid=102 tim=49600306163995 hv=733902562 ad='2185c6098' sqlid='96w3th0pvwxr2'
select /* my_java_testsql */ ID from DELME.TEST4031 where BUSINESS_TS = TO_TIMESTAMP(:"SYS_B_0" , 'YYYY-MM-DD HH24:MI:SS')
END OF STMT
PARSE #139635562439840:c=26,e=26,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=557049255,tim=49600306163995
BINDS #139635562439840:
Bind#0
  oacdty=01 mxl=32(19) mxlc=00 mal=00 scl=00 pre=00
  oacflg=10 fl2=0100 frm=01 csi=873 siz=32 off=0
  kxsbbbfp=7eff701cf320  bln=32  avl=19  flg=09
  value="2025-06-01 11:09:03"
EXEC #139635562439840:c=0,e=76,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=557049255,tim=49600306164154
WAIT #139635562439840: nam='SQL*Net message to client' ela= 0 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=49600306164174
FETCH #139635562439840:c=0,e=6,p=0,cr=3,cu=0,mis=0,r=0,dep=0,og=1,plh=557049255,tim=49600306164196
STAT #139635562439840 id=1 cnt=0 pid=0 pos=1 obj=393714 op='TABLE ACCESS BY INDEX ROWID BATCHED TEST4031 (cr=3 pr=0 pw=0 str=1 time=10 us cost=476 size=43952 card=2747)'
STAT #139635562439840 id=2 cnt=0 pid=1 pos=1 obj=393715 op='INDEX RANGE SCAN IDX_TS (cr=3 pr=0 pw=0 str=1 time=9 us cost=10 size=0 card=2747)'
WAIT #139635562439840: nam='SQL*Net message from client' ela= 41 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=49600306164341
CLOSE #139635562439840:c=0,e=6,dep=0,type=1,tim=49600306164366
=====================
PARSING IN CURSOR #139635562704640 len=122 dep=0 uid=102 oct=3 lid=102 tim=49600306164404 hv=733902562 ad='2185c6098' sqlid='96w3th0pvwxr2'
select /* my_java_testsql */ ID from DELME.TEST4031 where BUSINESS_TS = TO_TIMESTAMP(:"SYS_B_0" , 'YYYY-MM-DD HH24:MI:SS')
END OF STMT
PARSE #139635562704640:c=190,e=28,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=557049255,tim=49600306164404
BINDS #139635562704640:
Bind#0
  oacdty=01 mxl=32(19) mxlc=00 mal=00 scl=00 pre=00
  oacflg=10 fl2=0100 frm=01 csi=873 siz=32 off=0
  kxsbbbfp=7eff7018e390  bln=32  avl=19  flg=09
  value="2025-06-01 11:09:04"
EXEC #139635562704640:c=64,e=64,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=557049255,tim=49600306164514
WAIT #139635562704640: nam='SQL*Net message to client' ela= 1 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=49600306164532
FETCH #139635562704640:c=6,e=6,p=0,cr=3,cu=0,mis=0,r=0,dep=0,og=1,plh=557049255,tim=49600306164552
STAT #139635562704640 id=1 cnt=0 pid=0 pos=1 obj=393714 op='TABLE ACCESS BY INDEX ROWID BATCHED TEST4031 (cr=3 pr=0 pw=0 str=1 time=9 us cost=476 size=43952 card=2747)'
STAT #139635562704640 id=2 cnt=0 pid=1 pos=1 obj=393715 op='INDEX RANGE SCAN IDX_TS (cr=3 pr=0 pw=0 str=1 time=8 us cost=10 size=0 card=2747)'
WAIT #139635562704640: nam='SQL*Net message from client' ela= 36 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=49600306164690
CLOSE #139635562704640:c=6,e=6,dep=0,type=1,tim=49600306164715
=====================

I will comment on it in more detail later, but certain entries already make it fairly obvious that the execution was considerably faster, without unnecessarily consuming CPU cycles and shared pool memory.
First, we managed to significantly reduce the elapsed time of the two previously dominant contributors: the PARSE and EXEC database calls.

The corresponding e values are now almost negligible: 34 and 82 microseconds, respectively, compared to approximately 900 and 3,400 microseconds in the earlier scenarios (taking the first representative sample from each for comparison).

One might even be tempted to estimate the total elapsed time of the entire Java program based on these improvements, now that the SQL Translation Framework is (will be soon) in play.
Interestingly, both the PARSE and EXEC calls report mis=0, indicating that no library cache misses occurred during these calls.
This is consistent with successful cursor reuse, suggesting that Oracle was able to execute the translated SQL statement without repeatedly creating new child cursors.
In fact, we might reasonably suspect that only a single child cursor was needed throughout the test.
As a slight digression, while preparing this article I also reached out to the official Oracle documentation from the SQL Tuning Guide describing the End-to-End Application Tracing.
Much as people tend to shy away from official documentation, I believe this particular section is well worth taking a closer look at.

The last part (Part-3) will show the Translation Framework in action.