Return-Path: Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S1753963Ab3F0PWQ (ORCPT ); Thu, 27 Jun 2013 11:22:16 -0400 Received: from mx1.redhat.com ([209.132.183.28]:13556 "EHLO mx1.redhat.com" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1753902Ab3F0PWL (ORCPT ); Thu, 27 Jun 2013 11:22:11 -0400 Date: Thu, 27 Jun 2013 11:21:51 -0400 From: Dave Jones To: Dave Chinner Cc: Oleg Nesterov , "Paul E. McKenney" , Linux Kernel , Linus Torvalds , "Eric W. Biederman" , Andrey Vagin , Steven Rostedt Subject: Re: frequent softlockups with 3.10rc6. Message-ID: <20130627152151.GA11551@redhat.com> Mail-Followup-To: Dave Jones , Dave Chinner , Oleg Nesterov , "Paul E. McKenney" , Linux Kernel , Linus Torvalds , "Eric W. Biederman" , Andrey Vagin , Steven Rostedt References: <20130623150603.GA32313@redhat.com> <20130623160452.GA11740@redhat.com> <20130624155758.GA5993@redhat.com> <20130624173510.GA1321@redhat.com> <20130625153520.GA7784@redhat.com> <20130626191853.GA29049@redhat.com> <20130627002255.GA16553@redhat.com> <20130627075543.GA32195@dastard> <20130627100612.GA29338@dastard> <20130627125218.GB32195@dastard> MIME-Version: 1.0 Content-Type: text/plain; charset=us-ascii Content-Disposition: inline In-Reply-To: <20130627125218.GB32195@dastard> User-Agent: Mutt/1.5.21 (2010-09-15) Sender: linux-kernel-owner@vger.kernel.org List-ID: X-Mailing-List: linux-kernel@vger.kernel.org Content-Length: 16659 Lines: 261 On Thu, Jun 27, 2013 at 10:52:18PM +1000, Dave Chinner wrote: > > Yup, that's about three of orders of magnitude faster on this > > workload.... > > > > Lightly smoke tested patch below - it passed the first round of > > XFS data integrity tests in xfstests, so it's not completely > > busted... > > And now with even less smoke out that the first version. This one > gets though a full xfstests run... :sadface: [ 567.680836] ====================================================== [ 567.681582] [ INFO: SOFTIRQ-safe -> SOFTIRQ-unsafe lock order detected ] [ 567.682389] 3.10.0-rc7+ #9 Not tainted [ 567.682862] ------------------------------------------------------ [ 567.683607] trinity-child2/8665 [HC0[0]:SC0[0]:HE0:SE1] is trying to acquire: [ 567.684464] (&sb->s_type->i_lock_key#3){+.+...}, at: [] sync_inodes_sb+0x225/0x3b0 [ 567.685632] and this task is already holding: [ 567.686334] (&(&wb->wb_list_lock)->rlock){..-...}, at: [] sync_inodes_sb+0x191/0x3b0 [ 567.687506] which would create a new lock dependency: [ 567.688115] (&(&wb->wb_list_lock)->rlock){..-...} -> (&sb->s_type->i_lock_key#3){+.+...} [ 567.689188] but this new dependency connects a SOFTIRQ-irq-safe lock: [ 567.690137] (&(&wb->wb_list_lock)->rlock){..-...} ... which became SOFTIRQ-irq-safe at: [ 567.691151] [] __lock_acquire+0x595/0x1af0 [ 567.691866] [] lock_acquire+0x91/0x1f0 [ 567.692539] [] _raw_spin_lock+0x40/0x80 [ 567.693798] [] test_clear_page_writeback+0x11e/0x230 [ 567.695193] [] end_page_writeback+0x20/0x50 [ 567.696497] [] end_buffer_async_write+0x1a3/0x2b0 [ 567.697865] [] end_bio_bh_io_sync+0x2c/0x60 [ 567.699164] [] bio_endio+0x1d/0x30 [ 567.700361] [] blk_update_request+0xc2/0x5f0 [ 567.701675] [] blk_update_bidi_request+0x1c/0x80 [ 567.703009] [] blk_end_bidi_request+0x1f/0x60 [ 567.704294] [] blk_end_request+0x10/0x20 [ 567.705524] [] scsi_io_completion+0xf3/0x6e0 [ 567.706791] [] scsi_finish_command+0xb0/0x110 [ 567.708071] [] scsi_softirq_done+0x12f/0x160 [ 567.709339] [] blk_done_softirq+0x88/0xa0 [ 567.710574] [] __do_softirq+0xff/0x440 [ 567.711799] [] irq_exit+0xcd/0xe0 [ 567.712965] [] do_IRQ+0x56/0xc0 [ 567.714108] [] ret_from_intr+0x0/0x13 [ 567.715305] [] __const_udelay+0x29/0x30 [ 567.716514] [] __rcu_read_unlock+0x54/0xa0 [ 567.717753] [] __d_lookup+0x14d/0x320 [ 567.718939] [] lookup_fast+0x16a/0x2d0 [ 567.720129] [] link_path_walk+0x1ab/0x900 [ 567.721350] [] path_openat+0x94/0x530 [ 567.722524] [] do_filp_open+0x38/0x80 [ 567.723701] [] do_sys_open+0xe9/0x1c0 [ 567.724875] [] SyS_open+0x1e/0x20 [ 567.726007] [] tracesys+0xdd/0xe2 [ 567.727138] to a SOFTIRQ-irq-unsafe lock: [ 567.728823] (&sb->s_type->i_lock_key#3){+.+...} ... which became SOFTIRQ-irq-unsafe at: [ 567.730875] ... [] __lock_acquire+0x5e9/0x1af0 [ 567.732150] [] lock_acquire+0x91/0x1f0 [ 567.733339] [] _raw_spin_lock+0x40/0x80 [ 567.734533] [] new_inode_pseudo+0x28/0x60 [ 567.735736] [] new_inode+0x19/0x30 [ 567.736853] [] mount_pseudo+0xb1/0x180 [ 567.738008] [] bd_mount+0x24/0x30 [ 567.739090] [] mount_fs+0x39/0x1b0 [ 567.740172] [] vfs_kern_mount+0x63/0xf0 [ 567.741314] [] kern_mount_data+0x19/0x30 [ 567.742450] [] bdev_cache_init+0x56/0x80 [ 567.743571] [] vfs_caches_init+0x9e/0x115 [ 567.744691] [] start_kernel+0x3a2/0x3fe [ 567.745790] [] x86_64_start_reservations+0x2a/0x2c [ 567.747011] [] x86_64_start_kernel+0xcc/0xcf [ 567.748167] other info that might help us debug this: [ 567.750396] Possible interrupt unsafe locking scenario: [ 567.752062] CPU0 CPU1 [ 567.753025] ---- ---- [ 567.753981] lock(&sb->s_type->i_lock_key#3); [ 567.754969] local_irq_disable(); [ 567.756085] lock(&(&wb->wb_list_lock)->rlock); [ 567.757368] lock(&sb->s_type->i_lock_key#3); [ 567.758642] [ 567.759370] lock(&(&wb->wb_list_lock)->rlock); [ 567.760379] *** DEADLOCK *** [ 567.762337] 2 locks held by trinity-child2/8665: [ 567.763297] #0: (&type->s_umount_key#23){++++..}, at: [] iterate_supers+0x9c/0x110 [ 567.764898] #1: (&(&wb->wb_list_lock)->rlock){..-...}, at: [] sync_inodes_sb+0x191/0x3b0 [ 567.766558] the dependencies between SOFTIRQ-irq-safe lock and the holding lock: [ 567.768362] -> (&(&wb->wb_list_lock)->rlock){..-...} ops: 395 { [ 567.769581] IN-SOFTIRQ-W at: [ 567.770428] [] __lock_acquire+0x595/0x1af0 [ 567.771803] [] lock_acquire+0x91/0x1f0 [ 567.773128] [] _raw_spin_lock+0x40/0x80 [ 567.774457] [] test_clear_page_writeback+0x11e/0x230 [ 567.775923] [] end_page_writeback+0x20/0x50 [ 567.777303] [] end_buffer_async_write+0x1a3/0x2b0 [ 567.778745] [] end_bio_bh_io_sync+0x2c/0x60 [ 567.780125] [] bio_endio+0x1d/0x30 [ 567.781428] [] blk_update_request+0xc2/0x5f0 [ 567.782820] [] blk_update_bidi_request+0x1c/0x80 [ 567.784245] [] blk_end_bidi_request+0x1f/0x60 [ 567.785634] [] blk_end_request+0x10/0x20 [ 567.786971] [] scsi_io_completion+0xf3/0x6e0 [ 567.788349] [] scsi_finish_command+0xb0/0x110 [ 567.789740] [] scsi_softirq_done+0x12f/0x160 [ 567.791140] [] blk_done_softirq+0x88/0xa0 [ 567.792502] [] __do_softirq+0xff/0x440 [ 567.793845] [] irq_exit+0xcd/0xe0 [ 567.795127] [] do_IRQ+0x56/0xc0 [ 567.796375] [] ret_from_intr+0x0/0x13 [ 567.797685] [] __const_udelay+0x29/0x30 [ 567.799016] [] __rcu_read_unlock+0x54/0xa0 [ 567.800381] [] __d_lookup+0x14d/0x320 [ 567.801692] [] lookup_fast+0x16a/0x2d0 [ 567.803013] [] link_path_walk+0x1ab/0x900 [ 567.804361] [] path_openat+0x94/0x530 [ 567.805668] [] do_filp_open+0x38/0x80 [ 567.806974] [] do_sys_open+0xe9/0x1c0 [ 567.808275] [] SyS_open+0x1e/0x20 [ 567.809534] [] tracesys+0xdd/0xe2 [ 567.810809] INITIAL USE at: [ 567.811668] [] __lock_acquire+0x2e5/0x1af0 [ 567.813038] [] lock_acquire+0x91/0x1f0 [ 567.814364] [] _raw_spin_lock+0x40/0x80 [ 567.815688] [] test_set_page_writeback+0x155/0x200 [ 567.817128] [] __block_write_full_page+0x140/0x3a0 [ 567.818565] [] block_write_full_page_endio+0xf9/0x120 [ 567.820035] [] block_write_full_page+0x15/0x20 [ 567.821436] [] blkdev_writepage+0x18/0x20 [ 567.822782] [] __writepage+0x16/0x50 [ 567.824081] [] write_cache_pages+0x27b/0x630 [ 567.825460] [] generic_writepages+0x43/0x60 [ 567.826819] [] do_writepages+0x21/0x50 [ 567.828128] [] __filemap_fdatawrite_range+0x59/0x60 [ 567.829562] [] filemap_write_and_wait_range+0x2d/0x70 [ 567.831010] [] blkdev_fsync+0x1b/0x50 [ 567.832292] [] do_fsync+0x56/0x80 [ 567.833514] [] SyS_fsync+0x10/0x20 [ 567.834741] [] tracesys+0xdd/0xe2 [ 567.835955] } [ 567.836583] ... key at: [] __key.27437+0x0/0x8 [ 567.837800] ... acquired at: [ 567.838584] [] check_irq_usage+0x4a/0xc0 [ 567.839712] [] __lock_acquire+0xe13/0x1af0 [ 567.840877] [] lock_acquire+0x91/0x1f0 [ 567.841991] [] _raw_spin_lock+0x40/0x80 [ 567.843107] [] sync_inodes_sb+0x225/0x3b0 [ 567.844245] [] sync_inodes_one_sb+0x19/0x20 [ 567.845399] [] iterate_supers+0xb2/0x110 [ 567.846526] [] sys_sync+0x35/0x90 [ 567.847580] [] tracesys+0xdd/0xe2 [ 567.849239] the dependencies between the lock to be acquired and SOFTIRQ-irq-unsafe lock: [ 567.851102] -> (&sb->s_type->i_lock_key#3){+.+...} ops: 1230 { [ 567.852314] HARDIRQ-ON-W at: [ 567.853160] [] __lock_acquire+0x5bc/0x1af0 [ 567.854498] [] lock_acquire+0x91/0x1f0 [ 567.855796] [] _raw_spin_lock+0x40/0x80 [ 567.857105] [] new_inode_pseudo+0x28/0x60 [ 567.858437] [] new_inode+0x19/0x30 [ 567.859693] [] mount_pseudo+0xb1/0x180 [ 567.861008] [] bd_mount+0x24/0x30 [ 567.862264] [] mount_fs+0x39/0x1b0 [ 567.863529] [] vfs_kern_mount+0x63/0xf0 [ 567.864846] [] kern_mount_data+0x19/0x30 [ 567.866174] [] bdev_cache_init+0x56/0x80 [ 567.867502] [] vfs_caches_init+0x9e/0x115 [ 567.868830] [] start_kernel+0x3a2/0x3fe [ 567.870125] [] x86_64_start_reservations+0x2a/0x2c [ 567.871554] [] x86_64_start_kernel+0xcc/0xcf [ 567.872906] SOFTIRQ-ON-W at: [ 567.873731] [] __lock_acquire+0x5e9/0x1af0 [ 567.875068] [] lock_acquire+0x91/0x1f0 [ 567.876362] [] _raw_spin_lock+0x40/0x80 [ 567.877669] [] new_inode_pseudo+0x28/0x60 [ 567.878996] [] new_inode+0x19/0x30 [ 567.880251] [] mount_pseudo+0xb1/0x180 [ 567.881560] [] bd_mount+0x24/0x30 [ 567.882802] [] mount_fs+0x39/0x1b0 [ 567.884053] [] vfs_kern_mount+0x63/0xf0 [ 567.885353] [] kern_mount_data+0x19/0x30 [ 567.886659] [] bdev_cache_init+0x56/0x80 [ 567.887964] [] vfs_caches_init+0x9e/0x115 [ 567.889276] [] start_kernel+0x3a2/0x3fe [ 567.890571] [] x86_64_start_reservations+0x2a/0x2c [ 567.891995] [] x86_64_start_kernel+0xcc/0xcf [ 567.893350] INITIAL USE at: [ 567.894182] [] __lock_acquire+0x2e5/0x1af0 [ 567.895503] [] lock_acquire+0x91/0x1f0 [ 567.896782] [] _raw_spin_lock+0x40/0x80 [ 567.898068] [] new_inode_pseudo+0x28/0x60 [ 567.899375] [] new_inode+0x19/0x30 [ 567.900622] [] mount_pseudo+0xb1/0x180 [ 567.901906] [] bd_mount+0x24/0x30 [ 567.903140] [] mount_fs+0x39/0x1b0 [ 567.904379] [] vfs_kern_mount+0x63/0xf0 [ 567.905663] [] kern_mount_data+0x19/0x30 [ 567.906957] [] bdev_cache_init+0x56/0x80 [ 567.908248] [] vfs_caches_init+0x9e/0x115 [ 567.909555] [] start_kernel+0x3a2/0x3fe [ 567.910850] [] x86_64_start_reservations+0x2a/0x2c [ 567.912247] [] x86_64_start_kernel+0xcc/0xcf [ 567.913576] } [ 567.914201] ... key at: [] bd_type+0x68/0x80 [ 567.915389] ... acquired at: [ 567.916163] [] check_irq_usage+0x4a/0xc0 [ 567.917282] [] __lock_acquire+0xe13/0x1af0 [ 567.918426] [] lock_acquire+0x91/0x1f0 [ 567.919527] [] _raw_spin_lock+0x40/0x80 [ 567.920639] [] sync_inodes_sb+0x225/0x3b0 [ 567.921793] [] sync_inodes_one_sb+0x19/0x20 [ 567.922959] [] iterate_supers+0xb2/0x110 [ 567.924087] [] sys_sync+0x35/0x90 [ 567.925140] [] tracesys+0xdd/0xe2 [ 567.926805] stack backtrace: [ 567.928164] CPU: 2 PID: 8665 Comm: trinity-child2 Not tainted 3.10.0-rc7+ #9 [ 567.931829] ffffffff824d5e70 ffff88022fe7db30 ffffffff816df0ad ffff88022fe7dc30 [ 567.933224] ffffffff810b6ee5 0000000000000000 ffffffff00000000 0000000700000001 [ 567.934620] ffff88022fe7db80 ffff88022fe7dbc0 ffffffff81a129af ffff88022fe7db80 [ 567.936023] Call Trace: [ 567.936804] [] dump_stack+0x19/0x1b [ 567.937906] [] check_usage+0x4d5/0x4e0 [ 567.939042] [] ? local_clock+0x3f/0x50 [ 567.940176] [] check_irq_usage+0x4a/0xc0 [ 567.941332] [] __lock_acquire+0xe13/0x1af0 [ 567.942507] [] ? local_clock+0x3f/0x50 [ 567.943643] [] ? wait_for_completion+0x4d/0x110 [ 567.944875] [] ? mark_held_locks+0xbb/0x140 [ 567.946065] [] ? _raw_spin_unlock_irq+0x2c/0x60 [ 567.947296] [] lock_acquire+0x91/0x1f0 [ 567.948430] [] ? sync_inodes_sb+0x225/0x3b0 [ 567.949612] [] _raw_spin_lock+0x40/0x80 [ 567.950752] [] ? sync_inodes_sb+0x225/0x3b0 [ 567.951932] [] sync_inodes_sb+0x225/0x3b0 [ 567.953091] [] ? wait_for_completion+0xdf/0x110 [ 567.954320] [] ? generic_write_sync+0x70/0x70 [ 567.955526] [] sync_inodes_one_sb+0x19/0x20 [ 567.956714] [] iterate_supers+0xb2/0x110 [ 567.957873] [] sys_sync+0x35/0x90 [ 567.958960] [] tracesys+0xdd/0xe2 -- To unsubscribe from this list: send the line "unsubscribe linux-kernel" in the body of a message to majordomo@vger.kernel.org More majordomo info at http://vger.kernel.org/majordomo-info.html Please read the FAQ at http://www.tux.org/lkml/