diff options
Diffstat (limited to 'Documentation/trace/ftrace.rst')
| -rw-r--r-- | Documentation/trace/ftrace.rst | 271 |
1 files changed, 255 insertions, 16 deletions
diff --git a/Documentation/trace/ftrace.rst b/Documentation/trace/ftrace.rst index 60bceb018d6a..d1f313a5f4ad 100644 --- a/Documentation/trace/ftrace.rst +++ b/Documentation/trace/ftrace.rst @@ -30,7 +30,7 @@ disabled and enabled, as well as for preemption and from a time a task is woken to the task is actually scheduled in. One of the most common uses of ftrace is the event tracing. -Throughout the kernel is hundreds of static event points that +Throughout the kernel are hundreds of static event points that can be enabled via the tracefs file system to see what is going on in certain parts of the kernel. @@ -180,6 +180,21 @@ of ftrace. Here is a list of some of the key files: Only active when the file contains a number greater than 0. (in microseconds) + buffer_percent: + + This is the watermark for how much the ring buffer needs to be filled + before a waiter is woken up. That is, if an application calls a + blocking read syscall on one of the per_cpu trace_pipe_raw files, it + will block until the given amount of data specified by buffer_percent + is in the ring buffer before it wakes the reader up. This also + controls how the splice system calls are blocked on this file:: + + 0 - means to wake up as soon as there is any data in the ring buffer. + 50 - means to wake up when roughly half of the ring buffer sub-buffers + are full. + 100 - means to block until the ring buffer is totally full and is + about to start overwriting the older data. + buffer_size_kb: This sets or displays the number of kilobytes each CPU @@ -203,6 +218,27 @@ of ftrace. Here is a list of some of the key files: This displays the total combined size of all the trace buffers. + buffer_subbuf_size_kb: + + This sets or displays the sub buffer size. The ring buffer is broken up + into several same size "sub buffers". An event can not be bigger than + the size of the sub buffer. Normally, the sub buffer is the size of the + architecture's page (4K on x86). The sub buffer also contains meta data + at the start which also limits the size of an event. That means when + the sub buffer is a page size, no event can be larger than the page + size minus the sub buffer meta data. + + Note, the buffer_subbuf_size_kb is a way for the user to specify the + minimum size of the subbuffer. The kernel may make it bigger due to the + implementation details, or simply fail the operation if the kernel can + not handle the request. + + Changing the sub buffer size allows for events to be larger than the + page size. + + Note: When changing the sub-buffer size, tracing is stopped and any + data in the ring buffer and the snapshot buffer will be discarded. + free_buffer: If a process is performing tracing, and the ring buffer should be @@ -324,6 +360,20 @@ of ftrace. Here is a list of some of the key files: "set_graph_function", or "set_graph_notrace". (See the section "dynamic ftrace" below for more details.) + available_filter_functions_addrs: + + Similar to available_filter_functions, but with address displayed + for each function. The displayed address is the patch-site address + and can differ from /proc/kallsyms address. + + syscall_user_buf_size: + + Some system call trace events will record the data from a user + space address that one of the parameters point to. The amount of + data per event is limited. This file holds the max number of bytes + that will be recorded into the ring buffer to hold this data. + The max value is currently 165. + dyn_ftrace_total_info: This file is for debugging purposes. The number of functions that @@ -341,7 +391,7 @@ of ftrace. Here is a list of some of the key files: not be listed in this count. If the callback registered to be traced by a function with - the "save regs" attribute (thus even more overhead), a 'R' + the "save regs" attribute (thus even more overhead), an 'R' will be displayed on the same line as the function that is returning registers. @@ -350,6 +400,19 @@ of ftrace. Here is a list of some of the key files: an 'I' will be displayed on the same line as the function that can be overridden. + If a non-ftrace trampoline is attached (BPF) a 'D' will be displayed. + Note, normal ftrace trampolines can also be attached, but only one + "direct" trampoline can be attached to a given function at a time. + + Some architectures can not call direct trampolines, but instead have + the ftrace ops function located above the function entry point. In + such cases an 'O' will be displayed. + + If a function had either the "ip modify" or a "direct" call attached to + it in the past, a 'M' will be shown. This flag is never cleared. It is + used to know if a function was ever modified by the ftrace infrastructure, + and can be used for debugging. + If the architecture supports it, it will also show what callback is being directly called by the function. If the count is greater than 1 it most likely will be ftrace_ops_list_func(). @@ -359,6 +422,18 @@ of ftrace. Here is a list of some of the key files: its address will be printed as well as the function that the trampoline calls. + touched_functions: + + This file contains all the functions that ever had a function callback + to it via the ftrace infrastructure. It has the same format as + enabled_functions but shows all functions that have ever been + traced. + + To see any function that has every been modified by "ip modify" or a + direct trampoline, one can perform the following command: + + grep ' M ' /sys/kernel/tracing/touched_functions + function_profile_enabled: When set it will enable all functions with either the function @@ -450,7 +525,7 @@ of ftrace. Here is a list of some of the key files: Whenever an event is recorded into the ring buffer, a "timestamp" is added. This stamp comes from a specified clock. By default, ftrace uses the "local" clock. This - clock is very fast and strictly per cpu, but on some + clock is very fast and strictly per CPU, but on some systems it may not be monotonic with respect to other CPUs. In other words, the local clocks may not be in sync with local clocks on other CPUs. @@ -743,6 +818,12 @@ Here is the list of current tracers that may be configured. to draw a graph of function calls similar to C code source. + Note that the function graph calculates the timings of when the + function starts and returns internally and for each instance. If + there are two instances that run function graph tracer and traces + the same functions, the length of the timings may be slightly off as + each read the timestamp separately and not at the same time. + "blk" The block tracer. The tracer used by the blktrace user @@ -795,7 +876,7 @@ Here is the list of current tracers that may be configured. "mmiotrace" - A special tracer that is used to trace binary module. + A special tracer that is used to trace binary modules. It will trace all the calls that a module makes to the hardware. Everything it writes and reads from the I/O as well. @@ -830,10 +911,10 @@ Error conditions The extended error information and usage takes the form shown in this example:: - # echo xxx > /sys/kernel/debug/tracing/events/sched/sched_wakeup/trigger + # echo xxx > /sys/kernel/tracing/events/sched/sched_wakeup/trigger echo: write error: Invalid argument - # cat /sys/kernel/debug/tracing/error_log + # cat /sys/kernel/tracing/error_log [ 5348.887237] location: error: Couldn't yyy: zzz Command: xxx ^ @@ -843,7 +924,7 @@ Error conditions To clear the error log, echo the empty string into it:: - # echo > /sys/kernel/debug/tracing/error_log + # echo > /sys/kernel/tracing/error_log Examples of using the tracer ---------------------------- @@ -964,14 +1045,15 @@ explains which is which. CPU#: The CPU which the process was running on. irqs-off: 'd' interrupts are disabled. '.' otherwise. - .. caution:: If the architecture does not support a way to - read the irq flags variable, an 'X' will always - be printed here. need-resched: + - 'B' all, TIF_NEED_RESCHED, PREEMPT_NEED_RESCHED and TIF_RESCHED_LAZY is set, - 'N' both TIF_NEED_RESCHED and PREEMPT_NEED_RESCHED is set, - 'n' only TIF_NEED_RESCHED is set, - 'p' only PREEMPT_NEED_RESCHED is set, + - 'L' both PREEMPT_NEED_RESCHED and TIF_RESCHED_LAZY is set, + - 'b' both TIF_NEED_RESCHED and TIF_RESCHED_LAZY is set, + - 'l' only TIF_RESCHED_LAZY is set - '.' otherwise. hardirq/softirq: @@ -1027,6 +1109,7 @@ To see what is available, simply cat the file:: nohex nobin noblock + nofields trace_printk annotate nouserstacktrace @@ -1110,9 +1193,39 @@ Here are the available options: block When set, reading trace_pipe will not block when polled. + fields + Print the fields as described by their types. This is a better + option than using hex, bin or raw, as it gives a better parsing + of the content of the event. + trace_printk Can disable trace_printk() from writing into the buffer. + trace_printk_dest + Set to have trace_printk() and similar internal tracing functions + write into this instance. Note, only one trace instance can have + this set. By setting this flag, it clears the trace_printk_dest flag + of the instance that had it set previously. By default, the top + level trace has this set, and will get it set again if another + instance has it set then clears it. + + This flag cannot be cleared by the top level instance, as it is the + default instance. The only way the top level instance has this flag + cleared, is by it being set in another instance. + + copy_trace_marker + If there are applications that hard code writing into the top level + trace_marker file (/sys/kernel/tracing/trace_marker or trace_marker_raw), + and the tooling would like it to go into an instance, this option can + be used. Create an instance and set this option, and then all writes + into the top level trace_marker file will also be redirected into this + instance. + + Note, by default this option is set for the top level instance. If it + is disabled, then writes to the trace_marker or trace_marker_raw files + will not be written into the top level file. If no instance has this + option set, then a write will error with the errno of ENODEV. + annotate It is sometimes confusing when the CPU buffers are full and one CPU buffer had a lot of events recently, thus @@ -1328,6 +1441,19 @@ Options for function_graph tracer: only a closing curly bracket "}" is displayed for the return of a function. + funcgraph-retval + When set, the return value of each traced function + will be printed after an equal sign "=". By default + this is off. + + funcgraph-retval-hex + When set, the return value will always be printed + in hexadecimal format. If the option is not set and + the return value is an error code, it will be printed + in signed decimal format; otherwise it will also be + printed in hexadecimal format. By default, this option + is off. + sleep-time When running function graph tracer, to include the time a task schedules out in its function. @@ -1882,7 +2008,7 @@ wakeup One common case that people are interested in tracing is the time it takes for a task that is woken to actually wake up. Now for non Real-Time tasks, this can be arbitrary. But tracing -it none the less can be interesting. +it nonetheless can be interesting. Without function tracing:: @@ -2524,7 +2650,7 @@ want, depending on your needs. - The cpu number on which the function executed is default enabled. It is sometimes better to only trace one cpu (see - tracing_cpu_mask file) or you might sometimes see unordered + tracing_cpumask file) or you might sometimes see unordered function calls while cpu tracing switch. - hide: echo nofuncgraph-cpu > trace_options @@ -2673,6 +2799,119 @@ It is default disabled. 0) 1.757 us | } /* kmem_cache_free() */ 0) 2.861 us | } /* putname() */ +The return value of each traced function can be displayed after +an equal sign "=". When encountering system call failures, it +can be very helpful to quickly locate the function that first +returns an error code. + + - hide: echo nofuncgraph-retval > trace_options + - show: echo funcgraph-retval > trace_options + + Example with funcgraph-retval:: + + 1) | cgroup_migrate() { + 1) 0.651 us | cgroup_migrate_add_task(); /* = 0xffff93fcfd346c00 */ + 1) | cgroup_migrate_execute() { + 1) | cpu_cgroup_can_attach() { + 1) | cgroup_taskset_first() { + 1) 0.732 us | cgroup_taskset_next(); /* = 0xffff93fc8fb20000 */ + 1) 1.232 us | } /* cgroup_taskset_first = 0xffff93fc8fb20000 */ + 1) 0.380 us | sched_rt_can_attach(); /* = 0x0 */ + 1) 2.335 us | } /* cpu_cgroup_can_attach = -22 */ + 1) 4.369 us | } /* cgroup_migrate_execute = -22 */ + 1) 7.143 us | } /* cgroup_migrate = -22 */ + +The above example shows that the function cpu_cgroup_can_attach +returned the error code -22 firstly, then we can read the code +of this function to get the root cause. + +When the option funcgraph-retval-hex is not set, the return value can +be displayed in a smart way. Specifically, if it is an error code, +it will be printed in signed decimal format, otherwise it will +printed in hexadecimal format. + + - smart: echo nofuncgraph-retval-hex > trace_options + - hexadecimal: echo funcgraph-retval-hex > trace_options + + Example with funcgraph-retval-hex:: + + 1) | cgroup_migrate() { + 1) 0.651 us | cgroup_migrate_add_task(); /* = 0xffff93fcfd346c00 */ + 1) | cgroup_migrate_execute() { + 1) | cpu_cgroup_can_attach() { + 1) | cgroup_taskset_first() { + 1) 0.732 us | cgroup_taskset_next(); /* = 0xffff93fc8fb20000 */ + 1) 1.232 us | } /* cgroup_taskset_first = 0xffff93fc8fb20000 */ + 1) 0.380 us | sched_rt_can_attach(); /* = 0x0 */ + 1) 2.335 us | } /* cpu_cgroup_can_attach = 0xffffffea */ + 1) 4.369 us | } /* cgroup_migrate_execute = 0xffffffea */ + 1) 7.143 us | } /* cgroup_migrate = 0xffffffea */ + +At present, there are some limitations when using the funcgraph-retval +option, and these limitations will be eliminated in the future: + +- Even if the function return type is void, a return value will still + be printed, and you can just ignore it. + +- Even if return values are stored in multiple registers, only the + value contained in the first register will be recorded and printed. + To illustrate, in the x86 architecture, eax and edx are used to store + a 64-bit return value, with the lower 32 bits saved in eax and the + upper 32 bits saved in edx. However, only the value stored in eax + will be recorded and printed. + +- In certain procedure call standards, such as arm64's AAPCS64, when a + type is smaller than a GPR, it is the responsibility of the consumer + to perform the narrowing, and the upper bits may contain UNKNOWN values. + Therefore, it is advisable to check the code for such cases. For instance, + when using a u8 in a 64-bit GPR, bits [63:8] may contain arbitrary values, + especially when larger types are truncated, whether explicitly or implicitly. + Here are some specific cases to illustrate this point: + + **Case One**: + + The function narrow_to_u8 is defined as follows:: + + u8 narrow_to_u8(u64 val) + { + // implicitly truncated + return val; + } + + It may be compiled to:: + + narrow_to_u8: + < ... ftrace instrumentation ... > + RET + + If you pass 0x123456789abcdef to this function and want to narrow it, + it may be recorded as 0x123456789abcdef instead of 0xef. + + **Case Two**: + + The function error_if_not_4g_aligned is defined as follows:: + + int error_if_not_4g_aligned(u64 val) + { + if (val & GENMASK(31, 0)) + return -EINVAL; + + return 0; + } + + It could be compiled to:: + + error_if_not_4g_aligned: + CBNZ w0, .Lnot_aligned + RET // bits [31:0] are zero, bits + // [63:32] are UNKNOWN + .Lnot_aligned: + MOV x0, #-EINVAL + RET + + When passing 0x2_0000_0000 to it, the return value may be recorded as + 0x2_0000_0000 instead of 0. + You can put some comments on specific functions by using trace_printk() For example, if you want to put a comment inside the __might_sleep() function, you just have to include @@ -2859,7 +3098,7 @@ Notice that we lost the sys_nanosleep. # cat set_ftrace_filter hrtimer_run_queues hrtimer_run_pending - hrtimer_init + hrtimer_setup hrtimer_cancel hrtimer_try_to_cancel hrtimer_forward @@ -2897,7 +3136,7 @@ Again, now we want to append. # cat set_ftrace_filter hrtimer_run_queues hrtimer_run_pending - hrtimer_init + hrtimer_setup hrtimer_cancel hrtimer_try_to_cancel hrtimer_forward @@ -2940,7 +3179,7 @@ Produces:: bash-1994 [000] .... 4342.324898: ima_get_action <-process_measurement bash-1994 [000] .... 4342.324898: ima_match_policy <-ima_get_action bash-1994 [000] .... 4342.324899: do_truncate <-do_last - bash-1994 [000] .... 4342.324899: should_remove_suid <-do_truncate + bash-1994 [000] .... 4342.324899: setattr_should_drop_suidgid <-do_truncate bash-1994 [000] .... 4342.324899: notify_change <-do_truncate bash-1994 [000] .... 4342.324900: current_fs_time <-notify_change bash-1994 [000] .... 4342.324900: current_kernel_time <-current_fs_time @@ -3510,7 +3749,7 @@ directories, the rmdir will fail with EBUSY. Stack trace ----------- Since the kernel has a fixed sized stack, it is important not to -waste it in functions. A kernel developer must be conscience of +waste it in functions. A kernel developer must be conscious of what they allocate on the stack. If they add too much, the system can be in danger of a stack overflow, and corruption will occur, usually leading to a system panic. |