Re: db_file_sequential_reads takes over 7 seconds per seq# change jump for single block read.
Date: Wed, 2 Mar 2016 14:41:35 +0530
Message-ID: <CACoevcqW9ZdUtuij_TPSAiUoEnxnnhoGWo7DdU5TZdoKrQnPGA_at_mail.gmail.com>
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-lReceived on Wed Mar 02 2016 - 10:11:35 CET