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!

snapper: "cpu + waits != DB time" means cpu starvation?

Joaquin GonzalezNov 18 2014 — edited Nov 21 2014

Hi,

Oracle Database 11g Enterprise Edition Release 11.2.0.3.0 - 64bit Production

I'm using snapper (Tanel Poder's blog: Core IT for Geeks and Pros) to guess what is doing a specific session:

@snapper all 10 1 7

Sampling SID 7 with interval 10 seconds, taking 1 snapshots...

-- Session Snapper v4.03 BETA - by Tanel Poder ( http://blog.tanelpoder.com ) - Enjoy the Most Advanced Oracle Troubleshooting Script on the Planet!

-------------------------------------------------------------------------------------------------------------------------------------------------------

SID @INST, USERNAME , TYPE, STATISTIC , DELTA, HDELTA/SEC, %TIME, GRAPH , NUM_WAITS,

-------------------------------------------------------------------------------------------------------------------------------------------------------

7 @1, US_BATCH , STAT, opened cursors cumulative , 71, 7,31, , , ,

7 @1, US_BATCH , STAT, recursive calls , 71, 7,31, , , ,

7 @1, US_BATCH , STAT, recursive cpu usage , 184, 18,94, , , ,

7 @1, US_BATCH , STAT, session logical reads , 246502, 25,37k, , , ,

7 @1, US_BATCH , STAT, CPU used by this session , 186, 19,14, , , ,

7 @1, US_BATCH , STAT, concurrency wait time , 10, 1,03, , , ,

7 @1, US_BATCH , STAT, user I/O wait time , 36, 3,71, , , ,

7 @1, US_BATCH , STAT, non-idle wait time , 48, 4,94, , , ,

7 @1, US_BATCH , STAT, non-idle wait count , 396, 40,76, , , ,

7 @1, US_BATCH , STAT, in call idle wait time , 4, ,41, , , ,

7 @1, US_BATCH , STAT, session uga memory , 320808, 33,02k, , , ,

7 @1, US_BATCH , STAT, messages sent , 20, 2,06, , , ,

7 @1, US_BATCH , STAT, enqueue requests , 26, 2,68, , , ,

7 @1, US_BATCH , STAT, enqueue releases , 27, 2,78, , , ,

7 @1, US_BATCH , STAT, global enqueue gets sync , 44, 4,53, , , ,

7 @1, US_BATCH , STAT, global enqueue releases , 45, 4,63, , , ,

7 @1, US_BATCH , STAT, physical read total IO requests , 2, ,21, , , ,

7 @1, US_BATCH , STAT, physical read total bytes , 32768, 3,37k, , , ,

7 @1, US_BATCH , STAT, physical write total IO requests , 4, ,41, , , ,

7 @1, US_BATCH , STAT, physical write total bytes , 81920, 8,43k, , , ,

7 @1, US_BATCH , STAT, cell physical IO interconnect bytes , 196608, 20,24k, , , ,

7 @1, US_BATCH , STAT, gcs messages sent , 3, ,31, , , ,

7 @1, US_BATCH , STAT, db block gets , 160, 16,47, , , ,

7 @1, US_BATCH , STAT, db block gets from cache , 155, 15,95, , , ,

7 @1, US_BATCH , STAT, db block gets from cache (fastpath) , 46, 4,73, , , ,

7 @1, US_BATCH , STAT, db block gets direct , 5, ,51, , , ,

7 @1, US_BATCH , STAT, consistent gets , 246505, 25,37k, , , ,

7 @1, US_BATCH , STAT, consistent gets from cache , 246509, 25,37k, , , ,

7 @1, US_BATCH , STAT, consistent gets from cache (fastpath) , 175274, 18,04k, , , ,

7 @1, US_BATCH , STAT, consistent gets - examination , 71233, 7,33k, , , ,

7 @1, US_BATCH , STAT, logical read bytes from cache , 4041572352, 415,98M, , , ,

7 @1, US_BATCH , STAT, physical reads , 2, ,21, , , ,

7 @1, US_BATCH , STAT, physical reads cache , 2, ,21, , , ,

7 @1, US_BATCH , STAT, physical read IO requests , 2, ,21, , , ,

7 @1, US_BATCH , STAT, physical read bytes , 32768, 3,37k, , , ,

7 @1, US_BATCH , STAT, db block changes , 143, 14,72, , , ,

7 @1, US_BATCH , STAT, physical writes , 5, ,51, , , ,

7 @1, US_BATCH , STAT, physical writes direct , 5, ,51, , , ,

7 @1, US_BATCH , STAT, physical write IO requests , 4, ,41, , , ,

7 @1, US_BATCH , STAT, physical write bytes , 81920, 8,43k, , , ,

7 @1, US_BATCH , STAT, physical writes non checkpoint , 5, ,51, , , ,

7 @1, US_BATCH , STAT, change write time , 3, ,31, , , ,

7 @1, US_BATCH , STAT, free buffer requested , 6, ,62, , , ,

7 @1, US_BATCH , STAT, commit cleanouts , 13, 1,34, , , ,

7 @1, US_BATCH , STAT, commit cleanouts successfully completed , 13, 1,34, , , ,

7 @1, US_BATCH , STAT, switch current to new buffer , 4, ,41, , , ,

7 @1, US_BATCH , STAT, physical writes direct (lob) , 5, ,51, , , ,

7 @1, US_BATCH , STAT, shared hash latch upgrades - no wait , 4, ,41, , , ,

7 @1, US_BATCH , STAT, calls to kcmgcs , 20, 2,06, , , ,

7 @1, US_BATCH , STAT, calls to kcmgas , 21, 2,16, , , ,

7 @1, US_BATCH , STAT, calls to get snapshot scn: kcmgss , 99, 10,19, , , ,

7 @1, US_BATCH , STAT, redo entries , 96, 9,88, , , ,

7 @1, US_BATCH , STAT, redo size , 141732, 14,59k, , , ,

7 @1, US_BATCH , STAT, redo size for direct writes , 82100, 8,45k, , , ,

7 @1, US_BATCH , STAT, redo ordering marks , 5, ,51, , , ,

7 @1, US_BATCH , STAT, redo subscn max counts , 1, ,1, , , ,

7 @1, US_BATCH , STAT, file io wait time , 260061, 26,77k, , , ,

7 @1, US_BATCH , STAT, gc local grants , 3, ,31, , , ,

7 @1, US_BATCH , STAT, gc remote grants , 3, ,31, , , ,

7 @1, US_BATCH , STAT, undo change vector size , 24240, 2,49k, , , ,

7 @1, US_BATCH , STAT, no work - consistent read gets , 176846, 18,2k, , , ,

7 @1, US_BATCH , STAT, immediate (CURRENT) block cleanout applications , 3, ,31, , , ,

7 @1, US_BATCH , STAT, deferred (CURRENT) block cleanout applications , 5, ,51, , , ,

7 @1, US_BATCH , STAT, commit txn count during cleanout , 1, ,1, , , ,

7 @1, US_BATCH , STAT, active txn count during cleanout , 3, ,31, , , ,

7 @1, US_BATCH , STAT, cleanout - number of ktugct calls , 3, ,31, , , ,

7 @1, US_BATCH , STAT, table scans (short tables) , 8, ,82, , , ,

7 @1, US_BATCH , STAT, table scan rows gotten , 54272, 5,59k, , , ,

7 @1, US_BATCH , STAT, table scan blocks gotten , 152, 15,64, , , ,

7 @1, US_BATCH , STAT, table fetch by rowid , 118879, 12,24k, , , ,

7 @1, US_BATCH , STAT, table fetch continued row , 3245, 333,99, , , ,

7 @1, US_BATCH , STAT, rows fetched via callback , 58439, 6,01k, , , ,

7 @1, US_BATCH , STAT, leaf node splits , 1, ,1, , , ,

7 @1, US_BATCH , STAT, leaf node 90-10 splits , 1, ,1, , , ,

7 @1, US_BATCH , STAT, lob writes , 4, ,41, , , ,

7 @1, US_BATCH , STAT, lob writes unaligned , 4, ,41, , , ,

7 @1, US_BATCH , STAT, index fetch by key , 58450, 6,02k, , , ,

7 @1, US_BATCH , STAT, index scans kdiixs1 , 14, 1,44, , , ,

7 @1, US_BATCH , STAT, HSC Heap Segment Block Changes , 22, 2,26, , , ,

7 @1, US_BATCH , STAT, session cursor cache hits , 59, 6,07, , , ,

7 @1, US_BATCH , STAT, buffer is pinned count , 101399, 10,44k, , , ,

7 @1, US_BATCH , STAT, buffer is not pinned count , 150506, 15,49k, , , ,

7 @1, US_BATCH , STAT, workarea memory allocated , -465, -47,86, , , ,

7 @1, US_BATCH , STAT, workarea executions - optimal , 13, 1,34, , , ,

7 @1, US_BATCH , STAT, execute count , 59, 6,07, , , ,

7 @1, US_BATCH , STAT, bytes sent via SQL*Net to dblink , 980, 100,87, , , ,

7 @1, US_BATCH , STAT, bytes received via SQL*Net from dblink , 12, 1,24, , , ,

7 @1, US_BATCH , STAT, SQL*Net roundtrips to/from dblink , 3, ,31, , , ,

7 @1, US_BATCH , STAT, sorts (memory) , 6, ,62, , , ,

7 @1, US_BATCH , STAT, sorts (rows) , 92, 9,47, , , ,

7 @1, US_BATCH , TIME, repeated bind elapsed time , 44, 4,53us, .0%, [ ], ,

7 @1, US_BATCH , TIME, PL/SQL execution elapsed time , 151993, 15,64ms, 1.6%, [# ], ,

7 @1, US_BATCH , TIME, DB CPU , 2386412, 245,62ms, 24.6%, [@@@ ], ,

7 @1, US_BATCH , TIME, sql execute elapsed time , 10065556, 1,04s, 103.6%, [##########], ,

7 @1, US_BATCH , TIME, DB time , 10065556, 1,04s, 103.6%, [##########], ,

7 @1, US_BATCH , TIME, sequence load elapsed time , 7580, 780,18us, .1%, [ ], ,

7 @1, US_BATCH , WAIT, latch: cache buffers chains , 261, 26,86us, .0%, [ ], 1,

7 @1, US_BATCH , WAIT, db file sequential read , 260061, 26,77ms, 2.7%, [W ], 2,

7 @1, US_BATCH , WAIT, gc cr grant 2-way , 515, 53,01us, .0%, [ ], 1,

7 @1, US_BATCH , WAIT, gc current grant 2-way , 256, 26,35us, .0%, [ ], 1,

7 @1, US_BATCH , WAIT, gc current grant busy , 292, 30,05us, .0%, [ ], 1,

7 @1, US_BATCH , WAIT, direct path write , 4624, 475,93us, .0%, [ ], 3,

7 @1, US_BATCH , WAIT, row cache lock , 1035, 106,53us, .0%, [ ], 12,

7 @1, US_BATCH , WAIT, latch: shared pool , 95594, 9,84ms, 1.0%, [W ], 3,

7 @1, US_BATCH , WAIT, BFILE read , 117, 12,04us, .0%, [ ], 5,

7 @1, US_BATCH , WAIT, utl_file I/O , 92538, 9,52ms, 1.0%, [W ], 346,

7 @1, US_BATCH , WAIT, External Procedure call , 331, 34,07us, .0%, [ ], 4,

7 @1, US_BATCH , WAIT, HS message to agent , 55683, 5,73ms, .6%, [W ], 8,

7 @1, US_BATCH , WAIT, events in waitclass Other , 8513, 876,2us, .1%, [ ], 20,

-- End of Stats snap 1, end=2014-11-18 16:58:49, seconds=9,7

----------------------------------------------------------------------------------------------------

----------------------------------------------------------------------------------------------------

92% | 1 | ghxd2trbvvubg | 0 | ON CPU | ON CPU

2% | 1 | 67w54h1j9gj0q | 1 | db file sequential read | User I/O

2% | 1 | 67w54h1j9gj0q | 1 | ON CPU | ON CPU

2% | 1 | gtnwbkt3bastt | 0 | utl_file I/O | User I/O

1% | 1 | | | latch: shared pool | Concurrency

-- End of ASH snap 1, end=2014-11-18 16:58:49, seconds=10, samples_taken=93

Normaly DB time ~= total waits + db cpu, isn't it?

As you can see that's not the case shown. What could it mean? cpu starvation? process swapping?

Any clue?

Thanks.

Locked Post

New comments cannot be posted to this locked post.

Locked on Dec 19 2014

Added on Nov 18 2014

#general-database-discussions

8 comments

1,831 views