Oracle Database Discussions

Announcement

For appeals, questions and feedback about Oracle Forums, please email oracle-forums-moderators_us@oracle.com. Technical questions should be asked in the appropriate category. Thank you!

resolve high user i/o wait for first run

spur230May 22 2015 — edited May 26 2015

I am using Oracle 11.2.0.3 in Red Hat Linux 5.8.

My query is running for around 24 min in first run then it runs for 2 minutes in subsequent runs. I ran this in various environment ( dev, int) and I see same behavior.

Sql plan_hash_value and buffer get remains same . Physical read changes from 432K in first run to 271K in second. Most importantly, user IO wait time is 127K in first run while it is 892 is 2nd run.

Why would wait time be so high in first run? Is there anything I could do to resolve it?

Update:

I could not replicate this behavior by flushing shared_pool and buffer_cache. Although physical read would be same as 1st run but elasped time was still under 5 minutes. Main difference between 1st and other runs is in 'file io wait time'

1st run statistic and explain plan

buffer is not pinned count 6479846
buffer is pinned count 1448329
bytes received via SQL*Net from client 12841
bytes sent via SQL*Net to client 3281421
Cached Commit SCN referenced 829880
calls to get snapshot scn: kcmgss 2019403
calls to kcmgas 0
calls to kcmgcs 1
CCursor + sql area evicted 4
cell physical IO interconnect bytes -1508540416
cleanout - number of ktugct calls 1
cleanouts only - consistent read gets 1
cluster key scan block gets 67
cluster key scans 50
commit cleanouts 0
commit cleanouts successfully completed 0
Commit SCN cached 1
commit txn count during cleanout 1
consistent gets 9430119
consistent gets - examination 5655516
consistent gets from cache 9430119
consistent gets from cache (fastpath) 2973750
CPU used by this session 21494
CPU used when call started 21496
cursor authentications 22
db block changes 1
db block gets 0
db block gets from cache 0
DB time 146927
deferred (CURRENT) block cleanout applications 0
dirty buffers inspected 312
enqueue releases 79
enqueue requests 79
execute count 2019407
file io wait time 1270072080
free buffer inspected 438587
free buffer requested 432214
hot buffers moved to head of LRU 202736
HSC Heap Segment Block Changes 0
immediate (CR) block cleanout applications 1
index fetch by key 805381
index scans kdiixs1 2126943
logical read bytes from cache -115752960
logons cumulative 0
logons current 0
messages sent 0
min active SCN optimization applied on CR 94680
no buffer to keep pinned count 38
no work - consistent read gets 3774471
non-idle wait count 432657
non-idle wait time 127009
opened cursors cumulative 2019389
opened cursors current 1
parse count (failures) 0
parse count (hard) 45
parse count (total) 81
parse time cpu 4
parse time elapsed 14
physical read bytes -1508540416
physical read IO requests 432214
physical read total bytes -1508540416
physical read total IO requests 432214
physical reads 432214
physical reads cache 432214
pinned buffers inspected 10
pinned cursors current 0
prefetched blocks aged out before use 4283
process last non-idle time 0
recursive calls 2020404
recursive cpu usage 14340
redo entries 1
redo size 116
redo synch time (usec) 0
redo synch writes 0
Requests to/from client 55
rows fetched via callback 778746
session connect time 0
session cursor cache count -26
session cursor cache hits 53258
session logical reads 9430119
session pga memory 851968
session pga memory max 8126464
session uga memory 1768160
session uga memory max 9377000
shared hash latch upgrades - no wait 40193
sorts (memory) 2045881
sorts (rows) 657078
sql area evicted 32
sql area purged 0
SQL*Net roundtrips to/from client 56
table fetch by rowid 2512139
table fetch continued row 2
table scan blocks gotten 1
table scan rows gotten 10
table scans (short tables) 1
undo change vector size 0
user calls 64
user I/O wait time 127008
workarea executions - optimal 568734
workarea memory allocated 275

Plan hash value: 2966358639

-----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
| Id  | Operation                      | Name                     | Starts | E-Rows |E-Bytes| Cost (%CPU)| E-Time   | A-Rows |   A-Time   | Buffers | Reads  |  OMem |  1Mem | Used-Mem |
-----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT               |                          |      1 |        |       |    18 (100)|          |  26569 |00:24:28.95 |    9429K|    432K|       |       |          |
|   1 |  TABLE ACCESS BY INDEX ROWID   | INDVL                    |  26569 |      1 |    29 |     1   (0)| 00:00:01 |  26569 |00:00:16.69 |   79713 |  20370 |       |       |          |
|*  2 |   INDEX UNIQUE SCAN            | PKINDVL                 |  26569 |      1 |       |     1   (0)| 00:00:01 |  26569 |00:00:14.69 |   53143 |   2521 |       |       |          |
|   3 |  SORT GROUP BY                 |                          |  26569 |      1 |    16 |            |          |  26569 |00:00:21.68 |   56251 |   3553 |  2048 |  2048 | 2048  (0)|
|*  4 |   TABLE ACCESS BY INDEX ROWID  | OCRN                     |  26569 |      1 |    16 |     1   (0)| 00:00:01 |   3687 |00:00:22.03 |   56251 |   3553 |       |       |          |
|*  5 |    INDEX RANGE SCAN            | XIE1OCRN                 |  26569 |      1 |       |     1   (0)| 00:00:01 |   3687 |00:00:06.62 |   53149 |   1398 |       |       |          |
|   6 |  SORT AGGREGATE                |                          |  26569 |      1 |    13 |            |          |  26569 |00:00:02.46 |   27157 |    543 |       |       |          |
|*  7 |   TABLE ACCESS BY INDEX ROWID  | INDVL_RGSTN_DFCNY        |  26569 |      1 |    13 |     1   (0)| 00:00:01 |   1540 |00:00:02.73 |   27157 |    543 |       |       |          |
|*  8 |    INDEX RANGE SCAN            | XIF1188INDVL_RGSTN_DFCNY |  26569 |      1 |       |     1   (0)| 00:00:01 |   1540 |00:00:01.19 |   26638 |    285 |       |       |          |
|   9 |  NESTED LOOPS                  |                          |  26569 |      1 |    43 |     2   (0)| 00:00:01 |  26569 |00:00:00.29 |   79717 |      0 |       |       |          |
|  10 |   TABLE ACCESS BY INDEX ROWID  | INDVL                    |  26569 |      1 |    17 |     1   (0)| 00:00:01 |  26569 |00:00:00.17 |   79713 |      0 |       |       |          |
|* 11 |    INDEX UNIQUE SCAN           | XPKINDVL                 |  26569 |      1 |       |     1   (0)| 00:00:01 |  26569 |00:00:00.10 |   53143 |      0 |       |       |          |
|* 12 |   INDEX UNIQUE SCAN            | PK$CE_ST_TBL             |  26569 |      7 |   182 |     1   (0)| 00:00:01 |  26569 |00:00:00.08 |       4 |      0 |       |       |          |
|  13 |  TABLE ACCESS BY INDEX ROWID   | H230_INDV_PRS_INFO       |  26569 |      1 |     8 |     1   (0)| 00:00:01 |  26555 |00:16:43.10 |     509K|    234K|       |       |          |
|* 14 |   INDEX UNIQUE SCAN            | XPKH230_INDV_PRS_INFO    |  26569 |      1 |       |     1   (0)| 00:00:01 |  26555 |00:15:13.44 |     482K|    219K|       |       |          |
|  15 |    SORT AGGREGATE              |                          |  26569 |      1 |    21 |            |          |  26569 |00:14:50.09 |     429K|    215K|       |       |          |
|* 16 |     TABLE ACCESS BY INDEX ROWID| H000_TRANS               |  26569 |      1 |    21 |     2   (0)| 00:00:01 |    171K|00:13:28.87 |     429K|    215K|       |       |          |
|* 17 |      INDEX RANGE SCAN          | XIF1032H000_TRANS        |  26569 |      6 |       |     1   (0)| 00:00:01 |    380K|00:01:33.03 |   53706 |  15168 |       |       |          |
|  18 |  SORT ORDER BY                 |                          |      1 |     20 |  1600 |    18   (6)| 00:00:01 |  26569 |00:24:28.95 |    9429K|    432K|  9195K|  1077K| 8173K (0)|
|  19 |   NESTED LOOPS SEMI            |                          |      1 |     20 |  1600 |    17   (0)| 00:00:01 |  26569 |00:02:06.10 |   96543 |  39113 |       |       |          |
|  20 |    NESTED LOOPS                |                          |      1 |     20 |  1220 |     5   (0)| 00:00:01 |  27883 |00:00:04.53 |    8665 |   6297 |       |       |          |
|  21 |     TABLE ACCESS BY INDEX ROWID| ORG_HDR                  |      1 |      1 |    33 |     1   (0)| 00:00:01 |      1 |00:00:00.01 |       3 |      0 |       |       |          |
|* 22 |      INDEX UNIQUE SCAN         | XPKORG_HDR               |      1 |      1 |       |     1   (0)| 00:00:01 |      1 |00:00:00.01 |       2 |      0 |       |       |          |
|  23 |     TABLE ACCESS BY INDEX ROWID| INDVL_FIRM_ASCTN         |      1 |     20 |   560 |     4   (0)| 00:00:01 |  27883 |00:00:04.52 |    8662 |   6297 |       |       |          |
|* 24 |      INDEX RANGE SCAN          | XIE2INDVL_FIRM_ASCTN     |      1 |     20 |       |     1   (0)| 00:00:01 |  27883 |00:00:00.04 |      62 |     60 |       |       |          |
|* 25 |    TABLE ACCESS BY INDEX ROWID | INDVL_RGSTN              |  27883 |    199 |  3781 |     1   (0)| 00:00:01 |  26569 |00:01:56.48 |   87878 |  32816 |       |       |          |
|* 26 |     INDEX RANGE SCAN           | XPKINDVL_RGSTN           |  27883 |      1 |       |     1   (0)| 00:00:01 |  70914 |00:01:55.53 |   55859 |  17456 |       |       |          |
-----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------

2nd run statistics and explain plan

buffer is not pinned count	6479281
buffer is pinned count	1448247
bytes received via SQL*Net from client	11558
bytes sent via SQL*Net to client	3280668
Cached Commit SCN referenced	829880
calls to get snapshot scn: kcmgss	2019248
calls to kcmgas	0
calls to kcmgcs	0
CCursor + sql area evicted	0
cell physical IO interconnect bytes	158302208
cleanout - number of ktugct calls	0
cleanouts only - consistent read gets	0
cluster key scan block gets	2
cluster key scans	1
commit cleanouts	0
commit cleanouts successfully completed	0
Commit SCN cached	0
commit txn count during cleanout	0
consistent gets	9429530
consistent gets - examination	5655308
consistent gets from cache	9429530
consistent gets from cache (fastpath)	1823067
CPU used by this session	14524
CPU used when call started	14524
cursor authentications	1
db block changes	0
db block gets	0
db block gets from cache	0
DB time	14959
deferred (CURRENT) block cleanout applications	0
dirty buffers inspected	164
enqueue releases	1
enqueue requests	1
execute count	2019249
file io wait time	8926998
free buffer inspected	276839
free buffer requested	271806
hot buffers moved to head of LRU	54014
HSC Heap Segment Block Changes	0
immediate (CR) block cleanout applications	0
index fetch by key	805313
index scans kdiixs1	2126835
logical read bytes from cache	-125403136
logons cumulative	0
logons current	0
messages sent	0
min active SCN optimization applied on CR	94680
no buffer to keep pinned count	38
no work - consistent read gets	3774108
non-idle wait count	272235
non-idle wait time	894
opened cursors cumulative	2019249
opened cursors current	1
parse count (failures)	0
parse count (hard)	3
parse count (total)	5
parse time cpu	0
parse time elapsed	0
physical read bytes	158302208
physical read IO requests	271806
physical read total bytes	158302208
physical read total IO requests	271806
physical reads	271806
physical reads cache	271806
pinned buffers inspected	3
pinned cursors current	0
prefetched blocks aged out before use	9
process last non-idle time	0
recursive calls	2019258
recursive cpu usage	10192
redo entries	0
redo size	0
redo synch time (usec)	0
redo synch writes	0
Requests to/from client	48
rows fetched via callback	778740
session connect time	0
session cursor cache count	5
session cursor cache hits	-12372
session logical reads	9429530
session pga memory	-1589920
session pga memory max	5619040
session uga memory	-196464
session uga memory max	523904
shared hash latch upgrades - no wait	25192
sorts (memory)	2045816
sorts (rows)	656653
sql area evicted	0
sql area purged	0
SQL*Net roundtrips to/from client	49
table fetch by rowid	2511965
table fetch continued row	2
table scan blocks gotten	0
table scan rows gotten	0
table scans (short tables)	0
undo change vector size	0
user calls	51
user I/O wait time	892
workarea executions - optimal	568689
workarea memory allocated	-66


Plan hash value: 2966358639
-----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
| Id  | Operation                      | Name                     | Starts | E-Rows |E-Bytes| Cost (%CPU)| E-Time   | A-Rows |   A-Time   | Buffers | Reads  |  OMem |  1Mem | Used-Mem |
-----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
|   0 | SELECT STATEMENT               |                          |      1 |        |       |    18 (100)|          |  26569 |00:02:29.56 |    9429K|    271K|       |       |          |
|   1 |  TABLE ACCESS BY INDEX ROWID   | INDVL                    |  26569 |      1 |    29 |     1   (0)| 00:00:01 |  26569 |00:00:02.59 |   79713 |  14640 |       |       |          |
|*  2 |   INDEX UNIQUE SCAN            | XPKINDVL                 |  26569 |      1 |       |     1   (0)| 00:00:01 |  26569 |00:00:01.61 |   53143 |    870 |       |       |          |
|   3 |  SORT GROUP BY                 |                          |  26569 |      1 |    16 |            |          |  26569 |00:00:00.47 |   56251 |   1483 |  2048 |  2048 | 2048  (0)|
|*  4 |   TABLE ACCESS BY INDEX ROWID  | OCRN                     |  26569 |      1 |    16 |     1   (0)| 00:00:01 |   3687 |00:00:00.34 |   56251 |   1483 |       |       |          |
|*  5 |    INDEX RANGE SCAN            | XIE1OCRN                 |  26569 |      1 |       |     1   (0)| 00:00:01 |   3687 |00:00:00.27 |   53149 |    163 |       |       |          |
|   6 |  SORT AGGREGATE                |                          |  26569 |      1 |    13 |            |          |  26569 |00:00:00.20 |   27157 |    182 |       |       |          |
|*  7 |   TABLE ACCESS BY INDEX ROWID  | INDVL_RGSTN_DFCNY        |  26569 |      1 |    13 |     1   (0)| 00:00:01 |   1540 |00:00:00.17 |   27157 |    182 |       |       |          |
|*  8 |    INDEX RANGE SCAN            | XIF1188INDVL_RGSTN_DFCNY |  26569 |      1 |       |     1   (0)| 00:00:01 |   1540 |00:00:00.15 |   26638 |      9 |       |       |          |
|   9 |  NESTED LOOPS                  |                          |  26569 |      1 |    43 |     2   (0)| 00:00:01 |  26569 |00:00:00.26 |   79717 |      0 |       |       |          |
|  10 |   TABLE ACCESS BY INDEX ROWID  | INDVL                    |  26569 |      1 |    17 |     1   (0)| 00:00:01 |  26569 |00:00:00.15 |   79713 |      0 |       |       |          |
|* 11 |    INDEX UNIQUE SCAN           | XPKINDVL                 |  26569 |      1 |       |     1   (0)| 00:00:01 |  26569 |00:00:00.09 |   53143 |      0 |       |       |          |
|* 12 |   INDEX UNIQUE SCAN            | PK$CE_ST_TBL             |  26569 |      7 |   182 |     1   (0)| 00:00:01 |  26569 |00:00:00.06 |       4 |      0 |       |       |          |
|  13 |  TABLE ACCESS BY INDEX ROWID   | H230_INDV_PRS_INFO       |  26569 |      1 |     8 |     1   (0)| 00:00:01 |  26555 |00:00:05.06 |     509K|    134K|       |       |          |
|* 14 |   INDEX UNIQUE SCAN            | XPKH230_INDV_PRS_INFO    |  26569 |      1 |       |     1   (0)| 00:00:01 |  26555 |00:00:04.70 |     482K|    124K|       |       |          |
|  15 |    SORT AGGREGATE              |                          |  26569 |      1 |    21 |            |          |  26569 |00:00:04.41 |     429K|    123K|       |       |          |
|* 16 |     TABLE ACCESS BY INDEX ROWID| H000_TRANS               |  26569 |      1 |    21 |     2   (0)| 00:00:01 |    171K|00:00:04.28 |     429K|    123K|       |       |          |
|* 17 |      INDEX RANGE SCAN          | XIF1032H000_TRANS        |  26569 |      6 |       |     1   (0)| 00:00:01 |    380K|00:00:00.69 |   53706 |   9802 |       |       |          |
|  18 |  SORT ORDER BY                 |                          |      1 |     20 |  1600 |    18   (6)| 00:00:01 |  26569 |00:02:29.56 |    9429K|    271K|  9195K|  1077K| 8173K (0)|
|  19 |   NESTED LOOPS SEMI            |                          |      1 |     20 |  1600 |    17   (0)| 00:00:01 |  26569 |00:00:02.98 |   96543 |  30427 |       |       |          |
|  20 |    NESTED LOOPS                |                          |      1 |     20 |  1220 |     5   (0)| 00:00:01 |  27883 |00:00:03.06 |    8665 |   7776 |       |       |          |
|  21 |     TABLE ACCESS BY INDEX ROWID| ORG_HDR                  |      1 |      1 |    33 |     1   (0)| 00:00:01 |      1 |00:00:00.01 |       3 |      0 |       |       |          |
|* 22 |      INDEX UNIQUE SCAN         | XPKORG_HDR               |      1 |      1 |       |     1   (0)| 00:00:01 |      1 |00:00:00.01 |       2 |      0 |       |       |          |
|  23 |     TABLE ACCESS BY INDEX ROWID| INDVL_FIRM_ASCTN         |      1 |     20 |   560 |     4   (0)| 00:00:01 |  27883 |00:00:03.04 |    8662 |   7776 |       |       |          |
|* 24 |      INDEX RANGE SCAN          | XIE2INDVL_FIRM_ASCTN     |      1 |     20 |       |     1   (0)| 00:00:01 |  27883 |00:00:00.03 |      62 |     59 |       |       |          |
|* 25 |    TABLE ACCESS BY INDEX ROWID | INDVL_RGSTN              |  27883 |    199 |  3781 |     1   (0)| 00:00:01 |  26569 |00:00:01.13 |   87878 |  22651 |       |       |          |
|* 26 |     INDEX RANGE SCAN           | XPKINDVL_RGSTN           |  27883 |      1 |       |     1   (0)| 00:00:01 |  70914 |00:00:00.70 |   55859 |  12815 |       |       |          |
-----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------

This post has been answered by spur230 on May 26 2015

Jump to Answer

Locked Post

New comments cannot be posted to this locked post.

Locked on Jun 23 2015

Added on May 22 2015

#11g, #general-database-discussions, #performance, #sql

10 comments

12,871 views