FAQ
Trying to understand what is affecting the performance of some INSERTs that
we have going on.

Database is a 3 node 10.2.0.3 RAC database.

Table is a range-hash partitioned table (date range, 128 partition numeric
hash), with no indexes or LOBs. Tablespace is a locally SYSTEM managed ASSM
bigfile tablespace.

This particular INSERT is a single threaded FORALL INSERT with an arraysize
of 50000.

Tkprof output
-----------------

INSERT INTO STAGE_TRANS_WAYNE
VALUES
(:B1 ,:B2 ,:B3 ,:B4 ,:B5 ,:B6 ,:B7 ,:B8 ,:B9 ,:B10 ,:B11 ,:B12 ,:B13 ,:B14
,
:B15 ,:B16 ,:B17 ,:B18 ,:B19 ,:B20 ,:B21 ,:B22 ,:B23 ,:B24 ,:B25 ,:B26 ,
:B27 ,:B28 ,:B29 ,:B30 ,:B31 ,:B32 ,:B33 ,:B34 ,:B35 ,:B36 ,:B37 ,:B38 ,
:B39 ,:B40 ,:B41 ,:B42 ,:B43 ,:B44 ,:B45 ,:B46 ,:B47 ,:B48 ,:B49 ,:B50 ,
:B51 ,:B52 ,:B53 ,:B54 ,:B55 ,:B56 ,:B57 ,:B58 ,:B59 ,:B60 ,:B61 ,:B62 ,
:B63 ,:B64 ,:B65 ,:B66 ,:B67 ,:B68 ,:B69 ,:B70 ,:B71 ,:B72 ,:B73 ,:B74 ,
:B75 ,:B76 ,:B77 ,:B78 ,:B79 ,:B80 ,:B81 ,:B82 ,:B83 ,:B84 ,:B85 ,:B86 ,
:B87 ,:B88 ,:B89 ,:B90 ,:B91 ,:B92 ,:B93 ,:B94 ,:B95 ,:B96 ,:B97 ,:B98 ,
:B99 ,:B100 ,:B101 ,:B102 ,:B103 ,:B104 ,:B105 ,:B106 ,:B107 ,:B108 ,:B109
,
:B110 ,:B111 ,:B112 ,:B113 ,:B114 ,:B115 ,:B116 ,:B117 ,:B118 ,:B119
,:B120
,:B121 ,:B122 ,:B123 ,:B124 ,:B125 ,:B126 ,:B127 ,:B128 ,:B129 ,:B130 ,
:B131 ,:B132 ,:B133 ,:B134 ,:B135 ,:B136 ,:B137 ,:B138 ,:B139 ,:B140
,:B141
,:B142 ,:B143 ,:B144 ,:B145 ,:B146 ,:B147 ,:B148 ,:B149 ,:B150 ,:B151 ,
:B152 ,:B153 ,:B154 ,:B155 ,:B156 ,:B157 ,:B158 ,:B159 ,:B160 ,:B161
,:B162
,:B163 ,:B164 ,:B165 ,:B166 ,:B167 ,:B168 ,:B169 ,:B170 ,:B171 ,:B172 ,
:B173 ,:B174 ,:B175 ,:B176 ,:B177 ,:B178 ,:B179 ,:B180 ,:B181 ,:B182
,:B183
,:B184 ,:B185 ,:B186 ,:B187 ,:B188 ,:B189 ,:B190 ,:B191 ,:B192 ,:B193 ,
:B194 ,:B195 ,:B196 ,:B197 ,:B198 ,:B199 ,:B200 ,:B201 ,:B202 ,:B203
,:B204
,:B205 ,:B206 ,:B207 ,:B208 ,:B209 ,:B210 ,:B211 ,:B212 ,:B213 ,:B214 ,
:B215 ,:B216 ,:B217 ,:B218 ,:B219 ,:B220 ,:B221 ,:B222 ,:B223 ,:B224
,:B225
,:B226 ,:B227 ,:B228 ,:B229 ,:B230 ,:B231 ,:B232 ,:B233 ,:B234 ,:B235 )


call count cpu elapsed disk query current
rows
------- ------ -------- ---------- ---------- ---------- ----------
----------
Parse 1 0.00 0.00 0 0 0

Execute 2 14.51 20.48 6647 61385 207160
50877
Fetch 0 0.00 0.00 0 0 0

------- ------ -------- ---------- ---------- ---------- ----------
----------
total 3 14.51 20.48 6647 61385 207160
50877

Misses in library cache during parse: 0
Optimizer mode: ALL_ROWS
Parsing user id: 145 (recursive depth: 1)

Elapsed times include waiting on following events:
Event waited on Times Max. Wait Total
Waited
---------------------------------------- Waited ----------
------------
enq: FB - contention 395 0.01
0.35
gc current grant 2-way 4187 0.00
1.02
db file sequential read 6639 0.02
3.53
enq: HW - contention 1331 0.01
0.94
enq: TT - contention 1 0.00
0.00
row cache lock 780 0.00
0.18
latch: ges resource hash list 7 0.00
0.00
KJC: Wait for msg sends to complete 4 0.00
0.00
latch free 1 0.00
0.00
****************************************************************************
****

Sample of Trace Output
----------------

WAIT #12: nam='db file sequential read' ela= 200 file#=9 block#=12234401
blocks=1 obj#=192843 tim=1286157671284413
WAIT #12: nam='gc current grant 2-way' ela= 2199 p1=9 p2=12234402
p3=33554433 obj#=192843 tim=1286157671288826
WAIT #12: nam='db file sequential read' ela= 244 file#=9 block#=12234402
blocks=1 obj#=192843 tim=1286157671289192
WAIT #12: nam='gc current grant 2-way' ela= 261 p1=9 p2=12234403 p3=33554433
obj#=192843 tim=1286157671289918
WAIT #12: nam='db file sequential read' ela= 305 file#=9 block#=12234403
blocks=1 obj#=192843 tim=1286157671290276
WAIT #12: nam='gc current grant 2-way' ela= 224 p1=9 p2=12234404 p3=33554433
obj#=192843 tim=1286157671291017
WAIT #12: nam='db file sequential read' ela= 417 file#=9 block#=12234404
blocks=1 obj#=192843 tim=1286157671291503
WAIT #12: nam='gc current grant 2-way' ela= 191 p1=9 p2=12234405 p3=33554433
obj#=192843 tim=1286157671291880
WAIT #12: nam='db file sequential read' ela= 234 file#=9 block#=12234405
blocks=1 obj#=192843 tim=1286157671292203
WAIT #12: nam='gc current grant 2-way' ela= 194 p1=9 p2=12234406 p3=33554433
obj#=192843 tim=1286157671292646
WAIT #12: nam='db file sequential read' ela= 1080 file#=9 block#=12234406
blocks=1 obj#=192843 tim=1286157671293777
WAIT #12: nam='gc current grant 2-way' ela= 168 p1=9 p2=12234407 p3=33554433
obj#=192843 tim=1286157671294260
WAIT #12: nam='db file sequential read' ela= 264 file#=9 block#=12234407
blocks=1 obj#=192843 tim=1286157671294583
WAIT #12: nam='gc current grant 2-way' ela= 198 p1=9 p2=12234408 p3=33554433
obj#=192843 tim=1286157671294989
WAIT #12: nam='db file sequential read' ela= 1082 file#=9 block#=12234408
blocks=1 obj#=192843 tim=1286157671296201
WAIT #12: nam='enq: FB - contention' ela= 760 name|mode=1178730502
tablespace #=9 dba=12235244 obj#=192843 tim=1286157671300116
WAIT #12: nam='gc current grant 2-way' ela= 420 p1=9 p2=12235289 p3=33554433
obj#=192783 tim=1286157671300857
WAIT #12: nam='db file sequential read' ela= 8455 file#=9 block#=12235289
blocks=1 obj#=192783 tim=1286157671309374
WAIT #12: nam='gc current grant 2-way' ela= 321 p1=9 p2=12235290 p3=33554433
obj#=192783 tim=1286157671310115
WAIT #12: nam='db file sequential read' ela= 3103 file#=9 block#=12235290
blocks=1 obj#=192783 tim=1286157671313341


Since this process is the only process doing any inserts into this table and
there are no indexes on the table, I'm puzzled as to why there are "db file
sequential read" and "enq:HW - contention". Not really even sure why it
needs the "gc current grant 2-way".

I looked at some of the objects being read, and I believe they are all the
subpartitions of the table.


Thanks in advance!

Wayne Adams
Senior Oracle Consultant

Search Discussions

  • Saibabu Devabhaktuni at Sep 26, 2011 at 9:44 pm
    Do you have flashback turned on and did you drop or truncate any objects in that tablespace? It is possible to see "db file sequential read" waitevent during insert into table data segment.
    Thanks,
    Sai
    http://sai-oracle.blogspot.com
  • Gaja Krishna Vaidyanatha at Sep 26, 2011 at 11:40 pm
    Hi Wayne,
    A few clarifications :

    1) The occurrence of db file sequential read does NOT always imply the existence or use of an index. Although that event does show up when an index is present, it can occur even when there are no indexes in the picture. It simply implies that the server process did a single-block I/O call and encountered a wait. This can also occur even on a full table scan or index fast full scan, if the number blocks remaining to be read (before an extent boundary) is less than I/O chunksize (db_file_multiblock_read_count). I have observed on many occasions where FTS encounters the db file sequential read wait for this very reason.

    2) The table STAGE_TRANS_WAYNE is setup as a composite range-hash partitioned table. Thus, I am not surprised to see the occurrence of db file sequential read especially for the sub-partitions which are hashed. There could be other reasons with varying amounts of freespace in the blocks, the hashing that is being done on the sub-partitions and available blocks on the freelist that may cause this event to occur too.

    3) gc current grant 2-way is surfacing as part of the messaging with the "Table Master Node". It is possible that the Node you are currently connected where the INSERT is being run (and the blocks that are being modified), is NOT the Master Node for those modified blocks of STAGE_TRANS_WAYNE. Thus, it will have to communicate with the Master Node which covers the blocks in question, before writing to those blocks.

    4) enq: HW contention usually happens when concurrent/parallel INSERT operations occur. You mention yours being a single-threaded operation. Do you have any undesired parallelism happening unbeknownst to you? For example, table-level PARALLELISM set on table creation etc. Given that it is 0.01 seconds of the total elapsed time, I am not sure I'd spend too much time on it, unless your quest is purely academic :)

    Finally, I am just curious. It seems like we are focused on trying to account for 5.97 seconds of waits, out of the total elapsed time of 20.48 seconds. I'd ask the bigger question of why do we have 14.51 seconds worth of CPU time for an INSERT. From past observations, I have seen the use of INSERT statements with scores of bind variables causing all sorts of CPU spikes on systems. The workaround (if possible) is to populate, manipulate and process using a Global Temporary Table (if relevant and possible). Does magic to the system in CPU reduction :)


    Cheers,

    Gaja


    Gaja Krishna Vaidyanatha,
    CEO & Founder, DBPerfMan LLC
    http://www.dbperfman.com
    Phone - 001-650-743-6060
    http://www.linkedin.com/in/gajakrishnavaidyanathaCo-author:Oracle Insights:Tales of the Oak Table - http://www.apress.com/book/bookDisplay.html?bID14
    Co-author:Oracle Performance Tuning 101 - http://www.amazon.com/gp/reader/0072131454/ref=sib_dp_pt/102-6130796-4625766


    ________________________________
    From: Wayne Adams <work@wayneadams.com>
    To: oracle-l@freelists.org
    Sent: Monday, September 26, 2011 12:57 PM
    Subject: db file sequential read waits on INSERT into non-indexed partitioned table

    Trying to understand what is affecting the performance of some INSERTs that
    we have going on.

    Database is a 3 node 10.2.0.3 RAC database.

    Table is a range-hash partitioned table (date range, 128 partition numeric
    hash), with no indexes or LOBs.  Tablespace is a locally SYSTEM managed ASSM
    bigfile tablespace.

    This particular INSERT is a single threaded FORALL  INSERT with an arraysize
    of 50000.

    Tkprof output
    -----------------

    INSERT INTO STAGE_TRANS_WAYNE
    VALUES
    (:B1 ,:B2 ,:B3 ,:B4 ,:B5 ,:B6 ,:B7 ,:B8 ,:B9 ,:B10 ,:B11 ,:B12 ,:B13 ,:B14
    ,
    :B15 ,:B16 ,:B17 ,:B18 ,:B19 ,:B20 ,:B21 ,:B22 ,:B23 ,:B24 ,:B25 ,:B26 ,
    :B27 ,:B28 ,:B29 ,:B30 ,:B31 ,:B32 ,:B33 ,:B34 ,:B35 ,:B36 ,:B37 ,:B38 ,
    :B39 ,:B40 ,:B41 ,:B42 ,:B43 ,:B44 ,:B45 ,:B46 ,:B47 ,:B48 ,:B49 ,:B50 ,
    :B51 ,:B52 ,:B53 ,:B54 ,:B55 ,:B56 ,:B57 ,:B58 ,:B59 ,:B60 ,:B61 ,:B62 ,
    :B63 ,:B64 ,:B65 ,:B66 ,:B67 ,:B68 ,:B69 ,:B70 ,:B71 ,:B72 ,:B73 ,:B74 ,
    :B75 ,:B76 ,:B77 ,:B78 ,:B79 ,:B80 ,:B81 ,:B82 ,:B83 ,:B84 ,:B85 ,:B86 ,
    :B87 ,:B88 ,:B89 ,:B90 ,:B91 ,:B92 ,:B93 ,:B94 ,:B95 ,:B96 ,:B97 ,:B98 ,
    :B99 ,:B100 ,:B101 ,:B102 ,:B103 ,:B104 ,:B105 ,:B106 ,:B107 ,:B108 ,:B109
    ,
    :B110 ,:B111 ,:B112 ,:B113 ,:B114 ,:B115 ,:B116 ,:B117 ,:B118 ,:B119
    ,:B120
    ,:B121 ,:B122 ,:B123 ,:B124 ,:B125 ,:B126 ,:B127 ,:B128 ,:B129 ,:B130 ,
    :B131 ,:B132 ,:B133 ,:B134 ,:B135 ,:B136 ,:B137 ,:B138 ,:B139 ,:B140
    ,:B141
    ,:B142 ,:B143 ,:B144 ,:B145 ,:B146 ,:B147 ,:B148 ,:B149 ,:B150 ,:B151 ,
    :B152 ,:B153 ,:B154 ,:B155 ,:B156 ,:B157 ,:B158 ,:B159 ,:B160 ,:B161
    ,:B162
    ,:B163 ,:B164 ,:B165 ,:B166 ,:B167 ,:B168 ,:B169 ,:B170 ,:B171 ,:B172 ,
    :B173 ,:B174 ,:B175 ,:B176 ,:B177 ,:B178 ,:B179 ,:B180 ,:B181 ,:B182
    ,:B183
    ,:B184 ,:B185 ,:B186 ,:B187 ,:B188 ,:B189 ,:B190 ,:B191 ,:B192 ,:B193 ,
    :B194 ,:B195 ,:B196 ,:B197 ,:B198 ,:B199 ,:B200 ,:B201 ,:B202 ,:B203
    ,:B204
    ,:B205 ,:B206 ,:B207 ,:B208 ,:B209 ,:B210 ,:B211 ,:B212 ,:B213 ,:B214 ,
    :B215 ,:B216 ,:B217 ,:B218 ,:B219 ,:B220 ,:B221 ,:B222 ,:B223 ,:B224
    ,:B225
    ,:B226 ,:B227 ,:B228 ,:B229 ,:B230 ,:B231 ,:B232 ,:B233 ,:B234 ,:B235 )


    call    count      cpu    elapsed      disk      query    current
    rows
    ------- ------  -------- ---------- ---------- ---------- ----------
    ----------
    Parse        1      0.00      0.00          0          0          0

    Execute      2    14.51      20.48      6647      61385    207160
    50877
    Fetch        0      0.00      0.00          0          0          0

    ------- ------  -------- ---------- ---------- ---------- ----------
    ----------
    total        3    14.51      20.48      6647      61385    207160
    50877

    Misses in library cache during parse: 0
    Optimizer mode: ALL_ROWS
    Parsing user id: 145    (recursive depth: 1)

    Elapsed times include waiting on following events:
    Event waited on                            Times  Max. Wait  Total
    Waited
    ----------------------------------------  Waited  ----------
    ------------
    enq: FB - contention                          395        0.01
    0.35
    gc current grant 2-way                      4187        0.00
    1.02
    db file sequential read                      6639        0.02
    3.53
    enq: HW - contention                        1331        0.01
    0.94
    enq: TT - contention                            1        0.00
    0.00
    row cache lock                                780        0.00
    0.18
    latch: ges resource hash list                  7        0.00
    0.00
    KJC: Wait for msg sends to complete            4        0.00
    0.00
    latch free                                      1        0.00
    0.00
    ****************************************************************************
    ****

    Sample of Trace Output
    ----------------

    WAIT #12: nam='db file sequential read' ela= 200 file#=9 block#234401
    blocks=1 obj#2843 tim86157671284413
    WAIT #12: nam='gc current grant 2-way' ela= 2199 p1=9 p2234402
    p33554433 obj#2843 tim86157671288826
    WAIT #12: nam='db file sequential read' ela= 244 file#=9 block#234402
    blocks=1 obj#2843 tim86157671289192
    WAIT #12: nam='gc current grant 2-way' ela= 261 p1=9 p2234403 p33554433
    obj#2843 tim86157671289918
    WAIT #12: nam='db file sequential read' ela= 305 file#=9 block#234403
    blocks=1 obj#2843 tim86157671290276
    WAIT #12: nam='gc current grant 2-way' ela= 224 p1=9 p2234404 p33554433
    obj#2843 tim86157671291017
    WAIT #12: nam='db file sequential read' ela= 417 file#=9 block#234404
    blocks=1 obj#2843 tim86157671291503
    WAIT #12: nam='gc current grant 2-way' ela= 191 p1=9 p2234405 p33554433
    obj#2843 tim86157671291880
    WAIT #12: nam='db file sequential read' ela= 234 file#=9 block#234405
    blocks=1 obj#2843 tim86157671292203
    WAIT #12: nam='gc current grant 2-way' ela= 194 p1=9 p2234406 p33554433
    obj#2843 tim86157671292646
    WAIT #12: nam='db file sequential read' ela= 1080 file#=9 block#234406
    blocks=1 obj#2843 tim86157671293777
    WAIT #12: nam='gc current grant 2-way' ela= 168 p1=9 p2234407 p33554433
    obj#2843 tim86157671294260
    WAIT #12: nam='db file sequential read' ela= 264 file#=9 block#234407
    blocks=1 obj#2843 tim86157671294583
    WAIT #12: nam='gc current grant 2-way' ela= 198 p1=9 p2234408 p33554433
    obj#2843 tim86157671294989
    WAIT #12: nam='db file sequential read' ela= 1082 file#=9 block#234408
    blocks=1 obj#2843 tim86157671296201
    WAIT #12: nam='enq: FB - contention' ela= 760 name|mode78730502
    tablespace #=9 dba235244 obj#2843 tim86157671300116
    WAIT #12: nam='gc current grant 2-way' ela= 420 p1=9 p2235289 p33554433
    obj#2783 tim86157671300857
    WAIT #12: nam='db file sequential read' ela= 8455 file#=9 block#235289
    blocks=1 obj#2783 tim86157671309374
    WAIT #12: nam='gc current grant 2-way' ela= 321 p1=9 p2235290 p33554433
    obj#2783 tim86157671310115
    WAIT #12: nam='db file sequential read' ela= 3103 file#=9 block#235290
    blocks=1 obj#2783 tim86157671313341


    Since this process is the only process doing any inserts into this table and
    there are no indexes on the table, I'm puzzled as to why there are "db file
    sequential read" and "enq:HW - contention".  Not really even sure why it
    needs the "gc current grant 2-way".

    I looked at some of the objects being read, and I believe they are all the
    subpartitions of the table.


    Thanks in advance!

    Wayne Adams
    Senior Oracle Consultant
  • Greg Rahn at Sep 27, 2011 at 3:17 am
    To elaborate on these points:

    I'd wager the reason these wait events are showing up is that the next
    extent size is relatively small for the hash partition segments.
    Perhaps this is the first insert into an empty range partition so the
    initial extent size is just 64K, the default for ASSM. If you are
    putting 50000 rows in per array insert, these are most likely spanning
    all 128 hash subpartition segments so this is where you are getting
    your concurrency - all 128 segments are growing, allocating new
    extents at the same time. If you increase your initial extent size
    (say to like 8M, which is what 11.2.0.2 defaults to for partitioned
    segments -- the size of _partition_large_extents), these waits will
    likely disappear.


    On Mon, Sep 26, 2011 at 4:16 PM, Gaja Krishna Vaidyanatha
    wrote:
    Hi Wayne,
    A few clarifications :

    1) The occurrence of db file sequential read does NOT always imply the existence or use of an index. Although that event does show up when an index is present, it can occur even when there are no indexes in the picture. It simply implies that the server process did a single-block I/O call and encountered a wait. This can also occur even on a full table scan or index fast full scan, if the number blocks remaining to be read (before an extent boundary) is less than I/O chunksize (db_file_multiblock_read_count). I have observed on many occasions where FTS encounters the db file sequential read wait for this very reason.

    2) The table STAGE_TRANS_WAYNE is setup as a composite range-hash partitioned table. Thus, I am not surprised to see the occurrence of db file sequential read especially for the sub-partitions which are hashed. There could be other reasons with varying amounts of freespace in the blocks, the hashing that is being done on the sub-partitions and available blocks on the freelist that may cause this event to occur too.

    3) gc current grant 2-way is surfacing as part of the messaging with the "Table Master Node". It is possible that the Node you are currently connected where the INSERT is being run (and the blocks that are being modified), is NOT the Master Node for those modified blocks of STAGE_TRANS_WAYNE. Thus, it will have to communicate with the Master Node which covers the blocks in question, before writing to those blocks.

    4) enq: HW contention usually happens when concurrent/parallel INSERT operations occur. You mention yours being a single-threaded operation. Do you have any undesired parallelism happening unbeknownst to you? For example, table-level PARALLELISM set on table creation etc. Given that it is 0.01 seconds of the total elapsed time, I am not sure I'd spend too much time on it, unless your quest is purely academic :)

    Finally, I am just curious. It seems like we are focused on trying to account for 5.97 seconds of waits, out of the total elapsed time of 20.48 seconds. I'd ask the bigger question of why do we have 14.51 seconds worth of CPU time for an INSERT. From past observations, I have seen the use of INSERT statements with scores of bind variables causing all sorts of CPU spikes on systems. The workaround (if possible) is to populate, manipulate and process using a Global Temporary Table (if relevant and possible). Does magic to the system in CPU reduction :)
    --
    Regards,
    Greg Rahn
    http://structureddata.org
    --
    http://www.freelists.org/webpage/oracle-l
  • Wayne Adams at Sep 28, 2011 at 12:11 am
    Thanks for the feedback guys!

    To elaborate, this particular scenario and discussion is partly out of
    curiosity (myself trying to understand the "db file sequential read" on
    INSERT with no indexes), and partly as a pre-cursor to putting forth a more
    concrete INSERT performance problem example very soon.

    To provide some additional info.

    1) All of these inserts were into the same RANGE partition (we partition by
    month), and the test/trace was done after having just inserted 450k rows.
    The table has already been dropped, so I can't tell the extent size at the
    end, but it probably wasn't 64k.
    2) The table never has any updates or deletes, only inserts.
    3) The table does have the DEGREE set to 4, but we did not issue the "alter
    session force parallel dml" clause, so I didn't think it would do any
    concurrent inserts. Am I wrong in that?

    I am also puzzled by the high CPU time for the insert. In this example,
    it's 75% of the total elapsed time. I have never heard of a high number of
    bind variables in an INSERT causing high CPU. The data being passed to the
    insert has just been finished being massaged by a bunch of PL/SQL code, so
    I'm not sure how would using a GTT in this example help. You would have to
    use the binds to insert into the GTT too wouldn't you?

    Wayne
    To elaborate on these points:

    I'd wager the reason these wait events are showing up is that the next
    extent size is relatively small for the hash partition segments.
    Perhaps this is the first insert into an empty range partition so the
    initial extent size is just 64K, the default for ASSM. If you are
    putting 50000 rows in per array insert, these are most likely spanning
    all 128 hash subpartition segments so this is where you are getting
    your concurrency - all 128 segments are growing, allocating new
    extents at the same time. If you increase your initial extent size
    (say to like 8M, which is what 11.2.0.2 defaults to for partitioned
    segments -- the size of _partition_large_extents), these waits will
    likely disappear.


    On Mon, Sep 26, 2011 at 4:16 PM, Gaja Krishna Vaidyanatha
    wrote:
    Hi Wayne,
    A few clarifications :

    1) The occurrence of db file sequential read does NOT always imply the
    existence or use of an index. Although that event does show up when an
    index
    is present, it can occur even when there are no indexes in the picture.
    It
    simply implies that the server process did a single-block I/O call and
    encountered a wait. This can also occur even on a full table scan or
    index
    fast full scan, if the number blocks remaining to be read (before an
    extent
    boundary) is less than I/O chunksize (db_file_multiblock_read_count). I
    have
    observed on many occasions where FTS encounters the db file sequential
    read
    wait for this very reason.

    2) The table STAGE_TRANS_WAYNE is setup as a composite range-hash
    partitioned
    table. Thus, I am not surprised to see the occurrence of db file
    sequential
    read especially for the sub-partitions which are hashed. There could be
    other
    reasons with varying amounts of freespace in the blocks, the hashing that
    is
    being done on the sub-partitions and available blocks on the freelist
    that
    may cause this event to occur too.

    3) gc current grant 2-way is surfacing as part of the messaging with the
    "Table Master Node". It is possible that the Node you are currently
    connected
    where the INSERT is being run (and the blocks that are being modified),
    is
    NOT the Master Node for those modified blocks of STAGE_TRANS_WAYNE. Thus,
    it
    will have to communicate with the Master Node which covers the blocks in
    question, before writing to those blocks.

    4) enq: HW contention usually happens when concurrent/parallel INSERT
    operations occur. You mention yours being a single-threaded operation. Do
    you
    have any undesired parallelism happening unbeknownst to you? For example,
    table-level PARALLELISM set on table creation etc. Given that it is 0.01
    seconds of the total elapsed time, I am not sure I'd spend too much time
    on
    it, unless your quest is purely academic :)

    Finally, I am just curious. It seems like we are focused on trying to
    account
    for 5.97 seconds of waits, out of the total elapsed time of 20.48
    seconds.
    I'd ask the bigger question of why do we have 14.51 seconds worth of CPU
    time
    for an INSERT. From past observations, I have seen the use of INSERT
    statements with scores of bind variables causing all sorts of CPU spikes
    on
    systems. The workaround (if possible) is to populate, manipulate and
    process
    using a Global Temporary Table (if relevant and possible). Does magic to
    the
    system in CPU reduction :)
    --
    Regards,
    Greg Rahn
    http://structureddata.org
    --
    http://www.freelists.org/webpage/oracle-l
    -----Original Message-----
    From: Wayne Adams
    Sent: Monday, September 26, 2011 12:57 PM
    To: 'oracle-l@freelists.org'
    Subject: db file sequential read waits on INSERT into non-indexed
    partitioned table

    Trying to understand what is affecting the performance of some INSERTs that
    we have going on.

    Database is a 3 node 10.2.0.3 RAC database.

    Table is a range-hash partitioned table (date range, 128 partition numeric
    hash), with no indexes or LOBs. Tablespace is a locally SYSTEM managed ASSM
    bigfile tablespace.

    This particular INSERT is a single threaded FORALL INSERT with an arraysize
    of 50000.

    Tkprof output
    -----------------

    INSERT INTO STAGE_TRANS_WAYNE
    VALUES
    (:B1 ,:B2 ,:B3 ,:B4 ,:B5 ,:B6 ,:B7 ,:B8 ,:B9 ,:B10 ,:B11 ,:B12 ,:B13 ,:B14
    ,
    :B15 ,:B16 ,:B17 ,:B18 ,:B19 ,:B20 ,:B21 ,:B22 ,:B23 ,:B24 ,:B25 ,:B26 ,
    :B27 ,:B28 ,:B29 ,:B30 ,:B31 ,:B32 ,:B33 ,:B34 ,:B35 ,:B36 ,:B37 ,:B38 ,
    :B39 ,:B40 ,:B41 ,:B42 ,:B43 ,:B44 ,:B45 ,:B46 ,:B47 ,:B48 ,:B49 ,:B50 ,
    :B51 ,:B52 ,:B53 ,:B54 ,:B55 ,:B56 ,:B57 ,:B58 ,:B59 ,:B60 ,:B61 ,:B62 ,
    :B63 ,:B64 ,:B65 ,:B66 ,:B67 ,:B68 ,:B69 ,:B70 ,:B71 ,:B72 ,:B73 ,:B74 ,
    :B75 ,:B76 ,:B77 ,:B78 ,:B79 ,:B80 ,:B81 ,:B82 ,:B83 ,:B84 ,:B85 ,:B86 ,
    :B87 ,:B88 ,:B89 ,:B90 ,:B91 ,:B92 ,:B93 ,:B94 ,:B95 ,:B96 ,:B97 ,:B98 ,
    :B99 ,:B100 ,:B101 ,:B102 ,:B103 ,:B104 ,:B105 ,:B106 ,:B107 ,:B108 ,:B109
    ,
    :B110 ,:B111 ,:B112 ,:B113 ,:B114 ,:B115 ,:B116 ,:B117 ,:B118 ,:B119
    ,:B120
    ,:B121 ,:B122 ,:B123 ,:B124 ,:B125 ,:B126 ,:B127 ,:B128 ,:B129 ,:B130 ,
    :B131 ,:B132 ,:B133 ,:B134 ,:B135 ,:B136 ,:B137 ,:B138 ,:B139 ,:B140
    ,:B141
    ,:B142 ,:B143 ,:B144 ,:B145 ,:B146 ,:B147 ,:B148 ,:B149 ,:B150 ,:B151 ,
    :B152 ,:B153 ,:B154 ,:B155 ,:B156 ,:B157 ,:B158 ,:B159 ,:B160 ,:B161
    ,:B162
    ,:B163 ,:B164 ,:B165 ,:B166 ,:B167 ,:B168 ,:B169 ,:B170 ,:B171 ,:B172 ,
    :B173 ,:B174 ,:B175 ,:B176 ,:B177 ,:B178 ,:B179 ,:B180 ,:B181 ,:B182
    ,:B183
    ,:B184 ,:B185 ,:B186 ,:B187 ,:B188 ,:B189 ,:B190 ,:B191 ,:B192 ,:B193 ,
    :B194 ,:B195 ,:B196 ,:B197 ,:B198 ,:B199 ,:B200 ,:B201 ,:B202 ,:B203
    ,:B204
    ,:B205 ,:B206 ,:B207 ,:B208 ,:B209 ,:B210 ,:B211 ,:B212 ,:B213 ,:B214 ,
    :B215 ,:B216 ,:B217 ,:B218 ,:B219 ,:B220 ,:B221 ,:B222 ,:B223 ,:B224
    ,:B225
    ,:B226 ,:B227 ,:B228 ,:B229 ,:B230 ,:B231 ,:B232 ,:B233 ,:B234 ,:B235 )


    call count cpu elapsed disk query current
    rows
    ------- ------ -------- ---------- ---------- ---------- ----------
    ----------
    Parse 1 0.00 0.00 0 0 0

    Execute 2 14.51 20.48 6647 61385 207160
    50877
    Fetch 0 0.00 0.00 0 0 0

    ------- ------ -------- ---------- ---------- ---------- ----------
    ----------
    total 3 14.51 20.48 6647 61385 207160
    50877

    Misses in library cache during parse: 0
    Optimizer mode: ALL_ROWS
    Parsing user id: 145 (recursive depth: 1)

    Elapsed times include waiting on following events:
    Event waited on Times Max. Wait Total
    Waited
    ---------------------------------------- Waited ----------
    ------------
    enq: FB - contention 395 0.01
    0.35
    gc current grant 2-way 4187 0.00
    1.02
    db file sequential read 6639 0.02
    3.53
    enq: HW - contention 1331 0.01
    0.94
    enq: TT - contention 1 0.00
    0.00
    row cache lock 780 0.00
    0.18
    latch: ges resource hash list 7 0.00
    0.00
    KJC: Wait for msg sends to complete 4 0.00
    0.00
    latch free 1 0.00
    0.00
    ****************************************************************************
    ****

    Sample of Trace Output
    ----------------

    WAIT #12: nam='db file sequential read' ela= 200 file#=9 block#=12234401
    blocks=1 obj#=192843 tim=1286157671284413 WAIT #12: nam='gc current grant
    2-way' ela= 2199 p1=9 p2=12234402 p3=33554433 obj#=192843
    tim=1286157671288826 WAIT #12: nam='db file sequential read' ela= 244
    file#=9 block#=12234402 blocks=1 obj#=192843 tim=1286157671289192 WAIT #12:
    nam='gc current grant 2-way' ela= 261 p1=9 p2=12234403 p3=33554433
    obj#=192843 tim=1286157671289918 WAIT #12: nam='db file sequential read'
    ela= 305 file#=9 block#=12234403 blocks=1 obj#=192843 tim=1286157671290276
    WAIT #12: nam='gc current grant 2-way' ela= 224 p1=9 p2=12234404 p3=33554433
    obj#=192843 tim=1286157671291017 WAIT #12: nam='db file sequential read'
    ela= 417 file#=9 block#=12234404 blocks=1 obj#=192843 tim=1286157671291503
    WAIT #12: nam='gc current grant 2-way' ela= 191 p1=9 p2=12234405 p3=33554433
    obj#=192843 tim=1286157671291880 WAIT #12: nam='db file sequential read'
    ela= 234 file#=9 block#=12234405 blocks=1 obj#=192843 tim=1286157671292203
    WAIT #12: nam='gc current grant 2-way' ela= 194 p1=9 p2=12234406 p3=33554433
    obj#=192843 tim=1286157671292646 WAIT #12: nam='db file sequential read'
    ela= 1080 file#=9 block#=12234406 blocks=1 obj#=192843 tim=1286157671293777
    WAIT #12: nam='gc current grant 2-way' ela= 168 p1=9 p2=12234407 p3=33554433
    obj#=192843 tim=1286157671294260 WAIT #12: nam='db file sequential read'
    ela= 264 file#=9 block#=12234407 blocks=1 obj#=192843 tim=1286157671294583
    WAIT #12: nam='gc current grant 2-way' ela= 198 p1=9 p2=12234408 p3=33554433
    obj#=192843 tim=1286157671294989 WAIT #12: nam='db file sequential read'
    ela= 1082 file#=9 block#=12234408 blocks=1 obj#=192843 tim=1286157671296201
    WAIT #12: nam='enq: FB - contention' ela= 760 name|mode=1178730502
    tablespace #=9 dba=12235244 obj#=192843 tim=1286157671300116 WAIT #12:
    nam='gc current grant 2-way' ela= 420 p1=9 p2=12235289 p3=33554433
    obj#=192783 tim=1286157671300857 WAIT #12: nam='db file sequential read'
    ela= 8455 file#=9 block#=12235289 blocks=1 obj#=192783 tim=1286157671309374
    WAIT #12: nam='gc current grant 2-way' ela= 321 p1=9 p2=12235290 p3=33554433
    obj#=192783 tim=1286157671310115 WAIT #12: nam='db file sequential read'
    ela= 3103 file#=9 block#=12235290 blocks=1 obj#=192783 tim=1286157671313341


    Since this process is the only process doing any inserts into this table and
    there are no indexes on the table, I'm puzzled as to why there are "db file
    sequential read" and "enq:HW - contention". Not really even sure why it
    needs the "gc current grant 2-way".

    I looked at some of the objects being read, and I believe they are all the
    subpartitions of the table.


    Thanks in advance!

    Wayne Adams
    Senior Oracle Consultant


    --
    http://www.freelists.org/webpage/oracle-l
  • Greg Rahn at Sep 28, 2011 at 3:18 am
    Understand that "db file sequential read" just means its not a
    multi-block read - it's a single block read. Most any time that a
    single block needs to be retrieved, this event shows up. There are
    numerous reasons for this: file header block access, space management
    (bitmap blocks), etc, etc.

    As I mentioned, it would appear that this event showed up because of
    extent allocation. Simply put, when doing bulk inserts, the larger
    the extent, the less frequent the need to get a new extent.
    Especially important when doing bulk inserts into numerous segments
    (e.g. 128 hash subpartitions).

    The rest of the stuff you mention doesn't really matter here that I see.
    On Tue, Sep 27, 2011 at 3:57 PM, Wayne Adams wrote:
    Thanks for the feedback guys!

    To elaborate, this particular scenario and discussion is partly out of
    curiosity (myself trying to understand the "db file sequential read" on
    INSERT with no indexes), and partly as a pre-cursor to putting forth a more
    concrete INSERT performance problem example very soon.

    To provide some additional info.

    1) All of these inserts were into the same RANGE partition (we partition by
    month), and the test/trace was done after having just inserted 450k rows.
    The table has already been dropped, so I can't tell the extent size at the
    end, but it probably wasn't 64k.
    2) The table never has any updates or deletes, only inserts.
    3) The table does have the DEGREE set to 4, but we did not issue the "alter
    session force parallel dml" clause, so I didn't think it would do any
    concurrent inserts.  Am I wrong in that?

    I am also puzzled by the high CPU time for the insert.  In this example,
    it's 75% of the total elapsed time.  I have never heard of a high number of
    bind variables in an INSERT causing high CPU.  The data being passed to the
    insert has just been finished being massaged by a bunch of PL/SQL code, so
    I'm not sure how would using a GTT in this example help.  You would have to
    use the binds to insert into the GTT too wouldn't you?

    --
    Regards,
    Greg Rahn
    http://structureddata.org
    --
    http://www.freelists.org/webpage/oracle-l
  • Wayne Adams at Sep 29, 2011 at 1:34 am
    Thanks for the help guys! After reading the explanations here, I decided to
    try a test. I created 2 identical tables (again with no indexes). One with
    8 SUBPARTITONS, one with NO SUBPARTITIONS (range instead of range-hash) and
    did my INSERTs. The difference was pretty impressive (and to me personally,
    surprising).

    INSERT into range-hash partitioned table (128 SUBPARTITIONS), no indexes

    call count cpu elapsed disk query current
    rows
    ------- ------ -------- ---------- ---------- ---------- ----------
    ----------
    Parse 1 0.00 0.00 0 0 0

    Execute 6 8.96 14.00 3738 53964 180790
    50877
    Fetch 0 0.00 0.00 0 0 0

    ------- ------ -------- ---------- ---------- ---------- ----------
    ----------
    total 7 8.96 14.00 3738 53964 180790
    50877

    Elapsed times include waiting on following events:
    Event waited on Times Max. Wait Total
    Waited
    ---------------------------------------- Waited ----------
    ------------
    db file sequential read 3726 0.05
    4.77
    gc current grant 2-way 1990 0.02
    0.55
    gc cr grant 2-way 70 0.00
    0.01
    gc current multi block request 288 0.01
    0.19
    enq: FB - contention 230 0.00
    0.09
    enq: TT - contention 56 0.00
    0.02
    row cache lock 81 0.00
    0.01
    ****************************************************************************
    ****

    INSERT into range-hash partitioned table (8 SUBPARTITIONS), no indexes

    call count cpu elapsed disk query current
    rows
    ------- ------ -------- ---------- ---------- ---------- ----------
    ----------
    Parse 1 0.00 0.00 0 0 0

    Execute 6 7.73 8.82 1110 47728 162319
    50877
    Fetch 0 0.00 0.00 0 0 0

    ------- ------ -------- ---------- ---------- ---------- ----------
    ----------
    total 7 7.73 8.83 1110 47728 162319
    50877


    Elapsed times include waiting on following events:
    Event waited on Times Max. Wait Total
    Waited
    ---------------------------------------- Waited ----------
    ------------
    gc current grant 2-way 471 0.00
    0.12
    db file sequential read 1106 0.02
    0.93
    gc cr grant 2-way 6 0.00
    0.00
    gc current multi block request 334 0.00
    0.18
    enq: FB - contention 290 0.00
    0.08
    gc cr block 2-way 1 0.00
    0.00
    enq: HW - contention 3 0.00
    0.00
    row cache lock 2 0.00
    0.00
    ****************************************************************************
    ****

    INSERT into range partitioned table (no SUBPARTITIONS), no indexes

    call count cpu elapsed disk query current
    rows
    ------- ------ -------- ---------- ---------- ---------- ----------
    ----------
    Parse 1 0.00 0.00 0 0 0

    Execute 6 4.62 5.02 276 10485 48295
    50877
    Fetch 0 0.00 0.00 0 0 0

    ------- ------ -------- ---------- ---------- ---------- ----------
    ----------
    total 7 4.62 5.02 276 10485 48295
    50877

    Elapsed times include waiting on following events:
    Event waited on Times Max. Wait Total
    Waited
    ---------------------------------------- Waited ----------
    ------------
    db file sequential read 275 0.00
    0.15
    enq: FB - contention 194 0.01
    0.17
    enq: HW - contention 3 0.00
    0.00
    row cache lock 2 0.00
    0.00
    gc current block 2-way 1 0.00
    0.00
    ****************************************************************************
    ****

    Intuitively, you would expect some overhead for having the subpartitions,
    but I did not expect quite that much difference (1/2 the CPU, and 1/3 the
    elapsed time with no SUBPARTITIONS vs the 128).

    We may have to revisit whether we need the SUBPARTITIONS at all (we don't
    reference the SUBPARTITION key in our queries much).

    Wayne

    -----Original Message-----
    From: Greg Rahn
    Sent: Tuesday, September 27, 2011 8:18 PM
    To: work@wayneadams.com
    Cc: oracle-l@freelists.org
    Subject: Re: db file sequential read waits on INSERT into non-indexed
    partitioned table

    Understand that "db file sequential read" just means its not a multi-block
    read - it's a single block read. Most any time that a single block needs to
    be retrieved, this event shows up. There are numerous reasons for this:
    file header block access, space management (bitmap blocks), etc, etc.

    As I mentioned, it would appear that this event showed up because of extent
    allocation. Simply put, when doing bulk inserts, the larger the extent, the
    less frequent the need to get a new extent.
    Especially important when doing bulk inserts into numerous segments (e.g.
    128 hash subpartitions).

    The rest of the stuff you mention doesn't really matter here that I see.
    On Tue, Sep 27, 2011 at 3:57 PM, Wayne Adams wrote:
    Thanks for the feedback guys!

    To elaborate, this particular scenario and discussion is partly out of
    curiosity (myself trying to understand the "db file sequential read"
    on INSERT with no indexes), and partly as a pre-cursor to putting
    forth a more concrete INSERT performance problem example very soon.

    To provide some additional info.

    1) All of these inserts were into the same RANGE partition (we
    partition by month), and the test/trace was done after having just
    inserted 450k rows.
    The table has already been dropped, so I can't tell the extent size at
    the end, but it probably wasn't 64k.
    2) The table never has any updates or deletes, only inserts.
    3) The table does have the DEGREE set to 4, but we did not issue the
    "alter session force parallel dml" clause, so I didn't think it would
    do any concurrent inserts.  Am I wrong in that?

    I am also puzzled by the high CPU time for the insert.  In this
    example, it's 75% of the total elapsed time.  I have never heard of a
    high number of bind variables in an INSERT causing high CPU.  The data
    being passed to the insert has just been finished being massaged by a
    bunch of PL/SQL code, so I'm not sure how would using a GTT in this
    example help.  You would have to use the binds to insert into the GTT too
    wouldn't you?
  • Gaja Krishna Vaidyanatha at Sep 29, 2011 at 5:33 am
    Hi Wayne,
    Just wondering if you perform your tests by creating the table with a large extent size such as 8MB as Greg had originally suggested? If not, it may be worthwhile to do the tests again.  Here is the trend in the numbers I observe:

    Sub-Partitions   CPU(in secs)QUERYCURRENTTOTAL LIO
    1288.9653964180790234,754
    87.7347728162319210,047
    04.6210485   4829558,780


    The "current" numbers in the trace output are rather high when there are sub-partitions (possibly for segment management) and extent size could play a part here. So, it may be worthwhile to take Greg's advice on this and re-test. Also, one can observe in this case, there is a direct correlation between CPU time and LIO (query+current).


    Moral of this story - Performance Management is about LIO Management. When you optimize the LIO, the CPU numbers automatically reflect the optimization. With regards to your question with GTTs, the concept is still the same - LIO Management. In a prior project, the offending SQL with a 1000 bind variables was a SELECT and it was easy to populate a GTT with the bind variable values and then hang a sub-query off the original SELECT to read the populated GTT. It dropped LIO down to nothing and with it the CPU numbers.

    Given that the GTT lives in the PGA until it overflows into the TEMP tablespace, LIOs (or the resemblance of it) that occur in the PGA are usually super-fast and low on CPU, as there is no buffer cache management in the picture. If this table's function in the application is that of a "staging table" and is used for some sort of pre-loading operation, I'd give the GTT (with ON COMMIT PRESERVE ROWS) a shot, just for the heck of it. To ensure that there is no spillage to the TEMP tablespace, do your tests by setting WORKAREA_SIZE_POLICY to MANUAL in the session, and set a reasonable number for SORT_AREA_SIZE and SORT_AREA_RETAINED_SIZE (keep them the SAME value, say 128MB or so) and do your tests. Keep us posted.

    Cheers,

    Gaja


    Gaja Krishna Vaidyanatha,
    CEO & Founder, DBPerfMan LLC
    http://www.dbperfman.com
    Phone - 001-650-743-6060
    http://www.linkedin.com/in/gajakrishnavaidyanathaCo-author:Oracle Insights:Tales of the Oak Table - http://www.apress.com/book/bookDisplay.html?bID14
    Co-author:Oracle Performance Tuning 101 - http://www.amazon.com/gp/reader/0072131454/ref=sib_dp_pt/102-6130796-4625766


    ________________________________
    From: Wayne Adams <work@wayneadams.com>
    To: oracle-l@freelists.org
    Cc: 'Greg Rahn' <greg@structureddata.org>
    Sent: Wednesday, September 28, 2011 6:32 PM
    Subject: RE: db file sequential read waits on INSERT into non-indexed partitioned table

    Thanks for the help guys!  After reading the explanations here, I decided to
    try a test.  I created 2 identical tables (again with no indexes).  One with
    8 SUBPARTITONS, one with NO SUBPARTITIONS (range instead of range-hash) and
    did my INSERTs.  The difference was pretty impressive (and to me personally,
    surprising).

    INSERT into range-hash partitioned table (128 SUBPARTITIONS), no indexes

    call    count      cpu    elapsed      disk      query    current
    rows
    ------- ------  -------- ---------- ---------- ---------- ----------
    ----------
    Parse        1      0.00      0.00          0          0          0

    Execute      6      8.96      14.00      3738      53964    180790
    50877
    Fetch        0      0.00      0.00          0          0          0

    ------- ------  -------- ---------- ---------- ---------- ----------
    ----------
    total        7      8.96      14.00      3738      53964    180790
    50877

    Elapsed times include waiting on following events:
    Event waited on                            Times  Max. Wait  Total
    Waited
    ----------------------------------------  Waited  ----------
    ------------
    db file sequential read                      3726        0.05
    4.77
    gc current grant 2-way                      1990        0.02
    0.55
    gc cr grant 2-way                              70        0.00
    0.01
    gc current multi block request                288        0.01
    0.19
    enq: FB - contention                          230        0.00
    0.09
    enq: TT - contention                          56        0.00
    0.02
    row cache lock                                81        0.00
    0.01
    ****************************************************************************
    ****

    INSERT into range-hash partitioned table (8 SUBPARTITIONS), no indexes

    call    count      cpu    elapsed      disk      query    current
    rows
    ------- ------  -------- ---------- ---------- ---------- ----------
    ----------
    Parse        1      0.00      0.00          0          0          0

    Execute      6      7.73      8.82      1110      47728    162319
    50877
    Fetch        0      0.00      0.00          0          0          0

    ------- ------  -------- ---------- ---------- ---------- ----------
    ----------
    total        7      7.73      8.83      1110      47728    162319
    50877


    Elapsed times include waiting on following events:
    Event waited on                            Times  Max. Wait  Total
    Waited
    ----------------------------------------  Waited  ----------
    ------------
    gc current grant 2-way                        471        0.00
    0.12
    db file sequential read                      1106        0.02
    0.93
    gc cr grant 2-way                              6        0.00
    0.00
    gc current multi block request                334        0.00
    0.18
    enq: FB - contention                          290        0.00
    0.08
    gc cr block 2-way                              1        0.00
    0.00
    enq: HW - contention                            3        0.00
    0.00
    row cache lock                                  2        0.00
    0.00
    ****************************************************************************
    ****

    INSERT into range partitioned table (no SUBPARTITIONS), no indexes

    call    count      cpu    elapsed      disk      query    current
    rows
    ------- ------  -------- ---------- ---------- ---------- ----------
    ----------
    Parse        1      0.00      0.00          0          0          0

    Execute      6      4.62      5.02        276      10485      48295
    50877
    Fetch        0      0.00      0.00          0          0          0

    ------- ------  -------- ---------- ---------- ---------- ----------
    ----------
    total        7      4.62      5.02        276      10485      48295
    50877

    Elapsed times include waiting on following events:
    Event waited on                            Times  Max. Wait  Total
    Waited
    ----------------------------------------  Waited  ----------
    ------------
    db file sequential read                      275        0.00
    0.15
    enq: FB - contention                          194        0.01
    0.17
    enq: HW - contention                            3        0.00
    0.00
    row cache lock                                  2        0.00
    0.00
    gc current block 2-way                          1        0.00
    0.00
    ****************************************************************************
    ****

    Intuitively, you would expect some overhead for having the subpartitions,
    but I did not expect quite that much difference (1/2 the CPU, and 1/3 the
    elapsed time with no SUBPARTITIONS vs the 128).

    We may have to revisit whether we need the SUBPARTITIONS at all (we don't
    reference the SUBPARTITION key in our queries much).

    Wayne

    -----Original Message-----
    From: Greg Rahn
    Sent: Tuesday, September 27, 2011 8:18 PM
    To: work@wayneadams.com
    Cc: oracle-l@freelists.org
    Subject: Re: db file sequential read waits on INSERT into non-indexed
    partitioned table

    Understand that "db file sequential read" just means its not a multi-block
    read - it's a single block read.  Most any time that a single block needs to
    be retrieved, this event shows up.  There are numerous reasons for this:
    file header block access, space management (bitmap blocks), etc, etc.

    As I mentioned, it would appear that this event showed up because of extent
    allocation.  Simply put, when doing bulk inserts, the larger the extent, the
    less frequent the need to get a new extent.
    Especially important when doing bulk inserts into numerous segments (e.g.
    128 hash subpartitions).

    The rest of the stuff you mention doesn't really matter here that I see.
    On Tue, Sep 27, 2011 at 3:57 PM, Wayne Adams wrote:
    Thanks for the feedback guys!

    To elaborate, this particular scenario and discussion is partly out of
    curiosity (myself trying to understand the "db file sequential read"
    on INSERT with no indexes), and partly as a pre-cursor to putting
    forth a more concrete INSERT performance problem example very soon.

    To provide some additional info.

    1) All of these inserts were into the same RANGE partition (we
    partition by month), and the test/trace was done after having just
    inserted 450k rows.
    The table has already been dropped, so I can't tell the extent size at
    the end, but it probably wasn't 64k.
    2) The table never has any updates or deletes, only inserts.
    3) The table does have the DEGREE set to 4, but we did not issue the
    "alter session force parallel dml" clause, so I didn't think it would
    do any concurrent inserts.  Am I wrong in that?

    I am also puzzled by the high CPU time for the insert.  In this
    example, it's 75% of the total elapsed time.  I have never heard of a
    high number of bind variables in an INSERT causing high CPU.  The data
    being passed to the insert has just been finished being massaged by a
    bunch of PL/SQL code, so I'm not sure how would using a GTT in this
    example help.  You would have to use the binds to insert into the GTT too
    wouldn't you?
  • Wayne Adams at Sep 29, 2011 at 7:10 am
    Thanks for the response Gaja.

    In regards to the extents, I'm preloading the tables with 500k before
    running my tests. By the time the preload is done, the tables have already
    jumped up to 8MB extents. So, for purposes of my testing, it should be the
    same as if I had created with the 8MB extents to start with.

    I agree with your comments about LIO. When I'm doing query perf tuning,
    that always plays a big factor. What surprised me was the number of LIO's
    required to handle the hash SUBPARTITION INSERTS. When doing research on
    performance implications of partitioning, I have yet to find any reference
    that talks about this kind of INSERT performance degradation (could be I'm
    just not doing the right keyword search...).

    As for the GTT, I could see where that might be useful for queries. For
    INSERTS, I did actually do a test INSERT into a GTT first and then tried
    INSERT INTO XXXXXXX SELECT FROM GTT. The INSERT into the GTT was fast (2 -
    3 sec for 50k rows), but the subsequent INSERT into the partitioned table
    had the same performance as if I had not used the GTT. So, no perf benefit
    for using GTT in my case.


    Wayne

    =-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=--
    Hi Wayne,
    Just wondering if you perform your tests by creating the table with a large
    extent size such as 8MB as Greg had originally suggested? If not, it may be
    worthwhile to do the tests again. Here is the trend in the numbers I
    observe:

    Sub-Partitions CPU(in secs)QUERYCURRENTTOTAL LIO
    1288.9653964180790234,754
    87.7347728162319210,047
    04.6210485 4829558,780


    The "current" numbers in the trace output are rather high when there are
    sub-partitions (possibly for segment management) and extent size could play
    a
    part here. So, it may be worthwhile to take Greg's advice on this and
    re-test. Also, one can observe in this case, there is a direct correlation
    between CPU time and LIO (query+current).


    Moral of this story - Performance Management is about LIO Management. When
    you
    optimize the LIO, the CPU numbers automatically reflect the optimization.
    With
    regards to your question with GTTs, the concept is still the same - LIO
    Management. In a prior project, the offending SQL with a 1000 bind variables

    was a SELECT and it was easy to populate a GTT with the bind variable values

    and then hang a sub-query off the original SELECT to read the populated GTT.
    It
    dropped LIO down to nothing and with it the CPU numbers.

    Given that the GTT lives in the PGA until it overflows into the TEMP
    tablespace, LIOs (or the resemblance of it) that occur in the PGA are
    usually
    super-fast and low on CPU, as there is no buffer cache management in the
    picture. If this table's function in the application is that of a "staging
    table" and is used for some sort of pre-loading operation, I'd give the GTT
    (with ON COMMIT PRESERVE ROWS) a shot, just for the heck of it. To ensure
    that
    there is no spillage to the TEMP tablespace, do your tests by setting
    WORKAREA_SIZE_POLICY to MANUAL in the session, and set a reasonable number
    for
    SORT_AREA_SIZE and SORT_AREA_RETAINED_SIZE (keep them the SAME value, say
    128MB
    or so) and do your tests. Keep us posted.

    Cheers,

    Gaja

    -----Original Message-----
    From: Wayne Adams
    Sent: Wednesday, September 28, 2011 6:32 PM
    To: 'oracle-l@freelists.org'
    Cc: 'Greg Rahn'
    Subject: RE: db file sequential read waits on INSERT into non-indexed
    partitioned table

    Thanks for the help guys! After reading the explanations here, I decided to
    try a test. I created 2 identical tables (again with no indexes). One with
    8 SUBPARTITONS, one with NO SUBPARTITIONS (range instead of range-hash) and
    did my INSERTs. The difference was pretty impressive (and to me personally,
    surprising).

    INSERT into range-hash partitioned table (128 SUBPARTITIONS), no indexes

    call count cpu elapsed disk query current
    rows
    ------- ------ -------- ---------- ---------- ---------- ----------
    ----------
    Parse 1 0.00 0.00 0 0 0

    Execute 6 8.96 14.00 3738 53964 180790
    50877
    Fetch 0 0.00 0.00 0 0 0

    ------- ------ -------- ---------- ---------- ---------- ----------
    ----------
    total 7 8.96 14.00 3738 53964 180790
    50877

    Elapsed times include waiting on following events:
    Event waited on Times Max. Wait Total
    Waited
    ---------------------------------------- Waited ----------
    ------------
    db file sequential read 3726 0.05
    4.77
    gc current grant 2-way 1990 0.02
    0.55
    gc cr grant 2-way 70 0.00
    0.01
    gc current multi block request 288 0.01
    0.19
    enq: FB - contention 230 0.00
    0.09
    enq: TT - contention 56 0.00
    0.02
    row cache lock 81 0.00
    0.01
    ****************************************************************************
    ****

    INSERT into range-hash partitioned table (8 SUBPARTITIONS), no indexes

    call count cpu elapsed disk query current
    rows
    ------- ------ -------- ---------- ---------- ---------- ----------
    ----------
    Parse 1 0.00 0.00 0 0 0

    Execute 6 7.73 8.82 1110 47728 162319
    50877
    Fetch 0 0.00 0.00 0 0 0

    ------- ------ -------- ---------- ---------- ---------- ----------
    ----------
    total 7 7.73 8.83 1110 47728 162319
    50877


    Elapsed times include waiting on following events:
    Event waited on Times Max. Wait Total
    Waited
    ---------------------------------------- Waited ----------
    ------------
    gc current grant 2-way 471 0.00
    0.12
    db file sequential read 1106 0.02
    0.93
    gc cr grant 2-way 6 0.00
    0.00
    gc current multi block request 334 0.00
    0.18
    enq: FB - contention 290 0.00
    0.08
    gc cr block 2-way 1 0.00
    0.00
    enq: HW - contention 3 0.00
    0.00
    row cache lock 2 0.00
    0.00
    ****************************************************************************
    ****

    INSERT into range partitioned table (no SUBPARTITIONS), no indexes

    call count cpu elapsed disk query current
    rows
    ------- ------ -------- ---------- ---------- ---------- ----------
    ----------
    Parse 1 0.00 0.00 0 0 0

    Execute 6 4.62 5.02 276 10485 48295
    50877
    Fetch 0 0.00 0.00 0 0 0

    ------- ------ -------- ---------- ---------- ---------- ----------
    ----------
    total 7 4.62 5.02 276 10485 48295
    50877

    Elapsed times include waiting on following events:
    Event waited on Times Max. Wait Total
    Waited
    ---------------------------------------- Waited ----------
    ------------
    db file sequential read 275 0.00
    0.15
    enq: FB - contention 194 0.01
    0.17
    enq: HW - contention 3 0.00
    0.00
    row cache lock 2 0.00
    0.00
    gc current block 2-way 1 0.00
    0.00
    ****************************************************************************
    ****

    Intuitively, you would expect some overhead for having the subpartitions,
    but I did not expect quite that much difference (1/2 the CPU, and 1/3 the
    elapsed time with no SUBPARTITIONS vs the 128).

    We may have to revisit whether we need the SUBPARTITIONS at all (we don't
    reference the SUBPARTITION key in our queries much).

    Wayne

    -----Original Message-----
    From: Greg Rahn
    Sent: Tuesday, September 27, 2011 8:18 PM
    To: work@wayneadams.com
    Cc: oracle-l@freelists.org
    Subject: Re: db file sequential read waits on INSERT into non-indexed
    partitioned table

    Understand that "db file sequential read" just means its not a multi-block
    read - it's a single block read. Most any time that a single block needs to
    be retrieved, this event shows up. There are numerous reasons for this:
    file header block access, space management (bitmap blocks), etc, etc.

    As I mentioned, it would appear that this event showed up because of extent
    allocation. Simply put, when doing bulk inserts, the larger the extent, the
    less frequent the need to get a new extent.
    Especially important when doing bulk inserts into numerous segments (e.g.
    128 hash subpartitions).

    The rest of the stuff you mention doesn't really matter here that I see.
    On Tue, Sep 27, 2011 at 3:57 PM, Wayne Adams wrote:
    Thanks for the feedback guys!

    To elaborate, this particular scenario and discussion is partly out of
    curiosity (myself trying to understand the "db file sequential read"
    on INSERT with no indexes), and partly as a pre-cursor to putting
    forth a more concrete INSERT performance problem example very soon.

    To provide some additional info.

    1) All of these inserts were into the same RANGE partition (we
    partition by month), and the test/trace was done after having just
    inserted 450k rows.
    The table has already been dropped, so I can't tell the extent size at
    the end, but it probably wasn't 64k.
    2) The table never has any updates or deletes, only inserts.
    3) The table does have the DEGREE set to 4, but we did not issue the
    "alter session force parallel dml" clause, so I didn't think it would
    do any concurrent inserts.  Am I wrong in that?

    I am also puzzled by the high CPU time for the insert.  In this
    example, it's 75% of the total elapsed time.  I have never heard of a
    high number of bind variables in an INSERT causing high CPU.  The data
    being passed to the insert has just been finished being massaged by a
    bunch of PL/SQL code, so I'm not sure how would using a GTT in this
    example help.  You would have to use the binds to insert into the GTT too
    wouldn't you?
  • Wayne Adams at Sep 29, 2011 at 7:48 am
    Subodh,


    The table holds data fed from a transactional system. It receives, on
    average, 50 - 60k rows every 4 min and the data needs to be immediately
    available for queries. I'm trying to see if INSERT performance can be sped
    up, so I started my testing on test tables with no indexes. The actual
    production table has 3 indexes, 4.5 billion rows and is about 6TB in size
    (and as mentioned before is range-hash partitioned).



    I'm not sure what you mean by dbnk.



    Wayne



    From: Subodh Deshpande
    Sent: Thursday, September 29, 2011 12:33 AM
    To: work@wayneadams.com
    Cc: oracle-l@freelists.org
    Subject: Re: db file sequential read waits on INSERT into non-indexed
    partitioned table



    Hello Wayne,



    What you are saying about use of subpartitions, may be right in your scnerio



    Quote

    We may have to revisit whether we need the SUBPARTITIONS at all (we don't
    reference the SUBPARTITION key in our queries much).

    UnQuote



    it all depends on how you are going to access the data and depending upon
    that need of partitions could be justified..



    I am just curious to know..

    is it day-today used transaction table to hold the data, any other holding
    table in data cleansing in your data mart..or just a one time activity...

    yes if there are millions of rows based on some data element then you can
    decide having partitions based on such data elements

    many times unnecessary features are used..architectural issues....



    do you have any dbnk parameter set for this tables, tablespace and does that
    match with average row size you are inserting..


    thanks and take care..subodh

    On 29 September 2011 12:38, Wayne Adams wrote:

    Thanks for the response Gaja.

    In regards to the extents, I'm preloading the tables with 500k before
    running my tests. By the time the preload is done, the tables have already
    jumped up to 8MB extents. So, for purposes of my testing, it should be the
    same as if I had created with the 8MB extents to start with.

    I agree with your comments about LIO. When I'm doing query perf tuning,
    that always plays a big factor. What surprised me was the number of LIO's
    required to handle the hash SUBPARTITION INSERTS. When doing research on
    performance implications of partitioning, I have yet to find any reference
    that talks about this kind of INSERT performance degradation (could be I'm
    just not doing the right keyword search...).

    As for the GTT, I could see where that might be useful for queries. For
    INSERTS, I did actually do a test INSERT into a GTT first and then tried
    INSERT INTO XXXXXXX SELECT FROM GTT. The INSERT into the GTT was fast (2 -
    3 sec for 50k rows), but the subsequent INSERT into the partitioned table
    had the same performance as if I had not used the GTT. So, no perf benefit
    for using GTT in my case.


    Wayne

    =-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=--

    Hi Wayne,
    Just wondering if you perform your tests by creating the table with a large
    extent size such as 8MB as Greg had originally suggested? If not, it may be
    worthwhile to do the tests again. Here is the trend in the numbers I
    observe:

    Sub-Partitions CPU(in secs)QUERYCURRENTTOTAL LIO
    1288.9653964180790234,754
    87.7347728162319210,047
    04.6210485 4829558,780


    The "current" numbers in the trace output are rather high when there are
    sub-partitions (possibly for segment management) and extent size could play
    a
    part here. So, it may be worthwhile to take Greg's advice on this and
    re-test. Also, one can observe in this case, there is a direct correlation
    between CPU time and LIO (query+current).


    Moral of this story - Performance Management is about LIO Management. When
    you
    optimize the LIO, the CPU numbers automatically reflect the optimization.
    With
    regards to your question with GTTs, the concept is still the same - LIO
    Management. In a prior project, the offending SQL with a 1000 bind variables

    was a SELECT and it was easy to populate a GTT with the bind variable values

    and then hang a sub-query off the original SELECT to read the populated GTT.
    It
    dropped LIO down to nothing and with it the CPU numbers.

    Given that the GTT lives in the PGA until it overflows into the TEMP
    tablespace, LIOs (or the resemblance of it) that occur in the PGA are
    usually
    super-fast and low on CPU, as there is no buffer cache management in the
    picture. If this table's function in the application is that of a "staging
    table" and is used for some sort of pre-loading operation, I'd give the GTT
    (with ON COMMIT PRESERVE ROWS) a shot, just for the heck of it. To ensure
    that
    there is no spillage to the TEMP tablespace, do your tests by setting
    WORKAREA_SIZE_POLICY to MANUAL in the session, and set a reasonable number
    for
    SORT_AREA_SIZE and SORT_AREA_RETAINED_SIZE (keep them the SAME value, say
    128MB
    or so) and do your tests. Keep us posted.

    Cheers,

    Gaja

    -----Original Message-----
    From: Wayne Adams

    Sent: Wednesday, September 28, 2011 6:32 PM

    To: 'oracle-l@freelists.org'
    Cc: 'Greg Rahn'

    Subject: RE: db file sequential read waits on INSERT into non-indexed
    partitioned table

    Thanks for the help guys! After reading the explanations here, I decided to
    try a test. I created 2 identical tables (again with no indexes). One with
    8 SUBPARTITONS, one with NO SUBPARTITIONS (range instead of range-hash) and
    did my INSERTs. The difference was pretty impressive (and to me personally,
    surprising).

    INSERT into range-hash partitioned table (128 SUBPARTITIONS), no indexes

    call count cpu elapsed disk query current
    rows
    ------- ------ -------- ---------- ---------- ---------- ----------
    ----------
    Parse 1 0.00 0.00 0 0 0


    Execute 6 8.96 14.00 3738 53964 180790

    50877
    Fetch 0 0.00 0.00 0 0 0

    ------- ------ -------- ---------- ---------- ---------- ----------
    ----------

    total 7 8.96 14.00 3738 53964 180790
    50877


    Elapsed times include waiting on following events:
    Event waited on Times Max. Wait Total
    Waited
    ---------------------------------------- Waited ----------
    ------------

    db file sequential read 3726 0.05
    4.77
    gc current grant 2-way 1990 0.02
    0.55
    gc cr grant 2-way 70 0.00
    0.01
    gc current multi block request 288 0.01
    0.19
    enq: FB - contention 230 0.00
    0.09
    enq: TT - contention 56 0.00
    0.02
    row cache lock 81 0.00
    0.01
    ****************************************************************************
    ****

    INSERT into range-hash partitioned table (8 SUBPARTITIONS), no indexes

    call count cpu elapsed disk query current
    rows
    ------- ------ -------- ---------- ---------- ---------- ----------
    ----------
    Parse 1 0.00 0.00 0 0 0


    Execute 6 7.73 8.82 1110 47728 162319

    50877
    Fetch 0 0.00 0.00 0 0 0

    ------- ------ -------- ---------- ---------- ---------- ----------
    ----------

    total 7 7.73 8.83 1110 47728 162319
    50877


    Elapsed times include waiting on following events:
    Event waited on Times Max. Wait Total
    Waited
    ---------------------------------------- Waited ----------
    ------------

    gc current grant 2-way 471 0.00
    0.12
    db file sequential read 1106 0.02
    0.93
    gc cr grant 2-way 6 0.00
    0.00
    gc current multi block request 334 0.00
    0.18
    enq: FB - contention 290 0.00
    0.08
    gc cr block 2-way 1 0.00
    0.00

    enq: HW - contention 3 0.00
    0.00
    row cache lock 2 0.00

    0.00
    ****************************************************************************
    ****

    INSERT into range partitioned table (no SUBPARTITIONS), no indexes

    call count cpu elapsed disk query current
    rows
    ------- ------ -------- ---------- ---------- ---------- ----------
    ----------
    Parse 1 0.00 0.00 0 0 0


    Execute 6 4.62 5.02 276 10485 48295

    50877
    Fetch 0 0.00 0.00 0 0 0

    ------- ------ -------- ---------- ---------- ---------- ----------
    ----------

    total 7 4.62 5.02 276 10485 48295
    50877


    Elapsed times include waiting on following events:
    Event waited on Times Max. Wait Total
    Waited
    ---------------------------------------- Waited ----------
    ------------

    db file sequential read 275 0.00
    0.15
    enq: FB - contention 194 0.01
    0.17

    enq: HW - contention 3 0.00
    0.00
    row cache lock 2 0.00
    0.00
    gc current block 2-way 1 0.00
    0.00
    ****************************************************************************
    ****


    Intuitively, you would expect some overhead for having the subpartitions,
    but I did not expect quite that much difference (1/2 the CPU, and 1/3 the
    elapsed time with no SUBPARTITIONS vs the 128).

    We may have to revisit whether we need the SUBPARTITIONS at all (we don't
    reference the SUBPARTITION key in our queries much).

    Wayne

    -----Original Message-----
    From: Greg Rahn
    Sent: Tuesday, September 27, 2011 8:18 PM
    To: work@wayneadams.com
    Cc: oracle-l@freelists.org

    Subject: Re: db file sequential read waits on INSERT into non-indexed
    partitioned table

    Understand that "db file sequential read" just means its not a multi-block
    read - it's a single block read. Most any time that a single block needs to
    be retrieved, this event shows up. There are numerous reasons for this:
    file header block access, space management (bitmap blocks), etc, etc.

    As I mentioned, it would appear that this event showed up because of extent
    allocation. Simply put, when doing bulk inserts, the larger the extent, the
    less frequent the need to get a new extent.
    Especially important when doing bulk inserts into numerous segments (e.g.
    128 hash subpartitions).

    The rest of the stuff you mention doesn't really matter here that I see.
    On Tue, Sep 27, 2011 at 3:57 PM, Wayne Adams wrote:
    Thanks for the feedback guys!

    To elaborate, this particular scenario and discussion is partly out of
    curiosity (myself trying to understand the "db file sequential read"
    on INSERT with no indexes), and partly as a pre-cursor to putting
    forth a more concrete INSERT performance problem example very soon.

    To provide some additional info.

    1) All of these inserts were into the same RANGE partition (we
    partition by month), and the test/trace was done after having just
    inserted 450k rows.
    The table has already been dropped, so I can't tell the extent size at
    the end, but it probably wasn't 64k.
    2) The table never has any updates or deletes, only inserts.
    3) The table does have the DEGREE set to 4, but we did not issue the
    "alter session force parallel dml" clause, so I didn't think it would
    do any concurrent inserts. Am I wrong in that?

    I am also puzzled by the high CPU time for the insert. In this
    example, it's 75% of the total elapsed time. I have never heard of a
    high number of bind variables in an INSERT causing high CPU. The data
    being passed to the insert has just been finished being massaged by a
    bunch of PL/SQL code, so I'm not sure how would using a GTT in this
    example help. You would have to use the binds to insert into the GTT too
    wouldn't you?


    --
    Regards,
    Greg Rahn
    http://structureddata.org <http://structureddata.org/>


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






    --
    ==============================
    DO NOT FORGET TO SMILE TODAY
    ==============================



    --
    http://www.freelists.org/webpage/oracle-l
  • Wayne Adams at Sep 29, 2011 at 8:03 am
    Just for completeness, I created another test table (range-hash, 128 SUBP)
    specifying a large INITIAL/NEXT so that I would get 8MB extents. I then ran
    the tests again. The results were practically identical to my other tests.

    INSERT into range-hash (128 SUBP)

    call count cpu elapsed disk query current
    rows
    ------- ------ -------- ---------- ---------- ---------- ----------
    ----------
    Parse 1 0.00 0.00 0 0 0

    Execute 6 8.89 13.97 2572 53355 180107
    50877
    Fetch 0 0.00 0.00 0 0 0

    ------- ------ -------- ---------- ---------- ---------- ----------
    ----------
    total 7 8.89 13.97 2572 53355 180107
    50877

    Elapsed times include waiting on following events:
    Event waited on Times Max. Wait Total
    Waited
    ---------------------------------------- Waited ----------
    ------------
    db file sequential read 2570 0.04
    4.61
    gc current grant 2-way 1495 0.03
    0.45
    gc cr grant 2-way 17 0.00
    0.00
    enq: FB - contention 216 0.00
    0.12
    gc current multi block request 439 0.00
    0.16
    enq: TT - contention 5 0.00
    0.00
    gc current grant busy 2 0.00
    0.00
    ****************************************************************************
    ****

    INSERT into range (no SUBP)

    call count cpu elapsed disk query current
    rows
    ------- ------ -------- ---------- ---------- ---------- ----------
    ----------
    Parse 1 0.00 0.00 0 0 0

    Execute 6 3.03 3.17 99 10218 48616
    50877
    Fetch 0 0.00 0.00 0 0 0

    ------- ------ -------- ---------- ---------- ---------- ----------
    ----------
    total 7 3.03 3.17 99 10218 48616
    50877

    Elapsed times include waiting on following events:
    Event waited on Times Max. Wait Total
    Waited
    ---------------------------------------- Waited ----------
    ------------
    db file sequential read 99 0.00
    0.07
    enq: FB - contention 194 0.00
    0.08
    buffer busy waits 1 0.00
    0.00
    KJC: Wait for msg sends to complete 1 0.00
    0.00
    ****************************************************************************
    ****


    Wayne

    -----Original Message-----
    From: Wayne Adams
    Sent: Thursday, September 29, 2011 12:08 AM
    To: oracle-l@freelists.org
    Subject: RE: db file sequential read waits on INSERT into non-indexed
    partitioned table

    Thanks for the response Gaja.

    In regards to the extents, I'm preloading the tables with 500k before
    running my tests. By the time the preload is done, the tables have already
    jumped up to 8MB extents. So, for purposes of my testing, it should be the
    same as if I had created with the 8MB extents to start with.

    I agree with your comments about LIO. When I'm doing query perf tuning,
    that always plays a big factor. What surprised me was the number of LIO's
    required to handle the hash SUBPARTITION INSERTS. When doing research on
    performance implications of partitioning, I have yet to find any reference
    that talks about this kind of INSERT performance degradation (could be I'm
    just not doing the right keyword search...).

    As for the GTT, I could see where that might be useful for queries. For
    INSERTS, I did actually do a test INSERT into a GTT first and then tried
    INSERT INTO XXXXXXX SELECT FROM GTT. The INSERT into the GTT was fast (2 -
    3 sec for 50k rows), but the subsequent INSERT into the partitioned table
    had the same performance as if I had not used the GTT. So, no perf benefit
    for using GTT in my case.


    Wayne

    =-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=--
    Hi Wayne,
    Just wondering if you perform your tests by creating the table with a large
    extent size such as 8MB as Greg had originally suggested? If not, it may be
    worthwhile to do the tests again. Here is the trend in the numbers I
    observe:

    Sub-Partitions CPU(in secs)QUERYCURRENTTOTAL LIO
    1288.9653964180790234,754
    87.7347728162319210,047
    04.6210485 4829558,780


    The "current" numbers in the trace output are rather high when there are
    sub-partitions (possibly for segment management) and extent size could play
    a part here. So, it may be worthwhile to take Greg's advice on this and
    re-test. Also, one can observe in this case, there is a direct correlation
    between CPU time and LIO (query+current).


    Moral of this story - Performance Management is about LIO Management. When
    you optimize the LIO, the CPU numbers automatically reflect the
    optimization. With regards to your question with GTTs, the concept is still
    the same - LIO Management. In a prior project, the offending SQL with a 1000
    bind variables was a SELECT and it was easy to populate a GTT with the bind
    variable values and then hang a sub-query off the original SELECT to read
    the populated GTT. It dropped LIO down to nothing and with it the CPU
    numbers.

    Given that the GTT lives in the PGA until it overflows into the TEMP
    tablespace, LIOs (or the resemblance of it) that occur in the PGA are
    usually super-fast and low on CPU, as there is no buffer cache management in
    the picture. If this table's function in the application is that of a
    "staging table" and is used for some sort of pre-loading operation, I'd give
    the GTT (with ON COMMIT PRESERVE ROWS) a shot, just for the heck of it. To
    ensure that there is no spillage to the TEMP tablespace, do your tests by
    setting WORKAREA_SIZE_POLICY to MANUAL in the session, and set a reasonable
    number for SORT_AREA_SIZE and SORT_AREA_RETAINED_SIZE (keep them the SAME
    value, say 128MB or so) and do your tests. Keep us posted.

    Cheers,

    Gaja

    -----Original Message-----
    From: Wayne Adams
    Sent: Wednesday, September 28, 2011 6:32 PM
    To: 'oracle-l@freelists.org'
    Cc: 'Greg Rahn'
    Subject: RE: db file sequential read waits on INSERT into non-indexed
    partitioned table

    Thanks for the help guys! After reading the explanations here, I decided to
    try a test. I created 2 identical tables (again with no indexes). One with
    8 SUBPARTITONS, one with NO SUBPARTITIONS (range instead of range-hash) and
    did my INSERTs. The difference was pretty impressive (and to me personally,
    surprising).

    INSERT into range-hash partitioned table (128 SUBPARTITIONS), no indexes

    call count cpu elapsed disk query current
    rows
    ------- ------ -------- ---------- ---------- ---------- ----------
    ----------
    Parse 1 0.00 0.00 0 0 0

    Execute 6 8.96 14.00 3738 53964 180790
    50877
    Fetch 0 0.00 0.00 0 0 0

    ------- ------ -------- ---------- ---------- ---------- ----------
    ----------
    total 7 8.96 14.00 3738 53964 180790
    50877

    Elapsed times include waiting on following events:
    Event waited on Times Max. Wait Total
    Waited
    ---------------------------------------- Waited ----------
    ------------
    db file sequential read 3726 0.05
    4.77
    gc current grant 2-way 1990 0.02
    0.55
    gc cr grant 2-way 70 0.00
    0.01
    gc current multi block request 288 0.01
    0.19
    enq: FB - contention 230 0.00
    0.09
    enq: TT - contention 56 0.00
    0.02
    row cache lock 81 0.00
    0.01
    ****************************************************************************
    ****

    INSERT into range-hash partitioned table (8 SUBPARTITIONS), no indexes

    call count cpu elapsed disk query current
    rows
    ------- ------ -------- ---------- ---------- ---------- ----------
    ----------
    Parse 1 0.00 0.00 0 0 0

    Execute 6 7.73 8.82 1110 47728 162319
    50877
    Fetch 0 0.00 0.00 0 0 0

    ------- ------ -------- ---------- ---------- ---------- ----------
    ----------
    total 7 7.73 8.83 1110 47728 162319
    50877


    Elapsed times include waiting on following events:
    Event waited on Times Max. Wait Total
    Waited
    ---------------------------------------- Waited ----------
    ------------
    gc current grant 2-way 471 0.00
    0.12
    db file sequential read 1106 0.02
    0.93
    gc cr grant 2-way 6 0.00
    0.00
    gc current multi block request 334 0.00
    0.18
    enq: FB - contention 290 0.00
    0.08
    gc cr block 2-way 1 0.00
    0.00
    enq: HW - contention 3 0.00
    0.00
    row cache lock 2 0.00
    0.00
    ****************************************************************************
    ****

    INSERT into range partitioned table (no SUBPARTITIONS), no indexes

    call count cpu elapsed disk query current
    rows
    ------- ------ -------- ---------- ---------- ---------- ----------
    ----------
    Parse 1 0.00 0.00 0 0 0

    Execute 6 4.62 5.02 276 10485 48295
    50877
    Fetch 0 0.00 0.00 0 0 0

    ------- ------ -------- ---------- ---------- ---------- ----------
    ----------
    total 7 4.62 5.02 276 10485 48295
    50877

    Elapsed times include waiting on following events:
    Event waited on Times Max. Wait Total
    Waited
    ---------------------------------------- Waited ----------
    ------------
    db file sequential read 275 0.00
    0.15
    enq: FB - contention 194 0.01
    0.17
    enq: HW - contention 3 0.00
    0.00
    row cache lock 2 0.00
    0.00
    gc current block 2-way 1 0.00
    0.00
    ****************************************************************************
    ****

    Intuitively, you would expect some overhead for having the subpartitions,
    but I did not expect quite that much difference (1/2 the CPU, and 1/3 the
    elapsed time with no SUBPARTITIONS vs the 128).

    We may have to revisit whether we need the SUBPARTITIONS at all (we don't
    reference the SUBPARTITION key in our queries much).

    Wayne

    -----Original Message-----
    From: Greg Rahn
    Sent: Tuesday, September 27, 2011 8:18 PM
    To: work@wayneadams.com
    Cc: oracle-l@freelists.org
    Subject: Re: db file sequential read waits on INSERT into non-indexed
    partitioned table

    Understand that "db file sequential read" just means its not a multi-block
    read - it's a single block read. Most any time that a single block needs to
    be retrieved, this event shows up. There are numerous reasons for this:
    file header block access, space management (bitmap blocks), etc, etc.

    As I mentioned, it would appear that this event showed up because of extent
    allocation. Simply put, when doing bulk inserts, the larger the extent, the
    less frequent the need to get a new extent.
    Especially important when doing bulk inserts into numerous segments (e.g.
    128 hash subpartitions).

    The rest of the stuff you mention doesn't really matter here that I see.
    On Tue, Sep 27, 2011 at 3:57 PM, Wayne Adams wrote:
    Thanks for the feedback guys!

    To elaborate, this particular scenario and discussion is partly out of
    curiosity (myself trying to understand the "db file sequential read"
    on INSERT with no indexes), and partly as a pre-cursor to putting
    forth a more concrete INSERT performance problem example very soon.

    To provide some additional info.

    1) All of these inserts were into the same RANGE partition (we
    partition by month), and the test/trace was done after having just
    inserted 450k rows.
    The table has already been dropped, so I can't tell the extent size at
    the end, but it probably wasn't 64k.
    2) The table never has any updates or deletes, only inserts.
    3) The table does have the DEGREE set to 4, but we did not issue the
    "alter session force parallel dml" clause, so I didn't think it would
    do any concurrent inserts.  Am I wrong in that?

    I am also puzzled by the high CPU time for the insert.  In this
    example, it's 75% of the total elapsed time.  I have never heard of a
    high number of bind variables in an INSERT causing high CPU.  The data
    being passed to the insert has just been finished being massaged by a
    bunch of PL/SQL code, so I'm not sure how would using a GTT in this
    example help.  You would have to use the binds to insert into the GTT too
    wouldn't you?
  • Wayne Adams at Sep 29, 2011 at 6:04 pm
    Thanks Jonathan for the response and the explanations!

    The tablespaces have an 8k blocksize. These tests have been in our QA
    system which has FLASHBACK DATABASE turned off. So I don't think we can
    attribute the "db file sequential reads" to that (flashback is turned on in
    our production system however, so we'll have to look at how much that
    factors into the INSERT performance there).

    Avg Row Len is 719, but I ran your rows/block script for a more accurate
    result:

    TWENTIETH MIN_ROWS MAX_ROWS TOT_BLOCKS TOT_ROWS AVG_ROWS
    ---------- ---------- ---------- ---------- ---------- --------
    1 1 1 212 212 1.00
    2 2 2 16 32 2.00
    3 3 3 21 63 3.00
    4 4 4 19 76 4.00
    5 5 5 14 70 5.00
    6 6 6 16 96 6.00
    7 7 7 259 1813 7.00
    8 8 8 6577 52616 8.00
    9 9 9 43927 395343 9.00
    10 10 10 9651 96510 10.00
    11 11 11 158 1738 11.00
    ----------
    sum 60870 548569

    I have included a sampling of the WAITS for the INSERT. Obj# are all
    various SUBP of the table.

    WAIT #11: nam='db file sequential read' ela= 259 file#=12 block#=7573302
    blocks=1 obj#=38684000 tim=1286408819092647
    WAIT #11: nam='enq: FB - contention' ela= 665 name|mode=1178730502
    tablespace #=6 dba=5749315 obj#=38684000 tim=1286408819095790
    WAIT #11: nam='db file sequential read' ela= 994 file#=12 block#=7573318
    blocks=1 obj#=38684000 tim=1286408819098305
    WAIT #11: nam='db file sequential read' ela= 171 file#=12 block#=7452688
    blocks=1 obj#=38684073 tim=1286408819098944
    WAIT #11: nam='db file sequential read' ela= 1347 file#=12 block#=7573334
    blocks=1 obj#=38684000 tim=1286408819103219
    WAIT #11: nam='db file sequential read' ela= 817 file#=12 block#=7573350
    blocks=1 obj#=38684000 tim=1286408819108149
    WAIT #11: nam='db file sequential read' ela= 433 file#=12 block#=7573366
    blocks=1 obj#=38684000 tim=1286408819112474
    WAIT #11: nam='gc current grant 2-way' ela= 262 p1=12 p2=7573382 p3=33554433
    obj#=38684000 tim=1286408819118822
    WAIT #11: nam='db file sequential read' ela= 1829 file#=12 block#=7573382
    blocks=1 obj#=38684000 tim=1286408819120736
    WAIT #11: nam='gc current grant 2-way' ela= 265 p1=12 p2=7573398 p3=33554433
    obj#=38684000 tim=1286408819124516
    WAIT #11: nam='db file sequential read' ela= 2041 file#=12 block#=7573398
    blocks=1 obj#=38684000 tim=1286408819126633
    WAIT #11: nam='gc current grant 2-way' ela= 231 p1=12 p2=5716113 p3=33554433
    obj#=38683993 tim=1286408819127771
    WAIT #11: nam='db file sequential read' ela= 814 file#=12 block#=5716113
    blocks=1 obj#=38683993 tim=1286408819128632
    WAIT #11: nam='gc current grant 2-way' ela= 250 p1=12 p2=7573414 p3=33554433
    obj#=38684000 tim=1286408819130314
    WAIT #11: nam='db file sequential read' ela= 1218 file#=12 block#=7573414
    blocks=1 obj#=38684000 tim=1286408819131582
    WAIT #11: nam='db file sequential read' ela= 1172 file#=12 block#=5617757
    blocks=1 obj#=38683987 tim=1286408819137810
    WAIT #11: nam='enq: FB - contention' ela= 522 name|mode=1178730502
    tablespace #=6 dba=7452675 obj#=38683987 tim=1286408819143040


    Also, regarding your damage limitation. Since the performance seems to be
    affected by the hash subpartitions and not the range (there is only 1 range
    partition in my test table), how would you sort the data before inserting
    it?

    In order to test the ASSM impact, I created a non ASSM tablespace and reran
    my tests. The fact that ASSM has a negative affect didn't surprise me, but
    the degree did.

    INSERT into range part (no SUBP), no indexes, ASSM

    call count cpu elapsed disk query current
    rows
    ------- ------ -------- ---------- ---------- ---------- ----------
    ----------
    Parse 1 0.00 0.00 0 0 0

    Execute 6 3.26 3.62 310 10393 48259
    50877
    Fetch 0 0.00 0.00 0 0 0

    ------- ------ -------- ---------- ---------- ---------- ----------
    ----------
    total 7 3.26 3.62 310 10393 48259
    50877

    Elapsed times include waiting on following events:
    Event waited on Times Max. Wait Total
    Waited
    ---------------------------------------- Waited ----------
    ------------
    db file sequential read 307 0.01
    0.20
    enq: FB - contention 183 0.00
    0.08
    enq: HW - contention 3 0.00
    0.00
    row cache lock 2 0.00
    0.00
    ****************************************************************************
    ****

    INSERT into range-hash part (128 SUBP), no indexes, no ASSM

    call count cpu elapsed disk query current
    rows
    ------- ------ -------- ---------- ---------- ---------- ----------
    ----------
    Parse 1 0.00 0.00 0 0 0

    Execute 6 6.16 7.25 507 53036 68817
    50877
    Fetch 0 0.00 0.00 0 0 0

    ------- ------ -------- ---------- ---------- ---------- ----------
    ----------
    total 7 6.16 7.25 507 53036 68817
    50877

    Elapsed times include waiting on following events:
    Event waited on Times Max. Wait Total
    Waited
    ---------------------------------------- Waited ----------
    ------------
    gc cr grant 2-way 63 0.00
    0.01
    db file sequential read 507 0.02
    0.28
    gc current grant 2-way 222 0.00
    0.05
    enq: HW - contention 1630 0.00
    0.43
    gc current multi block request 733 0.00
    0.34
    enq: TT - contention 7 0.00
    0.00
    KJC: Wait for msg sends to complete 8 0.00
    0.00
    latch free 2 0.00
    0.00
    latch: ges resource hash list 1 0.00
    0.00
    ****************************************************************************
    ****

    INSERT into range-hash part (128 SUBP), no indexes, ASSM

    call count cpu elapsed disk query current
    rows
    ------- ------ -------- ---------- ---------- ---------- ----------
    ----------
    Parse 1 0.00 0.00 0 0 0

    Execute 6 8.57 12.47 3494 53406 179867
    50877
    Fetch 0 0.00 0.00 0 0 0

    ------- ------ -------- ---------- ---------- ---------- ----------
    ----------
    total 7 8.57 12.47 3494 53406 179867
    50877

    Elapsed times include waiting on following events:
    Event waited on Times Max. Wait Total
    Waited
    ---------------------------------------- Waited ----------
    ------------
    db file sequential read 3492 0.04
    3.80
    gc current grant 2-way 1857 0.00
    0.52
    gc cr grant 2-way 17 0.00
    0.00
    enq: FB - contention 215 0.00
    0.10
    gc current multi block request 307 0.00
    0.15
    enq: TT - contention 3 0.00
    0.00
    ****************************************************************************
    ****

    Wayne

    -----Original Message-----

    I should have asked - how many rows do you get per block, and what's the
    block
    size (which, in your version, with ASSM) might make a difference to what's
    going on.

    Regards
    Jonathan Lewis
    -----Original Message-----
    Wayne,

    I can't explain why you are waiting for the enqueues, but I think the extra
    current block gets appear because every time a row in the array goes into a
    different partition from the previous row your session does a bitmap search
    for
    the first free block in that partition. The more partitions you have the
    more
    likely it is that the next row belongs in a different partition from the
    previous row. The difference (worst case) is probably three current gets
    per
    row, although I haven't tested your scenario, which may make it four.

    Damage limitation:
    a) sort the data by target partition before inserting it.
    b) use freelist management, not ASSM.

    The db file sequentil reads are probably the effect of enabling flashback
    datase, every block you "new" may have to be read and copied into the
    flashback
    log.

    The FB enqueues are Format Block - and I think you're formatting 16 blocks
    at a
    time; the TT enqueues are tablespace bitmap update locks taken as you modify

    space from the tablespace freespace bitmap (there are related reasons for
    TT's), and the HW lock is the highwatermark bump lock, taken as you update
    the
    segment header highwater mark. I can understand the TT resulting in a wait,

    but if you are the only person inserting into this table I don't understand
    why
    the FB and HW see waits.


    I have a few clues that things are done a little differently in 11.2, and
    the
    changes may make a difference to the results you are seeing.

    Regards
    Jonathan Lewis

    -----Original Message-----
    From: Wayne Adams
    Sent: Thursday, September 29, 2011 1:02 AM
    To: oracle-l@freelists.org
    Subject: RE: db file sequential read waits on INSERT into non-indexed
    partitioned table

    Just for completeness, I created another test table (range-hash, 128 SUBP)
    specifying a large INITIAL/NEXT so that I would get 8MB extents. I then ran
    the tests again. The results were practically identical to my other tests.

    INSERT into range-hash (128 SUBP)

    call count cpu elapsed disk query current
    rows
    ------- ------ -------- ---------- ---------- ---------- ----------
    ----------
    Parse 1 0.00 0.00 0 0 0

    Execute 6 8.89 13.97 2572 53355 180107
    50877
    Fetch 0 0.00 0.00 0 0 0

    ------- ------ -------- ---------- ---------- ---------- ----------
    ----------
    total 7 8.89 13.97 2572 53355 180107
    50877

    Elapsed times include waiting on following events:
    Event waited on Times Max. Wait Total
    Waited
    ---------------------------------------- Waited ----------
    ------------
    db file sequential read 2570 0.04
    4.61
    gc current grant 2-way 1495 0.03
    0.45
    gc cr grant 2-way 17 0.00
    0.00
    enq: FB - contention 216 0.00
    0.12
    gc current multi block request 439 0.00
    0.16
    enq: TT - contention 5 0.00
    0.00
    gc current grant busy 2 0.00
    0.00
    ****************************************************************************
    ****

    INSERT into range (no SUBP)

    call count cpu elapsed disk query current
    rows
    ------- ------ -------- ---------- ---------- ---------- ----------
    ----------
    Parse 1 0.00 0.00 0 0 0

    Execute 6 3.03 3.17 99 10218 48616
    50877
    Fetch 0 0.00 0.00 0 0 0

    ------- ------ -------- ---------- ---------- ---------- ----------
    ----------
    total 7 3.03 3.17 99 10218 48616
    50877

    Elapsed times include waiting on following events:
    Event waited on Times Max. Wait Total
    Waited
    ---------------------------------------- Waited ----------
    ------------
    db file sequential read 99 0.00
    0.07
    enq: FB - contention 194 0.00
    0.08
    buffer busy waits 1 0.00
    0.00
    KJC: Wait for msg sends to complete 1 0.00
    0.00
    ****************************************************************************
    ****


    Wayne


    --
    http://www.freelists.org/webpage/oracle-l
  • Jonathan at Sep 29, 2011 at 12:43 pm
    Wayne,

    I can't explain why you are waiting for the enqueues, but I think the extra current block gets appear because every time a row in the array goes into a different partition from the previous row your session does a bitmap search for the first free block in that partition. The more partitions you have the more likely it is that the next row belongs in a different partition from the previous row. The difference (worst case) is probably three current gets per row, although I haven't tested your scenario, which may make it four.

    Damage limitation:
    a) sort the data by target partition before inserting it.
    b) use freelist management, not ASSM.

    The db file sequentil reads are probably the effect of enabling flashback datase, every block you "new" may have to be read and copied into the flashback log.

    The FB enqueues are Format Block - and I think you're formatting 16 blocks at a time; the TT enqueues are tablespace bitmap update locks taken as you modify space from the tablespace freespace bitmap (there are related reasons for TT's), and the HW lock is the highwatermark bump lock, taken as you update the segment header highwater mark. I can understand the TT resulting in a wait, but if you are the only person inserting into this table I don't understand why the FB and HW see waits.


    I have a few clues that things are done a little differently in 11.2, and the changes may make a difference to the results you are seeing.

    Regards
    Jonathan Lewis
  • Jonathan at Sep 29, 2011 at 12:55 pm
    I should have asked - how many rows do you get per block, and what's the block size (which, in your version, with ASSM) might make a difference to what's going on.

    Regards
    Jonathan Lewis

Related Discussions

Discussion Navigation
viewthread | post
Discussion Overview
grouporacle-l @
categoriesoracle
postedSep 26, '11 at 7:58p
activeSep 29, '11 at 6:04p
posts14
users5
websiteoracle.com

People

Translate

site design / logo © 2022 Grokbase