lkml.org 
[lkml]   [2008]   [Sep]   [30]   [last100]   RSS Feed
Views: [wrap][no wrap]   [headers]  [forward] 
 
Messages in this thread
/
Date
From
SubjectRe: [PATCH 0/6] ftrace: port to the new ring_buffer

ok, -tip testing found a serious-looking locking bug:

[ 4.044005] calling init_irqsoff_tracer+0x0/0x11 @ 1
[ 4.048005] Testing tracer irqsoff:
[ 4.056202] =============================================
[ 4.060000] [ INFO: possible recursive locking detected ]
[ 4.060000] 2.6.27-rc8-tip-00917-g01214de-dirty #37512
[ 4.060000] ---------------------------------------------
[ 4.060000] swapper/1 is trying to acquire lock:
[ 4.060000] (&cpu_buffer->lock){++..}, at: [<c015a216>] ring_buffer_lock+0x3b/0x50
[ 4.060000]
[ 4.060000] but task is already holding lock:
[ 4.060000] (&cpu_buffer->lock){++..}, at: [<c015a216>] ring_buffer_lock+0x3b/0x50
[ 4.060000]
[ 4.060000] other info that might help us debug this:
[ 4.060000] 3 locks held by swapper/1:
[ 4.060000] #0: (trace_types_lock){--..}, at: [<c015d758>] register_tracer+0x2f/0x14f
[ 4.060000] #1: (max_trace_lock){....}, at: [<c015eab0>] check_critical_timing+0x5d/0x113
[ 4.060000] #2: (&cpu_buffer->lock){++..}, at: [<c015a216>] ring_buffer_lock+0x3b/0x50
[ 4.060000]
[ 4.060000] stack backtrace:
[ 4.060000] Pid: 1, comm: swapper Not tainted 2.6.27-rc8-tip-00917-g01214de-dirty #37512
[ 4.060000] [<c014446d>] validate_chain+0x4e9/0xb4c
[ 4.060000] [<c0108b54>] ? native_sched_clock+0xe2/0x101
[ 4.060000] [<c014519a>] __lock_acquire+0x6ca/0x730
[ 4.060000] [<c014525b>] lock_acquire+0x5b/0x81
[ 4.060000] [<c015a216>] ? ring_buffer_lock+0x3b/0x50
[ 4.060000] [<c05908cf>] _spin_lock+0x23/0x50
[ 4.060000] [<c015a216>] ? ring_buffer_lock+0x3b/0x50
[ 4.060000] [<c015a216>] ring_buffer_lock+0x3b/0x50
[ 4.060000] [<c015a2b3>] ring_buffer_reset+0x16/0x46
[ 4.060000] [<c015e16f>] update_max_tr_single+0x65/0xc0
[ 4.060000] [<c015eb15>] check_critical_timing+0xc2/0x113
[ 4.060000] [<c015d270>] ? trace_selftest_startup_irqsoff+0x49/0xac
[ 4.060000] [<c015d270>] ? trace_selftest_startup_irqsoff+0x49/0xac
[ 4.060000] [<c015ec0c>] time_hardirqs_on+0xa6/0xb9
[ 4.060000] [<c014393c>] ? trace_hardirqs_on+0xb/0xd
[ 4.060000] [<c01437fb>] trace_hardirqs_on_caller+0x16/0x14c
[ 4.060000] [<c014393c>] trace_hardirqs_on+0xb/0xd
[ 4.060000] [<c015d270>] trace_selftest_startup_irqsoff+0x49/0xac
[ 4.060000] [<c0128ba9>] ? printk+0x1a/0x1c
[ 4.060000] [<c015d7f1>] register_tracer+0xc8/0x14f
[ 4.060000] [<c08803fc>] init_irqsoff_tracer+0xd/0x11
[ 4.060000] [<c010104f>] do_one_initcall+0x4f/0x130
[ 4.060000] [<c08803ef>] ? init_irqsoff_tracer+0x0/0x11
[ 4.060000] [<c0121390>] ? wake_up_process+0xf/0x11
[ 4.060000] [<c0134ab2>] ? start_workqueue_thread+0x22/0x25
[ 4.060000] [<c0134d99>] ? __create_workqueue_key+0xa9/0x141
[ 4.060000] [<c086c5c3>] kernel_init+0x17b/0x1e2
[ 4.060000] [<c086c448>] ? kernel_init+0x0/0x1e2
[ 4.060000] [<c0104ab3>] kernel_thread_helper+0x7/0x10
[ 4.060000] =======================
[ 4.064053] PASSED
[ 4.066133] initcall init_irqsoff_tracer+0x0/0x11 returned 0 after 15 msecs
[ 4.068005] calling init_wakeup_tracer+0x0/0xf @ 1

Ingo


\
 
 \ /
  Last update: 2008-09-30 11:15    [W:0.111 / U:0.112 seconds]
©2003-2020 Jasper Spaans|hosted at Digital Ocean and TransIP|Read the blog|Advertise on this site