Hopefully this is not too redundant to previous posts but I’ve found that I keep using a particular script to debug performance issues and I thought I’d share it and explain what I use it for. It’s helpful to me so I’m sure someone could use it unless they have their own tools which meet the same needs.
The first usergroup presentation I did was on the topic of profiles and was based on things I had learned a variety of places including Jeff Holt and Cary Millsap’s excellent book titled “Optimizing Oracle Performance”.
Out of all that came a simple set of SQL and sqlplus commands that I tag on to the end of a sqlplus script that I want to get a profile of. In my case a profile includes:
- Real Elapsed time
- CPU
- Waits
The main point of my paper and the critical point I got from the Holt and Millsap book and other things was to compare the total waits and CPU to the real time. So, this SQL/sqlplus code is a quick and dirty way to get this kind of profile for a sqlplus script that you are running as part of a performance testing exercise. Here is the code:
VARIABLE monitored_sid number;
begin
SELECT sid into :monitored_sid from v$session
where audsid=USERENV('SESSIONID');
end;
/
SELECT SID, substr(USERNAME,1,12) Username,
substr(TIMESOURCE,1,30), SECONDS,
ROUND(SECONDS/(SELECT ROUND((SYSDATE-LOGON_TIME)*24*60*60,0)
FROM V$SESSION WHERE SID= :monitored_sid),2)*100
AS PERCENTAGE
FROM
(SELECT logon_time, SID, username, 'TOTAL_TIME' TIMESOURCE,
ROUND((SYSDATE-LOGON_TIME)*24*60*60,0) SECONDS
FROM V$SESSION
WHERE SID= :monitored_sid
UNION ALL
SELECT a.logon_time, a.SID,a.USERNAME,'CPU' TIMESOURCE,
ROUND((VALUE/100),0) SECONDS
FROM V$SESSION a, V$SESSTAT b
where a.SID = b.SID
and a.SID = :monitored_sid
and b.STATISTIC# = (SELECT STATISTIC# FROM V$STATNAME
WHERE NAME='CPU used by this session')
UNION ALL
SELECT b.logon_time, a.SID,b.USERNAME,a.EVENT TIMESOURCE,
ROUND((TIME_WAITED/100),0) SECONDS
FROM V$SESSION_EVENT a, V$SESSION b
WHERE a.SID = b.SID
AND a.SID= :monitored_sid
UNION ALL
select b.logon_time, a.sid, b.username,
'UNACCOUNTED_TIME' TIMESOURCE,
ROUND(MAX(SYSDATE-LOGON_TIME)*24*60*60,0)-
(ROUND(SUM((TIME_WAITED/100)),0)+ROUND(MAX(VALUE/100),0))
as UNACCOUNTED_FOR_TIME
FROM V$SESSION_EVENT a, V$SESSION b, V$SESSTAT c
WHERE a.SID = b.SID
AND b.sid = c.sid
and c.STATISTIC# = (SELECT STATISTIC# FROM V$STATNAME
WHERE NAME='CPU used by this session')
AND a.SID= :monitored_sid
group by b.logon_time, a.sid, b.username)
order by SECONDS desc;
And here is some typical output:
SUBSTR(TIMESOURCE,1,30) SECONDS PERCENTAGE ------------------------------ ---------- ---------- TOTAL_TIME 43 100 direct path read 30 70 CPU 5 12 db file scattered read 4 9 db file sequential read 4 9 Disk file operations I/O 0 0 SQL*Net message to client 0 0 SQL*Net message from client 0 0 events in waitclass Other 0 0 enq: KO - fast object checkpoi 0 0 UNACCOUNTED_TIME -1 -2
I left off the initial SID and username columns so the output would fit on this page, but if you run it you get that information as well. The output contains waits and CPU which I think are typical but the two values TOTAL_TIME and UNACCOUNTED_TIME may be unusual.
TOTAL_TIME is the real elapsed time since the user first logged in to this session.
UNACCOUNTED_TIME is TOTAL_TIME-sum of the waits and CPU. If there is a lot of queuing for the CPU then UNACCOUNTED_TIME goes up.
Here is a zip of an example of the use of this code in a script.
The idea is that you run the script like this:
username/password@dbname < profileexample.sql
If you want to learn how to use this kind of profile I would encourage you to read the paper, but the short answer is to just look at which is the biggest consumer of time – CPU, a particular wait, or something unknown, and let that lead the next steps of your investigation.
– Bobby
