Unfortunately, Tkprof and Statspack would often fail to point in proper direction when it gets to profiling activity performed by a Call-Less Cursor. In this case such cursor was responsible for writing and reading BLOBs. This issue was not specific to JDBC API. Later it was reproduced with DBMS_LOB API.

Just as an additional point to the mentioned above topic, here is an example of Tkprof and Statspack reports from the system where this issue was reproduced with help of single threaded application in an idle environment.

Tkprof

OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse       16      0.00       0.02          0          0          0           0
Execute     23      3.09       4.57          6      13894      18366          17
Fetch        3      0.00       0.00          0          6          0           3
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total       42      3.10       4.59          6      13900      18366          20

OVERALL TOTALS FOR ALL RECURSIVE STATEMENTS

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse   230212      5.39       5.14          0          0          0           0
Execute 230215    176.87     173.89         47     692034     175390      176321
Fetch   153422      4.22       3.96          5     230821          3       77048
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total   613849    186.49     183.01         52     922855     175393      253369

Statspack

Load Profile                            Per Second       Per Transaction
~~~~~~~~~~~~                       ---------------       ---------------
                  Redo size:          1,553,489.88        668,736,513.89
              Logical reads:            630,504.58        271,415,631.42
              Block changes:                782.47            336,833.37
             Physical reads:                171.33             73,752.42
            Physical writes:                181.92             78,311.00
                 User calls:                 42.80             18,424.58
                     Parses:                 44.40             19,114.63
                Hard parses:                  0.00                  1.00
                      Sorts:                  0.39                169.89
                     Logons:                  0.00                  0.84
                   Executes:                 44.94             19,344.89
               Transactions:                  0.00

Top 5 Timed Events                                                    Avg %Total
~~~~~~~~~~~~~~~~~~                                                   wait   Call
Event                                            Waits    Time (s)   (ms)   Time
----------------------------------------- ------------ ----------- ------ ------
CPU time                                                     7,764          95.9
log file parallel write                         85,190         147      2    1.8
log file switch (checkpoint incomplete)            246          88    357    1.1
log file switch completion                         502          76    151     .9
control file parallel write                      7,973           9      1     .1
          -------------------------------------------------------------

Instance Activity Stats
Statistic                                      Total     per Second    per Trans
--------------------------------- ------------------ -------------- ------------
...
db block gets                          5,116,321,961      625,543.7 ############
db block gets direct                       1,442,703          176.4     75,931.7
db block gets from cache               5,114,879,258      625,367.3 ############
...
physical writes                            1,487,909          181.9     78,311.0
physical writes direct                     1,444,083          176.6     76,004.4
physical writes direct (lob)               1,442,684          176.4     75,930.7
session logical reads                  5,156,896,997      630,504.6 ############
...

Segments by Logical Reads
                                           Subobject    Obj.       Logical   Pct
Owner      Tablespace Object Name          Name         Type         Reads Total
---------- ---------- -------------------- ------------ ----- ------------ -----
SYS        SYSTEM     SEG$                              TABLE      434,992  23.6
SYS        SYSTEM     TSQ$                              TABLE      432,816  23.5
TEST       TEST       SYS_LOB0000056448C00              LOB        289,808  15.7
SYS        SYSTEM     I_FILE#_BLOCK#                    INDEX      288,448  15.7
SYS        SYSTEM     FILE$                             TABLE      220,416  12.0
          -------------------------------------------------------------

As it can be seen, the number of session logical reads in the test doesn’t align well with figures in Segments by Logical Reads section. Tkprof doesn’t even have a clue about 7K CPU seconds.

But let’s get back to the business. What could be happening that triggered such a vast amount of reads when writing BLOBs? A call to the vendor of the software revealed that the BLOB data is written in chunks and for each chunk the BLOB was closed and reset with an updated position. So, we duplicated this behavior and have gotten following statistics using “runstats” and DbmsOutput.java shared by Tom Kyte and Java API shared by R. M. Menon on AskTom.

BLOB...chunk size                    32,768  32,768  32,768  32,768  32,768  32,768  32,768  32,768  32,768
BLOB...write buffer size             2,048   4,096   8,132   8,192   16,264  16,384  24,396  32,528  32,768
STAT...consistent gets               971     375     119     319     51      234     27      190     222
STAT...consistent gets direct        252     159     52      79      16      32      9       4       20
STAT...db block gets                 6,146   884     423     479     209     268     109     100     208
STAT...db block gets direct          268     140     64      76      32      44      32      16      36
STAT...physical reads direct (lob)   252     124     48      60      16      28      16      0       20
STAT...physical writes direct (lob)  268     140     64      76      32      44      32      16      36
STAT...session logical reads         7,117   1,259   542     798     260     502     136     290     430

BLOB...chunk size                    16,384  16,384  16,384  16,384  16,384  16,384  16,384  16,384  16,384
BLOB...write buffer size             2,048   4,096   8,132   8,192   16,264  16,384  24,396  32,528  32,768
STAT...consistent gets               449     222     99      213     47      74      25      35      63
STAT...consistent gets direct        126     80      24      53      8       22      3       8       19
STAT...db block gets                 3,904   733     397     813     182     295     113     143     250
STAT...db block gets direct          142     78      32      46      16      30      22      16      26
STAT...physical reads direct (lob)   126     62      16      30      0       14      6       0       10
STAT...physical writes direct (lob)  142     78      32      46      16      30      22      16      26
STAT...session logical reads         4,353   955     496     1,026   229     369     138     178     313

BLOB...chunk size                    8,192   8,192   8,192   8,192   8,192   8,192   8,192   8,192   8,192
BLOB...write buffer size             2,048   4,096   8,132   8,192   16,264  16,384  24,396  32,528  32,768
STAT...consistent gets               347     264     95      128     71      91      23      17      39
STAT...consistent gets direct        63      78      16      35      16      27      0       0       7
STAT...db block gets                 2,657   996     349     468     273     369     103     85      161
STAT...db block gets direct          79      47      16      31      16      23      16      16      21
STAT...physical reads direct (lob)   63      31      0       15      0       7       0       0       5
STAT...physical writes direct (lob)  79      47      16      31      16      23      16      16      21
STAT...session logical reads         3,004   1,260   444     596     344     460     126     102     200

By looking at physical reads direct (lob) statistics we can see that there are certain write buffer sizes for each BLOB chunk size that do no produce any additional reading. For our tests with chunk sizes 8K, 16K and 32K it appears that these local minimum points can be derived from BLOB chunk size and certain chunk overhead as in N*(chunk size – K), where N is any natural number and K overhead which dependents on the chunk size as in 8K – 60 Bytes, 16K – 120 Bytes and 32K – 240 Bytes. In these points the amount of physical writes direct (lob) is minimal and what is interesting depends only on the size of the incoming data and the Block Size as in Blob Size/Block Size. From which we can see that each BLOB chunk is written only once.

Here is one more interesting thing to mention, although it is not confirmed. Number of additional operations in other cases exactly matches following scenario that can be clearly described as rewriting BLOB chunks, when ongoing operation reads entire BLOB chunk that is left incompleteby the previous write operation, appends data from current buffer and stores all chunk’s blocks back into the DB. This also triggers significant degradation of LIO per effective amount of written data ratio, which improves with the increase of the write buffer size. This behavior was one of the culprits of the original issue. Of course, not closing BLOB stream on each write would be a better way. However, sometime it isn’t possible to rewrite the code. If an application can be configured to use buffer of a certain length, the issue can be alleviated.

ASSM was playing not the least role in this situation. It has known for causing process “spinning” behavior. In our case the session was sitting in the following stack.

#0  0x000000000159fa03 in kcbgcur ()
#1  0x0000000001007f3b in ktugusc ()
#2  0x0000000001019032 in ktugti () - KTU: Kernel Transaction Undo Get Transaction table entry Information
#3  0x0000000001047e66 in ktbIsItlEntryCommitted ()
#4  0x000000000104db76 in ktrIsItlEntryCommitted ()
#5  0x00000000027cfa2e in kdlxgs_init () - reclaim space from transaction freelist in index
#6  0x0000000000bfab81 in ktsplbfmb ()
#7  0x0000000000bfbd80 in ktsplbrecl ()
#8  0x0000000000bd36e9 in ktspgsp_cbk1 ()
#9  0x00000000027e740f in kdlgsp_init () - Space management batching
#10 0x00000000027e45cb in kdl_write1 ()
#11 0x0000000001d2ece3 in koklwrite () - KOK Lob WRITE
#12 0x00000000022f2094 in kpolob () - KPP Lob operations
#13 0x0000000000711ef8 in opiodr ()
#14 0x00000000039a973b in ttcpip ()
#15 0x000000000070df90 in opitsk ()
#16 0x0000000000710e36 in opiino ()
#17 0x0000000000711ef8 in opiodr ()
#18 0x000000000070bc23 in opidrv ()
#19 0x000000000070a0ce in sou2o ()
#20 0x00000000006d008b in opimai_real ()
#21 0x00000000006cffdc in main ()

Moving hot BLOBs to tablespaces with manual segment space management further improved the situation.

Here are few papers on Metalink that could be helpful in resolving similar BLOB issues.

Note:162345.1 “LOBS – Storage, Read-consistency and Rollback”
Note:66431.1 “LOBS – Storage, Redo and Performance Issues”
Note:268476.1 “LOB Performance Guideline”
Bug: 5253061 “LOB INSERT PERFORMANCE DIFFERS AFTER INSERT DEPENDING ON COMMIT”
Bug: 6128525 “ELAPSED TIME IS TOO HIGHER THAN “WAITED TIME + CPU TIME” IN ASSM LOB ACCESS”
Bug: 5131464 “10.1.0.4 RDBMS 10.1.0.4 SPACE PRODID-5 PORTID-226”

 Tricky part is to find enough time to enjoy both – the event and the place. So, next week I probably will run fewer tests and help fewer customers. But I’m sure I’ll catch up later with all that new energy.

The definition of recursive call as per Metalink Note:41634.1 and 10g Tkprof Manual: 

“Recursive Calls
—————

Sometimes to execute a SQL statement issued by a user, Oracle must issue
additional statements. Such statements are called ‘recursive calls’ or
‘recursive SQL statements’. For example, if you insert a row into a table
that does not have enough space to hold that row, Oracle makes recursive
calls to allocate the space dynamically. Recursive calls are also generated
when data dictionary information is not available in the data dictionary
cache and must be retrieved from disk.

If recursive calls occur while the SQL trace facility is enabled, TKPROF
produces statistics for the recursive SQL statements and clearly marks them
as recursive SQL statements in the output file.  Note that the statistics for
a recursive SQL statement are included in the listing for that statement,
not in the listing for the SQL statement that caused the recursive call.  So
when you are calculating the total resources required to process a SQL
statement, you should consider the statistics for that statement as well as
those for recursive calls caused by that statement.”

Recursive calls are triggered by top level calls that governs processing of statements directly issued by users (or more precisely, issued by a program that communicates directly with Oracle on behalf of its end-users or scripts). Tkprof is supposed to report base statistics (excluding the statistics of its recursive calls) of a call at any level.

For the purpose of the following discussion let me add the following statistics definitions taken from Statistics Descriptions that can be viewed either in Statspack or AWR report or directly using v$sysstat view:

“CPU used by this session – Amount of CPU time (in 10s of milliseconds) used by a session from the time a user call starts until it ends. If a user call completes within 10 milliseconds, the start and end user-call time are the same for purposes of this statistics, and 0 milliseconds are added.
recursive cpu usage – Total CPU time used by non-user calls (recursive calls). Subtract this value from “CPU used by this session” to determine how much CPU time was used by the user calls.”

Documentation says that “CPU used by this session” statistics includes CPU used by recursive calls.

Let’s run a test and take a look at this from practical perspecive and see how well 10.2.0.3 DB conforms to its documentation. I’ve chosen following code for this testing:

create or replace function recursive_function(leveln number, maxlevel number) return number
as
    l_level number := leveln;
    c number := 0;
begin

    loop
        exit when c > 4000000000;
        c := c + 1;
    end loop;

    if l_level+1 <= maxlevel then
        execute immediate 'select /*+ query at level '||(l_level+1)||' */ recursive_function('||(l_level+1)||','||maxlevel||') from dual' into c;
    end if;
   
    return c;
end;
/

begin
    perfstat.statspack.snap(i_ucomment=>'start at '||to_char(sysdate,'yy/mm/dd hh24:mi:ss'));
    DBMS_WORKLOAD_REPOSITORY.CREATE_SNAPSHOT ('ALL');
end;
/

alter session set events '10046 trace name context forever, level 8';              

select /*+ top */ recursive_function(0,3) from dual;

begin
    perfstat.statspack.snap(i_ucomment=>'end at '||to_char(sysdate,'yy/mm/dd hh24:mi:ss'));
    DBMS_WORKLOAD_REPOSITORY.CREATE_SNAPSHOT ('ALL');
end;
/

alter session set events '10046 trace name context off';

It triggers chain of recursive calls with max level 3. This code generates quasi-equal amount of pure CPU load and should allow identifying resource consumption on any level quite easily.

Raw Trace:

PARSING IN CURSOR #53 len=51 dep=0 uid=57 oct=3 lid=57 tim=1166023881658166 hv=1409094977 ad='6cf1aba8'
select /*+ top */ recursive_function(0,3) from dual
END OF STMT
PARSE #53:c=0,e=163,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=1166023881658162
EXEC #53:c=0,e=37,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=1166023881658276
WAIT #53: nam='SQL*Net message to client' ela= 2 driver id=1413697536 #bytes=1 p3=0 obj#=56115 tim=1166023881658319
WAIT #53: nam='SQL*Net message from client' ela= 44597 driver id=1413697536 #bytes=1 p3=0 obj#=56115 tim=1166023881702983
*** 2007-11-02 09:05:46.334
=====================
PARSING IN CURSOR #13 len=64 dep=1 uid=57 oct=3 lid=57 tim=1166024166342227 hv=1557986045 ad='72a95828'
select /*+ query at level 1 */ recursive_function(1,3) from dual
END OF STMT
PARSE #13:c=2999,e=2789,p=0,cr=0,cu=0,mis=1,r=0,dep=1,og=1,tim=1166024166342221
EXEC #13:c=0,e=37,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=1,tim=1166024166342394
*** 2007-11-02 09:10:59.564
=====================
PARSING IN CURSOR #55 len=64 dep=2 uid=57 oct=3 lid=57 tim=1166024472231315 hv=4273745374 ad='6e06c2e8'
select /*+ query at level 2 */ recursive_function(2,3) from dual
END OF STMT
PARSE #55:c=3000,e=2617,p=0,cr=0,cu=0,mis=1,r=0,dep=2,og=1,tim=1166024472231309
EXEC #55:c=0,e=38,p=0,cr=0,cu=0,mis=0,r=0,dep=2,og=1,tim=1166024472231491
*** 2007-11-02 09:15:50.950
=====================
PARSING IN CURSOR #14 len=64 dep=3 uid=57 oct=3 lid=57 tim=1166024756787955 hv=1817767248 ad='6e2b2ec8'
select /*+ query at level 3 */ recursive_function(3,3) from dual
END OF STMT
PARSE #14:c=2000,e=2633,p=0,cr=0,cu=0,mis=1,r=0,dep=3,og=1,tim=1166024756787948
EXEC #14:c=0,e=65,p=0,cr=0,cu=0,mis=0,r=0,dep=3,og=1,tim=1166024756788155
*** 2007-11-02 09:20:42.250
FETCH #14:c=291241724,e=284472442,p=0,cr=0,cu=0,mis=0,r=1,dep=3,og=1,tim=1166025041260627
STAT#14 id=1 cnt=1 pid=0 pos=1 obj=0 op='FASTDUAL  (cr=0 pr=0 pw=0 time=5 us)'
FETCH #55:c=582567435,e=569029386,p=0,cr=0,cu=0,mis=0,r=1,dep=2,og=1,tim=1166025041260907
STAT#55 id=1 cnt=1 pid=0 pos=1 obj=0 op='FASTDUAL  (cr=0 pr=0 pw=0 time=3 us)'
FETCH #13:c=895731828,e=874918635,p=0,cr=0,cu=0,mis=0,r=1,dep=1,og=1,tim=1166025041261058
WAIT #53: nam='SQL*Net message to client' ela= 4 driver id=1413697536 #bytes=1 p3=0 obj#=56115 tim=1166025041261123
FETCH #53:c=1187120530,e=1159558108,p=0,cr=0,cu=0,mis=0,r=1,dep=0,og=1,tim=1166025041261160
WAIT #53: nam='SQL*Net message from client' ela= 54812 driver id=1413697536 #bytes=1 p3=0 obj#=56115 tim=1166025041316063
STAT#53 id=1 cnt=1 pid=0 pos=1 obj=0 op='FASTDUAL  (cr=0 pr=0 pw=0 time=5 us)'

In the 10g raw trace time is given in microseconds. So, you see how the CPU cosumption and elapsed time are reported in the trace. At each level reported as its own CPU load plus the CPU load from the call sub-tree (all descendants):

CPUL3 (291241724)  = CPUL3.base + CPUL4(0: there are no further descendants)
CPUL2 (582567435)  = CPUL2.base + CPUL3(291241724)
CPUL1 (895731828)  = CPUL1.base + CPUL2(582567435)
CPUL0 (1187120530) = CPUL0.base + CPUL1(895731828)

or,

CPUL3.base = CPUL3 = 291241724 = 291 s
CPUL2.base = CPUL2 (582567435) - CPUL3(291241724) = 291325711 = 291 s
CPUL1.base = CPUL1 (895731828) - CPUL2(582567435) = 313164393 = 313 s
CPUL0.base = CPUL0 (1187120530) - CPUL1(895731828) = 291388702 = 291 s

Tkprof:

select /*+ top */ recursive_function(0,3)
from
 dual

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          0          0           0
Execute      1      0.00       0.00          0          0          0           0
Fetch        1   1187.12    1159.55          0          0          0           1
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        3   1187.12    1159.55          0          0          0           1

Parsing user id: 57

================================================================================
select /*+ query at level 1 */ recursive_function(1,3)
from
 dual

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          0          0           0
Execute      1      0.00       0.00          0          0          0           0
Fetch        1    313.16     305.88          0          0          0           1
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        3    313.16     305.88          0          0          0           1

Parsing user id: 57     (recursive depth: 1)

================================================================================
select /*+ query at level 2 */ recursive_function(2,3)
from
 dual

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          0          0           0
Execute      1      0.00       0.00          0          0          0           0
Fetch        1    291.32     284.55          0          0          0           1
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        3    291.32     284.55          0          0          0           1

Parsing user id: 57     (recursive depth: 2)

================================================================================
select /*+ query at level 3 */ recursive_function(3,3)
from
 dual


call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        1      0.00       0.00          0          0          0           0
Execute      1      0.00       0.00          0          0          0           0
Fetch        1    291.24     284.47          0          0          0           1
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total        3    291.24     284.47          0          0          0           1

Parsing user id: 57     (recursive depth: 3)

I always thought Tkprof doesn’t report net statistics for calls, but now I see how wrong I was. From this test it is obvious that the Tkprof reported base times for recursive calls at all levels, and only for the top level calls the CPU and elapsed time are defined as gross load including all levels: CPU_L0 = CPU_L0.base + CPU_L1.base + CPU_L2.base + CPU_L3.base  = 291 + 313 + 291 + 291 = 1187 s. My memory might be playing tricks with me, but I recall I saw a discussion on Jonathan Lewis’s blog about this Tkprof deficiency. Maybe someone will update me where it was.

AWR:

SQL ordered by Elapsed Time

  Elapsed      CPU                  Elap per  % Total
  Time (s)   Time (s)  Executions   Exec (s)  DB Time    SQL Id
---------- ---------- ------------ ---------- ------- -------------
     1,160      1,160            1     1159.6    99.8 1rcptud9zu5a1
Module: SQL Developer
select /*+ top */ recursive_function(0,3) from dual

       875        875            1      874.9    75.3 9pgc4u1fdtyrx
Module: SQL Developer
select /*+ query at level 1 */ recursive_function(1,3) from dual

       569        569            1      569.0    49.0 0v0qmk7zbsbfy
Module: SQL Developer
select /*+ query at level 2 */ recursive_function(2,3) from dual

       284        284            1      284.5    24.5 2zfr66tq5jvah
Module: SQL Developer
select /*+ query at level 3 */ recursive_function(3,3) from dual


Top 5 Timed Events                                         Avg %Total
~~~~~~~~~~~~~~~~~~                                        wait   Call
Event                                 Waits    Time (s)   (ms)   Time Wait Class
------------------------------ ------------ ----------- ------ ------ ----------
CPU time                                          1,162         100.0
control file parallel write             396           1      1    0.0 System I/O
...


Time Model Statistics

Statistic Name                                       Time (s) % of DB Time
------------------------------------------ ------------------ ------------
sql execute elapsed time                              1,162.0        100.0
DB CPU                                                1,161.9        100.0
PL/SQL execution elapsed time                         1,159.6         99.8
...
DB time                                               1,162.1          N/A
background elapsed time                                   2.9          N/A
background cpu time                                       1.5          N/A


Instance Activity Stats

Statistic                                     Total     per Second     per Trans
-------------------------------- ------------------ -------------- -------------
CPU used by this session                    118,971          100.0      13,219.0
CPU used when call started                  118,946           99.9      13,216.2
recursive cpu usage                          89,804           75.5       9,978.2

I rearranged it a little bit for better view.  

First of all, the top section shows that each of the times reported at each level contain times of its descendants (i.e. as in raw trace). Well, no wonder, there is probably not enough information to track call dependency and subtract statistics of children from a parent. Anyhow, it reports gross load for each recursive level and top level calls. Anyone analyzing AWR reports should note statement “Resources reported for PL/SQL code includes the resources used by all SQL statements called by the code.”that precedes this section. Apparently it is actually true not only for PL/SQL code, but for any type of code. This can be seen in the time model statistics where the sql execute elapsed time roughly equal PL/SQL execution elapsed time.

Also, comparing this section to the raw trace or Tkprof output shows that in the AWR report CPU time matches exactly the elapsed time, although it was not the same in the raw trace. This would seem just a reporting “feature”, if not for the information from the further sections. CPU time in Top 5 Timed Events and DB CPU in Time Model Statistics is roughly about 1,160 s. Ignoring small difference, same time is spent by the top level statement. Only Instance Activity Stats section shows 1,189.7 s that almost matches the raw trace CPU time consumed by all subject statements with a little offset of 2.58 s. Further, the recursive cpu usage of 898 s matches the CPU time of the recursive calls starting at level 1 with difference of 2.3 s. Both deltas for the most part are time spent in Statspack subroutines that were captured by AWR.

Statspack:

Top 5 Timed Events                                                    Avg %Total
~~~~~~~~~~~~~~~~~~                                                   wait   Call
Event                                            Waits    Time (s)   (ms)   Time
----------------------------------------- ------------ ----------- ------ ------
CPU time                                                     1,190          99.9
control file parallel write                        397           1      1     .0
...

In Statspack the Time Model Statistics and Instance Activity Stats precisely equal to the corresponding sections in the AWR report. The SQL statistics wasn’t captured for our statements because they didn’t generate logical or physical reads nor they generate other activity that is considered a treat by the Statspack. However in the Top 5 Timed Events you can see that the CPU time is the figure of CPU used by this session statistics in the Instance Activity Stats, so it comes from v$sysstat view.

This behavior is different from AWR algorithm, which rather seem to be taking CPU time in Top 5 Timed Events from v$sys_time_model or directly from their common source. In case v$sys_time_model and v$sysstat have different source of information, AWR is not bound to the figures of the later when reporting Top 5 Timed Events. This perhaps holds an explanation for the AWR oddity seen by Jonathan Lewis. It would be interesting to find the relevant clues in the reports or in this particular system.

Someone was trying to capture performance problem for BLOB loading application. Any method they tried didn’t show good clue to the problem, and they could wonder around it for longer time unless weren’t hinted on certain LOB handling patterns that had been known for some buggy behavior.

But this was just an issue that made me post this other related observation. Here are two excerpts from Tkprof and Statspack reports from database where the case was reproduced.
 

Tkprof

OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse        7      0.02       0.02          4         86          0           0
Execute      9      0.66       1.14         82       2956       5618           8
Fetch        1      0.00       0.00          0          2          0           1
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total       17      0.68       1.16         86       3044       5618           9

Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  SQL*Net message from client                100014       54.07        112.26
  db file sequential read                         1        0.00          0.00
  SQL*Net message to client                  100013        0.00          0.19
  log file sync                                  10        0.00          0.02
  latch: shared pool                             11        0.02          0.02


OVERALL TOTALS FOR ALL RECURSIVE STATEMENTS

call     count       cpu    elapsed       disk      query    current        rows
------- ------  -------- ---------- ---------- ---------- ----------  ----------
Parse     4644      0.94       0.93          0          0        107           0
Execute  11059      6.06       9.85        570      45295       5516        8933
Fetch    23131      0.70       2.23        305      38484          3       28673
------- ------  -------- ---------- ---------- ---------- ----------  ----------
total    38834      7.71      13.03        875      83779       5626       37606

Elapsed times include waiting on following events:
  Event waited on                             Times   Max. Wait  Total Waited
  ----------------------------------------   Waited  ----------  ------------
  db file sequential read                    113211        0.30        324.45
  control file sequential read                  855        0.03          0.06
  direct path write                          154743        0.00          0.70
  direct path read                            99973        0.00          0.64
  log file switch completion                    111        0.97         65.21
  log file switch (checkpoint incomplete)       255        0.97        119.11
  latch: shared pool                              4        0.00          0.00
  latch: checkpoint queue latch                   1        0.00          0.00
  latch: library cache                            1        0.00          0.00
  latch: cache buffers chains                     1        0.00          0.00
  db file scattered read                          1        0.00          0.00

Statspack

  Top 5 Timed Events                                                    Avg %Total
~~~~~~~~~~~~~~~~~~                                                   wait   Call
Event                                            Waits    Time (s)   (ms)   Time
----------------------------------------- ------------ ----------- ------ ------
db file sequential read                        121,368         373      3   49.4
CPU time                                                       141          18.7
log file switch (checkpoint incomplete)            263         122    463   16.1
log file switch completion                         113          66    586    8.8
log file parallel write                          3,837          47     12    6.3
          -------------------------------------------------------------

Time Model System Stats  DB/Inst: TST10203/tst10203  Snaps: 2625-2631
-> Ordered by % of DB time desc, Statistic name

Statistic                                       Time (s) % of DB time
----------------------------------- -------------------- ------------
DB CPU                                             292.3         40.1
sql execute elapsed time                            45.8          6.3
PL/SQL execution elapsed time                       32.8          4.5
parse time elapsed                                   5.4           .7
hard parse elapsed time                              5.3           .7
PL/SQL compilation elapsed time                      0.1           .0
hard parse (sharing criteria) elaps                  0.1           .0
connection management call elapsed                   0.0           .0
repeated bind elapsed time                           0.0           .0
hard parse (bind mismatch) elapsed                   0.0           .0
sequence load elapsed time                           0.0           .0
DB time                                            728.5
background elapsed time                            130.7
background cpu time                                 27.5
          -------------------------------------------------------------



Both parts indicate that there was serious activity, like waits on the sequential disk reading and redo log synchronization, CPU utilization, that was not reported in category “sql execute elapsed time” and “PL/SQL execution elapsed time”. There was no statement reported in Tkprof or Statspack that generated this activity, but there was a particular cursor seen all over the 10046 trace that was responsible for some of these missing components.

I kind of was lucky to see it, because the cursor has no associated calls whatsoever, only wait records. Unless there are waits associated with such cursor, there will be no records about it in the Oracle Trace. Another “funny” thing is that this call-less cursor can have recursive calls too. This cursor is created solely to write and read LOB content.

So, here are few words of caution for those who do performance troubleshooting using raw trace files, Statspack or ASH/AWR reports. Tkprof or other tools that would try to calculate CPU, Elapsed Time or Wait statistics and build hierarchy of calls of sessions containing LOB operations will likely produce incorrect results from slightly wrong to misleading. This is because calls contain major information that allows traversing call hierarchy and calculating base statistics and timing figures. The “missing” calls might cause whole call hierarchy tree to break. For the same reason Statspack reports may show resource consumption without any visible consumer.

One more thing worth mentioning. If LOB operations are wrapped into code that uses calls to communicate with the database (i.e. PL/SQL anonymous blocks or procedures), then the resources consumed by the LOB operations inside that code will be assigned to these calls.

I will continue series about tuning collections in queries starting from the simplest case – collection of values joined to one table. Our subject SQL statements look similar to the following two forms.

1)
select table1.*
  from table1
 where table1.f1 in
       (select column_value from table(test_statement.getList1) nlist1);

and

2)
select table1.*
  from table1, table(test_statement.getList1) nlist1
 where t1.object_id = nlist1.column_value;

We will run them in several ways by adding hints and CBO parameters. First test run is dedicated to show default CBO computations. Note cryptic name KOKBF$ in the predicate section of the explain plan. KOKBF$ is a generic alias given the table expressions. COLLECTION ITERATOR PICKLER FETCH is an operation that retrieves values from collections (if collection was instantiated in the query the operation will read: COLLECTION ITERATOR CONSTRUCTOR FETCH).

Test 1.1:

select /*+ gather_plan_statistics */        t1.object_name,t1.object_type   from t1
where t1.object_id in        (select *           from table(cast(test_statement.getList1 as table_of_number)) nlist1)

Plan:

----------------------------------------------------------------------------------------------------------------------------
| Id  | Operation                           | Name     | Starts | E-Rows | A-Rows |   A-Time   | Buffers | Reads  | Writes |
----------------------------------------------------------------------------------------------------------------------------
|   1 |  NESTED LOOPS                       |          |      1 |    255 |   1252K|00:02:07.32 |    5091K|    177K|   2959 |
|   2 |   SORT UNIQUE                       |          |      1 |    255 |   1878K|00:00:31.30 |      31 |   2959 |   2959 |
|   3 |    COLLECTION ITERATOR PICKLER FETCH| GETLIST1 |      1 |        |   2000K|00:00:04.28 |       0 |      0 |      0 |
|   4 |   TABLE ACCESS BY INDEX ROWID       | T1       |   1878K|      1 |   1252K|00:01:31.73 |    5091K|    174K|      0 |
|*  5 |    INDEX UNIQUE SCAN                | T1_I     |   1878K|      1 |   1252K|00:00:37.04 |    3839K|  28328 |      0 |
----------------------------------------------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------

   5 - access("T1"."OBJECT_ID"=VALUE(KOKBF$))

About two minute runtime is not completely bad. But let’s see what we are driving into here. Nested Loops and Index Access isn’t very good choice for getting > 10% of the data of the base table. Clearly, the estimated cardinality in bold is the culprit here. The value in row with Id 2 is not the part of the output, rather it was taken from CBO trace figures. The original 10053 trace file doesn’t have definite clue where this figure comes from. For the reason described below, this could be a function of the default block size.

BASE STATISTICAL INFORMATION
***********************
Table Stats::
  Table: KOKBF$  Alias: KOKBF$  (NOT ANALYZED)
    #Rows: 8168  #Blks:  100  AvgRowLen:  100.00

...
Join order[2]:  KOKBF$[KOKBF$]#1  T1[T1]#0
    SORT resource      Sort statistics
      Sort width:         459 Area size:      402432 Max Area size:    80530432
      Degree:               1
      Blocks to Sort:    2865 Row size:           13 Total Rows:        1800000
      Initial runs:         2 Merge passes:        1 IO Cost / pass:       1554
      Total IO sort cost: 4419      Total CPU sort cost: 1764307007
      Total Temp space used: 28894000
***************
Now joining: T1[T1]#0
***************
NL Join
  Outer table: Card: 255.25  Cost: 4653.33  Resp: 4653.33  Degree: 1  Bytes: 2

The outer table KOKBF$ was assigned default cardinality as num_of_blocks * (block_size – cache_layer) / avg_row_len. In all tests cache_layer is 24. Something tells me it is similar to the 24 bytes per INITRANS, but I still cannot get my head around the fact where the block fixed header size has gone. It might be something else though. Anyway, given the figures, our default cardinality is 100 * (8192 – 24) / 100 = 8168. With 16K block this would equal 16360 etc. When the collection is uniquely sorted for “IN” clause, its computed cardinality is reduced to 255.25 and rounded to 255. With 16K block this becomes 511.5. This is persuasively looks like default_cardinality/32. One more reason to think the value comes from default statistics assumptions shown in the below CBO trace which is generated by this simple query.

select distinct column_value from table(test_statement.getList1);

The CBO trace in this case has following number of distinct values taken from the default statistics of the collection. If this is so, it explains how CBO arrives at the cardinality of the uniquely sorted collection values in the above calculation.

BASE STATISTICAL INFORMATION
***********************
Table Stats::
  Table: KOKBF$  Alias: KOKBF$  (NOT ANALYZED)
    #Rows: 8168  #Blks:  100  AvgRowLen:  100.00
  Column (#1): KOKBC$(VARCHAR2)  NO STATISTICS (using defaults)
    AvgLen: 1.00 NDV: 255 Nulls: 0 Density: 0.0039177

But I will shut up about it for now until I find out this for certain. Now let’s see what the second form of the testing queries produce.

Test 1.2:

select /*+ gather_plan_statistics */
 t1.object_name,t1.object_type   from t1, table(cast(test_statement.getList1 as table_of_number)) nlist1
where t1.object_id = nlist1.column_value

Plan:

------------------------------------------------------------------------------------------------------------------
| Id  | Operation                          | Name     | Starts | E-Rows | A-Rows |   A-Time   | Buffers | Reads  |
------------------------------------------------------------------------------------------------------------------
|   1 |  NESTED LOOPS                      |          |      1 |   8168 |   1333K|01:27:04.70 |    5422K|   2692K|
|   2 |   COLLECTION ITERATOR PICKLER FETCH| GETLIST1 |      1 |   8168 |   2000K|00:00:06.30 |       0 |      0 |
|   3 |   TABLE ACCESS BY INDEX ROWID      | T1       |   2000K|      1 |   1333K|01:26:51.90 |    5422K|   2692K|
|*  4 |    INDEX UNIQUE SCAN               | T1_I     |   2000K|      1 |   1333K|00:05:39.05 |    4088K|   1382K|
------------------------------------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------

   4 - access("T1"."OBJECT_ID"=VALUE(KOKBF$))

In this case the default cardinality of the 8168 rows of the collection was left intact. The plan didn’t change from Nested Loops for obvious reasons. The time and number of reads skyrocketed. This happened because the collection values were randomly chosen and not sorted as they were in the previous example. Access of the base table became more scattered and subsequently more reads took place. If a key value distribution is known and clustered, it might be worth using co-located values in collections.

Now it’s time to move on to the different settings. To change CBO default cardinality estimation this query uses officially unsupported CARDINALITY hint. You should ask Oracle permission to use it in production.

Test 2.1 (adjusted cardinality):

select /*+ gather_plan_statistics */        t1.object_name,t1.object_type   from t1  where
t1.object_id in        (select /*+ cardinality(nlist1 1800000) */ *           from table(cast(test_statement.getList1 as table_of_number)) nlist1)

Plan:

----------------------------------------------------------------------------------------------------------------------------
| Id  | Operation                           | Name     | Starts | E-Rows | A-Rows |   A-Time   | Buffers | Reads  | Writes |
----------------------------------------------------------------------------------------------------------------------------
|   1 |  NESTED LOOPS                       |          |      1 |    255 |   1252K|00:01:37.31 |    5092K|    172K|   2959 |
|   2 |   SORT UNIQUE                       |          |      1 |    255 |   1878K|00:00:27.63 |     160 |   2970 |   2959 |
|   3 |    COLLECTION ITERATOR PICKLER FETCH| GETLIST1 |      1 |        |   2000K|00:00:04.32 |     129 |     11 |      0 |
|   4 |   TABLE ACCESS BY INDEX ROWID       | T1       |   1878K|      1 |   1252K|00:01:04.31 |    5091K|    169K|      0 |
|*  5 |    INDEX UNIQUE SCAN                | T1_I     |   1878K|      1 |   1252K|00:00:23.96 |    3839K|  23944 |      0 |
----------------------------------------------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------

   5 - access("T1"."OBJECT_ID"=VALUE(KOKBF$))

No changes in the plan and statistics. What happened?! Did CBO even considered the change? Let’s take a look at the CBO trace.

***********************
Table Stats::
  Table: KOKBF$  Alias: KOKBF$  (NOT ANALYZED)
    #Rows: 8168  #Blks:  100  AvgRowLen:  100.00
***************************************
SINGLE TABLE ACCESS PATH
  No statistics type defined for function TEST_STATEMENT
  Table: KOKBF$  Alias: KOKBF$
    Card: Original: 8168    >> Single Tab Card adjusted from: 8168.00  to: 1800000.00
  Rounded: 1800000  Computed: 1800000.00  Non Adjusted: 8168.00

It has obviously mentioned the hint value. But the final cardinality got value as before for the same reason of collection being processed as part of “IN” sub-query. I’ll get back to this a little later.

Alright, let’s see what the second form would be like.

Test 2.2 (adjusted cardinality):

select /*+ gather_plan_statistics cardinality(nlist1 1800000) */
t1.object_name,t1.object_type   from t1, table(cast(test_statement.getList1 as table_of_number)) nlist1  where t1.object_id = nlist1.column_value

Plan:

---------------------------------------------------------------------------------------------------------------------------
| Id  | Operation                          | Name     | Starts | E-Rows | A-Rows |   A-Time   | Buffers | Reads  | Writes |
---------------------------------------------------------------------------------------------------------------------------
|*  1 |  HASH JOIN                         |          |      1 |   1800K|   1333K|00:01:37.68 |     145K|    189K|  45724 |
|   2 |   COLLECTION ITERATOR PICKLER FETCH| GETLIST1 |      1 |   1800K|   2000K|00:00:04.22 |       0 |      0 |      0 |
|   3 |   TABLE ACCESS FULL                | T1       |      1 |     10M|     10M|00:00:31.42 |     145K|    143K|      0 |
---------------------------------------------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------

   1 - access("T1"."OBJECT_ID"=VALUE(KOKBF$))

Now, the hinted cardinality is in the final execution plan. And no wonder the CBO switched the plan from Nested Loops to Hash Join. Compare the logical and physical reads of this test and tests 1.1 and 2.1. If I would have allowed bigger hash area for this query, it could run in-memory and show even better results. Last test for this post is suppose to fix the query with the sub-query. For this we would need to do an additional modification. This time modification of the CBO parameter “_always_semi_join” is needed.

Test 3.1: (adjusted cardinality, “_always_semi_join”=off):

select /*+ gather_plan_statistics */        t1.object_name,t1.object_type   from t1  where
t1.object_id in        (select /*+ cardinality(nlist1 1800000) */ *           from table(cast(test_statement.getList1 as table_of_number)) nlist1)

Plan:

-----------------------------------------------------------------------------------------------------------------------------
| Id  | Operation                            | Name     | Starts | E-Rows | A-Rows |   A-Time   | Buffers | Reads  | Writes |
-----------------------------------------------------------------------------------------------------------------------------
|*  1 |  HASH JOIN                           |          |      1 |   1800K|   1252K|00:01:26.75 |     145K|    195K|  50757 |
|   2 |   VIEW                               | VW_NSO_1 |      1 |   1800K|   1878K|00:00:11.52 |       0 |   6825 |   6825 |
|   3 |    HASH UNIQUE                       |          |      1 |   1800K|   1878K|00:00:09.64 |       0 |   6825 |   6825 |
|   4 |     COLLECTION ITERATOR PICKLER FETCH| GETLIST1 |      1 |   1800K|   2000K|00:00:04.24 |       0 |      0 |      0 |
|   5 |   TABLE ACCESS FULL                  | T1       |      1 |     10M|     10M|00:00:31.40 |     145K|    144K|      0 |
-----------------------------------------------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------

   1 - access("T1"."OBJECT_ID"="COLUMN_VALUE")

Why, you might ask, the Semi Join parameter has any effect on this? In pre evaluation phase CBO tries to apply different query rewrite techniques in order to optimize the query. One of them is unnesting sub-query. In this case it can either do Semi Join or unnest the sub-query as a set (collection of distinct values). Since the Semi Join is disabled it used the later. The sub-query took following form with cardinality hint propagated to the outer query.

SELECT "T1"."OBJECT_NAME" "OBJECT_NAME","T1"."OBJECT_TYPE" "OBJECT_TYPE" FROM  (SELECT /*+ OPT_ESTIMATE (TABLE "KOKBF$" ROWS=1800000.000000 ) */ DISTINCT VALUE(KOKBF$) "COLUMN_VALUE" FROM TABLE(CAST("TEST"."TEST_STATEMENT"."GETLIST1"() AS "TABLE_OF_NUMBER") ) "KOKBF$") "VW_NSO_1","TEST"."T1" "T1" WHERE "T1"."OBJECT_ID"="VW_NSO_1"."COLUMN_VALUE"

Basically the original query was rewritten into following form. It is similar to the second original form with the exception of distinct clause. Cardinality hint was not ignored as it was in the original query and CBO generated desired plan.

select /*+ cardinality(nlist1 1800000) */
       t1.object_name,t1.object_type
  from t1
     , (select distinct column_value from table(cast(test_statement.getList1 as table_of_number))) nlist1
 where t1.object_id = nlist1.column_value;

Few words in conclusion. When tuning these queries, make sure CBO doesn’t rely on default statistics. In most cases CBO will subsequently generate sub-optimal plan, i.e. NLs instead of desired HJ or vice versa. If you cannot disable Semi Join, unnest “IN” sub-query. When tuning “IN” sub-query, use cardinality value close to the number of distinct elements, because that is what CBO will use in its calculations. If distribution of table data is deterministic, co-locate the values of the joined collection whenever possible to increase clustering of the access operation.

For the testing I used two databases Oracle 10g and Oracle 9i with database character set UTF8 and JDBC 10.2.0.3.

Some of the Asian language characters can consume up to 3 bytes in UTF8 encoding. But can you expect that a string composed of 1334 ASCII characters would not bind for VARCHAR2(4000)? However, it is possible. Let’s dig up little more details.

Here is how the string of 4000 “a” characters would appear to the Oracle 9iwhen bound from JDBC 10g with default properties. This bind is not spooled into the 10046 trace file. Instead it can be captured by enabling stacktrace dump on 1461 event.


 bind 19: dty=1 mxl=4001(12000) mal=00 scl=00 pre=00 oacflg=03 oacfl2=10 size=4000 offset=0
   bfp=ffffffff7cd7f060 bln=4000 avl=00flg=05


Oracle Server 10g. Note, that when you test this scenario, there are no errors – Oracle Server 10g  is perfectly fine with the 12000 bytes in the private buffer.


 Bind#19
  oacdty=01 mxl=4001(12000) mxlc=00 mal=00 scl=00 pre=00
  oacflg=03 fl2=1000010 frm=01 csi=871 siz=4000 off=0
  kxsbbbfp=ffffffff7b55a0c0  bln=4000  avl=4000  flg=05
  value="aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa....


According to Metalink Note: 3756847.8 this problem was introduced in some 10.1 versions of JDBC, but was fixed in 10.2. However, it is not enabled by default. Following JDBC connection property enables the fix.


java.util.Properties props = new java.util.Properties();
props.put("oracle.jdbc.RetainV9LongBindBehavior","true");
ods.setConnectionProperties(props);
ods.setURL(url);


And here is how the bind looks like after the fix is enabled.
 

Oracle Server 9i:


bind 19: dty=1 mxl=4000(4000) mal=00 scl=00 pre=00 oacflg=03 oacfl2=10 size=4000 offset=0
   bfp=ffffffff7cd56088 bln=4000 avl=4000 flg=05
   value="aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa...


Oracle Server 10g:


 Bind#19
  oacdty=01 mxl=4000(4000) mxlc=00 mal=00 scl=00 pre=00
  oacflg=03 fl2=1000010 frm=01 csi=871 siz=4000 off=0
  kxsbbbfp=ffffffff7b56f060  bln=4000 avl=4000flg=05
  value="aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa...


There is no need in enabling this fix for 10g/10g setup. 10g version of the trace is shown just for comparison purposes.

In conclusion I want to clarify that this article describes the unexpected behavior with legitimate length values. However, there are other cases when apparently correct values fail to insert with same message. I.e. already mentioned strings that, when using UTF8 for database character set, can expand from 4000 Asian language characters to up to 12000 byte values. In these cases, Notes: 241358.1, 370438.1 recommend different workarounds. Note: 445072.1  has decent example of getting the length of encoded string and suggests converting VARCHAR2 columns into CLOB if encoded string length exceeds maximum length of VARCHAR2 type.

If you never heard of using collections instead of regular IN-LIST expressions, you might want to read varying elements in IN list article from AskTom. It unfortunately has little information about the way CBO treats collections. So, if you have problems with tuning queries that employ nested tables or just evaluating what is in the way please read on. Here is one of the basic forms of SQL queries that employ collections.

select *
  from t1
 where t1.object_id in
     (
       select *
         from table(cast(:1 as table_of_number))
     );

There are several optimization issues related to tuning queries that use collections. Many of them can be attributed to the CBO statistical assumptions. The CBO calculations and figures are a little different in 9i and 10g. However the issue might have change the appearance, but not the essence. There will be few more posts on some basic forms of queries with collections.

Over the past three years I’ve engaged with the Oracle TS several times to find a good resolution for this nuisance. That generated couple bugs: 4484645, 4235962. One of them is closed as “NOT A BUG”.

Should we use undocumented or unofficial methods? Yes, no doubt. That is of course when they are judicially legitimate. I just wanted to point out few key elements of the documented versus undocumented approach as I understand and interpret it. In a different scope this might become discussion about supported versus unsupported and so on.

Documentation is a right place to go if it exists. If it doesn’t, “hacking” in the right meaning of the word, is the way to know the system better than it can possibly be documented. Consider Oracle tracing facility as free of charge and supported debugger. By using it you’d learn about the Oracle and application that uses Oracle, about specifics of different Oracle versions, the improvements in newer releases and deficiencies in former releases.

 What you would lack when you use Oracle tracing is official evidence. If you see a problem in the trace, but struggle to reproduce it using documented forms of proof, you might have some trouble building a case for an SR. You also will have certain difficulties explaining it to the Oracle TS what is that you are trying to solve. And final point against it, when filing SR, is that in Oracle R&D work people just like you. Reverse enginiring an issue from a trace file that you attached is the last thing they wanted to do. Similar to any other trace whether that is a stack trace from JVM or a core dump. It is always better for them to have a reproducible at will test case. However, many times by looking at traces I found things to build a simple test case that I wouldn’t have gotten that easily otherwise.

To summarize, as far as I’m concerned, if the Oracle traces, considering their generation can be done using supported API, allow me to find true problems and do right decisions I’ll keep using them even if their format is neither documented nor supported.

I noticed during my testing by fetching from different “width” tables and playing with prefetch row count, that the wider the row or higher prefetch count were the faster my cache had grown. I debugged my code for many hours looking whether I was closing result sets or for something else very obvious. Nope, no luck – everything was correct. And yet OOME was consistent.

In the end it appeared that JDBC OracleStatement kept reference to so called accessors’ arrays (like a cache of prefetched rows data) for a result set that had been last executed even when the result set was already closed. The size of that data was proportional to the product of the fetched data (in my tests table) width and prefetch row count. I’ve tried then JDBC implicit and explicit caching and was showing precisely same memory footprint.

Opened SR and after few weeks was advised by a nice Oracle TS lady that there could be one workaround (which is mentioned above). It was to use property FreeMemoryOnEnterImplicitCache and so instead of this:

conn = (OracleConnection) DriverManager.getConnection(url, user, password);

use this

OracleDataSource ods = new OracleDataSource();Properties props = new Properties();
props.put("user", user);
props.put("password", password);
props.put("oracle.jdbc.FreeMemoryOnEnterImplicitCache", true);
ods.setConnectionProperties(props);
ods.setURL(url);
conn = ods.getConnection();

During testing I didn’t find a way a custom or explicit cache with key can be used effectively, especially if they are LRU caches (the later appeared to be LRU type of cache) – that residue data is going to get into OldGeneration before the statement is reused and the arrays are repopulated. I really hope the “bug” is going to be fixed in JDBC 10.2.0.4.

Metalink bug reference: 6082980