tracing: common error_log for ftrace

From: Tom Zanussi <[email protected]>

Hi,

This is v5 of the frace error_log patchset. This version updates the patches according to suggestions from Masami and Namhyung and moves some of the selftest code from the kprobe/uprobe testcases to a common function that can be reused by multiple testcases, including the new error_log testcase.

Changes from v4:

- Merged in the >& -> 2> redirection patch into '[PATCH v5 06/11] selftests/ftrace: Add error_log testcase for probe errors'
- Added new patch, '[PATCH v5 07/11] selftests/ftrace: Move kprobe/uprobe check_error() to test.d/functions' that adds a new ftrace_errlog_check() to test.d/functions, which is based on check_error() from '[PATCH v5 06/11] selftests/ftrace: Add error_log testcase for probe errors'
- Modified the kprobe/uprobe test cases to use the common ftrace_errlog_check()
- Modified the error_log test cases to display the error position using the common ftrace_errlog_check()
- Updated subject for '[PATCH v5 08/11] selftests/ftrace: Remove trigger-extended-error-support testcase
- Streamlined the error_log open and write file operations as suggested by Masami
- Fixed the long lines in '[PATCH v4 04/11] tracing: Use tracing error_log with trace event filters' as suggested by Namhyung

Changes from v3:

- Added Masami's [PATCH 05/11] tracing: Use tracing error_log with probe events
- Added Masami's [PATCH 06/11] selftests/ftrace: Add error_log testcase for probe
- Added [PATCH 11/11] to fix [PATCH 06/11]
- Removed [RFC PATCH v3 4/5] tracing: Use tracing error_log with kprobe events
- Added [PATCH 08/11] selftests/ftrace: Add tracing/error_log testcase
- Removed trigger-extended-error-support testcase
- Changed [n] numbering to [timestamp] numbering as suggested by Masami
- Updated Documentation and README

Changes from v2:

- Added [n] numbering as suggested by Masami

Text from original post:

Last April, I posted an RFC patchset [1] implementing a common error_log interface as suggested by Masami [2]. We were supposed to discuss it at Plumbers but that never happened, and Steve recently asked about patches for a follow-on discussion [3], so here they are.

I incorporated comments from the previous discussion, the most important of which are:

- Incorporated Steve's suggestion of using static strings as in the existing trace event filter code, along with err_info indexing into the string arrays and a position for the error caret.

- Converted all the hist trigger errors and the existing trace event filter parse errors to use the new interface.

- Converted a few kprobe_event errors to the new interface as examples, but these will require more work - I didn't spend much time figuring out how to get the full kprobe command into the error info, for instance.

- Got rid of the custom single-page ring buffer and used standard lists instead.

For now, this is implemented on top of the latest 'hist trigger snapshot and onchange additions' patchset [4].

Below is an example session of a few failed commands and the corresponding error_log contents:

  # echo > /sys/kernel/debug/tracing/error_log

  # echo 'hist:keys=pid:ts0=common_timestamp.usecs if comm=="cyclictest"' >> /sys/kernel/debug/tracing/events/sched/sched_wakeup/trigger
  # echo 'hist:keys=pid:ts0=common_timestamp.usecs if comm=="cyclictest"' >> /sys/kernel/debug/tracing/events/sched/sched_wakeup/trigger
  -su: echo: write error: Invalid argument

# cat /sys/kernel/debug/tracing/error_log

  [  217.431858] hist:sched:sched_wakeup: error: Variable already defined
    Command: keys=pid:ts0=common_timestamp.usecs if comm=="cyclictest"
                      ^

  # echo 'hist:key=comm:p=prio:onchange($q).snapshot()' > /sys/kernel/debug/tracing/events/sched/sched_waking/trigger
  -su: echo: write error: Invalid argument

  # cat /sys/kernel/debug/tracing/error_log
  [  217.431858] hist:sched:sched_wakeup: error: Variable already defined
    Command: keys=pid:ts0=common_timestamp.usecs if comm=="cyclictest"
                      ^
  [  311.554978] hist:sched:sched_waking: error: Couldn't find onmax or onchange variable
    Command: key=comm:p=prio:onchange($q).snapshot()
                                       ^

  # echo 'hist:keys=pid' >> /sys/kernel/debug/tracing/events/sched/sched_wakeup/trigger
  # echo 'hist:keys=pid' >> /sys/kernel/debug/tracing/events/sched/sched_wakeup/trigger
  -su: echo: write error: File exists
  # echo 'comm="cyclictest"' > /sys/kernel/debug/tracing/events/sched/sched_wakeup/filter
  -su: echo: write error: Invalid argument

  # cat /sys/kernel/debug/tracing/error_log
  [  217.431858] hist:sched:sched_wakeup: error: Variable already defined
    Command: keys=pid:ts0=common_timestamp.usecs if comm=="cyclictest"
                      ^
  [  311.554978] hist:sched:sched_waking: error: Couldn't find onmax or onchange variable
    Command: key=comm:p=prio:onchange($q).snapshot()
                                       ^
  [  715.626153] hist:sched:sched_wakeup: error: Hist trigger already exists
    Command: keys=pid
             ^
  [  730.480310] event filter parse error: error: Invalid operator
    Command: comm="cyclictest"
                  ^

  # echo "((sig >= 10 && sig < 15) || dsig == 17) && comm != bash" > /sys/kernel/debug/tracing/events/signal/signal_generate/filter
  -su: echo: write error: Invalid argument

  # cat /sys/kernel/debug/tracing/error_log
  [  217.431858] hist:sched:sched_wakeup: error: Variable already defined
    Command: keys=pid:ts0=common_timestamp.usecs if comm=="cyclictest"
                      ^
  [  311.554978] hist:sched:sched_waking: error: Couldn't find onmax or onchange variable
    Command: key=comm:p=prio:onchange($q).snapshot()
                                       ^
  [  715.626153] hist:sched:sched_wakeup: error: Hist trigger already exists
    Command: keys=pid
             ^
  [  730.480310] event filter parse error: error: Invalid operator
    Command: comm="cyclictest"
                  ^
  [  800.548673] event filter parse error: error: Field not found
    Command: ((sig >= 10 && sig < 15) || dsig == 17) && comm != bash
                                              ^

Thanks,

Tom

[1] https://lore.kernel.org/lkml/[email protected]/
[2] https://lore.kernel.org/lkml/[email protected]/
[3] https://lore.kernel.org/lkml/[email protected]/
[4] https://lore.kernel.org/lkml/[email protected]/

The following changes since commit 01c4e8042fc949018b70ded769f959bc3d80e8b6:

tracing: initialize variable in create_dyn_event() (2019-03-22 15:19:34 -0400)

are available in the git repository at:

git://git.kernel.org/pub/scm/linux/kernel/git/zanussi/linux-trace.git ftrace/error_log_v5

Masami Hiramatsu (2):
tracing: Use tracing error_log with probe events selftests/ftrace: Add error_log testcase for probe errors

Tom Zanussi (9):
tracing: Add tracing error log
tracing: Save the last hist command's associated event name
tracing: Use tracing error_log with hist triggers
tracing: Use tracing error_log with trace event filters selftests/ftrace: Move kprobe/uprobe check_error() to test.d/functions selftests/ftrace: Remove trigger-extended-error-support testcase selftests/ftrace: Add tracing/error_log testcase
tracing: Add tracing/error_log Documentation
tracing: Add error_log to README

 Documentation/trace/ftrace.rst                     |  31 +++
 Documentation/trace/histogram.rst                  |  16 +-
 kernel/trace/trace.c                               | 219 ++++++++++++++++
 kernel/trace/trace.h                               |   4 +
 kernel/trace/trace_events_filter.c                 |  11 +-
 kernel/trace/trace_events_hist.c                   | 221 +++++++++--------
 kernel/trace/trace_kprobe.c                        |  77 +++---
 kernel/trace/trace_probe.c                         | 274 +++++++++++++++------
 kernel/trace/trace_probe.h                         |  77 +++++-
 kernel/trace/trace_uprobe.c                        |  44 +++-
 .../ftrace/test.d/ftrace/tracing-error-log.tc      |  19 ++
 tools/testing/selftests/ftrace/test.d/functions    |  12 +
 .../ftrace/test.d/kprobe/kprobe_syntax_errors.tc   |  85 +++++++
 .../ftrace/test.d/kprobe/uprobe_syntax_errors.tc   |  23 ++
 .../inter-event/trigger-extended-error-support.tc  |  28 ---
 15 files changed, 874 insertions(+), 267 deletions(-)
 create mode 100644 tools/testing/selftests/ftrace/test.d/ftrace/tracing-error-log.tc
 create mode 100644 tools/testing/selftests/ftrace/test.d/kprobe/kprobe_syntax_errors.tc
 create mode 100644 tools/testing/selftests/ftrace/test.d/kprobe/uprobe_syntax_errors.tc
 delete mode 100644 tools/testing/selftests/ftrace/test.d/trigger/inter-event/trigger-extended-error-support.tc

2.14.1