The code in stack tracer should not be executed within an NMI as it grabs
spinlocks and stack tracing an NMI gives the possibility of causing a
deadlock. Although this is safe on x86_64, because it does not perform stack
traces when the task struct stack is not in use (interrupts and NMIs), it
may be an issue for NMIs on i386 and other archs that use the same stack as
the NMI.
Signed-off-by: Steven Rostedt <[email protected]>
The stack tracer was triggering the WARN_ON() in module.c:
static void module_assert_mutex_or_preempt(void)
{
#ifdef CONFIG_LOCKDEP
if (unlikely(!debug_locks))
return;
WARN_ON(!rcu_read_lock_sched_held() &&
!lockdep_is_held(&module_mutex));
#endif
}
The reason is that the stack tracer traces all function calls, and some of
those calls happen while exiting or entering user space and idle. Some of
these functions are called after RCU had already stopped watching, as RCU
does not watch userspace or idle CPUs.
If a max stack is hit, then the save_stack_trace() is called, which will
check module addresses and call module_assert_mutex_or_preempt(), and then
trigger the warning. Sad part is, the warning itself will also do a stack
trace and tigger the same warning. That probably should be fixed.
The warning was added by 0be964be0d "module: Sanitize RCU usage and
locking" but this bug has probably been around longer. But it's unlikely to
cause much harm, but the new warning causes the system to lock up.
Cc: [email protected] # 4.2+
Cc: Peter Zijlstra <[email protected]>
Cc:"Paul E. McKenney" <[email protected]>
Signed-off-by: Steven Rostedt <[email protected]>
While looking at use cases of the wake queues in order to add support
for simple wait queues, I noticed that there was only a single user of
wake_up_interruptible_nr(), and that use was doing a single task wake
up. Have that user use the proper wake_up_interruptible() instead, and
perhaps we can even remove the function wake_up_interruptible_nr().
Signed-off-by: Steven Rostedt <[email protected]>
Signed-off-by: Mauro Carvalho Chehab <[email protected]>
The commit a4543a2fa9 "ring-buffer: Get timestamp after event is
allocated" is needed for some future work. But after adding it, there is a
race somewhere that causes the saved timestamp to have a slight shift, and
get ahead of the actual timestamp and make it look like time goes backwards.
I'm still looking into why this happens, but in the mean time, this is
holding up other work to get in. I'm reverting the change for now (which
makes the problem go away), and will add it back after I know what is wrong
and fix it.
Signed-off-by: Steven Rostedt <[email protected]>
It was reported that "%-8s" does not parse well when used in the printk
format. The '-' is what is throwing it off. Allow that to be included.
Reporter note:
Example before:
transhuge-stres-10730 [004] 5897.713989: mm_compaction_finished: node=0
zone=>-<8s order=-2119871790 ret=
Example after:
transhuge-stres-4235 [000] 453.149280: mm_compaction_finished: node=0
zone=ffffffff81815d7a order=9 ret=
(I will send patches to fix the string handling in the tracepoints so
it's on par with in-kernel printing via trace_pipe:)
transhuge-stres-10921 [007] ...1 6307.140205: mm_compaction_finished: node=0
zone=Normal order=9 ret=partial
Reported-by: Vlastimil Babka <[email protected]>
Signed-off-by: Steven Rostedt <[email protected]>
Tested-by: Vlastimil Babka <[email protected]>
Cc: Namhyung Kim <[email protected]>
Link: http://lkml.kernel.org/r/[email protected]
Signed-off-by: Arnaldo Carvalho de Melo <[email protected]>
Commit 4104d326b6 ("ftrace: Remove global function list and call function
directly") simplified the ftrace code by removing the global_ops list with a
new design. But this cleanup also broke the filtering of PIDs that are added
to the set_ftrace_pid file.
Add back the proper hooks to have pid filtering working once again.
Cc: [email protected] # 3.16+
Reported-by: Matt Fleming <[email protected]>
Reported-by: Richard Weinberger <[email protected]>
Tested-by: Matt Fleming <[email protected]>
Signed-off-by: Steven Rostedt <[email protected]>
Jungseok Lee noticed the following:
Currently, row's width of 7-digit duration numbers not aligned with
other cases like the following example.
3) $ 3999884 us | }
3) | finish_task_switch() {
3) 0.365 us | _raw_spin_unlock_irq();
3) 3.333 us | }
3) $ 3999976 us | }
3) $ 3999979 us | } /* schedule */
As adding a single white space in case of 7-digit numbers, the format
could be unified easily as follows.
3) $ 2237472 us | }
3) | finish_task_switch() {
3) 0.364 us | _raw_spin_unlock_irq();
3) 3.125 us | }
3) $ 2237556 us | }
3) $ 2237559 us | } /* schedule */
Instead of making a special case for 7-digit numbers, the logic
of the len and the space loop is slightly modified to make the
two cases have the same format.
Link: http://lkml.kernel.org/r/[email protected]
Reported-by: Jungseok Lee <[email protected]>
Signed-off-by: Steven Rostedt <[email protected]>
Akashi Takahiro was porting the stack tracer to arm64 and found some
issues with it. One was that it repeats the top function, due to the
stack frame added by the mcount caller and added by itself. This
was added when fentry came in, and before fentry created its own stack
frame. But x86's fentry now creates its own stack frame, and there's
no need to insert the function again.
This also cleans up the code a bit, where it doesn't need to do something
special for fentry, and doesn't include insertion of a duplicate
entry for the called function being traced.
Link: http://lkml.kernel.org/r/[email protected]
Some-suggestions-by: Jungseok Lee <[email protected]>
Some-suggestions-by: Mark Rutland <[email protected]>
Reported-by: AKASHI Takahiro <[email protected]>
Signed-off-by: Steven Rostedt <[email protected]>
Functions in ring-buffer.c have gotten interleaved between different
use cases. Move the functions around to get like functions closer
together. This may or may not help gcc keep cache locality, but it
makes it a little easier to work with the code.
Signed-off-by: Steven Rostedt <[email protected]>
Now that events only add time extends after it is committed, in case
an event comes in before it can discard the allocated event, the time
extend needs to be stored within the event. If the event is bigger
than then size needed for the time extend, padding must be added.
The minimum padding size is 8 bytes. Thus if the event is 12 bytes
(size of time extend + 4), there will not be enough room to add both
the time extend and padding. Make sure all events are either 8 bytes
or 16 or more bytes.
Signed-off-by: Steven Rostedt <[email protected]>
Move the capturing of the timestamp to after an event is allocated.
If the event is not a commit (where it is an event that preempted
another event), then no timestamp is needed, because the delta of
nested events is always zero.
If the event starts on a new page, no delta needs to be calculated
as the full timestamp will be added to the page header, and the
event will have a delta of zero.
Now if the event requires a time extend (the delta does not fit
in the 27 bit delta slot in the header), then the event is discarded,
the length is extended to hold the TIME_EXTEND event that allows for
a 59 bit delta, and the commit is tried again.
If the event can't be discarded (another event came in after it),
then the TIME_EXTEND is added directly to the allocated event and
the rest of the event is given padding.
Signed-off-by: Steven Rostedt <[email protected]>
Requiring a extended time stamp is an uncommon occurrence, and it is
best to do it out of line when needed.
Add a noinline function that handles the extended timestamp and
have it called with an unlikely to completely move it out of the
fast path.
Signed-off-by: Steven Rostedt <[email protected]>
Add rb_event_info descriptor to pass event info to functions a bit
easier than using a bunch of parameters. This will also allow for
changing the code around a bit to find better fast paths.
Signed-off-by: Steven Rostedt <[email protected]>
He Kuang noticed that the trace event samples for arrays was broken:
"The output result of trace_foo_bar event in traceevent samples is
wrong. This problem can be reproduced as following:
(Build kernel with SAMPLE_TRACE_EVENTS=m)
$ insmod trace-events-sample.ko
$ echo 1 > /sys/kernel/debug/tracing/events/sample-trace/foo_bar/enable
$ cat /sys/kernel/debug/tracing/trace
event-sample-980 [000] .... 43.649559: foo_bar: foo hello 21 0x15
BIT1|BIT3|0x10 {0x1,0x6f6f6e53,0xff007970,0xffffffff} Snoopy
^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
The array length is not right, should be {0x1}.
(ffffffff,ffffffff)
event-sample-980 [000] .... 44.653827: foo_bar: foo hello 22 0x16
BIT2|BIT3|0x10
{0x1,0x2,0x646e6147,0x666c61,0xffffffff,0xffffffff,0x750aeffe,0x7}
^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
The array length is not right, should be {0x1,0x2}.
Gandalf (ffffffff,ffffffff)"
This was caused by an update to have __print_array()'s second parameter
be the count of items in the array and not the size of the array.
As there is already users of __print_array(), it can not change. But
the sample code can and we can also improve on the documentation about
__print_array() and __get_dynamic_array_len().
Link: http://lkml.kernel.org/r/[email protected]
Fixes: ac01ce1410 ("tracing: Make ftrace_print_array_seq compute buf_len")
Reported-by: He Kuang <[email protected]>
Signed-off-by: Steven Rostedt <[email protected]>
Fengguang Wu's tests triggered a bug in the branch tracer's start up
test when CONFIG_DEBUG_PREEMPT set. This was because that config
adds some debug logic in the per cpu field, which calls back into
the branch tracer.
The branch tracer has its own recursive checks, but uses a per cpu
variable to implement it. If retrieving the per cpu variable calls
back into the branch tracer, you can see how things will break.
Instead of using a per cpu variable, use the trace_recursion field
of the current task struct. Simply set a bit when entering the
branch tracing and clear it when leaving. If the bit is set on
entry, just don't do the tracing.
There's also the case with lockdep, as the local_irq_save() called
before the recursion can also trigger code that can call back into
the function. Changing that to a raw_local_irq_save() will protect
that as well.
This prevents the recursion and the inevitable crash that follows.
Link: http://lkml.kernel.org/r/[email protected]
Cc: [email protected] # 3.10+
Reported-by: Fengguang Wu <[email protected]>
Tested-by: Fengguang Wu <[email protected]>
Signed-off-by: Steven Rostedt <[email protected]>
When I enable early_printk on a kernel, I cut and paste the
console= input and add to earlyprintk parameter. But I notice
recently that ktest has not been detecting triple faults. The
way it detects it, is by seeing the kernel banner "Linux version
.." with a different kernel version pop up. Then I noticed that
early printk was no longer working on my console, which was why
ktest was not seeing it.
I bisected it down and it was added to 4.0 with this commit:
ea9e9d8029 ("Specify PCI based UART for earlyprintk")
because it converted the simple_strtoul() that converts the baud
number into a kstrtoul(). The problem with this is, I had as my
baud rate, 115200n8 (acceptable for console=ttyS0), but because
of the "n8", the kstrtoul() doesn't parse the baud rate and
returns an error, which sets the baud rate to the default 9600.
This explains the garbage on my screen.
Now, earlyprintk= kernel parameter does not say it accepts that
format. Thus, one answer would simply be me changing my kernel
parameters to remove the "n8" since it isn't parsed anyway. But
I wonder if other people run into this, and it seems strange
that the two consoles for serial accepts different input.
I could also extend this to have earlyprintk do something with
that "n8" or whatever it has and have it match the console
parsing (which, BTW, still uses simple_strtoul(), as I guess it
has to).
This patch just makes my old kernel parameter parsing work like
it use to.
Although, simple_strtoull() is considered obsolete, it is the
only standard string parsing function that parses a number that
is attached to text. Ironically, commit ea9e9d8029 also added
several calls to simple_strtoul()!
Signed-off-by: Steven Rostedt <[email protected]>
Cc: Alan Cox <[email protected]>
Cc: Andy Lutomirski <[email protected]>
Cc: Andy Shevchenko <[email protected]>
Cc: Borislav Petkov <[email protected]>
Cc: Brian Gerst <[email protected]>
Cc: David Cohen <[email protected]>
Cc: Denys Vlasenko <[email protected]>
Cc: Greg Kroah-Hartman <[email protected]>
Cc: H. Peter Anvin <[email protected]>
Cc: Linus Torvalds <[email protected]>
Cc: Peter Zijlstra <[email protected]>
Cc: Stuart R. Anderson <[email protected]>
Cc: Thomas Gleixner <[email protected]>
Link: http://lkml.kernel.org/r/[email protected]
[ Cleaned it up a bit. ]
Signed-off-by: Ingo Molnar <[email protected]>
The trace.h header when called without CONFIG_EVENT_TRACING enabled
(seldom done), will not compile because of a typo in the protocol
of trace_event_enum_update().
Cc: [email protected] # 4.1+
Signed-off-by: Steven Rostedt <[email protected]>
While debugging a WARN_ON() for filtering, I found that it is possible
for the filter string to be referenced after its end. With the filter:
# echo '>' > /sys/kernel/debug/events/ext4/ext4_truncate_exit/filter
The filter_parse() function can call infix_get_op() which calls
infix_advance() that updates the infix filter pointers for the cnt
and tail without checking if the filter is already at the end, which
will put the cnt to zero and the tail beyond the end. The loop then calls
infix_next() that has
ps->infix.cnt--;
return ps->infix.string[ps->infix.tail++];
The cnt will now be below zero, and the tail that is returned is
already passed the end of the filter string. So far the allocation
of the filter string usually has some buffer that is zeroed out, but
if the filter string is of the exact size of the allocated buffer
there's no guarantee that the charater after the nul terminating
character will be zero.
Luckily, only root can write to the filter.
Cc: [email protected] # 2.6.33+
Signed-off-by: Steven Rostedt <[email protected]>
When testing the fix for the trace filter, I could not come up with
a scenario where the operand count goes below zero, so I added a
WARN_ON_ONCE(cnt < 0) to the logic. But there is legitimate case
that it can happen (although the filter would be wrong).
# echo '>' > /sys/kernel/debug/events/ext4/ext4_truncate_exit/filter
That is, a single operation without any operands will hit the path
where the WARN_ON_ONCE() can trigger. Although this is harmless,
and the filter is reported as a error. But instead of spitting out
a warning to the kernel dmesg, just fail nicely and report it via
the proper channels.
Link: http://lkml.kernel.org/r/[email protected]
Reported-by: Vince Weaver <[email protected]>
Reported-by: Sasha Levin <[email protected]>
Cc: [email protected] # 2.6.33+
Signed-off-by: Steven Rostedt <[email protected]>
When the following filter is used it causes a warning to trigger:
# cd /sys/kernel/debug/tracing
# echo "((dev==1)blocks==2)" > events/ext4/ext4_truncate_exit/filter
-bash: echo: write error: Invalid argument
# cat events/ext4/ext4_truncate_exit/filter
((dev==1)blocks==2)
^
parse_error: No error
------------[ cut here ]------------
WARNING: CPU: 2 PID: 1223 at kernel/trace/trace_events_filter.c:1640 replace_preds+0x3c5/0x990()
Modules linked in: bnep lockd grace bluetooth ...
CPU: 3 PID: 1223 Comm: bash Tainted: G W 4.1.0-rc3-test+ #450
Hardware name: Hewlett-Packard HP Compaq Pro 6300 SFF/339A, BIOS K01 v02.05 05/07/2012
0000000000000668 ffff8800c106bc98 ffffffff816ed4f9 ffff88011ead0cf0
0000000000000000 ffff8800c106bcd8 ffffffff8107fb07 ffffffff8136b46c
ffff8800c7d81d48 ffff8800d4c2bc00 ffff8800d4d4f920 00000000ffffffea
Call Trace:
[<ffffffff816ed4f9>] dump_stack+0x4c/0x6e
[<ffffffff8107fb07>] warn_slowpath_common+0x97/0xe0
[<ffffffff8136b46c>] ? _kstrtoull+0x2c/0x80
[<ffffffff8107fb6a>] warn_slowpath_null+0x1a/0x20
[<ffffffff81159065>] replace_preds+0x3c5/0x990
[<ffffffff811596b2>] create_filter+0x82/0xb0
[<ffffffff81159944>] apply_event_filter+0xd4/0x180
[<ffffffff81152bbf>] event_filter_write+0x8f/0x120
[<ffffffff811db2a8>] __vfs_write+0x28/0xe0
[<ffffffff811dda43>] ? __sb_start_write+0x53/0xf0
[<ffffffff812e51e0>] ? security_file_permission+0x30/0xc0
[<ffffffff811dc408>] vfs_write+0xb8/0x1b0
[<ffffffff811dc72f>] SyS_write+0x4f/0xb0
[<ffffffff816f5217>] system_call_fastpath+0x12/0x6a
---[ end trace e11028bd95818dcd ]---
Worse yet, reading the error message (the filter again) it says that
there was no error, when there clearly was. The issue is that the
code that checks the input does not check for balanced ops. That is,
having an op between a closed parenthesis and the next token.
This would only cause a warning, and fail out before doing any real
harm, but it should still not caues a warning, and the error reported
should work:
# cd /sys/kernel/debug/tracing
# echo "((dev==1)blocks==2)" > events/ext4/ext4_truncate_exit/filter
-bash: echo: write error: Invalid argument
# cat events/ext4/ext4_truncate_exit/filter
((dev==1)blocks==2)
^
parse_error: Meaningless filter expression
And give no kernel warning.
Link: http://lkml.kernel.org/r/[email protected]
Cc: Peter Zijlstra <[email protected]>
Cc: Ingo Molnar <[email protected]>
Cc: Arnaldo Carvalho de Melo <[email protected]>
Cc: [email protected] # 2.6.31+
Reported-by: Vince Weaver <[email protected]>
Tested-by: Vince Weaver <[email protected]>
Signed-off-by: Steven Rostedt <[email protected]>
blktrace.c is currently maintained by Jens Axboe as it is used for
debugging the block layer. That file should be added to the MAINTAINERS
file under BLOCK LAYER, such that people will know to Cc the BLOCK
LAYER maintainer when modifying that file.
Currently:
$ scripts/get_maintainer.pl -f kernel/trace/blktrace.c
Steven Rostedt <[email protected]> (maintainer:TRACING)
Ingo Molnar <[email protected]> (maintainer:TRACING)
[email protected] (open list)
After the patch:
$ scripts/get_maintainer.pl -f kernel/trace/blktrace.c
Jens Axboe <[email protected]> (maintainer:BLOCK LAYER)
Steven Rostedt <[email protected]> (maintainer:TRACING)
Ingo Molnar <[email protected]> (maintainer:TRACING)
[email protected] (open list)
Signed-off-by: Steven Rostedt <[email protected]>
Signed-off-by: Jens Axboe <[email protected]>
The tracing_off_permanent() call is a way to disable all ring_buffers.
Nothing uses it and nothing should use it, as tracing_off() and
friends are better, as they disable the ring buffers related to
tracing. The tracing_off_permanent() even disabled non tracing
ring buffers. This is a bit drastic, and was added to handle NMIs
doing outputs that could corrupt the ring buffer when only tracing
used them. It is now obsolete and adds a little overhead, it should
be removed.
Signed-off-by: Steven Rostedt <[email protected]>
Currently, if an NMI does a dump of a ring buffer, it disables
all ring buffers from ever doing any writes again. This is because
it wont take the locks for the cpu_buffer and this can cause
corruption if it preempted a read, or a read happens on another
CPU for the current cpu buffer. This is a bit overkill.
First, it should at least try to take the lock, and if it fails
then disable it. Also, there's no need to disable all ring
buffers, even those that are unrelated to what is being read.
Only disable the per cpu ring buffer that is being read if
it can not get the lock for it.
Signed-off-by: Steven Rostedt <[email protected]>
The ring_buffer_write() function isn't protected by the trace recursive
writes. Luckily, this function is not used as much and is unlikely
to ever recurse. But it should still have the protection, because
even a call to ring_buffer_lock_reserve() could cause ring buffer
corruption if called when ring_buffer_write() is being used.
Signed-off-by: Steven Rostedt <[email protected]>
Currently the trace_recursive checks are only done if CONFIG_TRACING
is enabled. That was because there use to be a dependency with tracing
for the recursive checks (it used the task_struct trace recursive
variable). But now it uses its own variable and there is no dependency.
Signed-off-by: Steven Rostedt <[email protected]>
Instead of using a global per_cpu variable to perform the recursive
checks into the ring buffer, use the already existing per_cpu descriptor
that is part of the ring buffer itself.
Not only does this simplify the code, it also allows for one ring buffer
to be used within the guts of the use of another ring buffer. For example
trace_printk() can now be used within the ring buffer to record changes
done by an instance into the main ring buffer. The recursion checks
will prevent the trace_printk() itself from causing recursive issues
with the main ring buffer (it is just ignored), but the recursive
checks wont prevent the trace_printk() from recording other ring buffers.
Signed-off-by: Steven Rostedt <[email protected]>
The name "ftrace" really refers to the function hook infrastructure. It
is not about the trace_events. The function ftrace_get_offsets_##call()
is used to find the offset into dynamically allocated trace event fields
for printing. It has nothing to do with function tracing. Rename it.
Signed-off-by: Steven Rostedt <[email protected]>
The name "ftrace" really refers to the function hook infrastructure. It
is not about the trace_events. The function ftrace_define_fields_##call()
is used to define how to process the trace_event fields. It has nothing to
do with function tracing. Rename it.
Signed-off-by: Steven Rostedt <[email protected]>
The name "ftrace" really refers to the function hook infrastructure. It
is not about the trace_events. The structure ftrace_event_type_funcs_##call
is used to define how the trace_events will be printed. It has nothing to
do with function tracing. Rename it.
Signed-off-by: Steven Rostedt <[email protected]>
The name "ftrace" really refers to the function hook infrastructure. It
is not about the trace_events. The structure ftrace_data_offset_##call is
used to find the offsets of dynamically allocated fields in trace_events.
It has nothing to do with function tracing. Rename it.
Signed-off-by: Steven Rostedt <[email protected]>
The name "ftrace" really refers to the function hook infrastructure. It
is not about the trace_events. The ftrace_raw_##call structures are built
by macros for trace events. They have nothing to do with function tracing.
Rename them.
Signed-off-by: Steven Rostedt <[email protected]>
The name "ftrace" really refers to the function hook infrastructure. It
is not about the trace_events. The ftrace_trigger_soft_disabled() tests if a
trace_event is soft disabled (called but not traced), and returns true if
it is. It has nothing to do with function tracing and should be renamed.
Signed-off-by: Steven Rostedt <[email protected]>
The name "ftrace" really refers to the function hook infrastructure. It
is not about the trace_events. The FTRACE_EVENT_FL_* flags are flags to
do with the trace_event files in the tracefs directory. They are not related
to function tracing. Rename them to a more descriptive name.
Signed-off-by: Steven Rostedt <[email protected]>
The name "ftrace" really refers to the function hook infrastructure. It
is not about the trace_events. The structure ftrace_subsystem_dir holds
the information about trace event subsystems. It should not be named
ftrace, rename it to trace_subsystem_dir.
Signed-off-by: Steven Rostedt <[email protected]>
The name "ftrace" really refers to the function hook infrastructure. It
is not about the trace_events. ftrace_event_name() returns the name of
an event tracepoint, has nothing to do with function tracing. Rename it
to trace_event_name().
Signed-off-by: Steven Rostedt <[email protected]>
The name "ftrace" really refers to the function hook infrastructure. It
is not about the trace_events. Rename the max trace_event type size to
something more descriptive and appropriate.
Signed-off-by: Steven Rostedt <[email protected]>
The name "ftrace" really refers to the function hook infrastructure. It
is not about the trace_events. The ftrace_output_*() and ftrace_raw_output_*()
functions represent the trace_event code. Rename them to just trace_output
or trace_raw_output.
Signed-off-by: Steven Rostedt <[email protected]>
The name "ftrace" really refers to the function hook infrastructure. It
is not about the trace_events. The ftrace_event_buffer functions and data
structures are for trace_events and not for function hooks. Rename them
to trace_event_buffer*.
Signed-off-by: Steven Rostedt <[email protected]>
The name "ftrace" really refers to the function hook infrastructure. It
is not about the trace_events. The structures ftrace_event_call and
ftrace_event_class have nothing to do with the function hooks, and are
really trace_event structures. Rename ftrace_event_* to trace_event_*.
Signed-off-by: Steven Rostedt <[email protected]>
The name "ftrace" really refers to the function hook infrastructure. It
is not about the trace_events. The structure ftrace_event_file is really
about trace events and not "ftrace". Rename it to trace_event_file.
Signed-off-by: Steven Rostedt <[email protected]>
The name "ftrace" really refers to the function hook infrastructure. It
is not about the trace_events. The functions (un)register_ftrace_event() is
really about trace_events, and the name should be register_trace_event()
instead.
Also renamed ftrace_event_reg() to trace_event_reg() for the same reason.
Signed-off-by: Steven Rostedt <[email protected]>
The name "ftrace" really refers to the function hook infrastructure. It
is not about the trace_events. The functions ftrace_print_*() are not part of
the function infrastructure, and the names can be confusing. Rename them
to be trace_print_*().
Signed-off-by: Steven Rostedt <[email protected]>
The term "ftrace" is really the infrastructure of the function hooks,
and not the trace events. Rename ftrace_event.h to trace_events.h to
represent the trace_event infrastructure and decouple the term ftrace
from it.
Signed-off-by: Steven Rostedt <[email protected]>
The trace_event.h file is for the generic trace event code. Move
the perf related code into its own trace header file perf.h
Signed-off-by: Steven Rostedt <[email protected]>
The name "ftrace" really refers to the function hook infrastructure. It
is not about the TRACE_EVENT() macros. The file trace/ftrace.h was originally
written to be mostly focused toward the "ftrace" code (that in kernel/trace/)
but ended up being generic and used by perf and others.
Rename the file to be less confusing about what infrastructure it belongs to.
Signed-off-by: Steven Rostedt <[email protected]>
The module notifier call chain for MODULE_STATE_COMING was moved up before
the parsing of args, into the complete_formation() call. But if the module failed
to load after that, the notifier call chain for MODULE_STATE_GOING was
never called and that prevented the users of those call chains from
cleaning up anything that was allocated.
Link: http://lkml.kernel.org/r/[email protected]
Reported-by: Pontus Fuchs <[email protected]>
Fixes: 4982223e51 "module: set nx before marking module MODULE_STATE_COMING"
Cc: [email protected] # 3.16+
Signed-off-by: Steven Rostedt <[email protected]>
Signed-off-by: Rusty Russell <[email protected]>
The code that replaces the enum names with the enum values in the
tracepoints' format files could possible miss the end of string nul
character. This was caused by processing things like backslashes, quotes
and other tokens. After processing the tokens, a check for the nul
character needed to be done before continuing the loop, because the loop
incremented the pointer before doing the check, which could bypass the nul
character.
Link: http://lkml.kernel.org/r/[email protected]
Reported-by: Sasha Levin <[email protected]> # via KASan
Tested-by: Andrey Ryabinin <[email protected]>
Fixes: 0c564a538a "tracing: Add TRACE_DEFINE_ENUM() macro to map enums to their values"
Signed-off-by: Steven Rostedt <[email protected]>
KERN_CONT is nicely commented in kern_levels.h, but pr_cont() is now used
more often, and it lacks the comment stating what it is used for. It can
be confused as continuing the log level, but that is not its purpose. Its
purpose is to continue a line that had no newline enclosed. This should
be documented by pr_cont() as well.
Signed-off-by: Steven Rostedt <[email protected]>
Acked-by: Borislav Petkov <[email protected]>
Signed-off-by: Andrew Morton <[email protected]>
Signed-off-by: Linus Torvalds <[email protected]>
Add a enum_map file in the tracing directory to see what enums have been
saved to convert in the print fmt files.
As this requires the enum mapping to be persistent in memory, it is only
created if the new config option CONFIG_TRACE_ENUM_MAP_FILE is enabled.
This is for debugging and will increase the persistent memory footprint
of the kernel.
Link: http://lkml.kernel.org/r/[email protected]
Reviewed-by: Masami Hiramatsu <[email protected]>
Tested-by: Masami Hiramatsu <[email protected]>
Signed-off-by: Steven Rostedt <[email protected]>
The enums used in tracepoints for __print_symbolic() do not have their
values shown in the tracepoint format files and this makes it difficult
for user space tools to convert the binary values to the strings they
are to represent.
Add TRACE_DEFINE_ENUM(x) macros to export the enum names to their values
to make the tracing output from user space tools more robust.
Link: http://lkml.kernel.org/r/[email protected]
Cc: Dave Chinner <[email protected]>
Cc: Jens Axboe <[email protected]>
Reviewed-by: Masami Hiramatsu <[email protected]>
Tested-by: Masami Hiramatsu <[email protected]>
Signed-off-by: Steven Rostedt <[email protected]>
Enums used by tracepoints for __print_symbolic() are shown in the
tracepoint format files with just their names and not their values.
This makes it difficult for user space tools to know how to convert the
binary data into their string representations.
By adding the use of TRACE_DEFINE_ENUM(), the enum names will be mapped
to their values and shown in the tracing file system to let tools
convert the data as necessary.
Link: http://lkml.kernel.org/r/[email protected]
Acked-by: Mauro Carvalho Chehab <[email protected]>
Reviewed-by: Masami Hiramatsu <[email protected]>
Tested-by: Masami Hiramatsu <[email protected]>
Signed-off-by: Steven Rostedt <[email protected]>
The enums used in the tracepoints for __print_symbolic() have their
names shown in the tracepoint format files. User space tools do not know
how to convert those names into their values to be able to convert the
binary data.
Use TRACE_DEFINE_ENUM() to export the enum names to their values for
userspace to do the parsing correctly.
Link: http://lkml.kernel.org/r/[email protected]
Acked-by: Trond Myklebust <[email protected]>
Reviewed-by: Masami Hiramatsu <[email protected]>
Tested-by: Masami Hiramatsu <[email protected]>
Signed-off-by: Steven Rostedt <[email protected]>
The enums used in tracepoints with __print_symbolic() have their
names shown in the tracepoint format files and not their values.
This makes it difficult for user space tools to convert the binary
data to the strings as user space does not know what those enums
are about.
By having them use TRACE_DEFINE_ENUM(), the names of the enums will
be mapped to the values and shown to user space.
Link: http://lkml.kernel.org/r/[email protected]
Reviewed-by: Masami Hiramatsu <[email protected]>
Tested-by: Masami Hiramatsu <[email protected]>
Signed-off-by: Steven Rostedt <[email protected]>
The enums used by the softirq mapping is what is shown in the output
of the __print_symbolic() and not their values, that are needed
to map them to their strings. Export them to userspace with the
TRACE_DEFINE_ENUM() macro so that user space tools can map the enums
with their values.
Link: http://lkml.kernel.org/r/[email protected]
Cc: Peter Zijlstra <[email protected]>
Cc: Ingo Molnar <[email protected]>
Reviewed-by: Masami Hiramatsu <[email protected]>
Tested-by: Masami Hiramatsu <[email protected]>
Signed-off-by: Steven Rostedt <[email protected]>
The tracepoints that use __print_symbolic() use enums as the value
to convert to strings. Unfortunately, the format files for these
tracepoints show the enum name and not their value. This causes some
userspace tools not to know how to convert __print_symbolic() to
their strings.
Add TRACE_DEFINE_ENUM() macros to export the enums used to userspace
to let those tools know what those enum values are.
Link: http://lkml.kernel.org/r/[email protected]
Cc: Namjae Jeon <[email protected]>
Cc: Pankaj Kumar <[email protected]>
Cc: Jaegeuk Kim <[email protected]>
Reviewed-by: Masami Hiramatsu <[email protected]>
Tested-by: Masami Hiramatsu <[email protected]>
Signed-off-by: Steven Rostedt <[email protected]>
The tracepoints in the 9p code use a lot of enums for the __print_symbolic()
function. These enums are shown in the tracepoint format files, and user
space tools such as trace-cmd does not have the information to parse it.
Add helper macros to export the enums with TRACE_DEFINE_ENUM().
Link: http://lkml.kernel.org/r/[email protected]
Cc: Aneesh Kumar K.V <[email protected]>
Cc: Eric Van Hensbergen <[email protected]>
Reviewed-by: Masami Hiramatsu <[email protected]>
Tested-by: Masami Hiramatsu <[email protected]>
Signed-off-by: Steven Rostedt <[email protected]>
Document the use of TRACE_DEFINE_ENUM() by adding enums to the
trace-event-sample.h and using this macro to convert them in the format
files.
Also update the comments and sho the use of __print_symbolic() and
__print_flags() as well as adding comments abount __print_array().
Link: http://lkml.kernel.org/r/[email protected]
Reviewed-by: Masami Hiramatsu <[email protected]>
Tested-by: Masami Hiramatsu <[email protected]>
Signed-off-by: Steven Rostedt <[email protected]>
Several tracepoints use the helper functions __print_symbolic() or
__print_flags() and pass in enums that do the mapping between the
binary data stored and the value to print. This works well for reading
the ASCII trace files, but when the data is read via userspace tools
such as perf and trace-cmd, the conversion of the binary value to a
human string format is lost if an enum is used, as userspace does not
have access to what the ENUM is.
For example, the tracepoint trace_tlb_flush() has:
__print_symbolic(REC->reason,
{ TLB_FLUSH_ON_TASK_SWITCH, "flush on task switch" },
{ TLB_REMOTE_SHOOTDOWN, "remote shootdown" },
{ TLB_LOCAL_SHOOTDOWN, "local shootdown" },
{ TLB_LOCAL_MM_SHOOTDOWN, "local mm shootdown" })
Which maps the enum values to the strings they represent. But perf and
trace-cmd do no know what value TLB_LOCAL_MM_SHOOTDOWN is, and would
not be able to map it.
With TRACE_DEFINE_ENUM(), developers can place these in the event header
files and ftrace will convert the enums to their values:
By adding:
TRACE_DEFINE_ENUM(TLB_FLUSH_ON_TASK_SWITCH);
TRACE_DEFINE_ENUM(TLB_REMOTE_SHOOTDOWN);
TRACE_DEFINE_ENUM(TLB_LOCAL_SHOOTDOWN);
TRACE_DEFINE_ENUM(TLB_LOCAL_MM_SHOOTDOWN);
$ cat /sys/kernel/debug/tracing/events/tlb/tlb_flush/format
[...]
__print_symbolic(REC->reason,
{ 0, "flush on task switch" },
{ 1, "remote shootdown" },
{ 2, "local shootdown" },
{ 3, "local mm shootdown" })
The above is what userspace expects to see, and tools do not need to
be modified to parse them.
Link: http://lkml.kernel.org/r/[email protected]
Cc: Guilherme Cox <[email protected]>
Cc: Tony Luck <[email protected]>
Cc: Xie XiuQi <[email protected]>
Acked-by: Namhyung Kim <[email protected]>
Reviewed-by: Masami Hiramatsu <[email protected]>
Tested-by: Masami Hiramatsu <[email protected]>
Signed-off-by: Steven Rostedt <[email protected]>
Add documentation about TRACE_SYSTEM needing to be alpha-numeric or with
underscores, and that if it is not, then the use of TRACE_SYSTEM_VAR is
required to make something that is.
An example of this is shown in samples/trace_events/trace-events-sample.h
Link: http://lkml.kernel.org/r/[email protected]
Reviewed-by: Masami Hiramatsu <[email protected]>
Tested-by: Masami Hiramatsu <[email protected]>
Signed-off-by: Steven Rostedt <[email protected]>
Normally the compiler will use the same pointer for a string throughout
the file. But there's no guarantee of that happening. Later changes will
require that all events have the same pointer to the system string.
Name the system string and have all events point to it.
Testing this, it did not increases the size of the text, except for the
notes section, which should not harm the real size any.
Link: http://lkml.kernel.org/r/[email protected]
Reviewed-by: Masami Hiramatsu <[email protected]>
Tested-by: Masami Hiramatsu <[email protected]>
Signed-off-by: Steven Rostedt <[email protected]>
Every tracing file must have its own TRACE_SYSTEM defined.
The brcmsmac tracepoint header broke this and added in the middle
of the file:
#undef TRACE_SYSTEM
#define TRACE_SYSTEM brcmsmac
#undef TRACE_SYSTEM
#define TRACE_SYSTEM brcmsmac_tx
#undef TRACE_SYSTEM
#define TRACE_SYSTEM brcmsmac_msg
Unfortunately, this broke new code in the ftrace infrastructure.
Moving each of these TRACE_SYSTEMs into their own trace file with
just one TRACE_SYSTEM per file fixes the issue.
Link: http://lkml.kernel.org/r/[email protected]
Acked-by: Arend van Spriel <[email protected]>
Signed-off-by: Steven Rostedt <[email protected]>
Every tracing file must have its own TRACE_SYSTEM defined.
The iwlwifi tracepoint header broke this and added in the middle
of the file:
#undef TRACE_SYSTEM
#define TRACE_SYSTEM iwlwifi_io
#undef TRACE_SYSTEM
#define TRACE_SYSTEM iwlwifi_ucode
#undef TRACE_SYSTEM
#define TRACE_SYSTEM iwlwifi_msg
#undef TRACE_SYSTEM
#define TRACE_SYSTEM iwlwifi_data
#undef TRACE_SYSTEM
#define TRACE_SYSTEM iwlwifi
Unfortunately, this broke new code in the ftrace infrastructure.
Moving each of these TRACE_SYSTEMs into their own trace file with
just one TRACE_SYSTEM per file fixes the issue.
Link: http://lkml.kernel.org/r/[email protected]
Reviewed-by: Johannes Berg <[email protected]>
Signed-off-by: Steven Rostedt <[email protected]>
Every tracing file must have its own TRACE_SYSTEM defined.
The mac80211 tracepoint header broke this and add in the middle
of the file had:
#undef TRACE_SYSTEM
#define TRACE_SYSTEM mac80211_msg
Unfortunately, this broke new code in the ftrace infrastructure.
Moving the mac80211_msg into its own trace file with its own
TRACE_SYSTEM defined fixes the issue.
Link: http://lkml.kernel.org/r/[email protected]
Reviewed-by: Johannes Berg <[email protected]>
Signed-off-by: Steven Rostedt <[email protected]>
New code will require TRACE_SYSTEM to be a valid C variable name,
but some tracepoints have TRACE_SYSTEM with '-' and not '_', so
it can not be used. Instead, add a TRACE_SYSTEM_VAR that can
give the tracing infrastructure a unique name for the trace system.
Cc: Xenia Ragiadakou <[email protected]>
Cc: Sarah Sharp <[email protected]>
Reviewed-by: Masami Hiramatsu <[email protected]>
Tested-by: Masami Hiramatsu <[email protected]>
Signed-off-by: Steven Rostedt <[email protected]>
New code will require TRACE_SYSTEM to be a valid C variable name,
but some tracepoints have TRACE_SYSTEM with '-' and not '_', so
it can not be used. Instead, add a TRACE_SYSTEM_VAR that can
give the tracing infrastructure a unique name for the trace system.
Link: http://lkml.kernel.org/r/[email protected]
Acked-by: Mark Brown <[email protected]>
Reviewed-by: Masami Hiramatsu <[email protected]>
Tested-by: Masami Hiramatsu <[email protected]>
Signed-off-by: Steven Rostedt <[email protected]>
The tracing infrastructure is adding a macro TRACE_SYSTEM_STRING, and
hit the following build failure:
In file included from include/trace/define_trace.h:90:0,
from drivers/gpu/drm/.//radeon/radeon_trace.h:209,
from drivers/gpu/drm/.//radeon/radeon_trace_points.c:9:
>> include/trace/ftrace.h:28:0: warning: "TRACE_SYSTEM_STRING" redefined
#define TRACE_SYSTEM_STRING __app(TRACE_SYSTEM_VAR,__trace_system_name)
Seems that the DRM folks have added their own use to the
TRACE_SYSTEM_STRING, with:
#define TRACE_SYSTEM_STRING __stringify(TRACE_SYSTEM)
Although, I can not find its use anywhere. I could simply use another
name, but if this macro is not being used, it should be removed.
Link: http://lkml.kernel.org/r/[email protected]
Cc: Alex Deucher <[email protected]>
Cc: Christian König <[email protected]>
Cc: David Airlie <[email protected]>
Cc: Daniel Vetter <[email protected]>
Cc: Jani Nikula <[email protected]>
Reviewed-by: Masami Hiramatsu <[email protected]>
Tested-by: Masami Hiramatsu <[email protected]>
Reported-by: kbuild test robot <[email protected]>
Signed-off-by: Steven Rostedt <[email protected]>
Dynamically allocated trampolines call ftrace_ops_get_func to get the
function which they should call. For dynamic fops (FTRACE_OPS_FL_DYNAMIC
flag is set) ftrace_ops_list_func is always returned. This is reasonable
for static trampolines but goes against the main advantage of dynamic
ones, that is avoidance of going through the list of all registered
callbacks for functions that are only being traced by a single callback.
We can fix it by returning ops->func (or recursion safe version) from
ftrace_ops_get_func whenever it is possible for dynamic trampolines.
Note that dynamic trampolines are not allowed for dynamic fops if
CONFIG_PREEMPT=y.
Link: http://lkml.kernel.org/r/[email protected]
Link: http://lkml.kernel.org/r/[email protected]
Reported-by: Miroslav Benes <[email protected]>
Signed-off-by: Steven Rostedt <[email protected]>
A clean up of the recursive protection code changed
val = this_cpu_read(current_context);
val--;
val &= this_cpu_read(current_context);
to
val = this_cpu_read(current_context);
val &= val & (val - 1);
Which has a duplicate use of '&' as the above is the same as
val = val & (val - 1);
Actually, it would be best to remove that line altogether and
just add it to where it is used.
And Christoph even mentioned that it can be further compacted to
just a single line:
__this_cpu_and(current_context, __this_cpu_read(current_context) - 1);
Link: http://lkml.kernel.org/[email protected]
Suggested-by: Christoph Lameter <[email protected]>
Signed-off-by: Steven Rostedt <[email protected]>
Guilherme Cox found that:
There is, however, a potential bug if there is an item with code zero
that is not the first one in the symbol list, since eval_flag(..)
returns 0 when it doesn't find anything.
That is, if you have the following enums:
enum {
FOO_START = 0,
FOO_GO = 1,
FOO_END = 2
}
and then have:
__print_symbolic(foo, FOO_GO, "go", FOO_START, "start",
FOO_END, "end")
If none of the enums are known to pevent, then eval_flag() will return
zero, and it will match it to the first item in the list, which would be
FOO_GO, which is not zero.
Luckily, in most cases, the first element would be zero, and the parsing
would match out of sheer luck.
Reported-by: Guilherme Cox <[email protected]>
Signed-off-by: Steven Rostedt <[email protected]>
Cc: Jiri Olsa <[email protected]>
Cc: Namhyung Kim <[email protected]>
Link: http://lkml.kernel.org/r/[email protected]
Signed-off-by: Arnaldo Carvalho de Melo <[email protected]>
It has come to my attention that this_cpu_read/write are horrible on
architectures other than x86. Worse yet, they actually disable
preemption or interrupts! This caused some unexpected tracing results
on ARM.
101.356868: preempt_count_add <-ring_buffer_lock_reserve
101.356870: preempt_count_sub <-ring_buffer_lock_reserve
The ring_buffer_lock_reserve has recursion protection that requires
accessing a per cpu variable. But since preempt_disable() is traced, it
too got traced while accessing the variable that is suppose to prevent
recursion like this.
The generic version of this_cpu_read() and write() are:
#define this_cpu_generic_read(pcp) \
({ typeof(pcp) ret__; \
preempt_disable(); \
ret__ = *this_cpu_ptr(&(pcp)); \
preempt_enable(); \
ret__; \
})
#define this_cpu_generic_to_op(pcp, val, op) \
do { \
unsigned long flags; \
raw_local_irq_save(flags); \
*__this_cpu_ptr(&(pcp)) op val; \
raw_local_irq_restore(flags); \
} while (0)
Which is unacceptable for locations that know they are within preempt
disabled or interrupt disabled locations.
Paul McKenney stated that __this_cpu_() versions produce much better code on
other architectures than this_cpu_() does, if we know that the call is done in
a preempt disabled location.
I also changed the recursive_unlock() to use two local variables instead
of accessing the per_cpu variable twice.
Link: http://lkml.kernel.org/r/[email protected]
Link: http://lkml.kernel.org/r/[email protected]
Cc: [email protected]
Acked-by: Christoph Lameter <[email protected]>
Reported-by: Uwe Kleine-Koenig <[email protected]>
Tested-by: Uwe Kleine-Koenig <[email protected]>
Signed-off-by: Steven Rostedt <[email protected]>
When a event PADDING is hit (a deleted event that is still in the ring
buffer), translate_data() sets the length of the padding and also updates
the data pointer which is passed back to the caller.
This is unneeded because the caller also updates the data pointer with
the passed back length. translate_data() should not update the pointer,
only set the length.
Signed-off-by: Steven Rostedt <[email protected]>
Cc: Andrew Morton <[email protected]>
Cc: Jiri Olsa <[email protected]>
Cc: Namhyung Kim <[email protected]>
Cc: [email protected] # 3.12+
Link: http://lkml.kernel.org/r/[email protected]
Signed-off-by: Arnaldo Carvalho de Melo <[email protected]>
There is a pevent_data_comm_from_pid() that returns the cmdline stored for
a given pid in order for users to map pids to comms, but there's no method
to convert a comm back to a pid. This is useful for filters that specify
a comm instead of a PID (it's faster than searching each individual event).
Add a way to retrieve a comm from a pid. Since there can be more than one
pid associated to a comm, it returns a data structure that lets the user
iterate over all the saved comms for a given pid.
Signed-off-by: Steven Rostedt <[email protected]>
Cc: Andrew Morton <[email protected]>
Cc: Jiri Olsa <[email protected]>
Cc: Namhyung Kim <[email protected]>
Link: http://lkml.kernel.org/r/[email protected]
Signed-off-by: Arnaldo Carvalho de Melo <[email protected]>
The pevent->trace_clock should not be a direct pointer to what was
given. It should be copied and freed.
Note, valgrind pointed this out when a caller passed in a pointer that
needed to be freed and it never was. Ideally, pevent should copy it
(which this change does), and free the copy. It's up to the caller to
free the clock string passed in.
Signed-off-by: Steven Rostedt <[email protected]>
Cc: Andrew Morton <[email protected]>
Cc: Jiri Olsa <[email protected]>
Cc: Namhyung Kim <[email protected]>
Link: http://lkml.kernel.org/r/[email protected]
Signed-off-by: Arnaldo Carvalho de Melo <[email protected]>
When debugging the latencies on a 40 core box, where we hit 300 to
500 microsecond latencies, I found there was a huge contention on the
runqueue locks.
Investigating it further, running ftrace, I found that it was due to
the pulling of RT tasks.
The test that was run was the following:
cyclictest --numa -p95 -m -d0 -i100
This created a thread on each CPU, that would set its wakeup in iterations
of 100 microseconds. The -d0 means that all the threads had the same
interval (100us). Each thread sleeps for 100us and wakes up and measures
its latencies.
cyclictest is maintained at:
git://git.kernel.org/pub/scm/linux/kernel/git/clrkwllms/rt-tests.git
What happened was another RT task would be scheduled on one of the CPUs
that was running our test, when the other CPU tests went to sleep and
scheduled idle. This caused the "pull" operation to execute on all
these CPUs. Each one of these saw the RT task that was overloaded on
the CPU of the test that was still running, and each one tried
to grab that task in a thundering herd way.
To grab the task, each thread would do a double rq lock grab, grabbing
its own lock as well as the rq of the overloaded CPU. As the sched
domains on this box was rather flat for its size, I saw up to 12 CPUs
block on this lock at once. This caused a ripple affect with the
rq locks especially since the taking was done via a double rq lock, which
means that several of the CPUs had their own rq locks held while trying
to take this rq lock. As these locks were blocked, any wakeups or load
balanceing on these CPUs would also block on these locks, and the wait
time escalated.
I've tried various methods to lessen the load, but things like an
atomic counter to only let one CPU grab the task wont work, because
the task may have a limited affinity, and we may pick the wrong
CPU to take that lock and do the pull, to only find out that the
CPU we picked isn't in the task's affinity.
Instead of doing the PULL, I now have the CPUs that want the pull to
send over an IPI to the overloaded CPU, and let that CPU pick what
CPU to push the task to. No more need to grab the rq lock, and the
push/pull algorithm still works fine.
With this patch, the latency dropped to just 150us over a 20 hour run.
Without the patch, the huge latencies would trigger in seconds.
I've created a new sched feature called RT_PUSH_IPI, which is enabled
by default.
When RT_PUSH_IPI is not enabled, the old method of grabbing the rq locks
and having the pulling CPU do the work is implemented. When RT_PUSH_IPI
is enabled, the IPI is sent to the overloaded CPU to do a push.
To enabled or disable this at run time:
# mount -t debugfs nodev /sys/kernel/debug
# echo RT_PUSH_IPI > /sys/kernel/debug/sched_features
or
# echo NO_RT_PUSH_IPI > /sys/kernel/debug/sched_features
Update: This original patch would send an IPI to all CPUs in the RT overload
list. But that could theoretically cause the reverse issue. That is, there
could be lots of overloaded RT queues and one CPU lowers its priority. It would
then send an IPI to all the overloaded RT queues and they could then all try
to grab the rq lock of the CPU lowering its priority, and then we have the
same problem.
The latest design sends out only one IPI to the first overloaded CPU. It tries to
push any tasks that it can, and then looks for the next overloaded CPU that can
push to the source CPU. The IPIs stop when all overloaded CPUs that have pushable
tasks that have priorities greater than the source CPU are covered. In case the
source CPU lowers its priority again, a flag is set to tell the IPI traversal to
restart with the first RT overloaded CPU after the source CPU.
Parts-suggested-by: Peter Zijlstra <[email protected]>
Signed-off-by: Steven Rostedt <[email protected]>
Signed-off-by: Peter Zijlstra (Intel) <[email protected]>
Cc: Joern Engel <[email protected]>
Cc: Clark Williams <[email protected]>
Cc: Mike Galbraith <[email protected]>
Cc: Paul E. McKenney <[email protected]>
Cc: Thomas Gleixner <[email protected]>
Link: http://lkml.kernel.org/r/[email protected]
Signed-off-by: Ingo Molnar <[email protected]>
When CONFIG_IRQ_WORK is not defined (difficult to do, as it also
requires CONFIG_PRINTK not to be defined), we get a build failure:
kernel/built-in.o: In function `flush_smp_call_function_queue':
kernel/smp.c:263: undefined reference to `irq_work_run'
kernel/smp.c:263: undefined reference to `irq_work_run'
Makefile:933: recipe for target 'vmlinux' failed
Simplest thing to do is to make irq_work_run() a nop when not set.
Signed-off-by: Steven Rostedt <[email protected]>
Signed-off-by: Peter Zijlstra (Intel) <[email protected]>
Cc: Andrew Morton <[email protected]>
Cc: Frederic Weisbecker <[email protected]>
Link: http://lkml.kernel.org/r/[email protected]
Signed-off-by: Ingo Molnar <[email protected]>
The tracing events for regmap are confined to the regmap subsystem. It
also requires accessing an internal header. Instead of including the
internal header from a generic file location, move the tracing file
into the regmap directory.
Also rename the regmap tracing header to trace.h, as it is redundant to
keep the regmap.h name when it is in the regmap directory.
Signed-off-by: Steven Rostedt <[email protected]>
Signed-off-by: Mark Brown <[email protected]>
Some archs (specifically PowerPC), are sensitive with the ordering of
the enabling of the calls to function tracing and setting of the
function to use to be traced.
That is, update_ftrace_function() sets what function the ftrace_caller
trampoline should call. Some archs require this to be set before
calling ftrace_run_update_code().
Another bug was discovered, that ftrace_startup_sysctl() called
ftrace_run_update_code() directly. If the function the ftrace_caller
trampoline changes, then it will not be updated. Instead a call
to ftrace_startup_enable() should be called because it tests to see
if the callback changed since the code was disabled, and will
tell the arch to update appropriately. Most archs do not need this
notification, but PowerPC does.
The problem could be seen by the following commands:
# echo 0 > /proc/sys/kernel/ftrace_enabled
# echo function > /sys/kernel/debug/tracing/current_tracer
# echo 1 > /proc/sys/kernel/ftrace_enabled
# cat /sys/kernel/debug/tracing/trace
The trace will show that function tracing was not active.
Cc: [email protected] # 2.6.27+
Signed-off-by: Steven Rostedt <[email protected]>
When /proc/sys/kernel/ftrace_enabled is set to zero, all function
tracing is disabled. But the records that represent the functions
still hold information about the ftrace_ops that are hooked to them.
ftrace_ops may request "REGS" (have a full set of pt_regs passed to
the callback), or "TRAMP" (the ops has its own trampoline to use).
When the record is updated to represent the state of the ops hooked
to it, it sets "REGS_EN" and/or "TRAMP_EN" to state that the callback
points to the correct trampoline (REGS has its own trampoline).
When ftrace_enabled is set to zero, all ftrace locations are a nop,
so they do not point to any trampoline. But the _EN flags are still
set. This can cause the accounting to go wrong when ftrace_enabled
is cleared and an ops that has a trampoline is registered or unregistered.
For example, the following will cause ftrace to crash:
# echo function_graph > /sys/kernel/debug/tracing/current_tracer
# echo 0 > /proc/sys/kernel/ftrace_enabled
# echo nop > /sys/kernel/debug/tracing/current_tracer
# echo 1 > /proc/sys/kernel/ftrace_enabled
# echo function_graph > /sys/kernel/debug/tracing/current_tracer
As function_graph uses a trampoline, when ftrace_enabled is set to zero
the updates to the record are not done. When enabling function_graph
again, the record will still have the TRAMP_EN flag set, and it will
look for an op that has a trampoline other than the function_graph
ops, and fail to find one.
Cc: [email protected] # 3.17+
Reported-by: Pratyush Anand <[email protected]>
Signed-off-by: Steven Rostedt <[email protected]>
In seq_buf_bprintf(), bstr_printf() is used to copy the format into the
buffer remaining in the seq_buf structure. The return of bstr_printf()
is the amount of characters written to the buffer excluding the '\0',
unless the line was truncated!
If the line copied does not fit, it is truncated, and a '\0' is added
to the end of the buffer. But in this case, '\0' is included in the length
of the line written. To know if the buffer had overflowed, the return
length will be the same or greater than the length of the buffer passed in.
The check in seq_buf_bprintf() only checked if the length returned from
bstr_printf() would fit in the buffer, as the seq_buf_bprintf() is only
to be an all or nothing command. It either writes all the string into
the seq_buf, or none of it. If the string is truncated, the pointers
inside the seq_buf must be reset to what they were when the function was
called. This is not the case. On overflow, it copies only part of the string.
The fix is to change the overflow check to see if the length returned from
bstr_printf() is less than the length remaining in the seq_buf buffer, and not
if it is less than or equal to as it currently does. Then seq_buf_bprintf()
will know if the write from bstr_printf() was truncated or not.
Link: http://lkml.kernel.org/r/[email protected]
Cc: [email protected]
Reported-by: Joe Perches <[email protected]>
Signed-off-by: Steven Rostedt <[email protected]>
In seq_buf_vprintf(), vsnprintf() is used to copy the format into the
buffer remaining in the seq_buf structure. The return of vsnprintf()
is the amount of characters written to the buffer excluding the '\0',
unless the line was truncated!
If the line copied does not fit, it is truncated, and a '\0' is added
to the end of the buffer. But in this case, '\0' is included in the length
of the line written. To know if the buffer had overflowed, the return
length will be the same as the length of the buffer passed in.
The check in seq_buf_vprintf() only checked if the length returned from
vsnprintf() would fit in the buffer, as the seq_buf_vprintf() is only
to be an all or nothing command. It either writes all the string into
the seq_buf, or none of it. If the string is truncated, the pointers
inside the seq_buf must be reset to what they were when the function was
called. This is not the case. On overflow, it copies only part of the string.
The fix is to change the overflow check to see if the length returned from
vsnprintf() is less than the length remaining in the seq_buf buffer, and not
if it is less than or equal to as it currently does. Then seq_buf_vprintf()
will know if the write from vsnpritnf() was truncated or not.
Cc: [email protected]
Signed-off-by: Steven Rostedt <[email protected]>
Commit:
1e02ce4ccc ("x86: Store a per-cpu shadow copy of CR4")
added a shadow CR4 such that reads and writes that do not
modify the CR4 execute much faster than always reading the
register itself.
The change modified cpu_init() in common.c, so that the
shadow CR4 gets initialized before anything uses it.
Unfortunately, there's two cpu_init()s in common.c. There's
one for 64-bit and one for 32-bit. The commit only added
the shadow init to the 64-bit path, but the 32-bit path
needs the init too.
Link: http://lkml.kernel.org/r/[email protected] Fixes: 1e02ce4ccc "x86: Store a per-cpu shadow copy of CR4"
Signed-off-by: Steven Rostedt <[email protected]>
Acked-by: Andy Lutomirski <[email protected]>
Cc: Peter Zijlstra (Intel) <[email protected]>
Cc: Linus Torvalds <[email protected]>
Link: http://lkml.kernel.org/r/[email protected]
Signed-off-by: Ingo Molnar <[email protected]>
When an application connects to the ring buffer via splice, it can only
read full pages. Splice does not work with partial pages. If there is
not enough data to fill a page, the splice command will either block
or return -EAGAIN (if set to nonblock).
Code was added where if the page is not full, to just sleep again.
The problem is, it will get woken up again on the next event. That
is, when something is written into the ring buffer, if there is a waiter
it will wake it up. The waiter would then check the buffer, see that
it still does not have enough data to fill a page and go back to sleep.
To make matters worse, when the waiter goes back to sleep, it could
cause another event, which would wake it back up again to see it
doesn't have enough data and sleep again. This produces a tremendous
overhead and fills the ring buffer with noise.
For example, recording sched_switch on an idle system for 10 seconds
produces 25,350,475 events!!!
Create another wait queue for those waiters wanting full pages.
When an event is written, it only wakes up waiters if there's a full
page of data. It does not wake up the waiter if the page is not yet
full.
After this change, recording sched_switch on an idle system for 10
seconds produces only 800 events. Getting rid of 25,349,675 useless
events (99.9969% of events!!), is something to take seriously.
Cc: [email protected] # 3.16+
Cc: Rabin Vincent <[email protected]>
Fixes: e30f53aad2 "tracing: Do not busy wait in buffer splice"
Signed-off-by: Steven Rostedt <[email protected]>
Add to samples/trace_events/ the macros DECLARE_EVENT_CLASS() and
DEFINE_EVENT() and recommend using them over multiple TRACE_EVENT()
macros if the multiple events have the same format.
Signed-off-by: Steven Rostedt <[email protected]>
If a function should be called before a tracepoint is enabled
and/or after it is disabled, the TRACE_EVENT_FN() serves this
purpose. But it is not well documented. Having it as a sample would
help developers to know how to use it.
Signed-off-by: Steven Rostedt <[email protected]>
The sample code lacks an example of TRACE_EVENT_CONDITION, and it
has been expressed to me that this feature for TRACE_EVENT is not
well known and not used when it could be.
Signed-off-by: Steven Rostedt <[email protected]>
The sample code in samples/trace_events/ is extremely out of date and does
not show all the new fields that have been added since the sample code
was written. As most people are unaware of these new fields, adding sample
code and explanations of those fields should help out.
Signed-off-by: Steven Rostedt <[email protected]>
When taking a CPU down for suspend and resume, a tracepoint may be called
when the CPU has been designated offline. As tracepoints require RCU for
protection, they must not be called if the current CPU is offline.
Unfortunately, trace_tlb_flush() is called in this scenario as was noted
by LOCKDEP:
...
Disabling non-boot CPUs ...
intel_pstate CPU 1 exiting
===============================
smpboot: CPU 1 didn't die...
[ INFO: suspicious RCU usage. ]
3.19.0-rc7-next-20150204.1-iniza-small #1 Not tainted
-------------------------------
include/trace/events/tlb.h:35 suspicious rcu_dereference_check() usage!
other info that might help us debug this:
RCU used illegally from offline CPU!
rcu_scheduler_active = 1, debug_locks = 0
no locks held by swapper/1/0.
stack backtrace:
CPU: 1 PID: 0 Comm: swapper/1 Not tainted 3.19.0-rc7-next-20150204.1-iniza-small #1
Hardware name: SAMSUNG ELECTRONICS CO., LTD. 530U3BI/530U4BI/530U4BH/530U3BI/530U4BI/530U4BH, BIOS 13XK 03/28/2013
0000000000000001 ffff88011a44fe18 ffffffff817e370d 0000000000000011
ffff88011a448290 ffff88011a44fe48 ffffffff810d6847 ffff8800c66b9600
0000000000000001 ffff88011a44c000 ffffffff81cb3900 ffff88011a44fe78
Call Trace:
[<ffffffff817e370d>] dump_stack+0x4c/0x65
[<ffffffff810d6847>] lockdep_rcu_suspicious+0xe7/0x120
[<ffffffff810b71a5>] idle_task_exit+0x205/0x2c0
[<ffffffff81054c4e>] play_dead_common+0xe/0x50
[<ffffffff81054ca5>] native_play_dead+0x15/0x140
[<ffffffff8102963f>] arch_cpu_idle_dead+0xf/0x20
[<ffffffff810cd89e>] cpu_startup_entry+0x37e/0x580
[<ffffffff81053e20>] start_secondary+0x140/0x150
intel_pstate CPU 2 exiting
...
By converting the tlb_flush tracepoint to a TRACE_EVENT_CONDITION where the
condition is cpu_online(smp_processor_id()), we can avoid calling RCU protected
code when the CPU is offline.
Link: http://lkml.kernel.org/r/CA+icZUUGiGDoL5NU8RuxKzFjoLjEKRtUWx=JB8B9a0EQv-eGzQ@mail.gmail.com
Cc: [email protected] # 3.17+
Fixes: d17d8f9ded "x86/mm: Add tracepoints for TLB flushes"
Reported-by: Sedat Dilek <[email protected]>
Tested-by: Sedat Dilek <[email protected]>
Suggested-by: Paul E. McKenney <[email protected]>
Acked-by: Paul E. McKenney <[email protected]>
Acked-by: Dave Hansen <[email protected]>
Signed-off-by: Steven Rostedt <[email protected]>
The trace_tlb_flush() tracepoint can be called when a CPU is going offline.
When a CPU is offline, RCU is no longer watching that CPU and since the
tracepoint is protected by RCU, it must not be called. To prevent the
tlb_flush tracepoint from being called when the CPU is offline, it was
converted to a TRACE_EVENT_CONDITION where the condition checks if the
CPU is online before calling the tracepoint.
Unfortunately, this was not enough to stop lockdep from complaining about
it. Even though the RCU protected code of the tracepoint will never be
called, the condition is hidden within the tracepoint, and even though the
condition prevents RCU code from being called, the lockdep checks are
outside the tracepoint (this is to test tracepoints even when they are not
enabled).
Even though tracepoints should be checked to be RCU safe when they are not
enabled, the condition should still be considered when checking RCU.
Link: http://lkml.kernel.org/r/CA+icZUUGiGDoL5NU8RuxKzFjoLjEKRtUWx=JB8B9a0EQv-eGzQ@mail.gmail.com
Fixes: 3a630178fd "tracing: generate RCU warnings even when tracepoints are disabled"
Cc: [email protected] # 3.18+
Acked-by: Dave Hansen <[email protected]>
Reported-by: Sedat Dilek <[email protected]>
Tested-by: Sedat Dilek <[email protected]>
Signed-off-by: Steven Rostedt <[email protected]>
