Re: process running slowly, lots of yield() calls ?

On 21 Nov, 03:52, Steve Howard <stevedhow..._at_gmail.com> wrote:
> On Nov 20, 9:09 am, Andy <andy..._at_gmail.com> wrote:
>
>
>
> > We upgraded database from 9i to 10g at the weekend. One of the
> > processes (whose statement basically consists of an "create table as
> > select etc") is taking +7hrs and still running instead of the more
> > usual 30 mins. OK, I would think that this is a statistics/explain-
> > plan related issue and we have the vendor investigating.
>
> > However, what I am more curious about is the truss output on the
> > spawned oracle process. It's peppered with yield() calls and I'm
> > suspicious. Why would it be running a processor flat out, and yet
> > yielding so much ? Can anyone throw some light on this please ?
>
> > sample:
> > ...
> > yield()                                         = 0
> > times(0xFFFFFFFF7FFF4070)                       = 164268253
> > times(0xFFFFFFFF7FFF3FC0)                       = 164268253
> > yield()                                         = 0
> > yield()                                         = 0
> > pread(268, "0602\0\001 B M A0781F492".., 8192, 0x49A82000) = 8192
> > yield()                                         = 0
> > yield()                                         = 0
> > yield()                                         = 0
> > times(0xFFFFFFFF7FFF4070)                       = 164268870
> > times(0xFFFFFFFF7FFF3FC0)                       = 164268870
> > pread(266, "0602\0\00102 ^9407 pB9B3".., 8192, 0x4BD28000) = 8192
> > yield()                                         = 0
> > yield()                                         = 0
> > yield()                                         = 0
> > yield()                                         = 0
> > yield()                                         = 0
> > yield()                                         = 0
> > yield()                                         = 0
> > yield()                                         = 0
> > yield()                                         = 0
> > yield()                                         = 0
> > ...
>
> > truss -cpf 8881
> > syscall              seconds   calls  errors
> > times                    .00      60
> > yield                    .01     330
> > pread                    .01     163
> >                      -------  ------   ----
> > sys totals:              .02     553      0
> > usr time:             173.64
> > elapsed:              175.24
> > I know times() is used by Oracle to help in its timing statistics, but
> > why the yield() so much ?
>
> > Thanks
>
> > AW
>
> Since it looks like it is reading database blocks (8192 byte reads),
> could the yield calls be in place while waiting for the I/O to
> return?  Are the disks slow?  What is the event in Oracle on which the
> statement is spending the most of its time?  I'm guessing single block
> I/O, unless your multiblock read count is set really low?

Thanks Steve, disks aren't slow at all - statspack shows the following:

Top 5 Timed Events
Avg %Total

Event                                            Waits    Time (s)

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

2,164          38.3
PL/SQL lock timer                                   91       1,333
14651   23.6
db file scattered read                         143,638
898      6   15.9
db file sequential read                        114,111
706      6   12.5
log file parallel write                         12,121         236

LWait Events DB/Inst: LIVE/LIVE Snaps: 21-31 -> s - second, cs - centisecond, ms - millisecond, us - microsecond -> %Timeouts: value of 0 indicates value was < .5%. Value of null is truly 0
-> Only events with Total Wait Time (s) >= .001 are shown -> ordered by Total Wait Time desc, Waits desc (idle events last)  

Avg

                                                %Time Total Wait
wait    Waits
Event                                    Waits  -outs   Time (s)
(ms)     /txn
--------------------------------- ------------ ------ ----------
------ --------
PL/SQL lock timer                           91    100      1,333
14651      0.0
db file scattered read                 143,638      0        898
6     12.7
db file sequential read                114,111      0        706
6     10.1
log file parallel write                 12,121      0        236
19      1.1
log file sync                            8,804      0        219
25      0.8
db file parallel write                   2,677      0         65
24      0.2
control file parallel write                454      0         15
32      0.0
library cache lock                           1      0          2
2252      0.0

Any advice, greatly appreciated. Incidentally, the slow process was a known bug against Oracle10g, but I'm still interested in what the yield ()s mean...

Thanks
AW Received on Fri Nov 21 2008 - 03:24:09 CST