lkml.org 
[lkml]   [2002]   [Dec]   [23]   [last100]   RSS Feed
Views: [wrap][no wrap]   [headers]  [forward] 
 
Messages in this thread
    /
    Subject2.5.52 process in disk wait for long time reading from cd
    From
    Date

    More info on the problem I reported earlier. I tested kernel 2.5.52 and the
    same problem occurs. Occasionally read syscalls to the DVD device take over a
    second to return.

    The only difference is that the wait channel on 2.4.x is listed as "lock_p"
    but on 2.5.52 it's listed as "io_sch".

    Linux stark.dyndns.tv 2.5.52 #5 Sat Dec 21 12:07:03 EST 2002 i686 unknown unknown GNU/Linux

    The device it's reading from is /dev/hdd. DMA is enabled on all the ide
    devices.

    The following is output from ogle, combined with stracing the process that
    blocks grepping for syscalls taking over a second to return, combined with
    running ps on the same process grepping for it not blocking on msgrcv which is
    the normal synchronization primitive ogle uses.

    As you can see, every time ogle gets out of sync and prints the message about
    "resyncing" it's following ogle_mpeg_ps blocking in a read syscall waiting on
    "io_sch".

    The only suggestion I've heard so far is that the DVD-Rom is bad. But to
    confirm that I would need some data from the ide driver. As it is there are no
    ide errors in the kernel log, no information from the driver on what operation
    was being attempted and took inordinately long to complete. Nothing to report
    to the vendor as evidence of a hardware defect.

    Someone suggested I try raw devices. Is that possible for cdrom devices? Where
    do I find the raw devices?

    display: frame rate: 22.891 fps
    0 T stark 18562 18559 2 76 0 - 2399 syscal 18:24 pts/6 00:00:07 ogle_mpeg_ps -m 32768
    0 D stark 18562 18559 2 75 0 - 2399 io_sch 18:24 pts/6 00:00:07 ogle_mpeg_ps -m 32768
    0 D stark 18562 18559 2 75 0 - 2399 io_sch 18:24 pts/6 00:00:07 ogle_mpeg_ps -m 32768
    0 D stark 18562 18559 2 75 0 - 2399 io_sch 18:24 pts/6 00:00:07 ogle_mpeg_ps -m 32768
    0 D stark 18562 18559 2 75 0 - 2399 io_sch 18:24 pts/6 00:00:07 ogle_mpeg_ps -m 32768
    0 D stark 18562 18559 2 75 0 - 2399 io_sch 18:24 pts/6 00:00:07 ogle_mpeg_ps -m 32768
    read(3, "\0\0\1\272D\32\334\253\345\231\1\211\303\370\0\0\1\340"..., 487424) = 487424 <1.596222>
    Debug[ogle_audio]: 1.+084663240 s off, resyncing
    !0 D stark 18562 18559 2 75 0 - 2399 io_sch 18:24 pts/6 00:00:07 ogle_mpeg_ps -m 32768
    0 D stark 18562 18559 2 75 0 - 2399 io_sch 18:24 pts/6 00:00:07 ogle_mpeg_ps -m 32768
    0 D stark 18562 18559 2 75 0 - 2399 io_sch 18:24 pts/6 00:00:07 ogle_mpeg_ps -m 32768
    0 D stark 18562 18559 2 75 0 - 2399 io_sch 18:24 pts/6 00:00:07 ogle_mpeg_ps -m 32768
    0 D stark 18562 18559 2 75 0 - 2399 io_sch 18:24 pts/6 00:00:07 ogle_mpeg_ps -m 32768
    read(3, "\0\0\1\272D\33\16\373\364\241\1\211\303\370\0\0\1\340\7"..., 532480) = 532480 <1.602640>
    Debug[ogle_audio]: 1.+297135680 s off, resyncing
    display: frame rate: 18.582 fps
    display: frame rate: 23.977 fps
    display: frame rate: 24.000 fps
    0 D stark 18562 18559 2 75 0 - 2399 io_sch 18:24 pts/6 00:00:08 ogle_mpeg_ps -m 32768
    display: frame rate: 23.951 fps
    0 D stark 18562 18559 2 75 0 - 2399 io_sch 18:24 pts/6 00:00:08 ogle_mpeg_ps -m 32768
    0 D stark 18562 18559 2 75 0 - 2399 io_sch 18:24 pts/6 00:00:08 ogle_mpeg_ps -m 32768
    0 D stark 18562 18559 2 75 0 - 2399 io_sch 18:24 pts/6 00:00:08 ogle_mpeg_ps -m 32768
    read(3, "\0\0\1\272D\35^\321\f\361\1\211\303\370\0\0\1\340\7\354"..., 323584) = 323584 <1.287339>
    Debug[ogle_audio]: 0.+879741440 s off, resyncing
    0 T stark 18562 18559 2 76 0 - 2399 syscal 18:24 pts/6 00:00:08 ogle_mpeg_ps -m 32768
    0 D stark 18562 18559 2 75 0 - 2399 io_sch 18:24 pts/6 00:00:08 ogle_mpeg_ps -m 32768
    0 D stark 18562 18559 2 75 0 - 2399 io_sch 18:24 pts/6 00:00:08 ogle_mpeg_ps -m 32768
    0 D stark 18562 18559 2 75 0 - 2399 io_sch 18:24 pts/6 00:00:08 ogle_mpeg_ps -m 32768
    0 D stark 18562 18559 2 75 0 - 2399 io_sch 18:24 pts/6 00:00:08 ogle_mpeg_ps -m 32768
    read(3, "\0\0\1\272D\35\214z\366I\1\211\303\370\0\0\1\340\7\354"..., 323584) = 323584 <1.171526>
    Debug[ogle_audio]: 0.+485963520 s off, resyncing
    read(3, "\0\0\1\272D\35\254\331\356E\1\211\303\370\0\0\1\340\7\354"..., 325632) = 325632 <0.109438>
    0 T stark 18562 18559 2 76 0 - 2399 syscal 18:24 pts/6 00:00:08 ogle_mpeg_ps -m 32768
    0 D stark 18562 18559 2 75 0 - 2399 io_sch 18:24 pts/6 00:00:08 ogle_mpeg_ps -m 32768
    0 D stark 18562 18559 2 75 0 - 2399 io_sch 18:24 pts/6 00:00:08 ogle_mpeg_ps -m 32768
    0 D stark 18562 18559 2 75 0 - 2399 io_sch 18:24 pts/6 00:00:08 ogle_mpeg_ps -m 32768
    read(3, "\0\0\1\272D\35\277\375\324\235\1\211\303\370\0\0\1\340"..., 339968) = 339968 <1.068391>
    Debug[ogle_audio]: 0.+381795280 s off, resyncing
    0 R stark 18562 18559 2 76 0 - 2399 - 18:24 pts/6 00:00:08 ogle_mpeg_ps -m 32768
    0 D stark 18562 18559 2 75 0 - 2399 io_sch 18:24 pts/6 00:00:08 ogle_mpeg_ps -m 32768
    0 D stark 18562 18559 2 75 0 - 2399 io_sch 18:24 pts/6 00:00:08 ogle_mpeg_ps -m 32768
    0 D stark 18562 18559 2 75 0 - 2399 io_sch 18:24 pts/6 00:00:08 ogle_mpeg_ps -m 32768
    0 D stark 18562 18559 2 75 0 - 2399 io_sch 18:24 pts/6 00:00:08 ogle_mpeg_ps -m 32768
    read(3, "\0\0\1\272D\35\356\21%\225\1\211\303\370\0\0\1\340\7\354"..., 421888) = 421888 <1.126259>
    Debug[ogle_audio]: 0.+381624160 s off, resyncing
    0 D stark 18562 18559 2 75 0 - 2399 io_sch 18:24 pts/6 00:00:08 ogle_mpeg_ps -m 32768
    0 D stark 18562 18559 2 75 0 - 2399 io_sch 18:24 pts/6 00:00:08 ogle_mpeg_ps -m 32768
    0 D stark 18562 18559 2 75 0 - 2399 io_sch 18:24 pts/6 00:00:08 ogle_mpeg_ps -m 32768
    0 D stark 18562 18559 2 75 0 - 2399 io_sch 18:24 pts/6 00:00:08 ogle_mpeg_ps -m 32768
    0 D stark 18562 18559 2 75 0 - 2399 io_sch 18:24 pts/6 00:00:08 ogle_mpeg_ps -m 32768
    read(3, "\0\0\1\272D\36\6\10\315A\1\211\303\370\0\0\1\340\7\354"..., 423936) = 423936 <1.593315>
    Debug[ogle_audio]: 1.+098514880 s off, resyncing
    0 T stark 18562 18559 2 75 0 - 2399 syscal 18:24 pts/6 00:00:08 ogle_mpeg_ps -m 32768
    display: frame rate: 17.287 fps
    0 D stark 18562 18559 2 75 0 - 2399 io_sch 18:24 pts/6 00:00:08 ogle_mpeg_ps -m 32768
    0 D stark 18562 18559 2 75 0 - 2399 io_sch 18:24 pts/6 00:00:08 ogle_mpeg_ps -m 32768
    0 D stark 18562 18559 2 75 0 - 2399 io_sch 18:24 pts/6 00:00:08 ogle_mpeg_ps -m 32768
    0 D stark 18562 18559 2 75 0 - 2399 io_sch 18:24 pts/6 00:00:08 ogle_mpeg_ps -m 32768
    read(3, "\0\0\1\272D\36&%\\\225\1\211\303\370\0\0\1\340\7\354\201"..., 378880) = 378880 <1.295461>
    ##Debug[ogle_audio]: 0.+731835080 s off, resyncing
    0 D stark 18562 18559 2 75 0 - 2399 io_sch 18:24 pts/6 00:00:08 ogle_mpeg_ps -m 32768
    0 D stark 18562 18559 2 75 0 - 2399 io_sch 18:24 pts/6 00:00:08 ogle_mpeg_ps -m 32768
    0 D stark 18562 18559 2 75 0 - 2399 io_sch 18:24 pts/6 00:00:08 ogle_mpeg_ps -m 32768
    0 D stark 18562 18559 2 75 0 - 2399 io_sch 18:24 pts/6 00:00:08 ogle_mpeg_ps -m 32768
    read(3, "\0\0\1\272D\36]\272}\231\1\211\303\370\0\0\1\340\7\354"..., 501760) = 501760 <1.071489>
    ##Debug[ogle_audio]: 0.+521272280 s off, resyncing
    0 T stark 18562 18559 2 76 0 - 2399 syscal 18:24 pts/6 00:00:08 ogle_mpeg_ps -m 32768
    0 D stark 18562 18559 2 75 0 - 2399 io_sch 18:24 pts/6 00:00:08 ogle_mpeg_ps -m 32768
    0 D stark 18562 18559 2 75 0 - 2399 io_sch 18:24 pts/6 00:00:08 ogle_mpeg_ps -m 32768
    0 D stark 18562 18559 2 75 0 - 2399 io_sch 18:24 pts/6 00:00:08 ogle_mpeg_ps -m 32768
    0 D stark 18562 18559 2 75 0 - 2399 io_sch 18:24 pts/6 00:00:08 ogle_mpeg_ps -m 32768
    read(3, "\0\0\1\272D\36tZ\275I\1\211\303\370\0\0\1\340\7\354\201"..., 362496) = 362496 <1.581139>
    ##Debug[ogle_audio]: 1.+038802240 s off, resyncing
    Debug[ogle_audio]: 0.+024722640 s off, resyncing
    0 R stark 18562 18559 2 76 0 - 2399 - 18:24 pts/6 00:00:08 ogle_mpeg_ps -m 32768
    0 D stark 18562 18559 2 75 0 - 2399 io_sch 18:24 pts/6 00:00:08 ogle_mpeg_ps -m 32768
    0 D stark 18562 18559 2 75 0 - 2399 io_sch 18:24 pts/6 00:00:08 ogle_mpeg_ps -m 32768
    0 D stark 18562 18559 2 75 0 - 2399 io_sch 18:24 pts/6 00:00:08 ogle_mpeg_ps -m 32768
    0 D stark 18562 18559 2 75 0 - 2399 io_sch 18:24 pts/6 00:00:08 ogle_mpeg_ps -m 32768
    read(3, "\0\0\1\272D\36}\276\365\361\1\211\303\370\0\0\1\340\7\354"..., 356352) = 356352 <1.438772>
    ##Debug[ogle_audio]: 1.+115369160 s off, resyncing
    read(3, "\0\0\1\272D\36\2070\346E\1\211\303\370\0\0\1\340\7\354"..., 354304) = 354304 <0.136682>
    0 T stark 18562 18559 2 75 0 - 2399 syscal 18:24 pts/6 00:00:08 ogle_mpeg_ps -m 32768
    0 D stark 18562 18559 2 75 0 - 2399 io_sch 18:24 pts/6 00:00:09 ogle_mpeg_ps -m 32768
    0 D stark 18562 18559 2 75 0 - 2399 io_sch 18:24 pts/6 00:00:09 ogle_mpeg_ps -m 32768
    0 D stark 18562 18559 2 75 0 - 2399 io_sch 18:24 pts/6 00:00:09 ogle_mpeg_ps -m 32768
    0 D stark 18562 18559 2 75 0 - 2399 io_sch 18:24 pts/6 00:00:09 ogle_mpeg_ps -m 32768
    0 D stark 18562 18559 2 75 0 - 2399 io_sch 18:24 pts/6 00:00:09 ogle_mpeg_ps -m 32768
    read(3, "\0\0\1\272D\36\2472\6A\1\211\303\370\0\0\1\340\7\354\201"..., 561152) = 561152 <1.575937>
    ##Debug[ogle_audio]: 0.+879007520 s off, resyncing


    --
    greg

    -
    To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
    the body of a message to majordomo@vger.kernel.org
    More majordomo info at http://vger.kernel.org/majordomo-info.html
    Please read the FAQ at http://www.tux.org/lkml/

    \
     
     \ /
      Last update: 2005-03-22 13:31    [W:0.049 / U:2.300 seconds]
    ©2003-2016 Jasper Spaans. hosted at Digital OceanAdvertise on this site