From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S1750742AbWFQRH0 (ORCPT ); Sat, 17 Jun 2006 13:07:26 -0400 Received: (majordomo@vger.kernel.org) by vger.kernel.org id S1750731AbWFQRH0 (ORCPT ); Sat, 17 Jun 2006 13:07:26 -0400 Received: from smtp.osdl.org ([65.172.181.4]:14061 "EHLO smtp.osdl.org") by vger.kernel.org with ESMTP id S1750742AbWFQRHZ (ORCPT ); Sat, 17 Jun 2006 13:07:25 -0400 Date: Sat, 17 Jun 2006 10:07:10 -0700 From: Andrew Morton To: "Charles C. Bennett, Jr." Cc: linux-kernel@vger.kernel.org, Ingo Molnar Subject: Re: BUG: write-lock lockup Message-Id: <20060617100710.ec05131f.akpm@osdl.org> In-Reply-To: <1150142023.3621.22.camel@cbox.memecycle.com> References: <1150142023.3621.22.camel@cbox.memecycle.com> X-Mailer: Sylpheed version 2.2.4 (GTK+ 2.8.17; i686-pc-linux-gnu) Mime-Version: 1.0 Content-Type: text/plain; charset=US-ASCII Content-Transfer-Encoding: 7bit Sender: linux-kernel-owner@vger.kernel.org X-Mailing-List: linux-kernel@vger.kernel.org On Mon, 12 Jun 2006 15:53:43 -0400 "Charles C. Bennett, Jr." wrote: > > Hi All - > > I'm seeing write-lock lockups... this is happening with > the Fedora kernels from at least as far back as their 2.6.15-1.1833_FC4 > (2.6.15.5) and as recently as their 2.6.16-1.2111_FC4 (2.6.16.17). > > It's a beefy box: > Gateway 9515R - Intel ICH5/ICH5R > Two Dual Core 3.0 ghz Xeons, 4GB RAM > All disks via Emulex LP101-H (thor), switched fabric to > Hitachi WMS SAN storage. > > The lockups are not process-specific. Running mke2fs on large > filesystems seems to get it happen sooner rather than later. Apart from these messages, does the machine otherwise work OK? > I can fish out any other data you need, run tests, etc. > > > Jun 9 20:43:40 localhost kernel: BUG: write-lock lockup on CPU#6, mkfs.ext2/3258, f799c864 (Not tainted) > Jun 9 20:43:40 localhost kernel: [] __write_lock_debug+0xb4/0xdd [] _raw_write_lock+0x3f/0x7c > Jun 9 20:43:40 localhost kernel: [] shrink_list+0x197/0x45d [] shrink_cache+0xe7/0x29b > Jun 9 20:43:40 localhost kernel: [] bad_range+0x22/0x2f [] __rmqueue+0xd1/0x156 > Jun 9 20:43:40 localhost kernel: [] shrink_zone+0x89/0xd8 [] shrink_caches+0x66/0x74 > Jun 9 20:43:40 localhost kernel: [] try_to_free_pages+0xad/0x1b7 [] __alloc_pages+0x136/0x2ec > Jun 9 20:43:40 localhost kernel: [] __block_commit_write+0x83/0x8f [] generic_file_buffered_write+0x16b/0x655 > Jun 9 20:43:40 localhost kernel: [] current_fs_time+0x5a/0x75 [] current_fs_time+0x5a/0x75 > Jun 9 20:43:40 localhost kernel: [] inode_update_time+0x2d/0x99 [] __generic_file_aio_write_nolock+0x2a3/0x4d9 > Jun 9 20:43:40 localhost kernel: [] generic_file_aio_write_nolock+0x3c/0x92 [] blkdev_file_write+0x0/0x24 > Jun 9 20:43:40 localhost kernel: [] generic_file_write_nolock+0x85/0x9f [] autoremove_wake_function+0x0/0x37 > Jun 9 20:43:40 localhost kernel: [] blkdev_file_write+0x20/0x24 [] vfs_write+0xa2/0x15a > Jun 9 20:43:40 localhost kernel: [] sys_write+0x41/0x6a [] syscall_call+0x7/0xb > Jun 9 21:02:58 localhost kernel: BUG: write-lock lockup on CPU#1, mkfs.ext2/3259, f799c864 (Not tainted) > Jun 9 21:02:58 localhost kernel: [] __write_lock_debug+0xb4/0xdd [] _raw_write_lock+0x3f/0x7c > Jun 9 21:02:58 localhost kernel: [] _write_lock_irqsave+0x9/0xd [] test_clear_page_writeback+0x2d/0xa6 > Jun 9 21:02:58 localhost kernel: [] end_page_writeback+0x76/0x84 [] end_buffer_async_write+0xbf/0x12a > Jun 9 21:02:58 localhost kernel: [] memmove+0x24/0x2d [] mempool_free+0x3a/0x73 > Jun 9 21:02:58 localhost kernel: [] end_bio_bh_io_sync+0x0/0x4f [] end_bio_bh_io_sync+0x0/0x4f > Jun 9 21:02:58 localhost kernel: [] end_bio_bh_io_sync+0x23/0x4f [] bio_endio+0x3e/0x69 > Jun 9 21:02:58 localhost kernel: [] __end_that_request_first+0x101/0x235 [] scsi_end_request+0x1b/0xb0 [scsi_mod] > Jun 9 21:02:58 localhost kernel: [] scsi_io_completion+0x151/0x4d2 [scsi_mod] [] sd_rw_intr+0x70/0x3c1 [sd_mod] > Jun 9 21:02:58 localhost kernel: [] scsi_finish_command+0x82/0xd0 [scsi_mod] [] scsi_softirq+0xc0/0x137 [scsi_mod] > Jun 9 21:02:58 localhost kernel: [] __do_softirq+0x72/0xdc [] do_softirq+0x4b/0x4f > Jun 9 21:02:58 localhost kernel: ======================= > Jun 9 21:02:58 localhost kernel: [] do_IRQ+0x55/0x86 [] common_interrupt+0x1a/0x20 > Jun 9 21:03:05 localhost kernel: [] free_hot_cold_page+0xd5/0x126 [] __pagevec_free+0x1f/0x2e > Jun 9 21:03:08 localhost kernel: [] __pagevec_release_nonlru+0x29/0x8b [] shrink_list+0x215/0x45d > Jun 9 21:03:09 localhost kernel: [] shrink_cache+0xe7/0x29b [] shrink_zone+0x89/0xd8 > Jun 9 21:03:09 localhost kernel: [] shrink_caches+0x66/0x74 [] try_to_free_pages+0xad/0x1b7 > Jun 9 21:03:09 localhost kernel: [] __alloc_pages+0x136/0x2ec [] __block_commit_write+0x83/0x8f > Jun 9 21:03:10 localhost kernel: [] generic_file_buffered_write+0x16b/0x655 [] current_fs_time+0x5a/0x75 > Jun 9 21:03:11 localhost kernel: [] inode_update_time+0x2d/0x99 [] __generic_file_aio_write_nolock+0x2a3/0x4d9 > Jun 9 21:03:11 localhost kernel: [] generic_file_aio_write_nolock+0x3c/0x92 [] blkdev_file_write+0x0/0x24 > Jun 9 21:03:12 localhost kernel: [] generic_file_write_nolock+0x85/0x9f [] autoremove_wake_function+0x0/0x37 > Jun 9 21:03:12 localhost kernel: [] blkdev_file_write+0x20/0x24 [] vfs_write+0xa2/0x15a > Jun 9 21:03:12 localhost kernel: [] sys_write+0x41/0x6a [] syscall_call+0x7/0xb Well. Obviously __write_lock_debug():print_once was meant to have static scope (__read_mostly, too). But that's a cosmetic thing. I'm suspecting that the debug code has simply gone wrong here - that there's such a lot of read_lock() traffic happening with this workload that the debug version of write_lock() simply isn't able to take the lock. This might fix it, but it'll break the timing calculations in that loop. --- devel/lib/spinlock_debug.c~a 2006-06-17 03:08:35.000000000 -0700 +++ devel-akpm/lib/spinlock_debug.c 2006-06-17 03:08:56.000000000 -0700 @@ -219,7 +219,7 @@ static void __write_lock_debug(rwlock_t for (i = 0; i < loops_per_jiffy * HZ; i++) { if (__raw_write_trylock(&lock->raw_lock)) return; - __delay(1); + cpu_relax(); } /* lockup suspected: */ if (print_once) { _ (I'm a little surprised that RH-FC ships with this debug option enabled. It's good for kernel development, but not optimal for users...) Ingo, we have two bugs in there - some assist and thought would be appreciated, please.