tracing: use raw spinlocks instead of spinlocks
Subsystems (3)
PATCH 1/1 tracing: use raw spinlocks instead of spinlocks
When I tried to figure out why my experimental function's return tracer was hanging, I discovered that it was partially caused by the fact that the ring buffer might use the usual spinlocks during entry insertion.
ring_buffer_lock_reserve() -> rb_reserve_next_event() -> __rb_reserve_next() -> spin_lock_irqsave()
Since this last function is traced, the result is a recursion during the trace. I guess it happens too with the function tracer.
We should use the raw_spin_locks which are not traced.
--- kernel/trace/ring_buffer.c | 33 ++++++++++++++++++++------------- 1 files changed, 20 insertions(+), 13 deletions(-)
kernel/trace/ring_buffer.c +20 -13
@@ -152,7 +152,7 @@ static inline int test_time_stamp(u64 delta)struct ring_buffer_per_cpu {int cpu;struct ring_buffer *buffer; -spinlock_t lock; +raw_spinlock_t lock;struct lock_class_key lock_key;struct list_head pages;struct buffer_page *head_page;/* read from head */
@@ -289,7 +289,7 @@ rb_allocate_cpu_buffer(struct ring_buffer *buffer, int cpu) cpu_buffer->cpu = cpu; cpu_buffer->buffer = buffer; -spin_lock_init (&cpu_buffer->lock); + cpu_buffer->lock = (raw_spinlock_t )__RAW_SPIN_LOCK_UNLOCKED;INIT_LIST_HEAD (&cpu_buffer->pages); page = kzalloc_node(ALIGN(sizeof(*page), cache_line_size()),
@@ -851,8 +851,8 @@ __rb_reserve_next(struct ring_buffer_per_cpu *cpu_buffer,/* See if we shot pass the end of this buffer page */ if (write >BUF_PAGE_SIZE ) {struct buffer_page *next_page = tail_page; - -spin_lock_irqsave (&cpu_buffer->lock, flags); +raw_local_irq_save (flags); +__raw_spin_lock (&cpu_buffer->lock);rb_inc_page (cpu_buffer, &next_page);
@@ -927,8 +927,8 @@ __rb_reserve_next(struct ring_buffer_per_cpu *cpu_buffer, tail == rb_commit_index(cpu_buffer)) {rb_set_commit_to_write (cpu_buffer); } - -spin_unlock_irqrestore (&cpu_buffer->lock, flags); +__raw_spin_unlock (&cpu_buffer->lock); +raw_local_irq_restore (flags);/* fail and let the caller try again */ return ERR_PTR (-EAGAIN );
@@ -951,7 +951,8 @@ __rb_reserve_next(struct ring_buffer_per_cpu *cpu_buffer,return event; out_unlock: -spin_unlock_irqrestore (&cpu_buffer->lock, flags); +__raw_spin_unlock (&cpu_buffer->lock); +raw_local_irq_restore (flags);return NULL ; }
@@ -1533,7 +1534,8 @@ rb_get_reader_page(struct ring_buffer_per_cpu *cpu_buffer)struct buffer_page *reader =NULL ;unsigned long flags; -spin_lock_irqsave (&cpu_buffer->lock, flags); +raw_local_irq_save (flags); +__raw_spin_lock (&cpu_buffer->lock); again: reader = cpu_buffer->reader_page;
@@ -1583,7 +1585,8 @@ rb_get_reader_page(struct ring_buffer_per_cpu *cpu_buffer) goto again; out: -spin_unlock_irqrestore (&cpu_buffer->lock, flags); +__raw_spin_unlock (&cpu_buffer->lock); +raw_local_irq_restore (flags);return reader; }
@@ -1824,9 +1827,11 @@ ring_buffer_read_start(struct ring_buffer *buffer, int cpu)atomic_inc (&cpu_buffer->record_disabled);synchronize_sched (); -spin_lock_irqsave (&cpu_buffer->lock, flags); +raw_local_irq_save (flags); +__raw_spin_lock (&cpu_buffer->lock);ring_buffer_iter_reset (iter); -spin_unlock_irqrestore (&cpu_buffer->lock, flags); +__raw_spin_unlock (&cpu_buffer->lock); +raw_local_irq_restore (flags);return iter; }
@@ -1912,11 +1917,13 @@ void ring_buffer_reset_cpu(struct ring_buffer *buffer, int cpu)if (!cpu_isset (cpu, buffer->cpumask))return ; -spin_lock_irqsave (&cpu_buffer->lock, flags); +raw_local_irq_save (flags); +__raw_spin_lock (&cpu_buffer->lock);rb_reset_cpu (cpu_buffer); -spin_unlock_irqrestore (&cpu_buffer->lock, flags); +__raw_spin_unlock (&cpu_buffer->lock); +raw_local_irq_restore (flags); }/**
Steven Rostedt
maintainerQuoted 4 lines · Frederic Weisbecker
When I tried to figure out why my experimental function's return tracer was hanging, I discovered that it was partially caused by the fact that the ring buffer might use the usual spinlocks during entry insertion.
Quoted 8 lines
ring_buffer_lock_reserve()->rb_reserve_next_event()->__rb_reserve_next()->spin_lock_irqsave()Since this last function is traced, the result is a recursion during the trace. I guess it happens too with the function tracer.
We should use the
raw_spin_lockswhich are not traced.Signed-off-by Frederic Weisbecker <[email protected]>
Frederic,
Ingo has been very adamant about not using raw_spin_locks in the ring buffers. My original code did this, and he nacked it. The reason being (and he eventually convinced me) was that by using raw, we not only do not trace the locking, we also remove the lock checking. This code can easily produce deadlocks, so we do not want the lock checking removed.
The real fix is to find a way in your tracer to detect the recursion, and be able to prevent it. Like the atomic disables I use in ftrace. It does the same thing. It leaves the lockdep checking on its own locks, but can also detect if the lock checking caused it to recurse. When the recusion is detected, the tracer itself will not trace.
[ I hope this makes sense, I'm writing this on 3 hours of sleep ]
Thanks,
-- Steve
2008/11/3 Steven Rostedt <[email protected]>:
Quoted 7 lines
Frederic,
Ingo has been very adamant about not using
raw_spin_locksin the ring buffers. My original code did this, and he nacked it. The reason being (and he eventually convinced me) was that by using raw, we not only do not trace the locking, we also remove the lock checking. This code can easily produce deadlocks, so we do not want the lock checking removed.
Ok. I understand...
Quoted 5 lines
The real fix is to find a way in your tracer to detect the recursion, and be able to prevent it. Like the atomic disables I use in ftrace. It does the same thing. It leaves the lockdep checking on its own locks, but can also detect if the lock checking caused it to recurse. When the recusion is detected, the tracer itself will not trace.
You mean this part in function_trace_call?
disabled = atomic_inc_return(&data->disabled);
if (likely(disabled == 1))
trace_function(tr, data, ip, parent_ip, flags, pc);
atomic_dec(&data->disabled);
That's a good idea. Since it applies on one cpu_data specific and preempt and irq are disabled, the function
tracer doesn't risk to loose a trace. I think I will apply the same method.
Thanks!
Quoted 1 line
[ I hope this makes sense, I'm writing this on 3 hours of sleep ]
Yes, don't worry :-)
Quoted 26 lines · Steven Rostedt
Quoted 8 lines · Frederic Weisbecker
When I tried to figure out why my experimental function's return tracer was hanging, I discovered that it was partially caused by the fact that the ring buffer might use the usual spinlocks during entry insertion.
ring_buffer_lock_reserve()->rb_reserve_next_event()->__rb_reserve_next()->spin_lock_irqsave()Quoted 6 lines
Since this last function is traced, the result is a recursion during the trace. I guess it happens too with the function tracer.
We should use the
raw_spin_lockswhich are not traced.Signed-off-by Frederic Weisbecker <[email protected]>Frederic,
Ingo has been very adamant about not using
raw_spin_locksin the ring buffers. My original code did this, and he nacked it. The reason being (and he eventually convinced me) was that by using raw, we not only do not trace the locking, we also remove the lock checking. This code can easily produce deadlocks, so we do not want the lock checking removed.
Quoted 6 lines
The real fix is to find a way in your tracer to detect the recursion, and be able to prevent it. Like the atomic disables I use in ftrace. It does the same thing. It leaves the lockdep checking on its own locks, but can also detect if the lock checking caused it to recurse. When the recusion is detected, the tracer itself will not trace.
i'm wondering, does the changing to raw-spinlocks fix the deadlock? It's generally just the lack of recursion checking that is causing lockdep troubles - and recursion checking we want for all the more intrusive ftrace plugins anyway.
Frederic, do you have trouble finding the source of the deadlock? In theory the NMI watchdog should be able to punch through it. (if not then we need to improve things so that it can)
Ingo
2008/11/3 Ingo Molnar <[email protected]>:
Quoted 1 line
i'm wondering, does the changing to raw-spinlocks fix the deadlock?
Yes. The real problem was that insertion hold a spinlock, and then the spinlock was traced, and then it could hold anymore the spinlock in insertion ....deadlock.
It fixed the problem with this solution.
Quoted 3 lines
It's generally just the lack of recursion checking that is causing lockdep troubles - and recursion checking we want for all the more intrusive ftrace plugins anyway.
This problem wasn't lockdep relative. _But_ I had to deactivate lockdep for my plugin to work. It seems there are some deadlock encountered with lockdep enabled but I'm not sure why...
But of course it's just to make easy its implementation, I will adapt it to rely on lockdep
in the end.
Quoted 3 lines
Frederic, do you have trouble finding the source of the deadlock? In theory the NMI watchdog should be able to punch through it. (if not then we need to improve things so that it can)
I haven't any deadlock more (I hope) since I implemented the solution of Steven (
and deactivated lockdep). But I discovered other problems that seem to rely on page
faults (or it causes them). But I'm not sure yet, it was late at night. I went to bed after some awful Oops.
The good news is that I now have backtraces to debug it :-)
2008/11/3 Ingo Molnar <[email protected]>:
Quoted 3 lines
Frederic, do you have trouble finding the source of the deadlock? In theory the NMI watchdog should be able to punch through it. (if not then we need to improve things so that it can)
Ok...actually I still have a deadlock. Or it seems to. I launch the return tracer and then...the system
can block after several seconds, typically after I try to write some characters on the terminal.
It happens more easily on SMP.
I enabled all I could for lock debugging, but I don't have any errors printed... Lockdep uses an NMI wachdog?
Quoted 5 lines · Frédéric Weisbecker
2008/11/3 Ingo Molnar <[email protected]>:
Quoted 3 lines
Frederic, do you have trouble finding the source of the deadlock? In theory the NMI watchdog should be able to punch through it. (if not then we need to improve things so that it can)
Quoted 8 lines
Ok...actually I still have a deadlock. Or it seems to. I launch the return tracer and then...the system can block after several seconds, typically after I try to write some characters on the terminal.
It happens more easily on SMP.
I enabled all I could for lock debugging, but I don't have any errors printed... Lockdep uses an NMI wachdog?
lockdep works via a completely different principle: it instruments all the actual lock acquire/release calls and builds a graph of lock dependencies in the system, as it happens.
It also guarantees that all the observed locking rules are followed (i.e. it proves that as long as you dont get any messages from lockdep, all the locking patterns are mathematically safe).
So a lockdep message will most of the time occur much easier than a real lockup would occur - as lockdep only needs to observe inconsistent locking patterns to prove that a lockup _could_ occur.
The NMI watchdog just observes the system and complains if it sees hardirqs not progressing (i.e. a hard lockup). It will detect anything that causes a hard lockup. (assuming that the NMI watchdog itself is not locked up)
Regarding your lockup ... it's quite hard. Maybe you can get more output out of the system by using:
earlyprintk=vga,keep
plus disablig regular tty output. (i.e. not passing any 'console=tty' line to the kernel bootup.)
this way you wont get any normal printk activities (which might lock up), you should only get the very simple early-printk output.
it is also probably useful to mark the early-printk code notrace in arch/x86/kernel/Makefile, via the patch below. (i've just applied to to tip/x86/debug and pushed it out into tip/master)
... but that's still not a guarantee that you'll be able to debug it this way :-/ Bootstrapping something this intrusive and wide is one of the hardest kernel development activities possible.
Ingo
---------------->
Quoted 1 line
From
6cf87efbc7a3676e0ad7c9622ec6aec244a593bcMon Sep 17 00:00:00 2001
From: Ingo Molnar <[email protected]>
Date: Tue, 4 Nov 2008 10:42:23 +0100
Subject: [PATCH] x86 debug: mark early_printk.o as notrace
Impact: do not do function-tracing in the early-printk code
this is useful when earlyprintk=vga,keep is used to debug tracer plugins.
--- arch/x86/kernel/Makefile | 1 + 1 files changed, 1 insertions(+), 0 deletions(-)
arch/x86/kernel/Makefile +1 -0
@@ -12,6 +12,7 @@ CFLAGS_REMOVE_tsc.o = -pg CFLAGS_REMOVE_rtc.o = -pg CFLAGS_REMOVE_paravirt-spinlocks.o = -pg CFLAGS_REMOVE_ftrace.o = -pg +CFLAGS_REMOVE_early_printk.o = -pg endif #
2008/11/4 Ingo Molnar <[email protected]>:
Quoted 11 lines
lockdep works via a completely different principle: it instruments all the actual lock acquire/release calls and builds a graph of lock dependencies in the system, as it happens.
It also guarantees that all the observed locking rules are followed (i.e. it proves that as long as you dont get any messages from lockdep, all the locking patterns are mathematically safe).
So a lockdep message will most of the time occur much easier than a real lockup would occur - as lockdep only needs to observe inconsistent locking patterns to prove that a lockup _could_ occur.
Ok, so if there is such an error, I could (hopefully) see it with early_printk....
Quoted 8 lines
The NMI watchdog just observes the system and complains if it sees hardirqs not progressing (i.e. a hard lockup). It will detect anything that causes a hard lockup. (assuming that the NMI watchdog itself is not locked up)
Regarding your lockup ... it's quite hard. Maybe you can get more output out of the system by using:
Quoted 7 lines
earlyprintk=vga,keep
plus disablig regular tty output. (i.e. not passing any 'console=tty' line to the kernel bootup.)
this way you wont get any normal printk activities (which might lock up), you should only get the very simple early-printk output.
Good idea. After reading your mail, I had a look on early_printk and it shoudn't cause any tracing recursion after
your patch: the strings are directly writed to the vga. Great.
Quoted 3 lines
... but that's still not a guarantee that you'll be able to debug it this way :-/ Bootstrapping something this intrusive and wide is one of the hardest kernel development activities possible.
I've been on it for two weeks now. Yes it's very hard. But exciting!
Quoted 24 lines
Ingo
---------------->
From6cf87efbc7a3676e0ad7c9622ec6aec244a593bcMon Sep 17 00:00:00 2001
From: Ingo Molnar <[email protected]>
Date: Tue, 4 Nov 2008 10:42:23 +0100
Subject: [PATCH] x86 debug: mark early_printk.o as notraceImpact: do not do function-tracing in the early-printk code
this is useful when earlyprintk=vga,keep is used to debug tracer plugins.
Signed-off-by Ingo Molnar <[email protected]>--- arch/x86/kernel/Makefile | 1 + 1 files changed, 1 insertions(+), 0 deletions(-)arch/x86/kernel/Makefile +0
-0
arch/x86/kernel/Makefile CFLAGS_REMOVE_tsc.o = -pg · line 18
Quoted 7 lines
arch/x86/kernel/Makefile +1
-0@@ -12,6 +12,7 @@ CFLAGS_REMOVE_tsc.o = -pg CFLAGS_REMOVE_rtc.o = -pg CFLAGS_REMOVE_paravirt-spinlocks.o = -pg CFLAGS_REMOVE_ftrace.o = -pg +CFLAGS_REMOVE_early_printk.o = -pg endif #
I will test your advices this evening and pull latest -tip to get this patch. Thanks!
Quoted 31 lines · Frédéric Weisbecker
2008/11/4 Ingo Molnar <[email protected]>:
Quoted 11 lines
lockdep works via a completely different principle: it instruments all the actual lock acquire/release calls and builds a graph of lock dependencies in the system, as it happens.
It also guarantees that all the observed locking rules are followed (i.e. it proves that as long as you dont get any messages from lockdep, all the locking patterns are mathematically safe).
So a lockdep message will most of the time occur much easier than a real lockup would occur - as lockdep only needs to observe inconsistent locking patterns to prove that a lockup _could_ occur.
Ok, so if there is such an error, I could (hopefully) see it with
early_printk....Quoted 13 lines
The NMI watchdog just observes the system and complains if it sees hardirqs not progressing (i.e. a hard lockup). It will detect anything that causes a hard lockup. (assuming that the NMI watchdog itself is not locked up)
Regarding your lockup ... it's quite hard. Maybe you can get more output out of the system by using:
earlyprintk=vga,keep
plus disablig regular tty output. (i.e. not passing any 'console=tty' line to the kernel bootup.)
Quoted 8 lines
Quoted 2 lines
this way you wont get any normal printk activities (which might lock up), you should only get the very simple early-printk output.
Good idea. After reading your mail, I had a look on
early_printkand it shoudn't cause any tracing recursion after your patch: the strings are directly writed to the vga. Great.
just make sure normal printk is totally silent. (otherwise you get double lines on the console plus no reduction in recursion risk)
i usually add a return; hack to kernel/printk.c:printk(), to make sure it never executes anything. (and add a notrace to it as well) Maybe we could even make this dependent on early_printk=...,keep.
Ingo
2008/11/4 Ingo Molnar <[email protected]>:
Quoted 6 lines
just make sure normal printk is totally silent. (otherwise you get double lines on the console plus no reduction in recursion risk)
i usually add a return; hack to kernel/printk.c:printk(), to make sure it never executes anything. (and add a notrace to it as well) Maybe we could even make this dependent on early_printk=...,keep.
Thanks for your help!
I tried the earlyprintk=vga,keep and I thought that the normal printk output would
be replaced by early_printk output but that's not the case... So I replaced the content of printk by this of early_printk and it worked. But it seems that after the setting of the console, the early_printk doesn't work anymore.
Should I disable something else? I haven't any console=.... parameter but I guess I missed
something there...
But, I set the parameter nmi_watchdog=2 (I didn't know I had to start explicitly the nmi watchdog)
and at last... I had my backtraces :-)
All these backtraces were related to time function. And one of the special things of the time functions
is that they often manipulate 64 bits numbers. Actually I totally forgot that a function could return a
long long, so I had to save edx register in the return handler to restore it in its end because 64 bits
numbers are returned as a couple into eax and edx in x86-32.
So the main problem is now solved. But it remains a last (but more rare) deadlock somewhere. I don't
know why at this time and the nmi watchdog doesn't tell anything. So I will have to use early_printk
to see the last functions traced. But the problem is that it doesn't print on the console...
Quoted 17 lines · Frédéric Weisbecker
2008/11/4 Ingo Molnar <[email protected]>:
Quoted 6 lines
just make sure normal printk is totally silent. (otherwise you get double lines on the console plus no reduction in recursion risk)
i usually add a return; hack to kernel/printk.c:printk(), to make sure it never executes anything. (and add a notrace to it as well) Maybe we could even make this dependent on early_printk=...,keep.
Thanks for your help!
I tried the earlyprintk=vga,keep and I thought that the normal printk output would
be replaced byearly_printkoutput but that's not the case... So I replaced the content of printk by this ofearly_printkand it worked. But it seems that after the setting of the console, theearly_printkdoesn't work anymore.
Quoted 3 lines
Should I disable something else? I haven't any console=.... parameter but I guess I missed
something there...
perhaps try a "console=tty 3" bootup - to boot into non-graphics initlevel 3, and to have a vga tty set up. Then comment out the regular printk(), to make sure it never tries to output to the regular tty.
does earlyprintk=vga,keep work in that case?
Quoted 3 lines
But, I set the parameter nmi_watchdog=2 (I didn't know I had to start explicitly the nmi watchdog) and at last... I had my backtraces :-)
heh :-)
Quoted 7 lines
All these backtraces were related to time function. And one of the special things of the time functions is that they often manipulate 64 bits numbers. Actually I totally forgot that a function could return a long long, so I had to save edx register in the return handler to restore it in its end because 64 bits numbers are returned as a couple into eax and edx in x86-32.
Quoted 5 lines
So the main problem is now solved. But it remains a last (but more rare) deadlock somewhere. I don't know why at this time and the nmi watchdog doesn't tell anything. So I will have to use
early_printkto see the last functions traced. But the problem is that it doesn't print on the console...
hm. Let me know if you cannot get this to work. I regularly use earlyprintk=serial,...,keep myself, and it works there - but i dont use earlyprintk=vga,keep that often.
Ingo
2008/11/5 Ingo Molnar <[email protected]>:
Quoted 50 lines · Frédéric Weisbecker
Quoted 18 lines
2008/11/4 Ingo Molnar <[email protected]>:
Quoted 6 lines
just make sure normal printk is totally silent. (otherwise you get double lines on the console plus no reduction in recursion risk)
i usually add a return; hack to kernel/printk.c:printk(), to make sure it never executes anything. (and add a notrace to it as well) Maybe we could even make this dependent on early_printk=...,keep.
Thanks for your help!
I tried the earlyprintk=vga,keep and I thought that the normal printk output would
be replaced byearly_printkoutput but that's not the case... So I replaced the content of printk by this ofearly_printkand it worked. But it seems that after the setting of the console, theearly_printkdoesn't work anymore.Quoted 3 lines
Should I disable something else? I haven't any console=.... parameter but I guess I missed
something there...perhaps try a "console=tty 3" bootup - to boot into non-graphics initlevel 3, and to have a vga tty set up. Then comment out the regular
printk(), to make sure it never tries to output to the regular tty.does earlyprintk=vga,keep work in that case?
Quoted 3 lines
But, I set the parameter nmi_watchdog=2 (I didn't know I had to start explicitly the nmi watchdog) and at last... I had my backtraces :-)
heh :-)
Quoted 7 lines
All these backtraces were related to time function. And one of the special things of the time functions is that they often manipulate 64 bits numbers. Actually I totally forgot that a function could return a long long, so I had to save edx register in the return handler to restore it in its end because 64 bits numbers are returned as a couple into eax and edx in x86-32.
Quoted 5 lines
So the main problem is now solved. But it remains a last (but more rare) deadlock somewhere. I don't know why at this time and the nmi watchdog doesn't tell anything. So I will have to use
early_printkto see the last functions traced. But the problem is that it doesn't print on the console...
Quoted 6 lines
hm. Let me know if you cannot get this to work. I regularly use earlyprintk=serial,...,keep myself, and it works there - but i dont use earlyprintk=vga,keep that often.
Ingo
Actually, I didn't need it. I just turned off the nmi watchdog and I don't have anymore deadlock. The good news is that I have now something that seems stable. I will have some time this week-end to try to make a proper patch with this feature.
Thanks for your help!