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.<\/p>\n
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.<\/p>\n
\r\nset serveroutput on\r\nset feedback off verify off\r\n\r\nvariable v1 number\r\nexec :v1 := &sid\r\n\r\nvariable instance_id number\r\nexec :instance_id := &instance_id\r\n\r\nvariable sleep_time number\r\nexec :sleep_time := &sleep_time\r\n\r\ndeclare\r\n type t_vals1 is table of varchar2(100);\r\n type t_vals2 is table of number;\r\n vals1 t_vals1 := t_vals1();\r\n vals2 t_vals2 := t_vals2();\r\n vals3 t_vals1 := t_vals1();\r\n vals4 t_vals2 := t_vals2();\r\n vals5 t_vals1 := t_vals1();\r\n vals6 t_vals2 := t_vals2();\r\n i number := 0;\r\n j number := 0;\r\n m number := 0;\r\n k number := 0;\r\n l number := 0;\r\nbegin\r\n for cur in (select event,time_waited_micro,total_waits\r\n from gv$session_event\r\n where sid = :v1\r\n and inst_id = :instance_id\r\n order by time_waited) loop\r\n vals1.extend(1);\r\n vals2.extend(1);\r\n vals5.extend(1);\r\n i := i + 1;\r\n vals1(i) := cur.event;\r\n vals2(i) := cur.time_waited_micro;\r\n vals5(i) := cur.total_waits;\r\n end loop;\r\n dbms_lock.sleep(:sleep_time);\r\n for cur in (select event,time_waited_micro,total_waits\r\n from gv$session_event\r\n where sid = :v1\r\n and inst_id = :instance_id\r\n order by time_waited) loop\r\n vals3.extend(1);\r\n vals4.extend(1);\r\n vals6.extend(1);\r\n j := j + 1;\r\n vals3(j) := cur.event;\r\n vals4(j) := cur.time_waited_micro;\r\n vals6(j) := cur.total_waits;\r\n end loop;\r\n k := i;\r\n l := 0;\r\n dbms_output.put_line('========================================================');\r\n while l < k loop\r\n l := l + 1;\r\n if vals1(l) = vals3(l) then\r\n if vals4(l) > vals2(l) then\r\n 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)');\r\n end if;\r\n end if;\r\n end loop;\r\n dbms_output.put_line('========================================================');\r\nend;\r\n\/\r\nexit\r\n<\/pre>\nFor 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.<\/p>\n
\r\nSQL> @waits\r\nEnter value for sid: 9555\r\nEnter value for instance_id: 1\r\nEnter value for sleep_time: 10\r\n========================================================\r\ngc cr grant congested 0 seconds (.4 average millis)\r\ngc current block 2-way 0 seconds (.3 average millis)\r\ngc current grant congested 0 seconds (.3 average millis)\r\nSQL*Net message to client 0 seconds (0 average millis)\r\ngc cr grant 2-way .1 seconds (.3 average millis)\r\ngc current grant busy .1 seconds (.7 average millis)\r\ngc current grant 2-way .2 seconds (.4 average millis)\r\nSQL*Net message from client .4 seconds (.2 average millis)\r\ndb file sequential read 8.3 seconds (7.2 average millis)\r\n========================================================\r\n<\/pre>\n","protected":false},"excerpt":{"rendered":"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.…<\/p>\n