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

From: Wayne Adams <work_at_wayneadams.com>
Date: Mon, 26 Sep 2011 12:57:00 -0700
Message-ID: <011501cc7c86$7447b4a0$5cd71de0$_at_wayneadams.com>

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 0
Execute 2 14.51 20.48 6647 61385 207160 50877
Fetch 0 0.00 0.00 0 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

Received on Mon Sep 26 2011 - 14:57:00 CDT