Re: db_file_sequential_reads takes over 7 seconds per seq# change jump for single block read.

On 2 March 2016 at 16:38, Ls Cheng <exriscer_at_gmail.com> wrote:

> hi
>
> have you checked the top sql?
>
> On Wed, Mar 2, 2016 at 10:11 AM, Jithin Sarath <jithinsarath_at_gmail.com>
> 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_at_jlcomp.demon.co.uk>
>> 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
>>> _at_jloracle
>>> ------------------------------
>>> *From:* oracle-l-bounce_at_freelists.org [oracle-l-bounce_at_freelists.org]
>>> on behalf of Jithin Sarath [jithinsarath_at_gmail.com]
>>> *Sent:* 02 March 2016 07:18
>>> *To:* oracle-l_at_freelists.org
>>> *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
>>>
>>
>>
>

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