trace_printk() using percpu buffers
Subsystems (2)
Steven Rostedt
maintainercover trace_printk() using percpu buffers
Peter,
You had issues with the previous version of my trace_printk() code. I rewrote it to do the following.
By default, it still uses the single buffer protected by a spinlock and an atomic (for NMIs). The NMI case can cause dropped prints if the NMI happens while a trace_printk() is processing.
When trace_printk_percpu is enabled, either via the trace options or the kernel command line, then two sets of percpu buffers are made, one for normal and irqs (interrupts are still disabled), and the other is for NMIs. These can be added or removed at anytime.
The last patch adds a CONFIG_TRACE_PRINTK_PERCPU that makes trace_printk() permanently use two sets of per_cpu buffers, and these can not be removed. This will give the least amount of overhead for trace_printk() with the sacrifice of memory overhead. This is an option I could imagine you would just set and forget about.
Let me know your thoughts.
Thanks,
-- Steve
Steven Rostedt (3):
tracing: Do not allocate buffer for trace_marker
tracing: Add optional percpu buffers for trace_printk()
tracing: Add config to permanently have trace_printk() use percpu buffers
----
Documentation/kernel-parameters.txt | 11 + kernel/trace/Kconfig | 18 ++ kernel/trace/trace.c | 360 ++++++++++++++++++++++++++++------- kernel/trace/trace.h | 1 + 4 files changed, 320 insertions(+), 70 deletions(-)
Steven Rostedt
maintainerRFC PATCH 1/3 tracing: Do not allocate buffer for trace_marker
From: Steven Rostedt <[email protected]>
When doing intense tracing, the kmalloc inside trace_marker can introduce side effects to what is being traced.
As trace_marker() is used by userspace to inject data into the kernel ring buffer, it needs to do so with the least amount of intrusion to the operations of the kernel or the user space application.
As the ring buffer is designed to write directly into the buffer without the need to make a temporary buffer, and userspace already went through the hassle of knowing how big the write will be, we can simply pin the userspace pages and write the data directly into the buffer. This improves the impact of tracing via trace_marker tremendously!
Thanks to Peter Zijlstra and Thomas Gleixner for pointing out the use of get_user_pages_fast() and kmap_atomic().
--- kernel/trace/trace.c | 111 +++++++++++++++++++++++++++++++++++++------------- 1 files changed, 83 insertions(+), 28 deletions(-)
kernel/trace/trace.c +83 -28
@@ -3628,22 +3628,24 @@ tracing_free_buffer_release(struct inode *inode, struct file *filp)return 0 ; } -static int mark_printk (const char *fmt, ...) -{ -int ret; -va_list args; -va_start (args, fmt); - ret =trace_vprintk (0 , fmt, args); -va_end (args); -return ret; -} -static ssize_t tracing_mark_write (struct file *filp,const char __user *ubuf,size_t cnt,loff_t *fpos) { -char *buf; -size_t written; +unsigned long addr = (unsigned long )ubuf; +struct ring_buffer_event *event; +struct ring_buffer *buffer; +struct print_entry *entry; +unsigned long irq_flags; +struct page *pages[2 ]; +int nr_pages =1 ; +ssize_t written; +void *page1; +void *page2; +int offset; +int size; +int len; +int ret;if (tracing_disabled)return -EINVAL ;
@@ -3651,28 +3653,81 @@ tracing_mark_write(struct file *filp, const char __user *ubuf,if (cnt >TRACE_BUF_SIZE ) cnt =TRACE_BUF_SIZE ; - buf =kmalloc (cnt +2 ,GFP_KERNEL ); -if (buf ==NULL ) -return -ENOMEM ; +/* +* Userspace is injecting traces into the kernel trace buffer. +* We want to be as non intrusive as possible. +* To do so, we do not want to allocate any special buffers +* or take any locks, but instead write the userspace data +* straight into the ring buffer. +* +* First we need to pin the userspace buffer into memory, +* which, most likely it is, because it just referenced it. +* But there's no guarantee that it is. By using get_user_pages_fast() +* and kmap_atomic/kunmap_atomic() we can get access to the +* pages directly. We then write the data directly into the +* ring buffer. +*/ +BUILD_BUG_ON (TRACE_BUF_SIZE >=PAGE_SIZE ); -if (copy_from_user (buf, ubuf, cnt)) { -kfree (buf); -return -EFAULT ; +/* check if we cross pages */ +if ((addr &PAGE_MASK ) != ((addr + cnt) &PAGE_MASK )) + nr_pages =2 ; + + offset = addr & (PAGE_SIZE -1 ); + addr &=PAGE_MASK ; + + ret =get_user_pages_fast (addr, nr_pages,0 , pages); +if (ret < nr_pages) { +while (--ret >=0 ) +put_page (pages[ret]); + written = -EFAULT ; + goto out; } -if (buf[cnt-1 ] !='\n' ) { - buf[cnt] ='\n' ; - buf[cnt+1 ] ='\0' ; + + page1 =kmap_atomic (pages[0 ]); +if (nr_pages ==2 ) + page2 =kmap_atomic (pages[1 ]); + +local_save_flags (irq_flags); + size =sizeof (*entry) + cnt +2 ;/* possible \n added */ + buffer = global_trace.buffer; + event =trace_buffer_lock_reserve (buffer,TRACE_PRINT , size, + irq_flags,preempt_count ()); +if (!event) { +/* Ring buffer disabled, return as if not open for write */ + written = -EBADF ; + goto out_unlock; + } + + entry =ring_buffer_event_data (event); + entry->ip = _THIS_IP_; + +if (nr_pages ==2 ) { + len =PAGE_SIZE - offset; +memcpy (&entry->buf, page1 + offset, len); +memcpy (&entry->buf[len], page2, cnt - len); }else - buf[cnt] ='\0' ; +memcpy (&entry->buf, page1 + offset, cnt); - written =mark_printk ("%s" , buf); -kfree (buf); - *fpos += written; +if (entry->buf[cnt -1 ] !='\n' ) { + entry->buf[cnt] ='\n' ; + entry->buf[cnt +1 ] ='\0' ; + }else + entry->buf[cnt] ='\0' ; + +ring_buffer_unlock_commit (buffer, event); -/* don't tell userspace we wrote more - it might confuse them */ -if (written > cnt) - written = cnt; + written = cnt; + *fpos += written; + + out_unlock: +if (nr_pages ==2 ) +kunmap_atomic (page2); +kunmap_atomic (page1); +while (nr_pages >0 ) +put_page (pages[--nr_pages]); + out:return written; }
Signature · 1 line
1.7.6.3
Steven Rostedt
maintainerRFC PATCH 2/3 tracing: Add optional percpu buffers for trace_printk()
In reply to Steven RostedtFrom: Steven Rostedt <[email protected]>
Currently, trace_printk() uses a single buffer to write into to calculate the size and format needed to save the trace. To do this safely in an SMP environment, a spin_lock() is taken to only allow one writer at a time to the buffer. But this could also affect what is being traced, and add synchronization that would not be there otherwise.
Ideally, using percpu buffers would be useful, but since trace_printk() is only used in development, having per cpu buffers for something never used is a waste of space. We could make this a compile option but trace_printk() may also be used for developing modules, on a distro kernels or for debugging at customer sites.
The approach taken here is to dynamically allocate percpu buffers with a new tracing/options switch "trace_printk_percpu". It can be allocated and freed at runtime, or "trace_printk_percpu" may also be specified on the command line and it will be allocated at boot up.
This allows a developer to create percpu buffers for trace_printk() on a running system, and also free them when not in used.
--- Documentation/kernel-parameters.txt | 11 ++ kernel/trace/trace.c | 216 ++++++++++++++++++++++++++++------- kernel/trace/trace.h | 1 + 3 files changed, 187 insertions(+), 41 deletions(-)
Documentation/kernel-parameters.txt +11 -0
@@ -2521,6 +2521,17 @@ bytes respectively. Such letter suffixes can also be entirely omitted. to facilitate early boot debugging. See also Documentation/trace/events.txt + trace_printk_percpu + [FTRACE] When using trace_printk(), by default the + temporary buffer is a single instance with a spinlock + to protect it. By adding this switch or enabling it at + runtime with: + echo 1 > /sys/kernel/debug/tracing/options/trace_printk_percpu + Per CPU buffers are allocated and trace_printk() will write + to them without taking any locks. Echo 0 into the above + file, and the percpu buffers will safely be freed. + Even if they were allocated with this kernel command line. + tsc= Disable clocksource stability checks for TSC. Format: <string> [x86] reliable: mark tsc clocksource as reliable, this
kernel/trace/trace.c +175 -41
325 lines not on this page · raw message
kernel/trace/trace.h +1 -0
@@ -654,6 +654,7 @@ enum trace_iterator_flags {TRACE_ITER_RECORD_CMD =0x100000 ,TRACE_ITER_OVERWRITE =0x200000 ,TRACE_ITER_STOP_ON_FREE =0x400000 , + TRACE_ITER_PRINTK_PERCPU = 0x800000, };/*
Signature · 1 line
1.7.6.3
Re: [PATCH 2/3][RFC] tracing: Add optional percpu buffers for trace_printk()
Quoted 7 lines · Steven Rostedt
Ideally, using percpu buffers would be useful, but since
trace_printk()is only used in development, having per cpu buffers for something never used is a waste of space. We could make this a compile option buttrace_printk()may also be used for developing modules, on a distro kernels or for debugging at customer sites.
Quoted 7 lines
The approach taken here is to dynamically allocate percpu buffers with a new tracing/options switch "
trace_printk_percpu". It can be allocated and freed at runtime, or "trace_printk_percpu" may also be specified on the command line and it will be allocated at boot up.This allows a developer to create percpu buffers for
trace_printk()on a running system, and also free them when not in used.
Kill the old code, make tracing/events/trace_printk default to 0 and use enabling of that to allocate your per-cpu buffers.
Steven Rostedt
maintainerRe: [PATCH 2/3][RFC] tracing: Add optional percpu buffers for trace_printk()
Quoted 13 lines · Peter Zijlstra
Quoted 12 lines · Steven Rostedt
Ideally, using percpu buffers would be useful, but since
trace_printk()is only used in development, having per cpu buffers for something never used is a waste of space. We could make this a compile option buttrace_printk()may also be used for developing modules, on a distro kernels or for debugging at customer sites.The approach taken here is to dynamically allocate percpu buffers with a new tracing/options switch "
trace_printk_percpu". It can be allocated and freed at runtime, or "trace_printk_percpu" may also be specified on the command line and it will be allocated at boot up.
Quoted 5 lines
Quoted 2 lines
This allows a developer to create percpu buffers for
trace_printk()on a running system, and also free them when not in used.Kill the old code, make tracing/events/trace_printk default to 0 and use enabling of that to allocate your per-cpu buffers.
This will make debugging some of my embedded boards difficult (the ones where I have no way to add kernel command lines). If there's a problem at boot up, I will have to modify the kernel to get this to print.
For those that don't know the tracing code, it will just simply break.
Unless you want me to keep the kconfig option that enables it permanently. Then I could do this.
I also expect tglx to throw frozen sharks at me for "why doesn't trace_printk() work anymore?!!!!"
-- Steve
Re: [PATCH 2/3][RFC] tracing: Add optional percpu buffers for trace_printk()
Quoted 8 lines · Steven Rostedt
This will make debugging some of my embedded boards difficult (the ones where I have no way to add kernel command lines). If there's a problem at boot up, I will have to modify the kernel to get this to print.
For those that don't know the tracing code, it will just simply break.
Unless you want me to keep the kconfig option that enables it permanently. Then I could do this.
There's a fairly easy fix for that, initialize it at boot, and free once userspace it up and running if no trace_printk() came by.
Quoted 2 lines
I also expect tglx to throw frozen sharks at me for "why doesn't
trace_printk()work anymore?!!!!"
I'm sure you'll get over that :-)
Steven Rostedt
maintainerRe: [PATCH 2/3][RFC] tracing: Add optional percpu buffers for trace_printk()
Quoted 6 lines · Peter Zijlstra
Quoted 4 lines · Steven Rostedt
This will make debugging some of my embedded boards difficult (the ones where I have no way to add kernel command lines). If there's a problem at boot up, I will have to modify the kernel to get this to print.
Quoted 7 lines
Quoted 4 lines
For those that don't know the tracing code, it will just simply break.
Unless you want me to keep the kconfig option that enables it permanently. Then I could do this.
There's a fairly easy fix for that, initialize it at boot, and free once userspace it up and running if no
trace_printk()came by.
Hmm, I could do that. Of course this will add a check for a global variable in all trace_printks. I could make it a read_mostly variable, as it only gets updated once, or even encapsulate the entire check with a static_switch() :)
Quoted 5 lines
Quoted 3 lines
I also expect tglx to throw frozen sharks at me for "why doesn't
trace_printk()work anymore?!!!!"I'm sure you'll get over that :-)
I've had too many, I'm not sure my head could take much more.
-- Steve
Steven Rostedt
maintainerRFC PATCH 3/3 tracing: Add config to permanently have trace_printk() use percpu
In reply to Steven RostedtFrom: Steven Rostedt <[email protected]>
For those that do a lot of developing, and use trace_printk() often. There is no need to have a switch to change between percpu buffers and a locked protected buffer. Just have the percpu buffers permanently allocated via a config option and keep a fast and non-intrusive tracing mechanism that can handle tracing in NMIs, but sacrifices memory overhead. But developers don't mind that.
--- kernel/trace/Kconfig | 18 ++++++++++++++++++ kernel/trace/trace.c | 41 ++++++++++++++++++++++++++++++++++++----- 2 files changed, 54 insertions(+), 5 deletions(-)
kernel/trace/Kconfig +18 -0
@@ -223,6 +223,24 @@ config SCHED_TRACER This tracer tracks the latency of the highest priority task to be scheduled in, starting from the point it has woken up. +config TRACE_PRINTK_PERCPU + bool "Allocate trace_printk() per_cpu buffers" + depends on TRACING + help + By default trace_printk() uses a singe 1KB buffer protected + with a spinlock. It also may lose trace data from NMIs, if an + NMI happens on a CPU that a trace is being recorded on. + + By default, per_cpu buffers can be allocated either by + setting trace_printk_percpu on the kernel command line, + or by enabling the trace option trace_printk_percpu. + + For developers that want it always set, by enabling this + config, per_cpu buffers will be permanently set, removing + any logic to check between single and per cpu buffers + adding less impact to tracing with the added cost of more + memory overhead. + config ENABLE_DEFAULT_TRACERS bool "Trace process context switches and events" depends on !GENERIC_TRACER
kernel/trace/trace.c +36 -5
76 lines not on this page · raw message
Signature · 1 line
1.7.6.3
Quoted 9 lines · Steven Rostedt
Peter,
You had issues with the previous version of my
trace_printk()code. I rewrote it to do the following.By default, it still uses the single buffer protected by a spinlock and an atomic (for NMIs). The NMI case can cause dropped prints if the NMI happens while a
trace_printk()is processing.
Why bother keeping that?
Quoted 4 lines
When
trace_printk_percpuis enabled, either via the trace options or the kernel command line, then two sets of percpu buffers are made, one for normal and irqs (interrupts are still disabled), and the other is for NMIs. These can be added or removed at anytime.
So why not allocate 4, one for {task, softirq, irq, NMI} resp, then all you need to do is disable preemption.
depending on tracing/options/trace_printk ?
Quoted 5 lines
The last patch adds a
CONFIG_TRACE_PRINTK_PERCPUthat makestrace_printk()permanently use two sets ofper_cpubuffers, and these can not be removed. This will give the least amount of overhead fortrace_printk()with the sacrifice of memory overhead. This is an option I could imagine you would just set and forget about.
Is that one dereference really that expensive?
Steven Rostedt
maintainerQuoted 4 lines · Peter Zijlstra
Quoted 3 lines · Steven Rostedt
Peter,
Quoted 8 lines
Quoted 6 lines
You had issues with the previous version of my
trace_printk()code. I rewrote it to do the following.By default, it still uses the single buffer protected by a spinlock and an atomic (for NMIs). The NMI case can cause dropped prints if the NMI happens while a
trace_printk()is processing.Why bother keeping that?
Because very few developers debug nmi's. printk is known not to work there.
I still find it useful to have without having to switch on a config option or kernel command line.
Quoted 10 lines
Quoted 5 lines
When
trace_printk_percpuis enabled, either via the trace options or the kernel command line, then two sets of percpu buffers are made, one for normal and irqs (interrupts are still disabled), and the other is for NMIs. These can be added or removed at anytime.So why not allocate 4, one for {task, softirq, irq, NMI} resp, then all you need to do is disable preemption.
depending on tracing/options/trace_printk ?
Preemption still needs to be disabled. But if you think that's better than disabling interrupts, I could do that too.
Quoted 8 lines
Quoted 6 lines
The last patch adds a
CONFIG_TRACE_PRINTK_PERCPUthat makestrace_printk()permanently use two sets ofper_cpubuffers, and these can not be removed. This will give the least amount of overhead fortrace_printk()with the sacrifice of memory overhead. This is an option I could imagine you would just set and forget about.Is that one dereference really that expensive?
It's also a compare and jump, but I added this option for you :)
That way, you could set this option and forget about it.
-- Steve
Quoted 11 lines · Steven Rostedt
Quoted 5 lines
Quoted 3 lines
By default, it still uses the single buffer protected by a spinlock and an atomic (for NMIs). The NMI case can cause dropped prints if the NMI happens while a
trace_printk()is processing.Why bother keeping that?
Because very few developers debug nmi's. printk is known not to work there.
I still find it useful to have without having to switch on a config option or kernel command line.
But its also a massive scalability fail. There's simply no sane reason to keep the shared buffer trace_printk() implementation.
Quoted 5 lines
Quoted 5 lines
Quoted 4 lines
When
trace_printk_percpuis enabled, either via the trace options or the kernel command line, then two sets of percpu buffers are made, one for normal and irqs (interrupts are still disabled), and the other is for NMIs. These can be added or removed at anytime.
Quoted 7 lines
Quoted 4 lines
So why not allocate 4, one for {task, softirq, irq, NMI} resp, then all you need to do is disable preemption.
depending on tracing/options/trace_printk ?
Preemption still needs to be disabled. But if you think that's better than disabling interrupts, I could do that too.
I guess it doesn't really matter that much..
Quoted 9 lines
Quoted 7 lines
Quoted 5 lines
The last patch adds a
CONFIG_TRACE_PRINTK_PERCPUthat makestrace_printk()permanently use two sets ofper_cpubuffers, and these can not be removed. This will give the least amount of overhead fortrace_printk()with the sacrifice of memory overhead. This is an option I could imagine you would just set and forget about.Is that one dereference really that expensive?
It's also a compare and jump, but I added this option for you :)
Ah, right :-)
Quoted 1 line
That way, you could set this option and forget about it.
Well, if all we have is the per-cpu option I'm fine either way.
Steven Rostedt
maintainerQuoted 8 lines · Peter Zijlstra
Quoted 6 lines · Steven Rostedt
Quoted 5 lines
Quoted 3 lines
By default, it still uses the single buffer protected by a spinlock and an atomic (for NMIs). The NMI case can cause dropped prints if the NMI happens while a
trace_printk()is processing.Why bother keeping that?
Quoted 8 lines
Quoted 5 lines
Because very few developers debug nmi's. printk is known not to work there.
I still find it useful to have without having to switch on a config option or kernel command line.
But its also a massive scalability fail. There's simply no sane reason to keep the shared buffer
trace_printk()implementation.
It was created as a "fast printk". Printk has the same scalability issues, and other issues as well. It matters what you are debugging and in most cases the single buffer has worked fine.
Nobody has yet to complain about it. Except for you when I told you how it worked. ;)
Quoted 3 lines
Quoted 1 line
That way, you could set this option and forget about it.
Well, if all we have is the per-cpu option I'm fine either way.
Good! This patch set improves trace_printk() from what it currently is to something that will work for you and not break the way it use to work for others.
I'll keep this patchset as is.
Thanks!
-- Steve