tracing: Cache comms only after an event occurred

Whenever an event is registered, the comm of tasks are saved at
every task switch instead of saving them at every event. But if
an event isn't executed much, the comm cache will be filled up
by tasks that did not record the event and you lose out on the comms
that did.

Here's an example, if you enable the following events:

echo 1 > /debug/tracing/events/kvm/kvm_cr/enable
echo 1 > /debug/tracing/events/net/net_dev_xmit/enable

Note, there's no kvm running on this machine so the first event will
never be triggered, but because it is enabled, the storing of comms
will continue. If we now disable the network event:

echo 0 > /debug/tracing/events/net/net_dev_xmit/enable

and look at the trace:

cat /debug/tracing/trace
            sshd-2672  [001] ..s2   375.731616: net_dev_xmit: dev=eth0 skbaddr=ffff88005cbb6de0 len=242 rc=0
            sshd-2672  [001] ..s1   375.731617: net_dev_xmit: dev=br0 skbaddr=ffff88005cbb6de0 len=242 rc=0
            sshd-2672  [001] ..s2   375.859356: net_dev_xmit: dev=eth0 skbaddr=ffff88005cbb6de0 len=242 rc=0
            sshd-2672  [001] ..s1   375.859357: net_dev_xmit: dev=br0 skbaddr=ffff88005cbb6de0 len=242 rc=0
            sshd-2672  [001] ..s2   375.947351: net_dev_xmit: dev=eth0 skbaddr=ffff88005cbb6de0 len=242 rc=0
            sshd-2672  [001] ..s1   375.947352: net_dev_xmit: dev=br0 skbaddr=ffff88005cbb6de0 len=242 rc=0
            sshd-2672  [001] ..s2   376.035383: net_dev_xmit: dev=eth0 skbaddr=ffff88005cbb6de0 len=242 rc=0
            sshd-2672  [001] ..s1   376.035383: net_dev_xmit: dev=br0 skbaddr=ffff88005cbb6de0 len=242 rc=0
            sshd-2672  [001] ..s2   377.563806: net_dev_xmit: dev=eth0 skbaddr=ffff88005cbb6de0 len=226 rc=0
            sshd-2672  [001] ..s1   377.563807: net_dev_xmit: dev=br0 skbaddr=ffff88005cbb6de0 len=226 rc=0
            sshd-2672  [001] ..s2   377.563834: net_dev_xmit: dev=eth0 skbaddr=ffff88005cbb6be0 len=114 rc=0
            sshd-2672  [001] ..s1   377.563842: net_dev_xmit: dev=br0 skbaddr=ffff88005cbb6be0 len=114 rc=0

We see that process 2672 which triggered the events has the comm "sshd".
But if we run hackbench for a bit and look again:

cat /debug/tracing/trace
           <...>-2672  [001] ..s2   375.731616: net_dev_xmit: dev=eth0 skbaddr=ffff88005cbb6de0 len=242 rc=0
           <...>-2672  [001] ..s1   375.731617: net_dev_xmit: dev=br0 skbaddr=ffff88005cbb6de0 len=242 rc=0
           <...>-2672  [001] ..s2   375.859356: net_dev_xmit: dev=eth0 skbaddr=ffff88005cbb6de0 len=242 rc=0
           <...>-2672  [001] ..s1   375.859357: net_dev_xmit: dev=br0 skbaddr=ffff88005cbb6de0 len=242 rc=0
           <...>-2672  [001] ..s2   375.947351: net_dev_xmit: dev=eth0 skbaddr=ffff88005cbb6de0 len=242 rc=0
           <...>-2672  [001] ..s1   375.947352: net_dev_xmit: dev=br0 skbaddr=ffff88005cbb6de0 len=242 rc=0
           <...>-2672  [001] ..s2   376.035383: net_dev_xmit: dev=eth0 skbaddr=ffff88005cbb6de0 len=242 rc=0
           <...>-2672  [001] ..s1   376.035383: net_dev_xmit: dev=br0 skbaddr=ffff88005cbb6de0 len=242 rc=0
           <...>-2672  [001] ..s2   377.563806: net_dev_xmit: dev=eth0 skbaddr=ffff88005cbb6de0 len=226 rc=0
           <...>-2672  [001] ..s1   377.563807: net_dev_xmit: dev=br0 skbaddr=ffff88005cbb6de0 len=226 rc=0
           <...>-2672  [001] ..s2   377.563834: net_dev_xmit: dev=eth0 skbaddr=ffff88005cbb6be0 len=114 rc=0
           <...>-2672  [001] ..s1   377.563842: net_dev_xmit: dev=br0 skbaddr=ffff88005cbb6be0 len=114 rc=0

The stored "sshd" comm has been flushed out and we get a useless "<...>".

But by only storing comms after a trace event occurred, we can run
hackbench all day and still get the same output.

Cc: Peter Zijlstra <a.p.zijlstra@chello.nl>
Cc: Thomas Gleixner <tglx@linutronix.de>
Signed-off-by: Steven Rostedt <rostedt@goodmis.org>

diff --git a/kernel/trace/trace.c b/kernel/trace/trace.c
index b90a827a4641b0a53de7dd3203a039a71b3b7ad2..88111b08b2c1d6885c703d3322b274ba425b4db3 100644 (file)
--- a/kernel/trace/trace.c
+++ b/kernel/trace/trace.c
@@ -77,6 +77,13 @@ static int dummy_set_flag(u32 old_flags, u32 bit, int set)
        return 0;
 }
 
+/*
+ * To prevent the comm cache from being overwritten when no
+ * tracing is active, only save the comm when a trace event
+ * occurred.
+ */
+static DEFINE_PER_CPU(bool, trace_cmdline_save);
+
 /*
  * Kill all tracing for good (never come back).
  * It is initialized to 1 but will turn to zero if the initialization
@@ -1135,6 +1142,11 @@ void tracing_record_cmdline(struct task_struct *tsk)
            !tracing_is_on())
                return;
 
+       if (!__this_cpu_read(trace_cmdline_save))
+               return;
+
+       __this_cpu_write(trace_cmdline_save, false);
+
        trace_save_cmdline(tsk);
 }
 
@@ -1178,13 +1190,20 @@ trace_buffer_lock_reserve(struct ring_buffer *buffer,
        return event;
 }
 
+void
+__buffer_unlock_commit(struct ring_buffer *buffer, struct ring_buffer_event *event)
+{
+       __this_cpu_write(trace_cmdline_save, true);
+       ring_buffer_unlock_commit(buffer, event);
+}
+
 static inline void
 __trace_buffer_unlock_commit(struct ring_buffer *buffer,
                             struct ring_buffer_event *event,
                             unsigned long flags, int pc,
                             int wake)
 {
-       ring_buffer_unlock_commit(buffer, event);
+       __buffer_unlock_commit(buffer, event);
 
        ftrace_trace_stack(buffer, flags, 6, pc);
        ftrace_trace_userstack(buffer, flags, pc);
@@ -1232,7 +1251,7 @@ void trace_nowake_buffer_unlock_commit_regs(struct ring_buffer *buffer,
                                            unsigned long flags, int pc,
                                            struct pt_regs *regs)
 {
-       ring_buffer_unlock_commit(buffer, event);
+       __buffer_unlock_commit(buffer, event);
 
        ftrace_trace_stack_regs(buffer, flags, 0, pc, regs);
        ftrace_trace_userstack(buffer, flags, pc);
@@ -1269,7 +1288,7 @@ trace_function(struct trace_array *tr,
        entry->parent_ip                = parent_ip;
 
        if (!filter_check_discard(call, entry, buffer, event))
-               ring_buffer_unlock_commit(buffer, event);
+               __buffer_unlock_commit(buffer, event);
 }
 
 void
@@ -1362,7 +1381,7 @@ static void __ftrace_trace_stack(struct ring_buffer *buffer,
        entry->size = trace.nr_entries;
 
        if (!filter_check_discard(call, entry, buffer, event))
-               ring_buffer_unlock_commit(buffer, event);
+               __buffer_unlock_commit(buffer, event);
 
  out:
        /* Again, don't let gcc optimize things here */
@@ -1458,7 +1477,7 @@ ftrace_trace_userstack(struct ring_buffer *buffer, unsigned long flags, int pc)
 
        save_stack_trace_user(&trace);
        if (!filter_check_discard(call, entry, buffer, event))
-               ring_buffer_unlock_commit(buffer, event);
+               __buffer_unlock_commit(buffer, event);
 
  out_drop_count:
        __this_cpu_dec(user_stack_count);
@@ -1653,7 +1672,7 @@ int trace_vbprintk(unsigned long ip, const char *fmt, va_list args)
 
        memcpy(entry->buf, tbuffer, sizeof(u32) * len);
        if (!filter_check_discard(call, entry, buffer, event)) {
-               ring_buffer_unlock_commit(buffer, event);
+               __buffer_unlock_commit(buffer, event);
                ftrace_trace_stack(buffer, flags, 6, pc);
        }
 
@@ -1724,7 +1743,7 @@ int trace_array_vprintk(struct trace_array *tr,
        memcpy(&entry->buf, tbuffer, len);
        entry->buf[len] = '\0';
        if (!filter_check_discard(call, entry, buffer, event)) {
-               ring_buffer_unlock_commit(buffer, event);
+               __buffer_unlock_commit(buffer, event);
                ftrace_trace_stack(buffer, flags, 6, pc);
        }
  out:
@@ -3993,7 +4012,7 @@ tracing_mark_write(struct file *filp, const char __user *ubuf,
        } else
                entry->buf[cnt] = '\0';
 
-       ring_buffer_unlock_commit(buffer, event);
+       __buffer_unlock_commit(buffer, event);
 
        written = cnt;
 

diff --git a/kernel/trace/trace.h b/kernel/trace/trace.h
index 7824a55bd3fcc43f72adb6737af94da40c56b1e8..839ae003a053345ccc76239d464ae5c9177709c3 100644 (file)
--- a/kernel/trace/trace.h
+++ b/kernel/trace/trace.h
@@ -359,6 +359,9 @@ struct trace_entry *tracing_get_trace_entry(struct trace_array *tr,
 struct trace_entry *trace_find_next_entry(struct trace_iterator *iter,
                                          int *ent_cpu, u64 *ent_ts);
 
+void __buffer_unlock_commit(struct ring_buffer *buffer,
+                           struct ring_buffer_event *event);
+
 int trace_empty(struct trace_iterator *iter);
 
 void *trace_find_next_entry_inc(struct trace_iterator *iter);

diff --git a/kernel/trace/trace_branch.c b/kernel/trace/trace_branch.c
index bd3e0eef4eaacfa71fe69d09483e1ad6a1afa27b..95e96842ed291584e7f6eb592069fbcaf8700891 100644 (file)
--- a/kernel/trace/trace_branch.c
+++ b/kernel/trace/trace_branch.c
@@ -77,7 +77,7 @@ probe_likely_condition(struct ftrace_branch_data *f, int val, int expect)
        entry->correct = val == expect;
 
        if (!filter_check_discard(call, entry, buffer, event))
-               ring_buffer_unlock_commit(buffer, event);
+               __buffer_unlock_commit(buffer, event);
 
  out:
        atomic_dec(&tr->data[cpu]->disabled);

diff --git a/kernel/trace/trace_functions_graph.c b/kernel/trace/trace_functions_graph.c
index a84b55879bc482baddfd1d58632bd80d6f5e0d52..4edb4b74eb7e75ba171240882b20ee14fbb41099 100644 (file)
--- a/kernel/trace/trace_functions_graph.c
+++ b/kernel/trace/trace_functions_graph.c
@@ -223,7 +223,7 @@ int __trace_graph_entry(struct trace_array *tr,
        entry   = ring_buffer_event_data(event);
        entry->graph_ent                        = *trace;
        if (!filter_current_check_discard(buffer, call, entry, event))
-               ring_buffer_unlock_commit(buffer, event);
+               __buffer_unlock_commit(buffer, event);
 
        return 1;
 }
@@ -327,7 +327,7 @@ void __trace_graph_return(struct trace_array *tr,
        entry   = ring_buffer_event_data(event);
        entry->ret                              = *trace;
        if (!filter_current_check_discard(buffer, call, entry, event))
-               ring_buffer_unlock_commit(buffer, event);
+               __buffer_unlock_commit(buffer, event);
 }
 
 void trace_graph_return(struct ftrace_graph_ret *trace)