Messages in this thread |  | | From | Martin Buck <> | Date | Sat, 4 Jan 97 03:10 MET | Subject | VFS: brelse: Trying to free free buffer with 2.0.27 |
| |
I noticed a problem with Linux 2.0.27 when I tried to read from a currently used swap partition. When reading the complete partition with "cat /dev/hda2 > /dev/null", I get a "VFS: brelse: Trying to free free buffer" followed by an Oops or GPF when the "cat" reaches the last few blocks of the partition.
I tested this on two different partitions on two different drives: An IDE drive (attached to the onboard controller of the Intel Triton-chipset, PIO mode 0) with a 41074 (512 byte-)block partition and a SCSI drive (attached to a NCR/Symbios Logic 53C810A) with a 103950 block partition. On the IDE drive, the problem occurs if you read at least 41073 blocks, on the SCSI drive, 103945 blocks are enough to trigger it. This happens on a P100 machine with 24MB; I couldn't reproduce it on another one with 32MB (and other partitions). Of course, the problem disappears on the 24MB-machine if you do a "swapoff" on the partition.
I've attached the relevant part of my syslog (the three errors are from three successive invocations of "cat"), ksymoops' output and the corresponding sourcecode below. If anybody needs more information, mail me--the bug is reproducible, so I can try out more things if you need.
Jan 3 19:11:29 gromit kernel: VFS: brelse: Trying to free free buffer Jan 3 19:11:29 gromit kernel: general protection: 0000 Jan 3 19:11:29 gromit kernel: CPU: 0 Jan 3 19:11:29 gromit kernel: EIP: 0010:[<00126b5a>] Jan 3 19:11:29 gromit kernel: EFLAGS: 00010286 Jan 3 19:11:29 gromit kernel: eax: 00000025 ebx: 0120dd58 ecx: ffaa0055 edx: 0063f380 Jan 3 19:11:29 gromit kernel: esi: 00000000 edi: 00000010 ebp: 00000400 esp: 01045cdc Jan 3 19:11:29 gromit kernel: ds: 0018 es: 0018 fs: 002b gs: 002b ss: 0018 Jan 3 19:11:29 gromit kernel: Process cat (pid: 146, process nr: 18, stackpage=01045000) Jan 3 19:11:29 gromit kernel: Stack: 0120dd58 01045e74 01045e78 00000400 015f19d4 0063f380 00000030 00126e5e Jan 3 19:11:29 gromit kernel: 0120dd58 0120dd58 00000000 01045f74 0012b7d4 0120dd58 01117000 00000000 Jan 3 19:11:29 gromit kernel: 00001000 010118b8 00001000 00000000 00000400 00000000 00001000 00000000 Jan 3 19:11:29 gromit kernel: Call Trace: [<00126e5e>] [<0012b7d4>] [<0011a983>] [<0012c234>] [<00133d81>] [<00126536>] [<00126e5e>] Jan 3 19:11:29 gromit kernel: [<00159c11>] [<0011cb92>] [<0015a1bd>] [<0015a1f0>] [<0015a21a>] [<00112850>] [<00112888>] [<00118377>] Jan 3 19:11:29 gromit kernel: [<0010a9db>] [<00123ebf>] [<00123d8a>] [<0010aa52>] Jan 3 19:11:29 gromit kernel: Code: 89 41 0c 0f b7 43 04 33 03 31 d2 f7 35 d0 08 19 00 89 d1 8b Jan 3 19:11:43 gromit kernel: VFS: iput: trying to free free inode Jan 3 19:11:43 gromit kernel: VFS: device 00:00, inode 0, mode=00000000 Jan 3 19:11:57 gromit kernel: VFS: brelse: Trying to free free buffer Jan 3 19:11:57 gromit kernel: general protection: 0000 Jan 3 19:11:57 gromit kernel: CPU: 0 Jan 3 19:11:57 gromit kernel: EIP: 0010:[<00126b5a>] Jan 3 19:11:57 gromit kernel: EFLAGS: 00010286 Jan 3 19:11:57 gromit kernel: eax: 00000025 ebx: 0120d798 ecx: ffaa0055 edx: 0063f380 Jan 3 19:11:57 gromit kernel: esi: 00000000 edi: ffffffff ebp: 00000400 esp: 01036cdc Jan 3 19:11:57 gromit kernel: ds: 0018 es: 0018 fs: 002b gs: 002b ss: 0018 Jan 3 19:11:57 gromit kernel: Process cat (pid: 156, process nr: 18, stackpage=01036000) Jan 3 19:11:57 gromit kernel: Stack: 0120d798 01036e74 01036e78 00000400 0139b000 0063f380 fffffffd 00126e5e Jan 3 19:11:57 gromit kernel: 0120d798 0120d798 00000000 01036f74 0012b7d4 0120d798 01117700 00000000 Jan 3 19:11:57 gromit kernel: 00001000 010118b8 00001000 00000000 00000400 00000000 00001000 00000000 Jan 3 19:11:57 gromit kernel: Call Trace: [<00126e5e>] [<0012b7d4>] [<0011a983>] [<0015ea0e>] [<0016003d>] [<0015f5ac>] [<0016338b>] Jan 3 19:11:57 gromit kernel: [<00160353>] [<00126e5e>] [<00159c11>] [<0011cb92>] [<0015a1bd>] [<0015a1f0>] [<0015a21a>] [<001168de>] Jan 3 19:11:57 gromit kernel: [<00117af9>] [<00117ae8>] [<001128c4>] [<00118377>] [<00123ebf>] [<00123d8a>] [<0010aa52>] Jan 3 19:11:57 gromit kernel: Code: 89 41 0c 0f b7 43 04 33 03 31 d2 f7 35 d0 08 19 00 89 d1 8b Jan 3 19:12:28 gromit kernel: VFS: brelse: Trying to free free buffer Jan 3 19:12:28 gromit kernel: Unable to handle kernel paging request at virtual address c325bbe0 Jan 3 19:12:28 gromit kernel: current->tss.cr3 = 01093000, Tr3 = 01093000 Jan 3 19:12:28 gromit kernel: *pde = 00000000 Jan 3 19:12:28 gromit kernel: Oops: 0000 Jan 3 19:12:28 gromit kernel: CPU: 0 Jan 3 19:12:28 gromit kernel: EIP: 0010:[<00126a12>] Jan 3 19:12:28 gromit kernel: EFLAGS: 00010216 Jan 3 19:12:28 gromit kernel: eax: 000ef6ff ebx: 00000002 ecx: 001b9000 edx: 00c28af3 Jan 3 19:12:28 gromit kernel: esi: e14cf000 edi: 01088e7c ebp: 00000400 esp: 01088cdc Jan 3 19:12:28 gromit kernel: ds: 0018 es: 0018 fs: 002b gs: 002b ss: 0018 Jan 3 19:12:28 gromit kernel: Process cat (pid: 160, process nr: 14, stackpage=01088000) Jan 3 19:12:28 gromit kernel: Stack: 00000002 01088e74 01088e7c 00000400 00806110 006be400 00007400 00126e5e Jan 3 19:12:28 gromit kernel: 00000002 00000002 00000000 01088f74 0012b7d4 00000002 01117ec0 00000000 Jan 3 19:12:28 gromit kernel: 00001000 010118b8 00001000 00000000 00000400 00000000 00001000 00000000 Jan 3 19:12:28 gromit kernel: Call Trace: [<00126e5e>] [<0012b7d4>] [<0011a983>] [<0012c234>] [<00133d81>] [<00126536>] [<00126e5e>] Jan 3 19:12:28 gromit kernel: [<00159c11>] [<0011cb92>] [<00174e3f>] [<0015a1bd>] [<0015a21a>] [<00112850>] [<00112888>] [<00118377>] Jan 3 19:12:28 gromit kernel: [<0010a9db>] [<00123ebf>] [<00123d8a>] [<0010aa52>] Jan 3 19:12:28 gromit kernel: Code: 83 7c 91 14 01 7f 08 f7 c6 40 00 00 00 74 07 be 05 00 00 00
BTW, the "iput: trying to free free inode" probably wasn't caused by the "cat" but by another process trying to write to disk at the same time. Looks strange to me, nevertheless.
This is the output of ksymoops for the three errors:
>>EIP: 126b5a <_refile_buffer+196/478> Trace: 126e5e <___brelse+22/44> Trace: 12b7d4 <_block_read+5f0/648> Trace: 11a983 <_put_dirty_page+bf/1f8> Trace: 12c234 <_setup_arg_pages+ec/104> Trace: 133d81 <_load_aout_binary+591/634> Trace: 126536 <_getblk+3a/468> Trace: 126e5e <___brelse+22/44> Trace: 159c11 <_ext2_update_inode+2b1/2c0> Trace: 11cb92 <_merge_segments+472/4e8> Trace: 15a1bd <_ext2_lookup+81/180> Trace: 15a1f0 <_ext2_lookup+b4/180> Trace: 15a21a <_ext2_lookup+de/180> Trace: 112850 <_timer_bh+b8/14c> Trace: 112888 <_timer_bh+f0/14c> Trace: 118377 <_do_bottom_half+3b/8c> Trace: 10a9db <handle_bottom_half+b/20> Trace: 123ebf <_sys_write+10f/148> Trace: 123d8a <_sys_read+8a/b0> Trace: 10aa52 <_system_call+52/80>
Code: 126b5a <_refile_buffer+196/478> movl %eax,0xc(%ecx) Code: 126b5d <_refile_buffer+199/478> movzwl 0x4(%ebx),%eax Code: 126b61 <_refile_buffer+19d/478> xorl (%ebx),%eax Code: 126b63 <_refile_buffer+19f/478> xorl %edx,%edx Code: 126b65 <_refile_buffer+1a1/478> divl 0x1908d0,%eax Code: 126b6b <_refile_buffer+1a7/478> movl %edx,%ecx Code: 126b6d <_refile_buffer+1a9/478> movl (%eax),%eax Code: 126b6f <_refile_buffer+1ab/478> nop Code: 126b70 <_refile_buffer+1ac/478> nop
>>EIP: 126b5a <_refile_buffer+196/478> Trace: 126e5e <___brelse+22/44> Trace: 12b7d4 <_block_read+5f0/648> Trace: 11a983 <_put_dirty_page+bf/1f8> Trace: 15ea0e <_ide_set_handler+26/2c> Trace: 16003d <_ide_do_request+335/5f0> Trace: 15f5ac <_read_intr> Trace: 16338b <_make_request+3ef/4a8> Trace: 160353 <_do_ide0_request+b/10> Trace: 126e5e <___brelse+22/44> Trace: 159c11 <_ext2_update_inode+2b1/2c0> Trace: 11cb92 <_merge_segments+472/4e8> Trace: 15a1bd <_ext2_lookup+81/180> Trace: 15a1f0 <_ext2_lookup+b4/180> Trace: 15a21a <_ext2_lookup+de/180> Trace: 1168de <_send_sig+13e/148> Trace: 117af9 <_it_real_fn+11/48> Trace: 117af9 <_it_real_fn+11/48> Trace: 1128c4 <_timer_bh+12c/14c> Trace: 118377 <_do_bottom_half+3b/8c> Trace: 123ebf <_sys_write+10f/148> Trace: 123d8a <_sys_read+8a/b0> Trace: 10aa52 <_system_call+52/80>
Code: 126b5a <_refile_buffer+196/478> movl %eax,0xc(%ecx) Code: 126b5d <_refile_buffer+199/478> movzwl 0x4(%ebx),%eax Code: 126b61 <_refile_buffer+19d/478> xorl (%ebx),%eax Code: 126b63 <_refile_buffer+19f/478> xorl %edx,%edx Code: 126b65 <_refile_buffer+1a1/478> divl 0x1908d0,%eax Code: 126b6b <_refile_buffer+1a7/478> movl %edx,%ecx Code: 126b6d <_refile_buffer+1a9/478> movl (%eax),%eax Code: 126b6f <_refile_buffer+1ab/478> nop Code: 126b70 <_refile_buffer+1ac/478> nop
>>EIP: 126a12 <_refile_buffer+4e/478> Trace: 126e5e <___brelse+22/44> Trace: 12b7d4 <_block_read+5f0/648> Trace: 11a983 <_put_dirty_page+bf/1f8> Trace: 12c234 <_setup_arg_pages+ec/104> Trace: 133d81 <_load_aout_binary+591/634> Trace: 126536 <_getblk+3a/468> Trace: 126e5e <___brelse+22/44> Trace: 159c11 <_ext2_update_inode+2b1/2c0> Trace: 11cb92 <_merge_segments+472/4e8> Trace: 174e3f <_n_tty_receive_buf+aef/b24> Trace: 15a1bd <_ext2_lookup+81/180> Trace: 15a21a <_ext2_lookup+de/180> Trace: 112850 <_timer_bh+b8/14c> Trace: 112888 <_timer_bh+f0/14c> Trace: 118377 <_do_bottom_half+3b/8c> Trace: 10a9db <handle_bottom_half+b/20> Trace: 123ebf <_sys_write+10f/148> Trace: 123d8a <_sys_read+8a/b0> Trace: 10aa52 <_system_call+52/80>
Code: 126a12 <_refile_buffer+4e/478> cmpl $0x1,0x14(%ecx,%edx,4) Code: 126a17 <_refile_buffer+53/478> jg 126a21 <_refile_buffer+5d/478> Code: 126a19 <_refile_buffer+55/478> testl $0x40,%esi Code: 126a1f <_refile_buffer+5b/478> je 126a28 <_refile_buffer+64/478> Code: 126a21 <_refile_buffer+5d/478> movl $0x5,%esi
EIP 126b5a <_refile_buffer+196/478> corresponds to fs/buffer.c:323 (inline-function remove_from_hash_queue, called from fs/buffer.c:380, inline-function remove_from_queues, called from fs/buffer.c:838, function refile_buffer).
EIP: 126a12 <_refile_buffer+4e/478> corresponds to fs/buffer.c:823 (first part).
Oh BTW, please don't ask why I want to read a swap-partition. :-)
BTW#2, please CC: all replies to me--I read this list via linux.dev.kernel, which is a bit unreliable. :-(
Thanks for any hints, Martin -- /* Martin Buck E-Mail: martin-2.buck@student.uni-ulm.de */ /* Student of electrical engineering WWW: http://www.uni-ulm.de/~s_mbuck1/ */ /* University of Ulm, Germany Snail-Mail: Paukengasse 2, 89077 Ulm, Germany */ #include <disclaimer.h> /* PGP Key available MIME-Mail welcome */
|  |