tracing: Fixes old and new

Linus,

Here's two fixes:

1) Discovered by Fengguang Wu's tests. I changed the parameters to the function graph x86 prepare_ftrace_return() call but forgot to update the call from entry_32 (i386 version). This patch corrects that.

2) I was tracing some code and found that the sched_switch tracepoint was showing tasks in the INTERRUPTIBLE state as RUNNING. This was due to the updates to convert preempt_count into a per_cpu variable. The tracepoint logic was made to use the task's saved_preempt_count which could hold a stale "PREEMPT_ACTIVE", instead of using the current preempt_count() call.

Please pull the latest trace-fixes-v3.18 tree, which can be found at:

git://git.kernel.org/pub/scm/linux/kernel/git/rostedt/linux-trace.git
trace-fixes-v3.18

Tag SHA1: acbe5cd526bb9de84fe73d68f8d7bfcbde8ab9f4 Head SHA1: aee4e5f3d3abb7a2239dd02f6d8fb173413fd02f

Steven Rostedt (Red Hat) (2):
ftrace/x86: Update i386 call to prepare_ftrace_return() tracing/sched: Check preempt_count() for current when reading task->state

----

 arch/x86/kernel/entry_32.S   | 6 +++---
 include/trace/events/sched.h | 2 +-
 2 files changed, 4 insertions(+), 4 deletions(-)

From: "Steven Rostedt (Red Hat)" <[email protected]>

The parameters for prepare_ftrace_return() used by the function graph tracer were swapped to simplify the code on x86_64. But i386 function graph trampoline also calls this function, and it did not have its parameters swapped.

---
 arch/x86/kernel/entry_32.S | 6 +++---
 1 file changed, 3 insertions(+), 3 deletions(-)

index b553ed89e5f5..df3e608d409b 100644
@@ -1192,10 +1192,10 @@ ENTRY(ftrace_graph_caller)
 	pushl %eax
 	pushl %ecx
 	pushl %edx
-	movl 0xc(%esp), %edx
-	lea 0x4(%ebp), %eax
+	movl 0xc(%esp), %eax
+	lea 0x4(%ebp), %edx
 	movl (%ebp), %ecx
-	subl $MCOUNT_INSN_SIZE, %edx
+	subl $MCOUNT_INSN_SIZE, %eax
 	call prepare_ftrace_return
 	popl %edx
 	popl %ecx

2.1.3

From: "Steven Rostedt (Red Hat)" <[email protected]>

When recording the state of a task for the sched_switch tracepoint a check of task_preempt_count() is performed to see if PREEMPT_ACTIVE is set. This is because, technically, a task being preempted is really in the TASK_RUNNING state, and that is what should be recorded when tracing a sched_switch, even if the task put itself into another state (it hasn't scheduled out in that state yet).

But with the change to use per_cpu preempt counts, the task_thread_info(p)->preempt_count is no longer used, and instead task_preempt_count(p) is used.

The problem is that this does not use the current preempt count but a stale one from a previous sched_switch. The task_preempt_count(p) uses saved_preempt_count and not preempt_count(). But for tracing sched_switch, if p is current, we really want preempt_count().

I hit this bug when I was tracing sleep and the call from do_nanosleep() scheduled out in the "RUNNING" state.

           sleep-4290  [000] 537272.259992: sched_switch:         sleep:4290 [120] R ==> swapper/0:0 [120]
           sleep-4290  [000] 537272.260015: kernel_stack:         <stack trace>

=> __schedule (ffffffff8150864a)
=> schedule (ffffffff815089f8)
=> do_nanosleep (ffffffff8150b76c)
=> hrtimer_nanosleep (ffffffff8108d66b)
=> SyS_nanosleep (ffffffff8108d750)
=> return_to_handler (ffffffff8150e8e5)
=> tracesys_phase2 (ffffffff8150c844)

After a bit of hair pulling, I found that the state was really TASK_INTERRUPTIBLE, but the saved_preempt_count had an old PREEMPT_ACTIVE set and caused the sched_switch tracepoint to show it as RUNNING.

---
 include/trace/events/sched.h | 2 +-
 1 file changed, 1 insertion(+), 1 deletion(-)

index 0a68d5ae584e..a7d67bc14906 100644
@@ -100,7 +100,7 @@ static inline long __trace_sched_switch_state(struct task_struct *p)
 	/*
 	 * For all intents and purposes a preempted task is a running task.
 	 */
-	if (task_preempt_count(p) & PREEMPT_ACTIVE)
+	if (preempt_count() & PREEMPT_ACTIVE)
 		state = TASK_RUNNING | TASK_STATE_MAX;
 #endif
 

2.1.3