Home » RDBMS Server » Performance Tuning » SQL ordered by Elapsed Time (10g)
SQL ordered by Elapsed Time [message #576253] Sat, 02 February 2013 00:23 Go to next message
gatetec
Messages: 38
Registered: December 2012
Member
Elapsed Time (s)	CPU Time (s)	Executions 	Elap per Exec (s) 	% Total DB Time	SQL Id	SQL Module	SQL Text
3,263	                32	        1	        3263.49	                2.79	       3ta0ms19fvgds httpd.exe 	SELECT CASE WHEN COUNT >= 1...Elapsed 
6,360	                164	        2	        3180.17	                5.44	       51jx99dm0swv7 cpm_srvscript@ahcaxasmil1b (TNS V1-V3) 	SELECT /*+ CCL<PFT_GET_RP...


On AWR, I see two script that are out of ordinary, and I want to make sure that I interpret them correctly.

1) "Elap per Exec (s)" shows 3263.49 with 1 "Executions".
2) "Elap per Exec (s)" shows 3180.17 each execution with 2 "Executions".

Does this mean that this script ran for ~ 54 minutes (3263.49 / 60 seconds) for 1 "Execution" and ~ 53 minutes (3180.17 / 60 seconds) per each execution?
I need to understand "Elapsed Time (s), CPU Time (s), Executions , Elap per Exec (s), % Total DB Time" represent.

Thank you so much!

[Updated on: Sat, 02 February 2013 01:10]

Report message to a moderator

Re: SQL ordered by Elapsed Time [message #576255 is a reply to message #576253] Sat, 02 February 2013 01:18 Go to previous messageGo to next message
Michel Cadot
Messages: 59427
Registered: March 2007
Location: Nanterre, France, http://...
Senior Member
Account Moderator
3,263 = 1*3263.49
6,360 = 2*3180.17

For the rest, read Database Performance Tuning Guide, Chapter 5 Automatic Performance Statistics.

Regards
Michel
Re: SQL ordered by Elapsed Time [message #576257 is a reply to message #576255] Sat, 02 February 2013 01:28 Go to previous messageGo to next message
gatetec
Messages: 38
Registered: December 2012
Member
Michel Cadot wrote on Sat, 02 February 2013 01:18
3,263 = 1*3263.49
6,360 = 2*3180.17


Thank you for the info.

If I understand correctly,

The first script:

Total: ~ 54 minutes (3263.49 / 60 seconds) for 1 "Execution", but CPU Time is 32 second only, which means almost of all 54 minutes are for "Wait Time".
This implies that Disk I/O (Read or Write) was taking a long time most likely, correct?


The second script:

Total: ~ 53 minutes (3180.17 / 60 seconds) per each execution, but CPU Time = 164 seconds. So, almost 50 minutes are for "Wait Time" due to Disk I/O (Read or Write) being slow most likely. Am I correct on these?

Thank you
Re: SQL ordered by Elapsed Time [message #576259 is a reply to message #576257] Sat, 02 February 2013 01:31 Go to previous messageGo to next message
Michel Cadot
Messages: 59427
Registered: March 2007
Location: Nanterre, France, http://...
Senior Member
Account Moderator
Quote:
This implies that Disk I/O (Read or Write) was taking a long time most likely, correct?


Or other waits like network ones.

Regards
Michel
Re: SQL ordered by Elapsed Time [message #576260 is a reply to message #576259] Sat, 02 February 2013 01:40 Go to previous messageGo to next message
gatetec
Messages: 38
Registered: December 2012
Member
On [SQL ordered by Reads], I am seeing the script has very high Physical Reads.
Physical Reads	Executions	Reads per Exec 	%Total	CPU Time (s)	Elapsed Time (s)	SQL Id	SQL Module	SQL Text
237,654	1	237,654.00	4.15	        42.20	                2877.19	0vcyhc2d4v28d    httpd.exe 	SELECT CASE WHEN COUNT > 50...
160,122	1	160,122.00	2.80	        31.54	                3263.49	3ta0ms19fvgds    httpd.exe 	SELECT CASE WHEN COUNT >= 1...


That explains the long "Wait Times".

On AWR Report, I see:

SQL ordered by Elapsed Time
SQL ordered by CPU Time
SQL ordered by Gets
SQL ordered by Reads
SQL ordered by Executions
SQL ordered by Parse Calls
SQL ordered by Sharable Memory
SQL ordered by Version Count
SQL ordered by Cluster Wait Time
Complete List of SQL Text

I think [SQL ordered by Elapsed Time ] gives us the best clue on which scripts are possibly causing slowness issues. Is it true in most cases?
Re: SQL ordered by Elapsed Time [message #576261 is a reply to message #576260] Sat, 02 February 2013 01:45 Go to previous messageGo to next message
Michel Cadot
Messages: 59427
Registered: March 2007
Location: Nanterre, France, http://...
Senior Member
Account Moderator
No, you have to first refer to the Top 5/10 events on the first page of AWR report.

Please read the chapter I pointed you to (and even the whole book) and come back then if you have more questions, we can't make a complete course on AWR on a forum.

Regards
Michel

[Updated on: Sat, 02 February 2013 01:46]

Report message to a moderator

Re: SQL ordered by Elapsed Time [message #576342 is a reply to message #576261] Sun, 03 February 2013 17:28 Go to previous messageGo to next message
alan.kendall@nfl.com
Messages: 163
Registered: June 2012
Location: Culver City, California
Senior Member
In the following database 95.15% of the time spent was on a library cache lock.
ECSCDAS1S > /

WAIT_CLASS  NAME                                 TIME_SECS     PCT
----------- ------------------------------ --------------- -------
Other       CGS wait for IPC msg                     97.16     .01
Cluster     gc cr block 2-way                       100.30     .01
Application SQL*Net break/reset to client           107.52     .01
Cluster     gc current block 2-way                  108.99     .01
System I/O  db file parallel write                  109.14     .01
System I/O  log file parallel write                 111.71     .01
Other       PX Deq: Slave Session Stats             112.04     .01
Other       ASM file metadata operation             126.44     .01
Other       PX Deq: reap credit                     131.16     .01
Other       enq: WF - contention                    137.86     .01
System I/O  control file parallel write             143.34     .01
Other       DFS lock handle                         159.61     .01
Network     SQL*Net more data to client             229.51     .01
Concurrency os thread startup                       249.96     .01
Other       reliable message                        378.04     .02
User I/O    db file scattered read                  441.15     .03
User I/O    db file sequential read                 492.50     .03
Other       PX Nsq: PQ load info query              556.99     .03
System I/O  RMAN backup & recovery I/O              691.09     .04
System I/O  control file sequential read          1,837.63     .11
Network     SQL*Net more data from client         2,223.40     .13
User I/O    direct path read                      2,565.99     .15
CPU         server CPU                           71,981.42    4.16
Concurrency library cache lock                1,646,942.02   95.15

ECSCDAS1S > list
  1  SELECT
  2     wait_class,
  3     NAME,
  4     ROUND (time_secs, 2) time_secs,
  5     ROUND (time_secs * 100 / SUM (time_secs) OVER (), 2) pct
  6  FROM
  7     (SELECT
  8        n.wait_class,
  9        e.event NAME,
 10        e.time_waited / 100 time_secs
 11      FROM
 12        v$system_event e,
 13        v$event_name n
 14      WHERE
 15         n.NAME = e.event AND n.wait_class <> 'Idle'
 16      AND
 17         time_waited > 0
 18      UNION
 19      SELECT
 20        'CPU',
 21        'server CPU',
 22        SUM (VALUE / 1000000) time_secs
 23      FROM
 24        v$sys_time_model
 25      WHERE
 26        stat_name IN ('background cpu time', 'DB CPU'))
 27  ORDER BY
 28*    time_secs
Re: SQL ordered by Elapsed Time [message #576360 is a reply to message #576342] Mon, 04 February 2013 01:20 Go to previous messageGo to next message
Michel Cadot
Messages: 59427
Registered: March 2007
Location: Nanterre, France, http://...
Senior Member
Account Moderator
The problem of these queries on v$ views is that the statistics are cumulative since the beginning of the instance and so can't give information on a period and even on a previous instance and when instances are never or seldom shut down (which is more and more the cases) they are useless.

Regards
Michel
Re: SQL ordered by Elapsed Time [message #576414 is a reply to message #576360] Mon, 04 February 2013 12:48 Go to previous messageGo to next message
alan.kendall@nfl.com
Messages: 163
Registered: June 2012
Location: Culver City, California
Senior Member
Michel,

I also have a version of this script, where I take a snapshot, wait one minute, take another snapshot and then display the difference. I sometimes take snapshots ten minutes apart. This will tell me what is happening now. I use this when the load on a Linux box goes so high (in the hundreds) that I cannot run the awr reports.
ECSESBP1 > @v$sys_time_model_top_Waits_with_BACK_GROUND_60.sql

WAIT_CLASS  NAME                                 TIME_SECS     PCT
----------- ------------------------------ --------------- -------
System I/O  control file parallel write                .01     .01
Cluster     gc current grant busy                      .01     .01
System I/O  log file sequential read                   .01     .01
Commit      log file sync                              .02     .02
Cluster     gc current block 2-way                     .02     .02
Cluster     gc cr block 2-way                          .02     .02
System I/O  log file parallel write                    .02     .02
Other       gcs log flush sync                         .03     .03
System I/O  db file parallel write                     .04     .05
System I/O  Log archive I/O                            .08     .09
User I/O    db file sequential read                    .13     .15
System I/O  control file sequential read               .33     .38
Network     LNS wait on SENDREQ                       1.74    2.01
CPU         server CPU                                5.61    6.47
Network     ARCH wait on SENDREQ                     78.59   90.69

On another database:
ENWEBTT > @v$sys_time_model_top_Waits_with_BACK_GROUND_60.sql

WAIT_CLASS  NAME                                 TIME_SECS     PCT
----------- ------------------------------ --------------- -------
User I/O    direct path write temp                     .00     .00
User I/O    db file scattered read                     .00     .00
System I/O  RMAN backup & recovery I/O                 .00     .00
User I/O    direct path write                          .00     .00
Network     SQL*Net message to client                  .01     .06
User I/O    Disk file operations I/O                   .01     .06
Network     SQL*Net more data from client              .02     .12
Network     SQL*Net more data to client                .02     .12
User I/O    db file sequential read                    .03     .18
System I/O  db file async I/O submit                   .10     .62
Commit      log file sync                              .23    1.42
System I/O  control file parallel write                .30    1.85
System I/O  log file parallel write                    .45    2.77
User I/O    direct path read                          2.70   16.64
CPU         server CPU                               12.36   76.16

The full sql follows.
COLUMN wait_class format a11
COLUMN name       format a30
COLUMN time_secs  format 999,999,999.99
COLUMN pct        format 999.99
set pages 40
set termout off
drop table v$sys_time_model_alana purge;
drop table v$sys_time_model_alanb purge;
drop table alanc purge;
create table v$sys_time_model_alana as
SELECT   
   wait_class, 
   NAME, 
   ROUND (time_secs, 2) time_secs,
   ROUND (time_secs * 100 / SUM (time_secs) OVER (), 2) pct
FROM 
   (SELECT 
      n.wait_class, 
      e.event NAME, 
      e.time_waited / 100 time_secs
    FROM 
      v$system_event e, 
      v$event_name n
    WHERE 
       n.NAME = e.event AND n.wait_class <> 'Idle'
    AND 
       time_waited > 0
    UNION
    SELECT 
      'CPU', 
      'server CPU', 
      SUM (VALUE / 1000000) time_secs
    FROM 
      v$sys_time_model
    WHERE 
      stat_name IN ('background cpu time', 'DB CPU'))
ORDER BY 
   time_secs;

execute dbms_lock.sleep(60);

create table v$sys_time_model_alanb as
SELECT   
   wait_class, 
   NAME, 
   ROUND (time_secs, 2) time_secs,
   ROUND (time_secs * 100 / SUM (time_secs) OVER (), 2) pct
FROM 
   (SELECT 
      n.wait_class, 
      e.event NAME, 
      e.time_waited / 100 time_secs
    FROM 
      v$system_event e, 
      v$event_name n
    WHERE 
       n.NAME = e.event AND n.wait_class <> 'Idle'
    AND 
       time_waited > 0
    UNION
    SELECT 
      'CPU', 
      'server CPU', 
      SUM (VALUE / 1000000) time_secs
    FROM 
      v$sys_time_model
    WHERE 
      stat_name IN ('background cpu time', 'DB CPU'))
ORDER BY 
   time_secs;
set termout on
create table alanc as select sum(b.TIME_SECS-a.TIME_SECS) times 
from v$sys_time_model_alanb b, v$sys_time_model_alana a
where b.WAIT_CLASS=a.wait_class and b.NAME=a.name;
select b.WAIT_CLASS,b.NAME,
(b.TIME_SECS-a.TIME_SECS)*1 time_secs,
(b.TIME_SECS-a.TIME_SECS)/decode(c.times,0,1,c.times)*100 "PCT"
from v$sys_time_model_alanb b, v$sys_time_model_alana a, alanc c
where b.WAIT_CLASS=a.wait_class and b.NAME=a.name
order by 4,3;


Re: SQL ordered by Elapsed Time [message #576416 is a reply to message #576414] Mon, 04 February 2013 12:53 Go to previous message
Michel Cadot
Messages: 59427
Registered: March 2007
Location: Nanterre, France, http://...
Senior Member
Account Moderator
My remark is just to point to the limits of the script.

Regards
Michel
Previous Topic: How can we verify the statistic info is not good
Next Topic: ADDM Report
Goto Forum:
  


Current Time: Sun Oct 26 02:17:42 CDT 2014

Total time taken to generate the page: 0.04382 seconds