From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S1756162AbZDQEwl (ORCPT ); Fri, 17 Apr 2009 00:52:41 -0400 Received: (majordomo@vger.kernel.org) by vger.kernel.org id S1751078AbZDQEwd (ORCPT ); Fri, 17 Apr 2009 00:52:33 -0400 Received: from tomts43.bellnexxia.net ([209.226.175.110]:43076 "EHLO tomts43-srv.bellnexxia.net" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1750872AbZDQEwc (ORCPT ); Fri, 17 Apr 2009 00:52:32 -0400 X-IronPort-Anti-Spam-Filtered: true X-IronPort-Anti-Spam-Result: AsAEALeh50lMQW1W/2dsb2JhbACBTs5jg30G Date: Fri, 17 Apr 2009 00:52:29 -0400 From: Mathieu Desnoyers To: Steven Rostedt Cc: Peter Zijlstra , LKML , Ingo Molnar , Andrew Morton , Thomas Gleixner , Frederic Weisbecker , Masami Hiramatsu Subject: Re: [PATCH 2/2] tracing/events/lockdep: move tracepoints within recursive protection Message-ID: <20090417045229.GA30001@Krystal> References: <20090416161543.199331330@goodmis.org> <20090416161746.831882528@goodmis.org> <1239900469.23397.3128.camel@laptop> <1239904428.23397.3278.camel@laptop> Mime-Version: 1.0 Content-Type: text/plain; charset=us-ascii Content-Transfer-Encoding: 7bit Content-Disposition: inline In-Reply-To: X-Editor: vi X-Info: http://krystal.dyndns.org:8080 X-Operating-System: Linux/2.6.21.3-grsec (i686) X-Uptime: 00:44:45 up 48 days, 1:10, 2 users, load average: 0.05, 0.36, 0.42 User-Agent: Mutt/1.5.18 (2008-05-17) Sender: linux-kernel-owner@vger.kernel.org List-ID: X-Mailing-List: linux-kernel@vger.kernel.org * Steven Rostedt (rostedt@goodmis.org) wrote: > > Here's the dump that I get that triggers the lockdep warning: > > WARNING: at kernel/lockdep.c:2893 check_flags+0x1a7/0x1d0() > Hardware name: Precision WorkStation 470 > Modules linked in: radeon drm autofs4 hidp rfcomm l2cap bluetooth sunrpc > > [snip] > > Pid: 3768, comm: sshd Not tainted 2.6.30-rc1 #1036 > Call Trace: > [] warn_slowpath+0xe1/0x110 > [] ? __lock_acquire+0x3ac/0xb20 > [] ? validate_chain+0x4ca/0x12d0 > [] ? validate_chain+0x4ca/0x12d0 > [] ? validate_chain+0x4ca/0x12d0 > [] ? validate_chain+0x4ca/0x12d0 > [] ? __lock_acquire+0x3ac/0xb20 > [] ? __alloc_skb+0x49/0x160 > [] check_flags+0x1a7/0x1d0 > [] lockdep_trace_alloc+0x33/0xe0 > [] kmem_cache_alloc+0x32/0x160 > [] __alloc_skb+0x49/0x160 > [] tcp_send_ack+0x2d/0xe0 > [] __tcp_ack_snd_check+0x61/0xb0 > [] tcp_rcv_established+0x398/0x600 > [] tcp_v4_do_rcv+0x228/0x380 > [] ? ftrace_call+0x5/0x2b > [] ? tcp_prequeue_process+0x2e/0xa0 > [] tcp_prequeue_process+0x6d/0xa0 > [] tcp_recvmsg+0x49a/0x880 > [] sock_common_recvmsg+0x37/0x50 > [] sock_aio_read+0x109/0x110 > [] do_sync_read+0xf1/0x130 > [] ? sched_clock+0x13/0x20 > [] ? native_sched_clock+0x1d/0x50 > [] ? autoremove_wake_function+0x0/0x40 > [] ? ftrace_call+0x5/0x2b > [] ? cap_file_permission+0x9/0x10 > [] ? security_file_permission+0x16/0x20 > [] vfs_read+0x159/0x170 > [] sys_read+0x55/0x90 > [] system_call_fastpath+0x16/0x1b > ---[ end trace 03d889e04bc7a9a7 ]--- > possible reason: unannotated irqs-on. > irq event stamp: 12569 > hardirqs last enabled at (12567): [] local_bh_enable+0xaa/0x110 > hardirqs last disabled at (12569): [] int3+0x16/0x40 > softirqs last enabled at (12566): [] lock_sock_nested+0xfb/0x110 > softirqs last disabled at (12568): [] tcp_prequeue_process+0x2e/0xa0 > > > Note, for some reason we hit int3 ?? > > Tracepoints do not use int3 does it? > Not in your ftrace tree. My LTTng tree includes the immediate values, which brienfly uses the int3 handler when enabling/disabling tracepoints. But this seems unrelated to your problem. > I have kprobes defined but not any kprobe self tests on. > Could this be a userspace breakpoint then ? > Anyway, let me describe what the above is and what I found in my > investigation. > > The lockdep took a check_flags error when it noticed that interrupts were > enabled, but the current->hardirqs_enabled was 0. Lockdep thought > interrupts were disabled but they were in fact enabled. > > > The last 4 lines of the warning have the numbers in the parenthesis > annotate the order of events: (Here they are in order) > > softirqs last enabled at (12566): [] lock_sock_nested+0xfb/0x110 > hardirqs last enabled at (12567): [] local_bh_enable+0xaa/0x110 > softirqs last disabled at (12568): [] tcp_prequeue_process+0x2e/0xa0 > hardirqs last disabled at (12569): [] int3+0x16/0x40 > > The last change that lockdep saw was interrupts being disabled by int3. I > still don't understand why int3 was enabled. I have startup tests for > ftrace and the event tracer, but this blob happened when I first ssh'd > into the box. Also note that maybe some entry.S annotation could be missing, making kallsyms think it was running within int3 when in fact it was running in a different function. I would double-check with objdump givin the ffffffff80610c76 address to make sure. Just giving my 2 cents before going to bed. I don't have any more brain left for tonight. Cheers, Mathieu > > In arch/x86/kernel/entry_64.S we have: > > paranoidzeroentry_ist int3 do_int3 DEBUG_STACK > > .macro paranoidzeroentry sym do_sym > ENTRY(\sym) > INTR_FRAME > PARAVIRT_ADJUST_EXCEPTION_FRAME > pushq $-1 /* ORIG_RAX: no syscall to restart */ > CFI_ADJUST_CFA_OFFSET 8 > subq $15*8, %rsp > call save_paranoid > TRACE_IRQS_OFF > movq %rsp,%rdi /* pt_regs pointer */ > xorl %esi,%esi /* no error code */ > call \do_sym > jmp paranoid_exit /* %ebx: no swapgs flag */ > CFI_ENDPROC > END(\sym) > .endm > > > ENTRY(paranoid_exit) > INTR_FRAME > DISABLE_INTERRUPTS(CLBR_NONE) > TRACE_IRQS_OFF > testl %ebx,%ebx /* swapgs needed? */ > jnz paranoid_restore > testl $3,CS(%rsp) > jnz paranoid_userspace > paranoid_swapgs: > TRACE_IRQS_IRETQ 0 > SWAPGS_UNSAFE_STACK > paranoid_restore: > RESTORE_ALL 8 > jmp irq_return > > > irq_return: > INTERRUPT_RETURN > > > INTERRUPT_RETURN is simply defined as iretq > > > I see that we call TRACE_IRQS_OFF when entering paranoid_exit, but if we > do not need to swapgs (we don't because int3 looks like it happened in > kernel space) we just call irq_return and jump back. We miss the fact that > the irq_return enables interrupts for us. > > I'd try to come up with a fix, but this gets a bit complex, and I figured > I let the lockdep irq-tracing guru's play with this magic. I'm just > reporting the problem ;-) > > -- Steve > -- Mathieu Desnoyers OpenPGP key fingerprint: 8CD5 52C3 8E3C 4140 715F BA06 3F25 A8FE 3BAE 9A68