Oracle Scratchpad

March 14, 2016

Quiz

Filed under: Oracle,Performance — Jonathan Lewis @ 9:38 pm GMT Mar 14,2016

Can you spot anything that might appear to be a little surprising about this (continuous) extract from a trace file ? The example is from 10.2.0.5, but 11g and 12c could produce similar results (or direct path read equivalents):


PARSING IN CURSOR #3 len=23 dep=0 uid=30 oct=3 lid=30 tim=112607775392 hv=4235652837 ad='2f647320'
select count(*) from t1
END OF STMT
PARSE #3:c=0,e=53,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=112607775385
EXEC #3:c=0,e=99,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=112607787370
WAIT #3: nam='SQL*Net message to client' ela= 9 driver id=1111838976 #bytes=1 p3=0 obj#=10443 tim=112607789931
WAIT #3: nam='db file sequential read' ela= 415 file#=5 block#=9 blocks=1 obj#=21580 tim=112607795682
WAIT #3: nam='db file scattered read' ela= 2785 file#=5 block#=905 blocks=98 obj#=21580 tim=112607801263
WAIT #3: nam='db file scattered read' ela= 2919 file#=5 block#=777 blocks=128 obj#=21580 tim=112607808280
WAIT #3: nam='db file scattered read' ela= 2066 file#=5 block#=649 blocks=128 obj#=21580 tim=112607813300
WAIT #3: nam='db file scattered read' ela= 1817 file#=5 block#=521 blocks=128 obj#=21580 tim=112607817243
WAIT #3: nam='db file scattered read' ela= 1563 file#=5 block#=393 blocks=128 obj#=21580 tim=112607820899
WAIT #3: nam='db file scattered read' ela= 1605 file#=5 block#=265 blocks=128 obj#=21580 tim=112607824710
WAIT #3: nam='db file scattered read' ela= 1529 file#=5 block#=137 blocks=128 obj#=21580 tim=112607828296
WAIT #3: nam='db file scattered read' ela= 1652 file#=5 block#=10 blocks=127 obj#=21580 tim=112607831946
FETCH #3:c=15625,e=41568,p=994,cr=996,cu=0,mis=0,r=1,dep=0,og=1,tim=112607834004
WAIT #3: nam='SQL*Net message from client' ela= 254 driver id=1111838976 #bytes=1 p3=0 obj#=21580 tim=112607835527
FETCH #3:c=0,e=3,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=0,tim=112607836780
WAIT #3: nam='SQL*Net message to client' ela= 2 driver id=1111838976 #bytes=1 p3=0 obj#=21580 tim=112607837935
WAIT #3: nam='SQL*Net message from client' ela= 14371 driver id=1111838976 #bytes=1 p3=0 obj#=21580 tim=112607853526
=====================
PARSING IN CURSOR #2 len=52 dep=0 uid=30 oct=47 lid=30 tim=112607855239 hv=1029988163 ad='2f6c5ec0'
BEGIN DBMS_OUTPUT.GET_LINES(:LINES, :NUMLINES); END;
END OF STMT
PARSE #2:c=0,e=51,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,tim=112607855228
WAIT #2: nam='SQL*Net message to client' ela= 4 driver id=1111838976 #bytes=1 p3=0 obj#=21580 tim=112607861803
EXEC #2:c=0,e=1271,p=0,cr=0,cu=0,mis=0,r=1,dep=0,og=1,tim=112607862976
WAIT #2: nam='SQL*Net message from client' ela= 1093883 driver id=1111838976 #bytes=1 p3=0 obj#=21580 tim=112608958078
STAT #3 id=1 cnt=1 pid=0 pos=1 obj=0 op='SORT AGGREGATE (cr=996 pr=994 pw=0 time=41588 us)'
STAT #3 id=2 cnt=8332 pid=1 pos=1 obj=21580 op='TABLE ACCESS FULL T1 (cr=996 pr=994 pw=0 time=144816 us)'

Update

If you look at the values for block# in the “db file scattered read” waits you’ll notice that they appear in descending order. This looks like a tablescan running backwards – and that’s not a coincidence, because that’s what it is.

It’s obviously a good strategy to have because if you do a big tablescan it’s the blocks at the END of the table which are mostly likely to be subject to change by other sessions [unless, see comment 4, you’ve done a purge of historic data] and the longer it takes you to get there the more work you’ll have to do to get consistent read versions of the last blocks in the table, so reading the last blocks first should, generally, reduce the workload – and the risk of ORA-01555: snapshot too old. Strangely it’s not documented – but it’s been around for years – at least since 10.2.0.5, if not earlier releases of 10g, through event 10460.

The topic came up in a conversation on the Oracle-L list server a few years ago, with Tanel Poder supplying the event number, but I had forgotten about it until I rediscovered the thread by accident a little while ago.

It’s not a supported feature, of course – but if you run into serious performance problems with tablescans doing lots of work with the undo tablespace (physical reads, lots of undo records applied for consistent read, etc.) while a lot of update activity is going on, then have a chat with Oracle support to see if it’s an allowed workaround.

 

 

13 Comments »

  1. blocks reads in descending order?

    Comment by Sayan Malakshinov — March 14, 2016 @ 9:56 pm GMT Mar 14,2016 | Reply

  2. Jonathan,

    For sure the strange think is it looks like Oracle has started a full table scan in reverse order. I’d suggest the first db file sequential read (flle#5 block#9) was for the segment header of the table t1. Surprisingly it does not continue with block 10, rather starts somehow from the end of the table. The second physical read (aka first multibloc} seems to be from the end of the table as it reads only 98 blocks and your instance has obviously set the db_file_multiblock_read_count parameter to 128. I’d be able to do similar think with:
    – taking tablespace uniform size 1MB
    – creating 8 different segments, i.e. by creating 8 tables aux1, aux2, .. aux8.
    – then contiune by drop table aux8 and createing table t1
    – drop table aux 7 and allocate extent tu t1
    – …. drop table aux1 and allocate the first extent of the file to t1
    but the 98 block read spoils my approach :)

    Have no idea at this moment how you achieved this. I was thinking of some strange things with an IOT, however the table t1 seems to be non-partitioned heap table (at least we see FULL TABLE SCAN in execution plan, not a INDEX FFS)

    Comment by Pavol Babel — March 14, 2016 @ 10:41 pm GMT Mar 14,2016 | Reply

    • Jonathan,

      Well, I think now it is clear to me :) . It seems you have really made oracle to perform backward table scan. I’l let other readers try to find the way themselves, shouldn’t be very difficult tough

      
      << perform magic command >>
      
      select count(*) from reporting_data.palo;
      
      fragment from my tracefile:
      
      PARSING IN CURSOR #4863320000 len=40 dep=0 uid=0 oct=3 lid=0 tim=3657879774519 hv=40460096 ad='700010294a7e100' sqlid='1ygtvhh16kru0'
      select count(*) from reporting_data.palo
      END OF STMT
      PARSE #4863320000:c=3082,e=5952,p=1,cr=64,cu=0,mis=1,r=0,dep=0,og=1,plh=2607168572,tim=3657879774519
      EXEC #4863320000:c=6,e=10,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=2607168572,tim=3657879774568
      WAIT #4863320000: nam='SQL*Net message to client' ela= 2 driver id=1650815232 #bytes=1 p3=0 obj#=40 tim=3657879774606
      WAIT #4863320000: nam='direct path read' ela= 3453 file number=120 first dba=7744 block cnt=33 obj#=40575 tim=3657879801159
      WAIT #4863320000: nam='direct path read' ela= 2797 file number=120 first dba=7616 block cnt=64 obj#=40575 tim=3657879804396
      WAIT #4863320000: nam='direct path read' ela= 4541 file number=120 first dba=7488 block cnt=64 obj#=40575 tim=3657879809394
      WAIT #4863320000: nam='direct path read' ela= 3846 file number=120 first dba=7360 block cnt=64 obj#=40575 tim=3657879813700
      WAIT #4863320000: nam='direct path read' ela= 2955 file number=120 first dba=7232 block cnt=64 obj#=40575 tim=3657879817098
      WAIT #4863320000: nam='direct path read' ela= 3366 file number=120 first dba=7104 block cnt=64 obj#=40575 tim=3657879820908
      WAIT #4863320000: nam='direct path read' ela= 3185 file number=120 first dba=6976 block cnt=64 obj#=40575 tim=3657879824543
      .
      .
      

      Please note I’m using 16kB block database and 1MB uniform size tablespace (12c database). This reminds me I was recalling this feature in 9i when I ran into troubles with a transaction table reconstruction (in an undo segment header), quite often finishing with infamous ORA-1555. I have to check if this hack did exist in 9i :)

      Best Regards
      Pavol Babel

      Comment by Pavol Babel — March 14, 2016 @ 11:07 pm GMT Mar 14,2016 | Reply

      • Jonathan,

        Yes the magic command was alter session set events ‘10460 trace name context forever, level1’ :)

        I was thinking whole day the reason why you have mentioned this “feature”. No I’m quite satisfied the reason is the same as mine. Meanwhile, I have checked 9i and it seems there was no event 10460, at least in 9.2.0.6

        Comment by Pavol Babel — March 15, 2016 @ 11:34 pm GMT Mar 15,2016 | Reply

        • Pavol,

          Big tables, long history, no purge. The bigger the table gets the longer the report takes to run because of the longer time available for more of the recent data to change.
          I did say “earlier versions of 10g” – my last 9i check was 9.2.0.8, and it wasn’t implemented in that version.

          Comment by Jonathan Lewis — March 16, 2016 @ 9:34 am GMT Mar 16,2016

  3. Hi Jonathan,

    With the introduction of ASSM and LMT data can be scattered across everywhere how could reading from the table from backward will help in this scenario? will it helpful if data get inserted in specific order and using manual segement management?

    Comment by Henish — March 16, 2016 @ 1:07 am GMT Mar 16,2016 | Reply

    • Henish,

      With ASSM the scattering of the data on insert tends to be restricted to a single extent at a time rather than being completely random. (It’s a strong bias, not a guarantee, and depends on patterns in the data content), so reading the table backwards will still tend to cover the most recent first. (But see also the response to Hemant’s comment).

      Comment by Jonathan Lewis — March 16, 2016 @ 8:27 am GMT Mar 16,2016 | Reply

  4. I’d add an “AND IF” between the “big tablescan” and “it’s the blocks at the END of the table ….” It’s not always the case that the blocks at the end of the table which are subject to change. Blocks at the end of the datafile could have been the first few extents of the table (depending on what pattern of CREATE this table after creating and populating other tables and then DROP other tables has occurred) and if the “oldest” (i.e first) rows in the table are not subject to change, these end-blocks are likely static. On the other hand, there might be an application scenario where the oldest rows in blocks at the beginning of the datafile are undergoing more DML (DELETE operations run periodically ?)

    Comment by Hemant K Chitale — March 16, 2016 @ 2:22 am GMT Mar 16,2016 | Reply

    • Hemant,

      You’re correct to raise the point about the positioning of blocks. The implementation leaves something to be desired. To my mind the “end” of the table is in the last allocated extent (which does leave a grey area for parallel insert/append) but while a normal tablescan reads the extents in order of extent_id (i.e. allocation), a reverse tablescan reads the extents in reverse order of block address (which, even if we never had to worry about random appearance of holes, still leaves us worrying about tablespaces with multiple files).

      [Update: I’m sure I got a result which showed the extents being read in reverse order of starting block id, but I’ve just re-run that test and they were read in reverse order of extent_id – which eliminates your concern about where extents are allocated]

      This also introduced doesn’t eliminate the problem (which I’ve now mentioned in the text) of tables where you’ve done a large purge, presumably with the intent of emptying the early blocks of the table and making them available for reuse. Again this would leave a reverse tablescan reaching the most recently changing data last even in a very cleanly allocated tablespace.

      There are several reasons the implementation could be improved, but that’s why I’ve described the symptoms that would give some indication that the mechanism might be relevant for their circumstances.

      P.S. I don’t think “AND IF” would be appropriate. The qualifying “most likely” is correct when the “END” of the table is the last allocated extent rather than the position in the file.

      Comment by Jonathan Lewis — March 16, 2016 @ 8:55 am GMT Mar 16,2016 | Reply

  5. You probably intended to write, “If you look at the values for block# in the ‘db file *** scattered *** read’ waits,” instead of “sequential.”

    Comment by Ted Persky — March 29, 2016 @ 7:53 pm GMT Mar 29,2016 | Reply

  6. Jonathan,

    For me it is not re-producing test case. I am using version 11.2.0.4 on Windows

    
    SQL> select * from v$version;
    
    BANNER
    --------------------------------------------------------------------------------
    Oracle Database 11g Enterprise Edition Release 11.2.0.4.0 - 64bit Production
    PL/SQL Release 11.2.0.4.0 - Production
    CORE    11.2.0.4.0      Production
    TNS for 64-bit Windows: Version 11.2.0.4.0 - Production
    NLSRTL Version 11.2.0.4.0 - Production
    
    

    and here is the trace output (of event: ‘10460 trace name context forever, level 1’) –

    PARSING IN CURSOR #343387048 len=23 dep=0 uid=110 oct=3 lid=110 tim=389466838656 hv=3206357463 ad='7ff44e9d418' sqlid='a2d8wpfzju8fr'
    select count(1) from t1
    END OF STMT
    PARSE #343387048:c=0,e=64,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=3724264953,tim=389466838656
    EXEC #343387048:c=0,e=31,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=1,plh=3724264953,tim=389466838739
    WAIT #343387048: nam='SQL*Net message to client' ela= 4 driver id=1111838976 #bytes=1 p3=0 obj#=0 tim=389466838789
    WAIT #343387048: nam='Disk file operations I/O' ela= 374365 FileOperation=2 fileno=4 filetype=2 obj#=94397 tim=389467213204
    WAIT #343387048: nam='db file sequential read' ela= 36069 file#=4 block#=170 blocks=1 obj#=94397 tim=389467249486
    WAIT #343387048: nam='db file sequential read' ela= 22929 file#=4 block#=39296 blocks=1 obj#=94397 tim=389467273531
    WAIT #343387048: nam='db file sequential read' ela= 18141 file#=4 block#=169 blocks=1 obj#=94397 tim=389467291796
    WAIT #343387048: nam='db file scattered read' ela= 7830 file#=4 block#=39297 blocks=3 obj#=94397 tim=389467299883
    WAIT #343387048: nam='direct path read' ela= 24632 file number=4 first dba=40064 block cnt=8 obj#=94397 tim=389467325182
    WAIT #343387048: nam='direct path read' ela= 736 file number=4 first dba=40072 block cnt=8 obj#=94397 tim=389467326364
    WAIT #343387048: nam='direct path read' ela= 12885 file number=4 first dba=40088 block cnt=8 obj#=94397 tim=389467339716
    WAIT #343387048: nam='direct path read' ela= 12048 file number=4 first dba=40096 block cnt=8 obj#=94397 tim=389467352148
    WAIT #343387048: nam='direct path read' ela= 14160 file number=4 first dba=40104 block cnt=8 obj#=94397 tim=389467366481
    WAIT #343387048: nam='direct path read' ela= 19572 file number=4 first dba=40112 block cnt=8 obj#=94397 tim=389467386235
    WAIT #343387048: nam='direct path read' ela= 29097 file number=4 first dba=40120 block cnt=8 obj#=94397 tim=389467415561
    WAIT #343387048: nam='direct path read' ela= 106 file number=4 first dba=40128 block cnt=8 obj#=94397 tim=389467415845
    WAIT #343387048: nam='direct path read' ela= 1180 file number=4 first dba=40136 block cnt=8 obj#=94397 tim=389467417101
    WAIT #343387048: nam='direct path read' ela= 4611 file number=4 first dba=40144 block cnt=8 obj#=94397 tim=389467421860
    WAIT #343387048: nam='direct path read' ela= 78 file number=4 first dba=40152 block cnt=8 obj#=94397 tim=389467422054
    
    *** 2016-04-02 18:50:15.967
    WAIT #343387048: nam='direct path read' ela= 46120 file number=4 first dba=40160 block cnt=8 obj#=94397 tim=389467468242
    WAIT #343387048: nam='direct path read' ela= 449 file number=4 first dba=40168 block cnt=8 obj#=94397 tim=389467468909
    WAIT #343387048: nam='direct path read' ela= 3836 file number=4 first dba=40176 block cnt=8 obj#=94397 tim=389467472846
    WAIT #343387048: nam='direct path read' ela= 402 file number=4 first dba=40184 block cnt=8 obj#=94397 tim=389467473374
    WAIT #343387048: nam='direct path read' ela= 38481 file number=4 first dba=40192 block cnt=8 obj#=94397 tim=389467511949
    WAIT #343387048: nam='direct path read' ela= 315 file number=4 first dba=40200 block cnt=8 obj#=94397 tim=389467512461
    WAIT #343387048: nam='direct path read' ela= 25226 file number=4 first dba=40208 block cnt=8 obj#=94397 tim=389467537802
    WAIT #343387048: nam='direct path read' ela= 46947 file number=4 first dba=40224 block cnt=8 obj#=94397 tim=389467585940
    WAIT #343387048: nam='direct path read' ela= 485 file number=4 first dba=40232 block cnt=8 obj#=94397 tim=389467586958
    WAIT #343387048: nam='direct path read' ela= 222 file number=4 first dba=40240 block cnt=8 obj#=94397 tim=389467587579
    WAIT #343387048: nam='direct path read' ela= 45418 file number=4 first dba=40248 block cnt=8 obj#=94397 tim=389467633382
    WAIT #343387048: nam='direct path read' ela= 310 file number=4 first dba=40256 block cnt=8 obj#=94397 tim=389467634188
    WAIT #343387048: nam='direct path read' ela= 39747 file number=4 first dba=40264 block cnt=8 obj#=94397 tim=389467674285
    WAIT #343387048: nam='direct path read' ela= 29952 file number=4 first dba=40280 block cnt=8 obj#=94397 tim=389467705051
    WAIT #343387048: nam='direct path read' ela= 393 file number=4 first dba=40288 block cnt=8 obj#=94397 tim=389467706073
    WAIT #343387048: nam='direct path read' ela= 7349 file number=4 first dba=40296 block cnt=8 obj#=94397 tim=389467713729
    WAIT #343387048: nam='direct path read' ela= 23940 file number=4 first dba=40312 block cnt=8 obj#=94397 tim=389467738482
    WAIT #343387048: nam='direct path read' ela= 24535 file number=4 first dba=39816 block cnt=8 obj#=94397 tim=389467763371
    

    Even I tried forcing scattered reads (by setting _small_table_threshold value high), but result are same. Is there any thing missing.

    Comment by Sandeep Redkar — April 2, 2016 @ 2:28 pm GMT Apr 2,2016 | Reply

    • Sandeep,

      I think there may be more to do in investigating the mechanism in detail, but I did note in one of the comments that the scan appears to be running in reverse order of extent id.

      In your case your read is 8 blocks (compared to my 128 blocks / 1MB) – so I suspect the extract you’ve shown is Oracle reading the last extent of the table in ascending order, with the very last line of the trace showing the Oracle reading the first few blocks of the last extent but one.

      You could confirm this by checking dbs_extents for extent_id, file_id and block_id. Looking at the starting db file sequential and scattered reads, I think you might be using a 32KB block size, and the reads of blocks 39296 – 39299 are the reads of the space management blocks at the start of an earlier (8MB) extent in the object. And if that’s correct I’m wondering if you’re doing parallel loads into partitioned objects – and the parallelism could result in an odd ordering of extent ids, even if you start with a completely clean tablespace.

      Comment by Jonathan Lewis — April 2, 2016 @ 8:25 pm GMT Apr 2,2016 | Reply


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

Blog at WordPress.com.