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

From: Jithin Sarath <jithinsarath_at_gmail.com>
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-l
Received on Wed Mar 02 2016 - 10:11:35 CET

Original text of this message