Calculating waits for a session for a given time window

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)
========================================================