Re: More tests [Was: Problem with read blocking for a long time on /dev/scd1]

Re: More tests [Was: Problem with read blocking for a long time on /dev/scd1]

[Andrey Borzenkov]

> I've done some more tests:
>
> The problem still occurs with straight ide drivers, no ide-scsi
>
> The problem still occurs with 2.4.20-ac2
>
> I removed extraneous llseek syscalls from libdvdread, it's now reading
> purely sequentially and still failing. I doubt an llseek to the current
> location even gets through to the driver but I figured I would remove
> another variable.
> 
> Question: Does the readahead parameter in hdparm affect accesses to the
> raw /dev/hdd device? Does it affect atapi cdrom access?

I have seen the same phenomenon under slightly different conditions.

I am running Mandrake with supermount. In short, supermount fakes mounting device and then mounts real device on first access. On every file operation it checks for media change and invalidates and remounts media in this case.

In some cases, the best example being rpm -Uvh * on CD, this command lasts ages. The reason is long pause during file closing, as much as 5 seconds (in my case), so it takes very long time to examine all files. The device is pure IDE DVD-R (Creative) running in UDMA2 on i815e. I put timing information in ide-cd.c and ide.c and it shows that pause happens between ide_do_drive_cmd called from cdrom_queue_packet_command (from cdrom_check_status) and next corresponding ide_do_request (unfortunately, the log output happened inside of it, when request is already fetched).

Some strange things to observe: 

- this delay happens only during file close, while there are much more checks for media changes (every operation on supermount fs does it), the delayed ones are probably just 10% at most

- there is always a READ request being processed between ide_do_drive_cmd and ide_do_request; the actual delay happens between ide_do_drive_cmd and this READ request; I am going to trace all requests to CD_ROM to see when READ is generated

- when I try the above during relatively high disk activity, this usually works normally (i.e. without delays); OTOH when system is mostly idle I get these delays. I have pure IDE system, HD is on one channel, DVD in question on the other. I thought it may be related to DMA (packet commands are run with DMA disabled) but disabling DMA did not change anything.

The problem is old, it existed at least in 2.4.18 that shipped in Mandrake. Currently Mandrake is on 2.4.20 with the same problem.

I will do some tests to pinpoint the place where delays happen; I have not looked at ps output, but if delay happens in ide_do_request, there should not be many possibilities.

Regards

-andrej

Problem with read blocking for a long time on /dev/scd1

[Gregory Stark]

I'm having a problem with ogle that seems to be being caused by the scsi or
ide-scsi driver. The video playback freezes for a second or randomly,
sometimes every few seconds, sometimes not for several minutes. Every such
glitch is correlated perfectly with a read syscall reading on /dev/scd1
blocking for an inordinate amount of time.

Most read syscalls from ogle seem to take between 30us to 100ms depending on
the size of the read. In fact plotting the time taken reported by strace -T vs
the size of the read in gnuplot produces a nice obvious linear correlation.

However occasionally there are outlier samples where the read call blocks for
between 150ms up to 1s or more. I've seen it block for about 10s once.

I've tried this on a machine that was essentially in single-user mode. The
only processes running were X, ogle, an xterm, and not much else. I'll include
my normal lsmod output below but the problem still occurred when playing with
hardly any modules loaded.

There's an FAQ about ogle glitching like this when something tries to probe
the cd drive, but nothing like that is running. And the glitches aren't
periodic like that FAQ describes.

The problem is definitely that the kernel simply doesn't schedule the process
calling read for over a second. 

There are no dmesg messages or other indication of problems in the ide-scsi or scsi
drivers.

Where would I start to track down what is preventing the kernel from
scheduling this process? It's presumably some problem in the ide or ide-scsi
driver, but I'm not sure where to start.

[I'm having trouble sending messages to the list, my ISPs mail server didn't
seem to deliver it the first time. My apologies if it finally makes it through
and this is a duplicate]

--
greg

Re: Problem with read blocking for a long time on /dev/scd1

[Greg Stark]

Gregory Stark <gsstark@MIT.EDU> writes:

> I'm having a problem with ogle that seems to be being caused by the scsi or
> ide-scsi driver. The video playback freezes for a second or randomly,
> sometimes every few seconds, sometimes not for several minutes. Every such
> glitch is correlated perfectly with a read syscall reading on /dev/scd1
> blocking for an inordinate amount of time.
> 
> Most read syscalls from ogle seem to take between 30us to 100ms depending on
> the size of the read. In fact plotting the time taken reported by strace -T vs
> the size of the read in gnuplot produces a nice obvious linear correlation.

One more piece of data I just found. Whenever the read blocks for a long time
like this it seems ps lists the process's wait channel as "lock_p". The only
matching symbol is lock_page. 

Does that help narrow down the source of the latency or is that just what the
device driver happens to use as its synchronization primitive?

--
greg

More tests [Was: Problem with read blocking for a long time on /dev/scd1]

[Greg Stark]

I've done some more tests:

The problem still occurs with straight ide drivers, no ide-scsi

The problem still occurs with 2.4.20-ac2

I removed extraneous llseek syscalls from libdvdread, it's now reading purely
sequentially and still failing. I doubt an llseek to the current location even
gets through to the driver but I figured I would remove another variable.

Question: Does the readahead parameter in hdparm affect accesses to the raw
/dev/hdd device? Does it affect atapi cdrom access?

-- 
greg

Re: More tests [Was: Problem with read blocking for a long time on /dev/scd1]

[Jakob Oestergaard]

On Sun, Dec 22, 2002 at 11:13:14AM -0500, Greg Stark wrote:
> 
> I've done some more tests:
> 
> The problem still occurs with straight ide drivers, no ide-scsi
> 
> The problem still occurs with 2.4.20-ac2

Can you reproduce on 2.4.18 or 2.4.19-pre5 ?

AFAIK 2.4.X broke at 2.4.19-pre6 - something was changed that related to
the order in which read requests are scheduled.

I have a file-server here which also blocks on reads for as long as 5-10
seconds at a time - in particular when the nightly backup runs.

It's a PITA for those of us who're hit by it (imagine working in an
emacs that freezes up for 10 seconds every 10 minutes). But not a lot of
people have complained, so nobody has (again to my knowledge - please
correct if I'm mistaken) come up with a solution that was not just a
hack that for some reason which noone understands, seems to make the
problem appear less.

I would *so* love to be corrected on that one  ;)

> 
> I removed extraneous llseek syscalls from libdvdread, it's now reading purely
> sequentially and still failing. I doubt an llseek to the current location even
> gets through to the driver but I figured I would remove another variable.

Writes stall reads "almost indefinitely". It's a "feature".

If you can reproduce this in 2.4.18 (which was "invincible" as
file-server kernel for me, except that I needed newer IDE drivers for a
new Promise card and therefore had to make the switch), then I'm
completely mistaken and my ramblings have nothing to do with what you're
seeing.

Please try reproducing on 2.4.18, to confirm or deny.

> Question: Does the readahead parameter in hdparm affect accesses to the raw
> /dev/hdd device? Does it affect atapi cdrom access?

Nothing tunable cures the problem - if it is indeed the same problem you
are hit by.

-- 
................................................................
:   jakob@unthought.net   : And I see the elder races,         :
:.........................: putrid forms of man                :
:   Jakob Østergaard      : See him rise and claim the earth,  :
:        OZ9ABN           : his downfall is at hand.           :
:.........................:............{Konkhra}...............:

Re: More tests [Was: Problem with read blocking for a long time on /dev/scd1]

[Greg Stark]

Jakob Oestergaard <jakob@unthought.net> writes:

> On Sun, Dec 22, 2002 at 11:13:14AM -0500, Greg Stark wrote:
> > 
> > I've done some more tests:
> > 
> > The problem still occurs with straight ide drivers, no ide-scsi
> > 
> > The problem still occurs with 2.4.20-ac2
> 
> Can you reproduce on 2.4.18 or 2.4.19-pre5 ?
> 
> AFAIK 2.4.X broke at 2.4.19-pre6 - something was changed that related to
> the order in which read requests are scheduled.

I originally had the problem with 2.4.18 and only updated to 2.4.20-ac2 hoping
it would solve the problem. It doesn't look like the same issue as yours.

When your process is blocked, what wait channel does ps -elf list for it?
What system call does strace -T show it executing and for how long?

I wonder what else is on the ide channels, perhaps if I move things around so
it's the only device on that channel it would help?

-- 
greg

Re: More tests [Was: Problem with read blocking for a long time on /dev/scd1]

[Jakob Oestergaard]

On Mon, Dec 23, 2002 at 03:58:02AM -0500, Greg Stark wrote:
...
> > AFAIK 2.4.X broke at 2.4.19-pre6 - something was changed that related to
> > the order in which read requests are scheduled.
> 
> I originally had the problem with 2.4.18 and only updated to 2.4.20-ac2 hoping
> it would solve the problem. It doesn't look like the same issue as yours.

I agree.

> 
> When your process is blocked, what wait channel does ps -elf list for it?
> What system call does strace -T show it executing and for how long?

I will check this evening when the backup starts.

> I wonder what else is on the ide channels, perhaps if I move things around so
> it's the only device on that channel it would help?

I have four seagate drives, one (master) on each channel of two Promise
adapters.

There's a bunch of other disks in the system as well, but these are the
drives where I notice the problem.

-- 
................................................................
:   jakob@unthought.net   : And I see the elder races,         :
:.........................: putrid forms of man                :
:   Jakob Østergaard      : See him rise and claim the earth,  :
:        OZ9ABN           : his downfall is at hand.           :
:.........................:............{Konkhra}...............:

Re: More tests [Was: Problem with read blocking for a long time on /dev/scd1]

[Jakob Oestergaard]

On Mon, Dec 23, 2002 at 03:58:02AM -0500, Greg Stark wrote:
> Jakob Oestergaard <jakob@unthought.net> writes:
> 
...
> When your process is blocked, what wait channel does ps -elf list for it?
> What system call does strace -T show it executing and for how long?

On the NFS server, knfsd and kupdated will block on "wait_on_b" (WCHAN
in top).

I guess an strace on the NFS client would just show the process waiting
in some open/read/write/close code, waiting for NFS/RPC. Not much good.

The hangs last for approximately 5 seconds, sometimes around 10.

-- 
................................................................
:   jakob@unthought.net   : And I see the elder races,         :
:.........................: putrid forms of man                :
:   Jakob Østergaard      : See him rise and claim the earth,  :
:        OZ9ABN           : his downfall is at hand.           :
:.........................:............{Konkhra}...............: