Forum Stats

  • 3,726,973 Users
  • 2,245,299 Discussions
  • 7,852,514 Comments

Discussions

Performance issue due to checkpoint wait

User_OCZ1T
User_OCZ1T Member Posts: 1,921 Gold Badge

Hi, We are using version 11.2.0.4 of oracle Exadata. We get hit by below bug in which cell offloading was not happening in DML(INSERT.. INTO TAB1.. SELECT...) , so we had set the session level parameter _serial_direct_read to 'ALWAYS' in the code. But as we had multiple DMLS getting impacted by this, we had tried setting the same session level parameter at the start of the package/procedure code which is getting called ~1500 times/day from different sessions ( it getting called concurrently also).

What we noticed is, during the actual run , one of the query which used to finish in <1minutes was running for hours, now when we checked it was all waiting on event "enq: KO - fast object checkpoint". I have posted just the specific section of the sql monitor as below. The sql plan has not been changed from past, but this time the "INDEX STORAGE FAST FULL SCAN" in a nested loop suffered badly as it was doing it 200k+ times, at line no-25 below.

We had talk to Support before setting this underscore parameter , it can be used as an workaround to get benefit of cell smart scan in case of DMLS. But they also , mentioned if any frequent DML is happening(say OLTP kind of app) and that table is getting read as direct path forcibly many times, that can affect negatively, as because each smartscan will try to force the checkpoint and have the DB writer to flush the dirty blocks from buffer cache to disk. But in this scenario the index which was suffering was belongs to a table which holds total ~70 rows and is a reference data table so not getting changed frequently even its getting accessed heavily from multiple sessions.

So , why the "fast object checkpoint" is affecting this query/index scan(which is part of a very small table having least DML acivity on it)?

Bug 13250070 - Enh: Serial direct reads not working in DML (Doc ID 13250070.8)

Below is the part of the sql monitor for the big query in which the INDEX FAST FULL SCAN showing ~4783 sample for "enq: KO - fast object checkpoint":


Global Stats

======================================================================================================

| Elapsed |  Cpu  |   IO   | Application | Cluster | Other  | Buffer | Read | Read | Cell  |

| Time(s) | Time(s) | Waits(s) | Waits(s)  | Waits(s) | Waits(s) | Gets | Reqs | Bytes | Offload |

======================================================================================================

|  10741 |    807 |    1686 |       4795 |    0.08 |    3453 |  912K | 273K |  2GB | 94.64% |

======================================================================================================


SQL Plan Monitoring Details (Plan Hash Value=3918063749)

========================================================================================================================================================================================================================================

| Id   |                  Operation                   |            Name             | Rows  | Cost |  Time   | Start | Execs |  Rows  | Read | Read | Cell  | Mem | Activity |            Activity Detail             |

|      |                                               |                              | (Estim) |     | Active(s) | Active |      | (Actual) | Reqs | Bytes | Offload |    |  (%)   |              (# samples)               |

========================================================================================================================================================================================================================================

|    0 | INSERT STATEMENT                              |                              |        |     |          |       |    1 |         |     |      |        |    |         |                                         |

| -> 1 |  LOAD TABLE CONVENTIONAL                     |                              |        |     |    10729 |   +16 |    1 |       0 |     |      |        |    |    0.03 | Cpu (3)                                 |

***************

*************

| -> 22 |         INDEX UNIQUE SCAN                    | TMRS_PK                      |      1 |     |    10729 |   +16 | 82371 |   82370 |     |      |        |    |         |                                         |

| -> 23 |        TABLE ACCESS BY INDEX ROWID           | TMRSC                        |      2 |   1 |    10729 |   +16 | 82371 |    268K |     |      |        |    |         |                                         |

| -> 24 |         INDEX RANGE SCAN                     | TMRSC_IX2                    |      3 |     |    10729 |   +16 | 82371 |    268K |     |      |        |    |         |                                         |

| -> 25 |       INDEX STORAGE FAST FULL SCAN           | TMRC_IX1                     |      1 |     |    10745 |    +0 | 268K |    112K | 267K |  2GB | 96.53% | 1M |   99.74 | enq: KO - fast object checkpoint (4783) |

|      |                                               |                              |        |     |          |       |      |         |     |      |        |    |         | Cpu (753)                               |

|      |                                               |                              |        |     |          |       |      |         |     |      |        |    |         | gcs drm freeze in enter server mode (25) |

|      |                                               |                              |        |     |          |       |      |         |     |      |        |    |         | latch free (1)                          |

|      |                                               |                              |        |     |          |       |      |         |     |      |        |    |         | reliable message (3505)                 |

|      |                                               |                              |        |     |          |       |      |         |     |      |        |    |         | cell smart index scan (1635)            |

| -> 26 |      INDEX RANGE SCAN                        | TMMC_IX1                     |      1 |     |    10729 |   +16 | 112K |    112K |     |      |        |    |    0.01 | Cpu (1)                                 |

| -> 27 |     TABLE ACCESS BY INDEX ROWID              | TMMC                         |      1 |   1 |    10729 |   +16 | 112K |    112K |     |      |        |    |         |                                         |

========================================================================================================================================================================================================================================

Best Answer

Answers

  • User_OCZ1T
    User_OCZ1T Member Posts: 1,921 Gold Badge
    edited October 2020


    Thank You So much @AndrewSayer

    Got your point regarding the fact that the plan would have been lot better(Say index range scan etc) so that this checkpoint would not have been an issue for us. And yes , with same plan in a normal day scenario(i.e. no forced serial_direct_read), it used to finish in <1minutes with same volume.

     So my doubt was , why this reference table(which is anyway very small in size) has to go through this wait event there were no changes made to this object during that time. And as i got it from your description is that because, it doesn't have to be really flush finite number of dirty blocks to the disk at each loop/check point/smart scan, rather its the amount of work it has to do to find out if the data in the disk for that index is all up to date or not for each iteration in the nested loop (i.e ~268k times it did that in the plan). Which means this sort of wrong execution path can cause such dramatic slowness with force Direct path read/smart scan, may it be oltp or warehousing kind of system, irrespective of size of the object or frequency of change of data in that object. This issue can be appeared even there is not much activity happening in the database or on that object, we need to be careful while setting this up in a bigger scope of sqls say for e.g. schema level etc . And this must be the reason Oracle has not made this default rather given as a work around for the bug. Correct me if wrong.

    Though for us this issue happened while our system was busy even if not much DML was happening on the exact object, but i will also try to reproduce that in a calm/silent period in the database and i hope this is going to show same slowness with the same path.

    Edited:-

    Still wondering though what all key steps it must be doing such that it was making that ~1minute query running for more than an hour?

  • AndrewSayer
    AndrewSayer Member Posts: 12,998 Gold Crown

    It comes down to the basic rule of performance tuning:

    Do it less often - you were doing 268K enq: KO - fast object checkpoint, once per time you had to direct path read something

    Do it quicker - each was taking about 0.2 seconds so perhaps that's how long it took to contact CKPT and get a confirmation that the data is safely on "disk". Perhaps CKPT was busy checkpointing other things, perhaps some of the time it needed to spend more time (0.2 seconds is just the average) and had to get DBWn to get involved. BTW you can check things like v$event_histogram to see the distribution of fast and slow waits on this event (get the difference of before the execution and after). You can also make some estimates based on v$active_session_history samples, each second that has a sample for this event will tell you how long it had been waiting on it - although you must appreciate that this is not going to be the strongest of evidence as you only get 1 sample per second (although apparently you had 4783 samples for one execution according to the SQL monitor report, and at an average of 0.2 seconds each you might actually get a good idea about the longer waits).

  • Jonathan Lewis
    Jonathan Lewis Member Posts: 9,569 Gold Crown


    You haven't shown us quite enough of the plan to let use see what's driving the nested loop that thinks an index fast full scan 268K times is a good idea. It would also be worth checking whether you have a setting of optimizer_index_cost_adj which is making the optimizer to an index fast full scan when an index range scan (or even an index full scan) would be better.

    The issue relates to the direct path segment (in your case index) scan and the need for the session to do an object checkpoint to ensure that the current version of all blocks in that object are on disc so that the direct path blocks can be made correctly read-consistent. The fact that you're also running RAC can make the problem much worse because the object checkpoint has to be cross-instance (which might explain the DRM freeze and the time it takes for the reliable message wait to complete).

    I've got a model that emulates the problem - and even running on non-RAC in 11g it only takes a handful of updates on the scanned segment to kick off a massive cascade of KO locks and reliable message waits. I've just re-run the test on 19.3 and it behaves completely differently - no massive cascade (yet)).

    It seems to me that your session should need only one KO lock to flush the index to disc at the start of the query (and one for any other object subject to direct path segment scan), since any further writes to disc mean any scans after the first one will still be reading data that can be rolled back successfully to the required SCN. Since the behaviour seems to have change by 19.3 it's possible that the 11g behaviour (which would be the simplest strategy if you're not expecting anyone to do 268K segments scans in a single query)) has been recognised as a performance threat and an enhancement (bug fix) has been introduced.

    If I can find the time I'll write up a note about my model and post a link in the next couple of weeks.

    Regard

    Jonathan Lewis

  • User_OCZ1T
    User_OCZ1T Member Posts: 1,921 Gold Badge
    edited October 2020

    Thank You So much @Jonathan Lewis

    The query which was suffering was having hint in it and its there since long and if i remove hints from this query its by default going for an index range scan. So i am not much concerned about the query tuning as because we are mostly going to remove hints in the future code fix. But here, we were added the _serial_direct_read= Always at the start of the procedure code, so that all the DML can be benefited from the cell smart scan wherever possible. We were not aware of such drastic performance degradation due to that change.

    You are correct that it should only do once at that start of the query but not for each nested loop. And may be as you mentioned the 19C upgrade will help us there but again, i think 12.1+ version has the bug fix for the DML smart scan issue. I mean to say 12c onwards DMLs(INSERt AS SELECT..) also able to get benefit of the smart scan, so we may not have to do it by forcibly using the "_serial_direct_read" to "ALWAYS".

    Another odd thing which we noticed, is after we quickly rolled-back the code i.e. removed the "alter session.. _serial_direct_read.." from it and compiled it. Then the incoming new query executions were still doing that smart scan as we were seeing same "enq: KO - fast object checkpoint" waits. Here just to note, we don't have any change in plan_hash_value occurred, so it was using same plan throughout even with/without forced _serial_direct_read. Then we kill those sessions and purged that cursor from shared pool. After that , new sessions were even followed same plan, but didn't do the smart scan and finished in normal time(<1 minutes). This is something i am not able to understand, is it correct interpretation that the "_serial_direct_read" setup is stored in shared cursor in shared pool even no change in Plan hash value ?

  • User_OCZ1T
    User_OCZ1T Member Posts: 1,921 Gold Badge

     @Jonathan Lewis Regarding below point, 

     "It seems to me that your session should need only one KO lock to flush the index to disc at the start of the query (and one for any other object subject to direct path segment scan), since any further writes to disc mean any scans after the first one will still be reading data that can be rolled back successfully to the required SCN."

     Is my understanding correct that, you mean to say , the check-pointing(or flushing of dirty blocks to disk for smartscan/direct path read) should only happen at the first iteration of the nested loop not all ~268K times as because then after whatever data change happen we don't care about that, as because we already have the consistent version of the data which we already got/flushed in the first time itself to disk and that should suffice all the 268K iteration.So basically it should not even check/verify(or do checkpointing) if data exists or not in disk for the subsequent smart scans. And this has been implemented on 19C.

  • Jonathan Lewis
    Jonathan Lewis Member Posts: 9,569 Gold Crown

    Is my understanding correct that, you mean to say ...

    Your understanding is absolutely correct.

    There may be some reason why Oracle does need to do this checkpointing more than just once, and my assumption could be wrong, but the extreme behaviour in 11g looks like a bug that has been fixed by 19c (and, as you suggest in the previous post, might have been fixed in 12c - I'll have to test my model against 12.2 and 12.1 some time).

    Regards

    Jonathan Lewis

  • Jonathan Lewis
    Jonathan Lewis Member Posts: 9,569 Gold Crown

    Then the incoming new query executions were still doing that smart scan as we were seeing same "enq: KO - fast object checkpoint" waits. Here just to note, we don't have any change in plan_hash_value occurred, so it was using same plan throughout even with/without forced _serial_direct_read

    Again you're correct - the serial direct read is part of the cursor, and since you hadn't invalidated the cursor the new session just picked up the old cursor and re-used it.

    Regards

    Jonathan Lewis

    user10472047
  • Jonathan Lewis
    Jonathan Lewis Member Posts: 9,569 Gold Crown

    I've just published a model and some results.

    The 12c results are inconclusive, and even cast doubt on my comment about 19.3 being fixed.

    With sufficient change going on both 12.1 and 12.2 start showing significant numbet of KO and reliable message waits - though not the huge numbers that you get from 11g with even a small change:


    Regards

    Jonathan Lewis

    User_OCZ1T
Sign In or Register to comment.