How Much Space is Required to Store a Whole Lot of Nothing?

29 04 2010

April 29, 2010

While looking for something completely unrelated I encountered one of the test cases that I posted to an OTN forum thread about a year ago.  There are a couple of interesting items in the test case, so I thought that I would reproduce it here, verifying the test case on Oracle 11.2.0.1.  The OTN forum thread asked if NULL values in table columns take up space, and if so does it depend on the data type of the column.  I answered the question like this:

It is my understanding that NULL values in the last columns (non-null values appear only in the first set of columns defined for the table) in of a row do not consume space, while NULL values in the first set of columns, if they are followed by columns containing non-NULL values will consume space. At this time, I am having trouble locating a reference which backs up my understanding of how NULLs affect storage space.

The test case was originally constructed to be executed against Oracle Database 10.2.0.4, and the output showed what was achieved with an ASSM autoallocate tablespace with an 8KB block size.  So, what happens when the test case is executed on Oracle Database 11.2.0.1 with an ASSM autoallocate tablespace with an 8KB block size?  The results may surprise you.

First, we need to create a table with a couple of different column data types, and then collect statistics for the table:

CREATE TABLE T1 (
  C1 VARCHAR2(300),
  C2 NUMBER(22,4),
  C3 DATE,
  C4 BLOB,
  C5 CLOB);

EXEC DBMS_STATS.GATHER_TABLE_STATS(OWNNAME=>USER,TABNAME=>'T1')

Surprised by the results yet?

SELECT
  NUM_ROWS,
  BLOCKS,
  EMPTY_BLOCKS,
  AVG_ROW_LEN,
  NUM_FREELIST_BLOCKS
FROM
  USER_TABLES
WHERE
  TABLE_NAME='T1';

  NUM_ROWS     BLOCKS EMPTY_BLOCKS AVG_ROW_LEN NUM_FREELIST_BLOCKS
---------- ---------- ------------ ----------- -------------------
         0          0            0           0                   0

SELECT
  EXTENT_ID,
  BYTES,
  BLOCKS
FROM
  USER_EXTENTS
WHERE
  SEGMENT_NAME='T1'
ORDER BY
  EXTENT_ID;

no rows selected

Probably not if you read about Oracle Database 11.2.0.1′s deferred segment creation feature.  Yes, the above results differed from that of Oracle Database 10.2.0.4, which showed the following for the second SQL statement:

 EXTENT_ID      BYTES     BLOCKS
---------- ---------- ----------
         0      65536          8

Next, insert 1,000,000 rows containing NULL values in all columns and re-gather the statistics:

INSERT INTO T1 (C1)
SELECT
  NULL
FROM
  DUAL
CONNECT BY
  LEVEL<=500000;

INSERT INTO T1 (C1)
SELECT
  NULL
FROM
  DUAL
CONNECT BY
  LEVEL<=500000;

COMMIT;

EXEC DBMS_STATS.GATHER_TABLE_STATS(OWNNAME=>USER,TABNAME=>'T1')

Now let’s check the table’s statistics:

SELECT
  NUM_ROWS,
  BLOCKS,
  EMPTY_BLOCKS,
  AVG_ROW_LEN,
  NUM_FREELIST_BLOCKS
FROM
  USER_TABLES
WHERE
  TABLE_NAME='T1';

  NUM_ROWS     BLOCKS EMPTY_BLOCKS AVG_ROW_LEN NUM_FREELIST_BLOCKS
---------- ---------- ------------ ----------- -------------------
   1000000       1630            0           1                   0

Oracle Database 10.2.0.4 was not quite as accurate when estimating the number of rows in the table:

  NUM_ROWS     BLOCKS EMPTY_BLOCKS AVG_ROW_LEN NUM_FREELIST_BLOCKS
---------- ---------- ------------ ----------- -------------------
    984619       1630            0           1                   0

Next let’s take a look at the extent allocation, which was the same for both releases of Oracle Database:

SELECT
  EXTENT_ID,
  BYTES,
  BLOCKS
FROM
  USER_EXTENTS
WHERE
  SEGMENT_NAME='T1'
ORDER BY
  EXTENT_ID;

 EXTENT_ID      BYTES     BLOCKS
---------- ---------- ----------
         0      65536          8
         1      65536          8
         2      65536          8
         3      65536          8
         4      65536          8
         5      65536          8
         6      65536          8
         7      65536          8
         8      65536          8
         9      65536          8
        10      65536          8
        11      65536          8
        12      65536          8
        13      65536          8
        14      65536          8
        15      65536          8
        16    1048576        128
        17    1048576        128
        18    1048576        128
        19    1048576        128
        20    1048576        128
        21    1048576        128
        22    1048576        128
        23    1048576        128
        24    1048576        128
        25    1048576        128
        26    1048576        128
        27    1048576        128

SELECT
  SUM(BYTES) BYTES,
  SUM(BLOCKS) BLOCKS
FROM
  USER_EXTENTS
WHERE
  SEGMENT_NAME='T1'
ORDER BY
  EXTENT_ID;

     BYTES     BLOCKS
---------- ----------
  13631488       1664

The above shows that the table is using 1630 blocks to store the rows with the completely NULL values, there are 1664 blocks allocated to extents used by the table, and 13,631,488 bytes used by the extents.  NULLs consuming space?

A little fun with the ROWID pseudocolumn, dissecting the components of that pseudocolumn (side note, I do not recall where I originally determined how to break apart the 18 byte long displayed ROWID, but it is found in the documentation):

SELECT
  SUBSTR(ROWID,1,6) OBJECT_ID,
  SUBSTR(ROWID,7,3) FILE_ID,
  SUBSTR(ROWID,10,6) BLOCK_ID,
  SUBSTR(ROWID,16,3) ROW_ID,
  LENGTHB(ROWID) LEN,
  COUNT(*) OVER (PARTITION BY SUBSTR(ROWID,10,6) ORDER BY ROWNUM) ROWN,
  SUM(LENGTH(ROWID)) OVER (PARTITION BY SUBSTR(ROWID,10,6) ORDER BY ROWNUM) BYTES
FROM
  T1
WHERE
  ROWNUM<=1400;

OBJECT FIL BLOCK_ ROW        LEN       ROWN      BYTES
------ --- ------ --- ---------- ---------- ----------
AAAULA AAH AAGLHT AAA         18          1         18
AAAULA AAH AAGLHT AAB         18          2         36
AAAULA AAH AAGLHT AAC         18          3         54
AAAULA AAH AAGLHT AAD         18          4         72
AAAULA AAH AAGLHT AAE         18          5         90
AAAULA AAH AAGLHT AAF         18          6        108
AAAULA AAH AAGLHT AAG         18          7        126
AAAULA AAH AAGLHT AAH         18          8        144
AAAULA AAH AAGLHT AAI         18          9        162
AAAULA AAH AAGLHT AAJ         18         10        180
AAAULA AAH AAGLHT AAK         18         11        198
AAAULA AAH AAGLHT AAL         18         12        216
AAAULA AAH AAGLHT AAM         18         13        234
AAAULA AAH AAGLHT AAN         18         14        252
AAAULA AAH AAGLHT AAO         18         15        270
AAAULA AAH AAGLHT AAP         18         16        288
AAAULA AAH AAGLHT AAQ         18         17        306
AAAULA AAH AAGLHT AAR         18         18        324
AAAULA AAH AAGLHT AAS         18         19        342
AAAULA AAH AAGLHT AAT         18         20        360
...
AAAULA AAH AAGLHT AKP         18        656      11808
AAAULA AAH AAGLHT AKQ         18        657      11826
AAAULA AAH AAGLHT AKR         18        658      11844
AAAULA AAH AAGLHT AKS         18        659      11862
AAAULA AAH AAGLHT AKT         18        660      11880
AAAULA AAH AAGLHU AAA         18          1         18
AAAULA AAH AAGLHU AAB         18          2         36
AAAULA AAH AAGLHU AAC         18          3         54
AAAULA AAH AAGLHU AAD         18          4         72
AAAULA AAH AAGLHU AAE         18          5         90
AAAULA AAH AAGLHU AAF         18          6        108
AAAULA AAH AAGLHU AAG         18          7        126
AAAULA AAH AAGLHU AAH         18          8        144
AAAULA AAH AAGLHU AAI         18          9        162
AAAULA AAH AAGLHU AAJ         18         10        180
AAAULA AAH AAGLHU AAK         18         11        198
AAAULA AAH AAGLHU AAL         18         12        216
AAAULA AAH AAGLHU AAM         18         13        234
AAAULA AAH AAGLHU AAN         18         14        252
...
AAAULA AAH AAGLHU AKP         18        656      11808
AAAULA AAH AAGLHU AKQ         18        657      11826
AAAULA AAH AAGLHU AKR         18        658      11844
AAAULA AAH AAGLHU AKS         18        659      11862
AAAULA AAH AAGLHU AKT         18        660      11880
AAAULA AAH AAGLHV AAA         18          1         18
AAAULA AAH AAGLHV AAB         18          2         36
AAAULA AAH AAGLHV AAC         18          3         54
AAAULA AAH AAGLHV AAD         18          4         72
AAAULA AAH AAGLHV AAE         18          5         90
AAAULA AAH AAGLHV AAF         18          6        108
AAAULA AAH AAGLHV AAG         18          7        126
AAAULA AAH AAGLHV AAH         18          8        144
AAAULA AAH AAGLHV AAI         18          9        162
AAAULA AAH AAGLHV AAJ         18         10        180
AAAULA AAH AAGLHV AAK         18         11        198
AAAULA AAH AAGLHV AAL         18         12        216
AAAULA AAH AAGLHV AAM         18         13        234
AAAULA AAH AAGLHV AAN         18         14        252
...
AAAULA AAH AAGLHV ABM         18         77       1386
AAAULA AAH AAGLHV ABN         18         78       1404
AAAULA AAH AAGLHV ABO         18         79       1422
AAAULA AAH AAGLHV ABP         18         80       1440

The above shows that Oracle was packing 660 of these completely NULL rows into each 8KB block with a default PCT_FREE of 10%, leaving about 7370 bytes of space for storing the 660 rows per block, indicating that each row was consuming about 11 bytes.  Obviously from the above, the actual ROWID for a row does not occupy a full 18 bytes of data storage per row.  It is actually 10 bytes (reference) that is externalized as a 18 byte (reference) base 64 encoded character string.  In retrospect, I probably should have done the following instead to decode the ROWID using the DBMS_ROWID package, and calculate the per row overhead plus the space required (1 byte) to store the data:

SELECT
  DBMS_ROWID.ROWID_OBJECT(ROWID) OBJECT_ID,
  DBMS_ROWID.ROWID_RELATIVE_FNO(ROWID) FILE_ID,
  DBMS_ROWID.ROWID_BLOCK_NUMBER(ROWID) BLOCK_NUMBER,
  DBMS_ROWID.ROWID_ROW_NUMBER(ROWID) ROW_ID,
  COUNT(*) OVER (PARTITION BY SUBSTR(ROWID,10,6) ORDER BY ROWNUM) ROWN,
  SUM(11) OVER (PARTITION BY SUBSTR(ROWID,10,6) ORDER BY ROWNUM) BYTES
FROM
  T1
WHERE
  ROWNUM<=1400;

 OBJECT_ID    FILE_ID BLOCK_NUMBER     ROW_ID       ROWN      BYTES

---------- ---------- ------------ ---------- ---------- ----------
     82624          7      1618387          0          1         11
     82624          7      1618387          1          2         22
     82624          7      1618387          2          3         33
     82624          7      1618387          3          4         44
     82624          7      1618387          4          5         55
     82624          7      1618387          5          6         66
     82624          7      1618387          6          7         77
     82624          7      1618387          7          8         88
     82624          7      1618387          8          9         99
     82624          7      1618387          9         10        110
     82624          7      1618387         10         11        121
     82624          7      1618387         11         12        132
     82624          7      1618387         12         13        143
     82624          7      1618387         13         14        154
     82624          7      1618387         14         15        165
...
     82624          7      1618387        655        656       7216
     82624          7      1618387        656        657       7227
     82624          7      1618387        657        658       7238
     82624          7      1618387        658        659       7249
     82624          7      1618387        659        660       7260
     82624          7      1618388          0          1         11
     82624          7      1618388          1          2         22
     82624          7      1618388          2          3         33
     82624          7      1618388          3          4         44
     82624          7      1618388          4          5         55
     82624          7      1618388          5          6         66
     82624          7      1618388          6          7         77
     82624          7      1618388          7          8         88
     82624          7      1618388          8          9         99
     82624          7      1618388          9         10        110
...
     82624          7      1618388        656        657       7227
     82624          7      1618388        657        658       7238
     82624          7      1618388        658        659       7249
     82624          7      1618388        659        660       7260
     82624          7      1618389          0          1         11
     82624          7      1618389          1          2         22
     82624          7      1618389          2          3         33
     82624          7      1618389          3          4         44
     82624          7      1618389          4          5         55
     82624          7      1618389          5          6         66
     82624          7      1618389          6          7         77
     82624          7      1618389          7          8         88
     82624          7      1618389          8          9         99
     82624          7      1618389          9         10        110
...
     82624          7      1618389         77         78        858
     82624          7      1618389         78         79        869
     82624          7      1618389         79         80        880

A comparison test with a second table containing a single column:

CREATE TABLE T2 (
  C1 VARCHAR2(1));

EXEC DBMS_STATS.GATHER_TABLE_STATS(OWNNAME=>USER,TABNAME=>'T2')

INSERT INTO T2 (C1)
SELECT
  NULL
FROM
  DUAL
CONNECT BY
  LEVEL<=500000;

INSERT INTO T2 (C1)
SELECT
  NULL
FROM
  DUAL
CONNECT BY
  LEVEL<=500000;

COMMIT;

EXEC DBMS_STATS.GATHER_TABLE_STATS(OWNNAME=>USER,TABNAME=>'T2')

If the columns containing NULL values required storage space in table T1, then we should expect that table T2 should require less space than that for table T1.

SELECT
  SUM(BYTES) BYTES,
  SUM(BLOCKS) BLOCKS
FROM
  USER_EXTENTS
WHERE
  SEGMENT_NAME='T2'
ORDER BY
  EXTENT_ID;

     BYTES     BLOCKS
---------- ----------
  13631488       1664

The 13,631,488 bytes and 1,664 blocks appears to be the same values as displayed for table T1.

For extra credit we might try something like this:

UPDATE
  T1
SET
  C2=1;

COMMIT;

EXEC DBMS_STATS.GATHER_TABLE_STATS(OWNNAME=>USER,TABNAME=>'T1')

SELECT
  NUM_ROWS,
  BLOCKS,
  EMPTY_BLOCKS,
  AVG_ROW_LEN,
  NUM_FREELIST_BLOCKS
FROM
  USER_TABLES
WHERE
  TABLE_NAME='T1';

  NUM_ROWS     BLOCKS EMPTY_BLOCKS AVG_ROW_LEN NUM_FREELIST_BLOCKS
---------- ---------- ------------ ----------- -------------------
   1000000       1630            0           4                   0

The average row length increased from 1 to 4 when the second column of the table was set to a value of 1 for all rows in the table – now the NULL values in column 1 require a single byte of storage space.

Feel free to experiment with this example.





Network Monitoring Experimentations 5

27 04 2010

April 27, 2010 (Updated May 13, 2010)

(Back to the Previous Post in the Series) (Forward to the Next Post in the Series)

Previous articles in this series showed a lot of interesting capabilities that Wireshark and similar packet capture utilities offer, such as seeing the behind the scenes SQL statements that do not appear in a 10046 trace when Autotrace is enabled in SQL*Plus.  But there is more that Wireshark offers to assist with analysis of Oracle data transfers across the network.  Today’s article explores some of these additional features while experimenting with different array fetch sizes using Oracle Database 11.2.0.1 with default listener settings on the server side, and Oracle client 11.1.0.7 on the client-side, with an 802.11g wireless network between the two computers (greater network packet latency than a wired connection).

The test table and SQL statement used in this article is similar to those used in this article, which demonstrated that the execution plan on Oracle Database 11.2.0.1 differed from that used on earlier releases, and that difference may affect your ability to reproduce the test results for today’s article if you are using an older release of Oracle Database.

CREATE TABLE T5 (
  C1 VARCHAR2(10),
  C2 VARCHAR2(100),
  PRIMARY KEY (C1));

INSERT INTO T5 NOLOGGING
SELECT
  'A'||TO_CHAR(ROWNUM,'0000000'),
  RPAD('A',100,'A')
FROM
  DUAL
CONNECT BY
  LEVEL<=1000000;

COMMIT;

EXEC DBMS_STATS.GATHER_TABLE_STATS(OWNNAME=>USER,TABNAME=>'T5',CASCADE=>TRUE)

The test script that will be used is as follows, executed after Wireshark packet capturing is enabled on the client computer:

SET AUTOTRACE TRACEONLY STATISTICS

SET ARRAYSIZE 10

SELECT /*+ USE_NL(T51 T52 T53 T54 T55 T56 T57 T58) */
  T51.C1,
  T51.C2,
  T52.C1,
  T52.C2,
  T53.C1,
  T53.C2,
  T54.C1,
  T54.C2,
  T55.C1,
  T55.C2,
  T56.C1,
  T56.C2,
  T57.C1,
  T57.C2,
  T58.C1,
  T58.C2
FROM
  T5 T51,
  T5 T52,
  T5 T53,
  T5 T54,
  T5 T55,
  T5 T56,
  T5 T57,
  T5 T58
WHERE
  T51.C1=T52.C1
  AND T51.C1=T53.C1
  AND T51.C1=T54.C1
  AND T51.C1=T55.C1
  AND T51.C1=T56.C1
  AND T51.C1=T57.C1
  AND T51.C1=T58.C1
  AND T51.C1 BETWEEN 'A 0001000' AND 'A 1000000';

host sleep 5

SET ARRAYSIZE 50

SELECT /*+ USE_NL(T51 T52 T53 T54 T55 T56 T57 T58) */
  T51.C1,
  T51.C2,
  T52.C1,
  T52.C2,
  T53.C1,
  T53.C2,
  T54.C1,
  T54.C2,
  T55.C1,
  T55.C2,
  T56.C1,
  T56.C2,
  T57.C1,
  T57.C2,
  T58.C1,
  T58.C2
FROM
  T5 T51,
  T5 T52,
  T5 T53,
  T5 T54,
  T5 T55,
  T5 T56,
  T5 T57,
  T5 T58
WHERE
  T51.C1=T52.C1
  AND T51.C1=T53.C1
  AND T51.C1=T54.C1
  AND T51.C1=T55.C1
  AND T51.C1=T56.C1
  AND T51.C1=T57.C1
  AND T51.C1=T58.C1
  AND T51.C1 BETWEEN 'A 0001000' AND 'A 1000000';

host sleep 5

SET ARRAYSIZE 100

SELECT /*+ USE_NL(T51 T52 T53 T54 T55 T56 T57 T58) */
  T51.C1,
  T51.C2,
  T52.C1,
  T52.C2,
  T53.C1,
  T53.C2,
  T54.C1,
  T54.C2,
  T55.C1,
  T55.C2,
  T56.C1,
  T56.C2,
  T57.C1,
  T57.C2,
  T58.C1,
  T58.C2
FROM
  T5 T51,
  T5 T52,
  T5 T53,
  T5 T54,
  T5 T55,
  T5 T56,
  T5 T57,
  T5 T58
WHERE
  T51.C1=T52.C1
  AND T51.C1=T53.C1
  AND T51.C1=T54.C1
  AND T51.C1=T55.C1
  AND T51.C1=T56.C1
  AND T51.C1=T57.C1
  AND T51.C1=T58.C1
  AND T51.C1 BETWEEN 'A 0001000' AND 'A 1000000';

host sleep 5

SET ARRAYSIZE 500

SELECT /*+ USE_NL(T51 T52 T53 T54 T55 T56 T57 T58) */
  T51.C1,
  T51.C2,
  T52.C1,
  T52.C2,
  T53.C1,
  T53.C2,
  T54.C1,
  T54.C2,
  T55.C1,
  T55.C2,
  T56.C1,
  T56.C2,
  T57.C1,
  T57.C2,
  T58.C1,
  T58.C2
FROM
  T5 T51,
  T5 T52,
  T5 T53,
  T5 T54,
  T5 T55,
  T5 T56,
  T5 T57,
  T5 T58
WHERE
  T51.C1=T52.C1
  AND T51.C1=T53.C1
  AND T51.C1=T54.C1
  AND T51.C1=T55.C1
  AND T51.C1=T56.C1
  AND T51.C1=T57.C1
  AND T51.C1=T58.C1
  AND T51.C1 BETWEEN 'A 0001000' AND 'A 1000000';

host sleep 5

SET ARRAYSIZE 1000

SELECT /*+ USE_NL(T51 T52 T53 T54 T55 T56 T57 T58) */
  T51.C1,
  T51.C2,
  T52.C1,
  T52.C2,
  T53.C1,
  T53.C2,
  T54.C1,
  T54.C2,
  T55.C1,
  T55.C2,
  T56.C1,
  T56.C2,
  T57.C1,
  T57.C2,
  T58.C1,
  T58.C2
FROM
  T5 T51,
  T5 T52,
  T5 T53,
  T5 T54,
  T5 T55,
  T5 T56,
  T5 T57,
  T5 T58
WHERE
  T51.C1=T52.C1
  AND T51.C1=T53.C1
  AND T51.C1=T54.C1
  AND T51.C1=T55.C1
  AND T51.C1=T56.C1
  AND T51.C1=T57.C1
  AND T51.C1=T58.C1
  AND T51.C1 BETWEEN 'A 0001000' AND 'A 1000000';

host sleep 5

SET ARRAYSIZE 5000

SELECT /*+ USE_NL(T51 T52 T53 T54 T55 T56 T57 T58) */
  T51.C1,
  T51.C2,
  T52.C1,
  T52.C2,
  T53.C1,
  T53.C2,
  T54.C1,
  T54.C2,
  T55.C1,
  T55.C2,
  T56.C1,
  T56.C2,
  T57.C1,
  T57.C2,
  T58.C1,
  T58.C2
FROM
  T5 T51,
  T5 T52,
  T5 T53,
  T5 T54,
  T5 T55,
  T5 T56,
  T5 T57,
  T5 T58
WHERE
  T51.C1=T52.C1
  AND T51.C1=T53.C1
  AND T51.C1=T54.C1
  AND T51.C1=T55.C1
  AND T51.C1=T56.C1
  AND T51.C1=T57.C1
  AND T51.C1=T58.C1
  AND T51.C1 BETWEEN 'A 0001000' AND 'A 1000000';

Windows client computers do not have an operating system sleep command, so if the client is running on Windows, create a file named sleep.vbs in the current folder used by SQL*Plus with the following code:

Const lngSleepSecondsDefault = 600
Dim lngSleepSeconds
Dim objScriptArguments
Dim strArgument

Set objScriptArguments = WScript.Arguments

If objScriptArguments.Count = 0 then
  lngSleepSeconds = lngSleepSecondsDefault
Else
  For Each strArgument in objScriptArguments
    If IsNumeric(strArgument) Then
      lngSleepSeconds = cLng(strArgument)
      Exit For
    End If
  Next
  If lngSleepSeconds <= 0 Then
    lngSleepSeconds = lngSleepSecondsDefault
  End If
End If

WScript.Sleep lngSleepSeconds * 1000

Before enabling the Wireshark capture, execute the test SQL statement a couple of times to limit the potential effects of a cold cache and physical reads unfairly affecting the first execution with the small array fetch size once packet logging is enabled. Start the Wireshark capture on the client, and then execute the above test script in SQL*Plus on the client computer.  The client will fetch approximately 999,001 rows from the database, and will likely result in a Wireshark packet capture totalling about 600MB.  Later processing of the packet capture, as depicted later in this article, will certainly tax the memory limits of 32 bit operating systems, and may result in Wireshark crashing (the latest beta version of Wireshark was used in this test).  Additionally, processing of the resulting packet capture is extremely CPU intensive – you have been warned.

First, we will start the analysis by right-clicking one of the TNS type packets, and select Follow TCP Stream.  The resulting window that is eventually displayed will not be used, we are just using that feature to enter the Filter criteria shown near the top of the Wireshark window with the light green background in the picture below:

As shown above, when a line is checked in the lower pane, such as Time delta from previous captured frame, the status bar at the bottom of the window is updated with a field name, in this case frame.time_delta.  If you manually review the Time column in the Wireshark window you will see that the time delta between packets varies quite a bit.  I wonder if the time delta values vary depending on the array fetch size… we could extract the information and process it a spreadsheet package to determine whether the time deltas change.  More on this later.  The packet frame length for this packet is 704 bytes.

If we scroll down to the bottom of the lower pane, we see that Wireshark has attempted to decode this TNS packet, all except for decrypting the control characters and binary data in the data portion of the packet.

We see that the TNS packet length is 650 of the packet frame’s 704 bytes, and the actual data contained in the packet is 640 of those 650 bytes.  The status bar shows that the field name for the data length is data.len – we will use this information later.  The data section shows that this is the submission of the first SQL statement in our test script.

The following screenshot is showing where the server is returning the data to the client early during the execution of the test script.  In this case, with the array fetch size set to 10, the server had to break the selected data into two network packets, with the first containing bytes 0 through 1459, and the second containing bytes 1460 through 1760 (just 301 bytes in the second packet).

Scrolling down near the end of the packet capture, we see one of the network packets where the array fetch size of 5,000 was in use.  The displayed time delta is 0.000341 seconds, which is very good for a wireless network.

Moving down to the next packet, we find that this packet is 855 bytes in length, but the total TCP length is 8,155 bytes, compared to the value 1,761 that we found when the array fetch size of 10 was in use.

The field name for the reassembled TCP length, as displayed in the status bar, is tcp.reassembled.length – we will use this later.

Now for the exciting part, graphing the result.  If you had to make a choice of which array fetch size to use: 10, 50, 100, 500, 1000, or 5000, which should you use, and why?  From the Statistics menu in Wireshark, select the IO Graphs menu item.  You should see something like this if you set the Tick Interval to 10 seconds and the Pixels per tick to 10.  The Tick Interval value determines how the statistics will be grouped together, in this case it is 10 second intervals.  The Pixels per tick value determines how horizontally spread out, the distance between the data items when displayed on screen.

The first bump width in the values represents the time required to retrieve the data 10 rows at a time.  The second bump width represents the time required to retrieve 50 rows at a time.  The third bump width represents the time required to retrieve 100 rows at a time.  The remaining bump widths show the time required to fetch 500, 1000, and 5000 rows at a time, respectively.  The height of the bumps, in this case, indicates the number of packets transmitted between the server and the client in each of the 10 second time intervals.  When the client retrieved 10 rows at a time, only about 50% of the number of network packets flowed between the server and client as when the client retrieved 50 or 100 rows at a time – this of course increased the time required to transmit all of the requested rows.

By changing Packets/Tick to Bytes/Tick we are able to determine how much data (including overhead) is actually contained in the packets flowing across the network every 10 seconds.  While the bumps in the previous screenshot showed that roughly the same number of packets flowed across the network for the array fetch sizes of 50 and 100, this screenshot shows that the amount of usable data (plus overhead) in the packets was about 20% less – this explains why the bump representing the array fetch size of 50 is about 20% longer than the bump representing the array fetch size of 100.

Interesting, but why were there only about half as many packets transferred every 10 seconds when the array fetch size was set to 10 compared to when it was set to 50?  Did I hear someone say “wait and see”, or was it “latency”?  :-)  If we change the Units field to Advanced we are able to find out what is happening.  For the Filter of Graph 1 I specified tcp.stream eq 1 (the same filter as was entered automatically when we earlier selected to Follow the TCP Stream).  For the Calc entry I selected Max(*) and then in the next field to the right I specified frame.time_delta_displayed – we saw earlier where this field was obtained in the main Wireshark window.  I then set the scale to 100000 so that I was able to see both the peaks and valleys in the graph.  The graph shows that there is a maximum latency between packets of about 50ms when the array fetch size was set to 10, and that maximum latency dropped significantly until the array fetch size increased to 1,000.  With the array fetch size set to 5,000 the maximum latency is nearly identical to that of the maximum latency when the array fetch size was set to 10 – at this point the client is essentially choking on all of the data that it is receiving, it is taking the client roughly 50ms to process the rows and send the next fetch request to the server.

Neat, what else are we able to do?  This time we will turn off the first graph an create two additional graphs.  The first of the additional graphs shows the sum of the sizes of the TNS section of the network packets for each of the 10 second time intervals, while the second of the additional graphs shows the maximum data length in the TNS section – how much actual data is stuffed into the network packets (per the configured Oracle SDU, and may actually be broken into multiple packets).  A logarithmic scale is selected for the data since the sum of the TNS section lengths will be considerably larger than the maximum data length in any given 10 second time interval.  The green line, representing the amount of actual data in the packets, shows that in a best case scenario, when the array fetch size is set to 10 all of the packets are leaving without being full, or more correctly, the SDU size is lower - so, not only are half as many packets transmitted per second, but in a best case each packet also contains less data.  The situation improves a bit when the fetch array size increased to 50, and then stabilized at a higher value when the fetch array size was bumped to 100.

The previous graph is somewhat useful, yet at the same time somewhat useless.  Rather than looking at the maximum of how full the data packets were in each 10 second time interval, it is probably more useful to look at how full the packets were on average.  Well, the following graph does not actually show that – it shows the amount of data Oracle is packaging before transmission, as controlled by the session data unit (SDU) size, which typically has a maximum default value of 8KB.  The following modified version of the previous chart shows how the average SDU size of the packets changed as the array fetch size increased.  The effective average SDU size doubled as the array fetch size increased from 100 to 500 – does that mean that the transfer completed twice as fast?  No, as shown in the previous graphs, but it might have made a greater difference with a gigabit wired network.

Wireshark also provides the option of controlling the graph type.  In the following screenshot I added the tcp.reassembled.length as Graph 4, changed Graph 2 to an Impulse style (vertical line) and changed Graph 3 to FBar style (vertical rectangle).  Notice that the tcp.reassembled.length values are greater when the array fetch size is 100 than when it is at any other value.  I believe that the reason why this is the case is because on average there was a greater percentage of “overhead” bytes in the TNS section of the packets when array fetching 100 rows at a time when compared to array fetching, for example, 500 rows at a time.

With the above in mind, what is the ideal array fetch size for this SQL statement?  Stop playing with your data packets and answer the question.  :-)

——–

Added May 13, 2010:

First 4 packets retrieving rows after the initial single row fetch, fetch array size set to 10, response to 3 fetch calls (click to zoom):

First 4 packets retrieving rows after the initial single row fetch, fetch array size set to 5,000, response to 1 fetch call (click to zoom):





Network Monitoring Experimentations 4

25 04 2010

April 25, 2010

(Back to the Previous Post in the Series) (Forward to the Next Post in the Series)

Previous articles in this series showed a number of interesting troubleshooting techniques that take advantage of the Wireshark packet capture utility.  A recent OTN thread made me wonder if there isn’t a lot more than Wireshark offers, which might be helpful to Oracle DBAs.  To demonstrate, first we need to create a simple test table with 1,000 rows:

CREATE TABLE T10(
  C1 NUMBER,
  C2 VARCHAR2(12),
  C4 CHAR(12),
  C3 DATE);

INSERT INTO
  T10
SELECT
  ROWNUM,
  'A'||TO_CHAR(ROWNUM)||'Z',
  'A'||TO_CHAR(ROWNUM)||'Z',
  SYSDATE+ROWNUM/10
FROM
  DUAL
CONNECT BY
  LEVEL<=1000;

COMMIT;

SET ARRAYSIZE 100

To begin the test, we will enable packet logging in Wireshark, then execute the following in our SQL*Plus session:

ALTER SESSION SET EVENTS '10046 TRACE NAME CONTEXT FOREVER, LEVEL 8';
ALTER SESSION SET TRACEFILE_IDENTIFIER = 'AUTOTRACE_STATISTICS_TRACE';

SET AUTOTRACE TRACEONLY STATISTICS

SELECT
  *
FROM
  T10
ORDER BY
  C1;

DISCONNECT ALL;

For my test execution, the following was displayed in SQL*Plus:

1000 rows selected.

Statistics
---------------------------------------------------
          0  recursive calls
          0  db block gets
          7  consistent gets
          0  physical reads
          0  redo size
      33470  bytes sent via SQL*Net to client
        459  bytes received via SQL*Net from client
         11  SQL*Net roundtrips to/from client
          1  sorts (memory)
          0  sorts (disk)
       1000  rows processed

It might be interesting to determine how SQL*Plus was able to indicate the number of consistent gets, sorts, and various other information.  First, let’s take a look at the raw 10046 trace file that was generated:

EXEC #5:c=0,e=21,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,plh=0,tim=491526459579
WAIT #5: nam='SQL*Net message to client' ela= 1 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=491526460488
WAIT #5: nam='SQL*Net message from client' ela= 3932 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=491526464434
CLOSE #5:c=0,e=3,dep=0,type=1,tim=491526464492
=====================
PARSING IN CURSOR #5 len=40 dep=0 uid=194 oct=3 lid=194 tim=491526464547 hv=3933222116 ad='36cab5360' sqlid='dyk4dprp70d74'
SELECT DECODE('A','A','1','2') FROM DUAL
END OF STMT
PARSE #5:c=0,e=29,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=1388734953,tim=491526464546
EXEC #5:c=0,e=14,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=1388734953,tim=491526464596
WAIT #5: nam='SQL*Net message to client' ela= 1 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=491526464624
FETCH #5:c=0,e=9,p=0,cr=0,cu=0,mis=0,r=1,dep=0,og=1,plh=1388734953,tim=491526464651
STAT #5 id=1 cnt=1 pid=0 pos=1 obj=0 op='FAST DUAL  (cr=0 pr=0 pw=0 time=0 us cost=2 size=0 card=1)'
WAIT #5: nam='SQL*Net message from client' ela= 1641 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=491526466337
CLOSE #5:c=0,e=6,dep=0,type=1,tim=491526466385
=====================
PARSING IN CURSOR #5 len=33 dep=0 uid=194 oct=3 lid=194 tim=491526466449 hv=2185052098 ad='36c33c460' sqlid='bzmk73q13ugy2'
SELECT DISTINCT SID FROM V$MYSTAT
END OF STMT
PARSE #5:c=0,e=27,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=2877173184,tim=491526466448
EXEC #5:c=0,e=35,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=2877173184,tim=491526466521
WAIT #5: nam='SQL*Net message to client' ela= 1 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=491526466548
WAIT #5: nam='asynch descriptor resize' ela= 1 outstanding #aio=0 current aio limit=4294967295 new aio limit=129 obj#=-1 tim=491526467243
FETCH #5:c=0,e=705,p=0,cr=0,cu=0,mis=0,r=1,dep=0,og=1,plh=2877173184,tim=491526467269
STAT #5 id=1 cnt=1 pid=0 pos=1 obj=0 op='HASH UNIQUE (cr=0 pr=0 pw=0 time=0 us cost=1 size=21 card=1)'
STAT #5 id=2 cnt=588 pid=1 pos=1 obj=0 op='FIXED TABLE FULL X$KSUMYSTA (cr=0 pr=0 pw=0 time=821 us cost=0 size=630 card=30)'
STAT #5 id=3 cnt=1 pid=2 pos=1 obj=0 op='FIXED TABLE FULL X$KSUSGIF (cr=0 pr=0 pw=0 time=0 us cost=0 size=4 card=1)'
WAIT #5: nam='SQL*Net message from client' ela= 2708 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=491526470036
CLOSE #5:c=0,e=7,dep=0,type=1,tim=491526470085
*** SESSION ID:(1229.11429) 2010-04-25 10:13:17.869
*** SERVICE NAME:(SYS$USERS) 2010-04-25 10:13:17.869
*** MODULE NAME:(SQL*Plus) 2010-04-25 10:13:17.869
*** ACTION NAME:() 2010-04-25 10:13:17.869

=====================
PARSING IN CURSOR #5 len=298 dep=0 uid=194 oct=3 lid=194 tim=491526480837 hv=3566218912 ad='36cdd1b90' sqlid='f7dctcva90bp0'
SELECT STATISTIC# S, NAME FROM SYS.V_$STATNAME WHERE NAME IN ('recursive calls','db block gets','consistent gets','physical reads','redo size','bytes sent via SQL*Net to client','bytes received via SQL*Net from client','SQL*Net roundtrips to/from client','sorts (memory)','sorts (disk)') ORDER BY S
END OF STMT
PARSE #5:c=0,e=24,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=601351913,tim=491526480836
EXEC #5:c=0,e=16,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=601351913,tim=491526480950
WAIT #5: nam='SQL*Net message to client' ela= 2 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=491526480978
FETCH #5:c=0,e=14,p=0,cr=0,cu=0,mis=0,r=1,dep=0,og=1,plh=601351913,tim=491526481009
WAIT #5: nam='SQL*Net message from client' ela= 1461 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=491526482489
WAIT #5: nam='SQL*Net message to client' ela= 1 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=491526482574
FETCH #5:c=0,e=248,p=0,cr=0,cu=0,mis=0,r=9,dep=0,og=1,plh=601351913,tim=491526482778
STAT #5 id=1 cnt=10 pid=0 pos=1 obj=0 op='FIXED TABLE FULL X$KSUSD (cr=0 pr=0 pw=0 time=0 us cost=0 size=360 card=10)'
WAIT #5: nam='SQL*Net message from client' ela= 4778 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=491526487592
*** SESSION ID:(1229.11429) 2010-04-25 10:13:17.869

CLOSE #5:c=0,e=8,dep=0,type=1,tim=491526491403
=====================
PARSING IN CURSOR #5 len=35 dep=0 uid=194 oct=3 lid=194 tim=491526491485 hv=410341182 ad='36c4497b0' sqlid='1y2frjhc7amty'
SELECT
  *
FROM
  T10
ORDER BY
  C1
END OF STMT
PARSE #5:c=0,e=26,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=4242492972,tim=491526491484
EXEC #5:c=0,e=12,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=4242492972,tim=491526491548
WAIT #5: nam='SQL*Net message to client' ela= 2 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=491526491574
WAIT #5: nam='Disk file operations I/O' ela= 121 FileOperation=2 fileno=8 filetype=2 obj#=-1 tim=491526491726
FETCH #5:c=0,e=446,p=0,cr=7,cu=0,mis=0,r=1,dep=0,og=1,plh=4242492972,tim=491526492037
WAIT #5: nam='SQL*Net message from client' ela= 3403 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=491526495465
WAIT #5: nam='SQL*Net message to client' ela= 1 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=491526495529
FETCH #5:c=0,e=65,p=0,cr=0,cu=0,mis=0,r=100,dep=0,og=1,plh=4242492972,tim=491526495589
WAIT #5: nam='SQL*Net message from client' ela= 3025 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=491526498633
WAIT #5: nam='SQL*Net message to client' ela= 2 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=491526498679
FETCH #5:c=0,e=81,p=0,cr=0,cu=0,mis=0,r=100,dep=0,og=1,plh=4242492972,tim=491526498754
WAIT #5: nam='SQL*Net message from client' ela= 2924 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=491526501694
WAIT #5: nam='SQL*Net message to client' ela= 1 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=491526501739
FETCH #5:c=0,e=82,p=0,cr=0,cu=0,mis=0,r=100,dep=0,og=1,plh=4242492972,tim=491526501815
WAIT #5: nam='SQL*Net message from client' ela= 2873 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=491526504704
WAIT #5: nam='SQL*Net message to client' ela= 1 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=491526504749
FETCH #5:c=0,e=82,p=0,cr=0,cu=0,mis=0,r=100,dep=0,og=1,plh=4242492972,tim=491526504825
WAIT #5: nam='SQL*Net message from client' ela= 2952 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=491526507793
WAIT #5: nam='SQL*Net message to client' ela= 2 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=491526507839
FETCH #5:c=0,e=82,p=0,cr=0,cu=0,mis=0,r=100,dep=0,og=1,plh=4242492972,tim=491526507914
WAIT #5: nam='SQL*Net message from client' ela= 3453 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=491526511383
WAIT #5: nam='SQL*Net message to client' ela= 1 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=491526511433
FETCH #5:c=0,e=107,p=0,cr=0,cu=0,mis=0,r=100,dep=0,og=1,plh=4242492972,tim=491526511536
WAIT #5: nam='SQL*Net message from client' ela= 2857 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=491526514412
WAIT #5: nam='SQL*Net message to client' ela= 1 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=491526514453
FETCH #5:c=0,e=53,p=0,cr=0,cu=0,mis=0,r=100,dep=0,og=1,plh=4242492972,tim=491526514501
WAIT #5: nam='SQL*Net message from client' ela= 2812 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=491526517332
WAIT #5: nam='SQL*Net message to client' ela= 1 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=491526517377
FETCH #5:c=0,e=58,p=0,cr=0,cu=0,mis=0,r=100,dep=0,og=1,plh=4242492972,tim=491526517429
WAIT #5: nam='SQL*Net message from client' ela= 2897 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=491526520366
WAIT #5: nam='SQL*Net message to client' ela= 2 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=491526520412
FETCH #5:c=0,e=58,p=0,cr=0,cu=0,mis=0,r=100,dep=0,og=1,plh=4242492972,tim=491526520463
WAIT #5: nam='SQL*Net message from client' ela= 2849 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=491526523328
WAIT #5: nam='SQL*Net message to client' ela= 1 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=491526523374
FETCH #5:c=0,e=67,p=0,cr=0,cu=0,mis=0,r=99,dep=0,og=1,plh=4242492972,tim=491526523435
STAT #5 id=1 cnt=1000 pid=0 pos=1 obj=0 op='SORT ORDER BY (cr=7 pr=0 pw=0 time=285 us cost=4 size=31000 card=1000)'
STAT #5 id=2 cnt=1000 pid=1 pos=1 obj=82545 op='TABLE ACCESS FULL T10 (cr=7 pr=0 pw=0 time=249 us cost=3 size=31000 card=1000)'
WAIT #5: nam='SQL*Net message from client' ela= 4630 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=491526528115
*** SESSION ID:(1229.11429) 2010-04-25 10:13:17.947

XCTEND rlbk=0, rd_only=1, tim=491526563841
=====================
PARSING IN CURSOR #6 len=447 dep=1 uid=0 oct=2 lid=0 tim=491526563926 hv=1097020010 ad='36cc895f8' sqlid='f711myt0q6cma'
insert into sys.aud$( sessionid,entryid,statement,ntimestamp#, userid,userhost,terminal,action#,returncode, logoff$lread,logoff$pread,logoff$lwrite,logoff$dead, logoff$time,comment$text,spare1,clientid,sessioncpu,proxy$sid,user$guid, instance#,process#,auditid,dbid) values(:1,:2,:3,SYS_EXTRACT_UTC(SYSTIMESTAMP),     :4,:5,:6,:7,:8,     :9,:10,:11,:12,     cast(SYS_EXTRACT_UTC(systimestamp) as date),:13,:14,:15,:16,:17,:18,     :19,:20,:21,:22)
END OF STMT
PARSE #6:c=0,e=18,p=0,cr=0,cu=0,mis=0,r=0,dep=1,og=4,plh=0,tim=491526563926
EXEC #6:c=0,e=67,p=0,cr=1,cu=2,mis=0,r=1,dep=1,og=4,plh=0,tim=491526564082
STAT #6 id=1 cnt=0 pid=0 pos=1 obj=0 op='LOAD TABLE CONVENTIONAL  (cr=1 pr=0 pw=0 time=0 us)'
CLOSE #6:c=0,e=4,dep=1,type=1,tim=491526564123
WAIT #0: nam='log file sync' ela= 33 buffer#=3872 sync scn=1305056145 p3=0 obj#=-1 tim=491526564191
CLOSE #2:c=0,e=6,dep=0,type=0,tim=491526564244
CLOSE #5:c=0,e=3,dep=0,type=0,tim=491526564260
CLOSE #4:c=0,e=4,dep=0,type=0,tim=491526564271
CLOSE #3:c=0,e=9,dep=0,type=0,tim=491526564287
CLOSE #1:c=0,e=3,dep=0,type=0,tim=491526564298

With the help of these articles, 10046 Extended SQL Trace Interpretation and 10046 Extended SQL Trace Interpretation 2, we are able to decode most of the above trace file output that was generated by Oracle Database 11.2.0.1.  For example, we see these helpful SQL statement before the SQL statement that we executed:

SELECT DECODE('A','A','1','2') FROM DUAL

SELECT DISTINCT SID FROM V$MYSTAT

SELECT STATISTIC# S, NAME FROM SYS.V_$STATNAME WHERE NAME IN
  ('recursive calls','db block gets','consistent gets','physical reads','redo size',
  'bytes sent via SQL*Net to client','bytes received via SQL*Net from client',
  'SQL*Net roundtrips to/from client','sorts (memory)','sorts (disk)') ORDER BY S

After the SQL statement finished executing the execution plan for the SQL statement was written to the trace file, a COMMIT was executed that did not affect any data, and then this SQL statement appeared:

insert into sys.aud$( sessionid,entryid,statement,ntimestamp#, userid,userhost,
terminal,action#,returncode, logoff$lread,logoff$pread,logoff$lwrite,logoff$dead,
logoff$time,comment$text,spare1,clientid,sessioncpu,proxy$sid,user$guid, instance#,
process#,auditid,dbid) values(:1,:2,:3,SYS_EXTRACT_UTC(SYSTIMESTAMP),
:4,:5,:6,:7,:8,     :9,:10,:11,:12,     cast(SYS_EXTRACT_UTC(systimestamp) as date),
:13,:14,:15,:16,:17,:18,     :19,:20,:21,:22)

The 10046 trace file successfully hid how SQL*Plus was able to determine the number of consistent gets, sorts, and various other information for the SQL statement.  It must be magic?  Or maybe something else is happening… such as the creation of a secondary session to retrieve the statistics.  Maybe Wireshark is able to help answer the question (note that some information in the Wireshark output is obscured – possibly you would not want someone seeing that information, or for that matter any of this “clear text” information, which would be clearly visible to all computers on a wireless network, as well as on networks that utilize hubs rather than switches, if the Oracle Advanced Security Option is not purchased and enabled).

There were two unrelated packets at the start of the Wireshark capture, so I right-clicked the first packet of interest and set it to be the Time Reference packet.  The data section of the first packet of interest shows the ALTER SESSION command that enabled the 10046 trace:

 —

A couple of packets later we see the first SQL statement that was not explicitly executed in our test script:

Finally, packet 23 shows the SQL statement that we executed in our test script:

Packet 24 shows the retrieval of the first row from the database, on the lines between bytes 0150 (336 in decimal) and 0170 (368 in decimal).  Packet 25 contains the request for the next set of 100 rows, and packet 26 begins the transmission of those 100 rows.

Packet 75 shows another SQL statement that was not explicitly included in the test script – this SQL statement also was not included in the 10046 trace file.  The SQL statement retrieves the ending statistics for the session, allowing SQL*Plus to display the output of the delta values for those statistics.

One of the problems when reviewing the packet trace output, of course, is that it is difficult to see the full picture of what is happening.  Wireshark allows right-clicking one of the packets in the conversation and then offers the option of Follow TCP Stream.  For example, this is the Follow TCP Stream output at the start of the test script execution, with the red colored text showing the client-side transmitted data and the blue colored text showing the server transmitted data.

Scrolling down a little further we see the SQL statement used to determine the STATISTIC# values, followed by the SQL statement that was executed in the secondary session which determined the current statistic values for the session of interest.

At the end of the transfer we see the last row sent by the database server containing the row with a column value of A1000Z, immediately followed by the SQL statement that was executed in the secondary session which determined the ending statistic values for the session of interest:

There were a lot of . (period) characters in the Raw output, designating unprintable characters.  Might some of these unprintable characters be the missing number column, the missing date column, or various control characters?  Switching to the Hex Dump view might be helpful.  In the below picture we see the SQL statement from our script, followed by a single row returned from the database, followed by another fetch call from the client, followed by the next 100 rows from the database. 

How do I know that the client is retrieving the next 100 rows?  Take a close look at the number displayed to the right of 00000DAF, in position 00000DB0.  The hexidecimal number 64 (100 in decimal) appears in that position.  How do I know that this is the number of requested rows?  A simple test script will confirm that the number of requested rows appears in that byte position:

SET AUTOTRACE TRACEONLY STATISTICS

SET ARRAYSIZE 10

SELECT
  *
FROM
  T10
ORDER BY
  C1;

SET ARRAYSIZE 50

SELECT
  *
FROM
  T10
ORDER BY
  C1;

SET ARRAYSIZE 100

SELECT
  *
FROM
  T10
ORDER BY
  C1;

SET ARRAYSIZE 500

SELECT
  *
FROM
  T10
ORDER BY
  C1;

I saved the Hex Dump output from Wireshark’s follow stream to a file: NetworkMonitoringExperimentations4-FetchSize.txt (save with a .txt extension).  Feel free to confirm that the array fetch size is provided in that byte location.

ARRAYSIZE=10
00000324  00 15 00 00 06 00 00 00  00 00 03 05 3b 05 00 00 ........ ....;...
00000334  00 0a 00 00 00                                   .....
...
00000339  00 15 00 00 06 00 00 00  00 00 03 05 3c 05 00 00 ........ ....<...
00000349  00 0a 00 00 00                                   .....
...
...
ARRAYSIZE=50
00000F13  00 15 00 00 06 00 00 00  00 00 03 05 aa 05 00 00 ........ ........
00000F23  00 32 00 00 00                                   .2...
...
00000F28  00 15 00 00 06 00 00 00  00 00 03 05 ab 05 00 00 ........ ........
00000F38  00 32 00 00 00                                   .2...
...
...
ARRAYSIZE=100
00001472  00 15 00 00 06 00 00 00  00 00 03 05 c9 05 00 00 ........ ........
00001482  00 64 00 00 00                                   .d...
...
00001487  00 15 00 00 06 00 00 00  00 00 03 05 ca 05 00 00 ........ ........
00001497  00 64 00 00 00                                   .d...
...
...
ARRAYSIZE=500
000018FF  00 15 00 00 06 00 00 00  00 00 03 05 de 05 00 00 ........ ........
0000190F  00 f4 01 00 00                                   .....
...
00001914  00 15 00 00 06 00 00 00  00 00 03 05 df 05 00 00 ........ ........
00001924  00 f4 01 00 00                                   .....

The byte containing the array size indicator seems to be incorrect when the fetch array size is set to 500 – F4 is equivalent to the decimal number 244.  True, but F401, or with the high byte first, 01F4 is equivalent to the decimal number 500.

As a late edition to this blog article, I submitted the same SQL statement using a client that is able to retrieve the full fetch array size of 100 in the first fetch call.  Below is the packet capture for that execution – compare the packet capture with the last of the above pictures to see if you are able to determine where SQL*Plus specified that the array fetch size for the first fetch should be only 1, rather than the user specified 100.

A search through YouTube locates a number of helpful Wireshark videos, including this one that shows how to use the Follow Stream feature.

So, the question remains, how do we decode the rest of the conversation between the client and server?  For instance, what happened to the number and date column values in the packet capture?  Does this OTN tread provide a clue?





True or False – Direct Path Reads

21 04 2010

 April 21, 2010

(Back to the Previous Post in the Series) (Forward to the Next Post in the Series)

Time for another true or false pop quiz.  Based on the number of views the previous true or false quizzes have experienced, this is a popular series.  However, the questions might be a little too hard to answer correctly - just what is correct is not always easy to determine?  Today’s quiz is on the topic of direct path reads, sparked by one of the test cases that we set up for the Expert Oracle Practices book.

Articles:

  1. http://www.dba-oracle.com/t_direct_path_read_waits.htm (dated June 5, 2009)
  2. http://oracledoug.com/serendipity/index.php?/archives/774-Direct-Path-Reads.html (dated May 22, 2006)
  3. http://oracledoug.com/serendipity/index.php?/archives/1321-11g-and-direct-path-reads.html (dated September 24, 2007)
  4. http://dioncho.wordpress.com/2009/07/21/disabling-direct-path-read-for-the-serial-full-table-scan-11g/ (dated July 21, 2009)
  5. http://antognini.ch/2009/07/impact-of-direct-reads-on-delayed-block-cleanouts/ (dated July 23, 2009)
  6. http://books.google.com/books?id=14OmJzfCfXMC&pg=PA121#v=onepage&q&f=false (dated 2004)

Answering the true or false questions probably requires examining the publication date of the article, if a specific Oracle release is not indicated in the article.  I have had a little bit of difficulty finding the exact (or even approximate) release dates of Oracle’s Database products in the past, so I performed a couple of searches and posted the results below.  The release dates listed below are from the following articles:
http://www.oracle.com/support/library/brochure/lifetime-support-technology.pdf
Metalink Doc ID 742060.1
http://www.orafaq.com/wiki/Oracle_8
http://www.orafaq.com/wiki/Oracle_8i

8         June 1997
8.1.5     February 1999
8.1.7     September 2000
9.0.1     June 2001
9.2.0.1   July 2002
10.1.0.1  January 2004
10.1.0.5  January 2006
10.2.0.1  July 2005
10.2.0.4  February 2008
11.1.0.6  August 2007
11.1.0.7  September 2008
11.2.0.1  September 2009

When answering the quiz, please provide justification for your answers – answer the question “why is the question true or false”.

The quiz:

1.  Direct path read waits will only appear when parallel query is used, for example, a full table scan executed in parallel. 

2.  Parallel query is enabled at the session and instance level by setting a table’s parallel degree to 32.

3.  Setting a parallel degree for a table or index forces the cost-based optimizer to calculate the cost of a full scan of the table (or index) with a lower value than the cost of the corresponding index’s range scan access path.

4.  Physical block reads performed during parallel query operations are always brought directly into the program global area (PGA), completely avoiding the buffer cache. *

5.  The hidden parameter _SERIAL_DIRECT_READ should be set to FALSE to prevent problems caused by excessive direct path reads.

6.  The hidden parameter _SMALL_TABLE_THRESHOLD affects Oracle’s decision to perform direct path reads.





True or False – Buffer Busy Waits

19 04 2010

April 19, 2010

(Back to the Previous Post in the Series) (Forward to the Next Post in the Series)

An earlier blog article provided a couple of links that I found to be helpful when encountering buffer busy waits.  There are certainly other helpful web pages within reach of the nearest search engine.  I thought for today’s True or False quiz I would reference some of the pages found by the Google search engine.

Please read the following articles, and try to answer the questions that follow with either a True or False answer, followed by justification for your answer:

  1. http://dba-oracle.com/art_builder_bbw.htm (updated February 2008)
  2. rafioracledba.blogspot.com/2010/03/buffer-busy-waits-and-remedies.html
  3. yanggq.itpub.net/post/1594/111558
  4. remote-dba.net/oracle_10g_tuning/t_buffer_busy_waits.htm
  5. http://www.jlcomp.demon.co.uk/bbw.html
  6. http://books.google.com/books?id=bxHDtttb0ZAC&pg=PA284
  7. http://books.google.com/books?id=tdRes4IdLiIC&pg=PA1176
  8. http://books.google.com/books?id=TmPoYfpeJAUC&pg=PA434
  9. http://books.google.com/books?id=b3DIkYO2gBQC&pg=PA539

The quiz:

1.  Referencing the Top 5 Timed Events at the top of article #1, a Statspack report that indicates 2,154 waits for the CPU is a possible sign of a problem with buffer busy waits.

2. Referencing the Top 5 Timed Events at the top of article #1, a Statspack report that indicates 2,598 waits on the ‘db file sequential read’ wait event and 25,519 waits on the ‘db file scattered read’ wait event provides significant evidence of buffer busy waits when 7,146 seconds and 3,246 seconds, respectively, were reported for those wait events.

3.  I/O bound Oracle database instances frequently experience buffer busy waits.

4.  ‘db file sequential read’ waits and ‘db file scattered read’ waits appearing in the top 5 list in a Statspack report indicate that the database instance is I/O bound.

5.  Eliminating buffer busy waits in the database instance will also reduce the I/O load in the instance.

6.  To reduce the frequency of buffer busy waits, missing indexes should be created, the freelists for the affected tables and indexes should be increased, and then those objects should be moved to an ASSM tablespace.

7.  Referencing article #1, assume that you query V$SYSTEM_EVENT and find that there were a total of 636,528 buffer busy waits.  The reported number of waits on this event indicate that there were 636,528 distinct waits for a block, and this number of buffer busy waits is an indication of a severe problem.

8.  As of February 2008, a block that is in the process of being read into the buffer cache will trigger a buffer busy wait in another session if that other session requires access to that same block.

9.  As of February 2008, the P3 column of V$SESSION_WAIT indicates the reason code for a buffer busy wait, with a value of 0 indicating that a block is in the process of being read into the buffer cache.

10. Freelist groups should be used to reduce segment header contention.

Tip: Think carefully about the questions – some of the questions might not have obvious answers.





Buffer Busy Waits – Reason Codes and Block Classes

16 04 2010

April 16, 2010

A couple of years ago the following question was asked in an OTN forum thread:

Does anyone know where I can find the reason codes for all the different wait events?

Sometimes questions need a but more detail to avoid confusion, where the correct answer is given to the wrong question.  The original poster was actually asking about the meaning of the P3 parameter of a ‘direct path write‘ wait event, while the phrase “reason codes” seems to typically imply ‘buffer busy waits’ wait events.  The thread eventually transitioned to a brief discussion of the P3 parameter of buffer busy waits.

For Oracle Database 10g R1 and above, the P3 parameter describes the block class, the type of block, involved in the buffer busy wait (source http://www.juliandyke.com/Internals/BlockClasses.html – see the links at the bottom of this article for the meaning of the P3 parameter prior to Oracle Database prior to 10g R1):

1  Data block
2  Sort block
3  Save undo block
4  Segment header
5  Save undo header
6  Free List
7  Extent map
8  1st level bitmap block
9  2nd level bitmap block
10 3rd level bitmap block
11 Bitmap block
12 Bitmap index block
13 File header block
14 Unused
15 System undo block
16 System undo block
17 Undo header
18 Undo block

For block class values above 18, the following calculation may be used, replacing n with the identified block class:

SELECT
  DECODE(MOD(n - 16,2),1,'Undo Header for Undo Segment ','Undo Block for Undo Segment ')||TO_CHAR(FLOOR((n - 17) / 2) + 1) DESCRIPTION
FROM
  DUAL;

For example, if the following appeared in a 10046 trace file (10.1 or above, in this case):

WAIT #12: nam='buffer busy waits' ela= 133261 file#=7 block#=2 class#=13 obj#=0 tim=14319369615

The P3 parameter is identified as class#, with a value of 13.  Based on the above list, the buffer busy wait is on the file header block of absolute file number 7.

If the following appeared in a 10046 trace file:

WAIT #24: nam='buffer busy waits' ela= 2636 file#=7 block#=137 class#=55 obj#=0 tim=82961305208

The output of the SQL statement calculation, after plugging in 55 for the value of n, is:

DESCRIPTION
-------------------------------
Undo Header for Undo Segment 20

The above indicates that the buffer busy wait is for the undo header of undo segment 20.  What should we do about buffer busy waits for the undo header, or for that matter any other block class?  The Oracle documentation (under the heading 10.3.1 buffer busy waits) offers suggestions for several of the block classes.  Maybe the next step in this case would be to start monitoring V$ROLLSTAT if automatic undo management is not in use:

SELECT
  *
FROM
  V$ROLLSTAT
WHERE
  USN=20;

Other Resources:
http://db-optimizer.blogspot.com/2010/01/oracle-wait-buffer-busy-wait.html
http://perfvision.com/papers/06_buffer_cache.ppt
http://perfvision.com/papers/Unit1_Intro_to_Waits.ppt





A Simple Request or a Performance Nightmare – Painted into a Corner by the ERP System

13 04 2010

April 13, 2010

Recently, a simple request came in from an ERP mailing list.  The author wanted to modify a report used by the purchasing module of the ERP program to show additional information on the report.  The purchasing module retrieves the data from the database, manipulates the data, and then pushes the manipulated data to a reporting package.  Wisely, the ERP developer allowed end users to add “extended queries” to bring in additional information from the database to be displayed on the report – all that the end user needs to do is to select from a list of variables provided by the ERP system to link to the database tables, and the ERP system will automatically pass the request to the database using bind variables.  Simple, right?

The table definitions look like this (primary key columns denoted by *):

DESC PURCHASE_ORDER
Name                Null?    Type
------------------- -------- ------------
ID                  NOT NULL VARCHAR2(15)  *
VENDOR_ID           NOT NULL VARCHAR2(15)
CONTACT_FIRST_NAME           VARCHAR2(30)
CONTACT_LAST_NAME            VARCHAR2(30)
CONTACT_INITIAL              VARCHAR2(2)
...

DESC PURC_ORDER_LINE
Name                Null?    Type
------------------- -------- ------------
PURC_ORDER_ID       NOT NULL VARCHAR2(15)  *
LINE_NO             NOT NULL NUMBER        *
PART_ID                      VARCHAR2(30)
VENDOR_PART_ID               VARCHAR2(30)
SERVICE_ID                   VARCHAR2(15)
USER_ORDER_QTY      NOT NULL NUMBER(14,4)
ORDER_QTY           NOT NULL NUMBER(14,4)
...

DESC PURC_LINE_DEL
Name                Null?    Type
------------------- -------- ------------
PURC_ORDER_ID       NOT NULL VARCHAR2(15)  *
PURC_ORDER_LINE_NO  NOT NULL NUMBER        *
DEL_SCHED_LINE_NO   NOT NULL NUMBER        *
DESIRED_RECV_DATE            DATE
ACTUAL_RECV_DATE             DATE
USER_ORDER_QTY      NOT NULL NUMBER(14,4)
RECEIVED_QTY                 NUMBER(14,4)
...

DESC PART
Name                Null?    Type
------------------- -------- ------------
ID                  NOT NULL VARCHAR2(30)  *
DESCRIPTION                  VARCHAR2(40)
STOCK_UM            NOT NULL VARCHAR2(15)
PLANNING_LEADTIME   NOT NULL NUMBER
ORDER_POLICY        NOT NULL CHAR(1)
ORDER_POINT                  NUMBER(14,4)
...

The PURCHASE_ORDER table contains the header information for the order, the PURC_ORDER_LINE table contains the line level detail for the order, and the PURC_LINE_DEL table contains the dates on which the line level detail should be provided to the company and the requested quantities for each of the dates.  While the delivery schedule’s date and order quantities already appear on the purchase order report, the previously received quantity and the delivery schedule line number need to be included on the report, along with a bit of other information.  The problem?  The ERP system does not provide a variable to target a specific delivery schedule line, but we do have the PURC_ORDER_ID (PO_ID variable), PURC_ORDER_LINE_NO (LN_LINE_NO), DESIRED_RECV_DATE (LN_DEL_SCHED_DATE), and USER_ORDER_QTY (LN_DEL_SCHED_QTY), so the first thought is to construct an extended query like this (line breaks are not permitted in the extended query, so this might be hard to read):

SELECT POL.PRODUCT_CODE , PO.STATUS , PLD.RECEIVED_QTY , PLD.DEL_SCHED_LINE_NO FROM PART P , PURCHASE_ORDER PO , PURC_ORDER_LINE POL , PURC_LINE_DEL PLD WHERE PO.ID = :pO_ID AND PO.ID=POL.PURC_ORDER_ID AND POL.LINE_NO = :LN_LINE_NO AND POL.PART_ID = P.ID(+) AND POL.PURC_ORDER_ID=PLD.PURC_ORDER_ID(+) AND POL.LINE_NO = PLD.PURC_ORDER_LINE_NO(+) AND PLD.DESIRED_RECV_DATE(+) = :LN_DEL_SCHED_DATE AND PLD.USER_ORDER_QTY(+) = :LN_DEL_SCHED_QTY

On trying the purchase order report with the extended query we are greeted with an invalid number error thrown by Oracle.  Invalid number?  Here is what a 10046 trace at level 4 showed:

BINDS #30:
kkscoacd
 Bind#0
  oacdty=96 mxl=32(06) mxlc=00 mal=00 scl=00 pre=00
  oacflg=01 fl2=1000000 frm=01 csi=178 siz=320 off=0
  kxsbbbfp=21c00ac8  bln=32  avl=06  flg=05
  value="144038"
 Bind#1
  oacdty=01 mxl=32(01) mxlc=00 mal=00 scl=00 pre=00
  oacflg=21 fl2=1000000 frm=01 csi=178 siz=0 off=32
  kxsbbbfp=21c00ae8  bln=32  avl=01  flg=01
  value="1"
 Bind#2
  oacdty=96 mxl=128(85) mxlc=00 mal=00 scl=00 pre=00
  oacflg=01 fl2=1000000 frm=01 csi=178 siz=0 off=64
  kxsbbbfp=21c00b08  bln=128  avl=85  flg=01
  value="2/1/2010
2/1/2010
3/22/2010
4/13/2010
4/16/2010
5/14/2010
6/11/2010
7/9/2010
"
 Bind#3
  oacdty=96 mxl=128(49) mxlc=00 mal=00 scl=00 pre=00
  oacflg=01 fl2=1000000 frm=01 csi=178 siz=0 off=192
  kxsbbbfp=21c00b88  bln=128  avl=49  flg=01
  value="8.00
8.00
8.00
16.00
0.00
8.00
8.00
8.00
"

Line 1 of this purchase order has 8 delivery schedule lines, and in this silly situation the extended query is executed only at the PURC_ORDER_LINE level, and not at the delivery schedule level – all of the delivery schedule information is passed into the report with the multiple lines in a single field, with CRLF characters separating the values in each of the delivery schedule lines.  OK, that was unexpected.  Now what, do we give up?  No, we use a little creativity to format the data in the required format, with all of the delivery schedule rows rolled in a single row:

SELECT
  P.PURC_ORDER_ID,
  P.PURC_ORDER_LINE_NO,
  MAX(REPLACE(SUBSTR(SYS_CONNECT_BY_PATH(P.DEL_SCHED_LINE_NO,', '),3),', ',CHR(13)||CHR(10))) DEL_SCHED_LINE_NO,
  MAX(REPLACE(SUBSTR(SYS_CONNECT_BY_PATH(P.RECEIVED_QTY,', '),3),', ',CHR(13)||CHR(10))) RECEIVED_QTY
FROM
  (SELECT
    PLD.PURC_ORDER_ID,
    PLD.PURC_ORDER_LINE_NO,
    PLD.DEL_SCHED_LINE_NO,
    PLD.RECEIVED_QTY,
    ROW_NUMBER() OVER (PARTITION BY PLD.PURC_ORDER_ID, PLD.PURC_ORDER_LINE_NO ORDER BY PLD.DEL_SCHED_LINE_NO) RN
  FROM
    PURC_LINE_DEL PLD
  WHERE
    PLD.PURC_ORDER_ID='144038'
    AND PLD.PURC_ORDER_LINE_NO=1) P
CONNECT BY PRIOR
  RN=RN-1
START WITH
  RN=1
GROUP BY
  P.PURC_ORDER_ID,
  P.PURC_ORDER_LINE_NO;

PURC_ORDER_ID   PURC_ORDER_LINE_NO DEL_SCHED_LINE_ RECEIVED_QTY
--------------- ------------------ --------------- ------------
144038                           1 1               8
                                   2               8
                                   3               8
                                   4               16
                                   5               0
                                   6               0
                                   7               0
                                   8               0

Easy, right?  The execution plan of the above looks like this:

---------------------------------------------------------------------------------------------------
| Id  | Operation                         | Name          | Rows  | Bytes | Cost (%CPU)| Time     |
---------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT                  |               |     1 |    51 |     4   (0)| 00:00:01 |
|   1 |  SORT GROUP BY                    |               |     1 |    51 |     4   (0)| 00:00:01 |
|*  2 |   CONNECT BY WITH FILTERING       |               |       |       |            |          |
|*  3 |    FILTER                         |               |       |       |            |          |
|   4 |     COUNT                         |               |       |       |            |          |
|   5 |      VIEW                         |               |    12 |   612 |     4   (0)| 00:00:01 |
|   6 |       WINDOW BUFFER               |               |    12 |   228 |     4   (0)| 00:00:01 |
|   7 |        TABLE ACCESS BY INDEX ROWID| PURC_LINE_DEL |    12 |   228 |     4   (0)| 00:00:01 |
|*  8 |         INDEX RANGE SCAN          | SYS_C005716   |    12 |       |     2   (0)| 00:00:01 |
|*  9 |    HASH JOIN                      |               |       |       |            |          |
|  10 |     CONNECT BY PUMP               |               |       |       |            |          |
|  11 |     COUNT                         |               |       |       |            |          |
|  12 |      VIEW                         |               |    12 |   612 |     4   (0)| 00:00:01 |
|  13 |       WINDOW BUFFER               |               |    12 |   228 |     4   (0)| 00:00:01 |
|  14 |        TABLE ACCESS BY INDEX ROWID| PURC_LINE_DEL |    12 |   228 |     4   (0)| 00:00:01 |
|* 15 |         INDEX RANGE SCAN          | SYS_C005716   |    12 |       |     2   (0)| 00:00:01 |
|  16 |    COUNT                          |               |       |       |            |          |
|  17 |     VIEW                          |               |    12 |   612 |     4   (0)| 00:00:01 |
|  18 |      WINDOW BUFFER                |               |    12 |   228 |     4   (0)| 00:00:01 |
|  19 |       TABLE ACCESS BY INDEX ROWID | PURC_LINE_DEL |    12 |   228 |     4   (0)| 00:00:01 |
|* 20 |        INDEX RANGE SCAN           | SYS_C005716   |    12 |       |     2   (0)| 00:00:01 |
---------------------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------
   2 - access("RN"-1=PRIOR "RN")
   3 - filter("RN"=1)
   8 - access("PLD"."PURC_ORDER_ID"='144038' AND "PLD"."PURC_ORDER_LINE_NO"=1)
       filter("PLD"."PURC_ORDER_ID"='144038' AND "PLD"."PURC_ORDER_LINE_NO"=1)
   9 - access("RN"-1=PRIOR "RN")
  15 - access("PLD"."PURC_ORDER_ID"='144038' AND "PLD"."PURC_ORDER_LINE_NO"=1)
       filter("PLD"."PURC_ORDER_ID"='144038' AND "PLD"."PURC_ORDER_LINE_NO"=1)
  20 - access("PLD"."PURC_ORDER_ID"='144038' AND "PLD"."PURC_ORDER_LINE_NO"=1)
       filter("PLD"."PURC_ORDER_ID"='144038' AND "PLD"."PURC_ORDER_LINE_NO"=1)

The above is fairly efficient, using the primary key index on the table.  We will just slide the above into an inline view in the report’s extended query (replacing the hardcoded literals with variables).  The following appears when trying to display the report:

Missing expression… :-(  how about what happened to the rest of the SQL statement?  Painted into a corner, again.  Now what, do we give up?

OK, no problem, just define a static view rather than wrapping our SQL statement into an inline view.  So, in testing it would look like this (the WHERE clause will be removed when it is created as a static view since the WHERE clause will be provided by the ERP package’s extended query):

SELECT
  P.PURC_ORDER_ID,   P.PURC_ORDER_LINE_NO,   MAX(REPLACE(SUBSTR(SYS_CONNECT_BY_PATH(P.DEL_SCHED_LINE_NO,', '),3),', ',CHR(13)||CHR(10))) DEL_SCHED_LINE_NO,   MAX(REPLACE(SUBSTR(SYS_CONNECT_BY_PATH(P.RECEIVED_QTY,', '),3),', ',CHR(13)||CHR(10))) RECEIVED_QTY FROM   (SELECT     PLD.PURC_ORDER_ID,     PLD.PURC_ORDER_LINE_NO,     PLD.DEL_SCHED_LINE_NO,     PLD.RECEIVED_QTY,     ROW_NUMBER() OVER (PARTITION BY PLD.PURC_ORDER_ID, PLD.PURC_ORDER_LINE_NO ORDER BY PLD.DEL_SCHED_LINE_NO) RN   FROM     PURC_LINE_DEL PLD) P WHERE   P.PURC_ORDER_ID='144038'   AND P.PURC_ORDER_LINE_NO=1 CONNECT BY PRIOR   P.RN=P.RN-1 START WITH   P.RN=1 GROUP BY   P.PURC_ORDER_ID,   P.PURC_ORDER_LINE_NO;

The execution plan for the above looks like this:

-----------------------------------------------------------------------------------------------------
| Id  | Operation                   | Name          | Rows  | Bytes |TempSpc| Cost (%CPU)| Time     |
-----------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT            |               | 49018 |  2441K|       |   273   (4)| 00:00:02 |
|   1 |  SORT GROUP BY              |               | 49018 |  2441K|       |   273   (4)| 00:00:02 |
|*  2 |   FILTER                    |               |       |       |       |            |          |
|*  3 |    CONNECT BY WITH FILTERING|               |       |       |       |            |          |
|*  4 |     FILTER                  |               |       |       |       |            |          |
|   5 |      COUNT                  |               |       |       |       |            |          |
|   6 |       VIEW                  |               | 49018 |  2441K|       |   273   (4)| 00:00:02 |
|   7 |        WINDOW SORT          |               | 49018 |   909K|  3096K|   273   (4)| 00:00:02 |
|   8 |         TABLE ACCESS FULL   | PURC_LINE_DEL | 49018 |   909K|       |    24   (5)| 00:00:01 |
|*  9 |     HASH JOIN               |               |       |       |       |            |          |
|  10 |      CONNECT BY PUMP        |               |       |       |       |            |          |
|  11 |      COUNT                  |               |       |       |       |            |          |
|  12 |       VIEW                  |               | 49018 |  2441K|       |   273   (4)| 00:00:02 |
|  13 |        WINDOW SORT          |               | 49018 |   909K|  3096K|   273   (4)| 00:00:02 |
|  14 |         TABLE ACCESS FULL   | PURC_LINE_DEL | 49018 |   909K|       |    24   (5)| 00:00:01 |
|  15 |     COUNT                   |               |       |       |       |            |          |
|  16 |      VIEW                   |               | 49018 |  2441K|       |   273   (4)| 00:00:02 |
|  17 |       WINDOW SORT           |               | 49018 |   909K|  3096K|   273   (4)| 00:00:02 |
|  18 |        TABLE ACCESS FULL    | PURC_LINE_DEL | 49018 |   909K|       |    24   (5)| 00:00:01 |
-----------------------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------
   2 - filter("P"."PURC_ORDER_ID"='144038' AND "P"."PURC_ORDER_LINE_NO"=1)
   3 - access("P"."RN"-1=PRIOR "P"."RN")
   4 - filter("P"."RN"=1)
   9 - access("P"."RN"-1=PRIOR "P"."RN")

The predicted time for execution is 2 seconds, and if there are 10 order lines ~~~ 2*10 = 20 seconds for the report to display.  The end user will complain, but let’s test just in case the predicted time is incorrect.  Executing the query…  Returning in an hour…  Why is this SQL statement still running?  Notice that the predicate information in the plan, unlike for the plan of the first SQL statement, does not include access(“PLD”.”PURC_ORDER_ID”=’144038′ AND “PLD”.”PURC_ORDER_LINE_NO”=1) on any of the lines – that predicate information was not pushed into the inline view, and providing a hint to push the predicates into the inline view does not change the execution plan.  The end user definitely will complain if it takes 10+ hours to print one report with the previously received quantities.  Painted into a corner, again.  Now what, do we give up?

If only we could somehow push at least the PURC_ORDER_ID further into the view.  Any ideas?

One possible solution is to create another table in the database, something like this:

CREATE TABLE CURRENT_PO_USER(
  USERNAME VARCHAR2(30) DEFAULT USER,
  PURC_ORDER_ID VARCHAR2(15),
  PRIMARY KEY(USERNAME));

GRANT ALL ON CURRENT_PO_USER TO PUBLIC;

We could then (somehow) do this before displaying the purchase order report:

DELETE FROM CURRENT_PO_USER WHERE USERNAME=USER;

INSERT INTO CURRENT_PO_USER(PURC_ORDER_ID) VALUES ('144038');

COMMIT;

Our test query then looks like this:

SELECT
  P.PURC_ORDER_ID,
  P.PURC_ORDER_LINE_NO,
  MAX(REPLACE(SUBSTR(SYS_CONNECT_BY_PATH(P.DEL_SCHED_LINE_NO,', '),3),', ',CHR(13)||CHR(10))) DEL_SCHED_LINE_NO,
  MAX(REPLACE(SUBSTR(SYS_CONNECT_BY_PATH(P.RECEIVED_QTY,', '),3),', ',CHR(13)||CHR(10))) RECEIVED_QTY
FROM
  (SELECT /*+ ORDERED */
    PLD.PURC_ORDER_ID,
    PLD.PURC_ORDER_LINE_NO,
    PLD.DEL_SCHED_LINE_NO,
    PLD.RECEIVED_QTY,
    ROW_NUMBER() OVER (PARTITION BY PLD.PURC_ORDER_ID, PLD.PURC_ORDER_LINE_NO ORDER BY PLD.DEL_SCHED_LINE_NO) RN
  FROM
    current_po_user CPU,
    PURC_LINE_DEL PLD
  WHERE
    CPU.USERNAME=USER
    AND CPU.PURC_ORDER_ID=PLD.PURC_ORDER_ID) P
WHERE
  P.PURC_ORDER_ID='144038'
  AND P.PURC_ORDER_LINE_NO=1
CONNECT BY PRIOR
  RN=RN-1
START WITH
  RN=1
GROUP BY
  P.PURC_ORDER_ID,
  P.PURC_ORDER_LINE_NO;

PURC_ORDER_ID   PURC_ORDER_LINE_NO DEL_SCHED_LINE_ RECEIVED_QTY
--------------- ------------------ --------------- ------------
144038                           1 1               8
                                   2               8
                                   3               8
                                   4               0
                                   5               0
                                   6               0
                                   7               0
                                   8               0

The query results are returned instantaneously, with an execution plan that looks like this:

-------------------------------------------------------------------------------------------------------
| Id  | Operation                           | Name            | Rows  | Bytes | Cost (%CPU)| Time     |
-------------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT                    |                 |     6 |   306 |     3   (0)| 00:00:01 |
|   1 |  SORT GROUP BY                      |                 |     6 |   306 |     3   (0)| 00:00:01 |
|*  2 |   FILTER                            |                 |       |       |            |          |
|*  3 |    CONNECT BY WITH FILTERING        |                 |       |       |            |          |
|*  4 |     FILTER                          |                 |       |       |            |          |
|   5 |      COUNT                          |                 |       |       |            |          |
|   6 |       VIEW                          |                 |     6 |   306 |     3   (0)| 00:00:01 |
|   7 |        WINDOW BUFFER                |                 |     6 |   270 |     3   (0)| 00:00:01 |
|   8 |         NESTED LOOPS                |                 |     6 |   270 |     3   (0)| 00:00:01 |
|   9 |          TABLE ACCESS BY INDEX ROWID| CURRENT_PO_USER |     1 |    26 |     1   (0)| 00:00:01 |
|* 10 |           INDEX UNIQUE SCAN         | SYS_C0022556    |     1 |       |     1   (0)| 00:00:01 |
|  11 |          TABLE ACCESS BY INDEX ROWID| PURC_LINE_DEL   |     6 |   114 |     2   (0)| 00:00:01 |
|* 12 |           INDEX RANGE SCAN          | SYS_C005716     |     6 |       |     1   (0)| 00:00:01 |
|* 13 |     HASH JOIN                       |                 |       |       |            |          |
|  14 |      CONNECT BY PUMP                |                 |       |       |            |          |
|  15 |      COUNT                          |                 |       |       |            |          |
|  16 |       VIEW                          |                 |     6 |   306 |     3   (0)| 00:00:01 |
|  17 |        WINDOW BUFFER                |                 |     6 |   270 |     3   (0)| 00:00:01 |
|  18 |         NESTED LOOPS                |                 |     6 |   270 |     3   (0)| 00:00:01 |
|  19 |          TABLE ACCESS BY INDEX ROWID| CURRENT_PO_USER |     1 |    26 |     1   (0)| 00:00:01 |
|* 20 |           INDEX UNIQUE SCAN         | SYS_C0022556    |     1 |       |     1   (0)| 00:00:01 |
|  21 |          TABLE ACCESS BY INDEX ROWID| PURC_LINE_DEL   |     6 |   114 |     2   (0)| 00:00:01 |
|* 22 |           INDEX RANGE SCAN          | SYS_C005716     |     6 |       |     1   (0)| 00:00:01 |
|  23 |     COUNT                           |                 |       |       |            |          |
|  24 |      VIEW                           |                 |     6 |   306 |     3   (0)| 00:00:01 |
|  25 |       WINDOW BUFFER                 |                 |     6 |   270 |     3   (0)| 00:00:01 |
|  26 |        NESTED LOOPS                 |                 |     6 |   270 |     3   (0)| 00:00:01 |
|  27 |         TABLE ACCESS BY INDEX ROWID | CURRENT_PO_USER |     1 |    26 |     1   (0)| 00:00:01 |
|* 28 |          INDEX UNIQUE SCAN          | SYS_C0022556    |     1 |       |     1   (0)| 00:00:01 |
|  29 |         TABLE ACCESS BY INDEX ROWID | PURC_LINE_DEL   |     6 |   114 |     2   (0)| 00:00:01 |
|* 30 |          INDEX RANGE SCAN           | SYS_C005716     |     6 |       |     1   (0)| 00:00:01 |
-------------------------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------
   2 - filter("P"."PURC_ORDER_ID"='144038' AND "P"."PURC_ORDER_LINE_NO"=1)
   3 - access("RN"-1=PRIOR "RN")
   4 - filter("RN"=1)
  10 - access("CPU"."USERNAME"=USER@!)
  12 - access("CPU"."PURC_ORDER_ID"="PLD"."PURC_ORDER_ID")
  13 - access("RN"-1=PRIOR "RN")
  20 - access("CPU"."USERNAME"=USER@!)
  22 - access("CPU"."PURC_ORDER_ID"="PLD"."PURC_ORDER_ID")
  28 - access("CPU"."USERNAME"=USER@!)
  30 - access("CPU"."PURC_ORDER_ID"="PLD"."PURC_ORDER_ID")

Note
-----
   - dynamic sampling used for this statement

The next step, of course, is to create a statically defined view for our SQL statement:

CREATE VIEW PURC_LINE_DEL_PO_REPORT AS
SELECT
  P.PURC_ORDER_ID,
  P.PURC_ORDER_LINE_NO,
  MAX(REPLACE(SUBSTR(SYS_CONNECT_BY_PATH(P.DEL_SCHED_LINE_NO,', '),3),', ',CHR(13)||CHR(10))) DEL_SCHED_LINE_NO,
  MAX(REPLACE(SUBSTR(SYS_CONNECT_BY_PATH(P.RECEIVED_QTY,', '),3),', ',CHR(13)||CHR(10))) RECEIVED_QTY
FROM
  (SELECT /*+ ORDERED */
    PLD.PURC_ORDER_ID,
    PLD.PURC_ORDER_LINE_NO,
    PLD.DEL_SCHED_LINE_NO,
    PLD.RECEIVED_QTY,
    ROW_NUMBER() OVER (PARTITION BY PLD.PURC_ORDER_ID, PLD.PURC_ORDER_LINE_NO ORDER BY PLD.DEL_SCHED_LINE_NO) RN
  FROM
    current_po_user CPU,
    PURC_LINE_DEL PLD
  WHERE
    CPU.USERNAME=USER
    AND CPU.PURC_ORDER_ID=PLD.PURC_ORDER_ID) P
CONNECT BY PRIOR
  RN=RN-1
START WITH
  RN=1
GROUP BY
  P.PURC_ORDER_ID,
  P.PURC_ORDER_LINE_NO;

GRANT SELECT ON PURC_LINE_DEL_PO_REPORT TO PUBLIC;

But how do we populate the CURRENT_PO_USER table?  The ERP module supports the execution of VBScript macros when a purchase order is opened and when it is saved.  So, we just create a VBScript macro that populates that table as needed.  Painted into a corner, but fortunately there is a door in that corner of the room.

Maybe there is a better way that does not require the custom table and the custom VBScript macros?





Auto-Tuned DB_FILE_MULTIBLOCK_READ_COUNT Parameter

10 04 2010

April 10, 2010

There were a couple of recent threads on the OTN forums about the behavior of the DB_FILE_MULTIBLOCK_READ_COUNT parameter’s auto-tuning capability which was introduced with Oracle Database 10.2.0.1.  The threads included this discussion about a problem where the DB_FILE_MULTIBLOCK_READ_COUNT parameter refused to remain at a value of 0, and this discussion that described a problem where Oracle Database was auto-tuning the parameter to a value of 36.

I found the second discussion to be more interesting than the first, but in the first discussion I provided the following quotes from the Oracle documentation:

http://download.oracle.com/docs/cd/B28359_01/server.111/b28320/initparams053.htm

“As of Oracle Database 10g release 2, the default value of this parameter is a value that corresponds to the maximum I/O size that can be performed efficiently. This value is platform-dependent and is 1MB for most platforms. Because the parameter is expressed in blocks, it will be set to a value that is equal to the maximum I/O size that can be performed efficiently divided by the standard block size. Note that if the number of sessions is extremely large the multiblock read count value is decreased to avoid the buffer cache getting flooded with too many table scan buffers.”

http://download.oracle.com/docs/cd/B28359_01/server.111/b28274/iodesign.htm#g35578

“DB_FILE_MULTIBLOCK_READ_COUNT: The maximum I/O size for full table scans is computed by multiplying this parameter with DB_BLOCK_SIZE. (the upper value is subject to operating system limits). If this value is not set explicitly (or is set to 0), the default value corresponds to the maximum I/O size that can be efficiently performed and is platform-dependent.”

While the documentation did not explicitly state so, I suspected that the size of the buffer cache might also contribute to the value of the auto-tuned DB_FILE_MULTIBLOCK_READ_COUNT parameter’s value.  In the same discussion thread Jonathan Lewis indicated that the DB_CACHE_SIZE parameter was part of the calculation.  More or less the same answer, so my suspicion might have some merit.  I think that we need a test case to see if the size of the buffer cache actually has an impact on the auto-tuned parameter.

I built a new database in 64 bit Oracle Database 11.2.0.1 with an 8KB block size with all of the SGA parameters unspecified (the memory target parameters were also left unspecified), except for SGA_TARGET and SGA_MAX_SIZE.  The PGA_AGGREGATE_TARGET was set to 1800MB.  For the test case I altered the value of SGA_TARGET and SESSIONS (the value of which apparently rounds up to the nearest multiple of 8).  The results of the test follow (the value of Database Buffers also decreased for the 8000M tests as the number of sessions increased, but the changing values were not recorded):

SGA_TARGET=8000M
SESSIONS   DB_FILE_MULTI   Database Buffers
--------   -------------   ----------------
    6000             128
    6400             128      6,979,321,856
    6448             127      6,979,321,856
    6504             126
    7000             117
    8000             102
   16000              51
   32000              25
   64000              12

-

SGA_TARGET=4000M
SESSIONS   DB_FILE_MULTI   Database Buffers
--------   -------------   ----------------
    3000             128      3,338,665,984
    3056             128      3,338,665,984
    3080             127      3,338,665,984
    3104             126      3,338,665,984
    3128             125      3,338,665,984
    3152             125      3,338,665,984
    6304              62      3,338,665,984
    6400              61      3,338,665,984
   12608              31      3,137,339,392
   25216              15      2,432,696,320
   50432               7      1,056,964,608
   64000               6        251,658,240

-

SGA_TARGET=2000M
SESSIONS   DB_FILE_MULTI   Database Buffers
--------   -------------   ----------------
    1400             128      1,560,281,088
    1504             123      1,560,281,088
    2000              92      1,560,281,088
    4000              46      1,560,281,088
    8000              23      1,358,954,496
   16000              11        905,969,664

In general, as the number of sessions doubles, the value of the auto-tuned DB_FILE_MULTIBLOCK_READ_COUNT is 1/2 of its previous value.  With the 8000MB SGA_TARGET, the DB_FILE_MULTIBLOCK_READ_COUNT hit 12 at 64,000 sessions.  With the 4000MB SGA_TARGET the DB_FILE_MULTIBLOCK_READ_COUNT hit 6 at 64,000 sessions.  With the 2000MB SGA_TARGET, the DB_FILE_MULTIBLOCK_READ_COUNT hit 11 at 16,000 sessions, which is roughly the same value as when the SGA_TARGET was 4 times larger with a SESSIONS parameter configured 4 times larger.

Pop quiz time:

1. What is the mathematical formula that determines the value of DB_FILE_MULTIBLOCK_READ_COUNT?  There is a chance that the above results might be different for a different release of Oracle Database.

2. Is the SGA_TARGET parameter, the DB_CACHE_SIZE parameter, the __DB_CACHE_SIZE hidden parameter, or the sum of the various buffer pool parameters the determining factor of the DB_FILE_MULTIBLOCK_READ_COUNT value (in addition to the value of the SESSIONS parameter)?  More tests are probably needed.

3. Assuming that the original poster in the OTN thread was using an 8KB block size, how was an auto-tuned value of 36 achieved for the DB_FILE_MULTIBLOCK_READ_COUNT parameter?





True or False – Autotrace

8 04 2010

April 8, 2010

(Back to the Previous Post in the Series) (Forward to the Next Post in the Series)

I recently encountered a discussion thread (dbaforums.org/oracle/index.php?showtopic=19435) that asked about how to determine whether or not a SQL statement executed in a program uses indexes or full table scans – the database in question is an unspecified release version of Oracle 10g.  One of the responders in that thread pointed to an undated article (praetoriate.com/teas_prae_util11.htm) about the AUTOTRACE functionality of SQL*Plus, while other responders suggested tracing the program’s execution and then using TKPROF.

Please read the article, keeping in mind that the question concerns some release version of Oracle 10g, and see if you are able to answer the following true or false questions.  State why you believe that the question is true, or why you believe that the question is false.  Any answers that attempt to utilize logical fallacies will be scored as incorrect.

1. SQL*Plus’ AUTOTRACE feature performs statement tracing.

2. Using SQL*Plus’ AUTOTRACE feature requires a PLAN_TABLE in the schema of the user using AUTOTRACE.

3. AUTOTRACE retrieves the actual execution plan, along with the associated statistics for the execution.

4. When a large number of rows will be returned by SQL*Plus, the AUTOTRACE TRACEONLY feature should be used.

5. For SQL performance issues, AUTOTRACE is the first tool of choice for investigating the SQL performance issues.

6. Performance issues that are present when SQL is executed in an application will also be present when the SQL statement is executed in SQL*Plus with AUTOTRACE enabled.

-

——————————————————————————-
——————————————————————————-

May 25, 2010

The following screen capture is completely unrelated to this blog article, but is relevant to the comments about the blog redesign.  This is how the redesigned blog appears on a 16:9 netbook, with 1024 horizontal pixels of resolution:

I had to scroll the window slightly to the right to see the entire content portion of the blog, while the “floating” navigation section is hidden from view.  Internet Explorer 8.0 offers a zoom feature near the bottom right of the IE window – that feature (or a similar one in other browsers) might be a solution if your monitor does not offer 1024 pixels of horizontal resolution.

————————

Original Layout (4:3 monitor):
 
Modified Layout (4:3 monitor):





Follow that Index

7 04 2010

April 7, 2010

A thread about access paths and hints on the OTN forums caught my attention.  The thread started with the following statement:

When I used Index Range Scan Descending hint for two select statements, it worked with one and not with the other.

The thread evolved a bit into whether or not the hint was valid, and what would happen if another access path had a lower cost than the hinted access path.  It was an interesting discussion, including a brief question about whether a hint could result in Oracle returning the wrong resultset for a query.  In the thread I put together a test case that demonstrated what happens with the potential existence of NULL values when index hints are used against those columns that permit NULL values.

Creating the table, inserting 10,000 rows into the test table, creating an index on the second column, and then gathering the statistics for the table and indexes:

CREATE TABLE T1 (
  C1 NUMBER,
  C2 NUMBER,
  C3 VARCHAR2(100),
  PRIMARY KEY (C1));

INSERT INTO T1
SELECT
  ROWNUM,
  DECODE(MOD(ROWNUM,100),0,NULL,ROWNUM),
  RPAD('A',100,'A')
FROM
  DUAL
CONNECT BY
  LEVEL<=10000;

COMMIT;

CREATE INDEX IND_T1_C2 ON T1(C2);

EXEC DBMS_STATS.GATHER_TABLE_STATS(OWNNAME=>USER,TABNAME=>'T1',CASCADE=>TRUE)

In the above table, 1 row of every 100 rows contains a NULL value in column C2. If we were to tell Oracle to order the rows using that column, Oracle could not use the IND_T1_C2 index to speed up the ordering of the rows because the rows containing the NULL values are not contained in the index.

SELECT
  *
FROM
  T1
ORDER BY
  C2;

SELECT
  *
FROM
  TABLE(DBMS_XPLAN.DISPLAY_CURSOR(NULL,NULL,'TYPICAL'));

The execution plan is as expected, using a full table scan:

-----------------------------------------------------------------------------------
| Id  | Operation          | Name | Rows  | Bytes |TempSpc| Cost (%CPU)| Time     |
-----------------------------------------------------------------------------------
|   0 | SELECT STATEMENT   |      |       |       |       |   217 (100)|          |
|   1 |  SORT ORDER BY     |      | 10000 |  1054K|  2376K|   217   (2)| 00:00:02 |
|   2 |   TABLE ACCESS FULL| T1   | 10000 |  1054K|       |    11  (10)| 00:00:01 |
-----------------------------------------------------------------------------------

Now let’s repeat the test, making certain that no NULL values are introduced in column C2:

DROP TABLE T1 PURGE;

CREATE TABLE T1 (
  C1 NUMBER,
  C2 NUMBER,
  C3 VARCHAR2(100),
  PRIMARY KEY (C1));

INSERT INTO T1
SELECT
  ROWNUM,
  ROWNUM,
  RPAD('A',100,'A')
FROM
  DUAL
CONNECT BY
  LEVEL<=10000;

COMMIT;

CREATE INDEX IND_T1_C2 ON T1(C2);

EXEC DBMS_STATS.GATHER_TABLE_STATS(OWNNAME=>USER,TABNAME=>'T1',CASCADE=>TRUE,NO_INVALIDATE=>FALSE)

In the above, NO_INVALIDATE=>FALSE was used to make certain that the queries for this table are hard parsed, if re-executed.  Trying the query again, with a hinted access path:

SELECT /*+ INDEX(T1 IND_T1_C2) */
  *
FROM
  T1
ORDER BY
  C2;

SELECT
  *
FROM
  TABLE(DBMS_XPLAN.DISPLAY_CURSOR(NULL,NULL,'TYPICAL'));

Oracle still cannot use that index to speed up retrieval, because the column C2 could possibly contain a NULL value, even though it does not:

-----------------------------------------------------------------------------------
| Id  | Operation          | Name | Rows  | Bytes |TempSpc| Cost (%CPU)| Time   |
-----------------------------------------------------------------------------------
|   0 | SELECT STATEMENT   |      |       |       |       |   217 (100)|          |
|   1 |  SORT ORDER BY     |      | 10000 |  1054K|  2376K|   217   (2)| 00:00:02 |
|   2 |   TABLE ACCESS FULL| T1   | 10000 |  1054K|       |    11  (10)| 00:00:01 |
-----------------------------------------------------------------------------------

So, if we fix the problem of potential NULL values and re-run the test:

ALTER TABLE T1 MODIFY (C2 NOT NULL);

EXEC DBMS_STATS.GATHER_TABLE_STATS(OWNNAME=>USER,TABNAME=>'T1',CASCADE=>TRUE,NO_INVALIDATE=>FALSE)

SELECT /*+ INDEX(T1 IND_T1_C2) */
  *
FROM
  T1
ORDER BY
  C2;

SELECT
  *
FROM
  TABLE(DBMS_XPLAN.DISPLAY_CURSOR(NULL,NULL,'TYPICAL'));

What happens now? Oracle knows that all possible values for C2 will be in the index due to the NOT NULL constraint, so there is no chance that it could return the wrong result (missing rows):

SQL_ID  2d4j0qkfaynst, child number 0
-------------------------------------
SELECT /*+ INDEX(T1 IND_T1_C2) */   * FROM   T1 ORDER BY   C2

Plan hash value: 4220775576

-----------------------------------------------------------------------------------------
| Id  | Operation                   | Name      | Rows  | Bytes | Cost (%CPU)| Time     |
-----------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT            |           |       |       |   182 (100)|          |
|   1 |  TABLE ACCESS BY INDEX ROWID| T1        | 10000 |  1054K|   182   (1)| 00:00:01 |
|   2 |   INDEX FULL SCAN           | IND_T1_C2 | 10000 |       |    22   (0)| 00:00:01 |
-----------------------------------------------------------------------------------------

The same execution plan is achieved even without the index hint due to the calculated cost of the plan, so we should perform a couple more tests while artificially increasing the cost for the index access:

ALTER SESSION SET OPTIMIZER_INDEX_COST_ADJ=200;

SELECT
  *
FROM
  T1
ORDER BY
  C2;

SELECT
  *
FROM
  TABLE(DBMS_XPLAN.DISPLAY_CURSOR(NULL,NULL,'TYPICAL'));

The execution plan now shows a full table scan, rather than an INDEX FULL SCAN:

SQL_ID c9s457r2swafn, child number 1

SELECT   * FROM   T1 ORDER BY  C2

Plan hash value: 2148421099
-----------------------------------------------------------------------------------
| Id  | Operation          | Name | Rows  | Bytes |TempSpc| Cost (%CPU)| Time     |
-----------------------------------------------------------------------------------
|   0 | SELECT STATEMENT   |      |       |       |       |   217 (100)|          |
|   1 |  SORT ORDER BY     |      | 10000 |  1054K|  2376K|   217   (2)| 00:00:02 |
|   2 |   TABLE ACCESS FULL| T1   | 10000 |  1054K|       |    11  (10)| 00:00:01 |
-----------------------------------------------------------------------------------

Now with an index hint to force the execution path:

SELECT /*+ INDEX(T1 IND_T1_C2) */
  *
FROM
  T1
ORDER BY
  C2;

SELECT
  *
FROM
  TABLE(DBMS_XPLAN.DISPLAY_CURSOR(NULL,NULL,'TYPICAL'));

---

SQL_ID 7cxfwpzxqfsbz, child number 0

SELECT /*+ INDEX(T1 IND_T1_C2) */   * FROM   T1 ORDER BY   C2

Plan hash value: 4220775576

-----------------------------------------------------------------------------------------
| Id  | Operation                   | Name      | Rows  | Bytes | Cost (%CPU)| Time     |
-----------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT            |           |       |       |   364 (100)|          |
|   1 |  TABLE ACCESS BY INDEX ROWID| T1        | 10000 |  1054K|   364   (1)| 00:00:02 |
|   2 |   INDEX FULL SCAN           | IND_T1_C2 | 10000 |       |    45   (3)| 00:00:01 |
-----------------------------------------------------------------------------------------

The above shows that the hinted execution path was selected even though it now has a higher calculated cost.

You might be wondering if we need a descending index to potentially speed up retrieval if the rows retrieved by the SQL statement needed to be sorted in descending order, with the requirement that the SORT ORDER BY operation does not appear in the execution plan.  Let’s test, leaving the altered OPTIMIZER_INDEX_COST_ADJ parameter value in place:

SELECT /*+ INDEX(T1 IND_T1_C2) */
  *
FROM
  T1
ORDER BY
  C2 DESC;

SELECT
  *
FROM
  TABLE(DBMS_XPLAN.DISPLAY_CURSOR(NULL,NULL,'TYPICAL'));

SQL_ID 3t3x7us3c0yyb, child number 0

SELECT /*+ INDEX(T1 IND_T1_C2) */   * FROM   T1 ORDER BY   C2 DESC

Plan hash value: 654729690

--------------------------------------------------------------------------------------------------
| Id  | Operation                    | Name      | Rows  | Bytes |TempSpc| Cost (%CPU)| Time     |
--------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT             |           |       |       |       |   570 (100)|          |
|   1 |  SORT ORDER BY               |           | 10000 |  1054K|  2376K|   570   (1)| 00:00:03 |
|   2 |   TABLE ACCESS BY INDEX ROWID| T1        | 10000 |  1054K|       |   364   (1)| 00:00:02 |
|   3 |    INDEX FULL SCAN           | IND_T1_C2 | 10000 |       |       |    45   (3)| 00:00:01 |
--------------------------------------------------------------------------------------------------

The above shows that we used an index full scan, like before, but now there is also a SORT ORDER BY operation, which sorted the rows in descending order.  Not quite what we need, so we need a different hint:

SELECT /*+ INDEX_DESC(T1 IND_T1_C2) */
  *
FROM
  T1
ORDER BY
  C2 DESC;

SELECT
  *
FROM
  TABLE(DBMS_XPLAN.DISPLAY_CURSOR(NULL,NULL,'TYPICAL'));

SQL_ID bq9wha0byz2hm, child number 0

SELECT /*+ INDEX_DESC(T1 IND_T1_C2) */  * FROM   T1 ORDER BY C2 DESC

Plan hash value: 4067756747

-----------------------------------------------------------------------------------------
| Id  | Operation                   | Name      | Rows  | Bytes | Cost (%CPU)| Time     |
-----------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT            |           |       |       |   364 (100)|          |
|   1 |  TABLE ACCESS BY INDEX ROWID| T1        | 10000 |  1054K|   364   (1)| 00:00:02 |
|   2 |   INDEX FULL SCAN DESCENDING| IND_T1_C2 | 10000 |       |    45   (3)| 00:00:01 |
-----------------------------------------------------------------------------------------

This time we were able to avoid the sort operation, as Oracle was able to simply read the index in reverse order.  You might wonder if this would happen automatically, without a hint.  First, we need to reset the OPTIMIZER_INDEX_COST_ADJ parameter:

ALTER SESSION SET OPTIMIZER_INDEX_COST_ADJ=100;

Now a quick test:

SELECT
  *
FROM
  T1
ORDER BY
  C2 DESC;

SELECT
  *
FROM
  TABLE(DBMS_XPLAN.DISPLAY_CURSOR(NULL,NULL,'TYPICAL'));

SQL_ID 0790s346b7qsv, child number 0

SELECT   * FROM   T1 ORDER BY  C2 DESC

Plan hash value: 4067756747

-----------------------------------------------------------------------------------------
| Id  | Operation                   | Name      | Rows  | Bytes | Cost (%CPU)| Time     |
-----------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT            |           |       |       |   182 (100)|          |
|   1 |  TABLE ACCESS BY INDEX ROWID| T1        | 10000 |  1054K|   182   (1)| 00:00:01 |
|   2 |   INDEX FULL SCAN DESCENDING| IND_T1_C2 | 10000 |       |    22   (0)| 00:00:01 |
-----------------------------------------------------------------------------------------

So, the answer is yes – Oracle is able to automatically read an index in reverse order to avoid a sort operation without a hint, even when all columns will be returned from a table.





Battling the Symptoms or Addressing the Root Cause

3 04 2010

April 3, 2010

A non-Oracle specific question arrived in an email from an ERP mailing list – I think that the user who wrote the email was probably running SQL Server, but that probably does not imply much other than potential differences in read-consistency and trigger code when compared to a user running the same ERP package with Oracle Database.

Paraphrasing the question:

I need to be able to automate the running of a utility (VMFIXOHQ) on a Windows client computer.  The utility does not offer a command line interface for specifying parameters, so the method of automation must be able to enter text into screen fields, click program buttons, and activate menu items so that the utility will automatically run on a nightly basis.  A program named Automate is able to accomplish this task, but is too expensive for this specific task.

I have in the past written task schedulers that would do exactly what the author of the email requested, but I did not offer the task scheduler to the original poster.  Why, well it is hard to describe why.  With a lead-in, I offered the following analogy:

IT Guy: “Doctor, I have a splitting headache and I seem to be having trouble remembering things.”
Doctor1: “Let me write you a prescription for a new desk with a padded writing surface.”
IT Guy: “OK, but I don’t see how that will help my headache.”
Doctor1: “You just told me that you only have splitting headaches while sitting at your desk.”
IT Guy: “That new desk works great.  The headaches still happen, but don’t last quite as long.”
Doctor1: “Now let me prescribe something to cure the imprint of the paperclip and the stapler on your forehead.”
Doctor2:Wouldn’t it be easier to find out why he keeps banging his head on his desk?

In the above analogy, Doctor1 was treating the symptoms of the problem.  Maybe he notice the IT guy’s red forehead, and thought that if the IT guy must bang his head on his desk, he really should have a softer surface for his forehead to hit.  Once the original problem was mitigated, a secondary, related problem remained – obviously, the IT guy should make certain to clear his desk before banging his head.

Doctor2, on the other hand, suggested a root cause analysis.  If the IT guy is banging his head on his desk, determine what triggers the IT guy to bang his head on his desk.  Maybe he can’t find the flyswatter.  Maybe he once hit his head and then by coincidence found a solution to a perplexing problem.  Maybe he is frustrated (he might have worn too small of a size of shoes, causing his feet to hurt).  Maybe someone is forcing him to bang his head?  Wouldn’t it be better to find out why, rather than just trying a number of things that might make the problem less severe, but never actually fix the problem?

An Oracle database example of this is simply throwing hardware at a performance problem because a root cause analysis is perceived as requiring too much time and being too expensive (computer hardware costs are decreasing while at the same time IT labor costs are increasing).  Sure, replace the server with one having 4 times as many CPUs and 4 times as much memory – after all, hardware is cheap compared to the perceived cost of a root cause analysis (at least that is what it says on the news).  Forget that such a cheap upgrade will require 4 times as many Oracle Database CPU licenses, accompanied by 4 times as much for annual Oracle support/maintenance fees.  On second thought, maybe a root cause analysis is really a much better and less costly approach, no matter if the performance problem is caused by a change to daylight savings time, someone verbally abusing the SAN, an upgrade of the Oracle Database version, or something else.

It might seem that I drifted a bit from the topic of the email that arrived from the ERP mailing list about scheduling the execution of the VMFIXOHQ utility.  That utility is not one that should be run daily, not one that should be run weekly, not one that should be run monthly, and not even one that should be run yearly (this doesn’t sound like anything in the Oracle Database universe, does it?).  That utility has a very specific purpose – it fixes the results of application and/or database trigger bugs that caused the stored on hand inventory counts for a specific part to differ from what is sitting on the shelf.  More accurately, a transaction is recorded in the database whenever parts are added to inventory, removed from inventory, or moved from one warehouse location to another, causing the on hand inventory counts for the parts are adjusted accordingly.  This VMFIXOHQ utility runs through these transactions from day 1 and effectively determines how many of the part should be sitting on the shelf based on the supporting inventory transactions.  Scheduling the running of the VMFIXOHQ utility does not address the real reason for the inventory counts being inaccurate; rather it is a band-aid (a padded desk, if you will) for the real problem – a code bug, missing trigger, improperly handled deadlock, or multi-session read-consistency issues.

Was I wrong not to tell the original poster how to schedule the running of this utility?  :-)





Finding the Right Index for this SQL Statement

1 04 2010

April 1, 2010

We have a SQL statement in our ERP package that looks like the following:

SELECT TRANSACTION_ID , WORKORDER_BASE_ID , WORKORDER_LOT_ID , WORKORDER_SPLIT_ID , WORKORDER_SUB_ID ,
OPERATION_SEQ_NO , RESOURCE_ID , TYPE , INDIRECT_ID , CLOCK_IN , TRUNC(TRANSACTION_DATE) , BREAK_CLOCKIN ,
HOURS_BREAK , HOURS_BREAK_IND , SHIFT_DATE , HOURS_PREVIOUS , HOURS_OVERALL , CLOCK_OUT , HOURS_WORKED ,
USER_ID , CREATE_DATE , STARTING_TRANS , UNADJ_CLOCK_IN , PRD_INSP_PLAN_ID , GOOD_QTY , BAD_QTY , DEVIATION_ID 
FROM LABOR_TICKET WHERE  EMPLOYEE_ID = :1  AND HOURS_WORKED IS NULL  ORDER BY EMPLOYEE_ID, TRANSACTION_ID DESC

This SQL statement is fired at the database many times a day, as employees on the production floor start and end production run batches (and also when they “clock-in” and “clock-out” for the day).  The ERP system has an index on the EMPLOYEE_ID column, but while that index will work great for the employee who was just recently hired, unfortunately that index will be inefficient for those employees with 15+ years of transaction history in the database.

One of the suggestions from the ERP user’s group back in 2001 was to create the following index to improve performance, which would hopefully eliminate the need to sort the rows retrieved by the query:

CREATE INDEX VT_LABOR_TICKET_1 ON LABOR_TICKET(EMPLOYEE_ID, TRANSACTION_ID DESC);

In case you are wondering, that descending index specification causes Oracle to create a function based index on recent Oracle releases, while that specification was silently ignored on older Oracle releases (prior to Oracle Database 8i for Enterprise Edition, if I recall correctly, and prior to Oracle Database 9i for Standard Edition).

Did the index help?  Maybe, maybe not.  Consider what would probably happen with a recent Oracle release.  The nightly automatic statistics collection process calculates that the clustering factor for this index is very high, and automatically generates a histogram on the column due to the uneven distribution of the column values.  With recent Oracle Database releases, bind variable peeking is enabled by default.  The employee with 15+ years of transaction history in the system is the first to sign in for the day – and a new child cursor is created for the SQL statement due to the statistics collection 5+ hours earlier.  Assuming that this entire table is in the KEEP buffer pool, the execution plan might look something like this:

Plan hash value: 2750877200

------------------------------------------------------------------------------------------------------------------------
| Id  | Operation          | Name         | Starts | E-Rows | A-Rows |   A-Time   | Buffers |  OMem |  1Mem | Used-Mem |
------------------------------------------------------------------------------------------------------------------------
|   1 |  SORT ORDER BY     |              |      1 |      1 |      0 |00:00:00.42 |   35610 |  1024 |  1024 |          |
|*  2 |   TABLE ACCESS FULL| LABOR_TICKET |      1 |      1 |      0 |00:00:00.42 |   35610 |       |       |          |
------------------------------------------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------
   2 - filter(("HOURS_WORKED" IS NULL AND "EMPLOYEE_ID"=:1))

A 10046 trace at level 12 for the query looks like this:

PARSING IN CURSOR #2 len=538 dep=0 uid=30 oct=3 lid=30 tim=402571814 hv=1657901498 ad='8af31240'
SELECT TRANSACTION_ID , WORKORDER_BASE_ID , WORKORDER_LOT_ID , WORKORDER_SPLIT_ID , WORKORDER_SUB_ID , OPERATION_SEQ_NO , RESOURCE_ID , TYPE , INDIRECT_ID , CLOCK_IN , TRUNC(TRANSACTION_DATE) , BREAK_CLOCKIN , HOURS_BREAK , HOURS_BREAK_IND , SHIFT_DATE , HOURS_PREVIOUS , HOURS_OVERALL , CLOCK_OUT , HOURS_WORKED , USER_ID , CREATE_DATE , STARTING_TRANS , UNADJ_CLOCK_IN , PRD_INSP_PLAN_ID , GOOD_QTY , BAD_QTY , DEVIATION_ID  FROM LABOR_TICKET WHERE  EMPLOYEE_ID = :1
AND HOURS_WORKED IS NULL
ORDER BY EMPLOYEE_ID, TRANSACTION_ID DESC
END OF STMT
PARSE #2:c=0,e=1198,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,tim=402571806
BINDS #2:
kkscoacd
 Bind#0
  oacdty=96 mxl=32(12) mxlc=00 mal=00 scl=00 pre=00
  oacflg=00 fl2=1000010 frm=01 csi=178 siz=32 off=0
  kxsbbbfp=2ee851f8  bln=32  avl=06  flg=05
  value="EMP103"
EXEC #2:c=0,e=5512,p=0,cr=2,cu=0,mis=1,r=0,dep=0,og=1,tim=402577873
FETCH #2:c=406250,e=415234,p=0,cr=35610,cu=0,mis=0,r=0,dep=0,og=1,tim=402993364
STAT #2 id=1 cnt=0 pid=0 pos=1 obj=0 op='SORT ORDER BY (cr=35610 pr=0 pw=0 time=415238 us)'
STAT #2 id=2 cnt=0 pid=1 pos=1 obj=12347 op='TABLE ACCESS FULL LABOR_TICKET (cr=35610 pr=0 pw=0 time=415190 us)'

The production floor employee is happy to get back to work with only a 1/2 second delay.  But what would happen if the table was not fully cached in the buffer cache, or if a new employee made his way to the computer first after the statistics collection?  Either the VT_LABOR_TICKET_1 index or the index just on the EMPLOYEE_ID column might have been used for the execution plan, and our long term employee might have had to endure a much longer wait to get back to work, and certainly would not leave the computer in a happy mood.

If we could modify the hard-coded SQL statement, we might try forcing the use of the VT_LABOR_TICKET_1 index, and we might even specify to only look at those transactions that we created in the last couple of days.  Let’s just try a hint to use the index, which we could implement using this approach:

SELECT /*+ INDEX(LABOR_TICKET VT_LABOR_TICKET_1) */ TRANSACTION_ID , WORKORDER_BASE_ID ,
WORKORDER_LOT_ID , WORKORDER_SPLIT_ID , WORKORDER_SUB_ID , OPERATION_SEQ_NO , RESOURCE_ID , TYPE ,
INDIRECT_ID , CLOCK_IN , TRUNC(TRANSACTION_DATE) , BREAK_CLOCKIN , HOURS_BREAK , HOURS_BREAK_IND ,
SHIFT_DATE , HOURS_PREVIOUS , HOURS_OVERALL , CLOCK_OUT , HOURS_WORKED , USER_ID , CREATE_DATE ,
STARTING_TRANS , UNADJ_CLOCK_IN , PRD_INSP_PLAN_ID , GOOD_QTY , BAD_QTY , DEVIATION_ID  FROM
LABOR_TICKET WHERE  EMPLOYEE_ID = :1  AND HOURS_WORKED IS NULL  ORDER BY EMPLOYEE_ID,
TRANSACTION_ID DESC;

For one of the employees with 15+ years of transaction history, the execution plan might look something like this:

Plan hash value: 1422135358

-----------------------------------------------------------------------------------------------------------
| Id  | Operation                   | Name              | Starts | E-Rows | A-Rows |   A-Time   | Buffers |
-----------------------------------------------------------------------------------------------------------
|*  1 |  TABLE ACCESS BY INDEX ROWID| LABOR_TICKET      |      1 |      1 |      0 |00:00:00.05 |    8684 |
|*  2 |   INDEX RANGE SCAN          | VT_LABOR_TICKET_1 |      1 |  11719 |  16376 |00:00:00.01 |      66 |
-----------------------------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------
   1 - filter("HOURS_WORKED" IS NULL)
   2 - access("EMPLOYEE_ID"=:1)
       filter("EMPLOYEE_ID"=:1)

The execution completed 10 times faster than the full table scan, which was certainly helped by careful use of the KEEP buffer pool to limit the impact of the index’s high clustering factor.  The 10046 trace at level 12 might look something like this:

PARSING IN CURSOR #13 len=583 dep=0 uid=30 oct=3 lid=30 tim=2180285132 hv=989309132 ad='7c9e2b58'
SELECT /*+ INDEX(LABOR_TICKET VT_LABOR_TICKET_1) */ TRANSACTION_ID , WORKORDER_BASE_ID , WORKORDER_LOT_ID , WORKORDER_SPLIT_ID , WORKORDER_SUB_ID , OPERATION_SEQ_NO , RESOURCE_ID , TYPE , INDIRECT_ID , CLOCK_IN , TRUNC(TRANSACTION_DATE) , BREAK_CLOCKIN , HOURS_BREAK , HOURS_BREAK_IND , SHIFT_DATE , HOURS_PREVIOUS , HOURS_OVERALL , CLOCK_OUT , HOURS_WORKED , USER_ID , CREATE_DATE , STARTING_TRANS , UNADJ_CLOCK_IN , PRD_INSP_PLAN_ID , GOOD_QTY , BAD_QTY , DEVIATION_ID  FROM LABOR_TICKET WHERE  EMPLOYEE_ID = :1
AND HOURS_WORKED IS NULL
ORDER BY EMPLOYEE_ID, TRANSACTION_ID DESC
END OF STMT
PARSE #13:c=0,e=1218,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,tim=2180285124
BINDS #13:
kkscoacd
 Bind#0
  oacdty=96 mxl=32(12) mxlc=00 mal=00 scl=00 pre=00
  oacflg=00 fl2=1000010 frm=01 csi=178 siz=32 off=0
  kxsbbbfp=2db72048  bln=32  avl=06  flg=05
  value="EMP103"
EXEC #13:c=15625,e=5540,p=0,cr=2,cu=0,mis=1,r=0,dep=0,og=1,tim=2180291322
WAIT #13: nam='SQL*Net message to client' ela= 5 driver id=1413697536 #bytes=1 p3=0 obj#=-1 tim=2180291466
FETCH #13:c=46875,e=54726,p=0,cr=8684,cu=0,mis=0,r=0,dep=0,og=1,tim=2180346313
STAT #13 id=1 cnt=0 pid=0 pos=1 obj=12347 op='TABLE ACCESS BY INDEX ROWID LABOR_TICKET (cr=8684 pr=0 pw=0 time=54719 us)'
STAT #13 id=2 cnt=16376 pid=1 pos=1 obj=14555 op='INDEX RANGE SCAN VT_LABOR_TICKET_1 (cr=66 pr=0 pw=0 time=51 us)'

If you have read many of Richard Foote’s blog articles, you are probably well aware that B*Tree indexes do not store NULL values… at least without using fancy tricks as described on his blog… or if there are multiple columns in the index and at least one column value is not NULL.  So, we create a new index:

CREATE INDEX IND_LT_EMPLOYEE_HW ON LABOR_TICKET(EMPLOYEE_ID,HOURS_WORKED);

The execution plan might look like the following for the employee with the 15+ years of transaction history:

SELECT /*+ INDEX(LABOR_TICKET IND_LT_EMPLOYEE_HW) */ TRANSACTION_ID , WORKORDER_BASE_ID , WORKORDER_LOT_ID , WORKORDER_SPLIT_ID
, WORKORDER_SUB_ID , OPERATION_SEQ_NO , RESOURCE_ID , TYPE , INDIRECT_ID , CLOCK_IN , TRUNC(TRANSACTION_DATE) , BREAK_CLOCKIN ,
HOURS_BREAK , HOURS_BREAK_IND , SHIFT_DATE , HOURS_PREVIOUS , HOURS_OVERALL , CLOCK_OUT , HOURS_WORKED , USER_ID , CREATE_DATE
, STARTING_TRANS , UNADJ_CLOCK_IN , PRD_INSP_PLAN_ID , GOOD_QTY , BAD_QTY , DEVIATION_ID  FROM LABOR_TICKET WHERE  EMPLOYEE_ID
= :1  AND HOURS_WORKED IS NULL  ORDER BY EMPLOYEE_ID, TRANSACTION_ID DESC

Plan hash value: 2790784761

----------------------------------------------------------------------------------------------------------------------------------------
| Id  | Operation                    | Name               | Starts | E-Rows | A-Rows |   A-Time   | Buffers |  OMem |  1Mem | Used-Mem |
----------------------------------------------------------------------------------------------------------------------------------------
|   1 |  SORT ORDER BY               |                    |      1 |      1 |      0 |00:00:00.01 |       3 |  1024 |  1024 |          |
|   2 |   TABLE ACCESS BY INDEX ROWID| LABOR_TICKET       |      1 |      1 |      0 |00:00:00.01 |       3 |       |       |          |
|*  3 |    INDEX RANGE SCAN          | IND_LT_EMPLOYEE_HW |      1 |      1 |      0 |00:00:00.01 |       3 |       |       |          |
----------------------------------------------------------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------
   3 - access("EMPLOYEE_ID"=:1 AND "HOURS_WORKED" IS NULL)

And a 10046 trace at level 12 might look like this:

PARSING IN CURSOR #6 len=584 dep=0 uid=30 oct=3 lid=30 tim=2919660608 hv=4195357598 ad='66272978'
SELECT /*+ INDEX(LABOR_TICKET IND_LT_EMPLOYEE_HW) */ TRANSACTION_ID , WORKORDER_BASE_ID , WORKORDER_LOT_ID , WORKORDER_SPLIT_ID , WORKORDER_SUB_ID , OPERATION_SEQ_NO , RESOURCE_ID , TYPE , INDIRECT_ID , CLOCK_IN , TRUNC(TRANSACTION_DATE) , BREAK_CLOCKIN , HOURS_BREAK , HOURS_BREAK_IND , SHIFT_DATE , HOURS_PREVIOUS , HOURS_OVERALL , CLOCK_OUT , HOURS_WORKED , USER_ID , CREATE_DATE , STARTING_TRANS , UNADJ_CLOCK_IN , PRD_INSP_PLAN_ID , GOOD_QTY , BAD_QTY , DEVIATION_ID  FROM LABOR_TICKET WHERE  EMPLOYEE_ID = :1
AND HOURS_WORKED IS NULL
ORDER BY EMPLOYEE_ID, TRANSACTION_ID DESC
END OF STMT
PARSE #6:c=0,e=1230,p=0,cr=0,cu=0,mis=1,r=0,dep=0,og=1,tim=2919660600
BINDS #6:
kkscoacd
 Bind#0
  oacdty=96 mxl=32(12) mxlc=00 mal=00 scl=00 pre=00
  oacflg=00 fl2=1000010 frm=01 csi=178 siz=32 off=0
  kxsbbbfp=2db7d620  bln=32  avl=06  flg=05
  value="EMP103"
EXEC #6:c=0,e=5468,p=0,cr=2,cu=0,mis=1,r=0,dep=0,og=1,tim=2919666706
FETCH #6:c=0,e=103,p=0,cr=3,cu=0,mis=0,r=0,dep=0,og=1,tim=2919667106
STAT #6 id=1 cnt=0 pid=0 pos=1 obj=0 op='SORT ORDER BY (cr=3 pr=0 pw=0 time=114 us)'
STAT #6 id=2 cnt=0 pid=1 pos=1 obj=12347 op='TABLE ACCESS BY INDEX ROWID LABOR_TICKET (cr=3 pr=0 pw=0 time=72 us)'
STAT #6 id=3 cnt=0 pid=2 pos=1 obj=102065 op='INDEX RANGE SCAN IND_LT_EMPLOYEE_HW (cr=3 pr=0 pw=0 time=64 us)'

Five times faster than using the VT_LABOR_TICKET_1 index?  No, not if you look at the STAT lines in the 10046 trace.  When the VT_LABOR_TICKET_1 index was used, the top STAT line shows time=54719 us, while the top STAT line when the IND_LT_EMPLOYEE_HW index was used shows time=72 us – that is about 760 times faster.  As you might imagine, the employee overjoyed to return to the production floor 0.054647 seconds faster.  :-)

But this whole exercise is not about doing something 0.054647 seconds faster, but instead about eliminating unnecessary work.  We should be looking at what else that is executing simultaneously against the database is now able to complete faster due to less CPU and I/O competition from the needless work that was caused by this SQL statement.








Follow

Get every new post delivered to your Inbox.

Join 139 other followers