From: Steven Rostedt <rostedt@goodmis.org>
To: linux-kernel@vger.kernel.org
Cc: Ingo Molnar <mingo@kernel.org>,
Andrew Morton <akpm@linux-foundation.org>
Subject: [for-next][PATCH 29/34] tracing/irqsoff: Handle preempt_count for different configs
Date: Sat, 11 Aug 2018 09:49:57 -0400 [thread overview]
Message-ID: <20180811135016.192087988@goodmis.org> (raw)
In-Reply-To: 20180811134928.034373761@goodmis.org
From: "Steven Rostedt (VMware)" <rostedt@goodmis.org>
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>
---
kernel/trace/trace_irqsoff.c | 66 ++++++++++++++++++++----------------
1 file changed, 37 insertions(+), 29 deletions(-)
diff --git a/kernel/trace/trace_irqsoff.c b/kernel/trace/trace_irqsoff.c
index ffbf1505d5bc..4af990e9c594 100644
--- a/kernel/trace/trace_irqsoff.c
+++ b/kernel/trace/trace_irqsoff.c
@@ -40,12 +40,12 @@ static int start_irqsoff_tracer(struct trace_array *tr, int graph);
#ifdef CONFIG_PREEMPT_TRACER
static inline int
-preempt_trace(void)
+preempt_trace(int pc)
{
- return ((trace_type & TRACER_PREEMPT_OFF) && preempt_count());
+ return ((trace_type & TRACER_PREEMPT_OFF) && pc);
}
#else
-# define preempt_trace() (0)
+# define preempt_trace(pc) (0)
#endif
#ifdef CONFIG_IRQSOFF_TRACER
@@ -366,7 +366,7 @@ check_critical_timing(struct trace_array *tr,
}
static inline void
-start_critical_timing(unsigned long ip, unsigned long parent_ip)
+start_critical_timing(unsigned long ip, unsigned long parent_ip, int pc)
{
int cpu;
struct trace_array *tr = irqsoff_trace;
@@ -394,7 +394,7 @@ start_critical_timing(unsigned long ip, unsigned long parent_ip)
local_save_flags(flags);
- __trace_function(tr, ip, parent_ip, flags, preempt_count());
+ __trace_function(tr, ip, parent_ip, flags, pc);
per_cpu(tracing_cpu, cpu) = 1;
@@ -402,7 +402,7 @@ start_critical_timing(unsigned long ip, unsigned long parent_ip)
}
static inline void
-stop_critical_timing(unsigned long ip, unsigned long parent_ip)
+stop_critical_timing(unsigned long ip, unsigned long parent_ip, int pc)
{
int cpu;
struct trace_array *tr = irqsoff_trace;
@@ -428,7 +428,7 @@ stop_critical_timing(unsigned long ip, unsigned long parent_ip)
atomic_inc(&data->disabled);
local_save_flags(flags);
- __trace_function(tr, ip, parent_ip, flags, preempt_count());
+ __trace_function(tr, ip, parent_ip, flags, pc);
check_critical_timing(tr, data, parent_ip ? : ip, cpu);
data->critical_start = 0;
atomic_dec(&data->disabled);
@@ -437,15 +437,19 @@ stop_critical_timing(unsigned long ip, unsigned long parent_ip)
/* start and stop critical timings used to for stoppage (in idle) */
void start_critical_timings(void)
{
- if (preempt_trace() || irq_trace())
- start_critical_timing(CALLER_ADDR0, CALLER_ADDR1);
+ int pc = preempt_count();
+
+ if (preempt_trace(pc) || irq_trace())
+ start_critical_timing(CALLER_ADDR0, CALLER_ADDR1, pc);
}
EXPORT_SYMBOL_GPL(start_critical_timings);
void stop_critical_timings(void)
{
- if (preempt_trace() || irq_trace())
- stop_critical_timing(CALLER_ADDR0, CALLER_ADDR1);
+ int pc = preempt_count();
+
+ if (preempt_trace(pc) || irq_trace())
+ stop_critical_timing(CALLER_ADDR0, CALLER_ADDR1, pc);
}
EXPORT_SYMBOL_GPL(stop_critical_timings);
@@ -603,40 +607,40 @@ static void irqsoff_tracer_stop(struct trace_array *tr)
*/
static void tracer_hardirqs_on(void *none, unsigned long a0, unsigned long a1)
{
+ unsigned int pc = preempt_count();
+
/*
* Tracepoint probes are expected to be called with preempt disabled,
* We don't care about being called with preempt disabled but we need
* to know in the future if that changes so we can remove the next
* preempt_enable.
*/
- WARN_ON_ONCE(!preempt_count());
-
- /* Tracepoint probes disable preemption atleast once, account for that */
- preempt_enable_notrace();
+ WARN_ON_ONCE(pc < PREEMPT_DISABLE_OFFSET);
- if (!preempt_trace() && irq_trace())
- stop_critical_timing(a0, a1);
+ /* Use PREEMPT_DISABLE_OFFSET to handle !CONFIG_PREEMPT cases */
+ pc -= PREEMPT_DISABLE_OFFSET;
- preempt_disable_notrace();
+ if (!preempt_trace(pc) && irq_trace())
+ stop_critical_timing(a0, a1, pc);
}
static void tracer_hardirqs_off(void *none, unsigned long a0, unsigned long a1)
{
+ unsigned int pc = preempt_count();
+
/*
* Tracepoint probes are expected to be called with preempt disabled,
* We don't care about being called with preempt disabled but we need
* to know in the future if that changes so we can remove the next
* preempt_enable.
*/
- WARN_ON_ONCE(!preempt_count());
-
- /* Tracepoint probes disable preemption atleast once, account for that */
- preempt_enable_notrace();
+ WARN_ON_ONCE(pc < PREEMPT_DISABLE_OFFSET);
- if (!preempt_trace() && irq_trace())
- start_critical_timing(a0, a1);
+ /* Use PREEMPT_DISABLE_OFFSET to handle !CONFIG_PREEMPT cases */
+ pc -= PREEMPT_DISABLE_OFFSET;
- preempt_disable_notrace();
+ if (!preempt_trace(pc) && irq_trace())
+ start_critical_timing(a0, a1, pc);
}
static int irqsoff_tracer_init(struct trace_array *tr)
@@ -679,14 +683,18 @@ static struct tracer irqsoff_tracer __read_mostly =
#ifdef CONFIG_PREEMPT_TRACER
static void tracer_preempt_on(void *none, unsigned long a0, unsigned long a1)
{
- if (preempt_trace() && !irq_trace())
- stop_critical_timing(a0, a1);
+ int pc = preempt_count();
+
+ if (preempt_trace(pc) && !irq_trace())
+ stop_critical_timing(a0, a1, pc);
}
static void tracer_preempt_off(void *none, unsigned long a0, unsigned long a1)
{
- if (preempt_trace() && !irq_trace())
- start_critical_timing(a0, a1);
+ int pc = preempt_count();
+
+ if (preempt_trace(pc) && !irq_trace())
+ start_critical_timing(a0, a1, pc);
}
static int preemptoff_tracer_init(struct trace_array *tr)
--
2.18.0
next prev parent reply other threads:[~2018-08-11 13:51 UTC|newest]
Thread overview: 35+ messages / expand[flat|nested] mbox.gz Atom feed top
2018-08-11 13:49 [for-next][PATCH 00/34] tracing: My official queue finally passed testing and ready for linux-next Steven Rostedt
2018-08-11 13:49 ` [for-next][PATCH 01/34] srcu: Add notrace variants of srcu_read_{lock,unlock} Steven Rostedt
2018-08-11 13:49 ` [for-next][PATCH 02/34] srcu: Add notrace variant of srcu_dereference Steven Rostedt
2018-08-11 13:49 ` [for-next][PATCH 03/34] tracing/irqsoff: Split reset into separate functions Steven Rostedt
2018-08-11 13:49 ` [for-next][PATCH 04/34] lib: Add module for testing preemptoff/irqsoff latency tracers Steven Rostedt
2018-08-11 13:49 ` [for-next][PATCH 05/34] kselftests: Add tests for the preemptoff and irqsoff tracers Steven Rostedt
2018-08-11 13:49 ` [for-next][PATCH 06/34] tracing: Make unregister_trigger() static Steven Rostedt
2018-08-11 13:49 ` [for-next][PATCH 07/34] tracing: Remove orphaned function using_ftrace_ops_list_func() Steven Rostedt
2018-08-11 13:49 ` [for-next][PATCH 08/34] tracing: Remove orphaned function ftrace_nr_registered_ops() Steven Rostedt
2018-08-11 13:49 ` [for-next][PATCH 09/34] tracing/kprobes: Simplify the logic of enable_trace_kprobe() Steven Rostedt
2018-08-11 13:49 ` [for-next][PATCH 10/34] tracing: preemptirq_delay_run() can be static Steven Rostedt
2018-08-11 13:49 ` [for-next][PATCH 11/34] tracing: kprobes: Prohibit probing on notrace function Steven Rostedt
2018-08-11 13:49 ` [for-next][PATCH 12/34] selftest/ftrace: Move kprobe selftest function to separate compile unit Steven Rostedt
2018-08-11 13:49 ` [for-next][PATCH 13/34] selftests/ftrace: Fix kprobe string testcase to not probe notrace function Steven Rostedt
2018-08-11 13:49 ` [for-next][PATCH 14/34] lockdep: Use this_cpu_ptr instead of get_cpu_var stats Steven Rostedt
2018-08-11 13:49 ` [for-next][PATCH 15/34] tracepoint: Make rcuidle tracepoint callers use SRCU Steven Rostedt
2018-08-11 13:49 ` [for-next][PATCH 16/34] tracing: Centralize preemptirq tracepoints and unify their usage Steven Rostedt
2018-08-11 13:49 ` [for-next][PATCH 17/34] tracefs: Annotate tracefs_ops with __ro_after_init Steven Rostedt
2018-08-11 13:49 ` [for-next][PATCH 18/34] tracing: Do not call start/stop() functions when tracing_on does not change Steven Rostedt
2018-08-11 13:49 ` [for-next][PATCH 19/34] ftrace: Add missing check for existing hwlat thread Steven Rostedt
2018-08-11 13:49 ` [for-next][PATCH 20/34] tracing: Do a WARN_ON() if start_thread() in hwlat is called when thread exists Steven Rostedt
2018-08-11 13:49 ` [for-next][PATCH 21/34] tracing: Make tracer_tracing_is_on() return bool Steven Rostedt
2018-08-11 13:49 ` [for-next][PATCH 22/34] ring-buffer: Make ring_buffer_record_is_on() " Steven Rostedt
2018-08-11 13:49 ` [for-next][PATCH 23/34] ring-buffer: Make ring_buffer_record_is_set_on() " Steven Rostedt
2018-08-11 13:49 ` [for-next][PATCH 24/34] ftrace: Use true and false for boolean values in ops_references_rec() Steven Rostedt
2018-08-11 13:49 ` [for-next][PATCH 25/34] tracing/kprobes: Fix within_notrace_func() to check only notrace functions Steven Rostedt
2018-08-11 13:49 ` [for-next][PATCH 26/34] trace: Use rcu_dereference_raw for hooks from trace-event subsystem Steven Rostedt
2018-08-11 13:49 ` [for-next][PATCH 27/34] tracing: irqsoff: Account for additional preempt_disable Steven Rostedt
2018-08-11 13:49 ` [for-next][PATCH 28/34] tracing: Partial revert of "tracing: Centralize preemptirq tracepoints and unify their usage" Steven Rostedt
2018-08-11 13:49 ` Steven Rostedt [this message]
2018-08-11 13:49 ` [for-next][PATCH 30/34] tracing: More reverting " Steven Rostedt
2018-08-11 13:49 ` [for-next][PATCH 31/34] ftrace: Remove unused pointer ftrace_swapper_pid Steven Rostedt
2018-08-11 13:50 ` [for-next][PATCH 32/34] tracing: Fix synchronizing to event changes with tracepoint_synchronize_unregister() Steven Rostedt
2018-08-11 13:50 ` [for-next][PATCH 33/34] uprobes: Use synchronize_rcu() not synchronize_sched() Steven Rostedt
2018-08-11 13:50 ` [for-next][PATCH 34/34] tracepoints: Free early tracepoints after RCU is initialized Steven Rostedt
Reply instructions:
You may reply publicly to this message via plain-text email
using any one of the following methods:
* Save the following mbox file, import it into your mail client,
and reply-to-all from there: mbox
Avoid top-posting and favor interleaved quoting:
https://en.wikipedia.org/wiki/Posting_style#Interleaved_style
* Reply using the --to, --cc, and --in-reply-to
switches of git-send-email(1):
git send-email \
--in-reply-to=20180811135016.192087988@goodmis.org \
--to=rostedt@goodmis.org \
--cc=akpm@linux-foundation.org \
--cc=linux-kernel@vger.kernel.org \
--cc=mingo@kernel.org \
/path/to/YOUR_REPLY
https://kernel.org/pub/software/scm/git/docs/git-send-email.html
* If your mail client supports setting the In-Reply-To header
via mailto: links, try the mailto: link
Be sure your reply has a Subject: header at the top and a blank line
before the message body.
This is a public inbox, see mirroring instructions
for how to clone and mirror all data and code used for this inbox