PROBLEM: Loopback mounting a file on an NFS partition hangs NFS client

From: Wayne Whitney (whitney@math.berkeley.edu)
Date: Fri Oct 13 2000 - 20:36:31 EST


Hi all,

[ My apologies if this is a duplicate; I tried sending this a week ago,
but I didn't see my message in the mailing list archives, so I assume that
it did not go through for some reason . . . ]

This is my first time posting a possible kernel bug, so I hope I get
everything right; I am following the format suggested in REPORTING-BUGS.
I hadn't "planned" on a kernel bug, so I did not save all of the kernel
state immediately, but I think I correctly reconstructed my modules stack.

Also, I don't subscribe to the list, so please cc: me on replies at
whitney@math.berkeley.edu. Thanks.

Cheers,
Wayne

[1.] Loopback mounting a file on an NFS partition hangs NFS client.

[2.] I have two machines, mf1 and mf2. mf1 NFS exports to mf2 a partition
containing foo.iso, an ISO9660 file system in a file. On mf2, I mount it
with 'mount -o loop foo.iso'. Everything works fine at first, but after a
bunch of I/O (circa 100MB), a process accessing this file system triggers
a "kernel bug" message and gets stuck in a "D" status on ps. An attempt
to unmount foo.iso generates another "kernel bug" messages and fails but
does return. This problem is repeatable.

[3.] NFS client, loopback, disk wait

[4.] cat /proc/version

Linux version 2.4.0-test9 (root@mf2.private) (gcc version 2.96 20000731
(Red Hat Linux 7.0)) #3 SMP Thu Oct 5 13:04:40 PDT 2000

[5.] ksymoops -m /boot/System.map messages

ksymoops 2.3.4 on i686 2.4.0-test9. Options used
     -V (default)
     -k /proc/ksyms (default)
     -l /proc/modules (default)
     -o /lib/modules/2.4.0-test9/ (default)
     -m /boot/System.map (specified)

Oct 5 15:55:30 mf2 kernel: invalid operand: 0000
Oct 5 15:55:30 mf2 kernel: CPU: 0
Oct 5 15:55:30 mf2 kernel: EIP: 0010:[<f88d3867>]
Using defaults from ksymoops -t elf32-i386 -a i386
Oct 5 15:55:30 mf2 kernel: EFLAGS: 00010282
Oct 5 15:55:30 mf2 kernel: eax: 0000003f ebx: f7aa62c0 ecx: d6cc4000 edx: 00000021
Oct 5 15:55:30 mf2 kernel: esi: f7dc0640 edi: f72f7120 ebp: d6cc4000 esp: d6cc5c94
Oct 5 15:55:30 mf2 kernel: ds: 0018 es: 0018 ss: 0018
Oct 5 15:55:30 mf2 kernel: Process rpm (pid: 2776, stackpage=d6cc5000)
Oct 5 15:55:30 mf2 kernel: Stack: f88e05cb f88e0800 000000a4 f30ef640 f3166860 f760bea0 c160da90 f30ef640
Oct 5 15:55:30 mf2 kernel: 00000000 f88d2875 f760bea0 c160da90 00000000 00001000 fffffff4 00000004
Oct 5 15:55:30 mf2 kernel: c160da90 c160da90 f30ef640 ffffffff c160da90 f30ef640 f760bea0 f88d3059
Oct 5 15:55:30 mf2 kernel: Call Trace: [<f88e05cb>] [<f88e0800>] [<f88d2875>] [<f88d3059>] [do_generic_file_read+766/1344] [do_anonymous_page+58/288] [<f890c567>]
Oct 5 15:55:30 mf2 kernel: [<f890c3b0>] [<f890c89b>] [<f890c580>] [__make_request+1493/1536] [__find_get_page+68/288] [tcp_delack_timer+0/432] [timer_bh+595/688] [filemap_nopage+157/1088]
Oct 5 15:55:30 mf2 kernel: Code: 0f 0b 83 c4 0c 89 5f 1c c7 47 3c 01 00 00 00 f0 ff 06 f0 ff

>>EIP; f88d3867 <[nfs]nfs_create_request+197/1c0> <=====
Trace; f88e05cb <[nfs].rodata.start+130b/4426>
Trace; f88e0800 <[nfs].rodata.start+1540/4426>
Trace; f88d2875 <[nfs]nfs_readpage_async+115/190>
Trace; f88d3059 <[nfs]nfs_readpage+79/c0>
Trace; f890c3b0 <END_OF_CODE+c309/???
Trace; f890c89b <END_OF_CODE+c7f4/???
Trace; f890c580 <END_OF_CODE+c4d9/???
Code; f88d3867 <[nfs]nfs_create_request+197/1c0>
00000000 <_EIP>:
Code; f88d3867 <[nfs]nfs_create_request+197/1c0> <=====
   0: 0f 0b ud2a <=====
Code; f88d3869 <[nfs]nfs_create_request+199/1c0>
   2: 83 c4 0c add $0xc,%esp
Code; f88d386c <[nfs]nfs_create_request+19c/1c0>
   5: 89 5f 1c mov %ebx,0x1c(%edi)
Code; f88d386f <[nfs]nfs_create_request+19f/1c0>
   8: c7 47 3c 01 00 00 00 movl $0x1,0x3c(%edi)
Code; f88d3876 <[nfs]nfs_create_request+1a6/1c0>
   f: f0 ff 06 lock incl (%esi)
Code; f88d3879 <[nfs]nfs_create_request+1a9/1c0>
  12: f0 ff 00 lock incl (%eax)

Oct 5 15:57:06 mf2 kernel: invalid operand: 0000
Oct 5 15:57:06 mf2 kernel: CPU: 0
Oct 5 15:57:06 mf2 kernel: EIP: 0010:[<f88d159c>]
Oct 5 15:57:06 mf2 kernel: EFLAGS: 00010282
Oct 5 15:57:06 mf2 kernel: eax: 0000003f ebx: f7aa62c0 ecx: 00000002 edx: 00000021
Oct 5 15:57:06 mf2 kernel: esi: c211fa20 edi: f30ef7c0 ebp: f31668e0 esp: d62c1f48
Oct 5 15:57:06 mf2 kernel: ds: 0018 es: 0018 ss: 0018
Oct 5 15:57:06 mf2 kernel: Process umount (pid: 2832, stackpage=d62c1000)
Oct 5 15:57:06 mf2 kernel: Stack: f88df2eb f88df4e0 000000a4 f760bf00 f7a3e5e0 c01363e7 f30ef7c0 f760bf00
Oct 5 15:57:06 mf2 kernel: f7a78800 00000700 f31668e0 ffffffe7 f890cd48 00000000 f75b8cc0 00004c01
Oct 5 15:57:06 mf2 kernel: c013d996 f7a78800 00000700 00004c01 00000000 c0144d47 f30c8c60 f75b8cc0
Oct 5 15:57:06 mf2 kernel: Call Trace: [<f88df2eb>] [<f88df4e0>] [fput+55/224] [<f890cd48>] [blkdev_ioctl+38/64] [sys_ioctl+455/528] [system_call+51/56]
Oct 5 15:57:06 mf2 kernel: Code: 0f 0b 83 c4 0c 85 db 74 09 53 56 e8 f4 50 fe ff 5b 5e bb 00

>>EIP; f88d159c <[nfs]nfs_release+5c/b0> <=====
Trace; f88df2eb <[nfs].rodata.start+2b/4426>
Trace; f88df4e0 <[nfs].rodata.start+220/4426>
Code; f88d159c <[nfs]nfs_release+5c/b0>
00000000 <_EIP>:
Code; f88d159c <[nfs]nfs_release+5c/b0> <=====
   0: 0f 0b ud2a <=====
Code; f88d159e <[nfs]nfs_release+5e/b0>
   2: 83 c4 0c add $0xc,%esp
Code; f88d15a1 <[nfs]nfs_release+61/b0>
   5: 85 db test %ebx,%ebx
Code; f88d15a3 <[nfs]nfs_release+63/b0>
   7: 74 09 je 12 <_EIP+0x12> f88d15ae <[nfs]nfs_release+6e/b0>
Code; f88d15a5 <[nfs]nfs_release+65/b0>
   9: 53 push %ebx
Code; f88d15a6 <[nfs]nfs_release+66/b0>
   a: 56 push %esi
Code; f88d15a7 <[nfs]nfs_release+67/b0>
   b: e8 f4 50 fe ff call fffe5104 <_EIP+0xfffe5104> f88b66a0 <[sunrpc]rpcauth_releasecred+0/80>
Code; f88d15ac <[nfs]nfs_release+6c/b0>
  10: 5b pop %ebx
Code; f88d15ad <[nfs]nfs_release+6d/b0>
  11: 5e pop %esi
Code; f88d15ae <[nfs]nfs_release+6e/b0>
  12: bb 00 00 00 00 mov $0x0,%ebx

[6.] Hmm, I don't have an example program that would trigger this, but I
believe that the following would: export foo.iso from machine a to machine
b. mount -o loop foo.iso /foo on machine b. Access the filesystem
extinsively on machine b: I was using rpm, but I would think cp -R /foo
/dev/null would do the trick.

Also, I should mention that several months ago, I was doing the exact same
thing on two different machines and similarly my process on the client
machine got stuck in a disk wait. I didn't look into the problem or
record any information, but I think the machines were running 2.2.x.

[7.1] /usr/local/src/linux/scripts/ver_linux

-- Versions installed: (if some fields are empty or look
-- unusual then possibly you have very old versions)
Linux mf2.private 2.4.0-test9 #3 SMP Thu Oct 5 13:04:40 PDT 2000 i686 unknown
Kernel modules 2.3.17
Gnu C 2.96
Gnu Make 3.79.1
Binutils 2.10.0.18
Linux C Library 1.92.so*
Dynamic linker ldd (GNU libc) 2.1.92
Procps 2.0.7
Mount 2.10m
Net-tools 1.56
Console-tools 0.3.3
Sh-utils 2.0
Modules Loaded nls_iso8859-1 isofs loop nfsd nfs lockd sunrpc tulip agpgart ipchains ide-scsi scsi_mod via82cxxx_audio ac97_codec soundcore

[7.2] cat /proc/cpuinfo

processor : 0
vendor_id : GenuineIntel
cpu family : 6
model : 8
model name : Pentium III (Coppermine)
stepping : 3
cpu MHz : 735.000024
cache size : 256 KB
fdiv_bug : no
hlt_bug : no
sep_bug : no
f00f_bug : no
coma_bug : no
fpu : yes
fpu_exception : yes
cpuid level : 2
wp : yes
flags : fpu vme de pse tsc msr pae mce cx8 apic sep mtrr pge mca
cmov pat pse36 mmx fxsr xmm
bogomips : 1464.73

processor : 1
vendor_id : GenuineIntel
cpu family : 6
model : 8
model name : Pentium III (Coppermine)
stepping : 3
cpu MHz : 735.000024
cache size : 256 KB
fdiv_bug : no
hlt_bug : no
sep_bug : no
f00f_bug : no
coma_bug : no
fpu : yes
fpu_exception : yes
cpuid level : 2
wp : yes
flags : fpu vme de pse tsc msr pae mce cx8 apic sep mtrr pge mca
cmov pat pse36 mmx fxsr xmm
bogomips : 1468.01

[7.3] cat /proc/modules

nls_iso8859-1 2880 3 (autoclean)
isofs 20864 3 (autoclean)
loop 8112 6 (autoclean)
nfsd 69744 8 (autoclean)
nfs 81904 2 (autoclean)
lockd 51056 1 (autoclean) [nfsd nfs]
sunrpc 63744 1 (autoclean) [nfsd nfs lockd]
tulip 34800 1 (autoclean)
agpgart 16176 0 (unused)
ipchains 35840 0 (unused)
ide-scsi 8432 0
scsi_mod 96768 1 [ide-scsi]
via82cxxx_audio 12144 0
ac97_codec 7760 0 [via82cxxx_audio]
soundcore 4432 2 [via82cxxx_audio]

[7.4] cat /proc/ioports /proc/iomem

0000-001f : dma1
0020-003f : pic1
0040-005f : timer
0060-006f : keyboard
0080-008f : dma page reg
00a0-00bf : pic2
00c0-00df : dma2
00f0-00ff : fpu
0170-0177 : ide1
01f0-01f7 : ide0
0376-0376 : ide1
03c0-03df : vga+
03f6-03f6 : ide0
0cf8-0cff : PCI conf1
4000-40ff : VIA Technologies, Inc. VT82C686 [Apollo Super ACPI]
  4000-4003 : acpi
  4008-400b : acpi
  4020-4023 : acpi
  40f0-40f1 : acpi
5000-500f : VIA Technologies, Inc. VT82C686 [Apollo Super ACPI]
6000-607f : VIA Technologies, Inc. VT82C686 [Apollo Super ACPI]
c000-cfff : PCI Bus #01
  c000-c0ff : ATI Technologies Inc 3D Rage Pro AGP 1X/2X
d000-d00f : VIA Technologies, Inc. Bus Master IDE
  d000-d007 : ide0
  d008-d00f : ide1
dc00-dcff : VIA Technologies, Inc. AC97 Audio Controller
  dc00-dcff : via82cxxx
e000-e003 : VIA Technologies, Inc. AC97 Audio Controller
e400-e403 : VIA Technologies, Inc. AC97 Audio Controller
e800-e8ff : Lite-On Communications Inc LNE100TX
  e800-e8ff : eth0
00000000-0009fbff : System RAM
0009fc00-0009ffff : System RAM
000a0000-000bffff : Video RAM area
000c0000-000c7fff : Video ROM
000f0000-000fffff : System ROM
00100000-3ffeffff : System RAM
  00100000-0020b4f7 : Kernel code
  0020b4f8-0021c53f : Kernel data
3fff0000-3fff2fff : ACPI Non-volatile Storage
3fff3000-3fffffff : ACPI Tables
d0000000-d3ffffff : VIA Technologies, Inc. VT82C693A/694x [Apollo PRO133x]
d4000000-d6ffffff : PCI Bus #01
  d4000000-d4ffffff : ATI Technologies Inc 3D Rage Pro AGP 1X/2X
  d6000000-d6000fff : ATI Technologies Inc 3D Rage Pro AGP 1X/2X
d8000000-d80000ff : Lite-On Communications Inc LNE100TX
  d8000000-d80000ff : eth0
fec00000-fec00fff : reserved
fee00000-fee00fff : reserved
ffff0000-ffffffff : reserved

[7.5] lspci -vvv

00:00.0 Host bridge: VIA Technologies, Inc. VT82C691 [Apollo PRO] (rev c4)
        Control: I/O- Mem+ BusMaster+ SpecCycle- MemWINV- VGASnoop-
ParErr- Stepping- SERR- FastB2B-
        Status: Cap+ 66Mhz- UDF- FastB2B- ParErr- DEVSEL=medium >TAbort-
<TAbort- <MAbort+ >SERR- <PERR+
        Latency: 0
        Region 0: Memory at d0000000 (32-bit, prefetchable) [size=64M]
        Capabilities: [a0] AGP version 2.0
                Status: RQ=31 SBA+ 64bit- FW- Rate=x1,x2
                Command: RQ=0 SBA- AGP- 64bit- FW- Rate=<none>
        Capabilities: [c0] Power Management version 2
                Flags: PMEClk- DSI- D1- D2- AuxCurrent=0mA
PME(D0-,D1-,D2-,D3hot-,D3cold-)
                Status: D0 PME-Enable- DSel=0 DScale=0 PME-

00:01.0 PCI bridge: VIA Technologies, Inc. VT82C598 [Apollo MVP3 AGP]
(prog-if 00 [Normal decode])
        Control: I/O+ Mem+ BusMaster+ SpecCycle- MemWINV- VGASnoop-
ParErr- Stepping- SERR- FastB2B-
        Status: Cap+ 66Mhz+ UDF- FastB2B- ParErr- DEVSEL=medium >TAbort-
<TAbort- <MAbort+ >SERR- <PERR-
        Latency: 0
        Bus: primary=00, secondary=01, subordinate=01, sec-latency=0
        I/O behind bridge: 0000c000-0000cfff
        Memory behind bridge: d4000000-d6ffffff
        Prefetchable memory behind bridge: fff00000-000fffff
        BridgeCtl: Parity- SERR- NoISA+ VGA+ MAbort- >Reset- FastB2B-
        Capabilities: [80] Power Management version 2
                Flags: PMEClk- DSI- D1+ D2- AuxCurrent=0mA
PME(D0-,D1-,D2-,D3hot-,D3cold-)
                Status: D0 PME-Enable- DSel=0 DScale=0 PME-

00:07.0 ISA bridge: VIA Technologies, Inc. VT82C686 [Apollo Super] (rev
22)
        Subsystem: VIA Technologies, Inc. VT82C686/A PCI to ISA Bridge
        Control: I/O+ Mem+ BusMaster+ SpecCycle- MemWINV- VGASnoop-
ParErr- Stepping+ SERR- FastB2B-
        Status: Cap+ 66Mhz- UDF- FastB2B- ParErr- DEVSEL=medium >TAbort-
<TAbort- <MAbort- >SERR- <PERR-
        Latency: 0

00:07.1 IDE interface: VIA Technologies, Inc. VT82C586 IDE [Apollo] (rev
10) (prog-if 8a [Master SecP PriP])
        Control: I/O+ Mem+ BusMaster+ SpecCycle- MemWINV- VGASnoop-
ParErr- Stepping- SERR- FastB2B-
        Status: Cap+ 66Mhz- UDF- FastB2B+ ParErr- DEVSEL=medium >TAbort-
<TAbort- <MAbort- >SERR- <PERR-
        Latency: 32
        Region 4: I/O ports at d000 [size=16]
        Capabilities: [c0] Power Management version 2
                Flags: PMEClk- DSI- D1- D2- AuxCurrent=0mA
PME(D0-,D1-,D2-,D3hot-,D3cold-)
                Status: D0 PME-Enable- DSel=0 DScale=0 PME-

00:07.4 Host bridge: VIA Technologies, Inc. VT82C686 [Apollo Super ACPI]
(rev 30)
        Control: I/O- Mem- BusMaster- SpecCycle- MemWINV- VGASnoop-
ParErr- Stepping- SERR- FastB2B-
        Status: Cap+ 66Mhz- UDF- FastB2B+ ParErr- DEVSEL=medium >TAbort-
<TAbort- <MAbort- >SERR- <PERR-
        Capabilities: [68] Power Management version 2
                Flags: PMEClk- DSI- D1- D2- AuxCurrent=0mA
PME(D0-,D1-,D2-,D3hot-,D3cold-)
                Status: D0 PME-Enable- DSel=0 DScale=0 PME-

00:07.5 Multimedia audio controller: VIA Technologies, Inc. VT82C686
[Apollo Super AC97/Audio] (rev 20)
        Subsystem: VIA Technologies, Inc. VT82C686 [Apollo Super
AC97/Audio]
        Control: I/O+ Mem- BusMaster- SpecCycle- MemWINV- VGASnoop-
ParErr- Stepping- SERR- FastB2B-
        Status: Cap+ 66Mhz- UDF- FastB2B- ParErr- DEVSEL=medium >TAbort-
<TAbort- <MAbort- >SERR- <PERR-
        Interrupt: pin C routed to IRQ 18
        Region 0: I/O ports at dc00 [size=256]
        Region 1: I/O ports at e000 [size=4]
        Region 2: I/O ports at e400 [size=4]
        Capabilities: [c0] Power Management version 2
                Flags: PMEClk- DSI- D1- D2- AuxCurrent=0mA
PME(D0-,D1-,D2-,D3hot-,D3cold-)
                Status: D0 PME-Enable- DSel=0 DScale=0 PME-

00:0f.0 Ethernet controller: Lite-On Communications Inc LNE100TX (rev 20)
        Subsystem: Kingston Technologies: Unknown device f002
        Control: I/O+ Mem+ BusMaster+ SpecCycle- MemWINV- VGASnoop-
ParErr- Stepping- SERR- FastB2B-
        Status: Cap- 66Mhz- UDF- FastB2B+ ParErr- DEVSEL=medium >TAbort-
<TAbort- <MAbort- >SERR- <PERR-
        Latency: 32
        Interrupt: pin A routed to IRQ 17
        Region 0: I/O ports at e800 [size=256]
        Region 1: Memory at d8000000 (32-bit, non-prefetchable) [size=256]
        Expansion ROM at <unassigned> [disabled] [size=256K]

01:00.0 VGA compatible controller: ATI Technologies Inc 3D Rage Pro AGP
1X/2X (rev 5c) (prog-if 00 [VGA])
        Subsystem: ATI Technologies Inc: Unknown device 0084
        Control: I/O+ Mem+ BusMaster+ SpecCycle- MemWINV- VGASnoop-
ParErr- Stepping+ SERR- FastB2B-
        Status: Cap+ 66Mhz- UDF- FastB2B+ ParErr- DEVSEL=medium >TAbort-
<TAbort- <MAbort- >SERR- <PERR-
        Latency: 32 (2000ns min), cache line size 08
        Interrupt: pin A routed to IRQ 0
        Region 0: Memory at d4000000 (32-bit, non-prefetchable) [size=16M]
        Region 1: I/O ports at c000 [size=256]
        Region 2: Memory at d6000000 (32-bit, non-prefetchable) [size=4K]
        Expansion ROM at <unassigned> [disabled] [size=128K]
        Capabilities: [50] AGP version 1.0
                Status: RQ=255 SBA+ 64bit- FW- Rate=x1,x2
                Command: RQ=0 SBA- AGP- 64bit- FW- Rate=<none>

[7.6] cat /proc/scsi/scsi

Attached devices:
Host: scsi0 Channel: 00 Id: 00 Lun: 00
  Vendor: SONY Model: CD-ROM CDU4821 Rev: S0.Q
  Type: CD-ROM ANSI SCSI revision: 02

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



This archive was generated by hypermail 2b29 : Sun Oct 15 2000 - 21:00:26 EST