There are two obvious (relatively common) ways in which you can use a lot of
CPU while doing not much I/O in the way of I/O to data.
a) You have a CPU intensive hash join
b) You have a very inefficient indexed access path in a nested loop join (e.g.
the optimizer has chosen the wrong index for your query), but most of the data
blocks you have to visit get buffered very early on and are then constantly
revisited.
The fact that your db file sequential read goes high if you keep flushing the
buffer suggests that it's (b).
If you are licensed to access v$active_session_history etc. then you could take
advantage of the dbms_sqltune.report_sql_monitor() procedure to show you where
the time has been spent so far in the execution plan; if you have access to OEM
this is displayed on the SQL Monitor screens in much easier form. You could
also look at Randolf Geist's "Xplan_ash" script which connects the SQL
execution with the related content of v$active_session_history.
Regards
Jonathan Lewis
http://jonathanlewis.wordpress.com
@jloracle
________________________________
From: Jithin Sarath [jithinsarath@xxxxxxxxx]
Sent: 02 March 2016 12:26
To: Ls Cheng
Cc: Jonathan Lewis; oracle-l@xxxxxxxxxxxxx
Subject: Re: db_file_sequential_reads takes over 7 seconds per seq# change jump
for single block read.
Well, this particular SQL has been running for the last 18+ hours. :)
On 2 March 2016 at 16:38, Ls Cheng
<exriscer@xxxxxxxxx<mailto:exriscer@xxxxxxxxx>> wrote:
hi
have you checked the top sql?
On Wed, Mar 2, 2016 at 10:11 AM, Jithin Sarath
<jithinsarath@xxxxxxxxx<mailto:jithinsarath@xxxxxxxxx>> wrote:
Jonathan, as always, you are spot on.
The State is "WAITED SHORT TIME" and the wait_time is -1 always.
I then used Tanel Poder's waitprof.sql and the results are exactly as you
described them
% Total Total Event
Distinct Avg time
SID STATE EVENT P1 Time Time ms
Events ms/Event
------- ------- ----------------------- ----------- ------- ------------
---------- ----------
2543 WORKING On CPU / runqueue 94.35 68688.969
1542 44.545
2543 WAITING db file sequential read file#= 1397 1.26 914.783
285 3.210
2543 WAITING db file sequential read file#= 1461 1.04 757.193
298 2.541
2543 WAITING db file sequential read file#= 1554 1.02 742.909
275 2.701
2543 WAITING db file sequential read file#= 1431 .81 590.168
167 3.534
2543 WAITING db file sequential read file#= 1516 .81 589.651
225 2.621
2543 WAITING db file sequential read file#= 1532 .42 306.845
205 1.497
2543 WAITING db file sequential read file#= 1736 .25 180.449
78 2.313
2543 WAITING db file sequential read file#= 1393 .04 28.538
11 2.594
2543 WAITING db file sequential read file#= 69 .00 .495
1 .495
How do I see what's causing the On CPU / runqueue? I'm on Windows, so the my
normal searching google hasn't helped.
With a background job that flushes the buffer pool every 6 seconds, the above
stats change to the below where the time spent on CPU has gone to 6%. 89% is
spent on DB file seq reads, which I assume are physical reads as I just flushed
the buffer_cache.
% Total Total Event
Distinct Avg time
SID STATE EVENT P1 Time Time ms
Events ms/Event
------- ------- ------------------------ ----------- ------- ------------
---------- ----------
2543 WAITING db file sequential read file#= 1397 16.71 10282.810
7338 1.401
2543 WAITING db file sequential read file#= 1736 16.67 10258.066
6949 1.476
2543 WAITING db file sequential read file#= 1532 12.81 7879.020
4484 1.757
2543 WAITING db file sequential read file#= 1431 12.61 7760.613
4550 1.706
2543 WAITING db file sequential read file#= 1461 12.05 7410.447
4816 1.539
2543 WAITING db file sequential read file#= 1554 11.10 6828.972
4870 1.402
2543 WAITING db file sequential read file#= 1516 10.74 6609.912
4760 1.389
2543 WORKING On CPU / runqueue 6.97 4290.829
37705 .114
2543 WAITING db file parallel read files= 6 .11 67.998
5 13.600
2543 WAITING db file parallel read files= 7 .04 25.758
4 6.440
2543 WAITING db file sequential read file#= 9 .04 22.215
14 1.587
2543 WAITING db file parallel read files= 5 .03 21.187
1 21.187
2543 WAITING db file parallel read files= 2 .03 18.776
3 6.259
2543 WAITING db file sequential read file#= 69 .03 17.398
4 4.349
2543 WAITING db file sequential read file#= 19 .02 11.258
8 1.407
2543 WAITING db file sequential read file#= 895 .02 9.714
16 .607
2543 WAITING db file parallel read files= 3 .01 4.608
4 1.152
2543 WAITING db file sequential read file#= 1393 .00 .418
1 .418
Regards, Jithin
On 2 March 2016 at 13:56, Jonathan Lewis
<jonathan@xxxxxxxxxxxxxxxxxx<mailto:jonathan@xxxxxxxxxxxxxxxxxx>> wrote:
This means you spend some time waiting for a db file sequential read and then
spend 6 or 7 seconds on CPU.
The column seconds_in_wait would be better named "second since this wait
started" - you need to look at STATE and WAIT_TIME to find out if the session
is still waiting, and how long it waited for if it isn't.
Better still, look at v$session_wait_history to get information on the last 10
waits for the session; even better - if you are licensed to view
v$active_session_history, check the per-second history for the session and
you'll probably get 6 or 7 explcit "ON CPU" rows for the time you've
interpreted as wait time.
Regards
Jonathan Lewis
http://jonathanlewis.wordpress.com
@jloracle
________________________________
From: oracle-l-bounce@xxxxxxxxxxxxx<mailto:oracle-l-bounce@xxxxxxxxxxxxx>
[oracle-l-bounce@xxxxxxxxxxxxx<mailto:oracle-l-bounce@xxxxxxxxxxxxx>] on behalf
of Jithin Sarath [jithinsarath@xxxxxxxxx<mailto:jithinsarath@xxxxxxxxx>]
Sent: 02 March 2016 07:18
To: oracle-l@xxxxxxxxxxxxx<mailto:oracle-l@xxxxxxxxxxxxx>
Subject: db_file_sequential_reads takes over 7 seconds per seq# change jump for
single block read.
All, I have a strange problem and need guidance.
I support databases for Oracle E-Business Suite, and in one of our production
instances, a job is long running. This in itself is not new, but what perplexes
me is that when I look at v$session_waits for this session, I see that the
seconds_in_wait climbs to 6 or 7 per db_file_sequential_read. Once it reached
this situation, the seq# will increment slowly as opposed to quick jumps in
1000s.
If I flush the buffer_cache, the processing speeds up and after a while it hit
the slow db_file_sequential_reads again. Other DB session do not show this
problem. I tried to dump the blocks that are referenced when it is slow, and it
points to one of the tow indexes. When I query the table directly using the
index, the results are quick. The execution plan doesn't show any "outliers"
and the expected execution is < 2 sections.
How do I explain this?
Thanks in advance, Jithin
