funcslower - Trace slow kernel or user function calls. funcslower [-hf] [-p PID] [-U | -K] [-m MIN_MS] [-u MIN_US] [-a ARGUMENTS] [-T] [-t] [-v] function [function ...] This script traces a kernel or user function's entry and return points, and prints a message when the function's latency exceeded the specified threshold. Multiple functions are supported, and you can mix kernel functions with user functions in different libraries. WARNING: See the OVERHEAD section. By default, a minimum millisecond threshold of 1 is used. Recursive functions are not supported: only the inner-most recursive invocation will be traced. Since this uses BPF, only the root user can use this tool. CONFIG_BPF and bcc. -p PID Trace this PID only.

-m MIN_NS Minimum duration to trace, in milliseconds. Default is 1 ms.

-u MIN_US Minimum duration to trace, in microseconds.

-a ARGUMENTS Print the function's arguments, up to 6.

-T Print a HH:MM:SS timestamp with each entry.

-t Print a seconds timestamp with each entry, at microsecond resolution.

-f Print output in folded stack format.

-U Show stacks from user space only (no kernel space stacks).

-K Show stacks from kernel space only (no user space stacks).

-v Print the resulting BPF program, for debugging purposes.

function The function to trace -- multiple functions are supported. If a plain function name is provided, the function is assumed to be a kernel function. For user functions, provide the library name and the function name, e.g. bash:readline or c:malloc.

Trace vfs_write calls slower than 1ms: # funcslower vfs_write

Trace open() calls in libc slower than 10us: # funcslower -u 10 c:open

Trace both malloc() and free() slower than 10us, in pid 135 only: # funcslower -p 135 -u 10 c:malloc c:free

Trace the write syscall and print its first 4 arguments: # funcslower -a 4 SyS_write

Trace opens from libc and print the user and kernel stack frames: # funcslower -UK c:open

TIME Time of the event as a human-readable HH:MM:SS format, or a timestamp in seconds at microsecond-accuracy from the first event seen.

COMM Process name.

PID Process ID.

LAT Latency of the operation in either microseconds (us) or milliseconds (ms).

RVAL The return value from the function. Often useful for diagnosing a relationship between slow and failed function calls.

FUNC The function name, followed by its arguments if requested.

Depending on the function(s) being traced, overhead can become severe. For example, tracing a common function like malloc() can slow down a C/C++ program by a factor of 2 or more. On the other hand, tracing a low-frequency event like the SyS_setreuid() function will probably not be as prohibitive, and in fact negligible for functions that are called up to 100-1000 times per second. You should first use the funclatency and argdist tools for investigation, because they summarize data in-kernel and have a much lower overhead than this tool. To get a general idea of the number of times a particular function is called (and estimate the overhead), use the funccount tool, e.g.:

# funccount c:open

This is from bcc. https://github.com/iovisor/bcc

Also look in the bcc distribution for a companion _examples.txt file containing example usage, output, and commentary for this tool.

Linux Unstable - in development. Sasha Goldshtein funccount(8), funclatency(8), argdist(8), trace(8)