Tracing IRQ-flags

[Sedat Dilek]

Hi Ingo, Hi Steven,

I am still fighting with a llvmlinux problem in the area...

    workqueue | hid | irq-flags (hardirqs/sofirqs disabled) | whatever?!

...(see [0]).

[   24.705463] BUG: sleeping function called from invalid context at
kernel/workqueue.c:2680
[   24.705576] in_atomic(): 0, irqs_disabled(): 1, pid: 1447, name: acpid

Several people had ideas where to look at - Thanks.

Finally, Jiri encouraged me to try with a ftrace graph trace (see [1]).

I remembered TraceFS entered Linux v4.1 and wanted to play with it.
One result is the attached doc.

Can I do a ftrace graph trace with TraceFS?
And how do I do that?

Steven, is it possible to place your tracing mini-HOWTO (file:
/sys/kernel/tracing/README) into docs-dir?
Existing Documentation/trace?
Documentation/tracefs (new)?
Documentation/tracing (new)?
First, I was confused how and where to mount tracefs :-(.
Thanks.

Ingo, the kernel-configs in irqflags-tracing.txt doc are a bit outdated.
Which are very important for irqflags-tracing (hardirq | softirq)?
Are the lockdeps settings important?
Is irqsoff setting important?

$ egrep -i 'lockdep|tracing|irqsoff|irqflags' /boot/config-$(uname -r) | sort
CONFIG_DEBUG_LOCKDEP=y
CONFIG_EVENT_TRACING=y
CONFIG_IRQSOFF_TRACER=y
CONFIG_IWLWIFI_DEVICE_TRACING=y
CONFIG_LOCKDEP_SUPPORT=y
CONFIG_LOCKDEP=y
# CONFIG_MAC80211_MESSAGE_TRACING is not set
CONFIG_TRACE_IRQFLAGS_SUPPORT=y
CONFIG_TRACE_IRQFLAGS=y
CONFIG_TRACING_SUPPORT=y
CONFIG_TRACING=y

What about a new tracing-dir in Documentation/ and place all tracing docs there?

Thanks.

Regards,
- Sedat -

[0] http://marc.info/?t=144179442100006&r=1&w=2
[1] http://marc.info/?l=linux-kernel&m=144318685710847&w=2
[2] https://lwn.net/Articles/631798/
[3] http://git.kernel.org/cgit/linux/kernel/git/torvalds/linux.git/tree/Documentation/irqflags-tracing.txt
***** TRACEFS-TRACING-IRQFLAGS.txt *****

[ HELP ]

[1] tracing mini-HOWTO: See /sys/kernel/tracing/README file
[2] http://git.kernel.org/cgit/linux/kernel/git/torvalds/linux.git/tree/Documentation/irqflags-tracing.txt
[3] http://git.kernel.org/cgit/linux/kernel/git/torvalds/linux.git/tree/Documentation/trace

[ KERNEL-CONFIG SETTINGS ]

[ TRACEFS ]
CONFIG_TRACING_SUPPORT=y
CONFIG_TRACING=y

[ IRQFLAGS-TRACING AND IRQSOFF LATENCY TRACER ]
CONFIG_TRACE_IRQFLAGS_SUPPORT=y
CONFIG_TRACE_IRQFLAGS=y
CONFIG_IRQSOFF_TRACER=y

[ MOUNT AND CHECK TRACEFS ]

root# mount -t tracefs none /sys/kernel/tracing

root# mount | grep tracefs
none on /sys/kernel/tracing type tracefs (rw,relatime)

[ ENTER TRACEFS-DIR ]

root# cd /sys/kernel/tracing/

[ DOCUMENTATION: TRACING MINI-HOWTO ]

root# cat README

[ CHECK TRACING SETTINGS ]

root# cat tracing_on
1

[ DISABLE TRACING AND EMPTY TRACE FILE ]

root# echo 0 > tracing_on
root# cat tracing_on
0

root# echo > trace
root# cat trace
# tracer: nop
#
# entries-in-buffer/entries-written: 0/0   #P:4
#
#                              _-----=> irqs-off
#                             / _----=> need-resched
#                            | / _---=> hardirq/softirq
#                            || / _--=> preempt-depth
#                            ||| /     delay
#           TASK-PID   CPU#  ||||    TIMESTAMP  FUNCTION
#              | |       |   ||||       |         |

[ CHECK AVAILABLE TRACERS AND EVENTS (HERE: IRQSOFF) ]

root# cat /sys/kernel/tracing/available_tracers
blk mmiotrace function_graph wakeup_dl wakeup_rt wakeup irqsoff function nop <--- XXX: IRQSOFF

root# cat /sys/kernel/tracing/available_events | grep irq:
irq:irq_handler_entry
irq:irq_handler_exit
irq:softirq_entry
irq:softirq_exit
irq:softirq_raise

root# cat events/irq/enable
1

root# cat events/irq/filter
### global filter ###
# Use this to set filters for multiple events.
# Only events with the given fields will be affected.
# If no events are modified, an error message will be displayed here

[ ENABLE IRQ_HANDLER AND SOFTIRQ SETTINGS ]

root# echo 1 > events/irq/irq_handler_entry/enable
root# echo 1 > events/irq/irq_handler_exit/enable
root# cat events/irq/irq_handler_entry/enable events/irq/irq_handler_exit/enable
1
1

root# echo 1 > events/irq/softirq_entry/enable
root# echo 1 > events/irq/softirq_exit/enable
root# echo 1 > events/irq/softirq_raise/enable
root# cat events/irq/softirq_entry/enable events/irq/softirq_exit/enable events/irq/softirq_raise/enable
1
1
1

root# cat trace
# tracer: nop
#
# entries-in-buffer/entries-written: 0/0   #P:4
#
#                              _-----=> irqs-off
#                             / _----=> need-resched
#                            | / _---=> hardirq/softirq
#                            || / _--=> preempt-depth
#                            ||| /     delay
#           TASK-PID   CPU#  ||||    TIMESTAMP  FUNCTION
#              | |       |   ||||       |         |

[ START TRACING ]

root# echo 1 > tracing_on

[ CHECK TRACE FILE ]

root# cat trace


-dileks // 27-SEP-2015
tracing mini-HOWTO:

# echo 0 > tracing_on : quick way to disable tracing
# echo 1 > tracing_on : quick way to re-enable tracing

 Important files:
  trace			- The static contents of the buffer
			  To clear the buffer write into this file: echo > trace
  trace_pipe		- A consuming read to see the contents of the buffer
  current_tracer	- function and latency tracers
  available_tracers	- list of configured tracers for current_tracer
  buffer_size_kb	- view and modify size of per cpu buffer
  buffer_total_size_kb  - view total size of all cpu buffers

  trace_clock		-change the clock used to order events
       local:   Per cpu clock but may not be synced across CPUs
      global:   Synced across CPUs but slows tracing down.
     counter:   Not a clock, but just an increment
      uptime:   Jiffy counter from time of boot
        perf:   Same clock that perf events use
     x86-tsc:   TSC cycle counter

  trace_marker		- Writes into this file writes into the kernel buffer
  tracing_cpumask	- Limit which CPUs to trace
  instances		- Make sub-buffers with: mkdir instances/foo
			  Remove sub-buffer with rmdir
  trace_options		- Set format or modify how tracing happens
			  Disable an option by adding a suffix 'no' to the
			  option name
  saved_cmdlines_size	- echo command number in here to store comm-pid list

  available_filter_functions - list of functions that can be filtered on
  set_ftrace_filter	- echo function name in here to only trace these
			  functions
	     accepts: func_full_name, *func_end, func_begin*, *func_middle*
	     modules: Can select a group via module
	      Format: :mod:<module-name>
	     example: echo :mod:ext3 > set_ftrace_filter
	    triggers: a command to perform when function is hit
	      Format: <function>:<trigger>[:count]
	     trigger: traceon, traceoff
		      enable_event:<system>:<event>
		      disable_event:<system>:<event>
		      stacktrace
		      snapshot
		      dump
		      cpudump
	     example: echo do_fault:traceoff > set_ftrace_filter
	              echo do_trap:traceoff:3 > set_ftrace_filter
	     The first one will disable tracing every time do_fault is hit
	     The second will disable tracing at most 3 times when do_trap is hit
	       The first time do trap is hit and it disables tracing, the
	       counter will decrement to 2. If tracing is already disabled,
	       the counter will not decrement. It only decrements when the
	       trigger did work
	     To remove trigger without count:
	       echo '!<function>:<trigger> > set_ftrace_filter
	     To remove trigger with a count:
	       echo '!<function>:<trigger>:0 > set_ftrace_filter
  set_ftrace_notrace	- echo function name in here to never trace.
	    accepts: func_full_name, *func_end, func_begin*, *func_middle*
	    modules: Can select a group via module command :mod:
	    Does not accept triggers
  set_ftrace_pid	- Write pid(s) to only function trace those pids
		    (function)
  set_graph_function	- Trace the nested calls of a function (function_graph)
  set_graph_notrace	- Do not trace the nested calls of a function (function_graph)
  max_graph_depth	- Trace a limited depth of nested calls (0 is unlimited)

  snapshot		- Like 'trace' but shows the content of the static
			  snapshot buffer. Read the contents for more
			  information
  stack_trace		- Shows the max stack trace when active
  stack_max_size	- Shows current max stack size that was traced
			  Write into this file to reset the max size (trigger a
			  new trace)
  stack_trace_filter	- Like set_ftrace_filter but limits what stack_trace
			  traces
  events/		- Directory containing all trace event subsystems:
      enable		- Write 0/1 to enable/disable tracing of all events
  events/<system>/	- Directory containing all trace events for <system>:
      enable		- Write 0/1 to enable/disable tracing of all <system>
			  events
      filter		- If set, only events passing filter are traced
  events/<system>/<event>/	- Directory containing control files for
			  <event>:
      enable		- Write 0/1 to enable/disable tracing of <event>
      filter		- If set, only events passing filter are traced
      trigger		- If set, a command to perform when event is hit
	    Format: <trigger>[:count][if <filter>]
	   trigger: traceon, traceoff
	            enable_event:<system>:<event>
	            disable_event:<system>:<event>
		    stacktrace
		    snapshot
	   example: echo traceoff > events/block/block_unplug/trigger
	            echo traceoff:3 > events/block/block_unplug/trigger
	            echo 'enable_event:kmem:kmalloc:3 if nr_rq > 1' > \
	                  events/block/block_unplug/trigger
	   The first disables tracing every time block_unplug is hit.
	   The second disables tracing the first 3 times block_unplug is hit.
	   The third enables the kmalloc event the first 3 times block_unplug
	     is hit and has value of greater than 1 for the 'nr_rq' event field.
	   Like function triggers, the counter is only decremented if it
	    enabled or disabled tracing.
	   To remove a trigger without a count:
	     echo '!<trigger> > <system>/<event>/trigger
	   To remove a trigger with a count:
	     echo '!<trigger>:0 > <system>/<event>/trigger
	   Filters can be ignored when removing a trigger.