Return-Path: Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S1757457AbZDWIWV (ORCPT ); Thu, 23 Apr 2009 04:22:21 -0400 Received: (majordomo@vger.kernel.org) by vger.kernel.org id S1757073AbZDWIVt (ORCPT ); Thu, 23 Apr 2009 04:21:49 -0400 Received: from mx3.mail.elte.hu ([157.181.1.138]:43315 "EHLO mx3.mail.elte.hu" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1756287AbZDWIVo (ORCPT ); Thu, 23 Apr 2009 04:21:44 -0400 Date: Thu, 23 Apr 2009 10:20:31 +0200 From: Ingo Molnar To: Steven Rostedt Cc: =?iso-8859-1?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 Message-ID: <20090423082031.GA599@elte.hu> References: <20090420222257.267399830@goodmis.org> <20090421082354.GC12512@elte.hu> <20090421094616.GA14561@elte.hu> MIME-Version: 1.0 Content-Type: text/plain; charset=us-ascii Content-Disposition: inline In-Reply-To: User-Agent: Mutt/1.5.18 (2008-05-17) X-ELTE-VirusStatus: clean X-ELTE-SpamScore: -1.5 X-ELTE-SpamLevel: X-ELTE-SpamCheck: no X-ELTE-SpamVersion: ELTE 2.0 X-ELTE-SpamCheck-Details: score=-1.5 required=5.9 tests=BAYES_00 autolearn=no SpamAssassin version=3.2.3 -1.5 BAYES_00 BODY: Bayesian spam probability is 0 to 1% [score: 0.0000] Sender: linux-kernel-owner@vger.kernel.org List-ID: X-Mailing-List: linux-kernel@vger.kernel.org Content-Length: 12433 Lines: 232 * Steven Rostedt wrote: > 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?? function tracer was active? So somewhere there we corrupted this state? It's unlikely that printk itself did this. Ingo -- 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/