Return-Path: Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S1753732AbZDWDf1 (ORCPT ); Wed, 22 Apr 2009 23:35:27 -0400 Received: (majordomo@vger.kernel.org) by vger.kernel.org id S1752465AbZDWDfP (ORCPT ); Wed, 22 Apr 2009 23:35:15 -0400 Received: from hrndva-omtalb.mail.rr.com ([71.74.56.122]:53248 "EHLO hrndva-omtalb.mail.rr.com" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1752254AbZDWDfO (ORCPT ); Wed, 22 Apr 2009 23:35:14 -0400 Date: Wed, 22 Apr 2009 23:35:10 -0400 (EDT) From: Steven Rostedt X-X-Sender: rostedt@gandalf.stny.rr.com To: Ingo Molnar cc: =?ISO-8859-15?Q?Fr=E9d=E9ric_Weisbecker?= , LKML , Andrew Morton , Glauber de Oliveira Costa , Chris Wright , Jeremy Fitzhardinge , Rusty Russell , Pekka Enberg Subject: Re: [PATCH 0/2] [GIT PULL] tracing: various bug fixes In-Reply-To: Message-ID: References: <20090420222257.267399830@goodmis.org> <20090421082354.GC12512@elte.hu> <20090421094616.GA14561@elte.hu> User-Agent: Alpine 2.00 (DEB 1167 2008-08-23) MIME-Version: 1.0 Content-Type: TEXT/PLAIN; charset=US-ASCII Sender: linux-kernel-owner@vger.kernel.org List-ID: X-Mailing-List: linux-kernel@vger.kernel.org Content-Length: 12596 Lines: 255 On Wed, 22 Apr 2009, Steven Rostedt wrote: > > > On Tue, 21 Apr 2009, Ingo Molnar wrote: > > > > > * Ingo Molnar wrote: > > > > > Pulled, thanks guys! I've reactivated the self-tests in tip:master > > > - lets see how it goes today. > > > > i'm still getting a ring-buffer warning - see below. Config > > attached. > > > > Ingo > > > > [ 7.671145] calling clear_boot_tracer+0x0/0x52 @ 1 > > [ 7.672145] initcall clear_boot_tracer+0x0/0x52 returned 0 after 0 usecs > > [ 7.673145] calling event_trace_self_tests_init+0x0/0x5f @ 1 > > [ 7.674206] Running tests on trace events: > > [ 7.675143] Testing event kfree_skb: OK > > [ 7.680145] Testing event kmalloc: OK > > [ 7.683819] Testing event kmem_cache_alloc: OK > > [ 7.686755] Testing event kmalloc_node: OK > > [ 7.689744] Testing event kmem_cache_alloc_node: OK > > [ 7.692711] Testing event kfree: OK > > [ 7.695712] Testing event kmem_cache_free: OK > > [ 7.698744] Testing event irq_handler_exit: OK > > [ 7.701724] Testing event irq_handler_entry: OK > > [ 7.704710] Testing event softirq_entry: OK > > [ 7.707743] Testing event softirq_exit: OK > > [ 7.710768] Testing event lock_acquired: OK > > [ 7.713738] Testing event lock_acquire: OK > > [ 7.716782] Testing event lock_release: OK > > [ 7.719771] Testing event lock_contended: OK > > [ 7.722740] Testing event sched_kthread_stop: OK > > [ 7.726741] Testing event sched_kthread_stop_ret: OK > > [ 7.729710] Testing event sched_wait_task: OK > > [ 7.732706] Testing event sched_wakeup: OK > > [ 7.735713] Testing event sched_wakeup_new: OK > > [ 7.738727] Testing event sched_switch: OK > > [ 7.741724] Testing event sched_migrate_task: OK > > [ 7.745711] Testing event sched_process_free: OK > > [ 7.749704] Testing event sched_process_exit: OK > > [ 7.753699] Testing event sched_process_wait: OK > > [ 7.757692] Testing event sched_process_fork: OK > > [ 7.761711] Testing event sched_signal_send: OK > > [ 7.764709] Running tests on trace event systems: > > [ 7.765144] Testing event system skb: OK > > [ 7.768776] Testing event system kmem: OK > > [ 7.771817] Testing event system irq: OK > > [ 7.774778] Testing event system lockdep: OK > > [ 7.777921] Testing event system sched: OK > > [ 7.780902] Running tests on all trace events: > > [ 7.781148] Testing all events: OK > > [ 7.787765] Running tests again, along with the function tracer > > [ 7.788156] Running tests on trace events: > > [ 7.789154] Testing event kfree_skb: OK > > [ 7.792858] Testing event kmalloc: OK > > [ 7.795853] Testing event kmem_cache_alloc: OK > > [ 7.799848] Testing event kmalloc_node: OK > > [ 7.802966] Testing event kmem_cache_alloc_node: OK > > [ 7.805970] Testing event kfree: OK > > [ 7.808942] Testing event kmem_cache_free: OK > > [ 7.812935] Testing event irq_handler_exit: OK > > [ 7.815850] Testing event irq_handler_entry: OK > > [ 7.818877] Testing event softirq_entry: OK > > [ 7.822846] Testing event softirq_exit: OK > > [ 7.825895] Testing event lock_acquired: OK > > [ 7.830045] Testing event lock_acquire: OK > > [ 7.834025] Testing event lock_release: OK > > [ 7.837920] Testing event lock_contended: OK > > [ 7.841854] Testing event sched_kthread_stop: OK > > [ 7.844883] Testing event sched_kthread_stop_ret: OK > > [ 7.847850] Testing event sched_wait_task: OK > > [ 7.851938] Testing event sched_wakeup: OK > > [ 7.855960] Testing event sched_wakeup_new: OK > > [ 7.858884] Testing event sched_switch: OK > > [ 7.861941] Testing event sched_migrate_task: OK > > [ 7.864972] Testing event sched_process_free: OK > > [ 7.867853] Testing event sched_process_exit: OK > > [ 7.870890] Testing event sched_process_wait: OK > > [ 7.873856] Testing event sched_process_fork: OK > > [ 7.876930] Testing event sched_signal_send: OK > > [ 7.879853] Running tests on trace event systems: > > [ 7.880154] Testing event system skb: OK > > [ 7.883940] Testing event system kmem: OK > > [ 7.888105] Testing event system irq: OK > > [ 7.892085] Testing event system lockdep: OK > > [ 7.896154] Testing event system sched: OK > > [ 7.901156] Running tests on all trace events: > > [ 7.903170] Testing all events: <4>------------[ cut here ]------------ > > [ 7.909137] WARNING: at kernel/trace/ring_buffer.c:1245 __rb_reserve_next+0x130/0x40c() > > [ 7.909137] Modules linked in: > > [ 7.909137] Pid: 0, comm: swapper Not tainted 2.6.30-rc2-tip #38087 > > [ 7.909137] Call Trace: > > [ 7.909137] [] warn_slowpath+0xca/0x115 > > [ 7.909137] [] ? __rb_reserve_next+0x2a5/0x40c > > [ 7.909137] [] ? native_sched_clock+0x4f/0x6a > > [ 7.909137] [] ? native_sched_clock+0x4f/0x6a > > [ 7.909137] [] ? native_sched_clock+0x4f/0x6a > > [ 7.909137] [] ? __rb_reserve_next+0x6d/0x40c > > [ 7.909137] [] ? time_hardirqs_off+0x31/0x47 > > [ 7.909137] [] __rb_reserve_next+0x130/0x40c > > [ 7.909137] [] rb_reserve_next_event+0x1d3/0x31a > > [ 7.909137] [] ring_buffer_lock_reserve+0x16b/0x1cb > > [ 7.909137] [] trace_buffer_lock_reserve+0x34/0x7e > > [ 7.909137] [] trace_vbprintk+0x136/0x275 > > [ 7.909137] [] ? trace_hardirqs_on_caller+0x132/0x18e > > [ 7.909137] [] ? lock_acquire+0x74/0x15b > > [ 7.909137] [] __trace_bprintk+0x80/0x9d > > [ 7.909137] [] ? run_timer_softirq+0x16f/0x281 > > [ 7.909137] [] ? __trace_bprintk+0x80/0x9d > > [ 7.909137] [] ? put_lock_stats+0x44/0x5a > > [ 7.909137] [] ? tracing_record_cmdline+0x3d/0x141 > > [ 7.909137] [] ? run_timer_softirq+0x16f/0x281 > > [ 7.909137] [] ftrace_event_lock_acquire+0x6a/0x89 > > [ 7.909137] [] ? run_timer_softirq+0x226/0x281 > > [ 7.909137] [] lock_acquire+0x74/0x15b > > [ 7.909137] [] ? run_timer_softirq+0x226/0x281 > > [ 7.909137] [] ? process_timeout+0x0/0x37 > > [ 7.909137] [] _spin_lock_irq+0x5c/0xa5 > > [ 7.909137] [] ? run_timer_softirq+0x226/0x281 > > [ 7.909137] [] run_timer_softirq+0x226/0x281 > > [ 7.909137] [] ? run_timer_softirq+0x16f/0x281 > > [ 7.909137] [] ? ftrace_call+0x5/0x2b > > [ 7.909137] [] __do_softirq+0xff/0x22c > > [ 7.909137] [] call_softirq+0x1c/0x30 > > [ 7.909137] [] do_softirq+0x5f/0xdb > > [ 7.909137] [] irq_exit+0x5d/0x7d > > [ 7.909137] [] do_IRQ+0xbe/0xeb > > [ 7.909137] [] ret_from_intr+0x0/0x16 > > [ 7.909137] [] ? __rb_reserve_next+0x50/0x40c > > [ 7.909137] [] ? rb_reserve_next_event+0x1d3/0x31a > > [ 7.909137] [] ? rb_reserve_next_event+0x1d3/0x31a > > [ 7.909137] [] ? ring_buffer_lock_reserve+0x16b/0x1cb > > [ 7.909137] [] ? trace_buffer_lock_reserve+0x34/0x7e > > [ 7.909137] [] ? test_ti_thread_flag+0x8/0x38 > > [ 7.909137] [] ? trace_current_buffer_lock_reserve+0x36/0x4c > > [ 7.909137] [] ? function_test_events_call+0x8f/0x12e > > [ 7.909137] [] ? need_resched+0x36/0x54 > > [ 7.909137] [] ? function_test_events_call+0xb9/0x12e > > [ 7.909137] [] ? ftrace_call+0x5/0x2b > > [ 7.909137] [] ? test_ti_thread_flag+0xd/0x38 > > [ 7.909137] [] ? need_resched+0x36/0x54 > > [ 7.909137] [] ? poll_idle+0x41/0x64 > > [ 7.909137] [] ? stop_critical_timings+0x3d/0x54 > > [ 7.909137] [] ? cpu_idle+0xb1/0x112 > > [ 7.909137] [] ? rest_init+0x8d/0xa3 > > [ 7.909137] [] ? start_kernel+0x49c/0x4bd > > [ 7.909137] [] ? early_idt_handler+0x0/0x71 > > [ 7.909137] [] ? x86_64_start_reservations+0xb9/0xd4 > > [ 7.909137] [] ? _sinittext+0x0/0x140 > > [ 7.909137] [] ? x86_64_start_kernel+0x158/0x17b > > [ 7.909137] ---[ end trace 3b85485e39bcb7cf ]--- > > [ 7.912099] OK > > [ 7.913421] initcall event_trace_self_tests_init+0x0/0x5f returned 0 after 233398 usecs > > [ 7.914172] calling random32_reseed+0x0/0xce @ 1 > > [ 7.915159] initcall random32_reseed+0x0/0xce returned 0 after 0 usecs > > [ 7.916145] calling pci_resource_alignment_sysfs_init+0x0/0x40 @ 1 > > > > I spent the entire day (and half the night) debugging this. I was fighting > a case where the hardirqs_enabled flag in the task struct (lockdep flag) > was mysteriously being set and cleared. I stepped through the entire > kernel thread fork process (that was an exercise) and could not find > anything wrong. > > Sometimes it would go away with printk's sometimes it would not. This was > driving me crazy, until I noticed that paravirt was enabled. > > Turning off paravirtualization here (so far) makes everything run > smoothly. > > Thus my theory is that there's something fishy with the modifying of the > irq enable/disable code when the system detects that it is running on bare > hardware. > > I'm too tired to look at this more. Ingo supplied a config to play with. > You can disable VSMP too and it will still trigger the crash. > OK, after spending two full days doing a config bisect to find out what is happening, I've found that CONFIG_PARAVIRT and CONFIG_DEBUG_PAGEALLOC do not play nicely. But I have yet to find out why. Here's the situation: We've added selftests for the event tracer. What this basically does is enables each event one at a time and runs tests. The tests include creating a kernel thread, executing workqueues and grabbing locks. We also have PROVE_LOCKING (LOCKDEP) enabled, that keeps track of interrupts being enabled. When they are, we set a flag in the task struct "hardirqs_enabled". When they are disabled, this flag is cleared. When we fork a process, a test is made to see if the flag is set for the new process and if it is not, a warning is printed (as is done in the above dump). I investigated this and found that the flag is mysteriously being set and cleared for no apparent reason. The flag is in the task struct and nothing should be touching it. In fact, it is a full int, not even a bit in a flags variable. I had a test that would print the flag and irqs_disabled() in copy_process before the warning and it showed that the flag was cleared but irqs was enabled. The funny part is, I if the test triggered, I printed the flag again, and the second print it was set again!! if (!p->hardirqs_enabled) { printk("irqs:%d flag:%d\n", irqs_disabled(), p->hardirqs_enabled); printk("try again: %d\n", p->hardirqs_enabled); } The first print showed that it was cleared, the second showed it was set again?? To trigger this I need these config options set: CONFIG_EVENT_TRACING CONFIG_FUNCTION_TRACER CONFIG_PROVE_LOCKING CONFIG_PARAVIRT CONFIG_DEBUG_PAGEALLOC CONFIG_EVENT_TRACING is needed because it does the tests. CONFIG_PROVE_LOCKING is needed because it is the trigger to the WARN_ON (the test for hardirqs_enabled being cleared) CONFIG_FUNCTION_TRACER may be part of the problem, or it just changes the way things work to cause it. CONFIG_PARAVIRT and CONFIG_DEBUG_PAGEALLOC, disable either of them, the problem goes away :-/ Also note, when I did the printks to find where the hardirqs_enabled went zero, it would consistantly happen after this call: ti = alloc_thread_info(tsk); I'll see if I can find exactly where it happens :-/ -- Steve -- 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/