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

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}...............:

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]

[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 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}...............:

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