ITL Waits – Changes in Recent Releases (script) – Striving for Optimal Performance

A reader of this blog, Paresh, asked me how I was able to find out the logic behind ITL waits without having access to Oracle code. My reply was: I wrote a test case that reproduce ITL waits and a piece of code that monitors them.

Since other readers might be interested, here is the shell script I wrote. Notice that it takes four parameters as input: user name, password, SID, and how long it has to wait in the monitoring phase.

#!/bin/sh

user=$1
password=$2
sid=$3
wait=$4

#
# Setup test environment
#

sqlplus -s $user/$password@$sid <<END
  SET ECHO OFF TERMOUT ON FEEDBACK OFF HEADING OFF
  BEGIN
    EXECUTE IMMEDIATE 'DROP TABLE t PURGE';
  EXCEPTION
    WHEN OTHERS THEN NULL;
  END;
  /
  CREATE TABLE t (n NUMBER, pad VARCHAR2(50)) PCTFREE 0 INITRANS 5 TABLESPACE users;
  INSERT INTO t SELECT rownum, rpad('*',50,'*') FROM dual CONNECT BY level <= 134 UNION ALL SELECT 135, rpad('*',48,'*') FROM dual;
  COMMIT;
  SELECT 'Setup correctly performed:', decode(count(DISTINCT dbms_rowid.rowid_block_number(rowid)),1,'YES','NO') FROM t;
END

#
# Produce ITL wait
#

for i in 1 2 3 4 5 6
do
  echo 'SET ECHO OFF TERMOUT OFF FEEDBACK OFF' > $i.$sid.sql
  if [[ $i = 6 ]]
  then
    # make sure that the other processes have locked one row
    echo 'execute dbms_lock.sleep(1)' >> $i.$sid.sql
  fi
  echo 'UPDATE t SET n = n WHERE n =' $i ';' >> $i.$sid.sql
  echo 'SET TERMOUT OFF' >> $i.$sid.sql
  if [[ $i < 6 ]]
  then
    echo 'execute dbms_lock.sleep(' $wait ')' >> $i.$sid.sql
  fi
  sqlplus -s $user/$password@$sid @$i.$sid.sql &
done

#
# Monitor ITL wait
#

sqlplus -s $user/$password@$sid <<END
  SET SERVEROUTPUT ON ECHO OFF TERMOUT ON FEEDBACK OFF HEADING OFF
  SELECT * FROM v$version WHERE rownum = 1;
  DECLARE
    l_waiter_session v$session.sid%TYPE := NULL;
    l_blocking_session_curr v$session.blocking_session%TYPE := NULL;
    l_blocking_session_prev v$session.blocking_session%TYPE := NULL;
    l_seconds_in_wait_curr v$session.seconds_in_wait%TYPE := NULL;
    l_seconds_in_wait_prev v$session.seconds_in_wait%TYPE := NULL;
    c_sleep CONSTANT NUMBER := 0.1;
    c_iterations CONSTANT NUMBER := ceil(($wait-5)/c_sleep);
  BEGIN
    WHILE l_waiter_session IS NULL
    LOOP
      BEGIN
        SELECT sid INTO l_waiter_session
        FROM v$session
        WHERE event = 'enq: TX - allocate ITL entry';
      EXCEPTION
        WHEN no_data_found THEN NULL;
      END;
    END LOOP;
    FOR i IN 1..c_iterations
    LOOP
      BEGIN
        SELECT blocking_session, seconds_in_wait INTO l_blocking_session_curr, l_seconds_in_wait_curr
        FROM v$session
        WHERE sid = l_waiter_session;
      EXCEPTION
        WHEN no_data_found THEN NULL;
      END;
      IF l_blocking_session_curr <> l_blocking_session_prev
         OR l_blocking_session_prev IS NULL
         OR i = c_iterations
      THEN
        dbms_output.put_line(to_char((i-1)*c_sleep,'000000')||
                             ' blocking_session='||nvl(l_blocking_session_prev,l_blocking_session_curr)||
                             ' sleep='||nvl(l_seconds_in_wait_prev,l_seconds_in_wait_curr));
      END IF;
      l_blocking_session_prev := l_blocking_session_curr;
      l_seconds_in_wait_prev := l_seconds_in_wait_curr;
      dbms_lock.sleep(c_sleep);
    END LOOP;
  END;
  /
END

#
# Cleanup
#

for i in 1 2 3 4 5 6
do
  rm $i.$sid.sql
done

sleep 5

sqlplus -s $user/$password@$sid <<END
  SET ECHO OFF TERMOUT ON FEEDBACK OFF HEADING OFF
  DROP TABLE t PURGE;
END

exit 0

The outputs I got are the following:

10.2.0.4

000000 blocking_session=136 sleep=0
000005 blocking_session=136 sleep=6
000010 blocking_session=140 sleep=3
000015 blocking_session=152 sleep=6
000020 blocking_session=159 sleep=6
029995 blocking_session=158 sleep=29979

10.2.0.5

000000 blocking_session=158 sleep=0
000001 blocking_session=158 sleep=0
000002 blocking_session=152 sleep=2
000003 blocking_session=141 sleep=0
000004 blocking_session=148 sleep=0
000005 blocking_session=140 sleep=3
000007 blocking_session=158 sleep=0
000009 blocking_session=152 sleep=3
000011 blocking_session=141 sleep=3
000013 blocking_session=148 sleep=0
000015 blocking_session=140 sleep=3
000019 blocking_session=158 sleep=3
000023 blocking_session=152 sleep=6
000027 blocking_session=141 sleep=3
000031 blocking_session=148 sleep=3
000035 blocking_session=140 sleep=6
000040 blocking_session=158 sleep=3
000045 blocking_session=152 sleep=6
000050 blocking_session=141 sleep=6
000054 blocking_session=148 sleep=3
000062 blocking_session=140 sleep=9
000067 blocking_session=158 sleep=6
000072 blocking_session=152 sleep=3
000077 blocking_session=141 sleep=6
000082 blocking_session=148 sleep=6
000098 blocking_session=140 sleep=15
000103 blocking_session=158 sleep=6
000108 blocking_session=152 sleep=3
000113 blocking_session=141 sleep=6
000118 blocking_session=148 sleep=6
000149 blocking_session=140 sleep=30
000154 blocking_session=158 sleep=6
000159 blocking_session=152 sleep=6
000164 blocking_session=141 sleep=3
000169 blocking_session=148 sleep=6
000232 blocking_session=140 sleep=63
000237 blocking_session=158 sleep=6
000242 blocking_session=152 sleep=6
000247 blocking_session=141 sleep=3
000252 blocking_session=148 sleep=6
000379 blocking_session=140 sleep=129
000383 blocking_session=158 sleep=3
000388 blocking_session=152 sleep=6
000393 blocking_session=141 sleep=6
000398 blocking_session=148 sleep=3
000651 blocking_session=140 sleep=258
000656 blocking_session=158 sleep=3
000661 blocking_session=152 sleep=6
000666 blocking_session=141 sleep=6
000671 blocking_session=148 sleep=3
001177 blocking_session=140 sleep=514
001182 blocking_session=158 sleep=6
001187 blocking_session=152 sleep=3
001192 blocking_session=141 sleep=6
001197 blocking_session=148 sleep=6
014218 blocking_session=140 sleep=13184
029995 blocking_session=140 sleep=28788

11.1.0.6

000000 blocking_session=146 sleep=0
000005 blocking_session=146 sleep=5
000010 blocking_session=129 sleep=5
000015 blocking_session=141 sleep=5
000020 blocking_session=126 sleep=5
029995 blocking_session=132 sleep=29978

11.1.0.7

000000 blocking_session=136 sleep=0
000005 blocking_session=136 sleep=5
000010 blocking_session=140 sleep=5
000015 blocking_session=132 sleep=5
000020 blocking_session=131 sleep=5
029995 blocking_session=134 sleep=29979

11.2.0.1

000000 blocking_session=131 sleep=0
000001 blocking_session=131 sleep=1
000002 blocking_session=133 sleep=1
000003 blocking_session=196 sleep=1
000004 blocking_session=67 sleep=1
000005 blocking_session=69 sleep=1
000007 blocking_session=131 sleep=2
000009 blocking_session=133 sleep=2
000011 blocking_session=196 sleep=2
000013 blocking_session=67 sleep=2
000015 blocking_session=69 sleep=2
000019 blocking_session=131 sleep=4
000023 blocking_session=133 sleep=4
000027 blocking_session=196 sleep=4
000031 blocking_session=67 sleep=4
000035 blocking_session=69 sleep=4
000040 blocking_session=131 sleep=5
000045 blocking_session=133 sleep=5
000050 blocking_session=196 sleep=5
000054 blocking_session=67 sleep=5
000062 blocking_session=69 sleep=8
000067 blocking_session=131 sleep=5
000072 blocking_session=133 sleep=5
000077 blocking_session=196 sleep=5
000082 blocking_session=67 sleep=5
000098 blocking_session=69 sleep=16
000103 blocking_session=131 sleep=5
000108 blocking_session=133 sleep=5
000113 blocking_session=196 sleep=5
000118 blocking_session=67 sleep=5
000149 blocking_session=69 sleep=32
000154 blocking_session=131 sleep=5
000159 blocking_session=133 sleep=5
000164 blocking_session=196 sleep=5
000169 blocking_session=67 sleep=5
000232 blocking_session=69 sleep=64
000237 blocking_session=131 sleep=5
000242 blocking_session=133 sleep=5
000247 blocking_session=196 sleep=5
000252 blocking_session=67 sleep=5
000379 blocking_session=69 sleep=128
000383 blocking_session=131 sleep=5
000388 blocking_session=133 sleep=5
000393 blocking_session=196 sleep=5
000398 blocking_session=67 sleep=5
000651 blocking_session=69 sleep=256
000656 blocking_session=131 sleep=5
000661 blocking_session=133 sleep=5
000666 blocking_session=196 sleep=5
000671 blocking_session=67 sleep=5
001177 blocking_session=69 sleep=512
001182 blocking_session=131 sleep=5
001187 blocking_session=133 sleep=5
001192 blocking_session=196 sleep=5
001196 blocking_session=67 sleep=5
029995 blocking_session=69 sleep=28787

8 Comments

Paresh

22 June 2011 - 05:34

Hi Christian,

Is it possible to register for automated email notification whenever there is a new blog entry or comments on your blog?

Thanks,
Paresh

Alexander Anokhin

23 June 2011 - 09:28

Hi Paresh,
I would recommend to use RSS

Christian Antognini

11 July 2011 - 17:22

Hi Paresh

> Is it possible to register for automated email notification whenever
> there is a new blog entry or comments on your blog?

For the moment such a feature does not exist. I.e. RSS is the way to go.

Cheers,
Chris

PS: I plan to change the SW infrastructure of my blog. Depending on the choice I do, it might be possible to (easily) add such a feature…

vijays

19 April 2013 - 20:21

Dear Christian,

could you please share the script on how to reproduce deadlock due to ITL. We are facing deadlock issue due to concurrent update on the table, the update statements are from different sessions and each update statement updates only one row. We are on 11g R2 (11.2.0.3), I am trying to create a test case to show that ITL slot unavailability can cause deadlocks.

Thanking you in anticipation.

Regards,
VijayS

1. Christian Antognini Author
  
  22 April 2013 - 06:44
  
  Hi
  
  I already provided everything is needed, IMO. What do you miss?
  
  Thank you,
  Chris
  
  1. vijays
    
    23 April 2013 - 08:26
    
    Dear Chris,
    
    thanks for reverting. With reference to you pervious post titled “ITL Waits – Changes in Recent Releases”, in the comment you stated
    “I have a demo about ITL waits/deadlocks that I use from time to time while teaching”.
    
    if you could please share the script to reproduce deadlock due to ITL. We are on 11g R2 (11.2.0.3) and we are facing a deadlock issue my assumption is this is due to ITL but I want to recreate the scenario at our end and verify the deadlock grapth with the trace file I have received from the team.
    
    Also with reference to the above script, how is the value getting assigned to variables i, l_blocking_session_prev, l_blocking_session_prev and c_iterations (may be I am missing something).
    
    Thanks once again for your time on this.
    
    Regards,
    VijayS
    
    1. Christian Antognini Author
      
      29 April 2013 - 21:05
      
      Hi
      
      > if you could please share the script to reproduce deadlock due to ITL
      
      Aha, sorry, I didn’t read carefully your question. I’ll write a short post containing it.
      
      > Also with reference to the above script, how is the value getting assigned to variables i,
      > l_blocking_session_prev, l_blocking_session_prev and c_iterations
      
      I don’t know what happened, part of the script was missing. I fixed it.
      
      Best,
      Chris
      
      1. Christian Antognini Author
        
        1 May 2013 - 06:18
        
        Here is the script…

ITL Waits – Changes in Recent Releases (script)

8 Comments

Leave a Reply Cancel reply