From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S934071Ab0BYVXk (ORCPT ); Thu, 25 Feb 2010 16:23:40 -0500 Received: from mx2.mail.elte.hu ([157.181.151.9]:34153 "EHLO mx2.mail.elte.hu" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S933961Ab0BYVXb (ORCPT ); Thu, 25 Feb 2010 16:23:31 -0500 Date: Thu, 25 Feb 2010 22:22:26 +0100 From: Ingo Molnar To: "Paul E. McKenney" , Peter Zijlstra Cc: linux-kernel@vger.kernel.org, laijs@cn.fujitsu.com, dipankar@in.ibm.com, akpm@linux-foundation.org, mathieu.desnoyers@polymtl.ca, josh@joshtriplett.org, dvhltc@us.ibm.com, niv@us.ibm.com, tglx@linutronix.de, peterz@infradead.org, rostedt@goodmis.org, Valdis.Kletnieks@vt.edu, dhowells@redhat.com Subject: Re: [PATCH tip/core/rcu 0/21] v6 add lockdep-based diagnostics to rcu_dereference() Message-ID: <20100225212226.GA9134@elte.hu> References: <20100223010435.GA666@linux.vnet.ibm.com> <20100225100022.GA25261@elte.hu> <20100225100147.GA28060@elte.hu> <20100225120444.GA17623@elte.hu> MIME-Version: 1.0 Content-Type: text/plain; charset=us-ascii Content-Disposition: inline In-Reply-To: <20100225120444.GA17623@elte.hu> User-Agent: Mutt/1.5.20 (2009-08-17) X-ELTE-SpamScore: 0.0 X-ELTE-SpamLevel: X-ELTE-SpamCheck: no X-ELTE-SpamVersion: ELTE 2.0 X-ELTE-SpamCheck-Details: score=0.0 required=5.9 tests=none autolearn=no SpamAssassin version=3.2.5 _SUMMARY_ Sender: linux-kernel-owner@vger.kernel.org List-ID: X-Mailing-List: linux-kernel@vger.kernel.org plus there's one with a lockdep warning as well: PM: Adding info for No Bus:vcsa10 eth0: no IPv6 routers present ------------[ cut here ]------------ WARNING: at kernel/softirq.c:143 _local_bh_enable_ip+0x3a/0x9d() Hardware name: System Product Name Modules linked in: Pid: 0, comm: swapper Not tainted 2.6.33-tip-00754-gbd37c01-dirty #18764 Call Trace: [] warn_slowpath_common+0x6a/0x81 [] ? _local_bh_enable_ip+0x3a/0x9d [] ? inet_putpeer+0x4c/0x4f [] warn_slowpath_null+0x12/0x15 [] _local_bh_enable_ip+0x3a/0x9d [] local_bh_enable_ip+0xd/0xf [] _raw_spin_unlock_bh+0x2a/0x2d [] inet_putpeer+0x4c/0x4f [] ipv4_dst_destroy+0x2b/0x44 [] dst_destroy+0x63/0xaf [] dst_free+0x1e/0x29 [] dst_rcu_free+0xd/0xf [] rcu_do_batch+0x91/0x16f [] __rcu_process_callbacks+0x91/0x95 [] rcu_needs_cpu+0x109/0x132 [] tick_nohz_stop_sched_tick+0x15c/0x36f [] cpu_idle+0x78/0xb3 [] rest_init+0x9c/0xa1 [] start_kernel+0x373/0x378 [] i386_start_kernel+0xab/0xb2 ---[ end trace 1110cdd88992d6b2 ]--- ========================================================= [ INFO: possible irq lock inversion dependency detected ] 2.6.33-tip-00754-gbd37c01-dirty #18764 --------------------------------------------------------- swapper/0 just changed the state of lock: (&(&base->lock)->rlock){+.-.-.}, at: [] get_next_timer_interrupt+0x27/0x1ba but this lock was taken by another, HARDIRQ-safe lock in the past: (&(&np->lock)->rlock){-.-...} and interrupts could create inverse lock ordering between them. other info that might help us debug this: no locks held by swapper/0. the shortest dependencies between 2nd lock and 1st lock: -> (&(&np->lock)->rlock){-.-...} ops: 4907 { IN-HARDIRQ-W at: [] mark_irqflags+0x50/0x110 [] __lock_acquire+0x21d/0x3d7 [] lock_acquire+0x92/0xa9 [] _raw_spin_lock+0x23/0x53 [] spin_lock+0xd/0xf [] nv_nic_irq_optimized+0xcf/0x242 [] handle_IRQ_event+0x4b/0xf1 [] handle_fasteoi_irq+0x7b/0xb2 [] handle_irq+0x40/0x4c [] do_IRQ+0x46/0x9f [] common_interrupt+0x35/0x40 IN-SOFTIRQ-W at: [] mark_irqflags+0x6f/0x110 [] __lock_acquire+0x21d/0x3d7 [] lock_acquire+0x92/0xa9 [] _raw_spin_lock_irqsave+0x2c/0x5f [] nv_start_xmit_optimized+0x81/0x406 [] dev_hard_start_xmit+0x141/0x1d3 [] sch_direct_xmit+0x55/0x134 [] dev_queue_xmit+0x241/0x38b [] neigh_resolve_output+0x10d/0x133 [] ip6_output_finish+0x7b/0xb0 [] ip6_output2+0x1d0/0x1d8 [] ip6_output+0xc2/0xc6 [] dst_output+0xe/0x10 [] mld_sendpack+0x1ae/0x2aa [] mld_send_cr+0x1e0/0x1e8 [] mld_ifc_timer_expire+0x10/0x33 [] run_timer_softirq+0x172/0x207 [] __do_softirq+0xb7/0x169 [] do_softirq+0x30/0x48 [] irq_exit+0x3a/0x6d [] smp_apic_timer_interrupt+0x6d/0x7b [] apic_timer_interrupt+0x36/0x40 INITIAL USE at: [] __lock_acquire+0x234/0x3d7 [] lock_acquire+0x92/0xa9 [] _raw_spin_lock_irq+0x29/0x59 [] spin_lock_irq+0xd/0xf [] nv_probe+0xa24/0xe40 [] local_pci_probe+0x13/0x15 [] pci_device_probe+0x48/0x6b [] really_probe+0x8e/0x165 [] driver_probe_device+0x4c/0x82 [] __driver_attach+0x48/0x64 [] bus_for_each_dev+0x42/0x6c [] driver_attach+0x19/0x1b [] bus_add_driver+0xb6/0x200 [] driver_register+0x7e/0xe5 [] __pci_register_driver+0x51/0xae [] init_nic+0x14/0x16 [] do_one_initcall+0x51/0x13b [] do_basic_setup+0x3f/0x52 [] kernel_init+0x6f/0xb0 [] kernel_thread_helper+0x6/0x10 } ... key at: [] __key.40874+0x0/0x8 ... acquired at: [] check_prev_add+0x177/0x1ae [] validate_chain+0x3e5/0x467 [] __lock_acquire+0x360/0x3d7 [] lock_acquire+0x92/0xa9 [] _raw_spin_lock_irqsave+0x2c/0x5f [] lock_timer_base+0x26/0x45 [] __mod_timer+0x27/0x109 [] mod_timer+0x20/0x27 [] nv_open+0x43c/0x45b [] dev_open+0x8b/0xc5 [] dev_change_flags+0x9a/0x149 [] devinet_ioctl+0x22e/0x43f [] inet_ioctl+0x93/0xac [] sock_ioctl+0x1ce/0x1f2 [] vfs_ioctl+0x2c/0x94 [] do_vfs_ioctl+0x267/0x27e [] sys_ioctl+0x46/0x66 [] sysenter_do_call+0x12/0x36 -> (&(&base->lock)->rlock){+.-.-.} ops: 142011 { HARDIRQ-ON-W at: [] mark_irqflags+0xb2/0x110 [] __lock_acquire+0x21d/0x3d7 [] lock_acquire+0x92/0xa9 [] _raw_spin_lock+0x23/0x53 [] get_next_timer_interrupt+0x27/0x1ba [] tick_nohz_stop_sched_tick+0x351/0x36f [] cpu_idle+0x78/0xb3 [] rest_init+0x9c/0xa1 [] start_kernel+0x373/0x378 [] i386_start_kernel+0xab/0xb2 IN-SOFTIRQ-W at: [] mark_irqflags+0x6f/0x110 [] __lock_acquire+0x21d/0x3d7 [] lock_acquire+0x92/0xa9 [] _raw_spin_lock_irq+0x29/0x59 [] run_timer_softirq+0x37/0x207 [] __do_softirq+0xb7/0x169 [] do_softirq+0x30/0x48 [] irq_exit+0x3a/0x6d [] do_IRQ+0x8b/0x9f [] common_interrupt+0x35/0x40 [] __setup_irq+0x1e2/0x26b [] setup_irq+0x1e/0x22 [] setup_default_timer_irq+0xf/0x11 [] hpet_time_init+0x16/0x18 [] x86_late_time_init+0x9/0x10 [] start_kernel+0x2e8/0x378 [] i386_start_kernel+0xab/0xb2 IN-RECLAIM_FS-W at: [] mark_irqflags+0xf9/0x110 [] __lock_acquire+0x21d/0x3d7 [] lock_acquire+0x92/0xa9 [] _raw_spin_lock_irqsave+0x2c/0x5f [] lock_timer_base+0x26/0x45 [] __mod_timer+0x27/0x109 [] schedule_timeout+0x79/0x9d [] kswapd+0xde/0x178 [] kthread+0x6f/0x74 [] kernel_thread_helper+0x6/0x10 INITIAL USE at: [] __lock_acquire+0x234/0x3d7 [] lock_acquire+0x92/0xa9 [] _raw_spin_lock_irqsave+0x2c/0x5f [] lock_timer_base+0x26/0x45 [] __mod_timer+0x27/0x109 [] mod_timer+0x20/0x27 [] con_init+0xa9/0x1cb [] console_init+0x12/0x20 [] start_kernel+0x20d/0x378 [] i386_start_kernel+0xab/0xb2 } ... key at: [] __key.33971+0x0/0x8 ... acquired at: [] check_usage_backwards+0x64/0x6f [] mark_lock_irq+0x5b/0xca [] mark_lock+0xbf/0x12e [] mark_irqflags+0xb2/0x110 [] __lock_acquire+0x21d/0x3d7 [] lock_acquire+0x92/0xa9 [] _raw_spin_lock+0x23/0x53 [] get_next_timer_interrupt+0x27/0x1ba [] tick_nohz_stop_sched_tick+0x351/0x36f [] cpu_idle+0x78/0xb3 [] rest_init+0x9c/0xa1 [] start_kernel+0x373/0x378 [] i386_start_kernel+0xab/0xb2 stack backtrace: Pid: 0, comm: swapper Tainted: G W 2.6.33-tip-00754-gbd37c01-dirty #18764 Call Trace: [] ? printk+0x14/0x16 [] print_irq_inversion_bug+0xde/0xe9 [] check_usage_backwards+0x64/0x6f [] ? dump_trace+0x7b/0xa8 [] mark_lock_irq+0x5b/0xca [] ? check_usage_backwards+0x0/0x6f [] mark_lock+0xbf/0x12e [] mark_irqflags+0xb2/0x110 [] __lock_acquire+0x21d/0x3d7 [] ? get_next_timer_interrupt+0x27/0x1ba [] lock_acquire+0x92/0xa9 [] ? get_next_timer_interrupt+0x27/0x1ba [] _raw_spin_lock+0x23/0x53 [] ? get_next_timer_interrupt+0x27/0x1ba [] get_next_timer_interrupt+0x27/0x1ba [] ? rcu_needs_cpu+0x109/0x132 [] tick_nohz_stop_sched_tick+0x351/0x36f [] cpu_idle+0x78/0xb3 [] rest_init+0x9c/0xa1 [] start_kernel+0x373/0x378 [] i386_start_kernel+0xab/0xb2