Active Session History: Updating the X$ASH, part 03

Part 01
Part 02

Here I try to show you what happens and why Oracle updates the V$ASH view. Please read the pdf by Graham Wood, for more details.

What I analyze is the session "session_id=1732" with "session_serial#=31065" saw in the previous post.

This is what happens

Click for enlarge

The session 1732 (serial# 31065) is sampled 3 times: at sample_id 50243482, 50243483, 50243484. In the last sample_id, there is a change of state of the session. In fact, querying the V$ACTIVE_SESSION_HISTORY, you see

Click for enlarge

But what happens behind the lines is something like this. Pay attention that my conclusions are based on my experiment

Click for enlarge

(1) SAMPLE_ID 50243482/SAMPLE_TIME 15-DEC-17 02:50:40.054

At the 15/12/2017 14:50:40.838429, one row is inserted in X$ASH with SAMPLE_TIME, 14:50:40.054

(2) SAMPLE_ID 50243484/SAMPLE_TIME 15-DEC-17 02:50:42.064

At the 15/12/2017 14:50:42.016313, one row is inserted in X$ASH with SAMPLE_TIME, 14:50:41.064

(3) SAMPLE_ID 50243484/SAMPLE_TIME 15-DEC-17 02:50:41.064

At the 15/12/2017 14:50:43.192604, one row is inserted in X$ASH with SAMPLE_TIME, 14:50:42.064

Note that, at this time, the session 1732 is waiting, but Oracle doesn't know yet how match time the session will wait

(4) SAMPLE_ID 50243484/SAMPLE_TIME 15-DEC-17 02:50:41.064 (the same of the previous one)

At the 15/12/2017 14:50:44.372309 (sample_id 50243485), the last row is updated in X$ASH with SAMPLE_TIME, 14:50:42.064

At sample_id 50243485, the session 1732 finish it works and Oracle know how much time the session waited. So he can update the state of the wait on X$ASH

Here I left the previous row, just to show what happening.

(5) The final result

What you see finally, is a consistent state of the session

Part 01
Part 02

Active Session History: Updating the X$ASH, part 02

Part01
Part03

Starting from previous output, running the following query

set lines 160
col SAMPLE_TIME for a30
set pages 99
select
    sample_id
  , session_id
  , session_serial#
  , time_waited
  , count(*)
  , sample_time 
from 
    my_active_session_history 
group by 
    sample_id
  , session_id
  , session_serial#
  , time_waited
  , sample_time
order by 
    session_id 
  , sample_id
/

you can aggregate the result. The output is here.

I get an extract of this output to try to explain what happens.

What my anonymous PL/SQL (see the previous post) does, is to polling the V$SESSION_ACTIVE_SESSION every second and save the output in MY_ACTIVE_SESSION_HISTORY table.

Because each time, the script read the same rows plus one (the V$ASH is renewed each second), for the same sessions, you see a lot of rows for each loop

Consider, for example, the session 1732/serial 31065.

select
    sample_id
  , session_id
  , session_serial#
  , time_waited
  , count(*)
  , sample_time
from
    my_active_session_history
    where session_id=1732 and session_serial#=31065
group by
    sample_id
  , session_id
  , session_serial#
  , time_waited
  , sample_time
order by
    session_id
  , sample_id
/

Click for enlarge

It appears 50 times for the snap_id 50243482, 49 times for the snap_id 50243483 and 48 times for snap_id 50243484 (see note).

What happens to the session 1732, where for the sample_id=50243484 you see two distinct rows?

The following statement has this output (it is just the detail of the session 1732):

select 
    row_number() over (partition by sample_id order by sample_id, inserting_time) rn
  , inserting_time
  , sample_id
  , wait_time
  , time_waited
  , session_state
  , event
from
    my_active_session_history 
where 
   session_id=1732 and session_serial#=31065
order by 
   sample_id, 1
/

Because I'm interested just in the first rows of each change of "sample_id" and/or change of the "state" inside the same sample_id, I want to see only this changes


with 
  mash as (
    select 
        inserting_time
      , time_waited
      , sample_id
      , sample_time
      , session_id
      , wait_time
      , event
      , session_state
      , row_number() over (partition by sample_id, time_waited, session_state, event order by inserting_time) rn
    from 
      my_active_session_history
    where 
      session_id=1732 and session_serial#=31065
)
select 
    sample_id
  , sample_time
  , inserting_time
  , time_waited
  , session_state
  , event
from 
  mash
where 
  rn =1
order by 
    sample_id
  , inserting_time
/

Click for enlarge

What happens here?

1. At sample_id =50243482 (14:50:40) the sid 1732 is working (it's ON CPU). This means that TIME_WAITED is 0 (zero)
2. One second after (14:50:41), sample_id=50243483, the sid 1732 is still working and TIME_WAITED is still 0 (zero)
3. One second after (14:50:42), sample_id=50243484, the sid 1732 wait on direct path read event, but the TIME_WAITED column is not updated. So while the SESSION_STATE/EVENT columns report the correct state of the session, the TIME_WAITED, not yet (inserting_time=15-DEC-17 02.50.43.192604 PM). Because of this Oracle update on the same SNAP_ID (50243484) this row with the correct value of TIME_WAITED column (inserting_time=15-DEC-17 02.50.44.372309 PM).

In the next session, I try to explain this "update" in a visual way

Note

Is it correct that each next sample_id, have one less? When my PL/SQL script inserts a row the first time, it does at 15-DEC-17 02.50.40.833420 PM (sample_id=50243482). The second time, it inserts at 15-DEC-17 02.50.42.016313 PM (sample_id=50243483): it inserts two seconds after the first time. The third time it inserts at 15-DEC-17 02.50.43.192604.
Anyway, the last record for all samples is the same: 15-DEC-17 02.51.40.488761 PM. Because all samples end at the same time (MX column in the next picture), each of them count one record less.

You can run the following select that show you the min and max timestamp

select * from (
  select
      sample_id
    , session_id
    , session_serial#
    , time_waited
    , sample_time
    , inserting_time
    , max(inserting_time) over (partition by sample_id) mx
    , count(*) over (partition by sample_id) cnt
    , row_number() over (partition by sample_id order by inserting_time) rn_min
    , row_number() over (partition by sample_id order by inserting_time desc) rn_max
  from
      my_active_session_history
  where 
      session_id=1732 and session_serial#=31065
  order by
      session_id
    , sample_id)
where rn_min=1 or rn_max=1
/

Click for enlarge

Please, pay attention. While the inserting_time is the instant when the row is inserted in the MY_ACTIVE_SESSION_HISTORY, the sampling happens each second (in the previous picture I put both SAMPLE_TIME and INSERTING_TIME)

Part01
Part03

Active Session History: updating the X$ASH, part 01

Part 02
Part 03

I'm a proud member of OraPub community. Some days ago I was speaking with Kaley Crum, another member of the OraPub community.

The context was ASH (Active Session History).

He told me that at some time, Oracle does an update of X$ASH in order to update the values of the TIME_WAITED column.

I didn't trust him because my conviction was that Oracle makes just an insert in this X$.

Well, I was wrong. Kaley right. Thanks to him to learn me something new.

On this argument, what is TIME_WAITED column, and some trouble with it. Kayle wrote a post himself.

Also, and I recommend it to you, a couple of post by Craig Shallahamer. You can find them here and here. And not forget the one wrote by Alberto Dell'Era.

And don't miss the pdf of Graham Wood, slide 35, where he shows the fallacies of the TIME_WAITED column in the V$ACTIVE_SESSION_HISTORY view. This series of posts are based on this slide nr 35.

What I want to do is try to explayn myself the problem, but here, in Part 01, I want just write the test I made.


1) Prepare the enviroment

create table my_active_session_history as select * from v$active_session_history where 1=2;
 
alter table my_active_session_history add (inserting_time timestamp);


2) Run the following anonymous PL/SQL


3) Run following statement, to report the result

col INSERTING_TIME for a30
col SAMPLE_TIME for a30
set lines 120
select 
    inserting_time
  , sample_id
  , sample_time
  , session_id
  , session_serial#
  , event
  , session_state
  , time_waited
from
    my_active_session_history
order by 
    session_id
  , sample_id
  , inserting_time;

You can see the result of this last statement, here.

Part 02
Part 03

Lock Chains 01: V$SESSION

I always receive a call where a colleague tell me that a session of an application is slow.  Really that session is not slow but locked by another one.

Starting with 10g, Oracle introduced a new column in the V$SESSION performance view, that report the instance number and the session id of the blockers. In this way, the troubleshooting is more simple.

Anyway, after you query the V$SESSION you have to scroll down the result set in order to match the blocking session with the locked session.

Because the relation between the blocker and locked sessions is of "hierarchical" type, I can use the hierarchical query (session 123 is blocking the session 234 and session 345. This last one also is blocking the session 999, for example) to try to picture this relation.

*****
***** Please pay attention. The following statements are not RAC aware yet. So they work just on a single instance *****
*****

col path_state for a30
col path_event for a160
col path_sid for a20
col b_session for 999999
set lines 230
set pages 25
with
  snap as (
   select
        sid
      , blocking_instance
      , blocking_session
      , sql_id
      , prev_sql_id
      , event
      , state
    from
      v$session)
select
    to_char(sysdate, 'dd/mm/yyyy hh24:mi:ss') now
  , CONNECT_BY_ISCYCLE cycle
  , CONNECT_BY_ROOT sid b_session
  , SID l_session
  , SUBSTR(SYS_CONNECT_BY_PATH(
        DECODE(state,
                     'WAITING', sid||'/'||nvl(sql_id, prev_sql_id||'(p)')||'/'||event,
                                sid||'/'||nvl(sql_id, prev_sql_id||'(p)')||'/ON CPU'), ' -> ')
          ,5) path_event
 from
  snap
where
  level >1
connect by
  nocycle prior sid=blocking_session
/

The result is like this

Picture 01 - Click for enlarge

Picture 02 - Click for enlarge

There are a lot of things that seem to be strange.


##### Picture 01

There are sessions that lock each other. They have the column "CYCLE" to 1. Both of them are waiting for "read by other sessions" event. This is strange because it seems to be a deadlock, but there isn't a trace file containing the "ORA-00060: deadlock detected while waiting for resource".

Other curious things are the "enq: TX - row lock contention". In green, I highlighted this. The session 2330 is waiting for the session 2330 that doing...nothing.

 In blue, instead, you can see how a session waiting for "read by other session" depend from a session is reading the same block. 

##### Picture 02

Here you can see how some sessions (in red) are locked by a session that did...nothing (in orange).

In the next post, I'll show a similar statement that you can use on V$ACTIVE_SESSION_HISTOR.

Note: How to read the output

1. The column CYCLE, tell you if you have a deadlock (like in picture 01). In this case, there will be a "1"
2. B_SESSION and L_SESSION columns are the blocking session (the head) and the locked session (the tail), respectively 
3. PATH_EVENT column, show you the lock path. It includes the Session ID, the SQL ID and the wait event if that session in waiting. Otherwise, the wait event is replaced by "ON CPU" 
4. If the SQL_ID is NULL, then I try to use the PREV_SQL_ID. In this case a "(p)" will appear (for example "2sbqfhnjz6ybw(p)" in orange in the picture 02). Anyway there are some cases where also the previous SQL_ID is NULL. In this case there will be only the "(p)" without the SQL_ID (B_SESSION = 1401, in the picture 02, for example).