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

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@xxxxxxxxxxxxxx>
To: oracle-l@xxxxxxxxxxxxx
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
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#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


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


Other related posts: