1. 26 Jul, 2013 1 commit
    • Steven Rostedt (Red Hat)'s avatar
      tracing: Add __tracepoint_string() to export string pointers · 102c9323
      Steven Rostedt (Red Hat) authored
      
      
      There are several tracepoints (mostly in RCU), that reference a string
      pointer and uses the print format of "%s" to display the string that
      exists in the kernel, instead of copying the actual string to the
      ring buffer (saves time and ring buffer space).
      
      But this has an issue with userspace tools that read the binary buffers
      that has the address of the string but has no access to what the string
      itself is. The end result is just output that looks like:
      
       rcu_dyntick:          ffffffff818adeaa 1 0
       rcu_dyntick:          ffffffff818adeb5 0 140000000000000
       rcu_dyntick:          ffffffff818adeb5 0 140000000000000
       rcu_utilization:      ffffffff8184333b
       rcu_utilization:      ffffffff8184333b
      
      The above is pretty useless when read by the userspace tools. Ideally
      we would want something that looks like this:
      
       rcu_dyntick:          Start 1 0
       rcu_dyntick:          End 0 140000000000000
       rcu_dyntick:          Start 140000000000000 0
       rcu_callback:         rcu_preempt rhp=0xffff880037aff710 func=put_cred_rcu 0/4
       rcu_callback:         rcu_preempt rhp=0xffff880078961980 func=file_free_rcu 0/5
       rcu_dyntick:          End 0 1
      
      The trace_printk() which also only stores the address of the string
      format instead of recording the string into the buffer itself, exports
      the mapping of kernel addresses to format strings via the printk_format
      file in the debugfs tracing directory.
      
      The tracepoint strings can use this same method and output the format
      to the same file and the userspace tools will be able to decipher
      the address without any modification.
      
      The tracepoint strings need its own section to save the strings because
      the trace_printk section will cause the trace_printk() buffers to be
      allocated if anything exists within the section. trace_printk() is only
      used for debugging and should never exist in the kernel, we can not use
      the trace_printk sections.
      
      Add a new tracepoint_str section that will also be examined by the output
      of the printk_format file.
      
      Cc: Paul E. McKenney <paulmck@linux.vnet.ibm.com>
      Signed-off-by: default avatarSteven Rostedt <rostedt@goodmis.org>
      102c9323
  2. 03 Jul, 2013 7 commits
  3. 02 Jul, 2013 14 commits
  4. 20 Jun, 2013 4 commits
  5. 11 Jun, 2013 7 commits
  6. 06 Jun, 2013 1 commit
    • Steven Rostedt (Red Hat)'s avatar
      tracing: Use current_uid() for critical time tracing · f17a5194
      Steven Rostedt (Red Hat) authored
      
      
      The irqsoff tracer records the max time that interrupts are disabled.
      There are hooks in the assembly code that calls back into the tracer when
      interrupts are disabled or enabled.
      
      When they are enabled, the tracer checks if the amount of time they
      were disabled is larger than the previous recorded max interrupts off
      time. If it is, it creates a snapshot of the currently running trace
      to store where the last largest interrupts off time was held and how
      it happened.
      
      During testing, this RCU lockdep dump appeared:
      
      [ 1257.829021] ===============================
      [ 1257.829021] [ INFO: suspicious RCU usage. ]
      [ 1257.829021] 3.10.0-rc1-test+ #171 Tainted: G        W
      [ 1257.829021] -------------------------------
      [ 1257.829021] /home/rostedt/work/git/linux-trace.git/include/linux/rcupdate.h:780 rcu_read_lock() used illegally while idle!
      [ 1257.829021]
      [ 1257.829021] other info that might help us debug this:
      [ 1257.829021]
      [ 1257.829021]
      [ 1257.829021] RCU used illegally from idle CPU!
      [ 1257.829021] rcu_scheduler_active = 1, debug_locks = 0
      [ 1257.829021] RCU used illegally from extended quiescent state!
      [ 1257.829021] 2 locks held by trace-cmd/4831:
      [ 1257.829021]  #0:  (max_trace_lock){......}, at: [<ffffffff810e2b77>] stop_critical_timing+0x1a3/0x209
      [ 1257.829021]  #1:  (rcu_read_lock){.+.+..}, at: [<ffffffff810dae5a>] __update_max_tr+0x88/0x1ee
      [ 1257.829021]
      [ 1257.829021] stack backtrace:
      [ 1257.829021] CPU: 3 PID: 4831 Comm: trace-cmd Tainted: G        W    3.10.0-rc1-test+ #171
      [ 1257.829021] Hardware name: To Be Filled By O.E.M. To Be Filled By O.E.M./To be filled by O.E.M., BIOS SDBLI944.86P 05/08/2007
      [ 1257.829021]  0000000000000001 ffff880065f49da8 ffffffff8153dd2b ffff880065f49dd8
      [ 1257.829021]  ffffffff81092a00 ffff88006bd78680 ffff88007add7500 0000000000000003
      [ 1257.829021]  ffff88006bd78680 ffff880065f49e18 ffffffff810daebf ffffffff810dae5a
      [ 1257.829021] Call Trace:
      [ 1257.829021]  [<ffffffff8153dd2b>] dump_stack+0x19/0x1b
      [ 1257.829021]  [<ffffffff81092a00>] lockdep_rcu_suspicious+0x109/0x112
      [ 1257.829021]  [<ffffffff810daebf>] __update_max_tr+0xed/0x1ee
      [ 1257.829021]  [<ffffffff810dae5a>] ? __update_max_tr+0x88/0x1ee
      [ 1257.829021]  [<ffffffff811002b9>] ? user_enter+0xfd/0x107
      [ 1257.829021]  [<ffffffff810dbf85>] update_max_tr_single+0x11d/0x12d
      [ 1257.829021]  [<ffffffff811002b9>] ? user_enter+0xfd/0x107
      [ 1257.829021]  [<ffffffff810e2b15>] stop_critical_timing+0x141/0x209
      [ 1257.829021]  [<ffffffff8109569a>] ? trace_hardirqs_on+0xd/0xf
      [ 1257.829021]  [<ffffffff811002b9>] ? user_enter+0xfd/0x107
      [ 1257.829021]  [<ffffffff810e3057>] time_hardirqs_on+0x2a/0x2f
      [ 1257.829021]  [<ffffffff811002b9>] ? user_enter+0xfd/0x107
      [ 1257.829021]  [<ffffffff8109550c>] trace_hardirqs_on_caller+0x16/0x197
      [ 1257.829021]  [<ffffffff8109569a>] trace_hardirqs_on+0xd/0xf
      [ 1257.829021]  [<ffffffff811002b9>] user_enter+0xfd/0x107
      [ 1257.829021]  [<ffffffff810029b4>] do_notify_resume+0x92/0x97
      [ 1257.829021]  [<ffffffff8154bdca>] int_signal+0x12/0x17
      
      What happened was entering into the user code, the interrupts were enabled
      and a max interrupts off was recorded. The trace buffer was saved along with
      various information about the task: comm, pid, uid, priority, etc.
      
      The uid is recorded with task_uid(tsk). But this is a macro that uses rcu_read_lock()
      to retrieve the data, and this happened to happen where RCU is blind (user_enter).
      
      As only the preempt and irqs off tracers can have this happen, and they both
      only have the tsk == current, if tsk == current, use current_uid() instead of
      task_uid(), as current_uid() does not use RCU as only current can change its uid.
      
      This fixes the RCU suspicious splat.
      Signed-off-by: default avatarSteven Rostedt <rostedt@goodmis.org>
      f17a5194
  7. 29 May, 2013 2 commits
  8. 28 May, 2013 1 commit
  9. 23 May, 2013 1 commit
    • Steven Rostedt (Red Hat)'s avatar
      tracing: Fix crash when ftrace=nop on the kernel command line · ca164318
      Steven Rostedt (Red Hat) authored
      
      
      If ftrace=<tracer> is on the kernel command line, when that tracer is
      registered, it will be initiated by tracing_set_tracer() to execute that
      tracer.
      
      The nop tracer is just a stub tracer that is used to have no tracer
      enabled. It is assigned at early bootup as it is the default tracer.
      
      But if ftrace=nop is on the kernel command line, the registering of the
      nop tracer will call tracing_set_tracer() which will try to execute
      the nop tracer. But it expects tr->current_trace to be assigned something
      as it usually is assigned to the nop tracer. As it hasn't been assigned
      to anything yet, it causes the system to crash.
      
      The simple fix is to move the tr->current_trace = nop before registering
      the nop tracer. The functionality is still the same as the nop tracer
      doesn't do anything anyway.
      Reported-by: default avatarPeter Zijlstra <peterz@infradead.org>
      Signed-off-by: default avatarSteven Rostedt <rostedt@goodmis.org>
      ca164318
  10. 16 May, 2013 1 commit
  11. 15 May, 2013 1 commit