Home » RDBMS Server » Performance Tuning » Digging out the Wait events.
Digging out the Wait events. [message #598574] Tue, 15 October 2013 14:48 Go to next message
VIP2013
Messages: 84
Registered: June 2013
Member
I am using 11.2.0.3.0 version of oracle. As told by the DBAs that two days back the system realised high wait_class i.e 'Application' wait, and its a lot high than regular value as per our system and we need to dig it down, to avoid any future issue. now using below query , i found that the high wait time due to wait class 'Application' is actually belongs to particular event 'SQL*Net break/reset to client', and the sample time was '9 AM' morning.

select time, 
           round(max(case when event = 'SQL*Net break/reset to client' then time_waited_delta/1e3/decode(total_waits_delta,0,1,nvl(total_waits_delta,1)) end) ,2) SQL_break_reset_client, 
           round(max(case when event = 'Wait for Table Lock' then time_waited_delta/1e3/decode(total_waits_delta,0,1,nvl(total_waits_delta,1)) end),2) Wait_for_Table_Lock ,
           round(max(case when event = 'enq: KO - fast object checkpoint' then time_waited_delta/1e3/decode(total_waits_delta,0,1,nvl(total_waits_delta,1)) end),2) enq_KO_fast_object_checkpoint ,
           round(max(case when event = 'enq: RO - fast object reuse' then time_waited_delta/1e3/decode(total_waits_delta,0,1,nvl(total_waits_delta,1)) end),2) enq_RO_fast_object_reuse ,
           round(max(case when event = 'enq: TM - contention' then time_waited_delta/1e3/decode(total_waits_delta,0,1,nvl(total_waits_delta,1)) end),2) enq_TM_contention ,
           round(max(case when event = 'enq: TX - row lock contention' then time_waited_delta/1e3/decode(total_waits_delta,0,1,nvl(total_waits_delta,1)) end),2) enq_TX_row_lock_contention ,
          round( max(case when event = 'enq: UL - contention' then time_waited_delta/1e3/decode(total_waits_delta,0,1,nvl(total_waits_delta,1)) end),2)  enq_UL_contention 
   from 
   ( 
       select sn.begin_interval_time- time, 
               e.event_name event, 
               e.wait_class wait_class,
               e.total_waits - lag(e.total_waits) over(partition by e.event_name order by e.snap_id) total_waits_delta, 
               e.time_waited_micro - lag(e.time_waited_micro) over(partition by e.event_name order by e.snap_id) time_waited_delta 
       from DBA_HIST_SYSTEM_EVENT e, 
             DBA_HIST_SNAPSHOT sn 
       where e.snap_id = sn.snap_id 
       AND sn.end_interval_time >= TO_DATE (TRIM ('14-Oct-2013 8:30:00'), 'dd-mon-yyyy hh24:mi:ss')
     AND sn.begin_interval_time <= TO_DATE (TRIM ('14-oct-2013 9:00:00 '), 'dd-mon-yyyy hh24:mi:ss')
      	and wait_class in ('Application')   
   ) 
   group by time 
   order by time desc; 


Now i want to track it down further to the 'session/sql query/application' level resulting into such high value of wait time. so i queried, dba_hist_active_session_history, for the same sample duration (8.30 to 9 am) having event 'SQL*Net break/reset to client', and got two sessions(123,154) and their serial# , but there i got one sql_id(3ahgrey10ogh i.e a 'SELECT' query) specific to one session(123) but for other(125) no sqlid, and also SUM (wait_time + time_waited) is showing '0'.

Then i just removed the sampletime filter from the below query and observed that the same 'same session(123)+session serial#' was activated since 4 days back and was experiencing same waitevent 'SQL*Net break/reset to client', (it was having normal wait event 'db file sequential read' for sometime then after it went for this event ). So now, i just stuck and could not able to move further, could you please help me to dig down the issue, that is finding actual culprit.

SELECT user_id,
         PROGRAM,
         machine,
         session_id,
         SESSION_SERIAL#,
         sample_time-7/24,
         session_state,
         event,
         wait_time / 1000 wait_time_sec,
         time_waited / 1000 time_waited_sec,
         sql_id,
         blocking_session,
         BLOCKING_SESSION_SERIAL#,
         BLOCKING_SESSION_STATUS,
         BLOCKING_HANGCHAIN_INFO,
         BLOCKING_HANGCHAIN_INFO,
         (SELECT sql_text
            FROM dba_hist_sqltext
           WHERE sql_id = DBA_HIST_ACTIVE_SESS_HISTORY.sql_id AND ROWNUM < 2),
         (SELECT object_name
            FROM dba_objects
           WHERE object_id = DBA_HIST_ACTIVE_SESS_HISTORY.current_obj#
                 AND ROWNUM < 2),
         sql_child_number CH#
    FROM DBA_HIST_ACTIVE_SESS_HISTORY
   WHERE  session_id = 123
         AND session_serial# = 4563
ORDER BY sample_time ;
Re: Digging out the Wait events. [message #598579 is a reply to message #598574] Tue, 15 October 2013 15:00 Go to previous messageGo to next message
BlackSwan
Messages: 22490
Registered: January 2009
Senior Member
bad SQL posted

 1  select time,
  2             round(max(case when event = 'SQL*Net break/reset to client' then time_waited_delta/1e3/decode(total_waits_delta,0,1,nvl(total_waits_delta,1)) end) ,2) SQL_break_reset_client,
  3             round(max(case when event = 'Wait for Table Lock' then time_waited_delta/1e3/decode(total_waits_delta,0,1,nvl(total_waits_delta,1)) end),2) Wait_for_Table_Lock ,
  4             round(max(case when event = 'enq: KO - fast object checkpoint' then time_waited_delta/1e3/decode(total_waits_delta,0,1,nvl(total_waits_delta,1)) end),2) enq_KO_fast_object_checkpoint ,
  5             round(max(case when event = 'enq: RO - fast object reuse' then time_waited_delta/1e3/decode(total_waits_delta,0,1,nvl(total_waits_delta,1)) end),2) enq_RO_fast_object_reuse ,
  6             round(max(case when event = 'enq: TM - contention' then time_waited_delta/1e3/decode(total_waits_delta,0,1,nvl(total_waits_delta,1)) end),2) enq_TM_contention ,
  7             round(max(case when event = 'enq: TX - row lock contention' then time_waited_delta/1e3/decode(total_waits_delta,0,1,nvl(total_waits_delta,1)) end),2) enq_TX_row_lock_contention ,
  8            round( max(case when event = 'enq: UL - contention' then time_waited_delta/1e3/decode(total_waits_delta,0,1,nvl(total_waits_delta,1)) end),2)  enq_UL_contention
  9     from
 10     (
 11         select sn.begin_interval_time- time,
 12                 e.event_name event,
 13                 e.wait_class wait_class,
 14                 e.total_waits - lag(e.total_waits) over(partition by e.event_name order by e.snap_id) total_waits_delta,
 15                 e.time_waited_micro - lag(e.time_waited_micro) over(partition by e.event_name order by e.snap_id) time_waited_delta
 16         from DBA_HIST_SYSTEM_EVENT e,
 17               DBA_HIST_SNAPSHOT sn
 18         where e.snap_id = sn.snap_id
 19         AND sn.end_interval_time >= TO_DATE (TRIM ('14-Oct-2013 8:30:00'), 'dd-mon-yyyy hh24:mi:ss')
 20       AND sn.begin_interval_time <= TO_DATE (TRIM ('14-oct-2013 9:00:00 '), 'dd-mon-yyyy hh24:mi:ss')
 21             and wait_class in ('Application')
 22     )
 23     group by time
 24*    order by time desc
SQL> /
       select sn.begin_interval_time- time,
                                      *
ERROR at line 11:
ORA-00904: "TIME": invalid identifier


SQL> 


Re: Digging out the Wait events. [message #598580 is a reply to message #598579] Tue, 15 October 2013 15:04 Go to previous messageGo to next message
VIP2013
Messages: 84
Registered: June 2013
Member
its as below

select time, 
           round(max(case when event = 'SQL*Net break/reset to client' then time_waited_delta/1e3/decode(total_waits_delta,0,1,nvl(total_waits_delta,1)) end) ,2) SQL_break_reset_client, 
           round(max(case when event = 'Wait for Table Lock' then time_waited_delta/1e3/decode(total_waits_delta,0,1,nvl(total_waits_delta,1)) end),2) Wait_for_Table_Lock ,
           round(max(case when event = 'enq: KO - fast object checkpoint' then time_waited_delta/1e3/decode(total_waits_delta,0,1,nvl(total_waits_delta,1)) end),2) enq_KO_fast_object_checkpoint ,
           round(max(case when event = 'enq: RO - fast object reuse' then time_waited_delta/1e3/decode(total_waits_delta,0,1,nvl(total_waits_delta,1)) end),2) enq_RO_fast_object_reuse ,
           round(max(case when event = 'enq: TM - contention' then time_waited_delta/1e3/decode(total_waits_delta,0,1,nvl(total_waits_delta,1)) end),2) enq_TM_contention ,
           round(max(case when event = 'enq: TX - row lock contention' then time_waited_delta/1e3/decode(total_waits_delta,0,1,nvl(total_waits_delta,1)) end),2) enq_TX_row_lock_contention ,
          round( max(case when event = 'enq: UL - contention' then time_waited_delta/1e3/decode(total_waits_delta,0,1,nvl(total_waits_delta,1)) end),2)  enq_UL_contention 
   from 
   ( 
       select sn.begin_interval_time time, 
               e.event_name event, 
               e.wait_class wait_class,
               e.total_waits - lag(e.total_waits) over(partition by e.event_name order by e.snap_id) total_waits_delta, 
               e.time_waited_micro - lag(e.time_waited_micro) over(partition by e.event_name order by e.snap_id) time_waited_delta 
       from DBA_HIST_SYSTEM_EVENT e, 
             DBA_HIST_SNAPSHOT sn 
       where e.snap_id = sn.snap_id 
       AND sn.end_interval_time >= TO_DATE (TRIM ('14-Oct-2013 8:30:00'), 'dd-mon-yyyy hh24:mi:ss')
     AND sn.begin_interval_time <= TO_DATE (TRIM ('14-oct-2013 9:00:00 '), 'dd-mon-yyyy hh24:mi:ss')
      	and wait_class in ('Application')   
   ) 
   group by time 
   order by time desc; 
Re: Digging out the Wait events. [message #598583 is a reply to message #598580] Tue, 15 October 2013 15:11 Go to previous messageGo to next message
BlackSwan
Messages: 22490
Registered: January 2009
Senior Member
my results are duly undewhelming.
SQL> /

TIME
---------------------------------------------------------------------------
SQL_BREAK_RESET_CLIENT WAIT_FOR_TABLE_LOCK ENQ_KO_FAST_OBJECT_CHECKPOINT
---------------------- ------------------- -----------------------------
ENQ_RO_FAST_OBJECT_REUSE ENQ_TM_CONTENTION ENQ_TX_ROW_LOCK_CONTENTION
------------------------ ----------------- --------------------------
ENQ_UL_CONTENTION
-----------------
14-OCT-13 08.00.03.096 AM





SQL> 


So what exactly do you see?
Re: Digging out the Wait events. [message #598586 is a reply to message #598583] Tue, 15 October 2013 15:18 Go to previous messageGo to next message
VIP2013
Messages: 84
Registered: June 2013
Member
it means in your database, there exists no such 'Application' waits within that sample time. But you should see at least zero values. I am pasting part of my results.

TIME	SQL_BREAK_RESET_CLIENT	WAIT_FOR_TABLE_LOCK	ENQ_KO_FAST_OBJECT_CHECKPOINT	ENQ_RO_FAST_OBJECT_REUSE	ENQ_TM_CONTENTION	ENQ_TX_ROW_LOCK_CONTENTION	ENQ_UL_CONTENTION
10/14/2013 08:30:14	0	0	0	0	0	775	283
10/14/2013 08:20:10	492,1	0	0	0	0	3,453	428
10/14/2013 08:10:06	1	0	0	0	0	1,567	360

[Updated on: Tue, 15 October 2013 15:19]

Report message to a moderator

Re: Digging out the Wait events. [message #598599 is a reply to message #598586] Tue, 15 October 2013 18:35 Go to previous messageGo to next message
BlackSwan
Messages: 22490
Registered: January 2009
Senior Member
I am confused by the following "value"; 492,1
I am confused by the following "value"; 3,453
I am confused by the following "value"; 1,567

rounded to the nearest whole integer what are each of the values displayed above?
Re: Digging out the Wait events. [message #598740 is a reply to message #598599] Thu, 17 October 2013 05:47 Go to previous messageGo to next message
VIP2013
Messages: 84
Registered: June 2013
Member
Each of the values are wait time for respective event for that snap time.

here , i want to validate , if my approach of digging down the issue is correct or not.

After getting high wait events and the exact time of occurrence, from DBA_HIST_SYSTEM_EVENT and DBA_HIST_SNAPSHOT data dictionaries, i am digging down the exact 'session/sql query' level info from DBA_HIST_ACTIVE_SESSION_HISTORY for the same sample time duration, is this correct approach? Or is there exist some other data dictionary which i should use for this info?

Actually the 'SUM (wait_time + time_waited) / 1000' from dba_hist_active_session_history is not matching with the time that i got from DBA_HIST_SYSTEM_EVENT . So confused .

[Updated on: Thu, 17 October 2013 05:47]

Report message to a moderator

Re: Digging out the Wait events. [message #598750 is a reply to message #598740] Thu, 17 October 2013 06:49 Go to previous messageGo to next message
Roachcoach
Messages: 1178
Registered: May 2010
Location: UK
Senior Member
dba_hist_active_session_history is a (30 second?) snapshot of v$active_session_history which is itself a snapshot of the DB at points in time. Point being they are collections of samples, not exhaustive sources.
Re: Digging out the Wait events. [message #598757 is a reply to message #598750] Thu, 17 October 2013 08:13 Go to previous messageGo to next message
BlackSwan
Messages: 22490
Registered: January 2009
Senior Member
I am confused by the following "value"; 492,1
I am confused by the following "value"; 3,453
I am confused by the following "value"; 1,567
I am confused by what the commas signify?

rounded to the nearest whole integer what are each of the values displayed above?
Re: Digging out the Wait events. [message #598935 is a reply to message #598750] Sun, 20 October 2013 07:39 Go to previous messageGo to next message
VIP2013
Messages: 84
Registered: June 2013
Member
you are correct. but for a significant wait(more than ~20 minutes), they should get sampled in DBA_HIST_ACTIVE_SESS_HISTORY, and i should get details from this view.

During going through the data of DBA_HIST_ACTIVE_SESS_HISTORY, i found in general, the sample time in dba_hist_active_sess_history each with a interval of 10 second. in other words each consecutive samples have 10seconds difference between each other.

But for some of the cases i can see for same session_id and session_serial# there is more than 2hrs of difference between consecutive samples.So my question is, what activity, the session was doing withinn that time interval of time and why its not get sampled in dba_history_active_sess_history?

Session_id Session_serial# Sample_time Session_state Event
10,037 10,897 10/13/2013 23:21:38 WAITING enq: TX - row lock contention
10,037 10,897 10/13/2013 23:21:28 WAITING enq: TX - row lock contention
10,037 10,897 10/13/2013 23:21:18 WAITING enq: TX - row lock contention
10,037 10,897 10/13/2013 23:21:08 WAITING enq: TX - row lock contention
10,037 10,897 10/13/2013 22:24:10 WAITING enq: TX - row lock contention
10,037 10,897 10/13/2013 17:40:43 WAITING enq: TX - row lock contention

[Updated on: Sun, 20 October 2013 07:41]

Report message to a moderator

Re: Digging out the Wait events. [message #598939 is a reply to message #598935] Sun, 20 October 2013 09:38 Go to previous messageGo to next message
BlackSwan
Messages: 22490
Registered: January 2009
Senior Member
I asked a question & your response was "you are correct" which leaves my question still unanswered.

what problem are you really trying to solve?

how will you, I or anyone recognize the correct answer should it ever get posted here?
Re: Digging out the Wait events. [message #598940 is a reply to message #598935] Sun, 20 October 2013 10:01 Go to previous messageGo to next message
John Watson
Messages: 4379
Registered: January 2010
Location: Global Village
Senior Member
VIP2013 wrote on Sun, 20 October 2013 13:39
you are correct. but for a significant wait(more than ~20 minutes), they should get sampled in DBA_HIST_ACTIVE_SESS_HISTORY, and i should get details from this view.

During going through the data of DBA_HIST_ACTIVE_SESS_HISTORY, i found in general, the sample time in dba_hist_active_sess_history each with a interval of 10 second. in other words each consecutive samples have 10seconds difference between each other.

But for some of the cases i can see for same session_id and session_serial# there is more than 2hrs of difference between consecutive samples.So my question is, what activity, the session was doing withinn that time interval of time and why its not get sampled in dba_history_active_sess_history?

Session_id Session_serial# Sample_time Session_state Event
10,037 10,897 10/13/2013 23:21:38 WAITING enq: TX - row lock contention
10,037 10,897 10/13/2013 23:21:28 WAITING enq: TX - row lock contention
10,037 10,897 10/13/2013 23:21:18 WAITING enq: TX - row lock contention
10,037 10,897 10/13/2013 23:21:08 WAITING enq: TX - row lock contention
10,037 10,897 10/13/2013 22:24:10 WAITING enq: TX - row lock contention
10,037 10,897 10/13/2013 17:40:43 WAITING enq: TX - row lock contention
The reason for the gap is that the session was not sampled during that time. Sessions are sampled only if they are active, or hanging on a non-idle wait event. So presumably, session 10037 was not actually doing anything at the precise moments that sampling was done between 22:24:10 and 23:21:08.
Re: Digging out the Wait events. [message #598941 is a reply to message #598940] Sun, 20 October 2013 10:16 Go to previous messageGo to next message
BlackSwan
Messages: 22490
Registered: January 2009
Senior Member
DBA_HIST_ACTIVE_SESS_HISTORY contains snapshots taken from V$ACTIVE_SESSION_HISTORY
V$ACTIVE_SESSION_HISTORY contains snapshots taken from V$SESSION
Given the reality that none of the V$* views adhere to the ACID principals; there is no guarantee to the completeness or correctness of the details presented.

Re: Digging out the Wait events. [message #598945 is a reply to message #598940] Sun, 20 October 2013 12:43 Go to previous messageGo to next message
VIP2013
Messages: 84
Registered: June 2013
Member
hey john, So do you mean to say,
at 10/13/2013 17:40:43 one of the transaction initiates the database call resulting into event 'row lock contention' and then might execute some DML or other statement and the session got inactive untill 10/13/2013 22:24:10 where, another transaction which is totally different than previous one initiates the database call, picks the same session from the pool and result into same event 'row lock contention' for some different sql. and after that it too got inactive may be after executing some stetement which is not sampled(<~10sec).

Then again at 10/13/2013 23:21:08, some other request(different transction altogether) pick the same session id from the connection pool and start using it too.
Re: Digging out the Wait events. [message #598970 is a reply to message #598945] Mon, 21 October 2013 03:14 Go to previous message
VIP2013
Messages: 84
Registered: June 2013
Member
Also as per my initial question, our 'Application'(wait class) wait event increased to very high value for particular day i.e 14-oct-2013, then after digging more into that i observed that its due to the wait event 'SQL*Net break/reset to client'. then i verified, dba_hist_active_sess_history, during that exact time and found that, one of the specific session was experiencing heavy 'SQL*Net break/reset to client' wait at that same time. And as per the info from dba_histactive_sess_history, this session was Active and experiencing this wait starting since '8-oct-2013' for same sql_id(its a SELECT query). After summing all the wait time its coming ~8 minutes.

As per the description provided for 'SQL*Net break/reset to client' , its result of unhandled exception(might be from JAVA code) propagated directly to the client. So i am not able to conclude from this scenario, why the same session(same transaction) was experiencing this wait for same 'sql query' around ~6 days? Or i am intertreting this info in a wrong way?
Previous Topic: Need your help in tuning the query
Next Topic: db file parallel read
Goto Forum:
  


Current Time: Thu Jul 24 13:31:41 CDT 2014

Total time taken to generate the page: 0.07391 seconds