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

19 02 2010

February 19, 2010

(Forward to the Next Post in the Series)

A question recently appeared on the OTN forums asking what %CPU means in an explain plan output.  I did not see a clear definition of that column in the documentation, so I set up a test case.  We will use the test table from this blog article.  Let’s try creating an explain plan on Oracle 11.2.0.1 for a query:

EXPLAIN PLAN FOR
SELECT
  T1.C1,
  T1.C2,
  T1.C3
FROM
  T1,
  (SELECT
    C1,
    C2
  FROM
    T1
  WHERE
    MOD(C1,3)=0) V
WHERE
  T1.C1=V.C1(+)
  AND V.C1 IS NULL
ORDER BY
  T1.C1 DESC;

The above command wrote a couple of rows into the PLAN_TABLE table.  At this point, we should probably consult the documentation to understand the columns in the PLAN_TABLE table.

COST: Cost of the operation as estimated by the optimizer’s query approach. Cost is not determined for table access operations. The value of this column does not have any particular unit of measurement; it is merely a weighted value used to compare costs of execution plans. The value of this column is a function of the CPU_COST and IO_COST columns.

IO_COST: I/O cost of the operation as estimated by the query optimizer’s approach. The value of this column is proportional to the number of data blocks read by the operation. For statements that use the rule-based approach, this column is null.

CPU_COST: CPU cost of the operation as estimated by the query optimizer’s approach. The value of this column is proportional to the number of machine cycles required for the operation. For statements that use the rule-based approach, this column is null.

We found a couple of interesting columns in the PLAN_TABLE table, so let’s query the table

SELECT
  ID,
  COST,
  IO_COST,
  CPU_COST
FROM
  PLAN_TABLE;

 ID  COST  IO_COST   CPU_COST
--- ----- -------- ----------
  0  1482     1467  364928495
  1  1482     1467  364928495
  2   898      887  257272866
  3   889      887   42272866
  4     0        0       2150

Now let’s display the execution plan:

SELECT
  *
FROM
  TABLE(DBMS_XPLAN.DISPLAY);

Plan hash value: 1923834833

--------------------------------------------------------------------------------------------
| Id  | Operation           | Name         | Rows  | Bytes |TempSpc| Cost (%CPU)| Time     |
--------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT    |              | 99000 |  1836K|       |  1482   (2)| 00:00:18 |
|   1 |  SORT ORDER BY      |              | 99000 |  1836K|  2736K|  1482   (2)| 00:00:18 |
|   2 |   NESTED LOOPS ANTI |              | 99000 |  1836K|       |   898   (2)| 00:00:11 |
|   3 |    TABLE ACCESS FULL| T1           |   100K|  1367K|       |   889   (1)| 00:00:11 |
|*  4 |    INDEX UNIQUE SCAN| SYS_C0018049 |    10 |    50 |       |     0   (0)| 00:00:01 |
--------------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------
   4 - access("T1"."C1"="C1")
       filter(MOD("C1",3)=0)

The %CPU is 2 for ID 0, 1, and 2, and the %CPU is 1 for ID 3.  Let’s return to the query of the PLAN_TABLE table and perform a couple of calculations:

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;

 ID  COST  IO_COST  DIFF  PER_CPU   CPU_COST
--- ----- -------- ----- -------- ----------
  0  1482     1467    15        2  364928495
  1  1482     1467    15        2  364928495
  2   898      887    11        2  257272866
  3   889      887     2        1   42272866
  4     0        0     0        0       2150

In the above, I subtracted the IO_COST column from the COST column to derive the DIFF column.  I then divided the value in the DIFF column by the COST column, multiplied the result by 100 to convert the number to a percent, and then rounded up the result to derive the PER_CPU column.  The PER_CPU column seems to match the %CPU column in the DBMS_XPLAN output.  Let’s try another SQL statement:

DELETE FROM PLAN_TABLE;

EXPLAIN PLAN FOR
SELECT
  C1
FROM
  T1
WHERE
  'A'||C1 LIKE 'A%';

Now let’s run the query against the PLAN_TABLE table to see if we are able to predict the values that will appear in the %CPU column of the DBMS_XPLAN output:

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;

 ID  COST  IO_COST  DIFF  PER_CPU   CPU_COST
--- ----- -------- ----- -------- ----------
  0    54       52     2        4   43331709
  1    54       52     2        4   43331709

The above indicates that the %CPU column should show the number 4 on both rows of the execution plan.

SELECT
  *
FROM
  TABLE(DBMS_XPLAN.DISPLAY);

Plan hash value: 2950179127

-------------------------------------------------------------------------------------
| Id  | Operation            | Name         | Rows  | Bytes | Cost (%CPU)|  Time    |
-------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT     |              |  5000 | 25000 |    54   (4)| 00:00:01 |
|*  1 |  INDEX FAST FULL SCAN| SYS_C0018049 |  5000 | 25000 |    54   (4)| 00:00:01 |
-------------------------------------------------------------------------------------

Predicate Information (identified by operation id):
---------------------------------------------------
   1 - filter('A'||TO_CHAR("C1") LIKE 'A%')

One of my previous blog articles showed the following execution plan – this was the actual plan displayed by DBMS_XPLAN.DISPLAY_CURSOR after the SQL statement executed:

--------------------------------------------------------------------------------------------------------------
| 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)) 

Is there anything strange about the %CPU column in the above plan?

Incidentally, a query of SYS.AUX_STATS$ shows the following output (values are used to determine the impact of the CPU_COST column that is displayed in the PLAN_TABLE table):

SELECT
  PNAME,
  PVAL1
FROM
  SYS.AUX_STATS$
WHERE
  PNAME IN ('CPUSPEED','CPUSPEEDNW');

PNAME           PVAL1
---------- ----------
CPUSPEEDNW   2031.271
CPUSPEED 

Actions

Information

7 responses

19 02 2010
Anand

Hi Charles,

Thanks for making understand the %CPU column meaning so easy.

Regards,
Anand

19 02 2010
Charles Hooper

Anand,

Thank you for the compliment.

20 02 2010
Girish

Hi Charles,

Excellent explanation of %CPU column.

Regards
Girish

26 02 2010
Log Buffer #180: a Carnival of the Vanities for DBAs | The Pythian Blog

[...] Charles Hooper answers the question, What is the meaning of the %CPU column in an explain plan?. [...]

18 03 2010
Blogroll Report 12/02/2009 – 19/02/2010 « Coskan’s Approach to Oracle

[...] 25-What is %CPU in explain plan output? Charles Hooper-What is the Meaning of the %CPU Column in an Explain Plan? [...]

7 02 2011
PATRICIA

Interesante, pero como sé si x ciclos de máquina representan un costo significativo e involucran perdida de performance??

(edit: translate.google.com: Interesting, but I know if machine x cycles represent a significant cost and involve loss of performance?)

7 02 2011
Charles Hooper

Hi Patricia,

If I understand your question correctly, you are asking if it is possible to determine which SQL statements cause performance problems based on the calculated CPU_COST. I do not think that it is safe to determine which SQL statements will cause performance problem based only on the calculated CPU_COST or IO_COST – those numbers are only estimated values. It is not completely clear what the unit of measure is for the CPU_COST values, other than it is related to CPUSPEED from SYS.AUX_STATS$, which indicates the relative performance of the CPU when performing some sort of Oracle Database task (possibly directly related to the number of consistent gets that may be performed per second).

A 10046 extended SQL trace produces much better information about which queries executed by a session potentially cause performance problems. I have a three part series on my blog that describes 10046 extended SQL traces. Part 3 of the series is found here:

http://hoopercharles.wordpress.com/2010/09/06/10046-extended-sql-trace-interpretation-3/

You can process the 10046 extended SQL trace files using tkprof or many other utilities to help summarize the information, or you can look directly at the 10046 trace file. For example:

WAIT #3: nam='direct path read temp' ela= 874 file number=201 first dba=276414 block cnt=31 obj#=82052 tim=4482620835
WAIT #3: nam='asynch descriptor resize' ela= 0 outstanding #aio=0 current aio limit=4294967295 new aio limit=767 obj#=82052 tim=4482696314
WAIT #3: nam='asynch descriptor resize' ela= 1 outstanding #aio=0 current aio limit=4294967295 new aio limit=702 obj#=82052 tim=4482696416
FETCH #3:c=8704855,e=11028077,p=317918,cr=267225,cu=0,mis=0,r=1,dep=0,og=1,plh=4284856579,tim=4482696455

In the above we see “c=8704855,e=11028077″. That means fetching one row (“r=1″ in the line) required 8.704855 seconds of CPU time and 11.028077 seconds of total time.

On pages 215 through 218 of the “Expert Oracle Practices” book, Randolf Geist and I showed how to monitor the V$SQLSTATS view to watch in real-time for CPU intensive SQL statements. See the following link:

http://books.google.com/books?id=tUNtyMCwDWQC&pg=PA215#v=onepage&q&f=false

Statspack and AWR (if the database is licensed for the Diagnostics Pack) are also helpful. I have a couple of blog articles on the topic of Statspack reports, see:

http://hoopercharles.wordpress.com/2009/11/30/11-2-0-1-statspack-report-contents/

http://hoopercharles.wordpress.com/2009/12/14/statspackawr-report-resources/

Jonathan Lewis has a very well written collection of Statspack articles. You will find those articles here:

http://jonathanlewis.wordpress.com/statspack-examples/

Another approach that you can use is sampling the time model statistics. I have a three part series on that topic, with part three listed below:

http://hoopercharles.wordpress.com/2010/02/09/working-with-oracle%e2%80%99s-time-model-data-3/

Good luck.

Leave a Reply

Fill in your details below or click an icon to log in:

WordPress.com Logo

You are commenting using your WordPress.com account. Log Out / Change )

Twitter picture

You are commenting using your Twitter account. Log Out / Change )

Facebook photo

You are commenting using your Facebook account. Log Out / Change )

Google+ photo

You are commenting using your Google+ account. Log Out / Change )

Connecting to %s




Follow

Get every new post delivered to your Inbox.

Join 141 other followers

%d bloggers like this: