부팅 시간 추적(Boot-time tracing)

개요: bootconfig로 ftrace 기능 프로그래밍

이 문서는 GPL-2.0 라이선스를 사용하며 Masami Hiramatsu가 작성했다. Boot-time tracing은 장치 초기화를 포함한 부팅 과정을 추적한다.

이 기능은 이벤트별 filter와 action, histogram, kprobe event, synthetic event, trace instance를 포함한 ftrace의 전체 기능을 부팅 단계에서 사용할 수 있게 한다. 커널 명령줄만으로는 이런 복잡한 기능을 제어하기 어려우므로 bootconfig 파일에 추적 프로그램을 기술한다.

.. SPDX-License-Identifier: GPL-2.0

=================
Boot-time tracing
=================

:Author: Masami Hiramatsu <[email protected]>

Overview
========

Boot-time tracing allows users to trace boot-time process including
device initialization with full features of ftrace including per-event
filter and actions, histograms, kprobe-events and synthetic-events,
and trace instances.
Since kernel command line is not enough to control these complex features,
this uses bootconfig file to describe tracing feature programming.

Boot Config 옵션 접두어와 참고 문서

부팅 시간 추적 옵션은 bootconfig 파일에서 `ftrace.` 또는 `kernel.` 접두어 아래에 둔다. `kernel.`로 시작하는 옵션은 커널 매개변수 설명을 함께 확인해야 한다.

bootconfig 문법은 `Documentation/admin-guide/bootconfig.rst`, 커널 매개변수는 `Documentation/admin-guide/kernel-parameters.rst`를 참조한다.

Options in the Boot Config
==========================

Here is the list of available options for boot time tracing in
boot config file [1]_. All options are under "ftrace." or "kernel."
prefix. See kernel parameters for the options which starts
with "kernel." prefix [2]_.

.. [1] See :ref:`Documentation/admin-guide/bootconfig.rst <bootconfig>`
.. [2] See :ref:`Documentation/admin-guide/kernel-parameters.rst <kernelparameters>`

ftrace 전역 옵션

ftrace 전역 옵션은 bootconfig에서 `kernel.` 접두어를 사용하며 legacy kernel command line의 일부로 전달된다.

`kernel.tp_printk`는 trace event 데이터를 printk buffer에도 출력한다. `kernel.dump_on_oops[=MODE]`는 Oops 발생 시 ftrace를 dump한다. MODE가 1이거나 생략되면 모든 CPU의 trace buffer를, MODE가 2이면 Oops를 일으킨 CPU의 buffer만 dump한다.

`kernel.traceoff_on_warning`은 `WARN_ON()` 발생 시 추적을 멈춘다. `kernel.fgraph_max_depth`는 function graph tracer의 최대 깊이를 정하며, `kernel.fgraph_filters`와 `kernel.fgraph_notraces`는 각각 추적할 함수와 제외할 함수 filter를 쉼표 목록으로 추가한다.

Ftrace Global Options
---------------------

Ftrace global options have "kernel." prefix in boot config, which means
these options are passed as a part of kernel legacy command line.

kernel.tp_printk
   Output trace-event data on printk buffer too.

kernel.dump_on_oops [= MODE]
   Dump ftrace on Oops. If MODE = 1 or omitted, dump trace buffer
   on all CPUs. If MODE = 2, dump a buffer on a CPU which kicks Oops.

kernel.traceoff_on_warning
   Stop tracing if WARN_ON() occurs.

kernel.fgraph_max_depth = MAX_DEPTH
   Set MAX_DEPTH to maximum depth of fgraph tracer.

kernel.fgraph_filters = FILTER[, FILTER2...]
   Add fgraph tracing function filters.

kernel.fgraph_notraces = FILTER[, FILTER2...]
   Add fgraph non-tracing function filters.

ftrace 인스턴스별 옵션

인스턴스별 옵션은 전역 ftrace node를 포함해 각 trace instance에 적용한다. 경로 형식은 `ftrace.[instance.INSTANCE.]...`이며 `instance.INSTANCE`를 생략하면 전역 node를 뜻한다.

`options`는 ftrace 옵션 목록을 켜고, `tracing_on`은 부팅 시간 추적 시작 시 인스턴스 추적을 켜거나 끈다. 꺼 둔 추적은 event trigger의 `traceon` action으로 나중에 시작할 수 있다. `trace_clock`, `buffer_size`, `alloc_snapshot`, `cpumask`는 clock, KB·MB 단위 buffer, snapshot buffer, 추적 CPU mask를 정한다.

`events`는 wildcard를 허용하는 부팅 시 event 목록을 켠다. `tracer`는 현재 tracer를 지정하며 예로 `function`을 사용할 수 있다. `ftrace.filters`와 `ftrace.notraces`는 각각 함수 추적 포함 규칙과 제외 규칙의 배열을 받는다.

Ftrace Per-instance Options
---------------------------

These options can be used for each instance including global ftrace node.

ftrace.[instance.INSTANCE.]options = OPT1[, OPT2[...]]
   Enable given ftrace options.

ftrace.[instance.INSTANCE.]tracing_on = 0|1
   Enable/Disable tracing on this instance when starting boot-time tracing.
   (you can enable it by the "traceon" event trigger action)

ftrace.[instance.INSTANCE.]trace_clock = CLOCK
   Set given CLOCK to ftrace's trace_clock.

ftrace.[instance.INSTANCE.]buffer_size = SIZE
   Configure ftrace buffer size to SIZE. You can use "KB" or "MB"
   for that SIZE.

ftrace.[instance.INSTANCE.]alloc_snapshot
   Allocate snapshot buffer.

ftrace.[instance.INSTANCE.]cpumask = CPUMASK
   Set CPUMASK as trace cpu-mask.

ftrace.[instance.INSTANCE.]events = EVENT[, EVENT2[...]]
   Enable given events on boot. You can use a wild card in EVENT.

ftrace.[instance.INSTANCE.]tracer = TRACER
   Set TRACER to current tracer on boot. (e.g. function)

ftrace.[instance.INSTANCE.]ftrace.filters
   This will take an array of tracing function filter rules.

ftrace.[instance.INSTANCE.]ftrace.notraces
   This will take an array of NON-tracing function filter rules.

event별 enable·filter·action과 동적 event

event별 옵션은 `ftrace.[instance.INSTANCE.]event` 아래에 둔다. `GROUP.EVENT.enable`은 한 event, `GROUP.enable`은 group 전체, `event.enable`은 모든 event의 추적을 켠다.

`GROUP.EVENT.filter`는 해당 event의 filter 규칙을 설정하고 `GROUP.EVENT.actions`는 하나 이상의 action을 설정한다. `event.kprobes.EVENT.probes`는 같은 인수 형식을 가진 하나 이상의 probe로 새 kprobe event를 정의하며 group 이름이 `kprobes`인 event에서만 사용할 수 있다.

`event.synthetic.EVENT.fields`는 `type varname` 형식의 field 목록으로 새 synthetic event를 정의한다. kprobe와 synthetic event 정의는 instance node 아래에 작성할 수 있지만 다른 instance에서도 보이므로 event 이름 충돌을 피해야 한다.

Ftrace Per-Event Options
------------------------

These options are setting per-event options.

ftrace.[instance.INSTANCE.]event.GROUP.EVENT.enable
   Enable GROUP:EVENT tracing.

ftrace.[instance.INSTANCE.]event.GROUP.enable
   Enable all event tracing within GROUP.

ftrace.[instance.INSTANCE.]event.enable
   Enable all event tracing.

ftrace.[instance.INSTANCE.]event.GROUP.EVENT.filter = FILTER
   Set FILTER rule to the GROUP:EVENT.

ftrace.[instance.INSTANCE.]event.GROUP.EVENT.actions = ACTION[, ACTION2[...]]
   Set ACTIONs to the GROUP:EVENT.

ftrace.[instance.INSTANCE.]event.kprobes.EVENT.probes = PROBE[, PROBE2[...]]
   Defines new kprobe event based on PROBEs. It is able to define
   multiple probes on one event, but those must have same type of
   arguments. This option is available only for the event which
   group name is "kprobes".

ftrace.[instance.INSTANCE.]event.synthetic.EVENT.fields = FIELD[, FIELD2[...]]
   Defines new synthetic event with FIELDs. Each field should be
   "type varname".

Note that kprobe and synthetic event definitions can be written under
instance node, but those are also visible from other instances. So please
take care for event name conflict.

히스토그램 키·값·정렬·변수와 제어

event action 문자열로 histogram 전체를 쓰면 너무 길어지므로 event의 `hist` 하위에 트리형 옵션을 제공한다. 각 매개변수의 자세한 의미는 `Documentation/trace/histogram.rst`를 참조한다.

`hist.[N.]keys`는 필수 key 목록이다. 여러 histogram을 둘 때 `N`은 숫자 문자열이며 하나뿐이면 생략할 수 있다. `values`, `sort`, `size`, `name`은 각각 값 목록, 정렬 옵션, entry 수, histogram 이름을 지정한다.

`var.VARIABLE = EXPR`은 식으로 새 변수를 정의한다. `pause`, `continue`, `clear` 중 하나를 제어 매개변수로 설정할 수 있다.

Ftrace Histogram Options
------------------------

Since it is too long to write a histogram action as a string for per-event
action option, there are tree-style options under per-event 'hist' subkey
for the histogram actions. For the detail of the each parameter,
please read the event histogram document (Documentation/trace/histogram.rst)

ftrace.[instance.INSTANCE.]event.GROUP.EVENT.hist.[N.]keys = KEY1[, KEY2[...]]
  Set histogram key parameters. (Mandatory)
  The 'N' is a digit string for the multiple histogram. You can omit it
  if there is one histogram on the event.

ftrace.[instance.INSTANCE.]event.GROUP.EVENT.hist.[N.]values = VAL1[, VAL2[...]]
  Set histogram value parameters.

ftrace.[instance.INSTANCE.]event.GROUP.EVENT.hist.[N.]sort = SORT1[, SORT2[...]]
  Set histogram sort parameter options.

ftrace.[instance.INSTANCE.]event.GROUP.EVENT.hist.[N.]size = NR_ENTRIES
  Set histogram size (number of entries).

ftrace.[instance.INSTANCE.]event.GROUP.EVENT.hist.[N.]name = NAME
  Set histogram name.

ftrace.[instance.INSTANCE.]event.GROUP.EVENT.hist.[N.]var.VARIABLE = EXPR
  Define a new VARIABLE by EXPR expression.

ftrace.[instance.INSTANCE.]event.GROUP.EVENT.hist.[N.]<pause|continue|clear>
  Set histogram control parameter. You can set one of them.

ftrace.[instance.INSTANCE.]event.GROUP.EVENT.hist.[N.]onmatch.[M.]event = GROUP.EVENT

onmatch·onmax·onchange handler와 filter

`onmatch.[M.]event`는 일치시킬 `GROUP.EVENT`를 지정한다. 여러 handler를 둘 때 `M`은 숫자 문자열이고 하나뿐이면 생략할 수 있다. `onmatch.[M].trace`는 일치 시 실행할 synthetic event와 인수를 지정하며 `onmatch.event`를 설정했다면 필수다.

`onmax.[M].var`와 `onchange.[M].var`는 각각 최대값 또는 값 변경을 감시할 변수를 지정한다. 두 handler의 `save`는 저장할 인수 목록이고 `snapshot`은 snapshot action이다. `onmax.var`나 `onchange.var`를 설정했다면 `save`와 `snapshot` 중 하나가 필수다.

`hist.filter = FILTER_EXPR`는 histogram filter 식을 설정하며 식 앞에 `if`를 쓰지 않는다. event의 `actions` 옵션에도 histogram action이 있으면 이 트리형 `hist` 옵션과 충돌할 수 있다.

  Set histogram 'onmatch' handler matching event parameter.
  The 'M' is a digit string for the multiple 'onmatch' handler. You can omit it
  if there is one 'onmatch' handler on this histogram.

ftrace.[instance.INSTANCE.]event.GROUP.EVENT.hist.[N.]onmatch.[M.]trace = EVENT[, ARG1[...]]
  Set histogram 'trace' action for 'onmatch'.
  EVENT must be a synthetic event name, and ARG1... are parameters
  for that event. Mandatory if 'onmatch.event' option is set.

ftrace.[instance.INSTANCE.]event.GROUP.EVENT.hist.[N.]onmax.[M.]var = VAR
  Set histogram 'onmax' handler variable parameter.

ftrace.[instance.INSTANCE.]event.GROUP.EVENT.hist.[N.]onchange.[M.]var = VAR
  Set histogram 'onchange' handler variable parameter.

ftrace.[instance.INSTANCE.]event.GROUP.EVENT.hist.[N.]<onmax|onchange>.[M.]save = ARG1[, ARG2[...]]
  Set histogram 'save' action parameters for 'onmax' or 'onchange' handler.
  This option or below 'snapshot' option is mandatory if 'onmax.var' or
  'onchange.var' option is set.

ftrace.[instance.INSTANCE.]event.GROUP.EVENT.hist.[N.]<onmax|onchange>.[M.]snapshot
  Set histogram 'snapshot' action for 'onmax' or 'onchange' handler.
  This option or above 'save' option is mandatory if 'onmax.var' or
  'onchange.var' option is set.

ftrace.[instance.INSTANCE.]event.GROUP.EVENT.hist.filter = FILTER_EXPR
  Set histogram filter expression. You don't need 'if' in the FILTER_EXPR.

Note that this 'hist' option can conflict with the per-event 'actions'
option if the 'actions' option has a histogram action.

추적 활성화 시점

`ftrace`로 시작하는 모든 boot-time tracing 옵션은 `core_initcall` 끝에서 활성화된다. 따라서 `postcore_initcall`부터 발생하는 event를 추적할 수 있다. 대부분의 subsystem과 아키텍처 의존 driver는 그 뒤의 `arch_initcall` 또는 `subsys_initcall`에서 초기화되므로 boot-time tracing으로 관찰할 수 있다.

`core_initcall`보다 앞선 event가 필요하면 `kernel`로 시작하는 옵션을 사용한다. 일부는 initcall 처리보다 먼저 켜지며 `kernel.ftrace=function`과 `kernel.trace_event`가 그 예다.

When to Start
=============

All boot-time tracing options starting with ``ftrace`` will be enabled at the
end of core_initcall. This means you can trace the events from postcore_initcall.
Most of the subsystems and architecture dependent drivers will be initialized
after that (arch_initcall or subsys_initcall). Thus, you can trace those with
boot-time tracing.
If you want to trace events before core_initcall, you can use the options
starting with ``kernel``. Some of them will be enabled earlier than the initcall
processing (for example, ``kernel.ftrace=function`` and ``kernel.trace_event``
will start before the initcall.)

filter·kprobe·synthetic event와 initcall 지연

첫 예제는 event마다 filter와 action을 추가하고 kprobe event, synthetic event, histogram을 함께 정의한다. `task.task_newtask`는 `pid < 128`인 event만 활성화한다. `kprobes.vfs_read`는 `vfs_read $arg1 $arg2` probe를 만들고 `common_pid < 200` filter를 적용한다.

`synthetic.initcall_latency`는 `unsigned long func`와 `u64 lat` field를 가지며 `func.sym`, `lat`를 key로, `lat`를 value와 sort 기준으로 쓰는 histogram을 둔다.

`initcall_start` histogram은 `func`를 key로 시작 timestamp를 microsecond 단위 변수 `ts0`에 저장한다. `initcall_finish`는 현재 timestamp에서 `$ts0`를 빼 `lat`를 계산하고, start event와 일치시키는 `onmatch` handler에서 `initcall_latency` synthetic event에 `func`와 `$lat`를 전달한다.

Examples
========

For example, to add filter and actions for each event, define kprobe
events, and synthetic events with histogram, write a boot config like
below::

  ftrace.event {
        task.task_newtask {
                filter = "pid < 128"
                enable
        }
        kprobes.vfs_read {
                probes = "vfs_read $arg1 $arg2"
                filter = "common_pid < 200"
                enable
        }
        synthetic.initcall_latency {
                fields = "unsigned long func", "u64 lat"
                hist {
                        keys = func.sym, lat
                        values = lat
                        sort = lat
                }
        }
        initcall.initcall_start.hist {
                keys = func
                var.ts0 = common_timestamp.usecs
        }
        initcall.initcall_finish.hist {
                keys = func
                var.lat = common_timestamp.usecs - $ts0
                onmatch {
                        event = initcall.initcall_start
                        trace = initcall_latency, func, $lat
                }
        }
  }

목적별 다중 trace instance

Boot-time tracing은 여러 tracer를 서로 다른 목적으로 동시에 실행하는 `instance` node를 지원한다. 예제의 `foo`와 `bar`는 모두 `function` tracer를 사용하지만 함수 filter를 분리한다.

`foo`는 `user_*`로 시작하는 함수만, `bar`는 `kernel_*`로 시작하는 함수만 추적한다. instance node는 event node도 받을 수 있으므로 각 instance가 event tracing을 독립적으로 맞춤 설정할 수 있다.

Also, boot-time tracing supports "instance" node, which allows us to run
several tracers for different purpose at once. For example, one tracer
is for tracing functions starting with "user\_", and others tracing
"kernel\_" functions, you can write boot config as below::

  ftrace.instance {
        foo {
                tracer = "function"
                ftrace.filters = "user_*"
        }
        bar {
                tracer = "function"
                ftrace.filters = "kernel_*"
        }
  }

The instance node also accepts event nodes so that each instance
can customize its event tracing.

kprobe action으로 함수 그래프 구간 제한

trigger action과 kprobe를 결합하면 특정 함수가 실행되는 동안에만 function graph를 추적할 수 있다. 예제는 `tracing_on = 0`으로 시작하고 tracer를 `function_graph`로 설정한다.

`start_event`는 `pci_proc_init` 진입 kprobe에서 `traceon` action을 실행한다. `end_event`는 `pci_proc_init%return` 반환 probe에서 `traceoff` action을 실행한다. 결과적으로 `pci_proc_init()` 내부에서 호출되는 모든 함수만 기록한다.

With the trigger action and kprobes, you can trace function-graph while
a function is called. For example, this will trace all function calls in
the pci_proc_init()::

  ftrace {
        tracing_on = 0
        tracer = function_graph
        event.kprobes {
                start_event {
                        probes = "pci_proc_init"
                        actions = "traceon"
                }
                end_event {
                        probes = "pci_proc_init%return"
                        actions = "traceoff"
                }
        }
  }

기존 ftrace 커널 매개변수의 bootconfig 표현

Boot-time tracing은 기존 ftrace 커널 매개변수도 bootconfig에서 지원한다. 원래 명령줄의 `trace_options=sym-addr`, `trace_event=initcall:*`, `tp_printk`, `trace_buf_size=1M`, `ftrace=function`, `ftrace_filter="vfs*"`를 `kernel` node 아래의 같은 이름 key로 옮길 수 있다.

이 매개변수들은 트리형 `ftrace` 접두어가 아니라 `kernel` 접두어로 시작한다는 점이 핵심이다.

This boot-time tracing also supports ftrace kernel parameters via boot
config.
For example, following kernel parameters::

 trace_options=sym-addr trace_event=initcall:* tp_printk trace_buf_size=1M ftrace=function ftrace_filter="vfs*"

This can be written in boot config like below::

  kernel {
        trace_options = sym-addr
        trace_event = "initcall:*"
        tp_printk
        trace_buf_size = 1M
        ftrace = function
        ftrace_filter = "vfs*"
  }

Note that parameters start with "kernel" prefix instead of "ftrace".