Prev: [PATCH] driver core: Early dev_name() support.
Next: IRQ: Fix oneshot irq race between irq_finalize_oneshot and handle_level_irq
From: Hitoshi Mitake on 9 Mar 2010 02:20
On 03/03/10 15:55, Frederic Weisbecker wrote:
> There are rcu locked read side areas in the path where we submit
> a trace event. And these rcu_read_(un)lock() trigger lock events,
> which create recursive events.
>
> One pair in do_perf_sw_event:
>
> __lock_acquire
> |
> |--96.11%-- lock_acquire
> | |
> | |--27.21%-- do_perf_sw_event
> | | perf_tp_event
> | | |
> | | |--49.62%-- ftrace_profile_lock_release
> | | | lock_release
> | | | |
> | | | |--33.85%-- _raw_spin_unlock
>
> Another pair in perf_output_begin/end:
>
> __lock_acquire
> |--23.40%-- perf_output_begin
> | | __perf_event_overflow
> | | perf_swevent_overflow
> | | perf_swevent_add
> | | perf_swevent_ctx_event
> | | do_perf_sw_event
> | | perf_tp_event
> | | |
> | | |--55.37%-- ftrace_profile_lock_acquire
> | | | lock_acquire
> | | | |
> | | | |--37.31%-- _raw_spin_lock
>
> The problem is not that much the trace recursion itself, as we have a
> recursion protection already (though it's always wasteful to recurse).
> But the trace events are outside the lockdep recursion protection, then
> each lockdep event triggers a lock trace, which will trigger two
> other lockdep events. Here the recursive lock trace event won't
> be taken because of the trace recursion, so the recursion stops there
> but lockdep will still analyse these new events:
>
> To sum up, for each lockdep events we have:
>
> lock_*()
> |
> trace lock_acquire
> |
> ----- rcu_read_lock()
> | |
> | lock_acquire()
> | |
> | trace_lock_acquire() (stopped)
> | |
> | lockdep analyze
> |
> ----- rcu_read_unlock()
> |
> lock_release
> |
> trace_lock_release() (stopped)
> |
> lockdep analyze
>
> And you can repeat the above two times as we have two rcu read side
> sections when we submit an event.
>
> This is fixed in this patch by moving the lock trace event under
> the lockdep recursion protection.

Thanks a lot, Frederic!

I tested perf lock with your patch, result is like this,

Typical scores:

before:
% sudo ./perf lock record ./perf bench sched messaging
# Running sched/messaging benchmark...
# 20 sender and receiver processes per group
# 10 groups == 400 processes run

Total time: 3.265 [sec]
[ perf record: Woken up 0 times to write data ]
[ perf record: Captured and wrote 143.952 MB perf.data (~6289344 samples) ]

after:
% sudo ./perf lock record ./perf bench sched messaging
# Running sched/messaging benchmark...
# 20 sender and receiver processes per group
# 10 groups == 400 processes run

Total time: 1.943 [sec] <--- about x1.5 faster!
[ perf record: Woken up 0 times to write data ]
[ perf record: Captured and wrote 98.161 MB perf.data (~4288734 samples)
] <--- size of perf.data is also reduced

--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo(a)vger.kernel.org
More majordomo info at http://vger.kernel.org/majordomo-info.html
Please read the FAQ at http://www.tux.org/lkml/
From: Peter Zijlstra on 10 Mar 2010 10:50
On Wed, 2010-03-10 at 01:05 +0100, Frederic Weisbecker wrote:
> On Tue, Mar 09, 2010 at 09:35:37AM +0100, Jens Axboe wrote:
> > Which, btw, throws a new lockdep warning fest:
> >
> > [ 42.247718] scsi7 : ioc0: LSISAS1068E B3, FwRev=011b0300h,
> Ports=1, MaxQ=483, IRQ=26
> > [ 42.281125] BUG: key ffff880c7cb75250 not in .data!
> > [ 42.288346] ------------[ cut here ]------------
> > [ 42.294490] WARNING: at kernel/lockdep.c:2706 lockdep_init_map
> +0x545/0x5f0()
> > [ 42.304013] Hardware name: QSSC-S4R
> > [ 42.309674] Modules linked in: hid_apple usbhid ehci_hcd uhci_hcd
> usbcore nls_base mptsas(+) mptscsih mptbase scsi_transport_sas igb sg
> sr_mod cdrom
> > [ 42.332072] Pid: 5197, comm: modprobe Not tainted 2.6.34-rc1 #176
> > [ 42.340597] Call Trace:
> > [ 42.345335] [<ffffffff8107fb8d>] ? is_module_address+0x2d/0x60
> > [ 42.353670] [<ffffffff81074aa5>] ? lockdep_init_map+0x545/0x5f0
> > [ 42.362154] [<ffffffff81044648>] warn_slowpath_common+0x78/0xd0
> > [ 42.371913] [<ffffffff810446af>] warn_slowpath_null+0xf/0x20
> > [ 42.380109] [<ffffffff81074aa5>] lockdep_init_map+0x545/0x5f0
>
>
>
> This doesn't look related to my patch, it also happen in -rc1 right?


The per-cpu changes broke lockdep, Tejun already posted patches for
this:

http://lkml.org/lkml/2010/3/10/76
http://lkml.org/lkml/2010/3/10/79


--
To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
the body of a message to majordomo(a)vger.kernel.org
More majordomo info at http://vger.kernel.org/majordomo-info.html
Please read the FAQ at http://www.tux.org/lkml/
 | 
Pages: 1
Prev: [PATCH] driver core: Early dev_name() support.
Next: IRQ: Fix oneshot irq race between irq_finalize_oneshot and handle_level_irq