Merge tag 'trace-v4.3' of git://git.kernel.org/pub/scm/linux/kernel/git/rostedt/linux...
authorLinus Torvalds <torvalds@linux-foundation.org>
Tue, 8 Sep 2015 21:04:14 +0000 (14:04 -0700)
committerLinus Torvalds <torvalds@linux-foundation.org>
Tue, 8 Sep 2015 21:04:14 +0000 (14:04 -0700)
Pull tracing update from Steven Rostedt:
 "Mostly this is just clean ups and micro optimizations.

  The changes with more meat are:

   - Allowing the trace event filters to filter on CPU number and
     process ids

   - Two new markers for trace output latency were added (10 and 100
     msec latencies)

   - Have tracing_thresh filter function profiling time

  I also worked on modifying the ring buffer code for some future work,
  and moved the adding of the timestamp around.  One of my changes
  caused a regression, and since other changes were built on top of it
  and already tested, I had to operate a revert of that change.  Instead
  of rebasing, this change set has the code that caused a regression as
  well as the code to revert that change without touching the other
  changes that were made on top of it"

* tag 'trace-v4.3' of git://git.kernel.org/pub/scm/linux/kernel/git/rostedt/linux-trace:
  ring-buffer: Revert "ring-buffer: Get timestamp after event is allocated"
  tracing: Don't make assumptions about length of string on task rename
  tracing: Allow triggers to filter for CPU ids and process names
  ftrace: Format MCOUNT_ADDR address as type unsigned long
  tracing: Introduce two additional marks for delay
  ftrace: Fix function_graph duration spacing with 7-digits
  ftrace: add tracing_thresh to function profile
  tracing: Clean up stack tracing and fix fentry updates
  ring-buffer: Reorganize function locations
  ring-buffer: Make sure event has enough room for extend and padding
  ring-buffer: Get timestamp after event is allocated
  ring-buffer: Move the adding of the extended timestamp out of line
  ring-buffer: Add event descriptor to simplify passing data
  ftrace: correct the counter increment for trace_buffer data
  tracing: Fix for non-continuous cpu ids
  tracing: Prefer kcalloc over kzalloc with multiply

1  2 
Documentation/trace/ftrace.txt
kernel/trace/ftrace.c

@@@ -346,11 -346,6 +346,11 @@@ of ftrace. Here is a list of some of th
          x86-tsc: Architectures may define their own clocks. For
                   example, x86 uses its own TSC cycle clock here.
  
 +        ppc-tb: This uses the powerpc timebase register value.
 +                This is in sync across CPUs and can also be used
 +                to correlate events across hypervisor/guest if
 +                tb_offset is known.
 +
        To set a clock, simply echo the clock name into this file.
  
          echo global > trace_clock
@@@ -691,6 -686,8 +691,8 @@@ The above is mostly meaningful for kern
         The marks are determined by the difference between this
         current trace and the next trace.
          '$' - greater than 1 second
+         '@' - greater than 100 milisecond
+         '*' - greater than 10 milisecond
          '#' - greater than 1000 microsecond
          '!' - greater than 100 microsecond
          '+' - greater than 10 microsecond
@@@ -1944,26 -1941,49 +1946,49 @@@ want, depending on your needs
  
    ie:
  
-   0)               |    up_write() {
-   0)   0.646 us    |      _spin_lock_irqsave();
-   0)   0.684 us    |      _spin_unlock_irqrestore();
-   0)   3.123 us    |    }
-   0)   0.548 us    |    fput();
-   0) + 58.628 us   |  }
+   3) # 1837.709 us |          } /* __switch_to */
+   3)               |          finish_task_switch() {
+   3)   0.313 us    |            _raw_spin_unlock_irq();
+   3)   3.177 us    |          }
+   3) # 1889.063 us |        } /* __schedule */
+   3) ! 140.417 us  |      } /* __schedule */
+   3) # 2034.948 us |    } /* schedule */
+   3) * 33998.59 us |  } /* schedule_preempt_disabled */
  
    [...]
  
-   0)               |      putname() {
-   0)               |        kmem_cache_free() {
-   0)   0.518 us    |          __phys_addr();
-   0)   1.757 us    |        }
-   0)   2.861 us    |      }
-   0) ! 115.305 us  |    }
-   0) ! 116.402 us  |  }
+   1)   0.260 us    |              msecs_to_jiffies();
+   1)   0.313 us    |              __rcu_read_unlock();
+   1) + 61.770 us   |            }
+   1) + 64.479 us   |          }
+   1)   0.313 us    |          rcu_bh_qs();
+   1)   0.313 us    |          __local_bh_enable();
+   1) ! 217.240 us  |        }
+   1)   0.365 us    |        idle_cpu();
+   1)               |        rcu_irq_exit() {
+   1)   0.417 us    |          rcu_eqs_enter_common.isra.47();
+   1)   3.125 us    |        }
+   1) ! 227.812 us  |      }
+   1) ! 457.395 us  |    }
+   1) @ 119760.2 us |  }
+   [...]
+   2)               |    handle_IPI() {
+   1)   6.979 us    |                  }
+   2)   0.417 us    |      scheduler_ipi();
+   1)   9.791 us    |                }
+   1) + 12.917 us   |              }
+   2)   3.490 us    |    }
+   1) + 15.729 us   |            }
+   1) + 18.542 us   |          }
+   2) $ 3594274 us  |  }
  
    + means that the function exceeded 10 usecs.
    ! means that the function exceeded 100 usecs.
    # means that the function exceeded 1000 usecs.
+   * means that the function exceeded 10 msecs.
+   @ means that the function exceeded 100 msecs.
    $ means that the function exceeded 1 sec.
  
  
diff --combined kernel/trace/ftrace.c
@@@ -98,13 -98,6 +98,13 @@@ struct ftrace_pid 
        struct pid *pid;
  };
  
 +static bool ftrace_pids_enabled(void)
 +{
 +      return !list_empty(&ftrace_pids);
 +}
 +
 +static void ftrace_update_trampoline(struct ftrace_ops *ops);
 +
  /*
   * ftrace_disabled is set when an anomaly is discovered.
   * ftrace_disabled is much stronger than ftrace_enabled.
@@@ -116,6 -109,7 +116,6 @@@ static DEFINE_MUTEX(ftrace_lock)
  static struct ftrace_ops *ftrace_control_list __read_mostly = &ftrace_list_end;
  static struct ftrace_ops *ftrace_ops_list __read_mostly = &ftrace_list_end;
  ftrace_func_t ftrace_trace_function __read_mostly = ftrace_stub;
 -ftrace_func_t ftrace_pid_function __read_mostly = ftrace_stub;
  static struct ftrace_ops global_ops;
  static struct ftrace_ops control_ops;
  
@@@ -189,7 -183,14 +189,7 @@@ static void ftrace_pid_func(unsigned lo
        if (!test_tsk_trace_trace(current))
                return;
  
 -      ftrace_pid_function(ip, parent_ip, op, regs);
 -}
 -
 -static void set_ftrace_pid_function(ftrace_func_t func)
 -{
 -      /* do not set ftrace_pid_function to itself! */
 -      if (func != ftrace_pid_func)
 -              ftrace_pid_function = func;
 +      op->saved_func(ip, parent_ip, op, regs);
  }
  
  /**
  void clear_ftrace_function(void)
  {
        ftrace_trace_function = ftrace_stub;
 -      ftrace_pid_function = ftrace_stub;
  }
  
  static void control_ops_disable_all(struct ftrace_ops *ops)
@@@ -434,12 -436,6 +434,12 @@@ static int __register_ftrace_function(s
        } else
                add_ftrace_ops(&ftrace_ops_list, ops);
  
 +      /* Always save the function, and reset at unregistering */
 +      ops->saved_func = ops->func;
 +
 +      if (ops->flags & FTRACE_OPS_FL_PID && ftrace_pids_enabled())
 +              ops->func = ftrace_pid_func;
 +
        ftrace_update_trampoline(ops);
  
        if (ftrace_enabled)
@@@ -467,28 -463,15 +467,28 @@@ static int __unregister_ftrace_function
        if (ftrace_enabled)
                update_ftrace_function();
  
 +      ops->func = ops->saved_func;
 +
        return 0;
  }
  
  static void ftrace_update_pid_func(void)
  {
 +      bool enabled = ftrace_pids_enabled();
 +      struct ftrace_ops *op;
 +
        /* Only do something if we are tracing something */
        if (ftrace_trace_function == ftrace_stub)
                return;
  
 +      do_for_each_ftrace_op(op, ftrace_ops_list) {
 +              if (op->flags & FTRACE_OPS_FL_PID) {
 +                      op->func = enabled ? ftrace_pid_func :
 +                              op->saved_func;
 +                      ftrace_update_trampoline(op);
 +              }
 +      } while_for_each_ftrace_op(op);
 +
        update_ftrace_function();
  }
  
@@@ -630,13 -613,18 +630,18 @@@ static int function_stat_show(struct se
                goto out;
        }
  
+ #ifdef CONFIG_FUNCTION_GRAPH_TRACER
+       avg = rec->time;
+       do_div(avg, rec->counter);
+       if (tracing_thresh && (avg < tracing_thresh))
+               goto out;
+ #endif
        kallsyms_lookup(rec->ip, NULL, NULL, NULL, str);
        seq_printf(m, "  %-30.30s  %10lu", str, rec->counter);
  
  #ifdef CONFIG_FUNCTION_GRAPH_TRACER
        seq_puts(m, "    ");
-       avg = rec->time;
-       do_div(avg, rec->counter);
  
        /* Sample standard deviation (s^2) */
        if (rec->counter <= 1)
@@@ -1150,8 -1138,7 +1155,8 @@@ static struct ftrace_ops global_ops = 
        .local_hash.filter_hash         = EMPTY_HASH,
        INIT_OPS_HASH(global_ops)
        .flags                          = FTRACE_OPS_FL_RECURSION_SAFE |
 -                                        FTRACE_OPS_FL_INITIALIZED,
 +                                        FTRACE_OPS_FL_INITIALIZED |
 +                                        FTRACE_OPS_FL_PID,
  };
  
  /*
@@@ -5041,9 -5028,7 +5046,9 @@@ static void ftrace_update_trampoline(st
  
  static struct ftrace_ops global_ops = {
        .func                   = ftrace_stub,
 -      .flags                  = FTRACE_OPS_FL_RECURSION_SAFE | FTRACE_OPS_FL_INITIALIZED,
 +      .flags                  = FTRACE_OPS_FL_RECURSION_SAFE |
 +                                FTRACE_OPS_FL_INITIALIZED |
 +                                FTRACE_OPS_FL_PID,
  };
  
  static int __init ftrace_nodyn_init(void)
@@@ -5100,6 -5085,11 +5105,6 @@@ void ftrace_init_array_ops(struct trace
                if (WARN_ON(tr->ops->func != ftrace_stub))
                        printk("ftrace ops had %pS for function\n",
                               tr->ops->func);
 -              /* Only the top level instance does pid tracing */
 -              if (!list_empty(&ftrace_pids)) {
 -                      set_ftrace_pid_function(func);
 -                      func = ftrace_pid_func;
 -              }
        }
        tr->ops->func = func;
        tr->ops->private = tr;
@@@ -5386,7 -5376,7 +5391,7 @@@ static void *fpid_start(struct seq_fil
  {
        mutex_lock(&ftrace_lock);
  
 -      if (list_empty(&ftrace_pids) && (!*pos))
 +      if (!ftrace_pids_enabled() && (!*pos))
                return (void *) 1;
  
        return seq_list_start(&ftrace_pids, *pos);
@@@ -5625,7 -5615,6 +5630,7 @@@ static struct ftrace_ops graph_ops = 
        .func                   = ftrace_stub,
        .flags                  = FTRACE_OPS_FL_RECURSION_SAFE |
                                   FTRACE_OPS_FL_INITIALIZED |
 +                                 FTRACE_OPS_FL_PID |
                                   FTRACE_OPS_FL_STUB,
  #ifdef FTRACE_GRAPH_TRAMP_ADDR
        .trampoline             = FTRACE_GRAPH_TRAMP_ADDR,