What is the Meaning of the %CPU Column in an Explain Plan? 2

1 01 2012

January 1, 2012

(Back to the Previous Post in the Series)

Nearly two years ago I posted the following execution plan in a blog article and asked whether or not there was anything strange about the %CPU column:

--------------------------------------------------------------------------------------------------------------
| Id  | Operation            | Name     | Rows  | Bytes | Cost (%CPU)| Time     |    TQ  |IN-OUT| PQ Distrib |
--------------------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT     |          |       |       |   247 (100)|          |        |      |            |
|   1 |  PX COORDINATOR      |          |       |       |            |          |        |      |            |
|   2 |   PX SEND QC (RANDOM)| :TQ10000 | 10000 |  2236K|   247   (1)| 00:00:03 |  Q1,00 | P->S | QC (RAND)  |
|   3 |    PX BLOCK ITERATOR |          | 10000 |  2236K|   247   (1)| 00:00:03 |  Q1,00 | PCWC |            |
|*  4 |     TABLE ACCESS FULL| T1       | 10000 |  2236K|   247   (1)| 00:00:03 |  Q1,00 | PCWP |            |
--------------------------------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------
   4 - access(:Z>=:Z AND :Z<=:Z)
       filter(("C1"<=10000 AND "C1">=1)) 

For nearly two years no one mentioned that it is strange that the row in the execution plan with ID 0 can have a Cost of 247 with a %CPU of 100, while that operation’s child operations can have the same Cost of 247 with a %CPU of 1.  I had long forgotten about the challenge that I posed in the blog article, until someone mentioned the execution plan in an OTN forum thread and asked about that particular oddity.

In the earlier article I demonstrated querying the PLAN_TABLE after using EXPLAIN PLAN FOR to determine how the %CPU column is calculated.  Unfortunately, I did not perform that step two years ago for the SQL statement that was used to generate the above execution plan, so the challenge remains.

As best as I am able to determine, the following is the table creation script:

DROP TABLE T1 PURGE;

CREATE TABLE T1 (
  C1 NUMBER NOT NULL,
  C2 NUMBER NOT NULL,
  C3 NUMBER NOT NULL,
  C4 NUMBER NOT NULL,
  C5 VARCHAR2(30) NOT NULL,
  C6 VARCHAR2(30) NOT NULL,
  FILLER VARCHAR2(200),
  PRIMARY KEY (C1));

INSERT INTO T1
SELECT
  ROWNUM,
  ROWNUM,
  TRUNC(ROWNUM/100+1),
  TRUNC(ROWNUM/100+1),
  CHR(65+TRUNC(ROWNUM/10000))||TRUNC(ROWNUM/100+1),
  CHR(65+TRUNC(ROWNUM/10000))||TRUNC(ROWNUM/100+1),
  LPAD('A',200,'A')
FROM
  DUAL
CONNECT BY
  LEVEL<=100000;

COMMIT;

CREATE INDEX IND_T1_C3 ON T1(C3);
CREATE INDEX IND_T1_C4 ON T1(C4);
CREATE INDEX IND_T1_C5 ON T1(C5);

EXEC DBMS_STATS.GATHER_TABLE_STATS(OWNNAME=>USER,TABNAME=>'T1',CASCADE=>TRUE,ESTIMATE_PERCENT=>100,METHOD_OPT=>'FOR COLUMNS SIZE 254 C2, C4, C6') 

I originally created the execution plan on an unpatched version of Oracle Database 11.2.0.1 running on 64 bit Linux.  The following is the SQL statement that was used to generate the execution plan:

SELECT /*+ PARALLEL(4) */
  *
FROM
  T1
WHERE
  C1 BETWEEN 1 AND 10000; 

Unfortunately, the above SQL statement generates a bit of a different looking execution plan when not hinted to perform a full table scan.  In an Oracle Database 11.2.0.2 database, the following execution plan appeared (although a similar one also appears for 11.2.0.1):

Plan hash value: 2275811211

--------------------------------------------------------------------------------------------
| Id  | Operation                   | Name         | Rows  | Bytes | Cost (%CPU)| Time     |
--------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT            |              |   250 | 39750 |    17   (0)| 00:00:01 |
|   1 |  TABLE ACCESS BY INDEX ROWID| T1           |   250 | 39750 |    17   (0)| 00:00:01 |
|*  2 |   INDEX RANGE SCAN          | SYS_C0041509 |   450 |       |     2   (0)| 00:00:01 |
--------------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------
   2 - access("C1">=1 AND "C1"<=10000)

Note
-----
   - Degree of Parallelism is 1 because of hint 

The execution plan did not employ parallel execution even though it was hinted, because the calculated cost for the index access was less than the calculated cost for the parallel full table scan.  Note also that the cardinality estimate is incorrect  – this query will actually return 10,000 rows (for a side challenge, how is it possible that the index is projected to return 450 rows, when the parent operation is expected to return just 250 rows without a filter predicate applied at the parent operation?).

Let’s add a couple of hints to fix the cardinality issue (note that this particular hint is undocumented), and force the parallel table scan:

DELETE FROM PLAN_TABLE;

EXPLAIN PLAN FOR
SELECT /*+ PARALLEL(4) FULL(T1) CARDINALITY(T1 10000) */
  *
FROM
  T1
WHERE
  C1 BETWEEN 1 AND 10000;

SELECT
  ID,
  COST,
  IO_COST,
  COST-IO_COST DIFF,
  CEIL(DECODE(COST,0,0,(COST-IO_COST)/COST)*100) PER_CPU,
  CPU_COST
FROM
  PLAN_TABLE;

SET LINESIZE 120
SET PAGESIZE 1000

SELECT
  *
FROM
  TABLE(DBMS_XPLAN.DISPLAY); 

On the unpatched 11.2.0.1 database, the above script produced the following output:

ID       COST    IO_COST       DIFF    PER_CPU   CPU_COST
-- ---------- ---------- ---------- ---------- ----------
 0        247        246          1          1    5958333
 1
 2        247        246          1          1    5958333
 3        247        246          1          1    5958333
 4        247        246          1          1    5958333

PLAN_TABLE_OUTPUT
------------------------------------------------------------------------------------------------------------------------
Plan hash value: 2494645258

--------------------------------------------------------------------------------------------------------------
| Id  | Operation            | Name     | Rows  | Bytes | Cost (%CPU)| Time     |    TQ  |IN-OUT| PQ Distrib |
--------------------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT     |          | 10000 |  1552K|   247   (1)| 00:00:03 |        |      |            |
|   1 |  PX COORDINATOR      |          |       |       |            |          |        |      |            |
|   2 |   PX SEND QC (RANDOM)| :TQ10000 | 10000 |  1552K|   247   (1)| 00:00:03 |  Q1,00 | P->S | QC (RAND)  |
|   3 |    PX BLOCK ITERATOR |          | 10000 |  1552K|   247   (1)| 00:00:03 |  Q1,00 | PCWC |            |
|*  4 |     TABLE ACCESS FULL| T1       | 10000 |  1552K|   247   (1)| 00:00:03 |  Q1,00 | PCWP |            |
--------------------------------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------
   4 - filter("C1">=1 AND "C1"<=10000)

Note
-----
   - Degree of Parallelism is 4 because of hint 

The above execution plan is similar to the execution plan at the start of this article (even the costs are identical), yet not exactly the same.  The Predicate Information section of the execution plan is missing access(:Z>=:Z AND :Z<=:Z) and the %CPU column shows a value of 1 from bottom to top, rather than 100 for the top row in the plan.  The output from the query of PLAN_TABLE exactly matches the above output from DBMS_XPLAN.DISPLAY function.  So, what happened, how did I generate the execution plan that appears at the start of this blog article?

You might be curious – are we able to force the first line in the execution plan to show 100 in the %CPU column?  Let’s try an experiment where we manually change the IO_COST value for the row in the PLAN_TABLE where the ID column value is equal to 0:

UPDATE
  PLAN_TABLE
SET
  IO_COST=0
WHERE
  ID=0;

SELECT
  *
FROM
  TABLE(DBMS_XPLAN.DISPLAY); 

With the above change, this is the execution plan that I obtained:

PLAN_TABLE_OUTPUT
------------------------------------------------------------------------------------------------------------------------
Plan hash value: 2494645258

--------------------------------------------------------------------------------------------------------------
| Id  | Operation            | Name     | Rows  | Bytes | Cost (%CPU)| Time     |    TQ  |IN-OUT| PQ Distrib |
--------------------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT     |          | 10000 |  1552K|   247 (100)| 00:00:03 |        |      |            |
|   1 |  PX COORDINATOR      |          |       |       |            |          |        |      |            |
|   2 |   PX SEND QC (RANDOM)| :TQ10000 | 10000 |  1552K|   247   (1)| 00:00:03 |  Q1,00 | P->S | QC (RAND)  |
|   3 |    PX BLOCK ITERATOR |          | 10000 |  1552K|   247   (1)| 00:00:03 |  Q1,00 | PCWC |            |
|*  4 |     TABLE ACCESS FULL| T1       | 10000 |  1552K|   247   (1)| 00:00:03 |  Q1,00 | PCWP |            |
--------------------------------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------
   4 - filter("C1">=1 AND "C1"<=10000)

Note
-----
   - Degree of Parallelism is 4 because of hint 

The first line in the above execution plan now shows 100 in the %CPU column – so if a 0 were present in that row/column combination in the PLAN_TABLE when I generated the execution plan at the start of this article, that might be one explanation for the strange output.  Note, however, that the Predicate Information section still does not match.  So, did I fake the execution plan through manipulation of PLAN_TABLE, or did I actually execute the SQL statement and pull from memory the actual execution plan:

SELECT /*+ PARALLEL(4) FULL(T1) CARDINALITY(T1 10000) */
  *
FROM
  T1
WHERE
  C1 BETWEEN 1 AND 10000;

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

When I executed the above, this is the execution plan that appeared:

SQL_ID  4r3zujtat35jb, child number 0
-------------------------------------
SELECT /*+ PARALLEL(4) FULL(T1) CARDINALITY(T1 10000) */   * FROM   T1
WHERE   C1 BETWEEN 1 AND 10000

Plan hash value: 2494645258

--------------------------------------------------------------------------------------------------------------
| Id  | Operation            | Name     | Rows  | Bytes | Cost (%CPU)| Time     |    TQ  |IN-OUT| PQ Distrib |
--------------------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT     |          |       |       |   247 (100)|          |        |      |            |
|   1 |  PX COORDINATOR      |          |       |       |            |          |        |      |            |
|   2 |   PX SEND QC (RANDOM)| :TQ10000 | 10000 |  1552K|   247   (1)| 00:00:03 |  Q1,00 | P->S | QC (RAND)  |
|   3 |    PX BLOCK ITERATOR |          | 10000 |  1552K|   247   (1)| 00:00:03 |  Q1,00 | PCWC |            |
|*  4 |     TABLE ACCESS FULL| T1       | 10000 |  1552K|   247   (1)| 00:00:03 |  Q1,00 | PCWP |            |
--------------------------------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------
   4 - access(:Z>=:Z AND :Z<=:Z)
       filter(("C1">=1 AND "C1"<=10000))

Note
-----
   - Degree of Parallelism is 4 because of hint 

Notice in the above execution plan that the %CPU column matches the values in the execution plan that appears at the start of this blog article.  Also note that the missing access(:Z>=:Z AND :Z<=:Z) now appears in the Predicate Information section.  Another possible case of explain plan lies?  I wonder what is the point of the :Z >= :Z and :Z <= :Z access predicate?  That is the equivalent of :Z BETWEEN :Z AND :Z, or 1 BETWEEN 1 AND 1 (assuming that the value of the :Z bind variable is not NULL), if you prefer.

Now that I have reproduced the execution plan at the start of this blog article (ignoring the predicted Bytes column), why did the DBMS_XPLAN function display a value of 100 in the %CPU column of the first line in the execution plan?  Is it caused by a bug in DBMS_XPLAN, a bug in the 11.2.0.1 optimizer, or something else?

Recall earlier in this blog article that I tried an experiment of changing the IO_COST for a row in PLAN_TABLE to a value of 0, and that change resulted in a value of 100 appearing in the %CPU column – does that mean that the IO_COST for the first row in the execution plan is 0?  In an execution plan, the costs shown for parent operations includes the cost shown for child operations…

In this case we cannot query the PLAN_TABLE, but we are able to query V$SQL_PLAN for the same type of information using the SQL_ID and Plan hash value that appeared in the above DBMS_XPLAN output:

SELECT
  ID,
  COST,
  IO_COST,
  COST-IO_COST DIFF,
  CPU_COST
FROM
  V$SQL_PLAN
WHERE
  SQL_ID='4r3zujtat35jb'
  AND PLAN_HASH_VALUE=2494645258
ORDER BY
  ID;

        ID       COST    IO_COST       DIFF   CPU_COST
---------- ---------- ---------- ---------- ----------
         0        247
         1
         2        247        246          1    5958333
         3        247        246          1    5958333
         4        247        246          1    5958333 

A NULL value for the IO_COST in execution plan line ID 0 (the first line in the execution plan)…

In the previous article, I proposed that the %CPU column is calculated with the following formula:

CEIL(DECODE(COST,0,0,(COST-IO_COST)/COST)*100) PER_CPU 

If the above were true, then a NULL would appear in the %CPU column for the first row.  It appears that I need to adjust the formula slightly to account for the possibility of a NULL value in the IO_COST column and handle it as if the value were 0 (who says that NULL is not equal to 0?).

CEIL(DECODE(COST,0,0,(COST-NVL(IO_COST,0))/COST)*100) PER_CPU

Later in the OTN thread the OP expressed concern about two SQL statements and their execution plans, where the “the cost per se of a single execution is low, but since the query is executed many number of times, the cpu consumption is hitting a high.”  Feel free to read the OTN thread to see my comments related to this concern.








Follow

Get every new post delivered to your Inbox.

Join 147 other followers