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

From: Wayne Adams <work_at_wayneadams.com>
Date: Tue, 27 Sep 2011 15:57:31 -0700
Message-ID: <017c01cc7d68$d6a9e130$83fda390$_at_wayneadams.com>

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.

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.
The table never has any updates or deletes, only inserts.
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
><gajav_at_xxxxxxxxx> 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 [mailto:work_at_wayneadams.com] Sent: Monday, September 26, 2011 12:57 PM To: 'oracle-l_at_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 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 Tue Sep 27 2011 - 17:57:31 CDT

This message: [ Message body ]
Next message: Steve Harville: "Re: RMAN - Rewind Backup to SCN/Point-in-Time"
Previous message: Tanel Poder: "Re: High shared pool usage"
Next in thread: Greg Rahn: "Re: db file sequential read waits on INSERT into non-indexed partitioned table"
Reply: Greg Rahn: "Re: db file sequential read waits on INSERT into non-indexed partitioned table"

Contemporary messages sorted: [ by date ] [ by thread ] [ by subject ] [ by author ]

Original text of this message