2018-08-16 22:23:53 +07:00
|
|
|
// SPDX-License-Identifier: GPL-2.0
|
2008-05-13 02:20:42 +07:00
|
|
|
/*
|
2009-02-17 13:10:02 +07:00
|
|
|
* trace irqs off critical timings
|
2008-05-13 02:20:42 +07:00
|
|
|
*
|
|
|
|
* Copyright (C) 2007-2008 Steven Rostedt <srostedt@redhat.com>
|
|
|
|
* Copyright (C) 2008 Ingo Molnar <mingo@redhat.com>
|
|
|
|
*
|
|
|
|
* From code in the latency_tracer, that is:
|
|
|
|
*
|
|
|
|
* Copyright (C) 2004-2006 Ingo Molnar
|
2012-12-06 16:39:54 +07:00
|
|
|
* Copyright (C) 2004 Nadia Yvette Chambers
|
2008-05-13 02:20:42 +07:00
|
|
|
*/
|
|
|
|
#include <linux/kallsyms.h>
|
|
|
|
#include <linux/uaccess.h>
|
|
|
|
#include <linux/module.h>
|
|
|
|
#include <linux/ftrace.h>
|
|
|
|
|
|
|
|
#include "trace.h"
|
|
|
|
|
2017-10-11 05:51:37 +07:00
|
|
|
#include <trace/events/preemptirq.h>
|
|
|
|
|
2017-10-06 07:54:31 +07:00
|
|
|
#if defined(CONFIG_IRQSOFF_TRACER) || defined(CONFIG_PREEMPT_TRACER)
|
2008-05-13 02:20:42 +07:00
|
|
|
static struct trace_array *irqsoff_trace __read_mostly;
|
|
|
|
static int tracer_enabled __read_mostly;
|
|
|
|
|
2008-05-13 02:20:42 +07:00
|
|
|
static DEFINE_PER_CPU(int, tracing_cpu);
|
|
|
|
|
2009-07-25 22:13:33 +07:00
|
|
|
static DEFINE_RAW_SPINLOCK(max_trace_lock);
|
2008-05-13 02:20:44 +07:00
|
|
|
|
2008-05-13 02:20:42 +07:00
|
|
|
enum {
|
|
|
|
TRACER_IRQS_OFF = (1 << 1),
|
|
|
|
TRACER_PREEMPT_OFF = (1 << 2),
|
|
|
|
};
|
|
|
|
|
|
|
|
static int trace_type __read_mostly;
|
|
|
|
|
2013-03-15 02:03:53 +07:00
|
|
|
static int save_flags;
|
2009-03-05 10:15:30 +07:00
|
|
|
|
2010-04-03 00:01:22 +07:00
|
|
|
static void stop_irqsoff_tracer(struct trace_array *tr, int graph);
|
|
|
|
static int start_irqsoff_tracer(struct trace_array *tr, int graph);
|
|
|
|
|
2008-05-13 02:20:42 +07:00
|
|
|
#ifdef CONFIG_PREEMPT_TRACER
|
2008-05-13 02:20:51 +07:00
|
|
|
static inline int
|
tracing/irqsoff: Handle preempt_count for different configs
I was hitting the following warning:
WARNING: CPU: 0 PID: 1 at kernel/trace/trace_irqsoff.c:631 tracer_hardirqs_off+0x15/0x2a
Modules linked in:
CPU: 0 PID: 1 Comm: swapper/0 Not tainted 4.18.0-rc6-test+ #13
Hardware name: MSI MS-7823/CSM-H87M-G43 (MS-7823), BIOS V1.6 02/22/2014
EIP: tracer_hardirqs_off+0x15/0x2a
Code: ff 85 c0 74 0e 8b 45 00 8b 50 04 8b 45 04 e8 35 ff ff ff 5d c3 55 64 a1 cc 37 51 c1 a9 ff ff ff 7f 89 e5 53 89 d3 89 ca 75 02 <0f> 0b e8 90 fc ff ff 85 c0 74 07 89 d8 e8 0c ff ff ff 5b 5d c3 55
EAX: 80000000 EBX: c04337f0 ECX: c04338e3 EDX: c04338e3
ESI: c04337f0 EDI: c04338e3 EBP: f2aa1d68 ESP: f2aa1d64
DS: 007b ES: 007b FS: 00d8 GS: 00e0 SS: 0068 EFLAGS: 00210046
CR0: 80050033 CR2: 00000000 CR3: 01668000 CR4: 001406f0
Call Trace:
trace_irq_disable_rcuidle+0x63/0x6c
trace_hardirqs_off+0x26/0x30
default_send_IPI_mask_allbutself_logical+0x31/0x93
default_send_IPI_allbutself+0x37/0x48
native_send_call_func_ipi+0x4d/0x6a
smp_call_function_many+0x165/0x19d
? add_nops+0x34/0x34
? trace_hardirqs_on_caller+0x2d/0x2d
? add_nops+0x34/0x34
smp_call_function+0x1f/0x23
on_each_cpu+0x15/0x43
? trace_hardirqs_on_caller+0x2d/0x2d
? trace_hardirqs_on_caller+0x2d/0x2d
? trace_irq_disable_rcuidle+0x1/0x6c
text_poke_bp+0xa0/0xc2
? trace_hardirqs_on_caller+0x2d/0x2d
arch_jump_label_transform+0xa7/0xcb
? trace_irq_disable_rcuidle+0x5/0x6c
__jump_label_update+0x3e/0x6d
jump_label_update+0x7d/0x81
static_key_slow_inc_cpuslocked+0x58/0x6d
static_key_slow_inc+0x19/0x20
tracepoint_probe_register_prio+0x19e/0x1d1
? start_critical_timings+0x1c/0x1c
tracepoint_probe_register+0xf/0x11
irqsoff_tracer_init+0x21/0xf2
tracer_init+0x16/0x1a
trace_selftest_startup_irqsoff+0x25/0xc4
run_tracer_selftest+0xca/0x131
register_tracer+0xd5/0x172
? trace_event_define_fields_preemptirq_template+0x45/0x45
init_irqsoff_tracer+0xd/0x11
do_one_initcall+0xab/0x1e8
? rcu_read_lock_sched_held+0x3d/0x44
? trace_initcall_level+0x52/0x86
kernel_init_freeable+0x195/0x21a
? rest_init+0xb4/0xb4
kernel_init+0xd/0xe4
ret_from_fork+0x2e/0x38
It is due to running a CONFIG_PREEMPT_VOLUNTARY kernel, which would trigger
this warning every time:
WARN_ON_ONCE(preempt_count());
Because on CONFIG_PREEMPT_VOLUNTARY, preempt_count() is always zero.
This warning is to make sure preempt_count is set because
tracer_hardirqs_on() does a preempt_enable_notrace() to make the
preempt_trace() work properly, as being called by a trace event, the trace
event code disables preemption, and the tracer wants to know what the
preemption was before it was called.
Instead of enabling preemption like this, just record the preempt_count,
subtract PREEMPT_DISABLE_OFFSET from it (which is zero with !CONFIG_PREEMPT
set), and pass that value to the necessary functions, which should use the
passed in parameter instead of calling preempt_count() directly.
Fixes: da5b3ebb45277 ("tracing: irqsoff: Account for additional preempt_disable")
Signed-off-by: Steven Rostedt (VMware) <rostedt@goodmis.org>
2018-08-08 04:03:12 +07:00
|
|
|
preempt_trace(int pc)
|
2008-05-13 02:20:42 +07:00
|
|
|
{
|
tracing/irqsoff: Handle preempt_count for different configs
I was hitting the following warning:
WARNING: CPU: 0 PID: 1 at kernel/trace/trace_irqsoff.c:631 tracer_hardirqs_off+0x15/0x2a
Modules linked in:
CPU: 0 PID: 1 Comm: swapper/0 Not tainted 4.18.0-rc6-test+ #13
Hardware name: MSI MS-7823/CSM-H87M-G43 (MS-7823), BIOS V1.6 02/22/2014
EIP: tracer_hardirqs_off+0x15/0x2a
Code: ff 85 c0 74 0e 8b 45 00 8b 50 04 8b 45 04 e8 35 ff ff ff 5d c3 55 64 a1 cc 37 51 c1 a9 ff ff ff 7f 89 e5 53 89 d3 89 ca 75 02 <0f> 0b e8 90 fc ff ff 85 c0 74 07 89 d8 e8 0c ff ff ff 5b 5d c3 55
EAX: 80000000 EBX: c04337f0 ECX: c04338e3 EDX: c04338e3
ESI: c04337f0 EDI: c04338e3 EBP: f2aa1d68 ESP: f2aa1d64
DS: 007b ES: 007b FS: 00d8 GS: 00e0 SS: 0068 EFLAGS: 00210046
CR0: 80050033 CR2: 00000000 CR3: 01668000 CR4: 001406f0
Call Trace:
trace_irq_disable_rcuidle+0x63/0x6c
trace_hardirqs_off+0x26/0x30
default_send_IPI_mask_allbutself_logical+0x31/0x93
default_send_IPI_allbutself+0x37/0x48
native_send_call_func_ipi+0x4d/0x6a
smp_call_function_many+0x165/0x19d
? add_nops+0x34/0x34
? trace_hardirqs_on_caller+0x2d/0x2d
? add_nops+0x34/0x34
smp_call_function+0x1f/0x23
on_each_cpu+0x15/0x43
? trace_hardirqs_on_caller+0x2d/0x2d
? trace_hardirqs_on_caller+0x2d/0x2d
? trace_irq_disable_rcuidle+0x1/0x6c
text_poke_bp+0xa0/0xc2
? trace_hardirqs_on_caller+0x2d/0x2d
arch_jump_label_transform+0xa7/0xcb
? trace_irq_disable_rcuidle+0x5/0x6c
__jump_label_update+0x3e/0x6d
jump_label_update+0x7d/0x81
static_key_slow_inc_cpuslocked+0x58/0x6d
static_key_slow_inc+0x19/0x20
tracepoint_probe_register_prio+0x19e/0x1d1
? start_critical_timings+0x1c/0x1c
tracepoint_probe_register+0xf/0x11
irqsoff_tracer_init+0x21/0xf2
tracer_init+0x16/0x1a
trace_selftest_startup_irqsoff+0x25/0xc4
run_tracer_selftest+0xca/0x131
register_tracer+0xd5/0x172
? trace_event_define_fields_preemptirq_template+0x45/0x45
init_irqsoff_tracer+0xd/0x11
do_one_initcall+0xab/0x1e8
? rcu_read_lock_sched_held+0x3d/0x44
? trace_initcall_level+0x52/0x86
kernel_init_freeable+0x195/0x21a
? rest_init+0xb4/0xb4
kernel_init+0xd/0xe4
ret_from_fork+0x2e/0x38
It is due to running a CONFIG_PREEMPT_VOLUNTARY kernel, which would trigger
this warning every time:
WARN_ON_ONCE(preempt_count());
Because on CONFIG_PREEMPT_VOLUNTARY, preempt_count() is always zero.
This warning is to make sure preempt_count is set because
tracer_hardirqs_on() does a preempt_enable_notrace() to make the
preempt_trace() work properly, as being called by a trace event, the trace
event code disables preemption, and the tracer wants to know what the
preemption was before it was called.
Instead of enabling preemption like this, just record the preempt_count,
subtract PREEMPT_DISABLE_OFFSET from it (which is zero with !CONFIG_PREEMPT
set), and pass that value to the necessary functions, which should use the
passed in parameter instead of calling preempt_count() directly.
Fixes: da5b3ebb45277 ("tracing: irqsoff: Account for additional preempt_disable")
Signed-off-by: Steven Rostedt (VMware) <rostedt@goodmis.org>
2018-08-08 04:03:12 +07:00
|
|
|
return ((trace_type & TRACER_PREEMPT_OFF) && pc);
|
2008-05-13 02:20:42 +07:00
|
|
|
}
|
|
|
|
#else
|
tracing/irqsoff: Handle preempt_count for different configs
I was hitting the following warning:
WARNING: CPU: 0 PID: 1 at kernel/trace/trace_irqsoff.c:631 tracer_hardirqs_off+0x15/0x2a
Modules linked in:
CPU: 0 PID: 1 Comm: swapper/0 Not tainted 4.18.0-rc6-test+ #13
Hardware name: MSI MS-7823/CSM-H87M-G43 (MS-7823), BIOS V1.6 02/22/2014
EIP: tracer_hardirqs_off+0x15/0x2a
Code: ff 85 c0 74 0e 8b 45 00 8b 50 04 8b 45 04 e8 35 ff ff ff 5d c3 55 64 a1 cc 37 51 c1 a9 ff ff ff 7f 89 e5 53 89 d3 89 ca 75 02 <0f> 0b e8 90 fc ff ff 85 c0 74 07 89 d8 e8 0c ff ff ff 5b 5d c3 55
EAX: 80000000 EBX: c04337f0 ECX: c04338e3 EDX: c04338e3
ESI: c04337f0 EDI: c04338e3 EBP: f2aa1d68 ESP: f2aa1d64
DS: 007b ES: 007b FS: 00d8 GS: 00e0 SS: 0068 EFLAGS: 00210046
CR0: 80050033 CR2: 00000000 CR3: 01668000 CR4: 001406f0
Call Trace:
trace_irq_disable_rcuidle+0x63/0x6c
trace_hardirqs_off+0x26/0x30
default_send_IPI_mask_allbutself_logical+0x31/0x93
default_send_IPI_allbutself+0x37/0x48
native_send_call_func_ipi+0x4d/0x6a
smp_call_function_many+0x165/0x19d
? add_nops+0x34/0x34
? trace_hardirqs_on_caller+0x2d/0x2d
? add_nops+0x34/0x34
smp_call_function+0x1f/0x23
on_each_cpu+0x15/0x43
? trace_hardirqs_on_caller+0x2d/0x2d
? trace_hardirqs_on_caller+0x2d/0x2d
? trace_irq_disable_rcuidle+0x1/0x6c
text_poke_bp+0xa0/0xc2
? trace_hardirqs_on_caller+0x2d/0x2d
arch_jump_label_transform+0xa7/0xcb
? trace_irq_disable_rcuidle+0x5/0x6c
__jump_label_update+0x3e/0x6d
jump_label_update+0x7d/0x81
static_key_slow_inc_cpuslocked+0x58/0x6d
static_key_slow_inc+0x19/0x20
tracepoint_probe_register_prio+0x19e/0x1d1
? start_critical_timings+0x1c/0x1c
tracepoint_probe_register+0xf/0x11
irqsoff_tracer_init+0x21/0xf2
tracer_init+0x16/0x1a
trace_selftest_startup_irqsoff+0x25/0xc4
run_tracer_selftest+0xca/0x131
register_tracer+0xd5/0x172
? trace_event_define_fields_preemptirq_template+0x45/0x45
init_irqsoff_tracer+0xd/0x11
do_one_initcall+0xab/0x1e8
? rcu_read_lock_sched_held+0x3d/0x44
? trace_initcall_level+0x52/0x86
kernel_init_freeable+0x195/0x21a
? rest_init+0xb4/0xb4
kernel_init+0xd/0xe4
ret_from_fork+0x2e/0x38
It is due to running a CONFIG_PREEMPT_VOLUNTARY kernel, which would trigger
this warning every time:
WARN_ON_ONCE(preempt_count());
Because on CONFIG_PREEMPT_VOLUNTARY, preempt_count() is always zero.
This warning is to make sure preempt_count is set because
tracer_hardirqs_on() does a preempt_enable_notrace() to make the
preempt_trace() work properly, as being called by a trace event, the trace
event code disables preemption, and the tracer wants to know what the
preemption was before it was called.
Instead of enabling preemption like this, just record the preempt_count,
subtract PREEMPT_DISABLE_OFFSET from it (which is zero with !CONFIG_PREEMPT
set), and pass that value to the necessary functions, which should use the
passed in parameter instead of calling preempt_count() directly.
Fixes: da5b3ebb45277 ("tracing: irqsoff: Account for additional preempt_disable")
Signed-off-by: Steven Rostedt (VMware) <rostedt@goodmis.org>
2018-08-08 04:03:12 +07:00
|
|
|
# define preempt_trace(pc) (0)
|
2008-05-13 02:20:42 +07:00
|
|
|
#endif
|
|
|
|
|
|
|
|
#ifdef CONFIG_IRQSOFF_TRACER
|
2008-05-13 02:20:51 +07:00
|
|
|
static inline int
|
2008-05-13 02:20:42 +07:00
|
|
|
irq_trace(void)
|
|
|
|
{
|
|
|
|
return ((trace_type & TRACER_IRQS_OFF) &&
|
|
|
|
irqs_disabled());
|
|
|
|
}
|
|
|
|
#else
|
|
|
|
# define irq_trace() (0)
|
|
|
|
#endif
|
|
|
|
|
2010-04-03 00:01:22 +07:00
|
|
|
#ifdef CONFIG_FUNCTION_GRAPH_TRACER
|
2015-09-29 02:37:49 +07:00
|
|
|
static int irqsoff_display_graph(struct trace_array *tr, int set);
|
2015-09-30 20:42:05 +07:00
|
|
|
# define is_graph(tr) ((tr)->trace_flags & TRACE_ITER_DISPLAY_GRAPH)
|
2015-09-29 02:37:49 +07:00
|
|
|
#else
|
|
|
|
static inline int irqsoff_display_graph(struct trace_array *tr, int set)
|
|
|
|
{
|
|
|
|
return -EINVAL;
|
|
|
|
}
|
2015-09-30 20:42:05 +07:00
|
|
|
# define is_graph(tr) false
|
2010-04-03 00:01:22 +07:00
|
|
|
#endif
|
|
|
|
|
2008-05-13 02:20:42 +07:00
|
|
|
/*
|
|
|
|
* Sequence count - we record it when starting a measurement and
|
|
|
|
* skip the latency if the sequence has changed - some other section
|
|
|
|
* did a maximum and could disturb our measurement with serial console
|
|
|
|
* printouts, etc. Truly coinciding maximum latencies should be rare
|
2011-03-31 08:57:33 +07:00
|
|
|
* and what happens together happens separately as well, so this doesn't
|
2008-05-13 02:20:42 +07:00
|
|
|
* decrease the validity of the maximum found:
|
|
|
|
*/
|
|
|
|
static __cacheline_aligned_in_smp unsigned long max_sequence;
|
|
|
|
|
2008-10-07 06:06:12 +07:00
|
|
|
#ifdef CONFIG_FUNCTION_TRACER
|
2008-05-13 02:20:42 +07:00
|
|
|
/*
|
2010-10-06 06:41:43 +07:00
|
|
|
* Prologue for the preempt and irqs off function tracers.
|
|
|
|
*
|
|
|
|
* Returns 1 if it is OK to continue, and data->disabled is
|
|
|
|
* incremented.
|
|
|
|
* 0 if the trace is to be ignored, and data->disabled
|
|
|
|
* is kept the same.
|
|
|
|
*
|
|
|
|
* Note, this function is also used outside this ifdef but
|
|
|
|
* inside the #ifdef of the function graph tracer below.
|
|
|
|
* This is OK, since the function graph tracer is
|
|
|
|
* dependent on the function tracer.
|
2008-05-13 02:20:42 +07:00
|
|
|
*/
|
2010-10-06 06:41:43 +07:00
|
|
|
static int func_prolog_dec(struct trace_array *tr,
|
|
|
|
struct trace_array_cpu **data,
|
|
|
|
unsigned long *flags)
|
2008-05-13 02:20:42 +07:00
|
|
|
{
|
|
|
|
long disabled;
|
|
|
|
int cpu;
|
|
|
|
|
2008-05-13 02:20:44 +07:00
|
|
|
/*
|
|
|
|
* Does not matter if we preempt. We test the flags
|
|
|
|
* afterward, to see if irqs are disabled or not.
|
|
|
|
* If we preempt and get a false positive, the flags
|
|
|
|
* test will fail.
|
|
|
|
*/
|
|
|
|
cpu = raw_smp_processor_id();
|
|
|
|
if (likely(!per_cpu(tracing_cpu, cpu)))
|
2010-10-06 06:41:43 +07:00
|
|
|
return 0;
|
2008-05-13 02:20:42 +07:00
|
|
|
|
2010-10-06 06:41:43 +07:00
|
|
|
local_save_flags(*flags);
|
2016-03-18 23:27:43 +07:00
|
|
|
/*
|
|
|
|
* Slight chance to get a false positive on tracing_cpu,
|
|
|
|
* although I'm starting to think there isn't a chance.
|
|
|
|
* Leave this for now just to be paranoid.
|
|
|
|
*/
|
|
|
|
if (!irqs_disabled_flags(*flags) && !preempt_count())
|
2010-10-06 06:41:43 +07:00
|
|
|
return 0;
|
2008-05-13 02:20:42 +07:00
|
|
|
|
tracing: Consolidate max_tr into main trace_array structure
Currently, the way the latency tracers and snapshot feature works
is to have a separate trace_array called "max_tr" that holds the
snapshot buffer. For latency tracers, this snapshot buffer is used
to swap the running buffer with this buffer to save the current max
latency.
The only items needed for the max_tr is really just a copy of the buffer
itself, the per_cpu data pointers, the time_start timestamp that states
when the max latency was triggered, and the cpu that the max latency
was triggered on. All other fields in trace_array are unused by the
max_tr, making the max_tr mostly bloat.
This change removes the max_tr completely, and adds a new structure
called trace_buffer, that holds the buffer pointer, the per_cpu data
pointers, the time_start timestamp, and the cpu where the latency occurred.
The trace_array, now has two trace_buffers, one for the normal trace and
one for the max trace or snapshot. By doing this, not only do we remove
the bloat from the max_trace but the instances of traces can now use
their own snapshot feature and not have just the top level global_trace have
the snapshot feature and latency tracers for itself.
Signed-off-by: Steven Rostedt <rostedt@goodmis.org>
2013-03-05 21:24:35 +07:00
|
|
|
*data = per_cpu_ptr(tr->trace_buffer.data, cpu);
|
2010-10-06 06:41:43 +07:00
|
|
|
disabled = atomic_inc_return(&(*data)->disabled);
|
2008-05-13 02:20:42 +07:00
|
|
|
|
|
|
|
if (likely(disabled == 1))
|
2010-10-06 06:41:43 +07:00
|
|
|
return 1;
|
|
|
|
|
|
|
|
atomic_dec(&(*data)->disabled);
|
|
|
|
|
|
|
|
return 0;
|
|
|
|
}
|
|
|
|
|
|
|
|
/*
|
|
|
|
* irqsoff uses its own tracer function to keep the overhead down:
|
|
|
|
*/
|
|
|
|
static void
|
2011-08-09 03:57:47 +07:00
|
|
|
irqsoff_tracer_call(unsigned long ip, unsigned long parent_ip,
|
2011-08-09 23:50:46 +07:00
|
|
|
struct ftrace_ops *op, struct pt_regs *pt_regs)
|
2010-10-06 06:41:43 +07:00
|
|
|
{
|
|
|
|
struct trace_array *tr = irqsoff_trace;
|
|
|
|
struct trace_array_cpu *data;
|
|
|
|
unsigned long flags;
|
|
|
|
|
|
|
|
if (!func_prolog_dec(tr, &data, &flags))
|
|
|
|
return;
|
|
|
|
|
|
|
|
trace_function(tr, ip, parent_ip, flags, preempt_count());
|
2008-05-13 02:20:42 +07:00
|
|
|
|
|
|
|
atomic_dec(&data->disabled);
|
|
|
|
}
|
2008-10-07 06:06:12 +07:00
|
|
|
#endif /* CONFIG_FUNCTION_TRACER */
|
2008-05-13 02:20:42 +07:00
|
|
|
|
2010-04-03 00:01:22 +07:00
|
|
|
#ifdef CONFIG_FUNCTION_GRAPH_TRACER
|
2015-09-29 02:37:49 +07:00
|
|
|
static int irqsoff_display_graph(struct trace_array *tr, int set)
|
2010-04-03 00:01:22 +07:00
|
|
|
{
|
|
|
|
int cpu;
|
|
|
|
|
2015-09-30 20:42:05 +07:00
|
|
|
if (!(is_graph(tr) ^ set))
|
2010-04-03 00:01:22 +07:00
|
|
|
return 0;
|
|
|
|
|
|
|
|
stop_irqsoff_tracer(irqsoff_trace, !set);
|
|
|
|
|
|
|
|
for_each_possible_cpu(cpu)
|
|
|
|
per_cpu(tracing_cpu, cpu) = 0;
|
|
|
|
|
2014-01-14 23:28:38 +07:00
|
|
|
tr->max_latency = 0;
|
tracing: Consolidate max_tr into main trace_array structure
Currently, the way the latency tracers and snapshot feature works
is to have a separate trace_array called "max_tr" that holds the
snapshot buffer. For latency tracers, this snapshot buffer is used
to swap the running buffer with this buffer to save the current max
latency.
The only items needed for the max_tr is really just a copy of the buffer
itself, the per_cpu data pointers, the time_start timestamp that states
when the max latency was triggered, and the cpu that the max latency
was triggered on. All other fields in trace_array are unused by the
max_tr, making the max_tr mostly bloat.
This change removes the max_tr completely, and adds a new structure
called trace_buffer, that holds the buffer pointer, the per_cpu data
pointers, the time_start timestamp, and the cpu where the latency occurred.
The trace_array, now has two trace_buffers, one for the normal trace and
one for the max trace or snapshot. By doing this, not only do we remove
the bloat from the max_trace but the instances of traces can now use
their own snapshot feature and not have just the top level global_trace have
the snapshot feature and latency tracers for itself.
Signed-off-by: Steven Rostedt <rostedt@goodmis.org>
2013-03-05 21:24:35 +07:00
|
|
|
tracing_reset_online_cpus(&irqsoff_trace->trace_buffer);
|
2010-04-03 00:01:22 +07:00
|
|
|
|
|
|
|
return start_irqsoff_tracer(irqsoff_trace, set);
|
|
|
|
}
|
|
|
|
|
|
|
|
static int irqsoff_graph_entry(struct ftrace_graph_ent *trace)
|
|
|
|
{
|
|
|
|
struct trace_array *tr = irqsoff_trace;
|
|
|
|
struct trace_array_cpu *data;
|
|
|
|
unsigned long flags;
|
|
|
|
int ret;
|
|
|
|
int pc;
|
|
|
|
|
2016-12-09 07:28:28 +07:00
|
|
|
if (ftrace_graph_ignore_func(trace))
|
|
|
|
return 0;
|
|
|
|
/*
|
|
|
|
* Do not trace a function if it's filtered by set_graph_notrace.
|
|
|
|
* Make the index of ret stack negative to indicate that it should
|
|
|
|
* ignore further functions. But it needs its own ret stack entry
|
|
|
|
* to recover the original index in order to continue tracing after
|
|
|
|
* returning from the function.
|
|
|
|
*/
|
|
|
|
if (ftrace_graph_notrace_addr(trace->func))
|
|
|
|
return 1;
|
|
|
|
|
2010-10-06 06:41:43 +07:00
|
|
|
if (!func_prolog_dec(tr, &data, &flags))
|
2010-04-03 00:01:22 +07:00
|
|
|
return 0;
|
|
|
|
|
2010-10-06 06:41:43 +07:00
|
|
|
pc = preempt_count();
|
|
|
|
ret = __trace_graph_entry(tr, trace, flags, pc);
|
2010-04-03 00:01:22 +07:00
|
|
|
atomic_dec(&data->disabled);
|
2010-10-06 06:41:43 +07:00
|
|
|
|
2010-04-03 00:01:22 +07:00
|
|
|
return ret;
|
|
|
|
}
|
|
|
|
|
|
|
|
static void irqsoff_graph_return(struct ftrace_graph_ret *trace)
|
|
|
|
{
|
|
|
|
struct trace_array *tr = irqsoff_trace;
|
|
|
|
struct trace_array_cpu *data;
|
|
|
|
unsigned long flags;
|
|
|
|
int pc;
|
|
|
|
|
2010-10-06 06:41:43 +07:00
|
|
|
if (!func_prolog_dec(tr, &data, &flags))
|
2010-04-03 00:01:22 +07:00
|
|
|
return;
|
|
|
|
|
2010-10-06 06:41:43 +07:00
|
|
|
pc = preempt_count();
|
|
|
|
__trace_graph_return(tr, trace, flags, pc);
|
2010-04-03 00:01:22 +07:00
|
|
|
atomic_dec(&data->disabled);
|
|
|
|
}
|
|
|
|
|
|
|
|
static void irqsoff_trace_open(struct trace_iterator *iter)
|
|
|
|
{
|
2015-09-30 20:42:05 +07:00
|
|
|
if (is_graph(iter->tr))
|
2010-04-03 00:01:22 +07:00
|
|
|
graph_trace_open(iter);
|
|
|
|
|
|
|
|
}
|
|
|
|
|
|
|
|
static void irqsoff_trace_close(struct trace_iterator *iter)
|
|
|
|
{
|
|
|
|
if (iter->private)
|
|
|
|
graph_trace_close(iter);
|
|
|
|
}
|
|
|
|
|
|
|
|
#define GRAPH_TRACER_FLAGS (TRACE_GRAPH_PRINT_CPU | \
|
2011-06-03 21:58:47 +07:00
|
|
|
TRACE_GRAPH_PRINT_PROC | \
|
|
|
|
TRACE_GRAPH_PRINT_ABS_TIME | \
|
|
|
|
TRACE_GRAPH_PRINT_DURATION)
|
2010-04-03 00:01:22 +07:00
|
|
|
|
|
|
|
static enum print_line_t irqsoff_print_line(struct trace_iterator *iter)
|
|
|
|
{
|
|
|
|
/*
|
|
|
|
* In graph mode call the graph tracer output function,
|
|
|
|
* otherwise go with the TRACE_FN event handler
|
|
|
|
*/
|
2015-09-30 20:42:05 +07:00
|
|
|
if (is_graph(iter->tr))
|
2010-09-23 19:00:52 +07:00
|
|
|
return print_graph_function_flags(iter, GRAPH_TRACER_FLAGS);
|
2010-04-03 00:01:22 +07:00
|
|
|
|
|
|
|
return TRACE_TYPE_UNHANDLED;
|
|
|
|
}
|
|
|
|
|
|
|
|
static void irqsoff_print_header(struct seq_file *s)
|
|
|
|
{
|
2015-09-30 20:42:05 +07:00
|
|
|
struct trace_array *tr = irqsoff_trace;
|
|
|
|
|
|
|
|
if (is_graph(tr))
|
2010-09-23 19:00:52 +07:00
|
|
|
print_graph_headers_flags(s, GRAPH_TRACER_FLAGS);
|
|
|
|
else
|
2010-04-03 00:01:22 +07:00
|
|
|
trace_default_header(s);
|
|
|
|
}
|
|
|
|
|
|
|
|
static void
|
|
|
|
__trace_function(struct trace_array *tr,
|
|
|
|
unsigned long ip, unsigned long parent_ip,
|
|
|
|
unsigned long flags, int pc)
|
|
|
|
{
|
2015-09-30 20:42:05 +07:00
|
|
|
if (is_graph(tr))
|
2010-09-23 19:00:52 +07:00
|
|
|
trace_graph_function(tr, ip, parent_ip, flags, pc);
|
|
|
|
else
|
2010-04-03 00:01:22 +07:00
|
|
|
trace_function(tr, ip, parent_ip, flags, pc);
|
|
|
|
}
|
|
|
|
|
|
|
|
#else
|
|
|
|
#define __trace_function trace_function
|
|
|
|
|
2015-09-29 21:24:56 +07:00
|
|
|
#ifdef CONFIG_FUNCTION_TRACER
|
2010-04-03 00:01:22 +07:00
|
|
|
static int irqsoff_graph_entry(struct ftrace_graph_ent *trace)
|
|
|
|
{
|
|
|
|
return -1;
|
|
|
|
}
|
2015-09-29 21:24:56 +07:00
|
|
|
#endif
|
2010-04-03 00:01:22 +07:00
|
|
|
|
|
|
|
static enum print_line_t irqsoff_print_line(struct trace_iterator *iter)
|
|
|
|
{
|
|
|
|
return TRACE_TYPE_UNHANDLED;
|
|
|
|
}
|
|
|
|
|
|
|
|
static void irqsoff_trace_open(struct trace_iterator *iter) { }
|
|
|
|
static void irqsoff_trace_close(struct trace_iterator *iter) { }
|
tracing/latency: Fix header output for latency tracers
In case the the graph tracer (CONFIG_FUNCTION_GRAPH_TRACER) or even the
function tracer (CONFIG_FUNCTION_TRACER) are not set, the latency tracers
do not display proper latency header.
The involved/fixed latency tracers are:
wakeup_rt
wakeup
preemptirqsoff
preemptoff
irqsoff
The patch adds proper handling of tracer configuration options for latency
tracers, and displaying correct header info accordingly.
* The current output (for wakeup tracer) with both graph and function
tracers disabled is:
# tracer: wakeup
#
<idle>-0 0d.h5 1us+: 0:120:R + [000] 7: 0:R watchdog/0
<idle>-0 0d.h5 3us+: ttwu_do_activate.clone.1 <-try_to_wake_up
...
* The fixed output is:
# tracer: wakeup
#
# wakeup latency trace v1.1.5 on 3.1.0-tip+
# --------------------------------------------------------------------
# latency: 55 us, #4/4, CPU#0 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:2)
# -----------------
# | task: migration/0-6 (uid:0 nice:0 policy:1 rt_prio:99)
# -----------------
#
# _------=> CPU#
# / _-----=> irqs-off
# | / _----=> need-resched
# || / _---=> hardirq/softirq
# ||| / _--=> preempt-depth
# |||| / delay
# cmd pid ||||| time | caller
# \ / ||||| \ | /
cat-1129 0d..4 1us : 1129:120:R + [000] 6: 0:R migration/0
cat-1129 0d..4 2us+: ttwu_do_activate.clone.1 <-try_to_wake_up
* The current output (for wakeup tracer) with only function
tracer enabled is:
# tracer: wakeup
#
cat-1140 0d..4 1us+: 1140:120:R + [000] 6: 0:R migration/0
cat-1140 0d..4 2us : ttwu_do_activate.clone.1 <-try_to_wake_up
* The fixed output is:
# tracer: wakeup
#
# wakeup latency trace v1.1.5 on 3.1.0-tip+
# --------------------------------------------------------------------
# latency: 207 us, #109/109, CPU#1 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:2)
# -----------------
# | task: watchdog/1-12 (uid:0 nice:0 policy:1 rt_prio:99)
# -----------------
#
# _------=> CPU#
# / _-----=> irqs-off
# | / _----=> need-resched
# || / _---=> hardirq/softirq
# ||| / _--=> preempt-depth
# |||| / delay
# cmd pid ||||| time | caller
# \ / ||||| \ | /
<idle>-0 1d.h5 1us+: 0:120:R + [001] 12: 0:R watchdog/1
<idle>-0 1d.h5 3us : ttwu_do_activate.clone.1 <-try_to_wake_up
Link: http://lkml.kernel.org/r/20111107150849.GE1807@m.brq.redhat.com
Cc: Frederic Weisbecker <fweisbec@gmail.com>
Cc: Ingo Molnar <mingo@redhat.com>
Signed-off-by: Jiri Olsa <jolsa@redhat.com>
Signed-off-by: Steven Rostedt <rostedt@goodmis.org>
2011-11-07 22:08:49 +07:00
|
|
|
|
|
|
|
#ifdef CONFIG_FUNCTION_TRACER
|
2015-09-29 21:24:56 +07:00
|
|
|
static void irqsoff_graph_return(struct ftrace_graph_ret *trace) { }
|
tracing/latency: Fix header output for latency tracers
In case the the graph tracer (CONFIG_FUNCTION_GRAPH_TRACER) or even the
function tracer (CONFIG_FUNCTION_TRACER) are not set, the latency tracers
do not display proper latency header.
The involved/fixed latency tracers are:
wakeup_rt
wakeup
preemptirqsoff
preemptoff
irqsoff
The patch adds proper handling of tracer configuration options for latency
tracers, and displaying correct header info accordingly.
* The current output (for wakeup tracer) with both graph and function
tracers disabled is:
# tracer: wakeup
#
<idle>-0 0d.h5 1us+: 0:120:R + [000] 7: 0:R watchdog/0
<idle>-0 0d.h5 3us+: ttwu_do_activate.clone.1 <-try_to_wake_up
...
* The fixed output is:
# tracer: wakeup
#
# wakeup latency trace v1.1.5 on 3.1.0-tip+
# --------------------------------------------------------------------
# latency: 55 us, #4/4, CPU#0 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:2)
# -----------------
# | task: migration/0-6 (uid:0 nice:0 policy:1 rt_prio:99)
# -----------------
#
# _------=> CPU#
# / _-----=> irqs-off
# | / _----=> need-resched
# || / _---=> hardirq/softirq
# ||| / _--=> preempt-depth
# |||| / delay
# cmd pid ||||| time | caller
# \ / ||||| \ | /
cat-1129 0d..4 1us : 1129:120:R + [000] 6: 0:R migration/0
cat-1129 0d..4 2us+: ttwu_do_activate.clone.1 <-try_to_wake_up
* The current output (for wakeup tracer) with only function
tracer enabled is:
# tracer: wakeup
#
cat-1140 0d..4 1us+: 1140:120:R + [000] 6: 0:R migration/0
cat-1140 0d..4 2us : ttwu_do_activate.clone.1 <-try_to_wake_up
* The fixed output is:
# tracer: wakeup
#
# wakeup latency trace v1.1.5 on 3.1.0-tip+
# --------------------------------------------------------------------
# latency: 207 us, #109/109, CPU#1 | (M:preempt VP:0, KP:0, SP:0 HP:0 #P:2)
# -----------------
# | task: watchdog/1-12 (uid:0 nice:0 policy:1 rt_prio:99)
# -----------------
#
# _------=> CPU#
# / _-----=> irqs-off
# | / _----=> need-resched
# || / _---=> hardirq/softirq
# ||| / _--=> preempt-depth
# |||| / delay
# cmd pid ||||| time | caller
# \ / ||||| \ | /
<idle>-0 1d.h5 1us+: 0:120:R + [001] 12: 0:R watchdog/1
<idle>-0 1d.h5 3us : ttwu_do_activate.clone.1 <-try_to_wake_up
Link: http://lkml.kernel.org/r/20111107150849.GE1807@m.brq.redhat.com
Cc: Frederic Weisbecker <fweisbec@gmail.com>
Cc: Ingo Molnar <mingo@redhat.com>
Signed-off-by: Jiri Olsa <jolsa@redhat.com>
Signed-off-by: Steven Rostedt <rostedt@goodmis.org>
2011-11-07 22:08:49 +07:00
|
|
|
static void irqsoff_print_header(struct seq_file *s)
|
|
|
|
{
|
|
|
|
trace_default_header(s);
|
|
|
|
}
|
|
|
|
#else
|
|
|
|
static void irqsoff_print_header(struct seq_file *s)
|
|
|
|
{
|
|
|
|
trace_latency_header(s);
|
|
|
|
}
|
|
|
|
#endif /* CONFIG_FUNCTION_TRACER */
|
2010-04-03 00:01:22 +07:00
|
|
|
#endif /* CONFIG_FUNCTION_GRAPH_TRACER */
|
|
|
|
|
2008-05-13 02:20:42 +07:00
|
|
|
/*
|
|
|
|
* Should this new latency be reported/recorded?
|
|
|
|
*/
|
2016-12-22 02:32:01 +07:00
|
|
|
static bool report_latency(struct trace_array *tr, u64 delta)
|
2008-05-13 02:20:42 +07:00
|
|
|
{
|
|
|
|
if (tracing_thresh) {
|
|
|
|
if (delta < tracing_thresh)
|
2015-09-29 21:43:30 +07:00
|
|
|
return false;
|
2008-05-13 02:20:42 +07:00
|
|
|
} else {
|
2014-01-14 23:28:38 +07:00
|
|
|
if (delta <= tr->max_latency)
|
2015-09-29 21:43:30 +07:00
|
|
|
return false;
|
2008-05-13 02:20:42 +07:00
|
|
|
}
|
2015-09-29 21:43:30 +07:00
|
|
|
return true;
|
2008-05-13 02:20:42 +07:00
|
|
|
}
|
|
|
|
|
2008-05-13 02:20:51 +07:00
|
|
|
static void
|
2008-05-13 02:20:42 +07:00
|
|
|
check_critical_timing(struct trace_array *tr,
|
|
|
|
struct trace_array_cpu *data,
|
|
|
|
unsigned long parent_ip,
|
|
|
|
int cpu)
|
|
|
|
{
|
2016-12-22 02:32:01 +07:00
|
|
|
u64 T0, T1, delta;
|
2008-05-13 02:20:42 +07:00
|
|
|
unsigned long flags;
|
2008-10-02 00:14:09 +07:00
|
|
|
int pc;
|
2008-05-13 02:20:42 +07:00
|
|
|
|
|
|
|
T0 = data->preempt_timestamp;
|
2008-05-13 02:20:46 +07:00
|
|
|
T1 = ftrace_now(cpu);
|
2008-05-13 02:20:42 +07:00
|
|
|
delta = T1-T0;
|
|
|
|
|
|
|
|
local_save_flags(flags);
|
|
|
|
|
2008-10-03 06:23:04 +07:00
|
|
|
pc = preempt_count();
|
|
|
|
|
2014-01-14 23:28:38 +07:00
|
|
|
if (!report_latency(tr, delta))
|
2008-05-13 02:20:42 +07:00
|
|
|
goto out;
|
|
|
|
|
2009-07-25 22:13:33 +07:00
|
|
|
raw_spin_lock_irqsave(&max_trace_lock, flags);
|
2008-05-13 02:20:42 +07:00
|
|
|
|
2008-05-13 02:20:44 +07:00
|
|
|
/* check if we are still the max latency */
|
2014-01-14 23:28:38 +07:00
|
|
|
if (!report_latency(tr, delta))
|
2008-05-13 02:20:44 +07:00
|
|
|
goto out_unlock;
|
|
|
|
|
2010-04-03 00:01:22 +07:00
|
|
|
__trace_function(tr, CALLER_ADDR0, parent_ip, flags, pc);
|
2009-12-11 23:54:51 +07:00
|
|
|
/* Skip 5 functions to get to the irq/preempt enable function */
|
|
|
|
__trace_stack(tr, flags, 5, pc);
|
2008-05-13 02:20:42 +07:00
|
|
|
|
|
|
|
if (data->critical_sequence != max_sequence)
|
2008-05-13 02:20:44 +07:00
|
|
|
goto out_unlock;
|
2008-05-13 02:20:42 +07:00
|
|
|
|
|
|
|
data->critical_end = parent_ip;
|
|
|
|
|
2009-09-13 06:43:07 +07:00
|
|
|
if (likely(!is_tracing_stopped())) {
|
2014-01-14 23:28:38 +07:00
|
|
|
tr->max_latency = delta;
|
2009-09-13 06:43:07 +07:00
|
|
|
update_max_tr_single(tr, current, cpu);
|
|
|
|
}
|
2008-05-13 02:20:42 +07:00
|
|
|
|
|
|
|
max_sequence++;
|
|
|
|
|
2008-05-13 02:20:44 +07:00
|
|
|
out_unlock:
|
2009-07-25 22:13:33 +07:00
|
|
|
raw_spin_unlock_irqrestore(&max_trace_lock, flags);
|
2008-05-13 02:20:44 +07:00
|
|
|
|
2008-05-13 02:20:42 +07:00
|
|
|
out:
|
|
|
|
data->critical_sequence = max_sequence;
|
2008-05-13 02:20:46 +07:00
|
|
|
data->preempt_timestamp = ftrace_now(cpu);
|
2010-04-03 00:01:22 +07:00
|
|
|
__trace_function(tr, CALLER_ADDR0, parent_ip, flags, pc);
|
2008-05-13 02:20:42 +07:00
|
|
|
}
|
|
|
|
|
2008-05-13 02:20:51 +07:00
|
|
|
static inline void
|
tracing/irqsoff: Handle preempt_count for different configs
I was hitting the following warning:
WARNING: CPU: 0 PID: 1 at kernel/trace/trace_irqsoff.c:631 tracer_hardirqs_off+0x15/0x2a
Modules linked in:
CPU: 0 PID: 1 Comm: swapper/0 Not tainted 4.18.0-rc6-test+ #13
Hardware name: MSI MS-7823/CSM-H87M-G43 (MS-7823), BIOS V1.6 02/22/2014
EIP: tracer_hardirqs_off+0x15/0x2a
Code: ff 85 c0 74 0e 8b 45 00 8b 50 04 8b 45 04 e8 35 ff ff ff 5d c3 55 64 a1 cc 37 51 c1 a9 ff ff ff 7f 89 e5 53 89 d3 89 ca 75 02 <0f> 0b e8 90 fc ff ff 85 c0 74 07 89 d8 e8 0c ff ff ff 5b 5d c3 55
EAX: 80000000 EBX: c04337f0 ECX: c04338e3 EDX: c04338e3
ESI: c04337f0 EDI: c04338e3 EBP: f2aa1d68 ESP: f2aa1d64
DS: 007b ES: 007b FS: 00d8 GS: 00e0 SS: 0068 EFLAGS: 00210046
CR0: 80050033 CR2: 00000000 CR3: 01668000 CR4: 001406f0
Call Trace:
trace_irq_disable_rcuidle+0x63/0x6c
trace_hardirqs_off+0x26/0x30
default_send_IPI_mask_allbutself_logical+0x31/0x93
default_send_IPI_allbutself+0x37/0x48
native_send_call_func_ipi+0x4d/0x6a
smp_call_function_many+0x165/0x19d
? add_nops+0x34/0x34
? trace_hardirqs_on_caller+0x2d/0x2d
? add_nops+0x34/0x34
smp_call_function+0x1f/0x23
on_each_cpu+0x15/0x43
? trace_hardirqs_on_caller+0x2d/0x2d
? trace_hardirqs_on_caller+0x2d/0x2d
? trace_irq_disable_rcuidle+0x1/0x6c
text_poke_bp+0xa0/0xc2
? trace_hardirqs_on_caller+0x2d/0x2d
arch_jump_label_transform+0xa7/0xcb
? trace_irq_disable_rcuidle+0x5/0x6c
__jump_label_update+0x3e/0x6d
jump_label_update+0x7d/0x81
static_key_slow_inc_cpuslocked+0x58/0x6d
static_key_slow_inc+0x19/0x20
tracepoint_probe_register_prio+0x19e/0x1d1
? start_critical_timings+0x1c/0x1c
tracepoint_probe_register+0xf/0x11
irqsoff_tracer_init+0x21/0xf2
tracer_init+0x16/0x1a
trace_selftest_startup_irqsoff+0x25/0xc4
run_tracer_selftest+0xca/0x131
register_tracer+0xd5/0x172
? trace_event_define_fields_preemptirq_template+0x45/0x45
init_irqsoff_tracer+0xd/0x11
do_one_initcall+0xab/0x1e8
? rcu_read_lock_sched_held+0x3d/0x44
? trace_initcall_level+0x52/0x86
kernel_init_freeable+0x195/0x21a
? rest_init+0xb4/0xb4
kernel_init+0xd/0xe4
ret_from_fork+0x2e/0x38
It is due to running a CONFIG_PREEMPT_VOLUNTARY kernel, which would trigger
this warning every time:
WARN_ON_ONCE(preempt_count());
Because on CONFIG_PREEMPT_VOLUNTARY, preempt_count() is always zero.
This warning is to make sure preempt_count is set because
tracer_hardirqs_on() does a preempt_enable_notrace() to make the
preempt_trace() work properly, as being called by a trace event, the trace
event code disables preemption, and the tracer wants to know what the
preemption was before it was called.
Instead of enabling preemption like this, just record the preempt_count,
subtract PREEMPT_DISABLE_OFFSET from it (which is zero with !CONFIG_PREEMPT
set), and pass that value to the necessary functions, which should use the
passed in parameter instead of calling preempt_count() directly.
Fixes: da5b3ebb45277 ("tracing: irqsoff: Account for additional preempt_disable")
Signed-off-by: Steven Rostedt (VMware) <rostedt@goodmis.org>
2018-08-08 04:03:12 +07:00
|
|
|
start_critical_timing(unsigned long ip, unsigned long parent_ip, int pc)
|
2008-05-13 02:20:42 +07:00
|
|
|
{
|
|
|
|
int cpu;
|
|
|
|
struct trace_array *tr = irqsoff_trace;
|
|
|
|
struct trace_array_cpu *data;
|
|
|
|
unsigned long flags;
|
|
|
|
|
2013-07-02 02:58:24 +07:00
|
|
|
if (!tracer_enabled || !tracing_is_enabled())
|
2008-05-13 02:20:42 +07:00
|
|
|
return;
|
|
|
|
|
2008-05-13 02:20:55 +07:00
|
|
|
cpu = raw_smp_processor_id();
|
|
|
|
|
|
|
|
if (per_cpu(tracing_cpu, cpu))
|
2008-05-13 02:20:42 +07:00
|
|
|
return;
|
|
|
|
|
tracing: Consolidate max_tr into main trace_array structure
Currently, the way the latency tracers and snapshot feature works
is to have a separate trace_array called "max_tr" that holds the
snapshot buffer. For latency tracers, this snapshot buffer is used
to swap the running buffer with this buffer to save the current max
latency.
The only items needed for the max_tr is really just a copy of the buffer
itself, the per_cpu data pointers, the time_start timestamp that states
when the max latency was triggered, and the cpu that the max latency
was triggered on. All other fields in trace_array are unused by the
max_tr, making the max_tr mostly bloat.
This change removes the max_tr completely, and adds a new structure
called trace_buffer, that holds the buffer pointer, the per_cpu data
pointers, the time_start timestamp, and the cpu where the latency occurred.
The trace_array, now has two trace_buffers, one for the normal trace and
one for the max trace or snapshot. By doing this, not only do we remove
the bloat from the max_trace but the instances of traces can now use
their own snapshot feature and not have just the top level global_trace have
the snapshot feature and latency tracers for itself.
Signed-off-by: Steven Rostedt <rostedt@goodmis.org>
2013-03-05 21:24:35 +07:00
|
|
|
data = per_cpu_ptr(tr->trace_buffer.data, cpu);
|
2008-05-13 02:20:42 +07:00
|
|
|
|
2008-05-13 02:20:55 +07:00
|
|
|
if (unlikely(!data) || atomic_read(&data->disabled))
|
2008-05-13 02:20:42 +07:00
|
|
|
return;
|
|
|
|
|
|
|
|
atomic_inc(&data->disabled);
|
|
|
|
|
|
|
|
data->critical_sequence = max_sequence;
|
2008-05-13 02:20:46 +07:00
|
|
|
data->preempt_timestamp = ftrace_now(cpu);
|
2008-05-13 02:20:42 +07:00
|
|
|
data->critical_start = parent_ip ? : ip;
|
2008-05-13 02:20:42 +07:00
|
|
|
|
|
|
|
local_save_flags(flags);
|
2008-05-13 02:20:42 +07:00
|
|
|
|
tracing/irqsoff: Handle preempt_count for different configs
I was hitting the following warning:
WARNING: CPU: 0 PID: 1 at kernel/trace/trace_irqsoff.c:631 tracer_hardirqs_off+0x15/0x2a
Modules linked in:
CPU: 0 PID: 1 Comm: swapper/0 Not tainted 4.18.0-rc6-test+ #13
Hardware name: MSI MS-7823/CSM-H87M-G43 (MS-7823), BIOS V1.6 02/22/2014
EIP: tracer_hardirqs_off+0x15/0x2a
Code: ff 85 c0 74 0e 8b 45 00 8b 50 04 8b 45 04 e8 35 ff ff ff 5d c3 55 64 a1 cc 37 51 c1 a9 ff ff ff 7f 89 e5 53 89 d3 89 ca 75 02 <0f> 0b e8 90 fc ff ff 85 c0 74 07 89 d8 e8 0c ff ff ff 5b 5d c3 55
EAX: 80000000 EBX: c04337f0 ECX: c04338e3 EDX: c04338e3
ESI: c04337f0 EDI: c04338e3 EBP: f2aa1d68 ESP: f2aa1d64
DS: 007b ES: 007b FS: 00d8 GS: 00e0 SS: 0068 EFLAGS: 00210046
CR0: 80050033 CR2: 00000000 CR3: 01668000 CR4: 001406f0
Call Trace:
trace_irq_disable_rcuidle+0x63/0x6c
trace_hardirqs_off+0x26/0x30
default_send_IPI_mask_allbutself_logical+0x31/0x93
default_send_IPI_allbutself+0x37/0x48
native_send_call_func_ipi+0x4d/0x6a
smp_call_function_many+0x165/0x19d
? add_nops+0x34/0x34
? trace_hardirqs_on_caller+0x2d/0x2d
? add_nops+0x34/0x34
smp_call_function+0x1f/0x23
on_each_cpu+0x15/0x43
? trace_hardirqs_on_caller+0x2d/0x2d
? trace_hardirqs_on_caller+0x2d/0x2d
? trace_irq_disable_rcuidle+0x1/0x6c
text_poke_bp+0xa0/0xc2
? trace_hardirqs_on_caller+0x2d/0x2d
arch_jump_label_transform+0xa7/0xcb
? trace_irq_disable_rcuidle+0x5/0x6c
__jump_label_update+0x3e/0x6d
jump_label_update+0x7d/0x81
static_key_slow_inc_cpuslocked+0x58/0x6d
static_key_slow_inc+0x19/0x20
tracepoint_probe_register_prio+0x19e/0x1d1
? start_critical_timings+0x1c/0x1c
tracepoint_probe_register+0xf/0x11
irqsoff_tracer_init+0x21/0xf2
tracer_init+0x16/0x1a
trace_selftest_startup_irqsoff+0x25/0xc4
run_tracer_selftest+0xca/0x131
register_tracer+0xd5/0x172
? trace_event_define_fields_preemptirq_template+0x45/0x45
init_irqsoff_tracer+0xd/0x11
do_one_initcall+0xab/0x1e8
? rcu_read_lock_sched_held+0x3d/0x44
? trace_initcall_level+0x52/0x86
kernel_init_freeable+0x195/0x21a
? rest_init+0xb4/0xb4
kernel_init+0xd/0xe4
ret_from_fork+0x2e/0x38
It is due to running a CONFIG_PREEMPT_VOLUNTARY kernel, which would trigger
this warning every time:
WARN_ON_ONCE(preempt_count());
Because on CONFIG_PREEMPT_VOLUNTARY, preempt_count() is always zero.
This warning is to make sure preempt_count is set because
tracer_hardirqs_on() does a preempt_enable_notrace() to make the
preempt_trace() work properly, as being called by a trace event, the trace
event code disables preemption, and the tracer wants to know what the
preemption was before it was called.
Instead of enabling preemption like this, just record the preempt_count,
subtract PREEMPT_DISABLE_OFFSET from it (which is zero with !CONFIG_PREEMPT
set), and pass that value to the necessary functions, which should use the
passed in parameter instead of calling preempt_count() directly.
Fixes: da5b3ebb45277 ("tracing: irqsoff: Account for additional preempt_disable")
Signed-off-by: Steven Rostedt (VMware) <rostedt@goodmis.org>
2018-08-08 04:03:12 +07:00
|
|
|
__trace_function(tr, ip, parent_ip, flags, pc);
|
2008-05-13 02:20:42 +07:00
|
|
|
|
2008-05-13 02:20:55 +07:00
|
|
|
per_cpu(tracing_cpu, cpu) = 1;
|
2008-05-13 02:20:42 +07:00
|
|
|
|
2008-05-13 02:20:42 +07:00
|
|
|
atomic_dec(&data->disabled);
|
|
|
|
}
|
|
|
|
|
2008-05-13 02:20:51 +07:00
|
|
|
static inline void
|
tracing/irqsoff: Handle preempt_count for different configs
I was hitting the following warning:
WARNING: CPU: 0 PID: 1 at kernel/trace/trace_irqsoff.c:631 tracer_hardirqs_off+0x15/0x2a
Modules linked in:
CPU: 0 PID: 1 Comm: swapper/0 Not tainted 4.18.0-rc6-test+ #13
Hardware name: MSI MS-7823/CSM-H87M-G43 (MS-7823), BIOS V1.6 02/22/2014
EIP: tracer_hardirqs_off+0x15/0x2a
Code: ff 85 c0 74 0e 8b 45 00 8b 50 04 8b 45 04 e8 35 ff ff ff 5d c3 55 64 a1 cc 37 51 c1 a9 ff ff ff 7f 89 e5 53 89 d3 89 ca 75 02 <0f> 0b e8 90 fc ff ff 85 c0 74 07 89 d8 e8 0c ff ff ff 5b 5d c3 55
EAX: 80000000 EBX: c04337f0 ECX: c04338e3 EDX: c04338e3
ESI: c04337f0 EDI: c04338e3 EBP: f2aa1d68 ESP: f2aa1d64
DS: 007b ES: 007b FS: 00d8 GS: 00e0 SS: 0068 EFLAGS: 00210046
CR0: 80050033 CR2: 00000000 CR3: 01668000 CR4: 001406f0
Call Trace:
trace_irq_disable_rcuidle+0x63/0x6c
trace_hardirqs_off+0x26/0x30
default_send_IPI_mask_allbutself_logical+0x31/0x93
default_send_IPI_allbutself+0x37/0x48
native_send_call_func_ipi+0x4d/0x6a
smp_call_function_many+0x165/0x19d
? add_nops+0x34/0x34
? trace_hardirqs_on_caller+0x2d/0x2d
? add_nops+0x34/0x34
smp_call_function+0x1f/0x23
on_each_cpu+0x15/0x43
? trace_hardirqs_on_caller+0x2d/0x2d
? trace_hardirqs_on_caller+0x2d/0x2d
? trace_irq_disable_rcuidle+0x1/0x6c
text_poke_bp+0xa0/0xc2
? trace_hardirqs_on_caller+0x2d/0x2d
arch_jump_label_transform+0xa7/0xcb
? trace_irq_disable_rcuidle+0x5/0x6c
__jump_label_update+0x3e/0x6d
jump_label_update+0x7d/0x81
static_key_slow_inc_cpuslocked+0x58/0x6d
static_key_slow_inc+0x19/0x20
tracepoint_probe_register_prio+0x19e/0x1d1
? start_critical_timings+0x1c/0x1c
tracepoint_probe_register+0xf/0x11
irqsoff_tracer_init+0x21/0xf2
tracer_init+0x16/0x1a
trace_selftest_startup_irqsoff+0x25/0xc4
run_tracer_selftest+0xca/0x131
register_tracer+0xd5/0x172
? trace_event_define_fields_preemptirq_template+0x45/0x45
init_irqsoff_tracer+0xd/0x11
do_one_initcall+0xab/0x1e8
? rcu_read_lock_sched_held+0x3d/0x44
? trace_initcall_level+0x52/0x86
kernel_init_freeable+0x195/0x21a
? rest_init+0xb4/0xb4
kernel_init+0xd/0xe4
ret_from_fork+0x2e/0x38
It is due to running a CONFIG_PREEMPT_VOLUNTARY kernel, which would trigger
this warning every time:
WARN_ON_ONCE(preempt_count());
Because on CONFIG_PREEMPT_VOLUNTARY, preempt_count() is always zero.
This warning is to make sure preempt_count is set because
tracer_hardirqs_on() does a preempt_enable_notrace() to make the
preempt_trace() work properly, as being called by a trace event, the trace
event code disables preemption, and the tracer wants to know what the
preemption was before it was called.
Instead of enabling preemption like this, just record the preempt_count,
subtract PREEMPT_DISABLE_OFFSET from it (which is zero with !CONFIG_PREEMPT
set), and pass that value to the necessary functions, which should use the
passed in parameter instead of calling preempt_count() directly.
Fixes: da5b3ebb45277 ("tracing: irqsoff: Account for additional preempt_disable")
Signed-off-by: Steven Rostedt (VMware) <rostedt@goodmis.org>
2018-08-08 04:03:12 +07:00
|
|
|
stop_critical_timing(unsigned long ip, unsigned long parent_ip, int pc)
|
2008-05-13 02:20:42 +07:00
|
|
|
{
|
|
|
|
int cpu;
|
|
|
|
struct trace_array *tr = irqsoff_trace;
|
|
|
|
struct trace_array_cpu *data;
|
|
|
|
unsigned long flags;
|
|
|
|
|
2008-05-13 02:20:55 +07:00
|
|
|
cpu = raw_smp_processor_id();
|
2008-05-13 02:20:42 +07:00
|
|
|
/* Always clear the tracing cpu on stopping the trace */
|
2008-05-13 02:20:55 +07:00
|
|
|
if (unlikely(per_cpu(tracing_cpu, cpu)))
|
|
|
|
per_cpu(tracing_cpu, cpu) = 0;
|
2008-05-13 02:20:42 +07:00
|
|
|
else
|
|
|
|
return;
|
|
|
|
|
2013-07-02 02:58:24 +07:00
|
|
|
if (!tracer_enabled || !tracing_is_enabled())
|
2008-05-13 02:20:42 +07:00
|
|
|
return;
|
|
|
|
|
tracing: Consolidate max_tr into main trace_array structure
Currently, the way the latency tracers and snapshot feature works
is to have a separate trace_array called "max_tr" that holds the
snapshot buffer. For latency tracers, this snapshot buffer is used
to swap the running buffer with this buffer to save the current max
latency.
The only items needed for the max_tr is really just a copy of the buffer
itself, the per_cpu data pointers, the time_start timestamp that states
when the max latency was triggered, and the cpu that the max latency
was triggered on. All other fields in trace_array are unused by the
max_tr, making the max_tr mostly bloat.
This change removes the max_tr completely, and adds a new structure
called trace_buffer, that holds the buffer pointer, the per_cpu data
pointers, the time_start timestamp, and the cpu where the latency occurred.
The trace_array, now has two trace_buffers, one for the normal trace and
one for the max trace or snapshot. By doing this, not only do we remove
the bloat from the max_trace but the instances of traces can now use
their own snapshot feature and not have just the top level global_trace have
the snapshot feature and latency tracers for itself.
Signed-off-by: Steven Rostedt <rostedt@goodmis.org>
2013-03-05 21:24:35 +07:00
|
|
|
data = per_cpu_ptr(tr->trace_buffer.data, cpu);
|
2008-05-13 02:20:42 +07:00
|
|
|
|
2008-09-30 10:02:41 +07:00
|
|
|
if (unlikely(!data) ||
|
2008-05-13 02:20:42 +07:00
|
|
|
!data->critical_start || atomic_read(&data->disabled))
|
|
|
|
return;
|
|
|
|
|
|
|
|
atomic_inc(&data->disabled);
|
2008-05-13 02:20:55 +07:00
|
|
|
|
2008-05-13 02:20:42 +07:00
|
|
|
local_save_flags(flags);
|
tracing/irqsoff: Handle preempt_count for different configs
I was hitting the following warning:
WARNING: CPU: 0 PID: 1 at kernel/trace/trace_irqsoff.c:631 tracer_hardirqs_off+0x15/0x2a
Modules linked in:
CPU: 0 PID: 1 Comm: swapper/0 Not tainted 4.18.0-rc6-test+ #13
Hardware name: MSI MS-7823/CSM-H87M-G43 (MS-7823), BIOS V1.6 02/22/2014
EIP: tracer_hardirqs_off+0x15/0x2a
Code: ff 85 c0 74 0e 8b 45 00 8b 50 04 8b 45 04 e8 35 ff ff ff 5d c3 55 64 a1 cc 37 51 c1 a9 ff ff ff 7f 89 e5 53 89 d3 89 ca 75 02 <0f> 0b e8 90 fc ff ff 85 c0 74 07 89 d8 e8 0c ff ff ff 5b 5d c3 55
EAX: 80000000 EBX: c04337f0 ECX: c04338e3 EDX: c04338e3
ESI: c04337f0 EDI: c04338e3 EBP: f2aa1d68 ESP: f2aa1d64
DS: 007b ES: 007b FS: 00d8 GS: 00e0 SS: 0068 EFLAGS: 00210046
CR0: 80050033 CR2: 00000000 CR3: 01668000 CR4: 001406f0
Call Trace:
trace_irq_disable_rcuidle+0x63/0x6c
trace_hardirqs_off+0x26/0x30
default_send_IPI_mask_allbutself_logical+0x31/0x93
default_send_IPI_allbutself+0x37/0x48
native_send_call_func_ipi+0x4d/0x6a
smp_call_function_many+0x165/0x19d
? add_nops+0x34/0x34
? trace_hardirqs_on_caller+0x2d/0x2d
? add_nops+0x34/0x34
smp_call_function+0x1f/0x23
on_each_cpu+0x15/0x43
? trace_hardirqs_on_caller+0x2d/0x2d
? trace_hardirqs_on_caller+0x2d/0x2d
? trace_irq_disable_rcuidle+0x1/0x6c
text_poke_bp+0xa0/0xc2
? trace_hardirqs_on_caller+0x2d/0x2d
arch_jump_label_transform+0xa7/0xcb
? trace_irq_disable_rcuidle+0x5/0x6c
__jump_label_update+0x3e/0x6d
jump_label_update+0x7d/0x81
static_key_slow_inc_cpuslocked+0x58/0x6d
static_key_slow_inc+0x19/0x20
tracepoint_probe_register_prio+0x19e/0x1d1
? start_critical_timings+0x1c/0x1c
tracepoint_probe_register+0xf/0x11
irqsoff_tracer_init+0x21/0xf2
tracer_init+0x16/0x1a
trace_selftest_startup_irqsoff+0x25/0xc4
run_tracer_selftest+0xca/0x131
register_tracer+0xd5/0x172
? trace_event_define_fields_preemptirq_template+0x45/0x45
init_irqsoff_tracer+0xd/0x11
do_one_initcall+0xab/0x1e8
? rcu_read_lock_sched_held+0x3d/0x44
? trace_initcall_level+0x52/0x86
kernel_init_freeable+0x195/0x21a
? rest_init+0xb4/0xb4
kernel_init+0xd/0xe4
ret_from_fork+0x2e/0x38
It is due to running a CONFIG_PREEMPT_VOLUNTARY kernel, which would trigger
this warning every time:
WARN_ON_ONCE(preempt_count());
Because on CONFIG_PREEMPT_VOLUNTARY, preempt_count() is always zero.
This warning is to make sure preempt_count is set because
tracer_hardirqs_on() does a preempt_enable_notrace() to make the
preempt_trace() work properly, as being called by a trace event, the trace
event code disables preemption, and the tracer wants to know what the
preemption was before it was called.
Instead of enabling preemption like this, just record the preempt_count,
subtract PREEMPT_DISABLE_OFFSET from it (which is zero with !CONFIG_PREEMPT
set), and pass that value to the necessary functions, which should use the
passed in parameter instead of calling preempt_count() directly.
Fixes: da5b3ebb45277 ("tracing: irqsoff: Account for additional preempt_disable")
Signed-off-by: Steven Rostedt (VMware) <rostedt@goodmis.org>
2018-08-08 04:03:12 +07:00
|
|
|
__trace_function(tr, ip, parent_ip, flags, pc);
|
2008-05-13 02:20:42 +07:00
|
|
|
check_critical_timing(tr, data, parent_ip ? : ip, cpu);
|
2008-05-13 02:20:42 +07:00
|
|
|
data->critical_start = 0;
|
|
|
|
atomic_dec(&data->disabled);
|
|
|
|
}
|
|
|
|
|
2008-05-13 02:20:42 +07:00
|
|
|
/* start and stop critical timings used to for stoppage (in idle) */
|
2008-05-13 02:20:51 +07:00
|
|
|
void start_critical_timings(void)
|
2008-05-13 02:20:42 +07:00
|
|
|
{
|
tracing/irqsoff: Handle preempt_count for different configs
I was hitting the following warning:
WARNING: CPU: 0 PID: 1 at kernel/trace/trace_irqsoff.c:631 tracer_hardirqs_off+0x15/0x2a
Modules linked in:
CPU: 0 PID: 1 Comm: swapper/0 Not tainted 4.18.0-rc6-test+ #13
Hardware name: MSI MS-7823/CSM-H87M-G43 (MS-7823), BIOS V1.6 02/22/2014
EIP: tracer_hardirqs_off+0x15/0x2a
Code: ff 85 c0 74 0e 8b 45 00 8b 50 04 8b 45 04 e8 35 ff ff ff 5d c3 55 64 a1 cc 37 51 c1 a9 ff ff ff 7f 89 e5 53 89 d3 89 ca 75 02 <0f> 0b e8 90 fc ff ff 85 c0 74 07 89 d8 e8 0c ff ff ff 5b 5d c3 55
EAX: 80000000 EBX: c04337f0 ECX: c04338e3 EDX: c04338e3
ESI: c04337f0 EDI: c04338e3 EBP: f2aa1d68 ESP: f2aa1d64
DS: 007b ES: 007b FS: 00d8 GS: 00e0 SS: 0068 EFLAGS: 00210046
CR0: 80050033 CR2: 00000000 CR3: 01668000 CR4: 001406f0
Call Trace:
trace_irq_disable_rcuidle+0x63/0x6c
trace_hardirqs_off+0x26/0x30
default_send_IPI_mask_allbutself_logical+0x31/0x93
default_send_IPI_allbutself+0x37/0x48
native_send_call_func_ipi+0x4d/0x6a
smp_call_function_many+0x165/0x19d
? add_nops+0x34/0x34
? trace_hardirqs_on_caller+0x2d/0x2d
? add_nops+0x34/0x34
smp_call_function+0x1f/0x23
on_each_cpu+0x15/0x43
? trace_hardirqs_on_caller+0x2d/0x2d
? trace_hardirqs_on_caller+0x2d/0x2d
? trace_irq_disable_rcuidle+0x1/0x6c
text_poke_bp+0xa0/0xc2
? trace_hardirqs_on_caller+0x2d/0x2d
arch_jump_label_transform+0xa7/0xcb
? trace_irq_disable_rcuidle+0x5/0x6c
__jump_label_update+0x3e/0x6d
jump_label_update+0x7d/0x81
static_key_slow_inc_cpuslocked+0x58/0x6d
static_key_slow_inc+0x19/0x20
tracepoint_probe_register_prio+0x19e/0x1d1
? start_critical_timings+0x1c/0x1c
tracepoint_probe_register+0xf/0x11
irqsoff_tracer_init+0x21/0xf2
tracer_init+0x16/0x1a
trace_selftest_startup_irqsoff+0x25/0xc4
run_tracer_selftest+0xca/0x131
register_tracer+0xd5/0x172
? trace_event_define_fields_preemptirq_template+0x45/0x45
init_irqsoff_tracer+0xd/0x11
do_one_initcall+0xab/0x1e8
? rcu_read_lock_sched_held+0x3d/0x44
? trace_initcall_level+0x52/0x86
kernel_init_freeable+0x195/0x21a
? rest_init+0xb4/0xb4
kernel_init+0xd/0xe4
ret_from_fork+0x2e/0x38
It is due to running a CONFIG_PREEMPT_VOLUNTARY kernel, which would trigger
this warning every time:
WARN_ON_ONCE(preempt_count());
Because on CONFIG_PREEMPT_VOLUNTARY, preempt_count() is always zero.
This warning is to make sure preempt_count is set because
tracer_hardirqs_on() does a preempt_enable_notrace() to make the
preempt_trace() work properly, as being called by a trace event, the trace
event code disables preemption, and the tracer wants to know what the
preemption was before it was called.
Instead of enabling preemption like this, just record the preempt_count,
subtract PREEMPT_DISABLE_OFFSET from it (which is zero with !CONFIG_PREEMPT
set), and pass that value to the necessary functions, which should use the
passed in parameter instead of calling preempt_count() directly.
Fixes: da5b3ebb45277 ("tracing: irqsoff: Account for additional preempt_disable")
Signed-off-by: Steven Rostedt (VMware) <rostedt@goodmis.org>
2018-08-08 04:03:12 +07:00
|
|
|
int pc = preempt_count();
|
|
|
|
|
|
|
|
if (preempt_trace(pc) || irq_trace())
|
|
|
|
start_critical_timing(CALLER_ADDR0, CALLER_ADDR1, pc);
|
2008-05-13 02:20:42 +07:00
|
|
|
}
|
2008-07-26 20:09:47 +07:00
|
|
|
EXPORT_SYMBOL_GPL(start_critical_timings);
|
2008-05-13 02:20:42 +07:00
|
|
|
|
2008-05-13 02:20:51 +07:00
|
|
|
void stop_critical_timings(void)
|
2008-05-13 02:20:42 +07:00
|
|
|
{
|
tracing/irqsoff: Handle preempt_count for different configs
I was hitting the following warning:
WARNING: CPU: 0 PID: 1 at kernel/trace/trace_irqsoff.c:631 tracer_hardirqs_off+0x15/0x2a
Modules linked in:
CPU: 0 PID: 1 Comm: swapper/0 Not tainted 4.18.0-rc6-test+ #13
Hardware name: MSI MS-7823/CSM-H87M-G43 (MS-7823), BIOS V1.6 02/22/2014
EIP: tracer_hardirqs_off+0x15/0x2a
Code: ff 85 c0 74 0e 8b 45 00 8b 50 04 8b 45 04 e8 35 ff ff ff 5d c3 55 64 a1 cc 37 51 c1 a9 ff ff ff 7f 89 e5 53 89 d3 89 ca 75 02 <0f> 0b e8 90 fc ff ff 85 c0 74 07 89 d8 e8 0c ff ff ff 5b 5d c3 55
EAX: 80000000 EBX: c04337f0 ECX: c04338e3 EDX: c04338e3
ESI: c04337f0 EDI: c04338e3 EBP: f2aa1d68 ESP: f2aa1d64
DS: 007b ES: 007b FS: 00d8 GS: 00e0 SS: 0068 EFLAGS: 00210046
CR0: 80050033 CR2: 00000000 CR3: 01668000 CR4: 001406f0
Call Trace:
trace_irq_disable_rcuidle+0x63/0x6c
trace_hardirqs_off+0x26/0x30
default_send_IPI_mask_allbutself_logical+0x31/0x93
default_send_IPI_allbutself+0x37/0x48
native_send_call_func_ipi+0x4d/0x6a
smp_call_function_many+0x165/0x19d
? add_nops+0x34/0x34
? trace_hardirqs_on_caller+0x2d/0x2d
? add_nops+0x34/0x34
smp_call_function+0x1f/0x23
on_each_cpu+0x15/0x43
? trace_hardirqs_on_caller+0x2d/0x2d
? trace_hardirqs_on_caller+0x2d/0x2d
? trace_irq_disable_rcuidle+0x1/0x6c
text_poke_bp+0xa0/0xc2
? trace_hardirqs_on_caller+0x2d/0x2d
arch_jump_label_transform+0xa7/0xcb
? trace_irq_disable_rcuidle+0x5/0x6c
__jump_label_update+0x3e/0x6d
jump_label_update+0x7d/0x81
static_key_slow_inc_cpuslocked+0x58/0x6d
static_key_slow_inc+0x19/0x20
tracepoint_probe_register_prio+0x19e/0x1d1
? start_critical_timings+0x1c/0x1c
tracepoint_probe_register+0xf/0x11
irqsoff_tracer_init+0x21/0xf2
tracer_init+0x16/0x1a
trace_selftest_startup_irqsoff+0x25/0xc4
run_tracer_selftest+0xca/0x131
register_tracer+0xd5/0x172
? trace_event_define_fields_preemptirq_template+0x45/0x45
init_irqsoff_tracer+0xd/0x11
do_one_initcall+0xab/0x1e8
? rcu_read_lock_sched_held+0x3d/0x44
? trace_initcall_level+0x52/0x86
kernel_init_freeable+0x195/0x21a
? rest_init+0xb4/0xb4
kernel_init+0xd/0xe4
ret_from_fork+0x2e/0x38
It is due to running a CONFIG_PREEMPT_VOLUNTARY kernel, which would trigger
this warning every time:
WARN_ON_ONCE(preempt_count());
Because on CONFIG_PREEMPT_VOLUNTARY, preempt_count() is always zero.
This warning is to make sure preempt_count is set because
tracer_hardirqs_on() does a preempt_enable_notrace() to make the
preempt_trace() work properly, as being called by a trace event, the trace
event code disables preemption, and the tracer wants to know what the
preemption was before it was called.
Instead of enabling preemption like this, just record the preempt_count,
subtract PREEMPT_DISABLE_OFFSET from it (which is zero with !CONFIG_PREEMPT
set), and pass that value to the necessary functions, which should use the
passed in parameter instead of calling preempt_count() directly.
Fixes: da5b3ebb45277 ("tracing: irqsoff: Account for additional preempt_disable")
Signed-off-by: Steven Rostedt (VMware) <rostedt@goodmis.org>
2018-08-08 04:03:12 +07:00
|
|
|
int pc = preempt_count();
|
|
|
|
|
|
|
|
if (preempt_trace(pc) || irq_trace())
|
|
|
|
stop_critical_timing(CALLER_ADDR0, CALLER_ADDR1, pc);
|
2008-05-13 02:20:42 +07:00
|
|
|
}
|
2008-07-26 20:09:47 +07:00
|
|
|
EXPORT_SYMBOL_GPL(stop_critical_timings);
|
2008-05-13 02:20:42 +07:00
|
|
|
|
2015-09-29 21:24:56 +07:00
|
|
|
#ifdef CONFIG_FUNCTION_TRACER
|
|
|
|
static bool function_enabled;
|
|
|
|
|
2014-01-11 05:01:58 +07:00
|
|
|
static int register_irqsoff_function(struct trace_array *tr, int graph, int set)
|
2008-05-13 02:20:42 +07:00
|
|
|
{
|
2013-03-14 23:10:40 +07:00
|
|
|
int ret;
|
2010-04-03 00:01:22 +07:00
|
|
|
|
2013-03-14 23:10:40 +07:00
|
|
|
/* 'set' is set if TRACE_ITER_FUNCTION is about to be set */
|
2015-09-30 20:42:05 +07:00
|
|
|
if (function_enabled || (!set && !(tr->trace_flags & TRACE_ITER_FUNCTION)))
|
2013-03-14 23:10:40 +07:00
|
|
|
return 0;
|
|
|
|
|
|
|
|
if (graph)
|
2010-04-03 00:01:22 +07:00
|
|
|
ret = register_ftrace_graph(&irqsoff_graph_return,
|
|
|
|
&irqsoff_graph_entry);
|
2013-03-14 23:10:40 +07:00
|
|
|
else
|
2014-01-11 05:01:58 +07:00
|
|
|
ret = register_ftrace_function(tr->ops);
|
2013-03-14 23:10:40 +07:00
|
|
|
|
|
|
|
if (!ret)
|
|
|
|
function_enabled = true;
|
|
|
|
|
|
|
|
return ret;
|
|
|
|
}
|
|
|
|
|
2014-01-11 05:01:58 +07:00
|
|
|
static void unregister_irqsoff_function(struct trace_array *tr, int graph)
|
2013-03-14 23:10:40 +07:00
|
|
|
{
|
|
|
|
if (!function_enabled)
|
|
|
|
return;
|
|
|
|
|
|
|
|
if (graph)
|
|
|
|
unregister_ftrace_graph();
|
|
|
|
else
|
2014-01-11 05:01:58 +07:00
|
|
|
unregister_ftrace_function(tr->ops);
|
2013-03-14 23:10:40 +07:00
|
|
|
|
|
|
|
function_enabled = false;
|
|
|
|
}
|
|
|
|
|
2015-09-29 21:24:56 +07:00
|
|
|
static int irqsoff_function_set(struct trace_array *tr, u32 mask, int set)
|
2013-03-14 23:10:40 +07:00
|
|
|
{
|
2015-09-29 21:24:56 +07:00
|
|
|
if (!(mask & TRACE_ITER_FUNCTION))
|
|
|
|
return 0;
|
|
|
|
|
2013-03-14 23:10:40 +07:00
|
|
|
if (set)
|
2015-09-30 20:42:05 +07:00
|
|
|
register_irqsoff_function(tr, is_graph(tr), 1);
|
2013-03-14 23:10:40 +07:00
|
|
|
else
|
2015-09-30 20:42:05 +07:00
|
|
|
unregister_irqsoff_function(tr, is_graph(tr));
|
2015-09-29 21:24:56 +07:00
|
|
|
return 1;
|
|
|
|
}
|
|
|
|
#else
|
|
|
|
static int register_irqsoff_function(struct trace_array *tr, int graph, int set)
|
|
|
|
{
|
2015-09-29 02:37:49 +07:00
|
|
|
return 0;
|
2013-03-14 23:10:40 +07:00
|
|
|
}
|
2015-09-29 21:24:56 +07:00
|
|
|
static void unregister_irqsoff_function(struct trace_array *tr, int graph) { }
|
|
|
|
static inline int irqsoff_function_set(struct trace_array *tr, u32 mask, int set)
|
|
|
|
{
|
|
|
|
return 0;
|
|
|
|
}
|
|
|
|
#endif /* CONFIG_FUNCTION_TRACER */
|
2013-03-14 23:10:40 +07:00
|
|
|
|
2014-01-11 05:51:01 +07:00
|
|
|
static int irqsoff_flag_changed(struct trace_array *tr, u32 mask, int set)
|
2013-03-14 23:10:40 +07:00
|
|
|
{
|
2014-01-11 05:51:01 +07:00
|
|
|
struct tracer *tracer = tr->current_trace;
|
|
|
|
|
2015-09-29 21:24:56 +07:00
|
|
|
if (irqsoff_function_set(tr, mask, set))
|
|
|
|
return 0;
|
2015-09-29 02:37:49 +07:00
|
|
|
|
2015-09-29 21:15:10 +07:00
|
|
|
#ifdef CONFIG_FUNCTION_GRAPH_TRACER
|
2015-09-29 02:37:49 +07:00
|
|
|
if (mask & TRACE_ITER_DISPLAY_GRAPH)
|
|
|
|
return irqsoff_display_graph(tr, set);
|
2015-09-29 21:15:10 +07:00
|
|
|
#endif
|
2013-03-14 23:10:40 +07:00
|
|
|
|
|
|
|
return trace_keep_overwrite(tracer, mask, set);
|
|
|
|
}
|
|
|
|
|
|
|
|
static int start_irqsoff_tracer(struct trace_array *tr, int graph)
|
|
|
|
{
|
|
|
|
int ret;
|
|
|
|
|
2014-01-11 05:01:58 +07:00
|
|
|
ret = register_irqsoff_function(tr, graph, 0);
|
2010-04-03 00:01:22 +07:00
|
|
|
|
|
|
|
if (!ret && tracing_is_enabled())
|
ftrace: restructure tracing start/stop infrastructure
Impact: change where tracing is started up and stopped
Currently, when a new tracer is selected via echo'ing a tracer name into
the current_tracer file, the startup is only done if tracing_enabled is
set to one. If tracing_enabled is changed to zero (by echo'ing 0 into
the tracing_enabled file) a full shutdown is performed.
The full startup and shutdown of a tracer can be expensive and the
user can lose out traces when echo'ing in 0 to the tracing_enabled file,
because the process takes too long. There can also be places that
the user would like to start and stop the tracer several times and
doing the full startup and shutdown of a tracer might be too expensive.
This patch performs the full startup and shutdown when a tracer is
selected. It also adds a way to do a quick start or stop of a tracer.
The quick version is just a flag that prevents the tracing from
taking place, but the overhead of the code is still there.
For example, the startup of a tracer may enable tracepoints, or enable
the function tracer. The stop and start will just set a flag to
have the tracer ignore the calls when the tracepoint or function trace
is called. The overhead of the tracer may still be present when
the tracer is stopped, but no tracing will occur. Setting the tracer
to the 'nop' tracer (or any other tracer) will perform the shutdown
of the tracer which will disable the tracepoint or disable the
function tracer.
The tracing_enabled file will simply start or stop tracing.
This change is all internal. The end result for the user should be the same
as before. If tracing_enabled is not set, no trace will happen.
If tracing_enabled is set, then the trace will happen. The tracing_enabled
variable is static between tracers. Enabling tracing_enabled and
going to another tracer will keep tracing_enabled enabled. Same
is true with disabling tracing_enabled.
This patch will now provide a fast start/stop method to the users
for enabling or disabling tracing.
Note: There were two methods to the struct tracer that were never
used: The methods start and stop. These were to be used as a hook
to the reading of the trace output, but ended up not being
necessary. These two methods are now used to enable the start
and stop of each tracer, in case the tracer needs to do more than
just not write into the buffer. For example, the irqsoff tracer
must stop recording max latencies when tracing is stopped.
Signed-off-by: Steven Rostedt <srostedt@redhat.com>
Signed-off-by: Ingo Molnar <mingo@elte.hu>
2008-11-06 04:05:44 +07:00
|
|
|
tracer_enabled = 1;
|
2009-01-22 23:18:06 +07:00
|
|
|
else
|
ftrace: restructure tracing start/stop infrastructure
Impact: change where tracing is started up and stopped
Currently, when a new tracer is selected via echo'ing a tracer name into
the current_tracer file, the startup is only done if tracing_enabled is
set to one. If tracing_enabled is changed to zero (by echo'ing 0 into
the tracing_enabled file) a full shutdown is performed.
The full startup and shutdown of a tracer can be expensive and the
user can lose out traces when echo'ing in 0 to the tracing_enabled file,
because the process takes too long. There can also be places that
the user would like to start and stop the tracer several times and
doing the full startup and shutdown of a tracer might be too expensive.
This patch performs the full startup and shutdown when a tracer is
selected. It also adds a way to do a quick start or stop of a tracer.
The quick version is just a flag that prevents the tracing from
taking place, but the overhead of the code is still there.
For example, the startup of a tracer may enable tracepoints, or enable
the function tracer. The stop and start will just set a flag to
have the tracer ignore the calls when the tracepoint or function trace
is called. The overhead of the tracer may still be present when
the tracer is stopped, but no tracing will occur. Setting the tracer
to the 'nop' tracer (or any other tracer) will perform the shutdown
of the tracer which will disable the tracepoint or disable the
function tracer.
The tracing_enabled file will simply start or stop tracing.
This change is all internal. The end result for the user should be the same
as before. If tracing_enabled is not set, no trace will happen.
If tracing_enabled is set, then the trace will happen. The tracing_enabled
variable is static between tracers. Enabling tracing_enabled and
going to another tracer will keep tracing_enabled enabled. Same
is true with disabling tracing_enabled.
This patch will now provide a fast start/stop method to the users
for enabling or disabling tracing.
Note: There were two methods to the struct tracer that were never
used: The methods start and stop. These were to be used as a hook
to the reading of the trace output, but ended up not being
necessary. These two methods are now used to enable the start
and stop of each tracer, in case the tracer needs to do more than
just not write into the buffer. For example, the irqsoff tracer
must stop recording max latencies when tracing is stopped.
Signed-off-by: Steven Rostedt <srostedt@redhat.com>
Signed-off-by: Ingo Molnar <mingo@elte.hu>
2008-11-06 04:05:44 +07:00
|
|
|
tracer_enabled = 0;
|
2010-04-03 00:01:22 +07:00
|
|
|
|
|
|
|
return ret;
|
2008-05-13 02:20:42 +07:00
|
|
|
}
|
|
|
|
|
2010-04-03 00:01:22 +07:00
|
|
|
static void stop_irqsoff_tracer(struct trace_array *tr, int graph)
|
2008-05-13 02:20:42 +07:00
|
|
|
{
|
|
|
|
tracer_enabled = 0;
|
2010-04-03 00:01:22 +07:00
|
|
|
|
2014-01-11 05:01:58 +07:00
|
|
|
unregister_irqsoff_function(tr, graph);
|
2008-05-13 02:20:42 +07:00
|
|
|
}
|
|
|
|
|
2014-01-14 21:32:58 +07:00
|
|
|
static bool irqsoff_busy;
|
|
|
|
|
|
|
|
static int __irqsoff_tracer_init(struct trace_array *tr)
|
2008-05-13 02:20:42 +07:00
|
|
|
{
|
2014-01-14 21:32:58 +07:00
|
|
|
if (irqsoff_busy)
|
|
|
|
return -EBUSY;
|
|
|
|
|
2015-09-30 20:42:05 +07:00
|
|
|
save_flags = tr->trace_flags;
|
2013-03-15 02:03:53 +07:00
|
|
|
|
|
|
|
/* non overwrite screws up the latency tracers */
|
2012-05-12 00:29:49 +07:00
|
|
|
set_tracer_flag(tr, TRACE_ITER_OVERWRITE, 1);
|
|
|
|
set_tracer_flag(tr, TRACE_ITER_LATENCY_FMT, 1);
|
2009-03-05 10:15:30 +07:00
|
|
|
|
2014-01-14 23:28:38 +07:00
|
|
|
tr->max_latency = 0;
|
2008-05-13 02:20:42 +07:00
|
|
|
irqsoff_trace = tr;
|
2008-05-13 02:20:55 +07:00
|
|
|
/* make sure that the tracer is visible */
|
2008-05-13 02:20:42 +07:00
|
|
|
smp_wmb();
|
2010-04-03 00:01:22 +07:00
|
|
|
|
2014-01-11 05:01:58 +07:00
|
|
|
ftrace_init_array_ops(tr, irqsoff_tracer_call);
|
|
|
|
|
|
|
|
/* Only toplevel instance supports graph tracing */
|
|
|
|
if (start_irqsoff_tracer(tr, (tr->flags & TRACE_ARRAY_FL_GLOBAL &&
|
2015-09-30 20:42:05 +07:00
|
|
|
is_graph(tr))))
|
2010-04-03 00:01:22 +07:00
|
|
|
printk(KERN_ERR "failed to start irqsoff tracer\n");
|
2014-01-14 21:32:58 +07:00
|
|
|
|
|
|
|
irqsoff_busy = true;
|
|
|
|
return 0;
|
2008-05-13 02:20:42 +07:00
|
|
|
}
|
|
|
|
|
2018-06-29 01:21:45 +07:00
|
|
|
static void __irqsoff_tracer_reset(struct trace_array *tr)
|
2008-05-13 02:20:42 +07:00
|
|
|
{
|
2013-03-15 02:03:53 +07:00
|
|
|
int lat_flag = save_flags & TRACE_ITER_LATENCY_FMT;
|
|
|
|
int overwrite_flag = save_flags & TRACE_ITER_OVERWRITE;
|
|
|
|
|
2015-09-30 20:42:05 +07:00
|
|
|
stop_irqsoff_tracer(tr, is_graph(tr));
|
2009-03-05 10:15:30 +07:00
|
|
|
|
2012-05-12 00:29:49 +07:00
|
|
|
set_tracer_flag(tr, TRACE_ITER_LATENCY_FMT, lat_flag);
|
|
|
|
set_tracer_flag(tr, TRACE_ITER_OVERWRITE, overwrite_flag);
|
2014-01-11 05:01:58 +07:00
|
|
|
ftrace_reset_array_ops(tr);
|
2014-01-14 21:32:58 +07:00
|
|
|
|
|
|
|
irqsoff_busy = false;
|
2008-05-13 02:20:42 +07:00
|
|
|
}
|
|
|
|
|
ftrace: restructure tracing start/stop infrastructure
Impact: change where tracing is started up and stopped
Currently, when a new tracer is selected via echo'ing a tracer name into
the current_tracer file, the startup is only done if tracing_enabled is
set to one. If tracing_enabled is changed to zero (by echo'ing 0 into
the tracing_enabled file) a full shutdown is performed.
The full startup and shutdown of a tracer can be expensive and the
user can lose out traces when echo'ing in 0 to the tracing_enabled file,
because the process takes too long. There can also be places that
the user would like to start and stop the tracer several times and
doing the full startup and shutdown of a tracer might be too expensive.
This patch performs the full startup and shutdown when a tracer is
selected. It also adds a way to do a quick start or stop of a tracer.
The quick version is just a flag that prevents the tracing from
taking place, but the overhead of the code is still there.
For example, the startup of a tracer may enable tracepoints, or enable
the function tracer. The stop and start will just set a flag to
have the tracer ignore the calls when the tracepoint or function trace
is called. The overhead of the tracer may still be present when
the tracer is stopped, but no tracing will occur. Setting the tracer
to the 'nop' tracer (or any other tracer) will perform the shutdown
of the tracer which will disable the tracepoint or disable the
function tracer.
The tracing_enabled file will simply start or stop tracing.
This change is all internal. The end result for the user should be the same
as before. If tracing_enabled is not set, no trace will happen.
If tracing_enabled is set, then the trace will happen. The tracing_enabled
variable is static between tracers. Enabling tracing_enabled and
going to another tracer will keep tracing_enabled enabled. Same
is true with disabling tracing_enabled.
This patch will now provide a fast start/stop method to the users
for enabling or disabling tracing.
Note: There were two methods to the struct tracer that were never
used: The methods start and stop. These were to be used as a hook
to the reading of the trace output, but ended up not being
necessary. These two methods are now used to enable the start
and stop of each tracer, in case the tracer needs to do more than
just not write into the buffer. For example, the irqsoff tracer
must stop recording max latencies when tracing is stopped.
Signed-off-by: Steven Rostedt <srostedt@redhat.com>
Signed-off-by: Ingo Molnar <mingo@elte.hu>
2008-11-06 04:05:44 +07:00
|
|
|
static void irqsoff_tracer_start(struct trace_array *tr)
|
|
|
|
{
|
|
|
|
tracer_enabled = 1;
|
|
|
|
}
|
|
|
|
|
|
|
|
static void irqsoff_tracer_stop(struct trace_array *tr)
|
|
|
|
{
|
|
|
|
tracer_enabled = 0;
|
2008-05-13 02:20:42 +07:00
|
|
|
}
|
|
|
|
|
2008-05-13 02:20:42 +07:00
|
|
|
#ifdef CONFIG_IRQSOFF_TRACER
|
2018-07-31 05:24:23 +07:00
|
|
|
/*
|
|
|
|
* We are only interested in hardirq on/off events:
|
|
|
|
*/
|
2018-08-09 08:28:05 +07:00
|
|
|
void tracer_hardirqs_on(unsigned long a0, unsigned long a1)
|
2018-07-31 05:24:23 +07:00
|
|
|
{
|
tracing/irqsoff: Handle preempt_count for different configs
I was hitting the following warning:
WARNING: CPU: 0 PID: 1 at kernel/trace/trace_irqsoff.c:631 tracer_hardirqs_off+0x15/0x2a
Modules linked in:
CPU: 0 PID: 1 Comm: swapper/0 Not tainted 4.18.0-rc6-test+ #13
Hardware name: MSI MS-7823/CSM-H87M-G43 (MS-7823), BIOS V1.6 02/22/2014
EIP: tracer_hardirqs_off+0x15/0x2a
Code: ff 85 c0 74 0e 8b 45 00 8b 50 04 8b 45 04 e8 35 ff ff ff 5d c3 55 64 a1 cc 37 51 c1 a9 ff ff ff 7f 89 e5 53 89 d3 89 ca 75 02 <0f> 0b e8 90 fc ff ff 85 c0 74 07 89 d8 e8 0c ff ff ff 5b 5d c3 55
EAX: 80000000 EBX: c04337f0 ECX: c04338e3 EDX: c04338e3
ESI: c04337f0 EDI: c04338e3 EBP: f2aa1d68 ESP: f2aa1d64
DS: 007b ES: 007b FS: 00d8 GS: 00e0 SS: 0068 EFLAGS: 00210046
CR0: 80050033 CR2: 00000000 CR3: 01668000 CR4: 001406f0
Call Trace:
trace_irq_disable_rcuidle+0x63/0x6c
trace_hardirqs_off+0x26/0x30
default_send_IPI_mask_allbutself_logical+0x31/0x93
default_send_IPI_allbutself+0x37/0x48
native_send_call_func_ipi+0x4d/0x6a
smp_call_function_many+0x165/0x19d
? add_nops+0x34/0x34
? trace_hardirqs_on_caller+0x2d/0x2d
? add_nops+0x34/0x34
smp_call_function+0x1f/0x23
on_each_cpu+0x15/0x43
? trace_hardirqs_on_caller+0x2d/0x2d
? trace_hardirqs_on_caller+0x2d/0x2d
? trace_irq_disable_rcuidle+0x1/0x6c
text_poke_bp+0xa0/0xc2
? trace_hardirqs_on_caller+0x2d/0x2d
arch_jump_label_transform+0xa7/0xcb
? trace_irq_disable_rcuidle+0x5/0x6c
__jump_label_update+0x3e/0x6d
jump_label_update+0x7d/0x81
static_key_slow_inc_cpuslocked+0x58/0x6d
static_key_slow_inc+0x19/0x20
tracepoint_probe_register_prio+0x19e/0x1d1
? start_critical_timings+0x1c/0x1c
tracepoint_probe_register+0xf/0x11
irqsoff_tracer_init+0x21/0xf2
tracer_init+0x16/0x1a
trace_selftest_startup_irqsoff+0x25/0xc4
run_tracer_selftest+0xca/0x131
register_tracer+0xd5/0x172
? trace_event_define_fields_preemptirq_template+0x45/0x45
init_irqsoff_tracer+0xd/0x11
do_one_initcall+0xab/0x1e8
? rcu_read_lock_sched_held+0x3d/0x44
? trace_initcall_level+0x52/0x86
kernel_init_freeable+0x195/0x21a
? rest_init+0xb4/0xb4
kernel_init+0xd/0xe4
ret_from_fork+0x2e/0x38
It is due to running a CONFIG_PREEMPT_VOLUNTARY kernel, which would trigger
this warning every time:
WARN_ON_ONCE(preempt_count());
Because on CONFIG_PREEMPT_VOLUNTARY, preempt_count() is always zero.
This warning is to make sure preempt_count is set because
tracer_hardirqs_on() does a preempt_enable_notrace() to make the
preempt_trace() work properly, as being called by a trace event, the trace
event code disables preemption, and the tracer wants to know what the
preemption was before it was called.
Instead of enabling preemption like this, just record the preempt_count,
subtract PREEMPT_DISABLE_OFFSET from it (which is zero with !CONFIG_PREEMPT
set), and pass that value to the necessary functions, which should use the
passed in parameter instead of calling preempt_count() directly.
Fixes: da5b3ebb45277 ("tracing: irqsoff: Account for additional preempt_disable")
Signed-off-by: Steven Rostedt (VMware) <rostedt@goodmis.org>
2018-08-08 04:03:12 +07:00
|
|
|
unsigned int pc = preempt_count();
|
|
|
|
|
|
|
|
if (!preempt_trace(pc) && irq_trace())
|
|
|
|
stop_critical_timing(a0, a1, pc);
|
2018-07-31 05:24:23 +07:00
|
|
|
}
|
|
|
|
|
2018-08-09 08:28:05 +07:00
|
|
|
void tracer_hardirqs_off(unsigned long a0, unsigned long a1)
|
2018-07-31 05:24:23 +07:00
|
|
|
{
|
tracing/irqsoff: Handle preempt_count for different configs
I was hitting the following warning:
WARNING: CPU: 0 PID: 1 at kernel/trace/trace_irqsoff.c:631 tracer_hardirqs_off+0x15/0x2a
Modules linked in:
CPU: 0 PID: 1 Comm: swapper/0 Not tainted 4.18.0-rc6-test+ #13
Hardware name: MSI MS-7823/CSM-H87M-G43 (MS-7823), BIOS V1.6 02/22/2014
EIP: tracer_hardirqs_off+0x15/0x2a
Code: ff 85 c0 74 0e 8b 45 00 8b 50 04 8b 45 04 e8 35 ff ff ff 5d c3 55 64 a1 cc 37 51 c1 a9 ff ff ff 7f 89 e5 53 89 d3 89 ca 75 02 <0f> 0b e8 90 fc ff ff 85 c0 74 07 89 d8 e8 0c ff ff ff 5b 5d c3 55
EAX: 80000000 EBX: c04337f0 ECX: c04338e3 EDX: c04338e3
ESI: c04337f0 EDI: c04338e3 EBP: f2aa1d68 ESP: f2aa1d64
DS: 007b ES: 007b FS: 00d8 GS: 00e0 SS: 0068 EFLAGS: 00210046
CR0: 80050033 CR2: 00000000 CR3: 01668000 CR4: 001406f0
Call Trace:
trace_irq_disable_rcuidle+0x63/0x6c
trace_hardirqs_off+0x26/0x30
default_send_IPI_mask_allbutself_logical+0x31/0x93
default_send_IPI_allbutself+0x37/0x48
native_send_call_func_ipi+0x4d/0x6a
smp_call_function_many+0x165/0x19d
? add_nops+0x34/0x34
? trace_hardirqs_on_caller+0x2d/0x2d
? add_nops+0x34/0x34
smp_call_function+0x1f/0x23
on_each_cpu+0x15/0x43
? trace_hardirqs_on_caller+0x2d/0x2d
? trace_hardirqs_on_caller+0x2d/0x2d
? trace_irq_disable_rcuidle+0x1/0x6c
text_poke_bp+0xa0/0xc2
? trace_hardirqs_on_caller+0x2d/0x2d
arch_jump_label_transform+0xa7/0xcb
? trace_irq_disable_rcuidle+0x5/0x6c
__jump_label_update+0x3e/0x6d
jump_label_update+0x7d/0x81
static_key_slow_inc_cpuslocked+0x58/0x6d
static_key_slow_inc+0x19/0x20
tracepoint_probe_register_prio+0x19e/0x1d1
? start_critical_timings+0x1c/0x1c
tracepoint_probe_register+0xf/0x11
irqsoff_tracer_init+0x21/0xf2
tracer_init+0x16/0x1a
trace_selftest_startup_irqsoff+0x25/0xc4
run_tracer_selftest+0xca/0x131
register_tracer+0xd5/0x172
? trace_event_define_fields_preemptirq_template+0x45/0x45
init_irqsoff_tracer+0xd/0x11
do_one_initcall+0xab/0x1e8
? rcu_read_lock_sched_held+0x3d/0x44
? trace_initcall_level+0x52/0x86
kernel_init_freeable+0x195/0x21a
? rest_init+0xb4/0xb4
kernel_init+0xd/0xe4
ret_from_fork+0x2e/0x38
It is due to running a CONFIG_PREEMPT_VOLUNTARY kernel, which would trigger
this warning every time:
WARN_ON_ONCE(preempt_count());
Because on CONFIG_PREEMPT_VOLUNTARY, preempt_count() is always zero.
This warning is to make sure preempt_count is set because
tracer_hardirqs_on() does a preempt_enable_notrace() to make the
preempt_trace() work properly, as being called by a trace event, the trace
event code disables preemption, and the tracer wants to know what the
preemption was before it was called.
Instead of enabling preemption like this, just record the preempt_count,
subtract PREEMPT_DISABLE_OFFSET from it (which is zero with !CONFIG_PREEMPT
set), and pass that value to the necessary functions, which should use the
passed in parameter instead of calling preempt_count() directly.
Fixes: da5b3ebb45277 ("tracing: irqsoff: Account for additional preempt_disable")
Signed-off-by: Steven Rostedt (VMware) <rostedt@goodmis.org>
2018-08-08 04:03:12 +07:00
|
|
|
unsigned int pc = preempt_count();
|
|
|
|
|
|
|
|
if (!preempt_trace(pc) && irq_trace())
|
|
|
|
start_critical_timing(a0, a1, pc);
|
2018-07-31 05:24:23 +07:00
|
|
|
}
|
|
|
|
|
2008-11-16 11:57:26 +07:00
|
|
|
static int irqsoff_tracer_init(struct trace_array *tr)
|
2008-05-13 02:20:42 +07:00
|
|
|
{
|
|
|
|
trace_type = TRACER_IRQS_OFF;
|
|
|
|
|
2014-01-14 21:32:58 +07:00
|
|
|
return __irqsoff_tracer_init(tr);
|
2008-05-13 02:20:42 +07:00
|
|
|
}
|
2018-06-29 01:21:45 +07:00
|
|
|
|
|
|
|
static void irqsoff_tracer_reset(struct trace_array *tr)
|
|
|
|
{
|
|
|
|
__irqsoff_tracer_reset(tr);
|
|
|
|
}
|
|
|
|
|
2008-05-13 02:20:42 +07:00
|
|
|
static struct tracer irqsoff_tracer __read_mostly =
|
|
|
|
{
|
|
|
|
.name = "irqsoff",
|
|
|
|
.init = irqsoff_tracer_init,
|
|
|
|
.reset = irqsoff_tracer_reset,
|
ftrace: restructure tracing start/stop infrastructure
Impact: change where tracing is started up and stopped
Currently, when a new tracer is selected via echo'ing a tracer name into
the current_tracer file, the startup is only done if tracing_enabled is
set to one. If tracing_enabled is changed to zero (by echo'ing 0 into
the tracing_enabled file) a full shutdown is performed.
The full startup and shutdown of a tracer can be expensive and the
user can lose out traces when echo'ing in 0 to the tracing_enabled file,
because the process takes too long. There can also be places that
the user would like to start and stop the tracer several times and
doing the full startup and shutdown of a tracer might be too expensive.
This patch performs the full startup and shutdown when a tracer is
selected. It also adds a way to do a quick start or stop of a tracer.
The quick version is just a flag that prevents the tracing from
taking place, but the overhead of the code is still there.
For example, the startup of a tracer may enable tracepoints, or enable
the function tracer. The stop and start will just set a flag to
have the tracer ignore the calls when the tracepoint or function trace
is called. The overhead of the tracer may still be present when
the tracer is stopped, but no tracing will occur. Setting the tracer
to the 'nop' tracer (or any other tracer) will perform the shutdown
of the tracer which will disable the tracepoint or disable the
function tracer.
The tracing_enabled file will simply start or stop tracing.
This change is all internal. The end result for the user should be the same
as before. If tracing_enabled is not set, no trace will happen.
If tracing_enabled is set, then the trace will happen. The tracing_enabled
variable is static between tracers. Enabling tracing_enabled and
going to another tracer will keep tracing_enabled enabled. Same
is true with disabling tracing_enabled.
This patch will now provide a fast start/stop method to the users
for enabling or disabling tracing.
Note: There were two methods to the struct tracer that were never
used: The methods start and stop. These were to be used as a hook
to the reading of the trace output, but ended up not being
necessary. These two methods are now used to enable the start
and stop of each tracer, in case the tracer needs to do more than
just not write into the buffer. For example, the irqsoff tracer
must stop recording max latencies when tracing is stopped.
Signed-off-by: Steven Rostedt <srostedt@redhat.com>
Signed-off-by: Ingo Molnar <mingo@elte.hu>
2008-11-06 04:05:44 +07:00
|
|
|
.start = irqsoff_tracer_start,
|
|
|
|
.stop = irqsoff_tracer_stop,
|
2012-10-02 15:27:10 +07:00
|
|
|
.print_max = true,
|
2010-04-03 00:01:22 +07:00
|
|
|
.print_header = irqsoff_print_header,
|
|
|
|
.print_line = irqsoff_print_line,
|
2013-03-14 23:10:40 +07:00
|
|
|
.flag_changed = irqsoff_flag_changed,
|
2008-05-13 02:20:44 +07:00
|
|
|
#ifdef CONFIG_FTRACE_SELFTEST
|
|
|
|
.selftest = trace_selftest_startup_irqsoff,
|
|
|
|
#endif
|
2010-04-03 00:01:22 +07:00
|
|
|
.open = irqsoff_trace_open,
|
|
|
|
.close = irqsoff_trace_close,
|
2014-01-14 21:32:58 +07:00
|
|
|
.allow_instances = true,
|
2012-10-02 15:27:10 +07:00
|
|
|
.use_max_tr = true,
|
2008-05-13 02:20:42 +07:00
|
|
|
};
|
2018-07-31 05:24:23 +07:00
|
|
|
#endif /* CONFIG_IRQSOFF_TRACER */
|
2008-05-13 02:20:42 +07:00
|
|
|
|
|
|
|
#ifdef CONFIG_PREEMPT_TRACER
|
2018-08-09 08:28:05 +07:00
|
|
|
void tracer_preempt_on(unsigned long a0, unsigned long a1)
|
2018-07-31 05:24:23 +07:00
|
|
|
{
|
tracing/irqsoff: Handle preempt_count for different configs
I was hitting the following warning:
WARNING: CPU: 0 PID: 1 at kernel/trace/trace_irqsoff.c:631 tracer_hardirqs_off+0x15/0x2a
Modules linked in:
CPU: 0 PID: 1 Comm: swapper/0 Not tainted 4.18.0-rc6-test+ #13
Hardware name: MSI MS-7823/CSM-H87M-G43 (MS-7823), BIOS V1.6 02/22/2014
EIP: tracer_hardirqs_off+0x15/0x2a
Code: ff 85 c0 74 0e 8b 45 00 8b 50 04 8b 45 04 e8 35 ff ff ff 5d c3 55 64 a1 cc 37 51 c1 a9 ff ff ff 7f 89 e5 53 89 d3 89 ca 75 02 <0f> 0b e8 90 fc ff ff 85 c0 74 07 89 d8 e8 0c ff ff ff 5b 5d c3 55
EAX: 80000000 EBX: c04337f0 ECX: c04338e3 EDX: c04338e3
ESI: c04337f0 EDI: c04338e3 EBP: f2aa1d68 ESP: f2aa1d64
DS: 007b ES: 007b FS: 00d8 GS: 00e0 SS: 0068 EFLAGS: 00210046
CR0: 80050033 CR2: 00000000 CR3: 01668000 CR4: 001406f0
Call Trace:
trace_irq_disable_rcuidle+0x63/0x6c
trace_hardirqs_off+0x26/0x30
default_send_IPI_mask_allbutself_logical+0x31/0x93
default_send_IPI_allbutself+0x37/0x48
native_send_call_func_ipi+0x4d/0x6a
smp_call_function_many+0x165/0x19d
? add_nops+0x34/0x34
? trace_hardirqs_on_caller+0x2d/0x2d
? add_nops+0x34/0x34
smp_call_function+0x1f/0x23
on_each_cpu+0x15/0x43
? trace_hardirqs_on_caller+0x2d/0x2d
? trace_hardirqs_on_caller+0x2d/0x2d
? trace_irq_disable_rcuidle+0x1/0x6c
text_poke_bp+0xa0/0xc2
? trace_hardirqs_on_caller+0x2d/0x2d
arch_jump_label_transform+0xa7/0xcb
? trace_irq_disable_rcuidle+0x5/0x6c
__jump_label_update+0x3e/0x6d
jump_label_update+0x7d/0x81
static_key_slow_inc_cpuslocked+0x58/0x6d
static_key_slow_inc+0x19/0x20
tracepoint_probe_register_prio+0x19e/0x1d1
? start_critical_timings+0x1c/0x1c
tracepoint_probe_register+0xf/0x11
irqsoff_tracer_init+0x21/0xf2
tracer_init+0x16/0x1a
trace_selftest_startup_irqsoff+0x25/0xc4
run_tracer_selftest+0xca/0x131
register_tracer+0xd5/0x172
? trace_event_define_fields_preemptirq_template+0x45/0x45
init_irqsoff_tracer+0xd/0x11
do_one_initcall+0xab/0x1e8
? rcu_read_lock_sched_held+0x3d/0x44
? trace_initcall_level+0x52/0x86
kernel_init_freeable+0x195/0x21a
? rest_init+0xb4/0xb4
kernel_init+0xd/0xe4
ret_from_fork+0x2e/0x38
It is due to running a CONFIG_PREEMPT_VOLUNTARY kernel, which would trigger
this warning every time:
WARN_ON_ONCE(preempt_count());
Because on CONFIG_PREEMPT_VOLUNTARY, preempt_count() is always zero.
This warning is to make sure preempt_count is set because
tracer_hardirqs_on() does a preempt_enable_notrace() to make the
preempt_trace() work properly, as being called by a trace event, the trace
event code disables preemption, and the tracer wants to know what the
preemption was before it was called.
Instead of enabling preemption like this, just record the preempt_count,
subtract PREEMPT_DISABLE_OFFSET from it (which is zero with !CONFIG_PREEMPT
set), and pass that value to the necessary functions, which should use the
passed in parameter instead of calling preempt_count() directly.
Fixes: da5b3ebb45277 ("tracing: irqsoff: Account for additional preempt_disable")
Signed-off-by: Steven Rostedt (VMware) <rostedt@goodmis.org>
2018-08-08 04:03:12 +07:00
|
|
|
int pc = preempt_count();
|
|
|
|
|
|
|
|
if (preempt_trace(pc) && !irq_trace())
|
|
|
|
stop_critical_timing(a0, a1, pc);
|
2018-07-31 05:24:23 +07:00
|
|
|
}
|
|
|
|
|
2018-08-09 08:28:05 +07:00
|
|
|
void tracer_preempt_off(unsigned long a0, unsigned long a1)
|
2018-07-31 05:24:23 +07:00
|
|
|
{
|
tracing/irqsoff: Handle preempt_count for different configs
I was hitting the following warning:
WARNING: CPU: 0 PID: 1 at kernel/trace/trace_irqsoff.c:631 tracer_hardirqs_off+0x15/0x2a
Modules linked in:
CPU: 0 PID: 1 Comm: swapper/0 Not tainted 4.18.0-rc6-test+ #13
Hardware name: MSI MS-7823/CSM-H87M-G43 (MS-7823), BIOS V1.6 02/22/2014
EIP: tracer_hardirqs_off+0x15/0x2a
Code: ff 85 c0 74 0e 8b 45 00 8b 50 04 8b 45 04 e8 35 ff ff ff 5d c3 55 64 a1 cc 37 51 c1 a9 ff ff ff 7f 89 e5 53 89 d3 89 ca 75 02 <0f> 0b e8 90 fc ff ff 85 c0 74 07 89 d8 e8 0c ff ff ff 5b 5d c3 55
EAX: 80000000 EBX: c04337f0 ECX: c04338e3 EDX: c04338e3
ESI: c04337f0 EDI: c04338e3 EBP: f2aa1d68 ESP: f2aa1d64
DS: 007b ES: 007b FS: 00d8 GS: 00e0 SS: 0068 EFLAGS: 00210046
CR0: 80050033 CR2: 00000000 CR3: 01668000 CR4: 001406f0
Call Trace:
trace_irq_disable_rcuidle+0x63/0x6c
trace_hardirqs_off+0x26/0x30
default_send_IPI_mask_allbutself_logical+0x31/0x93
default_send_IPI_allbutself+0x37/0x48
native_send_call_func_ipi+0x4d/0x6a
smp_call_function_many+0x165/0x19d
? add_nops+0x34/0x34
? trace_hardirqs_on_caller+0x2d/0x2d
? add_nops+0x34/0x34
smp_call_function+0x1f/0x23
on_each_cpu+0x15/0x43
? trace_hardirqs_on_caller+0x2d/0x2d
? trace_hardirqs_on_caller+0x2d/0x2d
? trace_irq_disable_rcuidle+0x1/0x6c
text_poke_bp+0xa0/0xc2
? trace_hardirqs_on_caller+0x2d/0x2d
arch_jump_label_transform+0xa7/0xcb
? trace_irq_disable_rcuidle+0x5/0x6c
__jump_label_update+0x3e/0x6d
jump_label_update+0x7d/0x81
static_key_slow_inc_cpuslocked+0x58/0x6d
static_key_slow_inc+0x19/0x20
tracepoint_probe_register_prio+0x19e/0x1d1
? start_critical_timings+0x1c/0x1c
tracepoint_probe_register+0xf/0x11
irqsoff_tracer_init+0x21/0xf2
tracer_init+0x16/0x1a
trace_selftest_startup_irqsoff+0x25/0xc4
run_tracer_selftest+0xca/0x131
register_tracer+0xd5/0x172
? trace_event_define_fields_preemptirq_template+0x45/0x45
init_irqsoff_tracer+0xd/0x11
do_one_initcall+0xab/0x1e8
? rcu_read_lock_sched_held+0x3d/0x44
? trace_initcall_level+0x52/0x86
kernel_init_freeable+0x195/0x21a
? rest_init+0xb4/0xb4
kernel_init+0xd/0xe4
ret_from_fork+0x2e/0x38
It is due to running a CONFIG_PREEMPT_VOLUNTARY kernel, which would trigger
this warning every time:
WARN_ON_ONCE(preempt_count());
Because on CONFIG_PREEMPT_VOLUNTARY, preempt_count() is always zero.
This warning is to make sure preempt_count is set because
tracer_hardirqs_on() does a preempt_enable_notrace() to make the
preempt_trace() work properly, as being called by a trace event, the trace
event code disables preemption, and the tracer wants to know what the
preemption was before it was called.
Instead of enabling preemption like this, just record the preempt_count,
subtract PREEMPT_DISABLE_OFFSET from it (which is zero with !CONFIG_PREEMPT
set), and pass that value to the necessary functions, which should use the
passed in parameter instead of calling preempt_count() directly.
Fixes: da5b3ebb45277 ("tracing: irqsoff: Account for additional preempt_disable")
Signed-off-by: Steven Rostedt (VMware) <rostedt@goodmis.org>
2018-08-08 04:03:12 +07:00
|
|
|
int pc = preempt_count();
|
|
|
|
|
|
|
|
if (preempt_trace(pc) && !irq_trace())
|
|
|
|
start_critical_timing(a0, a1, pc);
|
2018-07-31 05:24:23 +07:00
|
|
|
}
|
|
|
|
|
2008-11-16 11:57:26 +07:00
|
|
|
static int preemptoff_tracer_init(struct trace_array *tr)
|
2008-05-13 02:20:42 +07:00
|
|
|
{
|
|
|
|
trace_type = TRACER_PREEMPT_OFF;
|
|
|
|
|
2014-01-14 21:32:58 +07:00
|
|
|
return __irqsoff_tracer_init(tr);
|
2008-05-13 02:20:42 +07:00
|
|
|
}
|
|
|
|
|
2018-06-29 01:21:45 +07:00
|
|
|
static void preemptoff_tracer_reset(struct trace_array *tr)
|
|
|
|
{
|
|
|
|
__irqsoff_tracer_reset(tr);
|
|
|
|
}
|
|
|
|
|
2008-05-13 02:20:42 +07:00
|
|
|
static struct tracer preemptoff_tracer __read_mostly =
|
|
|
|
{
|
|
|
|
.name = "preemptoff",
|
|
|
|
.init = preemptoff_tracer_init,
|
2018-06-29 01:21:45 +07:00
|
|
|
.reset = preemptoff_tracer_reset,
|
ftrace: restructure tracing start/stop infrastructure
Impact: change where tracing is started up and stopped
Currently, when a new tracer is selected via echo'ing a tracer name into
the current_tracer file, the startup is only done if tracing_enabled is
set to one. If tracing_enabled is changed to zero (by echo'ing 0 into
the tracing_enabled file) a full shutdown is performed.
The full startup and shutdown of a tracer can be expensive and the
user can lose out traces when echo'ing in 0 to the tracing_enabled file,
because the process takes too long. There can also be places that
the user would like to start and stop the tracer several times and
doing the full startup and shutdown of a tracer might be too expensive.
This patch performs the full startup and shutdown when a tracer is
selected. It also adds a way to do a quick start or stop of a tracer.
The quick version is just a flag that prevents the tracing from
taking place, but the overhead of the code is still there.
For example, the startup of a tracer may enable tracepoints, or enable
the function tracer. The stop and start will just set a flag to
have the tracer ignore the calls when the tracepoint or function trace
is called. The overhead of the tracer may still be present when
the tracer is stopped, but no tracing will occur. Setting the tracer
to the 'nop' tracer (or any other tracer) will perform the shutdown
of the tracer which will disable the tracepoint or disable the
function tracer.
The tracing_enabled file will simply start or stop tracing.
This change is all internal. The end result for the user should be the same
as before. If tracing_enabled is not set, no trace will happen.
If tracing_enabled is set, then the trace will happen. The tracing_enabled
variable is static between tracers. Enabling tracing_enabled and
going to another tracer will keep tracing_enabled enabled. Same
is true with disabling tracing_enabled.
This patch will now provide a fast start/stop method to the users
for enabling or disabling tracing.
Note: There were two methods to the struct tracer that were never
used: The methods start and stop. These were to be used as a hook
to the reading of the trace output, but ended up not being
necessary. These two methods are now used to enable the start
and stop of each tracer, in case the tracer needs to do more than
just not write into the buffer. For example, the irqsoff tracer
must stop recording max latencies when tracing is stopped.
Signed-off-by: Steven Rostedt <srostedt@redhat.com>
Signed-off-by: Ingo Molnar <mingo@elte.hu>
2008-11-06 04:05:44 +07:00
|
|
|
.start = irqsoff_tracer_start,
|
|
|
|
.stop = irqsoff_tracer_stop,
|
2012-10-02 15:27:10 +07:00
|
|
|
.print_max = true,
|
2010-04-03 00:01:22 +07:00
|
|
|
.print_header = irqsoff_print_header,
|
|
|
|
.print_line = irqsoff_print_line,
|
2013-03-14 23:10:40 +07:00
|
|
|
.flag_changed = irqsoff_flag_changed,
|
2008-05-13 02:20:44 +07:00
|
|
|
#ifdef CONFIG_FTRACE_SELFTEST
|
|
|
|
.selftest = trace_selftest_startup_preemptoff,
|
|
|
|
#endif
|
2010-04-03 00:01:22 +07:00
|
|
|
.open = irqsoff_trace_open,
|
|
|
|
.close = irqsoff_trace_close,
|
2014-01-14 21:32:58 +07:00
|
|
|
.allow_instances = true,
|
2012-10-02 15:27:10 +07:00
|
|
|
.use_max_tr = true,
|
2008-05-13 02:20:42 +07:00
|
|
|
};
|
2018-07-31 05:24:23 +07:00
|
|
|
#endif /* CONFIG_PREEMPT_TRACER */
|
2008-05-13 02:20:42 +07:00
|
|
|
|
2018-07-31 05:24:23 +07:00
|
|
|
#if defined(CONFIG_IRQSOFF_TRACER) && defined(CONFIG_PREEMPT_TRACER)
|
2008-05-13 02:20:42 +07:00
|
|
|
|
2008-11-16 11:57:26 +07:00
|
|
|
static int preemptirqsoff_tracer_init(struct trace_array *tr)
|
2008-05-13 02:20:42 +07:00
|
|
|
{
|
|
|
|
trace_type = TRACER_IRQS_OFF | TRACER_PREEMPT_OFF;
|
|
|
|
|
2014-01-14 21:32:58 +07:00
|
|
|
return __irqsoff_tracer_init(tr);
|
2008-05-13 02:20:42 +07:00
|
|
|
}
|
|
|
|
|
2018-06-29 01:21:45 +07:00
|
|
|
static void preemptirqsoff_tracer_reset(struct trace_array *tr)
|
|
|
|
{
|
|
|
|
__irqsoff_tracer_reset(tr);
|
|
|
|
}
|
|
|
|
|
2008-05-13 02:20:42 +07:00
|
|
|
static struct tracer preemptirqsoff_tracer __read_mostly =
|
|
|
|
{
|
|
|
|
.name = "preemptirqsoff",
|
|
|
|
.init = preemptirqsoff_tracer_init,
|
2018-06-29 01:21:45 +07:00
|
|
|
.reset = preemptirqsoff_tracer_reset,
|
ftrace: restructure tracing start/stop infrastructure
Impact: change where tracing is started up and stopped
Currently, when a new tracer is selected via echo'ing a tracer name into
the current_tracer file, the startup is only done if tracing_enabled is
set to one. If tracing_enabled is changed to zero (by echo'ing 0 into
the tracing_enabled file) a full shutdown is performed.
The full startup and shutdown of a tracer can be expensive and the
user can lose out traces when echo'ing in 0 to the tracing_enabled file,
because the process takes too long. There can also be places that
the user would like to start and stop the tracer several times and
doing the full startup and shutdown of a tracer might be too expensive.
This patch performs the full startup and shutdown when a tracer is
selected. It also adds a way to do a quick start or stop of a tracer.
The quick version is just a flag that prevents the tracing from
taking place, but the overhead of the code is still there.
For example, the startup of a tracer may enable tracepoints, or enable
the function tracer. The stop and start will just set a flag to
have the tracer ignore the calls when the tracepoint or function trace
is called. The overhead of the tracer may still be present when
the tracer is stopped, but no tracing will occur. Setting the tracer
to the 'nop' tracer (or any other tracer) will perform the shutdown
of the tracer which will disable the tracepoint or disable the
function tracer.
The tracing_enabled file will simply start or stop tracing.
This change is all internal. The end result for the user should be the same
as before. If tracing_enabled is not set, no trace will happen.
If tracing_enabled is set, then the trace will happen. The tracing_enabled
variable is static between tracers. Enabling tracing_enabled and
going to another tracer will keep tracing_enabled enabled. Same
is true with disabling tracing_enabled.
This patch will now provide a fast start/stop method to the users
for enabling or disabling tracing.
Note: There were two methods to the struct tracer that were never
used: The methods start and stop. These were to be used as a hook
to the reading of the trace output, but ended up not being
necessary. These two methods are now used to enable the start
and stop of each tracer, in case the tracer needs to do more than
just not write into the buffer. For example, the irqsoff tracer
must stop recording max latencies when tracing is stopped.
Signed-off-by: Steven Rostedt <srostedt@redhat.com>
Signed-off-by: Ingo Molnar <mingo@elte.hu>
2008-11-06 04:05:44 +07:00
|
|
|
.start = irqsoff_tracer_start,
|
|
|
|
.stop = irqsoff_tracer_stop,
|
2012-10-02 15:27:10 +07:00
|
|
|
.print_max = true,
|
2010-04-03 00:01:22 +07:00
|
|
|
.print_header = irqsoff_print_header,
|
|
|
|
.print_line = irqsoff_print_line,
|
2013-03-14 23:10:40 +07:00
|
|
|
.flag_changed = irqsoff_flag_changed,
|
2008-05-13 02:20:44 +07:00
|
|
|
#ifdef CONFIG_FTRACE_SELFTEST
|
|
|
|
.selftest = trace_selftest_startup_preemptirqsoff,
|
|
|
|
#endif
|
2010-04-03 00:01:22 +07:00
|
|
|
.open = irqsoff_trace_open,
|
|
|
|
.close = irqsoff_trace_close,
|
2014-01-14 21:32:58 +07:00
|
|
|
.allow_instances = true,
|
2012-10-02 15:27:10 +07:00
|
|
|
.use_max_tr = true,
|
2008-05-13 02:20:42 +07:00
|
|
|
};
|
|
|
|
#endif
|
2008-05-13 02:20:42 +07:00
|
|
|
|
|
|
|
__init static int init_irqsoff_tracer(void)
|
|
|
|
{
|
2018-07-31 05:24:23 +07:00
|
|
|
#ifdef CONFIG_IRQSOFF_TRACER
|
|
|
|
register_tracer(&irqsoff_tracer);
|
2017-10-06 07:54:31 +07:00
|
|
|
#endif
|
2018-07-31 05:24:23 +07:00
|
|
|
#ifdef CONFIG_PREEMPT_TRACER
|
|
|
|
register_tracer(&preemptoff_tracer);
|
2017-10-06 07:54:31 +07:00
|
|
|
#endif
|
2018-07-31 05:24:23 +07:00
|
|
|
#if defined(CONFIG_IRQSOFF_TRACER) && defined(CONFIG_PREEMPT_TRACER)
|
|
|
|
register_tracer(&preemptirqsoff_tracer);
|
2017-10-06 07:54:31 +07:00
|
|
|
#endif
|
|
|
|
|
2018-07-31 05:24:23 +07:00
|
|
|
return 0;
|
2017-10-06 07:54:31 +07:00
|
|
|
}
|
2018-07-31 05:24:23 +07:00
|
|
|
core_initcall(init_irqsoff_tracer);
|
|
|
|
#endif /* IRQSOFF_TRACER || PREEMPTOFF_TRACER */
|