measuring cpu time in 10g

Developers have long been familiar with the DBMS_UTILITY.GET_TIME function. It is commonly used in test harnesses for measuring the elapsed time between two points in a process. In 10g, Oracle has added to this with the DBMS_UTILITY.GET_CPU_TIME function. This new function enables us to measure the amount of CPU time used between two points. This short article demonstrates the difference between the new GET_CPU_TIME function and the existing GET_TIME function.

a cpu-bound example

The first example below is CPU-intensive; there is no I/O. This highlights the fact that for CPU-bound operations, the GET_TIME and GET_CPU_TIME return roughly the same timing (allowing for +/- measurement error). Note that like GET_TIME, GET_CPU_TIME measures in hundredths of a second.

SQL> DECLARE
  2  
  3     b1 PLS_INTEGER;
  4     b2 PLS_INTEGER;
  5     e1 PLS_INTEGER;
  6     e2 PLS_INTEGER;
  7  
  8  BEGIN
  9  
 10     b1 := DBMS_UTILITY.GET_TIME();
 11     b2 := DBMS_UTILITY.GET_CPU_TIME();
 12  
 13     FOR i IN 1 .. 100000000 LOOP
 14        NULL;
 15     END LOOP;
 16  
 17     e1 := DBMS_UTILITY.GET_TIME() - b1;
 18     e2 := DBMS_UTILITY.GET_CPU_TIME() - b2;
 19  
 20     DBMS_OUTPUT.PUT_LINE( 'GET_TIME elapsed = ' || e1 || ' hsecs.' );
 21     DBMS_OUTPUT.PUT_LINE( 'GET_CPU_TIME elapsed = ' || e2 || ' hsecs.' );
 22  
 23  END;
 24  /

GET_TIME elapsed = 157 hsecs.
GET_CPU_TIME elapsed = 158 hsecs.

PL/SQL procedure successfully completed.

an i/o bound example

This time we'll take a look at an example that includes some I/O. This is possibly more representative of a typical PL/SQL workload that mixes data access with procedural logic. We can now see a difference in the reported timings.

SQL> DECLARE
  2  
  3     b1 PLS_INTEGER;
  4     b2 PLS_INTEGER;
  5     e1 PLS_INTEGER;
  6     e2 PLS_INTEGER;
  7  
  8  BEGIN
  9  
 10     b1 := DBMS_UTILITY.GET_TIME();
 11     b2 := DBMS_UTILITY.GET_CPU_TIME();
 12  
 13     FOR r IN ( SELECT * FROM all_source ) LOOP
 14        NULL;
 15     END LOOP;
 16  
 17     e1 := DBMS_UTILITY.GET_TIME() - b1;
 18     e2 := DBMS_UTILITY.GET_CPU_TIME() - b2;
 19  
 20     DBMS_OUTPUT.PUT_LINE( 'GET_TIME elapsed = ' || e1 || ' hsecs.' );
 21     DBMS_OUTPUT.PUT_LINE( 'GET_CPU_TIME elapsed = ' || e2 || ' hsecs.' );
 22  
 23  END;
 24  /

GET_TIME elapsed = 278 hsecs.
GET_CPU_TIME elapsed = 175 hsecs.

PL/SQL procedure successfully completed.

source code

The source code for the examples in this article can be downloaded from here.

Adrian Billington, June 2004

oracle-developer.net