We used this to quickly determine where a specific session was spending its time. This simply creates associative arrays for events, the time waited, and the total number of waits for that event, all at a specific point in time. The script then sleeps a user specified number of seconds, then loads a second set of associative arrays with similar data, only at the then current point in time.
Finally, it does the math for each event and prints the number of seconds spent on each event for the period of time specified, as well as the average number of milliseconds waited for each event in that session.
set serveroutput on set feedback off verify off variable v1 number exec :v1 := &sid variable instance_id number exec :instance_id := &instance_id variable sleep_time number exec :sleep_time := &sleep_time declare type t_vals1 is table of varchar2(100); type t_vals2 is table of number; vals1 t_vals1 := t_vals1(); vals2 t_vals2 := t_vals2(); vals3 t_vals1 := t_vals1(); vals4 t_vals2 := t_vals2(); vals5 t_vals1 := t_vals1(); vals6 t_vals2 := t_vals2(); i number := 0; j number := 0; m number := 0; k number := 0; l number := 0; begin for cur in (select event,time_waited_micro,total_waits from gv$session_event where sid = :v1 and inst_id = :instance_id order by time_waited) loop vals1.extend(1); vals2.extend(1); vals5.extend(1); i := i + 1; vals1(i) := cur.event; vals2(i) := cur.time_waited_micro; vals5(i) := cur.total_waits; end loop; dbms_lock.sleep(:sleep_time); for cur in (select event,time_waited_micro,total_waits from gv$session_event where sid = :v1 and inst_id = :instance_id order by time_waited) loop vals3.extend(1); vals4.extend(1); vals6.extend(1); j := j + 1; vals3(j) := cur.event; vals4(j) := cur.time_waited_micro; vals6(j) := cur.total_waits; end loop; k := i; l := 0; dbms_output.put_line('========================================================'); while l < k loop l := l + 1; if vals1(l) = vals3(l) then if vals4(l) > vals2(l) then dbms_output.put_line(vals1(l) || ' ' || (round((vals4(l) - vals2(l))/1000000,1)) || ' seconds (' || (round((vals4(l) - vals2(l))/1000/((vals6(l) - vals5(l))),1)) || ' average millis)'); end if; end if; end loop; dbms_output.put_line('========================================================'); end; / exit
For example, below we can see the session is spending most of its time on single block I/O, but the average response time is reasonable at 7.2 milliseconds.
SQL> @waits Enter value for sid: 9555 Enter value for instance_id: 1 Enter value for sleep_time: 10 ======================================================== gc cr grant congested 0 seconds (.4 average millis) gc current block 2-way 0 seconds (.3 average millis) gc current grant congested 0 seconds (.3 average millis) SQL*Net message to client 0 seconds (0 average millis) gc cr grant 2-way .1 seconds (.3 average millis) gc current grant busy .1 seconds (.7 average millis) gc current grant 2-way .2 seconds (.4 average millis) SQL*Net message from client .4 seconds (.2 average millis) db file sequential read 8.3 seconds (7.2 average millis) ========================================================