Oracle Scratchpad

September 29, 2008

Index Analysis 2

Filed under: Infrastructure,Performance,Troubleshooting — Jonathan Lewis @ 5:33 pm BST Sep 29,2008

Shortly after I published the previous post, I received an email from an old client who reminded me of a problem he had had with empty index blocks, the solution we had used (which was a coalesce) and an update on how things had changed in the latest releases of Oracle.

Strangely, I was sure I had written a note about his problem, but I couldn’t find anything about it until I did a search on the Oracle Forum and found this thread where someone seems to have suffered from the same sort of issue.

The problem is that when an index suffers a massive delete – which could have accumulated over time, of course – it can end up with a lot of empty leaf blocks which cause an unexpected problem in the future. My summary of the issue is in the thread at this posting.

After a massive delete, you may have a lot of empty leaf blocks in the index. These blocks are left in the b-tree structure AND attached to the freelist.

On a subsequent insert, if a process needs to split a block it takes the top block off the free list and shares the data from the existing block between the old and new blocks; after which the two blocks have various pointers corrected.

However, there are cases where the splitting process will discover that the block it took from the free-list was also in a position in the index structure that made it an illegal choice. It only discovers this after doing all the work of splitting and relinking the blocks, and so has to roll back that work – which shows up as a ‘transaction rollback’ in v$sysstat – and try another block.

If you have done a massive delete, you could find that one process COULD work through a couple of hundred “not quite free enough” blocks before finding one it can use. This could (a) require lots of db file sequential reads to pick up each block in turn (b) cause other transactions to wait on a TX/4 for each of the blocks in turn.

I have seen this happen on a couple of live systems. I have not yet been able to emulate it on a test system because I can’t figure out the rules that cause the leaf block to be a reject.

A work around to the problem is to do an ‘alter index coalesce’ after doing the massive delete. This cleans all the empty blocks and takes them out of the index structure. (You have to have done a commit after the delete for this to work).

I don’t thnk you can spot this from the statistics – one long catastrophe appears as a single event in the stats. I think it might also be recorded as a hidden statistics in v$segstat, the ‘ITL service wait’.

Since I posted to that thread, though, things have moved on. My old client has upgraded to 10.2.0.3 where the “bug” has been fixed, and a new statistic (“failed probes on index block reclamation”) has been created to count the occurrences of the event.

Things still aren’t perfect unfortunately. The client has a small index which sometimes grows just a little bigger than it ought to and suffers a root block split to introduce a new index level. At present, they rebuild this index on a weekly basis to make sure that the index doesn’t (or is much less likely to) reach  the critical size where the index root block splits.  Unfortunately, when the root block split occurs, they still suffer a temporary blockage of their system. (Somewhere I’m sure I wrote a note suggesting that a rebuld like this that kept a small index to the minimum level could be a good idea because of a detail of the optimizer arithmetic – but I can’t find it! I’d have to update it if I could). 

After reading the email, I had a little search around Metalink, and found a couple of interesting bugs in the same area of code, in particular bug 5764993.8:

During an index block split a session may wait for one second unnecessarily if it already holds the required block in S mode and there are other holders in S mode – If it requests the block in X mode and the other S holders release their block pin/s then in this case the requesting (X) process is not posted so does not realize it can proceed until the “buffer busy wait” times out.

Another bug number gave a little summary of what the ASH (V$active_session_history) output might look like when this happened:


  BLCKNG                                                                 TIME
 SESSION SESSION EVENT                              P1        P2    P3 WAITED
 ------- ------- -------------------------- ---------- --------- ----- ------
     543     530 enq: TX - index contention 1415053316   2359308  2830 991957
     543     555 enq: TX - index contention 1415053316   2359308  2830 992447
     543     543 buffer busy waits                  12    880671     1 992274

Note how session 543 is both blocker and blocked in the bottom line. It is also the session that is blocking everyone else who is stuck in the ‘index transaction’ wait.

One of the things I really like about the blog environment is that other people can add value – this was a wonderful example of how the interaction can work well; so thanks, “old client”.

14 Comments »

  1. Great Idea…

    Your Book “Cost-Based Oracle Fundamentals” is great.

    Comment by Surachart Opun — September 29, 2008 @ 9:05 pm BST Sep 29,2008 | Reply

  2. I have been experiencing this issue in our production environment and have been working with Oracle for over two months now. We are running version 10.2.0.4 on Linux. We applied a patch for bug 8286901, but we still see the issue happening.

    From a data pattern standpoint we insert millions of records per day into a couple of table and then turn around and delete 99% of them, (rolling off at sysdate-4), but there are a few records that we don’t roll off.

    When we experience the enq TX –index contention wait event there is definitely a spike in the number of ‘failed probes on index block reclamation’. Typically in a standard AWR report for an hour of normal busy activity we will see 0-300 ‘failed probes on index block reclamation’.

    I took an AWR snapshot in the middle of an enq TX – index contention event. The snapshot was for just under 9 minutes and the ‘failed probes on index block reclamation’ was over 100,000. During this time I was able to issue the commands to dump the system state to trace per Oracle’s request.

    We have two Oracle Service Requests open that pertain to this issue. One has been turned into a bug: 8832886.

    Comment by Erik Cotsonas — August 28, 2009 @ 3:33 pm BST Aug 28,2009 | Reply

    • hello ,
      i have read the bug note; But there is no solution advised.
      Can you share your experience with this issue?

      Comment by maclean — January 25, 2010 @ 8:59 am BST Jan 25,2010 | Reply

  3. Erik,

    Thanks for the comment – sorry I lost track of it when you first posted it.

    I wonder if your problem is related in any way to this posting from Saibabu Devabhaktuni (which has been raised as bug on Metalink).

    Perhaps you have lots of processes waiting as one process performs a delayed removal of blocks from an index freelist.

    Comment by Jonathan Lewis — September 13, 2009 @ 8:20 am BST Sep 13,2009 | Reply

  4. [...] subsequent insert results in a performance problem. On the other hand if you read my description in this blog posting, you’ll see that I have described a scenario where the commit between the delete and the [...]

    Pingback by Index Freelists « Oracle Scratchpad — November 10, 2009 @ 7:11 pm BST Nov 10,2009 | Reply

  5. Hi ,
    My customer has a problem with wait event TX:index cotention. Oracle support suggest we should coalesce or reuild the index.
    Coalesce is less resource sensitive ,So i’d like to using coalesce.
    But as flow test:

      19:46:45 SQL> create table test(t1 int) tablespace datatb;
    
     Table created.
    SQL> create index ind_t1 on test(t1);
    
      Index created.
    
    Elapsed: 00:00:00.01
    19:47:08 SQL> begin
    19:47:17   2    for i in 1..20000 loop
    19:47:17   3      insert into test values(i);
    19:47:17   4      commit;
    19:47:17   5      end loop;
    19:47:17   6      end;
    19:47:18   7  /
    
    PL/SQL procedure successfully completed.
    SQL> set serveroutput on;
    SQL> declare
      2 
      3     l_fs1_bytes number;
      4     l_fs2_bytes number;
      5     l_fs3_bytes number;
      6     l_fs4_bytes number;
      7     l_fs1_blocks number;
      8     l_fs2_blocks number;
      9     l_fs3_blocks number;
     10     l_fs4_blocks number;
     11     l_full_bytes number;
     12     l_full_blocks number;
     13     l_unformatted_bytes number;
     14     l_unformatted_blocks number;
     15  begin
     16     dbms_space.space_usage(
     17        segment_owner      => user,
     18        segment_name       => 'IND_T1',
     19        segment_type       => 'INDEX',
     20        fs1_bytes          => l_fs1_bytes,
     21        fs1_blocks         => l_fs1_blocks,
     22        fs2_bytes          => l_fs2_bytes,
     23        fs2_blocks         => l_fs2_blocks,
     24        fs3_bytes          => l_fs3_bytes,
     25        fs3_blocks         => l_fs3_blocks,
     26        fs4_bytes          => l_fs4_bytes,
     27        fs4_blocks         => l_fs4_blocks,
     28        full_bytes         => l_full_bytes,
     29        full_blocks        => l_full_blocks,
     30        unformatted_blocks => l_unformatted_blocks,
     31        unformatted_bytes  => l_unformatted_bytes
     32     );
     33     dbms_output.put_line(' FS1 Blocks = '||l_fs1_blocks||' Bytes = '||l_fs1_bytes);
     34     dbms_output.put_line(' FS2 Blocks = '||l_fs2_blocks||' Bytes = '||l_fs2_bytes);
     35     dbms_output.put_line(' FS3 Blocks = '||l_fs3_blocks||' Bytes = '||l_fs3_bytes);
     36     dbms_output.put_line(' FS4 Blocks = '||l_fs4_blocks||' Bytes = '||l_fs4_bytes);
     37     dbms_output.put_line('Full Blocks = '||l_full_blocks||' Bytes = '||l_full_bytes);
     38  end;
     39  /
    FS1 Blocks = 0 Bytes = 0
    FS2 Blocks = 4 Bytes = 32768
    FS3 Blocks = 0 Bytes = 0
    FS4 Blocks = 0 Bytes = 0
    Full Blocks = 39 Bytes = 319488
    
    PL/SQL procedure successfully completed.
    
    Full blocks number is 39 ; fs2 is 4
    
    SQL> delete test where t1>10000 and (mod(t1,2)!=0);
    
    5000 rows deleted.
    Now :
    FS1 Blocks = 0 Bytes = 0
    FS2 Blocks = 4 Bytes = 32768
    FS3 Blocks = 0 Bytes = 0
    FS4 Blocks = 0 Bytes = 0
    Full Blocks = 39 Bytes = 319488
    nothing changed .
    
    SQL> alter index ind_t1 coalesce;  
    
    Index altered.
    FS1 Blocks = 0 Bytes = 0
    FS2 Blocks = 13 Bytes = 106496
    FS3 Blocks = 0 Bytes = 0
    FS4 Blocks = 0 Bytes = 0
    Full Blocks = 30 Bytes = 245760
    
    the free blocks increased
    
    SQL> delete test where t1>10000;
    
    5000 rows deleted.
    
    SQL> commit;
    
    Commit complete.
    
    Now :
    FS1 Blocks = 0 Bytes = 0
    FS2 Blocks = 23 Bytes = 188416
    FS3 Blocks = 0 Bytes = 0
    FS4 Blocks = 0 Bytes = 0
    Full Blocks = 20 Bytes = 163840
    after full block delete ,the free blocks increased again.
    
    SQL> alter index ind_t1 coalesce;
    
    Index altered.
    
    after coalesc , nothing changed:
    FS1 Blocks = 0 Bytes = 0
    FS2 Blocks = 23 Bytes = 188416
    FS3 Blocks = 0 Bytes = 0
    FS4 Blocks = 0 Bytes = 0
    Full Blocks = 20 Bytes = 163840
    
    but rebuild:
    SQL> alter index ind_t1 rebuild;
    
    Index altered.
    FS1 Blocks = 0 Bytes = 0
    FS2 Blocks = 1 Bytes = 8192
    FS3 Blocks = 0 Bytes = 0
    FS4 Blocks = 0 Bytes = 0
    Full Blocks = 21 Bytes = 172032
    

    what i want to ask, why the free blocks increased after coalesce? Can coalesce really resolve tx:index contention? If coalesce will lock table?

    Comment by maclean — January 22, 2010 @ 12:00 pm BST Jan 22,2010 | Reply

    • Maclean,

      As you can see from this posting, and from a related posting mentioned in comment 3 above, there are at least two reasons why you could see “Enq TX: index contention” if you do large deletes; and the advice to deal with the two different problems depends very strongly on which problem you are seeing.

      I hope that the Oracle support consultant explained why the coalesce might help – and pointed out the bits of information in your SR that took him to that conclusion.

      As far as your example is concerned the most important point is that it’s irrelevant if it isn’t a good match for your production scenario – do you really delete every other row from a large sequential section of your data; do you even get to a position where a number of deletions over a period of days leaves your data in that pattern ?

      A couple of comments on your results:

      The first “no change” after deleting 25% of the data is probably because you hadn’t issued a commit at that point.

      The “free blocks increased” after the first coalesce doesn’t match the perfect scenario – which would have been about 30 at full, and about 10 at FS1 – but the timing for bits being set and cleared in ASSM is an ongoing problem with Oracle and changes with version. We hope for some blocks to be cleared, though, because you have made a number of adjacent leaf blocks half empty, so some of those should be emptied and their contents combined with the next leaf block (i.e. instead of 20 half full blocks you hope to see 10 empty and 10 full).

      The “free blocks increased again”. You’ve deleted the rest of the top half of the index and committed (and the bitmaps have been updated). So where you have approximatly 40 full leaf blocks you now have 20 full and 20 empty.

      The “after coalesce, nothing changed”. Because you didn’t have any partly empty leaf blocks that could be the subject of a coalesce.

      After rebuild – you had a significant difference in the FS2 and Full blocks: but I’d be inclined to put that down to the weakness of the ASSM bitmap updates combined with the way in which the pctfree setting for indexes works – not to mention a couple of little oddities that show up when you’re dealing with small indexes. If you want to analyse exactly what’s going on you need to do a load of block dumps of the bitmap blocks and the index blocks as you work.

      To answer your questions:
      The free blocks increase after the coalesce because that’s what the coalesce command is designed to do: free up blocks which can be made free. More significantly, though, it’s supposed to take completely empty blocks out of the index structure and the nasty thing about your example is that it suggests that none of the index leaf blocks has become empty when clearly they should have been. You need to do some block dumps to find out whether this is just a defect in the bitmap report, or whether the blocks really are still in the index structure even though they are empty.

      The coalesce MAY resolve the contention if the contention is caused by the behaviour described in my posting. But if the coalesce is leaving empty blocks in the index structure then it MAY have no beneficial effect whatsoever.

      The coalesce command does not lock the table.

      Comment by Jonathan Lewis — January 24, 2010 @ 9:55 pm BST Jan 24,2010 | Reply

  6. Hi Jonathan,
    That’s great for your advise . I realize that I should not use dbms_space package to estimate the index but analyze index validate structure.
    But Oracle behave with index split is so unsatisfactory. I will test it on 11g r2.
    Thx for your help again.

    Comment by maclean — January 25, 2010 @ 8:56 am BST Jan 25,2010 | Reply

    • maclean,

      It’s not a good idea to use “analyze index validate structure” on a production index as the command locks the underlying table. It’s also not very useful for your test case, since all it gives is average stats, and you need more detail. For testing, you might like to check the effects of a treedump (on your little test case first) as this will tell you which blocks are still part of the index structure, and how many rows are in each.

      Comment by Jonathan Lewis — January 25, 2010 @ 5:11 pm BST Jan 25,2010 | Reply

  7. I still have a case open with Oracle. I believe that this is a bug in the Oracle code. The problem is that it has been difficult to create a reproducible test case for Oracle support. My specific issue was basically put on hold pending the results of another customer’s service request that appeared to have had the same issue, (9034788). Unfortunately they couldn’t reproduce the issue in that case either.

    I believe that there is a correlation between the enq TX – index contention wait event and a spike in the number of ‘failed probes on index block reclamation. I have specifically asked Oracle to explain why there is a spike in the ‘failed probes on index block reclamation’ during the same time frame as the enq TX index contention wait event, but they have not answered my question.

    I was hoping that some investigation by Oracle Support into the failed probes metric might get someone on the right track to discovering the bug. That hasn’t happened though.

    Comment by Erik Cotsonas — January 25, 2010 @ 2:55 pm BST Jan 25,2010 | Reply

    • There is another interesting little note under bug number 8286901, which says a similar type of bug (possibly the same one) is fixed in 11.2 – had you seen that ?

      Comment by Jonathan Lewis — January 25, 2010 @ 5:22 pm BST Jan 25,2010 | Reply

      • Yes, I saw that. I have applied patch 8286901 and set the event for version 10.2.0.4, but the problem still occurs periodically. And as I mentioned before, we see a correlation between enq TX waits and the failed probes on index block reclamation. Which is why I still think that it is a bug. I agree that trying to rebuild or coalesce the indexes are simply attempts to workaround the issue and not solve the root cause.

        Early on when I started on this issue I did do some index dumps and could clearly see that we had lots of blocks with only 1 or 2 records after our mass delete jobs. I have provided Oracle Support with this information as well as oradump files while the problem is occurring, but they don’t seem to be able to find anything wrong so far.

        If you are interested in seeing if you are experiencing a high ‘failed probes on index block reclamation’ event run the query below.

        select SS.snap_id,
        SS.stat_name,
        TO_CHAR(S.BEGIN_INTERVAL_TIME, ‘DAY’) DAY,
        S.BEGIN_INTERVAL_TIME,
        S.END_INTERVAL_TIME,
        SS.value,
        SS.value – LAG(SS.VALUE, 1, ss.value) OVER (ORDER BY SS.SNAP_ID) AS DIFF
        from DBA_HIST_SYSSTAT SS,
        DBA_HIST_SNAPSHOT S
        where S.SNAP_ID = SS.SNAP_ID
        AND SS.stat_NAME = ‘failed probes on index block reclamation’
        ORDER BY SS.SNAP_ID ;

        Comment by Erik Cotsonas — January 25, 2010 @ 7:49 pm BST Jan 25,2010 | Reply

        • Recently i have tested this bug on version 11.2.0.1 , still not fixed.
          Maybe Oracle Development department persisted in this index leaf split behavior is right; Saving space is important than a little index contention delay?

          Comment by maclean — June 7, 2010 @ 5:06 am BST Jun 7,2010

        • maclean,
          Thanks for the follow-up.

          Comment by Jonathan Lewis — June 8, 2010 @ 9:54 pm BST Jun 8,2010


RSS feed for comments on this post. TrackBack URI

Leave a Reply

Fill in your details below or click an icon to log in:

WordPress.com Logo

You are commenting using your WordPress.com account. Log Out / Change )

Twitter picture

You are commenting using your Twitter account. Log Out / Change )

Facebook photo

You are commenting using your Facebook account. Log Out / Change )

Google+ photo

You are commenting using your Google+ account. Log Out / Change )

Connecting to %s

Theme: Rubric. Get a free blog at WordPress.com

Follow

Get every new post delivered to your Inbox.

Join 4,267 other followers