From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S1754308AbZDUNIg (ORCPT ); Tue, 21 Apr 2009 09:08:36 -0400 Received: (majordomo@vger.kernel.org) by vger.kernel.org id S1752306AbZDUNIU (ORCPT ); Tue, 21 Apr 2009 09:08:20 -0400 Received: from hrndva-omtalb.mail.rr.com ([71.74.56.123]:50248 "EHLO hrndva-omtalb.mail.rr.com" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1750874AbZDUNIT (ORCPT ); Tue, 21 Apr 2009 09:08:19 -0400 Date: Tue, 21 Apr 2009 09:08:16 -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?= , linux-kernel@vger.kernel.org, Andrew Morton Subject: Re: [PATCH 0/2] [GIT PULL] tracing: various bug fixes In-Reply-To: <20090421094616.GA14561@elte.hu> 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 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() The warning means that we wrapped the ring buffer before finishing a single commit. But on start up, we only have two pages. This can easily happen if we do not expand the ring buffer before tracing. This warning does not turn off tracing or disable anything else, because it is perfectly valid to happen, but on large ring buffers it could be a sign of something wrong. Maybe I should only warn if the ring buffer has more than two pages? -- Steve > [ 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 >