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
Gregory Stark <[email protected]> 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.
I forgot to include the details:
$ uname -a
Linux stark.dyndns.tv 2.4.19 #6 Tue Sep 10 22:08:51 EDT 2002 i686 unknown unknown GNU/Linux
/dev/hdd:
HDIO_GET_MULTCOUNT failed: Input/output error
IO_support = 0 (default 16-bit)
unmaskirq = 0 (off)
using_dma = 1 (on)
keepsettings = 0 (off)
readonly = 0 (off)
BLKRAGET failed: Input/output error
HDIO_GETGEO failed: Invalid argument
(that's the same for /dev/hd{a,b,c,d} actually)
$ cat /proc/scsi/scsi
Attached devices:
Host: scsi0 Channel: 00 Id: 00 Lun: 00
Vendor: YAMAHA Model: CRW2100E Rev: 1.0G
Type: CD-ROM ANSI SCSI revision: 02
Host: scsi0 Channel: 00 Id: 01 Lun: 00
Vendor: LG Model: DVD-ROM DRD8160B Rev: 1.01
Type: CD-ROM ANSI SCSI revision: 02
$ dmesg
Linux version 2.4.19 ([email protected]) (gcc version 2.95.4 20011002 (Debian prerelease)) #6 Tue Sep 10 22:08:51 EDT 2002
BIOS-provided physical RAM map:
BIOS-e820: 0000000000000000 - 000000000009fc00 (usable)
BIOS-e820: 000000000009fc00 - 00000000000a0000 (reserved)
BIOS-e820: 00000000000f0000 - 0000000000100000 (reserved)
BIOS-e820: 0000000000100000 - 000000000fff0000 (usable)
BIOS-e820: 000000000fff0000 - 000000000fff3000 (ACPI NVS)
BIOS-e820: 000000000fff3000 - 0000000010000000 (ACPI data)
BIOS-e820: 00000000ffff0000 - 0000000100000000 (reserved)
255MB LOWMEM available.
Advanced speculative caching feature not present
On node 0 totalpages: 65520
zone(0): 4096 pages.
zone(1): 61424 pages.
zone(2): 0 pages.
Kernel command line: BOOT_IMAGE=linux-2.4.19 ro root=302 console=ttyS1,9600 console=tty0 hdc=ide-scsi hdd=ide-scsi
ide_setup: hdc=ide-scsi
ide_setup: hdd=ide-scsi
Local APIC disabled by BIOS -- reenabling.
Found and enabled local APIC!
Initializing CPU#0
Detected 551.263 MHz processor.
Console: colour VGA+ 80x50
Calibrating delay loop... 1101.00 BogoMIPS
Memory: 257228k/262080k available (907k kernel code, 4464k reserved, 391k data, 96k init, 0k highmem)
Dentry cache hash table entries: 32768 (order: 6, 262144 bytes)
Inode cache hash table entries: 16384 (order: 5, 131072 bytes)
Mount-cache hash table entries: 4096 (order: 3, 32768 bytes)
Buffer-cache hash table entries: 16384 (order: 4, 65536 bytes)
Page-cache hash table entries: 65536 (order: 6, 262144 bytes)
CPU: Before vendor init, caps: 0383fbff 00000000 00000000, vendor = 0
CPU: L1 I cache: 16K, L1 D cache: 16K
CPU: L2 cache: 256K
CPU: After vendor init, caps: 0383fbff 00000000 00000000 00000000
Intel machine check architecture supported.
Intel machine check reporting enabled on CPU#0.
CPU: After generic, caps: 0383fbff 00000000 00000000 00000000
CPU: Common caps: 0383fbff 00000000 00000000 00000000
CPU: Intel Pentium III (Coppermine) stepping 01
Enabling fast FPU save and restore... done.
Enabling unmasked SIMD FPU exception support... done.
Checking 'hlt' instruction... OK.
POSIX conformance testing by UNIFIX
enabled ExtINT on CPU#0
ESR value before enabling vector: 00000000
ESR value after enabling vector: 00000000
Using local APIC timer interrupts.
calibrating APIC timer ...
..... CPU clock speed is 551.2683 MHz.
..... host bus clock speed is 100.2305 MHz.
cpu: 0, clocks: 1002305, slice: 501152
CPU0<T0:1002304,T1:501152,D:0,S:501152,C:1002305>
mtrr: v1.40 (20010327) Richard Gooch ([email protected])
mtrr: detected mtrr type: Intel
PCI: PCI BIOS revision 2.10 entry at 0xfb2b0, last bus=1
PCI: Using configuration type 1
PCI: Probing PCI hardware
Unknown bridge resource 0: assuming transparent
PCI: Using IRQ router PIIX [8086/7110] at 00:07.0
Limiting direct PCI/PCI transfers.
Linux NET4.0 for Linux 2.4
Based upon Swansea University Computer Society NET3.039
Initializing RT netlink socket
apm: BIOS version 1.2 Flags 0x07 (Driver version 1.16)
Starting kswapd
pty: 256 Unix98 ptys configured
Uniform Multi-Platform E-IDE driver Revision: 6.31
ide: Assuming 33MHz system bus speed for PIO modes; override with idebus=xx
PIIX4: IDE controller on PCI bus 00 dev 39
PIIX4: chipset revision 1
PIIX4: not 100% native mode: will probe irqs later
ide0: BM-DMA at 0xf000-0xf007, BIOS settings: hda:DMA, hdb:DMA
ide1: BM-DMA at 0xf008-0xf00f, BIOS settings: hdc:DMA, hdd:DMA
hdb: C/H/S=38322/16/255 from BIOS ignored
hda: QUANTUM FIREBALL EL7.6A, ATA DISK drive
hdb: MAXTOR 6L080J4, ATA DISK drive
hdc: YAMAHA CRW2100E, ATAPI CD/DVD-ROM drive
hdd: LG DVD-ROM DRD-8160B, ATAPI CD/DVD-ROM drive
ide0 at 0x1f0-0x1f7,0x3f6 on irq 14
ide1 at 0x170-0x177,0x376 on irq 15
hda: 15032115 sectors (7696 MB) w/418KiB Cache, CHS=935/255/63, UDMA(33)
hdb: 156355584 sectors (80054 MB) w/1819KiB Cache, CHS=155114/16/63, UDMA(33)
Partition check:
hda: hda1 hda2 hda3 hda4 < hda5 hda6 >
hdb: hdb1 hdb2 hdb3
es1371: version v0.30 time 19:34:43 Aug 19 2002
PCI: Found IRQ 5 for device 00:0b.0
es1371: found chip, vendor id 0x1274 device id 0x1371 revision 0x08
es1371: found es1371 rev 8 at io 0x9800 irq 5
es1371: features: joystick 0x0
ac97_codec: AC97 Audio codec, id: 0x4352:0x5913 (Cirrus Logic CS4297A rev A)
NET4: Linux TCP/IP 1.0 for NET4.0
IP Protocols: ICMP, UDP, TCP, IGMP
IP: routing cache hash table of 2048 buckets, 16Kbytes
TCP: Hash tables configured (established 16384 bind 16384)
NET4: Unix domain sockets 1.0/SMP for Linux NET4.0.
VFS: Mounted root (ext2 filesystem) readonly.
Freeing unused kernel memory: 96k freed
Adding Swap: 128484k swap-space (priority -1)
Real Time Clock Driver v1.10e
ne2k-pci.c:v1.02 10/19/2000 D. Becker/P. Gortmaker
http://www.scyld.com/network/ne2k-pci.html
PCI: Found IRQ 10 for device 00:09.0
PCI: Sharing IRQ 10 with 00:07.2
eth0: RealTek RTL-8029 found at 0x9400, IRQ 10, 00:80:C8:DF:59:9E.
CSLIP: code copyright 1989 Regents of the University of California
PPP generic driver version 2.4.2
SCSI subsystem driver Revision: 1.00
scsi0 : SCSI host adapter emulation for IDE ATAPI devices
Vendor: YAMAHA Model: CRW2100E Rev: 1.0G
Type: CD-ROM ANSI SCSI revision: 02
Vendor: LG Model: DVD-ROM DRD8160B Rev: 1.01
Type: CD-ROM ANSI SCSI revision: 02
Linux agpgart interface v0.99 (c) Jeff Hartmann
agpgart: Maximum main memory to use for agp memory: 203M
agpgart: Detected Intel 440BX chipset
agpgart: AGP aperture is 128M @ 0xe0000000
[drm] AGP 0.99 on Intel 440BX @ 0xe0000000 128MB
[drm] Initialized mga 3.0.2 20010321 on minor 0
Matrox MGA G200/G400/G450/G550 YUV Video interface v2.01 (c) Aaron Holtzman & A'rpi
mga_vid: Found MGA G400/G450
mga_vid: MMIO at 0xd0881000 IRQ: 11 framebuffer: 0xEC000000
mga_vid: OPTION word: 0x50040120 mem: 0x00 SDRAM
mga_vid: detected RAMSIZE is 16 MB
syncfb (mga): IRQ disabled in mga_vid.c
parport0: PC-style at 0x378 (0x778) [PCSPP,TRISTATE,EPP]
parport0: irq 7 detected
lp0: using parport0 (polling).
isapnp: Scanning for PnP cards...
isapnp: No Plug & Play device found
Serial driver version 5.05c (2001-07-08) with MANY_PORTS SHARE_IRQ DETECT_IRQ SERIAL_PCI ISAPNP enabled
ttyS00 at 0x03f8 (irq = 4) is a 16550A
ttyS01 at 0x02f8 (irq = 3) is a 16550A
Linux Kernel Card Services 3.1.22
options: [pci] [cardbus] [pm]
Intel PCIC probe: not found.
Intel PCIC probe: not found.
Starting AFS cache scan...found 393 non-empty cache files (7%).
mtrr: 0xec000000,0x2000000 overlaps existing 0xec000000,0x1000000
mtrr: 0xec000000,0x2000000 overlaps existing 0xec000000,0x1000000
Adding Swap: 127992k swap-space (priority -2)
Adding Swap: 131064k swap-space (priority -3)
Adding Swap: 1048568k swap-space (priority -4)
(The "tainted" is bogus because of openafs, for which I have source.
I've tried it without openafs anyways)
$ lsmod
Module Size Used by Tainted: PF
sr_mod 12304 0 (autoclean)
openafs 403712 2
pcmcia_core 39872 0
serial 50884 0 (autoclean)
isa-pnp 28708 0 (autoclean) [serial]
parport_pc 25288 1 (autoclean)
lp 6432 0 (autoclean)
parport 25024 1 (autoclean) [parport_pc lp]
mga_vid 7800 0
mga 98104 3
agpgart 16552 3
ide-scsi 7632 0
scsi_mod 51356 2 [sr_mod ide-scsi]
pppoe 6924 2
pppox 1128 1 [pppoe]
ppp_generic 16416 3 [pppoe pppox]
slhc 4480 0 [ppp_generic]
ne2k-pci 4800 1
8390 5968 0 [ne2k-pci]
rtc 5916 0 (autoclean)
--
greg
Gregory Stark <[email protected]> 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
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
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.
--
................................................................
: [email protected] : 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}...............:
Jakob Oestergaard <[email protected]> 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
Gregory Stark <[email protected]> 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.
And scd1 is a ide-scsi CDROM? The CDROM might have problem reading the
disc, and it blocks the entire bus. IDEs AFAIK don't disconnect.
--
Krzysztof Halasa
Network Administrator
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.
--
................................................................
: [email protected] : 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}...............:
On Mon, Dec 23, 2002 at 03:58:02AM -0500, Greg Stark wrote:
> Jakob Oestergaard <[email protected]> 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.
--
................................................................
: [email protected] : 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}...............:
> 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