Tuesday, May 29, 2007

Modifying sprepins.sql for Custom Statspack Reports II

My last post was about modifying $ORACLE_HOME/rdbms/admin/sprepins.sql which is the script that produces the statspack report.

Another change I make in my sprepins.sql is about the section "Top 5 Timed Events". In 9.2 this section lists the wait events and CPU time and their percentages contributing to the database time. This way we can see which wait event caused most of the waits for that period or if it is CPU time that takes most of the time. 8.1.7 has a section titled "Top 5 Wait Events" and does not include CPU time in this section. I originally made this change for 8.1.7 to include CPU time in that section but I am still using it in 9.2 with a few changes. This last version is tested in 9.2.

In this modification I divide the CPU time into 3 parts as described in Metalink note 232443.1. as "parse time cpu", "recursive cpu usage" and "cpu other". "parse time cpu" is the time spent in parsing, "recursive cpu usage" is the time spent in recursive calls such as plsql calls from sql and "cpu other" is the remaining cpu time. This way when I look at the Top 10 Timed Events section (I list 10 events not 5) I can see which part consumes more time and if it is a problem or not.

After this change you will have a new section titled "Top 10 Timed Events" like below.


Top 10 Timed Events
~~~~~~~~~~~~~~~~~~~ Wait
Event Time (s) % TOTAL TIME
-------------------------------------------- ------------ ------------
SQL*Net message from dblink 4,700 36.01
cpu other 2,928 22.43
recursive cpu usage 2,479 19
SQL*Net more data to client 587 4.49
enqueue 456 3.49
sbtwrite2 372 2.85
async disk IO 354 2.71
log file parallel write 261 2
db file sequential read 244 1.87
single-task message 188 1.44


To make this change find the following lines in sprepins.sql.

set heading on;
repfooter left -
'-------------------------------------------------------------';

--
-- Top Wait Events


Just above this add the following lines.

----------------------------------------TOP 10 TIMED EVENTS--------------------------------------
set heading on;
repfooter left -

col event format a44 heading 'Top 10 Timed Events|~~~~~~~~~~~~~~~~~~~|Event';
col time_waited format 999,999,990 heading 'Wait|Time (s)' just c;
col pct format 999.99 heading '% Total|Time';

SELECT NAME "EVENT",VALUE "TIME_WAITED",ROUND(PCT_TOTAL*100,2) "% TOTAL TIME"
FROM (SELECT NAME, VALUE, ratio_to_report (VALUE) OVER () pct_total
FROM (SELECT s1.NAME, (s1.VALUE - s2.VALUE)/100 VALUE
FROM stats$sysstat s1, stats$sysstat s2
WHERE s1.NAME IN
('recursive cpu usage',
'parse time cpu')
AND s1.NAME = s2.NAME
AND s1.snap_id = :eid
AND s2.snap_id = :bid
UNION ALL
SELECT 'cpu other', diff/100
FROM (SELECT NAME, VALUE,
VALUE
- (LEAD (VALUE, 1) OVER (ORDER BY NAME))
- (LEAD (VALUE, 2) OVER (ORDER BY NAME))
diff
FROM (SELECT s1.NAME, s1.VALUE - s2.VALUE VALUE
FROM stats$sysstat s1, stats$sysstat s2
WHERE s1.NAME IN
('recursive cpu usage',
'parse time cpu',
'CPU used by this session'
)
AND s1.NAME = s2.NAME
AND s1.snap_id = :eid
AND s2.snap_id = :bid))
WHERE NAME = 'CPU used by this session'
UNION ALL
SELECT event, time_waited
FROM (SELECT s1.event,
(s1.time_waited_micro - nvl(s2.time_waited_micro,0))/1000000 time_waited,
ratio_to_report ( s1.time_waited_micro
- nvl(s2.time_waited_micro,0)
) OVER () pct
FROM stats$system_event s1, stats$system_event s2
WHERE s1.event = s2.event
AND s1.snap_id = :eid
AND s2.snap_id = :bid
AND s1.event NOT IN (SELECT event
FROM stats$idle_event
)))
ORDER BY pct_total DESC)
WHERE ROWNUM <= 10; ---------------------------------------END TOP 10 TIMED EVENTS-------------------------


With the help of this section I can see what the top 10 events are including the parts of CPU time and drill down from there to find the cause.

The next post will be about adding a "Rows Processed" column to the "SQL ordered by Gets" section and the removal of the sections "Rollback Segment Stats" and "Rollback Segment Storage" for databases with automatic undo management.

0 comments: