COLLECTION ITERATOR (PICKLER FETCH) Appearing in DBMS_XPLAN Output

December 6, 2009

In several discussion threads a DBMS_XPLAN is requested, and the provided output will occasionally look like this:

-----------------------------------------------------
| Id  | Operation                         | Name    |
-----------------------------------------------------
|   1 |  COLLECTION ITERATOR PICKLER FETCH| DISPLAY |
-----------------------------------------------------

One such case appeared in this discussion thread:
http://forums.oracle.com/forums/thread.jspa?threadID=656614&start=0

In short, the problem is caused by either enabling server output, or enabling SQL*Plus’ autotrace.

A quick test setup that I provided in the above thread to reproduce the problem:

CREATE TABLE T1 (C1 NUMBER(12));

INSERT INTO
  T1
SELECT
  ROWNUM
FROM
  DUAL
CONNECT BY
  LEVEL<=10000;

COMMIT;

Let’s try an experiment with a simple SQL statement:

SELECT
  C1
FROM
  T1
WHERE
  C1 BETWEEN 90 AND 150;

With the following settings:

OPTIMIZER_MODE=CHOOSE
OPTIMIZER_FEATURES_ENABLE=9.0.1
STATISTICS_LEVEL=ALL  (session level)

 

SQL_ID  84bwrtyfrxhzx, child number 0
--------------------------------------------------------------------------------
SELECT    C1  FROM    T1  WHERE    C1 BETWEEN 90 AND 150
Plan hash value: 3617692013
---------------------------------------------------------------------------
| Id  | Operation         | Name | Starts | A-Rows |   A-Time   | Buffers |
---------------------------------------------------------------------------
|*  1 |  TABLE ACCESS FULL| T1   |      1 |     61 |00:00:00.01 |      23 |
---------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------
   1 - filter(("C1"<=150 AND "C1">=90))
Note
--------------------------------------------------------------------------------
   - rule based optimizer used (consider using cbo)

(That warning surprised me a bit… as this is running on Oracle 11.1.0.6 and the rule based optimizer was deprecated in 10g R1.)

Partial output from a 10046 at level 12 enabled at the same time:

=====================
PARSING IN CURSOR #3 len=56 dep=0 uid=63 oct=3 lid=63 tim=657639757986 hv=2642330621 ad='1af34a2c' sqlid='84bwrtyfrxhzx'
SELECT
  C1
FROM
  T1
WHERE
  C1 BETWEEN 90 AND 150
END OF STMT
PARSE #3:c=0,e=701,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=4,tim=657639757982
BINDS #3:
EXEC #3:c=0,e=57,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=4,tim=657639758209
WAIT #3: nam='SQL*Net message to client' ela= 4 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=657639758249
FETCH #3:c=15600,e=713,p=0,cr=23,cu=0,mis=0,r=61,dep=0,og=4,tim=657639759004
STAT #3 id=1 cnt=61 pid=0 pos=1 obj=72628 op='TABLE ACCESS FULL T1 (cr=23 pr=0 pw=0 time=99 us)'
WAIT #3: nam='SQL*Net message from client' ela= 9637 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=657639779290
=====================
...
PARSING IN CURSOR #4 len=80 dep=0 uid=63 oct=3 lid=63 tim=657640013624 hv=266232738 ad='22039234' sqlid='0nfjn6n7xwsx2'
SELECT
  *
FROM
  TABLE(DBMS_XPLAN.DISPLAY_CURSOR(NULL,NULL,'ALLSTATS LAST'))
END OF STMT
PARSE #4:c=46800,e=234176,p=2,cr=199,cu=0,mis=1,r=0,dep=0,og=4,tim=657640013619
WAIT #4: nam='SQL*Net message to client' ela= 8 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=657640013799
WAIT #4: nam='SQL*Net message from client' ela= 570 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=657640014444
BINDS #4:
EXEC #4:c=0,e=58,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=4,tim=657640014557
WAIT #4: nam='SQL*Net message to client' ela= 9 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=657640495379
FETCH #4:c=171601,e=480979,p=15,cr=888,cu=0,mis=0,r=21,dep=0,og=4,tim=657640495566
STAT #4 id=1 cnt=21 pid=0 pos=1 obj=0 op='COLLECTION ITERATOR PICKLER FETCH DISPLAY_CURSOR (cr=888 pr=15 pw=15 time=81 us)'

In the above 10046 trace, note the STAT line containing “COLLECTION ITERATOR PICKLER FETCH DISPLAY_CURSOR” on the last line – that is the execution plan for the call to DBMS_XPLAN.DISPLAY_CURSOR, and not the original query that was of interest. That was the plan that Lokesh provided to Jonathan, and not the one that Jonathan requested.

Let’s try again to remove the “rule based optimizer used” warning:

OPTIMIZER_MODE=ALL_ROWS
OPTIMIZER_FEATURES_ENABLE=11.1.0.6
STATISTICS_LEVEL=ALL  (session level)

The DBMS_XPLAN:

SQL_ID  84bwrtyfrxhzx, child number 1
--------------------------------------------------------------------------------
SELECT    C1  FROM    T1  WHERE    C1 BETWEEN 90 AND 150
Plan hash value: 3617692013
------------------------------------------------------------------------------------
| Id  | Operation         | Name | Starts | E-Rows | A-Rows |   A-Time   | Buffers |
------------------------------------------------------------------------------------
|*  1 |  TABLE ACCESS FULL| T1   |      1 |     61 |     61 |00:00:00.01 |      23 |
------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------
   1 - filter(("C1">=90 AND "C1"<=150))
Note
--------------------------------------------------------------------------------
   - dynamic sampling used for this statement

 
Partial output from a 10046 at level 12 enabled at the same time:

=====================
PARSING IN CURSOR #12 len=56 dep=0 uid=63 oct=3 lid=63 tim=657812448763 hv=2642330621 ad='1af34a2c' sqlid='84bwrtyfrxhzx'
SELECT
  C1
FROM
  T1
WHERE
  C1 BETWEEN 90 AND 150
END OF STMT
PARSE #12:c=46801,e=54061,p=0,cr=24,cu=0,mis=1,r=0,dep=0,og=1,tim=657812448759
BINDS #12:
EXEC #12:c=0,e=51,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=657812449038
WAIT #12: nam='SQL*Net message to client' ela= 8 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=657812449085
FETCH #12:c=0,e=768,p=0,cr=23,cu=0,mis=0,r=61,dep=0,og=1,tim=657812449899
STAT #12 id=1 cnt=61 pid=0 pos=1 obj=72628 op='TABLE ACCESS FULL T1 (cr=23 pr=0 pw=0 time=75 us cost=7 size=793 card=61)'
WAIT #12: nam='SQL*Net message from client' ela= 10282 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=657812460271
=====================
...
PARSING IN CURSOR #11 len=80 dep=0 uid=63 oct=3 lid=63 tim=657812468416 hv=266232738 ad='22039234' sqlid='0nfjn6n7xwsx2'
SELECT
  *
FROM
  TABLE(DBMS_XPLAN.DISPLAY_CURSOR(NULL,NULL,'ALLSTATS LAST'))
END OF STMT
PARSE #11:c=0,e=7984,p=0,cr=111,cu=0,mis=1,r=0,dep=0,og=1,tim=657812468413
FETCH #11:c=62400,e=56650,p=0,cr=274,cu=0,mis=0,r=21,dep=0,og=1,tim=657812526032
STAT #11 id=1 cnt=21 pid=0 pos=1 obj=0 op='COLLECTION ITERATOR PICKLER FETCH DISPLAY_CURSOR (cr=274 pr=0 pw=0 time=86 us)'

I hope that clears things up for you. I tried the following, but was not able to reproduce DBMS_XPLAN returning the plan for DBMS_XPLAN, rather than the last plan executed:

ALTER SESSION SET STATISTICS_LEVEL='ALL';

ALTER SESSION SET EVENTS '10046 TRACE NAME CONTEXT FOREVER, LEVEL 12';

SET AUTOTRACE ON STATISTICS

SELECT
  C1
FROM
  T1
WHERE
  C1 BETWEEN 90 AND 150;

 

Statistics
--------------------------------------------------------------------------------
          0  recursive calls
          0  db block gets
         28  consistent gets
          0  physical reads
          0  redo size
       1279  bytes sent via SQL*Net to client
        460  bytes received via SQL*Net from client
          6  SQL*Net roundtrips to/from client
          0  sorts (memory)
          0  sorts (disk)
         61  rows processed

 

select * from table(dbms_xplan.display_cursor(null,null,'ALLSTATS LAST'));

 

SQL> SET AUTOTRACE ON STATISTICS
SQL> SET SERVEROUTPUT ON
SQL> SELECT /*+ gather_plan_statistics */
  2    C1
  3  FROM
  4    T1
  5  WHERE
  6    C1 BETWEEN 90 AND 150;
        C1
--------------------------------------------------------------------------------
        90
        91
        92
...
       148
       149
       150
61 rows selected.

Statistics
--------------------------------------------------------------------------------
          0  recursive calls
          0  db block gets
         28  consistent gets
          0  physical reads
          0  redo size
       1029  bytes sent via SQL*Net to client
        378  bytes received via SQL*Net from client
          6  SQL*Net roundtrips to/from client
          0  sorts (memory)
          0  sorts (disk)
         61  rows processed

 

SQL> select * from table(dbms_xplan.display_cursor(null,null,'ALLSTATS LAST'));
PLAN_TABLE_OUTPUT
--------------------------------------------------------------------------------
SQL_ID  9babjv8yq8ru3, child number 0
BEGIN DBMS_OUTPUT.GET_LINES(:LINES, :NUMLINES); END;
NOTE: cannot fetch plan for SQL_ID: 9babjv8yq8ru3, CHILD_NUMBER: 0
      Please verify value of SQL_ID and CHILD_NUMBER;
      It could also be that the plan is no longer in cursor cache (check v$sql_plan)
--------------------------------------------------------------------------------