Re: db file sequential read waits on INSERT into non-indexed partitioned table
Date: Mon, 26 Sep 2011 16:16:31 -0700 (PDT)
Message-ID: <1317078991.32567.YahooMailNeo_at_web83606.mail.sp1.yahoo.com>
Hi Wayne,
A few clarifications :
- 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.
- 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.
- 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.
- 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_at_wayneadams.com> To: oracle-l_at_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 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-lReceived on Mon Sep 26 2011 - 18:16:31 CDT