Home » Mailing list archives » linux-kernel » 2008 » September » 30

Re: [PATCH 0/6] ftrace: port to the new ring_buffer

Previous thread: [PATCH 4/6] ring_buffer: reset buffer page when freeing by Steven Rostedt on Monday, September 29, 2008 - 8:02 pm. (1 message)

Next thread: [PATCH 1/6] ftrace: give time for wakeup test to run by Steven Rostedt on Monday, September 29, 2008 - 8:02 pm. (1 message)
[view original message]
From: Steven Rostedt
Subject: [PATCH 0/6] ftrace: port to the new ring_buffer
Date: Monday, September 29, 2008 - 8:02 pm

These patches are against linux-tip.

The first is just a fix in the wakeup selftest.

The next is a port of the Unified tracer buffer to linux-tip and some updates.

After that is the ftrace port to use the ring buffer, followed by some
more enhancements to ftrace because of the new variable length
buffer.

I tried a few configurations and tried to test all the different ftrace
tracers, but I'm sure there may be some bugs still to work out. I worked
out all those that I found.

But, with the ring_buffer I can envision several ways to clean up
ftrace and to make adding new tracers cleaner.

I'm also thinking about making a way that each tracer can allocate
its own buffer, and allow for more than one tracer to be running
at the same time! (only with different buffers).

-- Steve

--


[ message continues ]
[view original message]
From: Ingo Molnar
Subject: Re: [PATCH 0/6] ftrace: port to the new ring_buffer
Date: Tuesday, September 30, 2008 - 12:45 am

very nice! I'd expect breakages and complications too so i restructured 
tip/tracing/* a bit: firstly i created a tip/tracing/core append-only 
merge branch which collects all the known-robust bits. Then i created a 
new branch for your new generic ring-buffer feature: 
tip/tracing/ring-buffer, and applied your patches. I've started testing 
it.


yeah. Ideally this should just fall out of the generic framework - i.e. 
tracer plugins should not have to do anything extra to get per tracer 
buffers. They should just add their own specialistic flavor, there 
should be no repetitions otherwise. (barring cases where a tracer wants 
to deviate from default behavior)

	Ingo
--


[ message continues ]
[view original message]
From: Ingo Molnar
Subject: Re: [PATCH 0/6] ftrace: port to the new ring_buffer
Date: Tuesday, September 30, 2008 - 1:23 am

-tip testing found that tip/tracing/ring-buffer causes a new lockdep 
splat:

[    0.000000] Linux version 2.6.27-rc8-tip-00915-g8cb18a9-dirty (mingo@dione)
               (gcc version 4.2.3) #37501 SMP Tue Sep 30 10:10:10 CEST 2008
[...]
[    0.268001] calling  tracer_alloc_buffers+0x0/0x1e5 @ 1
[    0.270983] ------------[ cut here ]------------
[    0.271100] WARNING: at kernel/lockdep.c:2880 check_flags+0x63/0x179()
[    0.271219] Modules linked in:
[    0.271356] Pid: 1, comm: swapper Not tainted 2.6.27-rc8-tip-00915-g8cb18a9-dirty #37501
[    0.271563] Call Trace:
[    0.271678]  [<ffffffff80271d2b>] warn_on_slowpath+0x5d/0x84
[    0.271797]  [<ffffffff80295973>] ? __lock_acquire+0xba4/0xbc5
[    0.271916]  [<ffffffff8029266d>] ? __raw_spin_is_locked+0x17/0x1a
[    0.272001]  [<ffffffff802929cc>] ? graph_unlock+0x79/0x7e
[    0.272001]  [<ffffffff8029449f>] ? mark_lock+0x1c/0x361
[    0.272001]  [<ffffffff8029483a>] ? mark_held_locks+0x56/0x71
[    0.272001]  [<ffffffff802cbb77>] ? time_hardirqs_off+0x12/0x26
[    0.272001]  [<ffffffff802934f1>] ? trace_hardirqs_off_caller+0x21/0xc2
[    0.272001]  [<ffffffff802927c3>] check_flags+0x63/0x179
[    0.272001]  [<ffffffff802966a1>] lock_acquire+0x51/0xc2
[    0.272001]  [<ffffffff816fcead>] _spin_lock+0x36/0x65
[    0.272001]  [<ffffffff802c7511>] ? ring_buffer_reset_cpu+0x47/0x6b
[    0.272001]  [<ffffffff802c7511>] ring_buffer_reset_cpu+0x47/0x6b
[    0.272001]  [<ffffffff802ca33f>] tracing_reset+0xc/0xe
[    0.272001]  [<ffffffff802cd0b4>] boot_trace_init+0x2a/0x46
[    0.272001]  [<ffffffff826817c3>] tracer_alloc_buffers+0x1a7/0x1e5
[    0.272001]  [<ffffffff8268161c>] ? tracer_alloc_buffers+0x0/0x1e5
[    0.272001]  [<ffffffff8020a062>] do_one_initcall+0x62/0x165
[    0.272001]  [<ffffffff816f3291>] ? print_cpu_info+0xab/0x135
[    0.272001]  [<ffffffff8024d8aa>] ? get_apic_id+0x0/0x13
[    0.272001]  [<ffffffff8268161c>] ? tracer_alloc_buffers+0x0/0x1e5
[    0.272001]  [<ffffffff8266190c>] kernel_init+0x60/0x21a
[ ...
[ message continues ]
[view original message]
From: Ingo Molnar
Subject: Re: [PATCH 0/6] ftrace: port to the new ring_buffer
Date: Tuesday, September 30, 2008 - 1:30 am

FYI, triggered on a number of 32-bit test-systems as well - see the log 
below.

	Ingo

[    0.564008] calling  tracer_alloc_buffers+0x0/0x16b @ 1
[    0.574504] ------------[ cut here ]------------
[    0.576002] WARNING: at kernel/lockdep.c:2880 check_flags+0x5a/0x155()
[    0.576002] Modules linked in:
[    0.576002] Pid: 1, comm: swapper Not tainted 2.6.27-rc8-tip-00915-g8cb18a9-dirty #37502
[    0.576002]  [<c01536c4>] warn_on_slowpath+0x46/0x6a
[    0.576002]  [<c0170b14>] ? trace_hardirqs_off+0xb/0xd
[    0.576002]  [<c0173294>] ? __lock_acquire+0xa91/0xaad
[    0.576002]  [<c01a6470>] ? get_page_from_freelist+0x37b/0x455
[    0.576002]  [<c0170044>] ? __raw_spin_is_locked+0x15/0x18
[    0.576002]  [<c0171cf8>] ? find_usage_backwards+0x21/0xe1
[    0.576002]  [<c019f852>] ? time_hardirqs_off+0xe/0x1f
[    0.576002]  [<c0170a66>] ? trace_hardirqs_off_caller+0x15/0xb8
[    0.576002]  [<c0170b14>] ? trace_hardirqs_off+0xb/0xd
[    0.576002]  [<c0120ef0>] ? native_sched_clock+0x83/0x9f
[    0.576002]  [<c0170169>] check_flags+0x5a/0x155
[    0.576002]  [<c01732ec>] lock_acquire+0x3c/0x97
[    0.576002]  [<c14296e9>] _spin_lock+0x23/0x50
[    0.576002]  [<c019bd32>] ? ring_buffer_reset_cpu+0x3f/0x5f
[    0.576002]  [<c019bd32>] ring_buffer_reset_cpu+0x3f/0x5f
[    0.576002]  [<c019e314>] tracing_reset+0xa/0xc
[    0.576002]  [<c01a0b36>] boot_trace_init+0x24/0x3b
[    0.576002]  [<c208577c>] tracer_alloc_buffers+0x137/0x16b
[    0.576002]  [<c010113f>] do_one_initcall+0x57/0x149
[    0.576002]  [<c2085645>] ? tracer_alloc_buffers+0x0/0x16b
[    0.576002]  [<c207bd1c>] ? setup_boot_APIC_clock+0x4b6/0x4cb
[    0.576002]  [<c1421701>] ? print_cpu_info+0x83/0x112
[    0.576002]  [<c2085645>] ? tracer_alloc_buffers+0x0/0x16b
[    0.576002]  [<c206a4c6>] kernel_init+0x54/0x1e2
[    0.576002]  [<c206a472>] ? kernel_init+0x0/0x1e2
[    0.576002]  [<c011cbd3>] kernel_thread_helper+0x7/0x10
[    0.576002]  =======================
[    0.576002] ---[ end trace 4eaa2a86a8e2da22 ...
[ message continues ]
[view original message]
From: Ingo Molnar
Subject: Re: [PATCH 0/6] ftrace: port to the new ring_buffer
Date: Tuesday, September 30, 2008 - 2:13 am

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]  ...
[ message continues ]
[view original message]
From: Steven Rostedt
Subject: Re: [PATCH 0/6] ftrace: port to the new ring_buffer
Date: Tuesday, September 30, 2008 - 5:04 am

Again, I think this is the same issue with the raws?

-- Steve

--


[ message continues ]
[view original message]
From: Steven Rostedt
Subject: Re: [PATCH 0/6] ftrace: port to the new ring_buffer
Date: Tuesday, September 30, 2008 - 5:04 am

I don't even need to look at the configs. There's places I still used the 
"raw_local_irq_save" and that is what in the past has caused this issue.
I'll go and remove those.

-- Steve
--


[ message continues ]
Previous thread: [PATCH 4/6] ring_buffer: reset buffer page when freeing by Steven Rostedt on Monday, September 29, 2008 - 8:02 pm. (1 message)

Next thread: [PATCH 1/6] ftrace: give time for wakeup test to run by Steven Rostedt on Monday, September 29, 2008 - 8:02 pm. (1 message)