High value of "enq: TX - allocate ITL entry" waits but wait events are on an index not affected by the SQL statement

From: Thomas Kellerer <thomas.kellerer_at_mgm-tp.com>
Date: Mon, 22 Jul 2013 16:30:52 +0200
Message-ID: <51ED421C.9090406_at_mgm-tp.com>

Hello,

we had a strang situation on a 2 node RAC this weekend.

For some reason one UPDATE statement startet waiting on the event "enq: TX - allocate ITL entry".

The AWR shows that in the hour in question the DB spent about 48% of the time waiting for that even.

Here is the entry from the AWR Report:

          Wait   |                                 |           Event              |           Wait Time      
---------------------------------------------------------------------------------------------------------------------
Class            | Event                           | Waits            %Timeouts   |  Total(s)      Avg(ms)   %DB time
Configuration    | enq: TX - allocate ITL entry    | 28,625           51.39       |  162,132.99    5664.03   48.55   

When I query the dba_hist_active_sess_history view to get details on the wait events:

select sql_id,

     event, 
     count(*), 
     lpad(round(ratio_to_report(count(*)) over () * 100)||'%',10,' ') percent

from dba_hist_active_sess_history
where sample_time between timestamp '2013-07-20 11:00:00' and timestamp '2013-07-20 12:00:00' and event = 'enq: TX - allocate ITL entry' group by sql_id, event
order by percent desc

It's three statements that show up:

SQL_ID        | EVENT                        | COUNT(*) | PERCENT
--------------+------------------------------+----------+-----------
g6pnz719zkz34 | enq: TX - allocate ITL entry | 12055    |        74%
bgy3mh3wby1js | enq: TX - allocate ITL entry | 3284     |        20%
fgcys0tkmdt12 | enq: TX - allocate ITL entry | 885      |         5%

When I pick the first statement (an UPDATE statement) for details on which object the waits happened, using the following statement:

select *
from (

  select ash.sql_id,
         ash.current_obj#,
         obj.object_name,
         count(*) as wait_count

  from dba_hist_active_sess_history ash     left join dba_objects obj on obj.object_id = ash.current_obj#    where ash.sample_time between timestamp '2013-07-20 11:00:00' and timestamp '2013-07-20 12:00:00'

  group by ash.sql_id, 
           ash.top_level_sql_id, 
           ash.current_obj#, 
           obj.object_name 

  order by 4 desc
)

where sql_id = 'g6pnz719zkz34'
and rownum <= 15;

the following is returned:

SQL_ID | CURRENT_OBJ# | OBJECT_NAME | WAIT_COUNT

--------------+--------------+-------------------+-----------
g6pnz719zkz34 | 153408       | ORDERS_IDX1       | 11250
g6pnz719zkz34 | 83055        | ORDERS_IDX2       | 494
g6pnz719zkz34 | 130088       | ORDERS_IDX3       | 164
g6pnz719zkz34 | 114650       | ORDERS_IDX4       | 116
g6pnz719zkz34 | -1           |                   | 17
g6pnz719zkz34 | 0            |                   | 11
g6pnz719zkz34 | 83053        | PK_726FA34AFB0    | 3

All shown indexes relate to the ORDERS table that is being updated in the UPDATE statement (g6pnz719zkz34).

What I don't understand is the fact that the UPDATE statement does not touch any of the columns from ORDERS_IDX1 index. The second statement (bgy3mh3wby1js) is an insert statement into the ORDERS table which naturally would touch the index ORDERS_IDX1 (and all the others).

Could that be caused by index block splits due to increasing in the ITL? The wait count is also way higher than the actual execution count of 1019 the UPDATE statement in the time frame in question.

The INSERT statement on the other hand does not wait on those indexes:

select *
from (

  select ash.sql_id,
         ash.current_obj#,
         obj.object_name,
         count(*) as wait_count

  from dba_hist_active_sess_history ash     left join dba_objects obj on obj.object_id = ash.current_obj#    where ash.sample_time between timestamp '2013-07-20 11:00:00' and timestamp '2013-07-20 12:00:00'

  group by ash.sql_id, 
           ash.top_level_sql_id, 
           ash.current_obj#, 
           obj.object_name 

  order by 4 desc
)

where sql_id = 'bgy3mh3wby1js'
and rownum <= 15;

SQL_ID | CURRENT_OBJ# | OBJECT_NAME | WAIT_COUNT

--------------+--------------+----------------+-----------
bgy3mh3wby1js | 83053        | PK_726FA34AFB0 | 2974
bgy3mh3wby1js | 82802        | ORDERS         | 261
bgy3mh3wby1js | -1           |                | 50
bgy3mh3wby1js | 83055        | ORDERS_IDX2    | 1

I don't understand why the insert doesn't generate waits on the ORDERS_IDX1 but the UPDATE (which doesn't touch the index columns) does.

Another figure that puzzles me is the fact that neither of those indexes show up in the segment statistics of the AWR report:

itl wait      APP      TBS_APP_DATA      ORDERS_IDX1            INDEX       211      56.87
              APP      TBS_APP_DATA      PK_726FA34AFB0         INDEX       156      42.05
              APP      TBS_APP_DATA      IDX_32767              INDEX         3       0.81
              APP      TBS_APP_DATA      IDX_21554              INDEX         1       0.27

I wonder why the numbers retrieved from dba_hist_active_sess_history don't line up with the segment statistics in the AWR. Are my SQL queries doing something wrong? Shoudn't the wait count from my SQL query somewhere in the neighbourhood of the segment waits in the AWR report?

Currently the PCTFREE and INITTRANS are set to the default values. Would increasing them help in this situation?

Any clues?

My Environment:
  Oracle 11.2.0.3 64bit
  Red Hat Enterprise Linux 4.4

Thanks for taking the time to read this.

Regards
Thomas

--
http://www.freelists.org/webpage/oracle-l

Received on Mon Jul 22 2013 - 16:30:52 CEST