events.txt 9.0 KB

123456789101112131415161718192021222324252627282930313233343536373839404142434445464748495051525354555657585960616263646566676869707172737475767778798081828384858687888990919293949596979899100101102103104105106107108109110111112113114115116117118119120121122123124125126127128129130131132133134135136137138139140141142143144145146147148149150151152153154155156157158159160161162163164165166167168169170171172173174175176177178179180181182183184185186187188189190191192193194195196197198199200201202203204205206207208209210211212213214215216217218219220221222223224225226227228229230231232233234235236237238239240241242243244245246247248249250251252253254255256257258259260261262263264265266267268269270271272273274275276277278279280281
  1. Event Tracing
  2. Documentation written by Theodore Ts'o
  3. Updated by Li Zefan and Tom Zanussi
  4. 1. Introduction
  5. ===============
  6. Tracepoints (see Documentation/trace/tracepoints.txt) can be used
  7. without creating custom kernel modules to register probe functions
  8. using the event tracing infrastructure.
  9. Not all tracepoints can be traced using the event tracing system;
  10. the kernel developer must provide code snippets which define how the
  11. tracing information is saved into the tracing buffer, and how the
  12. tracing information should be printed.
  13. 2. Using Event Tracing
  14. ======================
  15. 2.1 Via the 'set_event' interface
  16. ---------------------------------
  17. The events which are available for tracing can be found in the file
  18. /sys/kernel/debug/tracing/available_events.
  19. To enable a particular event, such as 'sched_wakeup', simply echo it
  20. to /sys/kernel/debug/tracing/set_event. For example:
  21. # echo sched_wakeup >> /sys/kernel/debug/tracing/set_event
  22. [ Note: '>>' is necessary, otherwise it will firstly disable
  23. all the events. ]
  24. To disable an event, echo the event name to the set_event file prefixed
  25. with an exclamation point:
  26. # echo '!sched_wakeup' >> /sys/kernel/debug/tracing/set_event
  27. To disable all events, echo an empty line to the set_event file:
  28. # echo > /sys/kernel/debug/tracing/set_event
  29. To enable all events, echo '*:*' or '*:' to the set_event file:
  30. # echo *:* > /sys/kernel/debug/tracing/set_event
  31. The events are organized into subsystems, such as ext4, irq, sched,
  32. etc., and a full event name looks like this: <subsystem>:<event>. The
  33. subsystem name is optional, but it is displayed in the available_events
  34. file. All of the events in a subsystem can be specified via the syntax
  35. "<subsystem>:*"; for example, to enable all irq events, you can use the
  36. command:
  37. # echo 'irq:*' > /sys/kernel/debug/tracing/set_event
  38. 2.2 Via the 'enable' toggle
  39. ---------------------------
  40. The events available are also listed in /sys/kernel/debug/tracing/events/ hierarchy
  41. of directories.
  42. To enable event 'sched_wakeup':
  43. # echo 1 > /sys/kernel/debug/tracing/events/sched/sched_wakeup/enable
  44. To disable it:
  45. # echo 0 > /sys/kernel/debug/tracing/events/sched/sched_wakeup/enable
  46. To enable all events in sched subsystem:
  47. # echo 1 > /sys/kernel/debug/tracing/events/sched/enable
  48. To enable all events:
  49. # echo 1 > /sys/kernel/debug/tracing/events/enable
  50. When reading one of these enable files, there are four results:
  51. 0 - all events this file affects are disabled
  52. 1 - all events this file affects are enabled
  53. X - there is a mixture of events enabled and disabled
  54. ? - this file does not affect any event
  55. 2.3 Boot option
  56. ---------------
  57. In order to facilitate early boot debugging, use boot option:
  58. trace_event=[event-list]
  59. event-list is a comma separated list of events. See section 2.1 for event
  60. format.
  61. 3. Defining an event-enabled tracepoint
  62. =======================================
  63. See The example provided in samples/trace_events
  64. 4. Event formats
  65. ================
  66. Each trace event has a 'format' file associated with it that contains
  67. a description of each field in a logged event. This information can
  68. be used to parse the binary trace stream, and is also the place to
  69. find the field names that can be used in event filters (see section 5).
  70. It also displays the format string that will be used to print the
  71. event in text mode, along with the event name and ID used for
  72. profiling.
  73. Every event has a set of 'common' fields associated with it; these are
  74. the fields prefixed with 'common_'. The other fields vary between
  75. events and correspond to the fields defined in the TRACE_EVENT
  76. definition for that event.
  77. Each field in the format has the form:
  78. field:field-type field-name; offset:N; size:N;
  79. where offset is the offset of the field in the trace record and size
  80. is the size of the data item, in bytes.
  81. For example, here's the information displayed for the 'sched_wakeup'
  82. event:
  83. # cat /sys/kernel/debug/tracing/events/sched/sched_wakeup/format
  84. name: sched_wakeup
  85. ID: 60
  86. format:
  87. field:unsigned short common_type; offset:0; size:2;
  88. field:unsigned char common_flags; offset:2; size:1;
  89. field:unsigned char common_preempt_count; offset:3; size:1;
  90. field:int common_pid; offset:4; size:4;
  91. field:int common_tgid; offset:8; size:4;
  92. field:char comm[TASK_COMM_LEN]; offset:12; size:16;
  93. field:pid_t pid; offset:28; size:4;
  94. field:int prio; offset:32; size:4;
  95. field:int success; offset:36; size:4;
  96. field:int cpu; offset:40; size:4;
  97. print fmt: "task %s:%d [%d] success=%d [%03d]", REC->comm, REC->pid,
  98. REC->prio, REC->success, REC->cpu
  99. This event contains 10 fields, the first 5 common and the remaining 5
  100. event-specific. All the fields for this event are numeric, except for
  101. 'comm' which is a string, a distinction important for event filtering.
  102. 5. Event filtering
  103. ==================
  104. Trace events can be filtered in the kernel by associating boolean
  105. 'filter expressions' with them. As soon as an event is logged into
  106. the trace buffer, its fields are checked against the filter expression
  107. associated with that event type. An event with field values that
  108. 'match' the filter will appear in the trace output, and an event whose
  109. values don't match will be discarded. An event with no filter
  110. associated with it matches everything, and is the default when no
  111. filter has been set for an event.
  112. 5.1 Expression syntax
  113. ---------------------
  114. A filter expression consists of one or more 'predicates' that can be
  115. combined using the logical operators '&&' and '||'. A predicate is
  116. simply a clause that compares the value of a field contained within a
  117. logged event with a constant value and returns either 0 or 1 depending
  118. on whether the field value matched (1) or didn't match (0):
  119. field-name relational-operator value
  120. Parentheses can be used to provide arbitrary logical groupings and
  121. double-quotes can be used to prevent the shell from interpreting
  122. operators as shell metacharacters.
  123. The field-names available for use in filters can be found in the
  124. 'format' files for trace events (see section 4).
  125. The relational-operators depend on the type of the field being tested:
  126. The operators available for numeric fields are:
  127. ==, !=, <, <=, >, >=
  128. And for string fields they are:
  129. ==, !=
  130. Currently, only exact string matches are supported.
  131. 5.2 Setting filters
  132. -------------------
  133. A filter for an individual event is set by writing a filter expression
  134. to the 'filter' file for the given event.
  135. For example:
  136. # cd /sys/kernel/debug/tracing/events/sched/sched_wakeup
  137. # echo "common_preempt_count > 4" > filter
  138. A slightly more involved example:
  139. # cd /sys/kernel/debug/tracing/events/signal/signal_generate
  140. # echo "((sig >= 10 && sig < 15) || sig == 17) && comm != bash" > filter
  141. If there is an error in the expression, you'll get an 'Invalid
  142. argument' error when setting it, and the erroneous string along with
  143. an error message can be seen by looking at the filter e.g.:
  144. # cd /sys/kernel/debug/tracing/events/signal/signal_generate
  145. # echo "((sig >= 10 && sig < 15) || dsig == 17) && comm != bash" > filter
  146. -bash: echo: write error: Invalid argument
  147. # cat filter
  148. ((sig >= 10 && sig < 15) || dsig == 17) && comm != bash
  149. ^
  150. parse_error: Field not found
  151. Currently the caret ('^') for an error always appears at the beginning of
  152. the filter string; the error message should still be useful though
  153. even without more accurate position info.
  154. 5.3 Clearing filters
  155. --------------------
  156. To clear the filter for an event, write a '0' to the event's filter
  157. file.
  158. To clear the filters for all events in a subsystem, write a '0' to the
  159. subsystem's filter file.
  160. 5.3 Subsystem filters
  161. ---------------------
  162. For convenience, filters for every event in a subsystem can be set or
  163. cleared as a group by writing a filter expression into the filter file
  164. at the root of the subsystem. Note however, that if a filter for any
  165. event within the subsystem lacks a field specified in the subsystem
  166. filter, or if the filter can't be applied for any other reason, the
  167. filter for that event will retain its previous setting. This can
  168. result in an unintended mixture of filters which could lead to
  169. confusing (to the user who might think different filters are in
  170. effect) trace output. Only filters that reference just the common
  171. fields can be guaranteed to propagate successfully to all events.
  172. Here are a few subsystem filter examples that also illustrate the
  173. above points:
  174. Clear the filters on all events in the sched subsystem:
  175. # cd /sys/kernel/debug/tracing/events/sched
  176. # echo 0 > filter
  177. # cat sched_switch/filter
  178. none
  179. # cat sched_wakeup/filter
  180. none
  181. Set a filter using only common fields for all events in the sched
  182. subsystem (all events end up with the same filter):
  183. # cd /sys/kernel/debug/tracing/events/sched
  184. # echo common_pid == 0 > filter
  185. # cat sched_switch/filter
  186. common_pid == 0
  187. # cat sched_wakeup/filter
  188. common_pid == 0
  189. Attempt to set a filter using a non-common field for all events in the
  190. sched subsystem (all events but those that have a prev_pid field retain
  191. their old filters):
  192. # cd /sys/kernel/debug/tracing/events/sched
  193. # echo prev_pid == 0 > filter
  194. # cat sched_switch/filter
  195. prev_pid == 0
  196. # cat sched_wakeup/filter
  197. common_pid == 0