12 Replies Latest reply: May 28, 2013 7:23 AM by mtefft RSS

    Very many 'db file sequential reads' for a simple UPDATE

    mtefft
      BANNER
      --------------------------------------------------------------------------------
      Oracle Database 11g Enterprise Edition Release 11.2.0.3.0 - 64bit Production
      PL/SQL Release 11.2.0.3.0 - Production
      CORE    11.2.0.3.0      Production
      TNS for Linux: Version 11.2.0.3.0 - Production
      NLSRTL Version 11.2.0.3.0 - Production
      
      5 rows selected.
      We have an UPDATE statement that is doing a very large number of 'db file sequential reads' for each execution, even though the plan shows it is a single-row update accessed via a unique index.
      From the TKPROF:
      SQL ID: 065zmdmsjj7vg Plan Hash: 3820849174
      
      Update PART_ITEM set row_filter_exp=null, row_filter_hash = null 
      where
       PART_ITEM_ID = :1  and row_filter_hash is not null
      
      
      call     count       cpu    elapsed       disk      query    current        rows
      ------- ------  -------- ---------- ---------- ---------- ----------  ----------
      Parse        0      0.00       0.00          0          0          0           0
      Execute    258     13.70     872.11     113473     516000          0           0
      Fetch        0      0.00       0.00          0          0          0           0
      ------- ------  -------- ---------- ---------- ---------- ----------  ----------
      total      258     13.70     872.11     113473     516000          0           0
      
      Misses in library cache during parse: 0
      Optimizer mode: ALL_ROWS
      Parsing user id: 119  
      
      Elapsed times include waiting on following events:
        Event waited on                             Times   Max. Wait  Total Waited
        ----------------------------------------   Waited  ----------  ------------
        db file sequential read                    113473        0.52        861.15
        SQL*Net message to client                     258        0.00          0.00
        SQL*Net message from client                   258        1.51          4.85
      So, this is 113473/258=440 db file sequential reads per execution. The ASH report shows that this was almost entirely in the table partition (not the index).
      This table has 4 CLOB columns all defined as ENABLE STORAGE IN ROW; the statement sets one of the CLOB columns to null (and 1 other VARCHAR2(128 BYTE) column to null). It is range/interval partitioned with 7 partitions. It has 47 million rows, but none of the LOB partition segments has grown beyond its original default size of 8 MB (so I think there are very few LOBs that are actually located in the LOB segments).

      Here is the plan:
      SQL_ID  065zmdmsjj7vg, child number 0
      -------------------------------------
      Update PART_ITEM set row_filter_exp=null, row_filter_hash = null where
      PART_ITEM_ID = :1  and row_filter_hash is not null
      
      Plan hash value: 3820849174
      
      --------------------------------------------------------------------------------------------------------------------
      | Id  | Operation                           | Name         | Rows  | Bytes | Cost (%CPU)| Time     | Pstart| Pstop |
      --------------------------------------------------------------------------------------------------------------------
      |   0 | UPDATE STATEMENT                    |              |       |       |     3 (100)|          |       |       |
      |   1 |  UPDATE                             | PART_ITEM    |       |       |            |          |       |       |
      |*  2 |   TABLE ACCESS BY GLOBAL INDEX ROWID| PART_ITEM    |     1 |   102 |     3   (0)| 00:00:01 | ROWID | ROWID |
      |*  3 |    INDEX UNIQUE SCAN                | PK_PART_ITEM |     1 |       |     2   (0)| 00:00:01 |       |       |
      --------------------------------------------------------------------------------------------------------------------
      
      Predicate Information (identified by operation id):
      ---------------------------------------------------
      
         2 - filter("ROW_FILTER_HASH" IS NOT NULL)
         3 - access("PART_ITEM_ID"=:1)
      Suspecting migrated rows, I ran the Segment Advisor on the table partitions and it reports that 5 of the partitions have over 30% chained rows. However, we do not see any significant amount of 'table fetch continued row' events in our AWR report - which should be a sign that such migrated rows are being encountered and re-assembled:
      Statistic                      Total   per Second   per Trans 
      table fetch by rowid       5,162,227     1,431.66   20,648.91 
      table fetch continued row        594         0.16        2.38 
      The average row length is about 350 (even with the LOBs) so I think chained rows (i.e. > block size) are also minimal.

      Any suggestions on where to look here?

      Thanks,
      Mike
        • 1. Re: Very many 'db file sequential reads' for a simple UPDATE
          sb92075
          is the table that is being updated part of any PK/FK relationship?
          is any column that is being updated included in any index?
          • 2. Re: Very many 'db file sequential reads' for a simple UPDATE
            damorgan
            Hi SB ... let me take a shot at answering your question.
            Update PART_ITEM
            |*  2 |   TABLE ACCESS BY GLOBAL INDEX ROWID| PART_ITEM    |     1 |   102 |     3   (0)| 00:00:01 | ROWID | ROWID |
            |*  3 |    INDEX UNIQUE SCAN                | PK_PART_ITEM |     1 |       |     2   (0)| 00:00:01 |       |       |
            --------------------------------------------------------------------------------------------------------------------
            Does this help? ;-)
            • 3. Re: Very many 'db file sequential reads' for a simple UPDATE
              mtefft
              The answer should be: 'it is parent in 16 foreign-key relationships, all of which are disabled'.
              Unfortunately, when checking that I see one of those constraints is enabled. (were you an understudy for Johnny Carson in his Karnak the Magnificent days?)
              It is also the child of 8 foreign-key relationships, all of which are disabled.

              However...
              The FK constraint references the PK of this table, and the PK column is not being changed.
              One of the columns being updated is a LOB and therefore has a LOB index - is that relevant? The other column is not indexed.

              (The constraints are defined, but disabled, so that an ETL tool can detect them and use them.)
              • 4. Re: Very many 'db file sequential reads' for a simple UPDATE
                mtefft
                ummm... no, I need another hint. What do you see?
                • 5. Re: Very many 'db file sequential reads' for a simple UPDATE
                  mtefft
                  Regarding the lone enabled foreign key - I do not see the table segment or the index segment for the child table in either the ASH report or the AWR report.

                  The foreign key is a good catch, and we will fix that, but I strongly suspect there is something else afoot here.
                  • 6. Re: Very many 'db file sequential reads' for a simple UPDATE
                    Jonathan Lewis
                    mtefft wrote:
                    Regarding the lone enabled foreign key - I do not see the table segment or the index segment for the child table in either the ASH report or the AWR report.

                    The foreign key is a good catch, and we will fix that, but I strongly suspect there is something else afoot here.
                    Did you get the execution plan from the tkprof output, and if so was it the Rowsource Execution bit ? One possible interpretation of the figures is that you were actually doing a tablescan of a table what was largely cached, and never needed multi-block reads (maybe a very small extent size and lots of prior indexed access.)

                    Do we trust ASH ? Maybe - for reasons unknown - the blocks reported by ASH are the wrong blocks. You have the 10046 trace with wait states, how about extracting all the db file sequential reads for the update cursor and checking the file, block and object numbers to see if that gives you any clues ?

                    Regards
                    Jonathan Lewis
                    • 7. Re: Very many 'db file sequential reads' for a simple UPDATE
                      Dropbear67
                      is the fact that it seems to be a partition based index relevant here?
                      • 8. Re: Very many 'db file sequential reads' for a simple UPDATE
                        Jonathan Lewis
                        Dropbear67 wrote:
                        is the fact that it seems to be a partition based index relevant here?
                        I don't think so.

                        The index used is a global unique index, accessed for a unique scan, and the only access predicate is the ID. This means Oracle does a single probe in the index segment (plus any work done for read-consistency or block cleanout) followed by a single block access to get the single row in the correct partition of the range-partitioned table (with any work needed for read consistency / block cleanout and chained row fetches).

                        (I've realised, by the way, that we probably ought to be able to assume that the in-memory plan was the plan used at the time of the trace because the plan hash values match, and the tkprof output shows no misses in the library cache on parse or execute).

                        The partitioning thing might help us if any rows had been updated - we haven't been told exactly how the table is partitioned, so we could imagine that changing the flag field caused row movement between partitions, which would require any out-of-row CLOBs in a moving row to be deleted from one CLOB section and inserted into another. (But even then we've been told that the CLOB segments are tiny, which suggests very few CLOBs have gone out of row.)

                        All in all, it's a bit of a puzzle - which is why a detailed analysis of the trace file might be the only sensible step - apart from anything else it might tell us (looking at the EXEC and WAIT lines whether the "average" reads per execution is a sensible reading, or whether all the reads should be attributed to just one or two executions.

                        Regards
                        Jonathan Lewis
                        • 9. Re: Very many 'db file sequential reads' for a simple UPDATE
                          mtefft
                          Thanks for the suggestion to investigate the detailed waits in the trace file.

                          Just to be clear about what I did... I parsed the 'db file sequential read' lines in the file; here is a sample:
                          WAIT #140693167443376: nam='db file sequential read' ela= 8258 file#=250 block#=1594591 blocks=1 obj#=1147874 tim=1369243612977716

                          Here are my findings.
                          - The 'db file sequential read' events referenced only two objects (i.e. obj#=): the index PK_PART_ITEM and a single partition in PART_ITEM. This single-partition behavior is as designed - this is a batch process which is to affect rows only from a single data source, which is what the partitioning column represents.
                          - 99.8% of the events, and 99.8% of the elapsed time (ela=), were on the table partition.
                          - Mean elapsed time is 7589 us. Median is 6854 us.

                          Other comments:
                          - The partitioning column is DATA_ORIGIN_ID - essentially a data source.
                          - In this run, none of the updates actually updated any rows, becuase of the predicate "and row_filter_hash is not null". (Note the line from the TKPROF: Execute count = 258 but rows=0). We pointed that out to the developer, with the request to add that predicate to the cursor that is driving these UPDATEs. That will certainly drastically reduce the frequency of these updates, for this job.

                          I will ask for runs of the new job, plus other jobs that do updates on this table, and see if we still have the same issues.
                          • 10. Re: Very many 'db file sequential reads' for a simple UPDATE
                            Jonathan Lewis
                            mtefft wrote:
                            Thanks for the suggestion to investigate the detailed waits in the trace file.

                            Just to be clear about what I did... I parsed the 'db file sequential read' lines in the file; here is a sample:
                            WAIT #140693167443376: nam='db file sequential read' ela= 8258 file#=250 block#=1594591 blocks=1 obj#=1147874 tim=1369243612977716

                            Here are my findings.
                            - The 'db file sequential read' events referenced only two objects (i.e. obj#=): the index PK_PART_ITEM and a single partition in PART_ITEM. This single-partition behavior is as designed - this is a batch process which is to affect rows only from a single data source, which is what the partitioning column represents.
                            - 99.8% of the events, and 99.8% of the elapsed time (ela=), were on the table partition.
                            - Mean elapsed time is 7589 us. Median is 6854 us.
                            The obj# should be correct for this wait in this version of Oracle - but to cover all bases I'd be prepared to assume it was wrong, and check some of the file/block numbers.

                            I'd pick the EXEC lines and the WAIT lines from the trace, and check the actual number of WAITs for each exec to see whether every EXEC did the same number of waits. I'd also look at a couple of examples in detail - dumping a few table blocks from consecutive waits to see if they show anything useful.

                            Regards
                            Jonathan Lewis
                            • 11. Re: Very many 'db file sequential reads' for a simple UPDATE
                              Bobby Durrett
                              Are there any triggers on the table?

                              - Bobby
                              • 12. Re: Very many 'db file sequential reads' for a simple UPDATE
                                mtefft
                                There are no triggers on the table.

                                Thanks,
                                Mike