mcount and latency tracing utility -v4
Subsystems (11)
Steven Rostedt
reviewercover mcount and latency tracing utility -v4
[
version 4 of mcount patches:
changes include:
Folded several patches together that made up tracer.c
changed the schedule context switch marker use pointers instead of simply listing pid and state.
Added wakeup latency timings.
Added John Stultz new RCU implementation of get_monotonic_cycles
(with special thanks to Mathieu Desnoyers for having the original
implementation)
Thanks also go out to Frank Ch. Eigler for helping out on deciding
how to use that scheduler marker.
]
All released version of these patches can be found at:
http://people.redhat.com/srostedt/tracing/
The following patch series brings to vanilla Linux a bit of the RT kernel trace facility. This incorporates the "-pg" profiling option of gcc that will call the "mcount" function for all functions called in the kernel.
Note: I did investigate using -finstrument-functions but that adds a call to both start and end of a function. Using mcount only does the beginning of the function. mcount alone adds ~13% overhead. The -finstrument-functions added ~19%. Also it caused me to do tricks with inline, because it adds the function calls to inline functions as well.
This patch series implements the code for x86 (32 and 64 bit), but other archs can easily be implemented as well (note: ARM and PPC are already implemented in -rt)
Some Background:
----------------
A while back, Ingo Molnar and William Lee Irwin III created a latency tracer to find problem latency areas in the kernel for the RT patch. This tracer became a very integral part of the RT kernel in solving where latency hot spots were. One of the features that the latency tracer added was a function trace. This function tracer would record all functions that were called (implemented by the gcc "-pg" option) and would show what was called when interrupts or preemption was turned off.
This feature is also very helpful in normal debugging. So it's been talked about taking bits and pieces from the RT latency tracer and bring them to LKML. But no one had the time to do it.
Arnaldo Carvalho de Melo took a crack at it. He pulled out the mcount as well as part of the tracing code and made it generic from the point of the tracing code. I'm not sure why this stopped. Probably because Arnaldo is a very busy man, and his efforts had to be utilized elsewhere.
While I still maintain my own Logdev utility:
http://rostedt.homelinux.com/logdev
I came across a need to do the mcount with logdev too. I was successful but found that it became very dependent on a lot of code. One thing that I liked about my logdev utility was that it was very non-intrusive, and has been easy to port from the Linux 2.0 days. I did not want to burden the logdev patch with the intrusiveness of mcount (not really that intrusive, it just needs to add a "notrace" annotation to functions in the kernel that will cause more conflicts in applying patches for me).
Being close to the holidays, I grabbed Arnaldos old patches and started massaging them into something that could be useful for logdev, and what I found out (and talking this over with Arnaldo too) that this can be much more useful for others as well.
The main thing I changed, was that I made the mcount function itself generic, and not the dependency on the tracing code. That is I added
register_mcount_function()
andclear_mcount_function()
So when ever mcount is enabled and a function is registered that function is called for all functions in the kernel that is not labeled with the "notrace" annotation.
The Simple Tracer:
------------------
To show the power of this I also massaged the tracer code that Arnaldo pulled from the RT patch and made it be a nice example of what can be done with this.
The function that is registered to mcount has the prototype:
void func(unsigned long ip, unsigned long parent_ip);
The ip is the address of the function and parent_ip is the address of the parent function that called it.
The x86_64 version has the assembly call the registered function directly to save having to do a double function call.
To enable mcount, a sysctl is added:
/proc/sys/kernel/mcount_enabled
Once mcount is enabled, when a function is registed, it will be called by all functions. The tracer in this patch series shows how this is done. It adds a directory in the debugfs, called mctracer. With a ctrl file that will allow the user have the tracer register its function. Note, the order of enabling mcount and registering a function is not important, but both must be done to initiate the tracing. That is, you can disable tracing by either disabling mcount or by clearing the registered function.
Only one function may be registered at a time. If another function is registered, it will simply override what ever was there previously.
Here's a simple example of the tracer output:
CPU 2: hackbench:11867 preempt_schedule+0xc/0x84 <-- avc_has_perm_noaudit+0x45d/0x52c CPU 1: hackbench:12052 selinux_file_permission+0x10/0x11c <-- security_file_permission+0x16/0x18 CPU 3: hackbench:12017 update_curr+0xe/0x8b <-- put_prev_task_fair+0x24/0x4c
CPU 2: hackbench:11867 avc_audit+0x16/0x9e3 <-- avc_has_perm+0x51/0x63
CPU 0: hackbench:12019 socket_has_perm+0x16/0x7c <-- selinux_socket_sendmsg+0x27/0x3e CPU 1: hackbench:12052 file_has_perm+0x16/0xbb <-- selinux_file_permission+0x104/0x11c
This is formated like:
CPU <CPU#>: <task-comm>:<task-pid> <function> <-- <parent-function>
Latency Tracer Format:
----------------------
The format used by the RT patch is a bit more complex. It is designed to record a lot of information quickly and dump out a lot too.
There's two versions of the format. Verbose and non-vebose.
verbose:
preemption latency trace v1.1.5 on 2.6.24-rc7-tst
--------------------------------------------------------------------
latency: 89 us, #3/3, CPU#1 | (M:desktop VP:0, KP:0, SP:0 HP:0 #P:4)
-----------------
| task: kjournald-600 (uid:0 nice:-5 policy:0 rt_prio:0)
----------------- => started at: _spin_lock_irqsave+0x2a/0x63 <c06310d2>
=> ended at: _spin_unlock_irqrestore+0x32/0x41 <c0631245>
kjournald 600 1 1 00000000 00000000 [397408f1] 0.003ms (+0.079ms): _spin_lock_irqsave+0x2a/0x63 <c06310d2> (scsi_dispatch_cmd+0x155/0x234 [scsi_mod] <f8867c19>)
kjournald 600 1 1 00000000 00000001 [39740940] 0.081ms (+0.005ms): _spin_unlock_irqrestore+0x32/0x41 <c0631245> (scsi_dispatch_cmd+0x1be/0x234 [scsi_mod] <f8867c82>)
kjournald 600 1 1 00000000 00000002 [39740945] 0.087ms (+0.000ms): trace_hardirqs_on_caller+0x74/0x86 <c0508bdc> (_spin_unlock_irqrestore+0x32/0x41 <c0631245>)non-verbose:
preemption latency trace v1.1.5 on 2.6.24-rc7-tst
--------------------------------------------------------------------
latency: 89 us, #3/3, CPU#2 | (M:desktop VP:0, KP:0, SP:0 HP:0 #P:4)
-----------------
| task: kjournald-600 (uid:0 nice:-5 policy:0 rt_prio:0)
----------------- => started at: _spin_lock_irqsave+0x2a/0x63 <c06310d2>
=> ended at: _spin_unlock_irqrestore+0x32/0x41 <c0631245>
_------=> CPU#
/ _-----=> irqs-off
| / _----=> need-resched
|| / _---=> hardirq/softirq
||| / _--=> preempt-depth
|||| /
||||| delay
cmd pid ||||| time | caller
\ / ||||| \ | /
kjournal-600 1d... 3us+: _spin_lock_irqsave+0x2a/0x63 <c06310d2> (scsi_dispatch_cmd+0x155/0x234 [scsi_mod] <f8867c19>)
kjournal-600 1d... 81us+: _spin_unlock_irqrestore+0x32/0x41 <c0631245> (scsi_dispatch_cmd+0x1be/0x234 [scsi_mod] <f8867c82>)
kjournal-600 1d... 87us : trace_hardirqs_on_caller+0x74/0x86 <c0508bdc> (_spin_unlock_irqrestore+0x32/0x41 <c0631245>)Debug FS:
---------
Although enabling and disabling mcount is done through the sysctl:
/proc/sys/kernel/mcount_enabled
The rest of the tracing uses debugfs.
/debugfs/tracing
Here's the available files:
fn_trace_ctrl
echo 1 to this enables mcount tracing (if mcount_enabled is set) echo 0 to disable the function trace tracing.
function_trace
Outputs the function trace in latency_trace format.
preempt_fn_trace_ctrl
echo 1 to enable function tracing in critical sections timings echo 0 to disable
preempt_trace
Outputs the critical section latency
preempt_thresh
echo a number (in usecs) into this to record all traces that are greater than threshold.
iter_ctrl
echo "symonly" to not show the instruction pointers in the trace echo "nosymonly" to disable symonly.
echo "verbose" for verbose output from latency format. echo "noverbose" to disable verbose ouput.
cat iter_ctrl to see the current settings.
preempt_max_latency
Holds the current max critical latency.
echo 0 to reset and start tracing.
wakeup_max_latency
Holds the current max wakeup latency (usecs)
wakeup_thresh
Holds the threshold to print after a latency exceeds it (usecs)
wakeup_trace_ctrl
Turn on or off wakeup latency
wakeup_trace
Holds the output of the highest wakeup latency.
trace
simple output format of the function trace code.
Overhead:
---------
Note that having mcount compiled in seems to show a little overhead.
Here's 3 runs of hackbench 50 without the patches:
Time: 2.137
Time: 2.283
Time: 2.245
Avg: 2.221
and here's 3 runs with the patches (without tracing on):
Time: 2.738
Time: 2.469
Time: 2.388
Avg: 2.531
So it is a 13% overhead when enabled (according to hackbench).
But full tracing can cause a bit more problems:
# hackbench 50 Time: 113.350
113.350!!!!!
But this is tracing *every* function call!
Future:
-------
The way the mcount hook is done here, other utilities can easily add their own functions. Just care needs to be made not to call anything that is not marked with notrace, or you will crash the box with recursion. But even the simple tracer adds a "disabled" feature so in case it happens to call something that is not marked with notrace, it is a safety net not to kill the box.
I was originally going to use the relay system to record the data, but that had a chance of calling functions not marked with notrace. But, if for example LTTng wanted to use this, it could disable tracing on a CPU when doing the calls, and this will protect from recusion.
Redesign:
---------
This will be the last series that has each of the traces as a separate buffer. The next series will be more like the RT patch implementation of holding a single buffer for all latency traces. The only disadvantage of this is that you can only perform one type of latency at a time. But this has never been brought up as an issue with the RT patch.
The user will still be able to switch at runtime which type of latency they would like to record.
SystemTap:
----------
One thing that Arnaldo and I discussed last year was using systemtap to add hooks into the kernel to start and stop tracing. kprobes is too heavy to do on all funtion calls, but it would be perfect to add to non hot paths to start the tracer and stop the tracer.
So when debugging the kernel, instead of recompiling with printks or other markers, you could simply use systemtap to place a trace start and stop locations and trace the problem areas to see what is happening.
Latency Tracing:
----------------
We can also add trace points to record the time the highest priority task needs to wait before running. This too is currently done in the RT patch.
These are just some of the ideas we have with this. And we are sure others could come up with more.
These patches are for the underlining work. We'll see what happens next.
Steven Rostedt
reviewerRFC PATCH 1/23 Add basic support for gcc profiler instrumentation
If CONFIG_MCOUNT is selected and /proc/sys/kernel/mcount_enabled is set to a non-zero value the mcount routine will be called everytime we enter a kernel function that is not marked with the "notrace" attribute.
The mcount routine will then call a registered function if a function happens to be registered.
[This code has been highly hacked by Steven Rostedt, so don't
blame Arnaldo for all of this ;-) ]
Update:
It is now possible to register more than one mcount function. If only one mcount function is registered, that will be the function that mcount calls directly. If more than one function is registered, then mcount will call a function that will loop through the functions to call.
--- Makefile | 3 arch/x86/Kconfig | 1 arch/x86/kernel/entry_32.S | 22 +++++++ arch/x86/kernel/entry_64.S | 33 ++++++++++ include/linux/linkage.h | 2 include/linux/mcount.h | 38 ++++++++++++ kernel/sysctl.c | 11 +++ lib/Kconfig.debug | 2 lib/Makefile | 2 lib/tracing/Kconfig | 10 +++ lib/tracing/Makefile | 3 lib/tracing/mcount.c | 141 +++++++++++++++++++++++++++++++++++++++++++++ 12 files changed, 268 insertions(+)
Makefile +3 -0
@@ -509,6 +509,9 @@ endif include $(srctree)/arch/$(SRCARCH)/Makefile +ifdef CONFIG_MCOUNT +KBUILD_CFLAGS += -pg +endif ifdef CONFIG_FRAME_POINTER KBUILD_CFLAGS += -fno-omit-frame-pointer -fno-optimize-sibling-calls else
arch/x86/Kconfig +1 -0
@@ -19,6 +19,7 @@ config X86_64 config X86 bool default y + select HAVE_MCOUNT config GENERIC_TIME bool
arch/x86/kernel/entry_32.S +22 -0
@@ -75,6 +75,28 @@ DF_MASK = 0x00000400 NT_MASK = 0x00004000 VM_MASK = 0x00020000 +#ifdef CONFIG_MCOUNT +.globl mcount +mcount: + cmpl $0, mcount_enabled + jz out + + /* taken from glibc */ + pushl %eax + pushl %ecx + pushl %edx + movl 0xc(%esp), %edx + movl 0x4(%ebp), %eax + + call *mcount_trace_function + + popl %edx + popl %ecx + popl %eax +out: + ret +#endif + #ifdef CONFIG_PREEMPT #define preempt_stop(clobbers) DISABLE_INTERRUPTS(clobbers); TRACE_IRQS_OFF #else
arch/x86/kernel/entry_64.S +33 -0
@@ -53,6 +53,39 @@ .code64 +#ifdef CONFIG_MCOUNT + +ENTRY(mcount) + cmpl $0, mcount_enabled + jz out + + /* taken from glibc */ + subq $0x38, %rsp + movq %rax, (%rsp) + movq %rcx, 8(%rsp) + movq %rdx, 16(%rsp) + movq %rsi, 24(%rsp) + movq %rdi, 32(%rsp) + movq %r8, 40(%rsp) + movq %r9, 48(%rsp) + + movq 0x38(%rsp), %rsi + movq 8(%rbp), %rdi + + call *mcount_trace_function + + movq 48(%rsp), %r9 + movq 40(%rsp), %r8 + movq 32(%rsp), %rdi + movq 24(%rsp), %rsi + movq 16(%rsp), %rdx + movq 8(%rsp), %rcx + movq (%rsp), %rax + addq $0x38, %rsp +out: + retq +#endif + #ifndef CONFIG_PREEMPT #define retint_kernel retint_restore_args #endif
include/linux/linkage.h +2 -0
@@ -3,6 +3,8 @@#include <asm/linkage.h> +#define notrace __attribute__((no_instrument_function)) +#ifdef __cplusplus#define CPP_ASMLINKAGE extern "C"#else
include/linux/mcount.h new file +38 -0
@@ -0,0 +1,38 @@ +#ifndef _LINUX_MCOUNT_H +#define _LINUX_MCOUNT_H + +#ifdef CONFIG_MCOUNT +extern int mcount_enabled; + +#include <linux/linkage.h> + +#define CALLER_ADDR0 ((unsigned long)__builtin_return_address(0)) +#define CALLER_ADDR1 ((unsigned long)__builtin_return_address(1)) +#define CALLER_ADDR2 ((unsigned long)__builtin_return_address(2)) + +typedef void (*mcount_func_t )(unsigned long ip,unsigned long parent_ip); + +struct mcount_ops { +mcount_func_t func; +struct mcount_ops *next; +}; + +/* +* The mcount_ops must be a static and should also +* be read_mostly. These functions do modify read_mostly variables +* so use them sparely. Never free an mcount_op or modify the +* next pointer after it has been registered. Even after unregistering +* it, the next pointer may still be used internally. +*/ +int register_mcount_function (struct mcount_ops *ops); +int unregister_mcount_function (struct mcount_ops *ops); +void clear_mcount_function (void ); + +extern void mcount (void ); + +#else /* !CONFIG_MCOUNT */ +# define register_mcount_function (ops) do { } while (0) +# define unregister_mcount_function (ops) do { } while (0) +# define clear_mcount_function (ops) do { } while (0) +#endif /* CONFIG_MCOUNT */ +#endif /* _LINUX_MCOUNT_H */
kernel/sysctl.c +11 -0
@@ -46,6 +46,7 @@#include <linux/nfs_fs.h> #include <linux/acpi.h> #include <linux/reboot.h> +#include <linux/mcount.h> #include <asm/uaccess.h> #include <asm/processor.h>
@@ -470,6 +471,16 @@ static struct ctl_table kern_table[] = { .mode = 0644, .proc_handler = &proc_dointvec, }, +#ifdef CONFIG_MCOUNT + { + .ctl_name = CTL_UNNUMBERED, + .procname = "mcount_enabled", + .data = &mcount_enabled, + .maxlen = sizeof(int), + .mode = 0644, + .proc_handler = &proc_dointvec, + }, +#endif #ifdef CONFIG_KMOD { .ctl_name = KERN_MODPROBE,
lib/Kconfig.debug +2 -0
@@ -517,4 +517,6 @@ config FAULT_INJECTION_STACKTRACE_FILTER help Provide stacktrace filter for fault-injection capabilities +source lib/tracing/Kconfig + source "samples/Kconfig"
lib/Makefile +2 -0
@@ -66,6 +66,8 @@ obj-$(CONFIG_AUDIT_GENERIC) += audit.o obj-$(CONFIG_SWIOTLB) += swiotlb.o obj-$(CONFIG_FAULT_INJECTION) += fault-inject.o +obj-$(CONFIG_MCOUNT) += tracing/ + lib-$(CONFIG_GENERIC_BUG) += bug.o hostprogs-y := gen_crc32table
lib/tracing/Kconfig new file +10 -0
@@ -0,0 +1,10 @@ + +# Archs that enable MCOUNT should select HAVE_MCOUNT +config HAVE_MCOUNT + bool + +# MCOUNT itself is useless, or will just be added overhead. +# It needs something to register a function with it. +config MCOUNT + bool + select FRAME_POINTER
lib/tracing/Makefile new file +3 -0
@@ -0,0 +1,3 @@ +obj-$(CONFIG_MCOUNT) += libmcount.o + +libmcount-y := mcount.o
lib/tracing/mcount.c new file +141 -0
141 lines not on this page · raw message
Steven Rostedt
reviewerRFC PATCH 2/23 Annotate core code that should not be traced
In reply to Steven RostedtMark with "notrace" functions in core code that should not be traced. The "notrace" attribute will prevent gcc from adding a call to mcount on the annotated funtions.
--- lib/smp_processor_id.c | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-)
lib/smp_processor_id.c +1 -1
@@ -7,7 +7,7 @@#include <linux/kallsyms.h> #include <linux/sched.h> -unsigned int debug_smp_processor_id (void ) +notrace unsigned int debug_smp_processor_id(void) {unsigned long preempt_count =preempt_count ();int this_cpu =raw_smp_processor_id ();
Steven Rostedt
reviewerRFC PATCH 3/23 x86_64: notrace annotations
In reply to Steven RostedtAdd "notrace" annotation to x86_64 specific files.
--- arch/x86/kernel/head64.c | 2 +- arch/x86/kernel/setup64.c | 4 ++-- arch/x86/kernel/smpboot_64.c | 2 +- 3 files changed, 4 insertions(+), 4 deletions(-)
arch/x86/kernel/head64.c +1 -1
@@ -46,7 +46,7 @@ static void __init copy_bootdata(char *r } } -void __init x86_64_start_kernel (char * real_mode_data) +notrace void __init x86_64_start_kernel(char *real_mode_data) {int i;
arch/x86/kernel/setup64.c +2 -2
@@ -114,7 +114,7 @@ void __init setup_per_cpu_areas(void) } } -void pda_init (int cpu) +notrace void pda_init(int cpu) {struct x8664_pda *pda =cpu_pda (cpu);
@@ -197,7 +197,7 @@ DEFINE_PER_CPU(struct orig_ist, orig_ist* 'CPU state barrier', nothing should get across. * A lot of state is already set up in PDA init. */ -void __cpuinit cpu_init (void ) +notrace void __cpuinit cpu_init(void) {int cpu =stack_smp_processor_id ();struct tss_struct *t = &per_cpu (init_tss, cpu);
arch/x86/kernel/smpboot_64.c +1 -1
@@ -317,7 +317,7 @@ static inline void set_cpu_sibling_map(i/* * Setup code on secondary processor (after comming out of the trampoline) */ -void __cpuinit start_secondary (void ) +notrace __cpuinit void start_secondary(void) {/* * Dont put anything before smp_callin(), SMP
Steven Rostedt
reviewerRFC PATCH 4/23 add notrace annotations to vsyscall.
In reply to Steven RostedtAdd the notrace annotations to some of the vsyscall functions.
--- arch/x86/kernel/vsyscall_64.c | 3 ++- arch/x86/vdso/vclock_gettime.c | 15 ++++++++------- arch/x86/vdso/vgetcpu.c | 3 ++- include/asm-x86/vsyscall.h | 3 ++- 4 files changed, 14 insertions(+), 10 deletions(-)
arch/x86/kernel/vsyscall_64.c +2 -1
@@ -42,7 +42,8 @@#include <asm/topology.h> #include <asm/vgtod.h> -#define __vsyscall (nr) __attribute__ ((unused,__section__(".vsyscall_" #nr))) +#define __vsyscall (nr) \ + __attribute__ ((unused, __section__(".vsyscall_" #nr))) notrace#define __syscall_clobber "r11","rcx","memory"#define __pa_vsymbol (x) \ ({unsigned long v; \
arch/x86/vdso/vclock_gettime.c +8 -7
@@ -24,7 +24,7 @@#define gtod vdso_vsyscall_gtod_data -static long vdso_fallback_gettime (long clock,struct timespec *ts) +notrace static long vdso_fallback_gettime(long clock, struct timespec *ts) {long ret; asm("syscall" : "=a" (ret) :
@@ -32,7 +32,7 @@ static long vdso_fallback_gettime(long creturn ret; } -static inline long vgetns (void ) +notrace static inline long vgetns(void) {long v;cycles_t (*vread)(void);
@@ -41,7 +41,7 @@ static inline long vgetns(void)return (v * gtod->clock.mult) >> gtod->clock.shift; } -static noinline int do_realtime(struct timespec *ts) +notrace static noinline int do_realtime(struct timespec *ts) {unsigned long seq, ns; do {
@@ -55,7 +55,8 @@ static noinline int do_realtime(struct t }/* Copy of the version in kernel/time.c which we cannot directly access */ -static void vset_normalized_timespec (struct timespec *ts,long sec,long nsec) +notrace static void +vset_normalized_timespec (struct timespec *ts,long sec,long nsec) {while (nsec >=NSEC_PER_SEC ) { nsec -=NSEC_PER_SEC ;
@@ -69,7 +70,7 @@ static void vset_normalized_timespec(str ts->tv_nsec = nsec; } -static noinline int do_monotonic(struct timespec *ts) +notrace static noinline int do_monotonic(struct timespec *ts) {unsigned long seq, ns, secs; do {
@@ -83,7 +84,7 @@ static noinline int do_monotonic(structreturn 0 ; } -int __vdso_clock_gettime (clockid_t clock,struct timespec *ts) +notrace int __vdso_clock_gettime(clockid_t clock, struct timespec *ts) {if (likely (gtod->sysctl_enabled && gtod->clock.vread))switch (clock) {
@@ -97,7 +98,7 @@ int __vdso_clock_gettime(clockid_t clockint clock_gettime (clockid_t ,struct timespec *) __attribute__((weak,alias ("__vdso_clock_gettime" ))); -int __vdso_gettimeofday (struct timeval *tv,struct timezone *tz) +notrace int __vdso_gettimeofday(struct timeval *tv, struct timezone *tz) {long ret;if (likely (gtod->sysctl_enabled && gtod->clock.vread)) {
arch/x86/vdso/vgetcpu.c +2 -1
@@ -13,7 +13,8 @@#include <asm/vgtod.h> #include "vextern.h" -long __vdso_getcpu (unsigned *cpu,unsigned *node,struct getcpu_cache *unused) +notrace long +__vdso_getcpu (unsigned *cpu,unsigned *node,struct getcpu_cache *unused) {unsigned int dummy, p;
include/asm-x86/vsyscall.h +2 -1
@@ -24,7 +24,8 @@ enum vsyscall_num { ((unused, __section__ (".vsyscall_gtod_data"),aligned(16)))#define __section_vsyscall_clock __attribute__ \ ((unused, __section__ (".vsyscall_clock"),aligned(16))) -#define __vsyscall_fn __attribute__ ((unused,__section__(".vsyscall_fn"))) +#define __vsyscall_fn \ + __attribute__ ((unused, __section__(".vsyscall_fn"))) notrace#define VGETCPU_RDTSCP 1#define VGETCPU_LSL 2
Steven Rostedt
reviewerRFC PATCH 5/23 add notrace annotations for NMI routines
In reply to Steven RostedtThis annotates NMI functions with notrace. Some tracers may be able to live with this, but some cannot. So we turn off NMI tracing.
One solution might be to make a notrace_nmi which would only turn off NMI tracing if a trace utility needed it off.
--- arch/x86/kernel/nmi_32.c | 2 +- arch/x86/kernel/nmi_64.c | 2 +- arch/x86/kernel/traps_32.c | 4 ++-- 3 files changed, 4 insertions(+), 4 deletions(-)
arch/x86/kernel/nmi_32.c +1 -1
@@ -323,7 +323,7 @@ EXPORT_SYMBOL(touch_nmi_watchdog);extern void die_nmi (struct pt_regs *,const char *msg); -__kprobes int nmi_watchdog_tick (struct pt_regs * regs,unsigned reason) +notrace __kprobes int nmi_watchdog_tick(struct pt_regs *regs, unsigned reason) {/*
arch/x86/kernel/nmi_64.c +1 -1
@@ -314,7 +314,7 @@ void touch_nmi_watchdog(void)touch_softlockup_watchdog (); } -int __kprobes nmi_watchdog_tick (struct pt_regs * regs,unsigned reason) +notrace __kprobes int nmi_watchdog_tick(struct pt_regs *regs, unsigned reason) {int sum;int touched =0 ;
arch/x86/kernel/traps_32.c +2 -2
@@ -723,7 +723,7 @@ void __kprobes die_nmi(struct pt_regs *rdo_exit (SIGSEGV ); } -static __kprobes void default_do_nmi (struct pt_regs * regs) +static notrace __kprobes void default_do_nmi(struct pt_regs *regs) {unsigned char reason =0 ;
@@ -763,7 +763,7 @@ static __kprobes void default_do_nmi(strstatic int ignore_nmis; -fastcall __kprobes void do_nmi(struct pt_regs * regs, long error_code) +notrace fastcall __kprobes void do_nmi(struct pt_regs *regs, long error_code) {int cpu;
Steven Rostedt
reviewerRFC PATCH 6/23 handle accurate time keeping over long delays
In reply to Steven RostedtHandle accurate time even if there's a long delay between accumulated clock cycles.
--- arch/x86/kernel/vsyscall_64.c | 5 ++- include/asm-x86/vgtod.h | 2 - include/linux/clocksource.h | 58 ++++++++++++++++++++++++++++++++++++++++-- kernel/time/timekeeping.c | 35 +++++++++++++------------ 4 files changed, 80 insertions(+), 20 deletions(-)
arch/x86/kernel/vsyscall_64.c +4 -1
@@ -86,6 +86,7 @@ void update_vsyscall(struct timespec *wa vsyscall_gtod_data.clock.mask = clock->mask; vsyscall_gtod_data.clock.mult = clock->mult; vsyscall_gtod_data.clock.shift = clock->shift; + vsyscall_gtod_data.clock.cycle_accumulated = clock->cycle_accumulated; vsyscall_gtod_data.wall_time_sec = wall_time->tv_sec; vsyscall_gtod_data.wall_time_nsec = wall_time->tv_nsec; vsyscall_gtod_data.wall_to_monotonic = wall_to_monotonic;
@@ -121,7 +122,7 @@ static __always_inline long time_syscall static __always_inline void do_vgettimeofday(struct timeval * tv) { -cycle_t now, base, mask, cycle_delta; +cycle_t now, base, accumulated, mask, cycle_delta;unsigned seq;unsigned long mult, shift, nsec;cycle_t (*vread)(void);
@@ -135,6 +136,7 @@ static __always_inline void do_vgettimeo } now =vread (); base = __vsyscall_gtod_data.clock.cycle_last; + accumulated = __vsyscall_gtod_data.clock.cycle_accumulated; mask = __vsyscall_gtod_data.clock.mask; mult = __vsyscall_gtod_data.clock.mult; shift = __vsyscall_gtod_data.clock.shift;
@@ -145,6 +147,7 @@ static __always_inline void do_vgettimeo/* calculate interval: */ cycle_delta = (now - base) & mask; + cycle_delta += accumulated;/* convert to nsecs: */ nsec += (cycle_delta * mult) >> shift;
include/asm-x86/vgtod.h +1 -1
@@ -15,7 +15,7 @@ struct vsyscall_gtod_data {struct timezone sys_tz;struct {/* extract of a clocksource struct */ cycle_t (*vread)(void ); -cycle_t cycle_last; +cycle_t cycle_last, cycle_accumulated;cycle_t mask;u32 mult;u32 shift;
include/linux/clocksource.h +56 -2
95 lines not on this page · raw message
kernel/time/timekeeping.c +19 -16
@@ -66,16 +66,10 @@ static struct clocksource *clock; /* poi*/ static inline s64 __get_nsec_offset (void ) { -cycle_t cycle_now, cycle_delta; +cycle_t cycle_delta;s64 ns_offset; -/* read clocksource: */ - cycle_now =clocksource_read (clock); - -/* calculate the delta since the last update_wall_time: */ - cycle_delta = (cycle_now - clock->cycle_last) & clock->mask; - -/* convert to nanoseconds: */ + cycle_delta =clocksource_get_cycles (clock,clocksource_read (clock)); ns_offset =cyc2ns (clock, cycle_delta);return ns_offset;
@@ -195,7 +189,7 @@ static void change_clocksource(void) clock = new; clock->cycle_last = now; - + clock->cycle_accumulated =0 ; clock->error =0 ; clock->xtime_nsec =0 ;clocksource_calculate_interval (clock,NTP_INTERVAL_LENGTH );
@@ -205,9 +199,15 @@ static void change_clocksource(void)printk (KERN_INFO "Time: %s clocksource has been installed.\n" , clock->name); } + +void timekeeping_accumulate (void ) +{ +clocksource_accumulate (clock,clocksource_read (clock)); +}#else static inline void change_clocksource (void ) { }static inline s64 __get_nsec_offset (void ) {return 0 ; } +void timekeeping_accumulate (void ) { }#endif /**
@@ -302,6 +302,7 @@ static int timekeeping_resume(struct systimespec_add_ns (&xtime, timekeeping_suspend_nsecs);/* re-base the last cycle value */ clock->cycle_last =clocksource_read (clock); + clock->cycle_accumulated =0 ; clock->error =0 ; timekeeping_suspended =0 ;write_sequnlock_irqrestore (&xtime_lock, flags);
@@ -448,27 +449,29 @@ static void clocksource_adjust(s64 offse*/ void update_wall_time (void ) { -cycle_t offset; +cycle_t cycle_now, offset;/* Make sure we're fully resumed: */ if (unlikely (timekeeping_suspended))return ;#ifdef CONFIG_GENERIC_TIME - offset = (clocksource_read (clock) - clock->cycle_last) & clock->mask; + cycle_now =clocksource_read (clock);#else - offset = clock->cycle_interval; + cycle_now = clock->cycle_last + clock->cycle_interval;#endif + offset = (cycle_now - clock->cycle_last) & clock->mask; +clocksource_accumulate (clock, cycle_now); + clock->xtime_nsec += (s64 )xtime.tv_nsec << clock->shift;/* normally this loop will run just once, however in the * case of lost or late ticks, it will accumulate correctly. */ -while (offset >= clock->cycle_interval) { +while (clock->cycle_accumulated >= clock->cycle_interval) {/* accumulate one interval */ clock->xtime_nsec += clock->xtime_interval; - clock->cycle_last += clock->cycle_interval; - offset -= clock->cycle_interval; + clock->cycle_accumulated -= clock->cycle_interval;if (clock->xtime_nsec >= (u64 )NSEC_PER_SEC << clock->shift) { clock->xtime_nsec -= (u64 )NSEC_PER_SEC << clock->shift;
@@ -482,7 +485,7 @@ void update_wall_time(void) }/* correct the clock when NTP error is too big */ -clocksource_adjust (offset); +clocksource_adjust (clock->cycle_accumulated);/* store full nanoseconds into xtime */ xtime.tv_nsec = (s64 )clock->xtime_nsec >> clock->shift;
Steven Rostedt
reviewerRFC PATCH 7/23 ppc clock accumulate fix
In reply to Steven RostedtThe following is a quick and dirty fix for powerpc so it includes cycle_accumulated in its calculation. It relies on the fact that the powerpc clocksource is a 64bit counter (don't have to worry about multiple overflows), so the subtraction should be safe.
--- arch/powerpc/kernel/time.c | 3 ++- 1 file changed, 2 insertions(+), 1 deletion(-)
arch/powerpc/kernel/time.c +2 -1
@@ -773,7 +773,8 @@ void update_vsyscall(struct timespec *wa stamp_xsec = (u64 ) xtime.tv_nsec *XSEC_PER_SEC ;do_div (stamp_xsec,1000000000 ); stamp_xsec += (u64 ) xtime.tv_sec *XSEC_PER_SEC ; -update_gtod (clock->cycle_last, stamp_xsec, t2x); +update_gtod (clock->cycle_last-clock->cycle_accumulated, + stamp_xsec, t2x); }void update_vsyscall_tz (void )
Steven Rostedt
reviewerRFC PATCH 8/23 Fixup merge between xtime_cache and timkkeeping starvation fix
In reply to Steven RostedtQuoted 7 lines
void
update_wall_time(void)
{(quoted diff) +1
-1- cycle_t offset; + cycle_t cycle_now, offset; /* Make sure we're fully resumed: */ if (unlikely(timekeeping_suspended))
Review
Quoted 10 lines
(quoted diff) +3
-2return; #ifdef CONFIG_GENERIC_TIME - offset = (clocksource_read(clock) - clock->cycle_last) & clock->mask; + cycle_now = clocksource_read(clock); #else - offset = clock->cycle_interval; + cycle_now = clock->cycle_last + clock->cycle_interval; #endif + offset = (cycle_now - clock->cycle_last) & clock->mask;
It seems this offset addition was to merge against the colliding xtime_cache changes in mainline. However, I don't think its quite right, and might be causing incorrect time() or vtime() results if NO_HZ is enabled.
Quoted 18 lines
(quoted diff) +4
-3+ clocksource_accumulate(clock, cycle_now); + clock->xtime_nsec += (s64)xtime.tv_nsec << clock->shift; /* normally this loop will run just once, however in the * case of lost or late ticks, it will accumulate correctly. */ - while (offset >= clock->cycle_interval) { + while (clock->cycle_accumulated >= clock->cycle_interval) { /* accumulate one interval */ clock->xtime_nsec += clock->xtime_interval; - clock->cycle_last += clock->cycle_interval; - offset -= clock->cycle_interval; + clock->cycle_accumulated -= clock->cycle_interval; if (clock->xtime_nsec >= (u64)NSEC_PER_SEC << clock->shift) { clock->xtime_nsec -= (u64)NSEC_PER_SEC << clock->shift;
Review void update_wall_time(void) · line 488
Quoted 5 lines
(quoted diff) +1
-1@@ -482,7 +485,7 @@ void update_wall_time(void) } /* correct the clock when NTP error is too big */ - clocksource_adjust(offset); + clocksource_adjust(clock->cycle_accumulated);
I suspect the following is needed, but haven't been able to test it yet.
Fixup merge between xtime_cache and timekeeping starvation fix.
--- kernel/time/timekeeping.c | 5 ++--- 1 file changed, 2 insertions(+), 3 deletions(-)
kernel/time/timekeeping.c +2 -3
@@ -449,7 +449,7 @@ static void clocksource_adjust(s64 offse*/ void update_wall_time (void ) { -cycle_t cycle_now, offset; +cycle_t cycle_now;/* Make sure we're fully resumed: */ if (unlikely (timekeeping_suspended))
@@ -460,7 +460,6 @@ void update_wall_time(void)#else cycle_now = clock->cycle_last + clock->cycle_interval;#endif - offset = (cycle_now - clock->cycle_last) & clock->mask;clocksource_accumulate (clock, cycle_now); clock->xtime_nsec += (s64 )xtime.tv_nsec << clock->shift;
@@ -491,7 +490,7 @@ void update_wall_time(void) xtime.tv_nsec = (s64 )clock->xtime_nsec >> clock->shift; clock->xtime_nsec -= (s64 )xtime.tv_nsec << clock->shift; -update_xtime_cache (cyc2ns (clock, offset)); +update_xtime_cache (cyc2ns (clock, clock->cycle_accumulated));/* check to see if there is a new clocksource to use */ change_clocksource ();
Steven Rostedt
reviewerRFC PATCH 9/23 time keeping add cycle_raw for actual incrementation
In reply to Steven RostedtThe get_monotonic_cycles needs to produce a monotonic counter as output.
This patch adds a cycle_raw to produce an accumulative counter. Unfortunately there is already an cycle_accumulate variable, but that is used to avoid clock source overflow and can also be decremented (probably that name should be changed and we should use that for this patch).
--- include/linux/clocksource.h | 3 ++- 1 file changed, 2 insertions(+), 1 deletion(-)
include/linux/clocksource.h +2 -1
@@ -87,7 +87,7 @@ struct clocksource {* more than one cache line. */ struct { -cycle_t cycle_last, cycle_accumulated; +cycle_t cycle_last, cycle_accumulated, cycle_raw; }____cacheline_aligned_in_smp ;u64 xtime_nsec;
@@ -204,6 +204,7 @@ static inline void clocksource_accumulatcycle_t offset = (now - cs->cycle_last) & cs->mask; cs->cycle_last = now; cs->cycle_accumulated += offset; + cs->cycle_raw += offset; }/**
Steven Rostedt
reviewerRFC PATCH 10/23 initialize the clock source to jiffies clock.
In reply to Steven RostedtThe latency tracer can call clocksource_read very early in bootup and before the clock source variable has been initialized. This results in a crash at boot up (even before earlyprintk is initialized). Since the clock->read variable points to NULL.
This patch simply initializes the clock to use clocksource_jiffies, so that any early user of clocksource_read will not crash.
--- include/linux/clocksource.h | 3 +++ kernel/time/timekeeping.c | 9 +++++++-- 2 files changed, 10 insertions(+), 2 deletions(-)
include/linux/clocksource.h +3 -0
@@ -274,6 +274,9 @@ extern struct clocksource* clocksource_gextern void clocksource_change_rating (struct clocksource *cs,int rating);extern void clocksource_resume (void ); +/* used to initialize clock */ +extern struct clocksource clocksource_jiffies; +#ifdef CONFIG_GENERIC_TIME_VSYSCALL extern void update_vsyscall (struct timespec *ts,struct clocksource *c);extern void update_vsyscall_tz (void );
kernel/time/timekeeping.c +7 -2
@@ -53,8 +53,13 @@ static inline void update_xtime_cache(u6timespec_add_ns (&xtime_cache, nsec); } -static struct clocksource *clock;/* pointer to current clocksource */ - +/* +* pointer to current clocksource +* Just in case we use clocksource_read before we initialize +* the actual clock source. Instead of calling a NULL read pointer +* we return jiffies. +*/ +static struct clocksource *clock = &clocksource_jiffies;#ifdef CONFIG_GENERIC_TIME /**
Steven Rostedt
reviewerRFC PATCH 11/23 add get_monotonic_cycles
In reply to Steven RostedtThe latency tracer needs a way to get an accurate time without grabbing any locks. Locks themselves might call the latency tracer and cause at best a slow down.
This patch adds get_monotonic_cycles that returns cycles from a reliable clock source in a monotonic fashion.
--- include/linux/clocksource.h | 3 ++ kernel/time/timekeeping.c | 48 ++++++++++++++++++++++++++++++++++++++++++++ 2 files changed, 51 insertions(+)
include/linux/clocksource.h +3 -0
@@ -273,6 +273,9 @@ extern int clocksource_register(struct cextern struct clocksource *clocksource_get_next (void );extern void clocksource_change_rating (struct clocksource *cs,int rating);extern void clocksource_resume (void ); +extern cycle_t get_monotonic_cycles (void ); +extern unsigned long cycles_to_usecs (cycle_t cycles); +extern cycle_t usecs_to_cycles (unsigned long usecs);/* used to initialize clock */ extern struct clocksource clocksource_jiffies;
kernel/time/timekeeping.c +48 -0
54 lines not on this page · raw message
Steven Rostedt
reviewerRFC PATCH 12/23 Use RCU algorithm for monotonic cycles.
In reply to Steven RostedtFrom: john stultz <[email protected]>
Quoted 9 lines · Mathieu Desnoyers
I would disable preemption in
clocksource_get_basecycles. We would not want to be scheduled out while we hold a pointer to the old array element.Review
Quoted 1 line
(quoted diff) +1
-0+ int num = cs->base_num;Since you deal with
base_numin a shared manner (not per cpu), you will need asmp_read_barrier_depend()here after thecs->base_numread.
Quoted 4 lines
You should think about reading the
cs->base_numfirst, and _after_ that read the real clocksource. Here, the clocksource value is passed as parameter. It means that the read clocksource may have been read in the previous RCU window.
Here's an updated version of the patch w/ the suggested memory barrier changes and favored (1-x) inversion change. ;) Let me know if you see any other holes, or have any other suggestions or ideas.
Still un-tested (my test box will free up soon, I promise!), but builds.
[ Steven Rostedt has been running this patch with no problems ]
--- include/linux/clocksource.h | 50 +++++++++++++++++++++++++++++++++++--------- kernel/time/timekeeping.c | 36 ++++--------------------------- 2 files changed, 45 insertions(+), 41 deletions(-)
include/linux/clocksource.h +40 -10
@@ -87,9 +87,17 @@ struct clocksource {* more than one cache line. */ struct { -cycle_t cycle_last, cycle_accumulated, cycle_raw; - }____cacheline_aligned_in_smp ; +cycle_t cycle_last, cycle_accumulated; +/* base structure provides lock-free read +* access to a virtualized 64bit counter +* Uses RCU-like update. +*/ +struct { +cycle_t cycle_base_last, cycle_base; + } base[2 ]; +int base_num; + }____cacheline_aligned_in_smp ;u64 xtime_nsec;s64 error;
@@ -175,19 +183,29 @@ static inline cycle_t clocksource_read(s }/** -* clocksource_get_cycles: - Access the clocksource's accumulated cycle value +* clocksource_get_basecycles: - get the clocksource's accumulated cycle value * @cs: pointer to clocksource being read * @now: current cycle value * * Uses the clocksource to return the current cycle_t value. * NOTE!!!: This is different from clocksource_read, because it -* returns the accumulated cycle value! Must hold xtime lock! +* returns a 64bit wide accumulated value. */ static inline cycle_t -clocksource_get_cycles (struct clocksource *cs,cycle_t now) +clocksource_get_basecycles (struct clocksource *cs) { -cycle_t offset = (now - cs->cycle_last) & cs->mask; - offset += cs->cycle_accumulated; +int num; +cycle_t now, offset; + +preempt_disable (); + num = cs->base_num; +smp_read_barrier_depends (); + now =clocksource_read (cs); + offset = (now - cs->base[num].cycle_base_last); + offset &= cs->mask; + offset += cs->base[num].cycle_base; +preempt_enable (); +return offset; }
@@ -197,14 +215,26 @@ clocksource_get_cycles(struct clocksourc* @now: current cycle value * * Used to avoids clocksource hardware overflow by periodically -* accumulating the current cycle delta. Must hold xtime write lock! +* accumulating the current cycle delta. Uses RCU-like update, but +* ***still requires the xtime_lock is held for writing!*** */ static inline void clocksource_accumulate (struct clocksource *cs,cycle_t now) { -cycle_t offset = (now - cs->cycle_last) & cs->mask; +/* First update the monotonic base portion. +* The dual array update method allows for lock-free reading. +*/ +int num =1 - cs->base_num; +cycle_t offset = (now - cs->base[1 -num].cycle_base_last); + offset &= cs->mask; + cs->base[num].cycle_base = cs->base[1 -num].cycle_base + offset; + cs->base[num].cycle_base_last = now; +wmb (); + cs->base_num = num; + +/* Now update the cycle_accumulated portion */ + offset = (now - cs->cycle_last) & cs->mask; cs->cycle_last = now; cs->cycle_accumulated += offset; - cs->cycle_raw += offset; }/**
kernel/time/timekeeping.c +5 -31
@@ -71,10 +71,12 @@ static struct clocksource *clock = &cloc*/ static inline s64 __get_nsec_offset (void ) { -cycle_t cycle_delta; +cycle_t now, cycle_delta;s64 ns_offset; - cycle_delta =clocksource_get_cycles (clock,clocksource_read (clock)); + now =clocksource_read (clock); + cycle_delta = (now - clock->cycle_last) & clock->mask; + cycle_delta += clock->cycle_accumulated; ns_offset =cyc2ns (clock, cycle_delta);return ns_offset;
@@ -105,35 +107,7 @@ static inline void __get_realtime_clock_ cycle_t notrace get_monotonic_cycles(void) { -cycle_t cycle_now, cycle_delta, cycle_raw, cycle_last; - -do { -/* -* cycle_raw and cycle_last can change on -* another CPU and we need the delta calculation -* of cycle_now and cycle_last happen atomic, as well -* as the adding to cycle_raw. We don't need to grab -* any locks, we just keep trying until get all the -* calculations together in one state. -* -* In fact, we __cant__ grab any locks. This -* function is called from the latency_tracer which can -* be called anywhere. To grab any locks (including -* seq_locks) we risk putting ourselves into a deadlock. -*/ - cycle_raw = clock->cycle_raw; - cycle_last = clock->cycle_last; - -/* read clocksource: */ - cycle_now =clocksource_read (clock); - -/* calculate the delta since the last update_wall_time: */ - cycle_delta = (cycle_now - cycle_last) & clock->mask; - - }while (cycle_raw != clock->cycle_raw || - cycle_last != clock->cycle_last); - -return cycle_raw + cycle_delta; +return clocksource_get_basecycles (clock); }unsigned long notrace cycles_to_usecs (cycle_t cycles)
Re: [RFC PATCH 12/23 -v4] Use RCU algorithm for monotonic cycles.
Quoted 4 lines · Steven Rostedt
From: john stultz <[email protected]>
static inline
cycle_tinclude/linux/clocksource.h +0
-1-clocksource_get_cycles(struct clocksource *cs, cycle_t now)
include/linux/clocksource.h static inline cycle_t clocksource_read(s · line 202
Quoted 10 lines
include/linux/clocksource.h +7
-2+clocksource_get_basecycles(struct clocksource *cs) { -cycle_t offset = (now - cs->cycle_last) & cs->mask; - offset += cs->cycle_accumulated; +int num; +cycle_t now, offset; + +preempt_disable (); + num = cs->base_num; +smp_read_barrier_depends ();
All barriers need comments in the code. eg. with read barriers, the comment should contain a list of the loads being ordered, and a reference to the places where stores come from.
I know it isn't too hard to follow _now_, but it makes the code more maintainable.
Quoted 20 lines
include/linux/clocksource.h +8
-2+ now =clocksource_read (cs); + offset = (now - cs->base[num].cycle_base_last); + offset &= cs->mask; + offset += cs->base[num].cycle_base; +preempt_enable (); +return offset; }@@ -197,14 +215,26 @@ clocksource_get_cycles(struct clocksourc* @now: current cycle value * * Used to avoids clocksource hardware overflow by periodically -* accumulating the current cycle delta. Must hold xtime write lock! +* accumulating the current cycle delta. Uses RCU-like update, but +* ***still requires the xtime_lock is held for writing!*** */ static inline void clocksource_accumulate (struct clocksource *cs,cycle_t now) { -cycle_t offset = (now - cs->cycle_last) & cs->mask;
include/linux/clocksource.h clocksource_get_cycles(struct clocksourc · line 232
Quoted 10 lines
include/linux/clocksource.h +10
-0+/* First update the monotonic base portion. +* The dual array update method allows for lock-free reading. +*/ +int num =1 - cs->base_num; +cycle_t offset = (now - cs->base[1 -num].cycle_base_last); + offset &= cs->mask; + cs->base[num].cycle_base = cs->base[1 -num].cycle_base + offset; + cs->base[num].cycle_base_last = now; +wmb (); + cs->base_num = num;
Ditto for the wmb. Also, I think the wmb() can probably just be smp_wmb().
Steven Rostedt
reviewerRe: [RFC PATCH 12/23 -v4] Use RCU algorithm for monotonic cycles.
Quoted 20 lines · Nick Piggin
Quoted 4 lines · Steven Rostedt
From: john stultz <[email protected]>
static inline
cycle_tinclude/linux/clocksource.h +0
-1-clocksource_get_cycles(struct clocksource *cs, cycle_t now)include/linux/clocksource.h static inline cycle_t clocksource_read(s · line 202
Quoted 10 lines
include/linux/clocksource.h +7
-2+clocksource_get_basecycles(struct clocksource *cs) { -cycle_t offset = (now - cs->cycle_last) & cs->mask; - offset += cs->cycle_accumulated; +int num; +cycle_t now, offset; + +preempt_disable (); + num = cs->base_num; +smp_read_barrier_depends ();All barriers need comments in the code. eg. with read barriers, the comment should contain a list of the loads being ordered, and a reference to the places where stores come from.
Quoted 2 lines
I know it isn't too hard to follow _now_, but it makes the code more maintainable.
Yep, thanks for the reminder. This was a quick patch from John. I'll add the necessary comment for the next release. Hmm, I'm surprised that checkpatch didn't complain.
Quoted 27 lines
Quoted 27 lines
include/linux/clocksource.h +13
-2+ now =clocksource_read (cs); + offset = (now - cs->base[num].cycle_base_last); + offset &= cs->mask; + offset += cs->base[num].cycle_base; +preempt_enable (); +return offset; }@@ -197,14 +215,26 @@ clocksource_get_cycles(struct clocksourc* @now: current cycle value * * Used to avoids clocksource hardware overflow by periodically -* accumulating the current cycle delta. Must hold xtime write lock! +* accumulating the current cycle delta. Uses RCU-like update, but +* ***still requires the xtime_lock is held for writing!*** */ static inline void clocksource_accumulate (struct clocksource *cs,cycle_t now) { -cycle_t offset = (now - cs->cycle_last) & cs->mask; +/* First update the monotonic base portion. +* The dual array update method allows for lock-free reading. +*/ +int num =1 - cs->base_num; +cycle_t offset = (now - cs->base[1 -num].cycle_base_last);
Quoted 8 lines
include/linux/clocksource.h clocksource_get_cycles(struct clocksourc · line 232
Quoted 5 lines
include/linux/clocksource.h +5
-0+ offset &= cs->mask; + cs->base[num].cycle_base = cs->base[1 -num].cycle_base + offset; + cs->base[num].cycle_base_last = now; +wmb (); + cs->base_num = num;Ditto for the wmb. Also, I think the
wmb()can probably just besmp_wmb().
Yep, this too. We suggested earlier to John to switch this to a smp_wmb, but I took his patch before the update. This will be fixed in the next round too.
Thanks,
-- Steve
Steven Rostedt
reviewerRFC PATCH 13/23 add notrace annotations to timing events
In reply to Steven RostedtThis patch adds notrace annotations to timer functions that will be used by tracing. This helps speed things up and also keeps the ugliness of printing these functions down.
--- arch/x86/kernel/apic_32.c | 2 +- arch/x86/kernel/hpet.c | 2 +- arch/x86/kernel/time_32.c | 2 +- arch/x86/kernel/tsc_32.c | 2 +- arch/x86/kernel/tsc_64.c | 4 ++-- arch/x86/lib/delay_32.c | 6 +++--- drivers/clocksource/acpi_pm.c | 8 ++++---- 7 files changed, 13 insertions(+), 13 deletions(-)
arch/x86/kernel/apic_32.c +1 -1
@@ -577,7 +577,7 @@ static void local_apic_timer_interrupt(v* interrupt as well. Thus we cannot inline the local irq ... ] */ -void fastcall smp_apic_timer_interrupt(struct pt_regs *regs) +notrace fastcall void smp_apic_timer_interrupt(struct pt_regs *regs) {struct pt_regs *old_regs =set_irq_regs (regs);
arch/x86/kernel/hpet.c +1 -1
@@ -295,7 +295,7 @@ static int hpet_legacy_next_event(unsign/* * Clock source related code */ -static cycle_t read_hpet (void ) +static notrace cycle_t read_hpet(void) {return (cycle_t )hpet_readl (HPET_COUNTER ); }
arch/x86/kernel/time_32.c +1 -1
@@ -122,7 +122,7 @@ static int set_rtc_mmss(unsigned long noint timer_ack; -unsigned long profile_pc (struct pt_regs *regs) +notrace unsigned long profile_pc (struct pt_regs *regs) {unsigned long pc =instruction_pointer (regs);
arch/x86/kernel/tsc_32.c +1 -1
@@ -269,7 +269,7 @@ core_initcall(cpufreq_tsc);static unsigned long current_tsc_khz =0 ; -static cycle_t read_tsc (void ) +static notrace cycle_t read_tsc(void) {cycle_t ret;
arch/x86/kernel/tsc_64.c +2 -2
@@ -248,13 +248,13 @@ __setup("notsc", notsc_setup);/* clock source code: */ -static cycle_t read_tsc (void ) +static notrace cycle_t read_tsc(void) {cycle_t ret = (cycle_t )get_cycles_sync ();return ret; } -static cycle_t __vsyscall_fn vread_tsc(void) +static notrace cycle_t __vsyscall_fn vread_tsc(void) {cycle_t ret = (cycle_t )get_cycles_sync ();return ret;
arch/x86/lib/delay_32.c +3 -3
@@ -24,7 +24,7 @@#endif /* simple loop based delay: */ -static void delay_loop (unsigned long loops) +static notrace void delay_loop(unsigned long loops) {int d0;
@@ -39,7 +39,7 @@ static void delay_loop(unsigned long loo }/* TSC based delay: */ -static void delay_tsc (unsigned long loops) +static notrace void delay_tsc(unsigned long loops) {unsigned long bclock, now;
@@ -72,7 +72,7 @@ int read_current_timer(unsigned long *tireturn -1 ; } -void __delay (unsigned long loops) +notrace void __delay(unsigned long loops) {delay_fn (loops); }
drivers/clocksource/acpi_pm.c +4 -4
@@ -30,13 +30,13 @@*/ u32 pmtmr_ioport__read_mostly ; -static inline u32 read_pmtmr (void ) +static inline notrace u32 read_pmtmr(void) {/* mask the output to 24 bits */ return inl (pmtmr_ioport) &ACPI_PM_MASK ; } -u32 acpi_pm_read_verified (void ) +notrace u32 acpi_pm_read_verified(void) {u32 v1 =0 , v2 =0 , v3 =0 ;
@@ -56,12 +56,12 @@ u32 acpi_pm_read_verified(void)return v2; } -static cycle_t acpi_pm_read_slow (void ) +static notrace cycle_t acpi_pm_read_slow(void) {return (cycle_t )acpi_pm_read_verified (); } -static cycle_t acpi_pm_read (void ) +static notrace cycle_t acpi_pm_read(void) {return (cycle_t )read_pmtmr (); }
Steven Rostedt
reviewerRFC PATCH 14/23 mcount based trace in the form of a header file library
In reply to Steven RostedtThis is a simple trace that uses the mcount infrastructure. It is designed to be fast and small, and easy to use. It is useful to record things that happen over a very short period of time, and not to analyze the system in general.
An interface is added to the debugfs
/debugfs/tracing/
This patch adds the following files:
fn_trace_ctrl
echoing "1" into this file starts the mcount function tracing
(if sysctl kernel.mcount_enabled=1)
echoing "0" turns it off.
function_trace
This file is readonly and holds the result of the trace.
trace
This file outputs a easier to read version of the trace.
iter_ctrl
Controls the way the output of traces look.
So far there's two controls:
echoing in "symonly" will only show the kallsyms variables
without the addresses (if kallsyms was configured)
echoing in "verbose" will change the output to show
a lot more data, but not very easy to understand by humans.
echoing in "nosymonly" turns off symonly. echoing in "noverbose" turns off verbose.
The output of the function_trace file is as follows
"echo noverbose > /debugfs/tracing/iter_ctrl"
preemption latency trace v1.1.5 on 2.6.24-rc7-tst
--------------------------------------------------------------------
latency: 0 us, #419428/4361791, CPU#1 | (M:desktop VP:0, KP:0, SP:0 HP:0 #P:4)
-----------------
| task: -0 (uid:0 nice:0 policy:0 rt_prio:0)
-----------------
_------=> CPU#
/ _-----=> irqs-off
| / _----=> need-resched
|| / _---=> hardirq/softirq
||| / _--=> preempt-depth
|||| /
||||| delay
cmd pid ||||| time | caller
\ / ||||| \ | /
swapper-0 0d.h. 1595128us+: set_normalized_timespec+0x8/0x2d <c043841d> (ktime_get_ts+0x4a/0x4e <c04499d4>)
swapper-0 0d.h. 1595131us+: _spin_lock+0x8/0x18 <c0630690> (hrtimer_interrupt+0x6e/0x1b0 <c0449c56>)Or with verbose turned on:
"echo verbose > /debugfs/tracing/iter_ctrl"
preemption latency trace v1.1.5 on 2.6.24-rc7-tst
--------------------------------------------------------------------
latency: 0 us, #419428/4361791, CPU#1 | (M:desktop VP:0, KP:0, SP:0 HP:0 #P:4)
-----------------
| task: -0 (uid:0 nice:0 policy:0 rt_prio:0)
-----------------
swapper 0 0 9 00000000 00000000 [f3675f41] 1595.128ms (+0.003ms): set_normalized_timespec+0x8/0x2d <c043841d> (ktime_get_ts+0x4a/0x4e <c04499d4>)
swapper 0 0 9 00000000 00000001 [f3675f45] 1595.131ms (+0.003ms): _spin_lock+0x8/0x18 <c0630690> (hrtimer_interrupt+0x6e/0x1b0 <c0449c56>)
swapper 0 0 9 00000000 00000002 [f3675f48] 1595.135ms (+0.003ms): _spin_lock+0x8/0x18 <c0630690> (hrtimer_interrupt+0x6e/0x1b0 <c0449c56>)The "trace" file is not affected by the verbose mode, but is by the symonly.
echo "nosymonly" > /debugfs/tracing/iter_ctrl
tracer:
[ 81.479967] CPU 0: bash:3154 register_mcount_function+0x5f/0x66 <ffffffff80337a4d> <-- _spin_unlock_irqrestore+0xe/0x5a <ffffffff8048cc8f> [ 81.479967] CPU 0: bash:3154 _spin_unlock_irqrestore+0x3e/0x5a <ffffffff8048ccbf> <-- sub_preempt_count+0xc/0x7a <ffffffff80233d7b> [ 81.479968] CPU 0: bash:3154 sub_preempt_count+0x30/0x7a <ffffffff80233d9f> <-- in_lock_functions+0x9/0x24 <ffffffff8025a75d> [ 81.479968] CPU 0: bash:3154 vfs_write+0x11d/0x155 <ffffffff8029a043> <-- dnotify_parent+0x12/0x78 <ffffffff802d54fb> [ 81.479968] CPU 0: bash:3154 dnotify_parent+0x2d/0x78 <ffffffff802d5516> <-- _spin_lock+0xe/0x70 <ffffffff8048c910> [ 81.479969] CPU 0: bash:3154 _spin_lock+0x1b/0x70 <ffffffff8048c91d> <-- add_preempt_count+0xe/0x77 <ffffffff80233df7> [ 81.479969] CPU 0: bash:3154 add_preempt_count+0x3e/0x77 <ffffffff80233e27> <-- in_lock_functions+0x9/0x24 <ffffffff8025a75d>
echo "symonly" > /debugfs/tracing/iter_ctrl
tracer:
[ 81.479913] CPU 0: bash:3154 register_mcount_function+0x5f/0x66 <-- _spin_unlock_irqrestore+0xe/0x5a [ 81.479913] CPU 0: bash:3154 _spin_unlock_irqrestore+0x3e/0x5a <-- sub_preempt_count+0xc/0x7a [ 81.479913] CPU 0: bash:3154 sub_preempt_count+0x30/0x7a <-- in_lock_functions+0x9/0x24 [ 81.479914] CPU 0: bash:3154 vfs_write+0x11d/0x155 <-- dnotify_parent+0x12/0x78 [ 81.479914] CPU 0: bash:3154 dnotify_parent+0x2d/0x78 <-- _spin_lock+0xe/0x70 [ 81.479914] CPU 0: bash:3154 _spin_lock+0x1b/0x70 <-- add_preempt_count+0xe/0x77 [ 81.479914] CPU 0: bash:3154 add_preempt_count+0x3e/0x77 <-- in_lock_functions+0x9/0x24
--- lib/Makefile | 1 lib/tracing/Kconfig | 16 lib/tracing/Makefile | 3 lib/tracing/trace_function.c | 190 ++++++++++ lib/tracing/tracer.c | 786 +++++++++++++++++++++++++++++++++++++++++++ lib/tracing/tracer.h | 94 +++++ 6 files changed, 1090 insertions(+)
lib/tracing/Kconfig +16 -0
@@ -8,3 +8,19 @@ config HAVE_MCOUNT config MCOUNT bool select FRAME_POINTER + +config TRACING + bool + depends on DEBUG_KERNEL + +config FUNCTION_TRACER + bool "Profiler instrumentation based tracer" + depends on DEBUG_KERNEL && HAVE_MCOUNT + default n + select MCOUNT + select TRACING + help + Use profiler instrumentation, adding -pg to CFLAGS. This will + insert a call to an architecture specific __mcount routine, + that the debugging mechanism using this facility will hook by + providing a set of inline routines.
lib/tracing/Makefile +3 -0
@@ -1,3 +1,6 @@ obj-$(CONFIG_MCOUNT) += libmcount.o +obj-$(CONFIG_TRACING) += tracer.o +obj-$(CONFIG_FUNCTION_TRACER) += trace_function.o + libmcount-y := mcount.o
lib/tracing/tracer.c new file +786 -0
786 lines not on this page · raw message
lib/tracing/tracer.h new file +94 -0
94 lines not on this page · raw message
lib/Makefile +1 -0
@@ -67,6 +67,7 @@ obj-$(CONFIG_SWIOTLB) += swiotlb.o obj-$(CONFIG_FAULT_INJECTION) += fault-inject.o obj-$(CONFIG_MCOUNT) += tracing/ +obj-$(CONFIG_TRACING) += tracing/ lib-$(CONFIG_GENERIC_BUG) += bug.o
lib/tracing/trace_function.c new file +190 -0
190 lines not on this page · raw message
Steven Rostedt
reviewerRFC PATCH 15/23 Add context switch marker to sched.c
In reply to Steven RostedtAdd marker into context_switch to record the prev and next tasks.
--- kernel/sched.c | 2 ++ 1 file changed, 2 insertions(+)
kernel/sched.c +2 -0
@@ -1933,6 +1933,8 @@ context_switch(struct rq *rq, struct tasstruct mm_struct *mm, *oldmm;prepare_task_switch (rq, prev, next); +trace_mark (kernel_sched_schedule, +"prev %p next %p" , prev, next); mm = next->mm; oldmm = prev->active_mm;/*
Steven Rostedt
reviewerRFC PATCH 16/23 Make the task State char-string visible to all
In reply to Steven RostedtThe tracer wants to be able to convert the state number into a user visible character. This patch pulls that conversion string out the scheduler into the header. This way if it were to ever change, other parts of the kernel will know.
--- include/linux/sched.h | 2 ++ kernel/sched.c | 2 +- 2 files changed, 3 insertions(+), 1 deletion(-)
include/linux/sched.h +2 -0
@@ -1987,6 +1987,8 @@ static inline void migration_init(void) }#endif +#define TASK_STATE_TO_CHAR_STR "RSDTtZX" +#endif /* __KERNEL__ */ #endif
kernel/sched.c +1 -1
@@ -4890,7 +4890,7 @@ out_unlock:return retval; } -static const char stat_nam[] ="RSDTtZX" ; +static const char stat_nam[] =TASK_STATE_TO_CHAR_STR ;static void show_task (struct task_struct *p) {
Steven Rostedt
reviewerRFC PATCH 17/23 Add tracing of context switches
In reply to Steven RostedtThis patch adds context switch tracing, of the format of:
_------=> CPU#
/ _-----=> irqs-off
| / _----=> need-resched
|| / _---=> hardirq/softirq
||| / _--=> preempt-depth
|||| /
||||| delay
cmd pid ||||| time | caller
\ / ||||| \ | /
swapper-0 1d..3 137us+: 0:140:R --> 2912:120
sshd-2912 1d..3 216us+: 2912:120:S --> 0:140
swapper-0 1d..3 261us+: 0:140:R --> 2912:120
bash-2920 0d..3 267us+: 2920:120:S --> 0:140
sshd-2912 1d..3 330us!: 2912:120:S --> 0:140
swapper-0 1d..3 2389us+: 0:140:R --> 2847:120
yum-upda-2847 1d..3 2411us!: 2847:120:S --> 0:140
swapper-0 0d..3 11089us+: 0:140:R --> 3139:120
gdm-bina-3139 0d..3 11113us!: 3139:120:S --> 0:140
swapper-0 1d..3 102328us+: 0:140:R --> 2847:120
yum-upda-2847 1d..3 102348us!: 2847:120:S --> 0:140Two files are added to /debugfs/tracing
sched_trace - outputs the above format.
sched_trace_ctrl
0 - turns off context switch tracing.
1 - turns on context switch tracing.
--- lib/tracing/Kconfig | 10 + lib/tracing/Makefile | 1 lib/tracing/trace_sched_switch.c | 205 +++++++++++++++++++++++++++++++++++++++ lib/tracing/tracer.c | 32 ++++++ lib/tracing/tracer.h | 18 +++ 5 files changed, 265 insertions(+), 1 deletion(-)
lib/tracing/Kconfig +10 -0
@@ -24,3 +24,13 @@ config FUNCTION_TRACER insert a call to an architecture specific __mcount routine, that the debugging mechanism using this facility will hook by providing a set of inline routines. + +config CONTEXT_SWITCH_TRACER + bool "Trace process context switches" + depends on DEBUG_KERNEL + default n + select TRACING + help + This tracer hooks into the context switch and records + all switching of tasks. +
lib/tracing/Makefile +1 -0
@@ -1,6 +1,7 @@ obj-$(CONFIG_MCOUNT) += libmcount.o obj-$(CONFIG_TRACING) += tracer.o +obj-$(CONFIG_CONTEXT_SWITCH_TRACER) += trace_sched_switch.o obj-$(CONFIG_FUNCTION_TRACER) += trace_function.o libmcount-y := mcount.o
lib/tracing/trace_sched_switch.c new file +205 -0
205 lines not on this page · raw message
lib/tracing/tracer.c +32 -0
@@ -31,6 +31,7 @@ enum trace_type { __TRACE_FIRST_TYPE =0 ,TRACE_FN , +TRACE_CTX , __TRACE_LAST_TYPE };
@@ -107,6 +108,24 @@ notrace void tracing_function_trace(stru entry->fn.parent_ip = parent_ip; } +notrace void tracing_sched_switch_trace(struct tracing_trace *tr, +struct tracing_trace_cpu *data, +struct task_struct *prev, +struct task_struct *next, +unsigned long flags) +{ +struct tracing_entry *entry; + + entry =tracing_get_trace_entry (tr, data); +tracing_generic_entry_update (entry, flags); + entry->type =TRACE_CTX ; + entry->ctx.prev_pid = prev->pid; + entry->ctx.prev_prio = prev->prio; + entry->ctx.prev_state = prev->state; + entry->ctx.next_pid = next->pid; + entry->ctx.next_prio = next->prio; +} +#ifdef CONFIG_DEBUG_FS enum trace_iterator { TRACE_ITER_SYM_ONLY = 1,
@@ -414,6 +433,8 @@ lat_print_timestamp(struct seq_file *m,seq_puts (m," : " ); } +static const char state_to_char[] =TASK_STATE_TO_CHAR_STR ; + static void notraceprint_lat_fmt (struct seq_file *m,struct tracing_iterator *iter,unsigned int trace_idx,int cpu)
@@ -424,6 +445,7 @@ print_lat_fmt(struct seq_file *m, structunsigned long rel_usecs;int sym_only = !!(trace_flags &TRACE_ITER_SYM_ONLY );int verbose = !!(trace_flags &TRACE_ITER_VERBOSE ); +int S ;if (!next_entry) next_entry = entry;
@@ -450,6 +472,16 @@ print_lat_fmt(struct seq_file *m, structseq_print_ip_sym (m, entry->fn.parent_ip, sym_only);seq_puts (m,")\n" );break ; +case TRACE_CTX : +S = entry->ctx.prev_state <sizeof (state_to_char) ? + state_to_char[entry->ctx.prev_state] :'X' ; +seq_printf (m," %d:%d:%c --> %d:%d\n" , + entry->ctx.prev_pid, + entry->ctx.prev_prio, +S , + entry->ctx.next_pid, + entry->ctx.next_prio); +break ; } }
lib/tracing/tracer.h +17 -1
@@ -10,6 +10,14 @@ struct tracing_function {unsigned long parent_ip; }; +struct tracing_sched_switch { +unsigned int prev_pid; +unsigned char prev_prio; +unsigned char prev_state; +unsigned int next_pid; +unsigned char next_prio; +}; +struct tracing_entry {char type;char cpu;/* who will want to trace more than 256 CPUS? */
@@ -18,7 +26,10 @@ struct tracing_entry {int pid;cycle_t t;char comm[TASK_COMM_LEN ]; -struct tracing_function fn; +union { +struct tracing_function fn; +struct tracing_sched_switch ctx; + }; };struct tracing_trace_cpu {
@@ -75,6 +86,11 @@ void tracing_function_trace(struct traciunsigned long ip, unsigned long parent_ip, unsigned long flags); +void tracing_sched_switch_trace (struct tracing_trace *tr, +struct tracing_trace_cpu *data, +struct task_struct *prev, +struct task_struct *next, +unsigned long flags);extern struct file_operations tracing_fops;extern struct file_operations tracing_lt_fops;
Steven Rostedt
reviewerRFC PATCH 18/23 Generic command line storage
In reply to Steven RostedtSaving the comm of tasks for each trace is very expensive. This patch includes in the context switch hook, a way to store the last 100 command lines of tasks. This table is examined when a trace is to be printed.
Note: The comm may be destroyed if other traces are performed. Later (TBD) patches may simply store this information in the trace itself.
--- lib/tracing/Kconfig | 1 lib/tracing/trace_function.c | 2 lib/tracing/trace_sched_switch.c | 12 +++- lib/tracing/tracer.c | 112 +++++++++++++++++++++++++++++++++++++-- lib/tracing/tracer.h | 5 + 5 files changed, 124 insertions(+), 8 deletions(-)
lib/tracing/Kconfig +1 -0
@@ -19,6 +19,7 @@ config FUNCTION_TRACER default n select MCOUNT select TRACING + select CONTEXT_SWITCH_TRACER help Use profiler instrumentation, adding -pg to CFLAGS. This will insert a call to an architecture specific __mcount routine,
lib/tracing/trace_function.c +2 -0
@@ -80,9 +80,11 @@ static void function_trace_ctrl_update(sif (tr->ctrl ^ val) {if (val) { trace_enabled =1 ; +atomic_inc (&trace_record_cmdline);register_mcount_function (&trace_ops); }else { trace_enabled =0 ; +atomic_dec (&trace_record_cmdline);unregister_mcount_function (&trace_ops); } tr->ctrl = val;
lib/tracing/trace_sched_switch.c +10 -2
@@ -41,6 +41,9 @@ static notrace void sched_switch_callbacva_list ap;int cpu; +if (unlikely (atomic_read (&trace_record_cmdline))) +tracing_record_cmdline (current); +if (likely (!trace_enabled))return ;
@@ -49,6 +52,7 @@ static notrace void sched_switch_callbac next =va_arg (ap,typeof (next));va_end (ap); +raw_local_irq_save (flags); cpu =raw_smp_processor_id (); data = tr->data[cpu];
@@ -82,10 +86,14 @@ static void sched_switch_trace_ctrl_updasched_switch_reset (tr);if (tr->ctrl ^ val) { -if (val) +if (val) { +atomic_inc (&trace_record_cmdline); trace_enabled =1 ; -else + }else { trace_enabled =0 ; +atomic_dec (&trace_record_cmdline); + } + tr->ctrl = val; } }
lib/tracing/tracer.c +107 -5
168 lines not on this page · raw message
lib/tracing/tracer.h +4 -1
@@ -25,7 +25,6 @@ struct tracing_entry {char preempt_count;/* assumes PREEMPT_MASK is 8 bits or less */ int pid;cycle_t t; -char comm[TASK_COMM_LEN ];union {struct tracing_function fn;struct tracing_sched_switch ctx;
@@ -91,6 +90,10 @@ void tracing_sched_switch_trace(struct tstruct task_struct *prev, struct task_struct *next, unsigned long flags); +void tracing_record_cmdline (struct task_struct *tsk); + +extern atomic_t trace_record_cmdline; +extern atomic_t trace_record_cmdline_disabled;extern struct file_operations tracing_fops;extern struct file_operations tracing_lt_fops;
Steven Rostedt
reviewerRFC PATCH 19/23 trace generic call to schedule switch
In reply to Steven RostedtThis patch adds hooks into the schedule switch tracing to allow other latency traces to hook into the schedule switches.
--- lib/tracing/trace_sched_switch.c | 121 ++++++++++++++++++++++++++++++++++----- lib/tracing/tracer.h | 14 ++++ 2 files changed, 120 insertions(+), 15 deletions(-)
lib/tracing/tracer.h +14 -0
@@ -110,4 +110,18 @@ static inline notrace int page_order(con return ilog2(roundup_pow_of_two(nr_pages)); } +#ifdef CONFIG_CONTEXT_SWITCH_TRACER +typedef void (*tracer_switch_func_t )(struct tracing_trace *tr, +struct task_struct *prev, +struct task_struct *next); +struct tracer_switch_ops { +tracer_switch_func_t func; +struct tracing_trace *tr; +struct tracer_switch_ops *next; +}; + +extern int register_tracer_switch (struct tracer_switch_ops *ops); +extern int unregister_tracer_switch (struct tracer_switch_ops *ops); +#endif /* CONFIG_CONTEXT_SWITCH_TRACER */ +#endif /* _LINUX_MCOUNT_TRACER_H */
lib/tracing/trace_sched_switch.c +106 -15
151 lines not on this page · raw message
Steven Rostedt
reviewerRFC PATCH 20/23 Add marker in try_to_wake_up
In reply to Steven RostedtI looked at what Mathieu Desnoyers did in his LTTng patches to use as a marker for the wakeup latency timings. But unfortunately, his marker didn't give me enough information. What I need is the task pointer itself. I also look at its priority but I need to keep track of the task itself incase it gets pulled to another CPU. (and no, I'm not going to hook into the migration code)
I took his marker and added a pointer to p and the pointer to the current running task on p's runqueue (note it may not be the same runqueue as current is on).
--- kernel/sched.c | 4 ++++ 1 file changed, 4 insertions(+)
kernel/sched.c +4 -0
@@ -1633,6 +1633,10 @@ out_set_cpu: out_activate:#endif /* CONFIG_SMP */ +trace_mark (kernel_sched_wakeup, +"p %p rq->curr %p" , + p, rq->curr); +schedstat_inc (p, se.nr_wakeups);if (sync)schedstat_inc (p, se.nr_wakeups_sync);
Steven Rostedt
reviewerRFC PATCH 21/23 mcount tracer for wakeup latency timings.
In reply to Steven RostedtThis patch adds hooks to trace the wake up latency of the highest priority waking task. The following files are added to /debugfs/tracing/
wakeup_max_latency
holds the current max latency for wakeup
wakeup_thresh
if set to other than zero, a log will be recorded for every wakeup that takes longer than the number entered in here (usecs for all counters) (deletes previous trace)
wakeup_trace_ctrl
echo 1 to start tracing wakeups
echo 0 to stop
wakeup_trace
holds the output of the traces:
Examples:
(with mcount_enabled = 0)
============
preemption latency trace v1.1.5 on 2.6.24-rc8
--------------------------------------------------------------------
latency: 26 us, #2/2, CPU#1 | (M:rt VP:0, KP:0, SP:0 HP:0 #P:2)
-----------------
| task: migration/0-3 (uid:0 nice:-5 policy:1 rt_prio:99)
-----------------
_------=> CPU#
/ _-----=> irqs-off
| / _----=> need-resched
|| / _---=> hardirq/softirq
||| / _--=> preempt-depth
|||| /
||||| delay
cmd pid ||||| time | caller
\ / ||||| \ | /
quilt-8551 0d..3 0us+: wake_up_process+0x15/0x17 <ffffffff80233e80> (sched_exec+0xc9/0x100 <ffffffff80235343>)
quilt-8551 0d..4 26us : sched_switch_callback+0x73/0x81 <ffffffff80338d2f> (schedule+0x483/0x6d5 <ffffffff8048b3ee>)vim:ft=help
============
(with mcount_enabled = 1)
============
preemption latency trace v1.1.5 on 2.6.24-rc8
--------------------------------------------------------------------
latency: 36 us, #45/45, CPU#0 | (M:rt VP:0, KP:0, SP:0 HP:0 #P:2)
-----------------
| task: migration/1-5 (uid:0 nice:-5 policy:1 rt_prio:99)
-----------------
_------=> CPU#
/ _-----=> irqs-off
| / _----=> need-resched
|| / _---=> hardirq/softirq
||| / _--=> preempt-depth
|||| /
||||| delay
cmd pid ||||| time | caller
\ / ||||| \ | /
bash-10653 1d..3 0us : wake_up_process+0x15/0x17 <ffffffff80233e80> (sched_exec+0xc9/0x100 <ffffffff80235343>)
bash-10653 1d..3 1us : try_to_wake_up+0x271/0x2e7 <ffffffff80233dcf> (sub_preempt_count+0xc/0x7a <ffffffff8023309e>)
bash-10653 1d..2 2us : try_to_wake_up+0x296/0x2e7 <ffffffff80233df4> (update_rq_clock+0x9/0x20 <ffffffff802303f3>)
bash-10653 1d..2 2us : update_rq_clock+0x1e/0x20 <ffffffff80230408> (__update_rq_clock+0xc/0x90 <ffffffff80230366>)
bash-10653 1d..2 3us : __update_rq_clock+0x1b/0x90 <ffffffff80230375> (sched_clock+0x9/0x29 <ffffffff80214529>)
bash-10653 1d..2 4us : try_to_wake_up+0x2a6/0x2e7 <ffffffff80233e04> (activate_task+0xc/0x3f <ffffffff8022ffca>)
bash-10653 1d..2 4us : activate_task+0x2d/0x3f <ffffffff8022ffeb> (enqueue_task+0xe/0x66 <ffffffff8022ff66>)
bash-10653 1d..2 5us : enqueue_task+0x5b/0x66 <ffffffff8022ffb3> (enqueue_task_rt+0x9/0x3c <ffffffff80233351>)
bash-10653 1d..2 6us : try_to_wake_up+0x2ba/0x2e7 <ffffffff80233e18> (check_preempt_wakeup+0x12/0x99 <ffffffff80234f84>)
[...]
bash-10653 1d..5 33us : tracing_record_cmdline+0xcf/0xd4 <ffffffff80338aad> (_spin_unlock+0x9/0x33 <ffffffff8048d3ec>)
bash-10653 1d..5 34us : _spin_unlock+0x19/0x33 <ffffffff8048d3fc> (sub_preempt_count+0xc/0x7a <ffffffff8023309e>)
bash-10653 1d..4 35us : wakeup_sched_switch+0x65/0x2ff <ffffffff80339f66> (_spin_lock_irqsave+0xc/0xa9 <ffffffff8048d08b>)
bash-10653 1d..4 35us : _spin_lock_irqsave+0x19/0xa9 <ffffffff8048d098> (add_preempt_count+0xe/0x77 <ffffffff8023311a>)
bash-10653 1d..4 36us : sched_switch_callback+0x73/0x81 <ffffffff80338d2f> (schedule+0x483/0x6d5 <ffffffff8048b3ee>)vim:ft=help
============
The [...] was added here to not waste your email box space.
--- lib/tracing/Kconfig | 10 lib/tracing/Makefile | 1 lib/tracing/trace_wakeup.c | 526 +++++++++++++++++++++++++++++++++++++++++++++ 3 files changed, 537 insertions(+)
lib/tracing/Kconfig +10 -0
@@ -26,6 +26,16 @@ config FUNCTION_TRACER that the debugging mechanism using this facility will hook by providing a set of inline routines. +config WAKEUP_TRACER + bool "Trace wakeup latencies" + depends on DEBUG_KERNEL + select TRACING + select CONTEXT_SWITCH_TRACER + help + This tracer adds hooks into scheduling to time the latency + of the highest priority task tasks to be scheduled in + after it has worken up. + config CONTEXT_SWITCH_TRACER bool "Trace process context switches" depends on DEBUG_KERNEL
lib/tracing/Makefile +1 -0
@@ -3,5 +3,6 @@ obj-$(CONFIG_MCOUNT) += libmcount.o obj-$(CONFIG_TRACING) += tracer.o obj-$(CONFIG_CONTEXT_SWITCH_TRACER) += trace_sched_switch.o obj-$(CONFIG_FUNCTION_TRACER) += trace_function.o +obj-$(CONFIG_WAKEUP_TRACER) += trace_wakeup.o libmcount-y := mcount.o
lib/tracing/trace_wakeup.c new file +526 -0
526 lines not on this page · raw message
Steven Rostedt
reviewerRFC PATCH 22/23 Trace irq disabled critical timings
In reply to Steven RostedtThis patch adds latency tracing for critical timings. In /debugfs/tracing/ three files are added:
preempt_max_latency
holds the max latency thus far (in usecs)
(default to large number so one must start latency tracing)
preempt_thresh
threshold (in usecs) to always print out if irqs off is detected to be longer than stated here. If irq_thresh is non-zero, then max_irq_latency is ignored.
preempt_trace
Trace of where the latecy was detected.
preempt_fn_trace_ctrl
0 - don't use mcount
1 - use mcount to trace
Here's an example of a trace with preempt_fn_trace_ctrl == 0
=======
preemption latency trace v1.1.5 on 2.6.24-rc7
--------------------------------------------------------------------
latency: 100 us, #3/3, CPU#1 | (M:rt VP:0, KP:0, SP:0 HP:0 #P:2)
-----------------
| task: swapper-0 (uid:0 nice:0 policy:0 rt_prio:0)
----------------- => started at: _spin_lock_irqsave+0x2a/0xb7
=> ended at: _spin_unlock_irqrestore+0x32/0x5f
_------=> CPU#
/ _-----=> irqs-off
| / _----=> need-resched
|| / _---=> hardirq/softirq
||| / _--=> preempt-depth
|||| /
||||| delay
cmd pid ||||| time | caller
\ / ||||| \ | /
swapper-0 1d.s3 0us+: _spin_lock_irqsave+0x2a/0xb7 (e1000_update_stats+0x47/0x64c [e1000])
swapper-0 1d.s3 100us : _spin_unlock_irqrestore+0x32/0x5f (e1000_update_stats+0x641/0x64c [e1000])
swapper-0 1d.s3 100us : trace_hardirqs_on_caller+0x75/0x89 (_spin_unlock_irqrestore+0x32/0x5f)vim:ft=help
=======
And this is a trace with irqsoff_fn_trace_ctrl == 1
=======
preemption latency trace v1.1.5 on 2.6.24-rc7
--------------------------------------------------------------------
latency: 102 us, #12/12, CPU#1 | (M:rt VP:0, KP:0, SP:0 HP:0 #P:2)
-----------------
| task: swapper-0 (uid:0 nice:0 policy:0 rt_prio:0)
----------------- => started at: _spin_lock_irqsave+0x2a/0xb7
=> ended at: _spin_unlock_irqrestore+0x32/0x5f
_------=> CPU#
/ _-----=> irqs-off
| / _----=> need-resched
|| / _---=> hardirq/softirq
||| / _--=> preempt-depth
|||| /
||||| delay
cmd pid ||||| time | caller
\ / ||||| \ | /
swapper-0 1dNs3 0us+: _spin_lock_irqsave+0x2a/0xb7 (e1000_update_stats+0x47/0x64c [e1000])
swapper-0 1dNs3 46us : e1000_read_phy_reg+0x16/0x225 [e1000] (e1000_update_stats+0x5e2/0x64c [e1000])
swapper-0 1dNs3 46us : e1000_swfw_sync_acquire+0x10/0x99 [e1000] (e1000_read_phy_reg+0x49/0x225 [e1000])
swapper-0 1dNs3 46us : e1000_get_hw_eeprom_semaphore+0x12/0xa6 [e1000] (e1000_swfw_sync_acquire+0x36/0x99 [e1000])
swapper-0 1dNs3 47us : __const_udelay+0x9/0x47 (e1000_read_phy_reg+0x116/0x225 [e1000])
swapper-0 1dNs3 47us+: __delay+0x9/0x50 (__const_udelay+0x45/0x47)
swapper-0 1dNs3 97us : preempt_schedule+0xc/0x84 (__delay+0x4e/0x50)
swapper-0 1dNs3 98us : e1000_swfw_sync_release+0xc/0x55 [e1000] (e1000_read_phy_reg+0x211/0x225 [e1000])
swapper-0 1dNs3 99us+: e1000_put_hw_eeprom_semaphore+0x9/0x35 [e1000] (e1000_swfw_sync_release+0x50/0x55 [e1000])
swapper-0 1dNs3 101us : _spin_unlock_irqrestore+0xe/0x5f (e1000_update_stats+0x641/0x64c [e1000])
swapper-0 1dNs3 102us : _spin_unlock_irqrestore+0x32/0x5f (e1000_update_stats+0x641/0x64c [e1000])
swapper-0 1dNs3 102us : trace_hardirqs_on_caller+0x75/0x89 (_spin_unlock_irqrestore+0x32/0x5f)vim:ft=help
=======
--- arch/x86/kernel/process_64.c | 3 arch/x86/lib/thunk_64.S | 18 + include/asm-x86/irqflags_32.h | 4 include/asm-x86/irqflags_64.h | 4 include/linux/irqflags.h | 37 ++ include/linux/mcount.h | 31 ++ kernel/fork.c | 2 kernel/lockdep.c | 25 + lib/tracing/Kconfig | 17 + lib/tracing/Makefile | 1 lib/tracing/trace_irqsoff.c | 529 ++++++++++++++++++++++++++++++++++++++++++ lib/tracing/tracer.c | 43 +++ lib/tracing/tracer.h | 1 13 files changed, 694 insertions(+), 21 deletions(-)
arch/x86/kernel/process_64.c +3 -0
@@ -233,7 +233,10 @@ void cpu_idle (void)*/ local_irq_disable ();enter_idle (); +/* Don't trace irqs off for idle */ +stop_critical_timings ();idle (); +start_critical_timings ();/* In many cases the interrupt that ended idle has already called exit_idle. But some idle loops can be woken up without interrupt. */
arch/x86/lib/thunk_64.S +16 -2
@@ -47,8 +47,22 @@ thunk __up_wakeup,__up #ifdef CONFIG_TRACE_IRQFLAGS - thunk trace_hardirqs_on_thunk,trace_hardirqs_on - thunk trace_hardirqs_off_thunk,trace_hardirqs_off + /* put return address in rdi (arg1) */ + .macro thunk_ra name,func + .globl \name +\name: + CFI_STARTPROC + SAVE_ARGS + /* SAVE_ARGS pushs 9 elements */ + /* the next element would be the rip */ + movq 9*8(%rsp), %rdi + call \func + jmp restore + CFI_ENDPROC + .endm + + thunk_ra trace_hardirqs_on_thunk,trace_hardirqs_on_caller + thunk_ra trace_hardirqs_off_thunk,trace_hardirqs_off_caller #endif #ifdef CONFIG_DEBUG_LOCK_ALLOC
include/asm-x86/irqflags_32.h +2 -2
@@ -139,9 +139,9 @@ static inline int raw_irqs_disabled(voidstatic inline void trace_hardirqs_fixup_flags (unsigned long flags) {if (raw_irqs_disabled_flags (flags)) -trace_hardirqs_off (); +__trace_hardirqs_off ();else -trace_hardirqs_on (); +__trace_hardirqs_on (); }static inline void trace_hardirqs_fixup (void )
include/asm-x86/irqflags_64.h +2 -2
@@ -120,9 +120,9 @@ static inline int raw_irqs_disabled(voidstatic inline void trace_hardirqs_fixup_flags (unsigned long flags) {if (raw_irqs_disabled_flags (flags)) -trace_hardirqs_off (); +__trace_hardirqs_off ();else -trace_hardirqs_on (); +__trace_hardirqs_on (); }static inline void trace_hardirqs_fixup (void )
include/linux/irqflags.h +29 -8
@@ -12,10 +12,21 @@#define _LINUX_TRACE_IRQFLAGS_H#ifdef CONFIG_TRACE_IRQFLAGS -extern void trace_hardirqs_on (void ); -extern void trace_hardirqs_off (void ); +# include <linux/mcount.h> +extern void trace_hardirqs_on_caller (unsigned long ip); +extern void trace_hardirqs_off_caller (unsigned long ip);extern void trace_softirqs_on (unsigned long ip);extern void trace_softirqs_off (unsigned long ip); +extern void trace_hardirqs_on (void ); +extern void trace_hardirqs_off (void ); + static inline void notrace __trace_hardirqs_on(void) + { +trace_hardirqs_on_caller (CALLER_ADDR0 ); + } + static inline void notrace __trace_hardirqs_off(void) + { +trace_hardirqs_off_caller (CALLER_ADDR0 ); + }# define trace_hardirq_context (p) ((p)->hardirq_context)# define trace_softirq_context (p) ((p)->softirq_context)# define trace_hardirqs_enabled (p) ((p)->hardirqs_enabled)
@@ -28,6 +39,8 @@#else # define trace_hardirqs_on () do { } while (0)# define trace_hardirqs_off () do { } while (0) +# define __trace_hardirqs_on () do { } while (0) +# define __trace_hardirqs_off () do { } while (0)# define trace_softirqs_on (ip) do { } while (0)# define trace_softirqs_off (ip) do { } while (0)# define trace_hardirq_context (p) 0
@@ -41,24 +54,32 @@# define INIT_TRACE_IRQFLAGS #endif +#ifdef CONFIG_CRITICAL_IRQSOFF_TIMING +extern void stop_critical_timings (void ); +extern void start_critical_timings (void ); +#else +# define stop_critical_timings () do { } while (0) +# define start_critical_timings () do { } while (0) +#endif +#ifdef CONFIG_TRACE_IRQFLAGS_SUPPORT #include <asm/irqflags.h> #define local_irq_enable () \ - do { trace_hardirqs_on(); raw_local_irq_enable(); } while (0) + do { __trace_hardirqs_on(); raw_local_irq_enable(); } while (0)#define local_irq_disable () \ - do { raw_local_irq_disable(); trace_hardirqs_off(); } while (0) + do { raw_local_irq_disable(); __trace_hardirqs_off(); } while (0)#define local_irq_save (flags) \ - do { raw_local_irq_save(flags); trace_hardirqs_off(); } while (0) + do { raw_local_irq_save(flags); __trace_hardirqs_off(); } while (0)#define local_irq_restore (flags) \ do { \ if (raw_irqs_disabled_flags(flags)) { \ raw_local_irq_restore(flags); \ - trace_hardirqs_off(); \ + __trace_hardirqs_off(); \ } else { \ - trace_hardirqs_on(); \ + __trace_hardirqs_on(); \ raw_local_irq_restore(flags); \ } \ } while (0)
@@ -76,7 +97,7 @@#ifdef CONFIG_TRACE_IRQFLAGS_SUPPORT #define safe_halt () \ do { \ - trace_hardirqs_on(); \ + __trace_hardirqs_on(); \ raw_safe_halt(); \ } while (0)
include/linux/mcount.h +27 -4
@@ -6,10 +6,6 @@ extern int mcount_enabled;#include <linux/linkage.h> -#define CALLER_ADDR0 ((unsigned long)__builtin_return_address(0)) -#define CALLER_ADDR1 ((unsigned long)__builtin_return_address(1)) -#define CALLER_ADDR2 ((unsigned long)__builtin_return_address(2)) -typedef void (*mcount_func_t )(unsigned long ip,unsigned long parent_ip);struct mcount_ops {
@@ -35,4 +31,31 @@ extern void mcount(void);# define unregister_mcount_function (ops) do { } while (0)# define clear_mcount_function (ops) do { } while (0)#endif /* CONFIG_MCOUNT */ + + +#ifdef CONFIG_FRAME_POINTER +/* TODO: need to fix this for ARM */ +# define CALLER_ADDR0 ((unsigned long)__builtin_return_address(0)) +# define CALLER_ADDR1 ((unsigned long)__builtin_return_address(1)) +# define CALLER_ADDR2 ((unsigned long)__builtin_return_address(2)) +# define CALLER_ADDR3 ((unsigned long)__builtin_return_address(3)) +# define CALLER_ADDR4 ((unsigned long)__builtin_return_address(4)) +# define CALLER_ADDR5 ((unsigned long)__builtin_return_address(5)) +#else +# define CALLER_ADDR0 ((unsigned long)__builtin_return_address(0)) +# define CALLER_ADDR1 0UL +# define CALLER_ADDR2 0UL +# define CALLER_ADDR3 0UL +# define CALLER_ADDR4 0UL +# define CALLER_ADDR5 0UL +#endif + +#ifdef CONFIG_CRITICAL_IRQSOFF_TIMING + extern void notrace time_hardirqs_on(unsigned long a0, unsigned long a1); + extern void notrace time_hardirqs_off(unsigned long a0, unsigned long a1); +#else +# define time_hardirqs_on (a0, a1) do { } while (0) +# define time_hardirqs_off (a0, a1) do { } while (0) +#endif +#endif /* _LINUX_MCOUNT_H */
kernel/fork.c +1 -1
@@ -1010,7 +1010,7 @@ static struct task_struct *copy_process(rt_mutex_init_task (p); -#ifdef CONFIG_TRACE_IRQFLAGS +#if defined(CONFIG_TRACE_IRQFLAGS ) && defined(CONFIG_LOCKDEP )DEBUG_LOCKS_WARN_ON (!p->hardirqs_enabled);DEBUG_LOCKS_WARN_ON (!p->softirqs_enabled);#endif
kernel/lockdep.c +23 -2
@@ -39,6 +39,7 @@#include <linux/irqflags.h> #include <linux/utsname.h> #include <linux/hash.h> +#include <linux/mcount.h> #include <asm/sections.h>
@@ -2009,7 +2010,7 @@ void early_boot_irqs_on(void)/* * Hardirqs will be enabled: */ -void trace_hardirqs_on (void ) +void notrace trace_hardirqs_on_caller(unsigned long a0) {struct task_struct *curr = current;unsigned long ip;
@@ -2050,14 +2051,27 @@ void trace_hardirqs_on(void) curr->hardirq_enable_ip = ip; curr->hardirq_enable_event = ++curr->irq_events;debug_atomic_inc (&hardirqs_on_events); + +#ifdef CONFIG_CRITICAL_IRQSOFF_TIMING +time_hardirqs_on (CALLER_ADDR0 , a0); +#endif } +EXPORT_SYMBOL (trace_hardirqs_on_caller); +void notrace trace_hardirqs_on(void) { +trace_hardirqs_on_caller (CALLER_ADDR0 ); +}EXPORT_SYMBOL (trace_hardirqs_on); +void notrace trace_hardirqs_off(void) { +trace_hardirqs_off_caller (CALLER_ADDR0 ); +} +EXPORT_SYMBOL (trace_hardirqs_off); +/* * Hardirqs were disabled: */ -void trace_hardirqs_off (void ) +void notrace trace_hardirqs_off_caller(unsigned long a0) {struct task_struct *curr = current;
@@ -2075,10 +2089,17 @@ void trace_hardirqs_off(void) curr->hardirq_disable_ip = _RET_IP_; curr->hardirq_disable_event = ++curr->irq_events;debug_atomic_inc (&hardirqs_off_events); +#ifdef CONFIG_CRITICAL_IRQSOFF_TIMING +time_hardirqs_off (CALLER_ADDR0 , a0); +#endif }else debug_atomic_inc (&redundant_hardirqs_off); } +void notrace trace_hardirqs_off(void) { +trace_hardirqs_off_caller (CALLER_ADDR0 ); +} +EXPORT_SYMBOL (trace_hardirqs_off);/*
lib/tracing/Kconfig +17 -0
@@ -26,6 +26,23 @@ config FUNCTION_TRACER that the debugging mechanism using this facility will hook by providing a set of inline routines. +config CRITICAL_IRQSOFF_TIMING + bool "Interrupts-off critical section latency timing" + default n + depends on TRACE_IRQFLAGS_SUPPORT + depends on GENERIC_TIME + select TRACE_IRQFLAGS + select TRACING + help + This option measures the time spent in irqs-off critical + sections, with microsecond accuracy. + + The default measurement method is a maximum search, which is + disabled by default and can be runtime (re-)started + via: + + echo 0 > /debug/tracing/preempt_max_latency + config WAKEUP_TRACER bool "Trace wakeup latencies" depends on DEBUG_KERNEL
lib/tracing/Makefile +1 -0
@@ -3,6 +3,7 @@ obj-$(CONFIG_MCOUNT) += libmcount.o obj-$(CONFIG_TRACING) += tracer.o obj-$(CONFIG_CONTEXT_SWITCH_TRACER) += trace_sched_switch.o obj-$(CONFIG_FUNCTION_TRACER) += trace_function.o +obj-$(CONFIG_CRITICAL_IRQSOFF_TIMING) += trace_irqsoff.o obj-$(CONFIG_WAKEUP_TRACER) += trace_wakeup.o libmcount-y := mcount.o
lib/tracing/trace_irqsoff.c new file +529 -0
529 lines not on this page · raw message
lib/tracing/tracer.c +43 -0
49 lines not on this page · raw message
lib/tracing/tracer.h +1 -0
@@ -98,6 +98,7 @@ extern atomic_t trace_record_cmdline_disextern struct file_operations tracing_fops;extern struct file_operations tracing_lt_fops;extern struct file_operations tracing_ctrl_fops; +extern struct file_operations tracing_usec_fops; static inline notrace cycle_t now(void) {
Steven Rostedt
reviewerRFC PATCH 23/23 trace preempt off critical timings
In reply to Steven RostedtAdd preempt off timings. A lot of this code is taken from the RT patch latency trace that was written by Ingo Molnar.
Now instead of just tracing irqs off, preemption off can be selected to be recorded.
When this is selected, it shares the same files as irqs off timings. One can either trace preemption off, irqs off, or one or the other off. But once it is configured in the kernel for what to trace, it can't be changed.
--- arch/x86/kernel/process_32.c | 3 +++ include/linux/irqflags.h | 3 ++- include/linux/mcount.h | 8 ++++++++ include/linux/preempt.h | 2 +- kernel/sched.c | 24 +++++++++++++++++++++++- lib/tracing/Kconfig | 24 ++++++++++++++++++++++++ lib/tracing/Makefile | 1 + lib/tracing/trace_irqsoff.c | 40 ++++++++++++++++++++++++++++++---------- 8 files changed, 92 insertions(+), 13 deletions(-)
lib/tracing/Kconfig +24 -0
@@ -43,6 +43,30 @@ config CRITICAL_IRQSOFF_TIMING echo 0 > /debug/tracing/preempt_max_latency + (Note that kernel size and overhead increases with this option + enabled. This option and the preempt-off timing option can be + used together or separately.) + +config CRITICAL_PREEMPT_TIMING + bool "Preemption-off critical section latency timing" + default n + depends on GENERIC_TIME + depends on PREEMPT + select TRACING + help + This option measures the time spent in preemption off critical + sections, with microsecond accuracy. + + The default measurement method is a maximum search, which is + disabled by default and can be runtime (re-)started + via: + + echo 0 > /debug/tracing/preempt_max_latency + + (Note that kernel size and overhead increases with this option + enabled. This option and the irqs-off timing option can be + used together or separately.) + config WAKEUP_TRACER bool "Trace wakeup latencies" depends on DEBUG_KERNEL
lib/tracing/Makefile +1 -0
@@ -4,6 +4,7 @@ obj-$(CONFIG_TRACING) += tracer.o obj-$(CONFIG_CONTEXT_SWITCH_TRACER) += trace_sched_switch.o obj-$(CONFIG_FUNCTION_TRACER) += trace_function.o obj-$(CONFIG_CRITICAL_IRQSOFF_TIMING) += trace_irqsoff.o +obj-$(CONFIG_CRITICAL_PREEMPT_TIMING) += trace_irqsoff.o obj-$(CONFIG_WAKEUP_TRACER) += trace_wakeup.o libmcount-y := mcount.o
lib/tracing/trace_irqsoff.c +30 -10
@@ -36,6 +36,12 @@ static int __init set_nr_entries(char *s }__setup ("trace_irq_entries=" , set_nr_entries); +#ifdef CONFIG_CRITICAL_PREEMPT_TIMING +# define preempt_trace () (preempt_count()) +#else +# define preempt_trace () (0) +#endif +/* * max trace is switched with this buffer. */
@@ -206,7 +212,7 @@ start_critical_timing(unsigned long ip, data->critical_sequence = max_sequence; data->preempt_timestamp =now (); - data->critical_start = parent_ip; + data->critical_start = parent_ip ? : ip;tracing_reset (data);local_save_flags (flags);
@@ -230,18 +236,19 @@ stop_critical_timing(unsigned long ip, uatomic_inc (&data->disabled);local_save_flags (flags);tracing_function_trace (tr, data, ip, parent_ip, flags); -check_critical_timing (tr, data, parent_ip, cpu); +check_critical_timing (tr, data, parent_ip ? : ip, cpu); data->critical_start =0 ;atomic_dec (&data->disabled); } +/* start and stop critical timings used to for stoppage (in idle) */ void notrace start_critical_timings(void) {unsigned long flags;local_save_flags (flags); -if (irqs_disabled_flags (flags)) +if (preempt_trace () ||irqs_disabled_flags (flags))start_critical_timing (CALLER_ADDR0 ,0 ); }
@@ -251,10 +258,11 @@ void notrace stop_critical_timings(void)local_save_flags (flags); -if (irqs_disabled_flags (flags)) +if (preempt_trace () ||irqs_disabled_flags (flags))stop_critical_timing (CALLER_ADDR0 ,0 ); } +#ifdef CONFIG_CRITICAL_IRQSOFF_TIMING #ifdef CONFIG_LOCKDEP void notrace time_hardirqs_on(unsigned long a0, unsigned long a1) {
@@ -262,7 +270,7 @@ void notrace time_hardirqs_on(unsigned llocal_save_flags (flags); -if (irqs_disabled_flags (flags)) +if (!preempt_trace () &&irqs_disabled_flags (flags))stop_critical_timing (a0, a1); }
@@ -272,7 +280,7 @@ void notrace time_hardirqs_off(unsignedlocal_save_flags (flags); -if (irqs_disabled_flags (flags)) +if (!preempt_trace () &&irqs_disabled_flags (flags))start_critical_timing (a0, a1); }
@@ -311,7 +319,7 @@ void notrace trace_hardirqs_on(void)local_save_flags (flags); -if (irqs_disabled_flags (flags)) +if (!preempt_trace () &&irqs_disabled_flags (flags))stop_critical_timing (CALLER_ADDR0 ,0 ); }EXPORT_SYMBOL (trace_hardirqs_on);
@@ -322,7 +330,7 @@ void notrace trace_hardirqs_off(void)local_save_flags (flags); -if (irqs_disabled_flags (flags)) +if (!preempt_trace () &&irqs_disabled_flags (flags))start_critical_timing (CALLER_ADDR0 ,0 ); }EXPORT_SYMBOL (trace_hardirqs_off);
@@ -333,7 +341,7 @@ void notrace trace_hardirqs_on_caller(unlocal_save_flags (flags); -if (irqs_disabled_flags (flags)) +if (!preempt_trace () &&irqs_disabled_flags (flags))stop_critical_timing (CALLER_ADDR0 , caller_addr); }EXPORT_SYMBOL (trace_hardirqs_on_caller);
@@ -344,13 +352,25 @@ void notrace trace_hardirqs_off_caller(ulocal_save_flags (flags); -if (irqs_disabled_flags (flags)) +if (!preempt_trace () &&irqs_disabled_flags (flags))start_critical_timing (CALLER_ADDR0 , caller_addr); }EXPORT_SYMBOL (trace_hardirqs_off_caller);#endif /* CONFIG_LOCKDEP */ +#endif /* CONFIG_CRITICAL_IRQSOFF_TIMING */ +#ifdef CONFIG_CRITICAL_PREEMPT_TIMING +void notrace trace_preempt_on(unsigned long a0, unsigned long a1) +{ +stop_critical_timing (a0, a1); +} + +void notrace trace_preempt_off(unsigned long a0, unsigned long a1) +{ +start_critical_timing (a0, a1); +} +#endif /* CONFIG_CRITICAL_PREEMPT_TIMING */ #ifdef CONFIG_MCOUNT static void notrace irqsoff_trace_call(unsigned long ip,
include/linux/preempt.h +1 -1
@@ -10,7 +10,7 @@#include <linux/linkage.h> #include <linux/list.h> -#ifdef CONFIG_DEBUG_PREEMPT +#if defined(CONFIG_DEBUG_PREEMPT ) || defined(CONFIG_CRITICAL_PREEMPT_TIMING ) extern void fastcall add_preempt_count(int val); extern void fastcall sub_preempt_count(int val);#else
kernel/sched.c +23 -1
@@ -63,6 +63,7 @@#include <linux/reciprocal_div.h> #include <linux/unistd.h> #include <linux/pagemap.h> +#include <linux/mcount.h> #include <asm/tlb.h> #include <asm/irq_regs.h>
@@ -3505,26 +3506,44 @@ void scheduler_tick(void)#endif } -#if defined(CONFIG_PREEMPT ) && defined(CONFIG_DEBUG_PREEMPT ) +#if defined(CONFIG_PREEMPT ) && (defined(CONFIG_DEBUG_PREEMPT ) || \ + defined(CONFIG_CRITICAL_PREEMPT_TIMING )) + +static inline unsigned long get_parent_ip (unsigned long addr) +{ +if (in_lock_functions (addr)) { + addr =CALLER_ADDR2 ; +if (in_lock_functions (addr)) + addr =CALLER_ADDR3 ; + } +return addr; +} void fastcall add_preempt_count(int val) { +#ifdef CONFIG_DEBUG_PREEMPT /* * Underflow? */ if (DEBUG_LOCKS_WARN_ON ((preempt_count () <0 )))return ; +#endif preempt_count () += val; +#ifdef CONFIG_DEBUG_PREEMPT /* * Spinlock count overflowing soon? */ DEBUG_LOCKS_WARN_ON ((preempt_count () &PREEMPT_MASK ) >=PREEMPT_MASK -10 ); +#endif +if (preempt_count () == val) +trace_preempt_off (CALLER_ADDR0 ,get_parent_ip (CALLER_ADDR1 )); }EXPORT_SYMBOL (add_preempt_count); void fastcall sub_preempt_count(int val) { +#ifdef CONFIG_DEBUG_PREEMPT /* * Underflow? */
@@ -3536,7 +3555,10 @@ void fastcall sub_preempt_count(int val)if (DEBUG_LOCKS_WARN_ON ((val <PREEMPT_MASK ) && !(preempt_count () &PREEMPT_MASK )))return ; +#endif +if (preempt_count () == val) +trace_preempt_on (CALLER_ADDR0 ,get_parent_ip (CALLER_ADDR1 ));preempt_count () -= val; }EXPORT_SYMBOL (sub_preempt_count);
arch/x86/kernel/process_32.c +3 -0
@@ -195,7 +195,10 @@ void cpu_idle(void)play_dead ();__get_cpu_var (irq_stat).idle_timestamp = jiffies; +/* Don't trace irqs off for idle */ +stop_critical_timings ();idle (); +start_critical_timings (); }tick_nohz_restart_sched_tick ();preempt_enable_no_resched ();
include/linux/mcount.h +8 -0
@@ -58,4 +58,12 @@ extern void mcount(void);# define time_hardirqs_off (a0, a1) do { } while (0)#endif +#ifdef CONFIG_CRITICAL_PREEMPT_TIMING + extern void notrace trace_preempt_on(unsigned long a0, unsigned long a1); + extern void notrace trace_preempt_off(unsigned long a0, unsigned long a1); +#else +# define trace_preempt_on (a0, a1) do { } while (0) +# define trace_preempt_off (a0, a1) do { } while (0) +#endif +#endif /* _LINUX_MCOUNT_H */
include/linux/irqflags.h +2 -1
@@ -54,7 +54,8 @@# define INIT_TRACE_IRQFLAGS #endif -#ifdef CONFIG_CRITICAL_IRQSOFF_TIMING +#if defined(CONFIG_CRITICAL_IRQSOFF_TIMING ) || \ + defined(CONFIG_CRITICAL_PREEMPT_TIMING )extern void stop_critical_timings (void );extern void start_critical_timings (void );#else