klockstat(8)

NAME
klockstat - Traces kernel mutex lock events and display locks statistics. Uses Linux eBPF/bcc.

SYNOPSIS
klockstat [-h] [-i] [-n] [-s] [-c] [-S FIELDS] [-p] [-t] [-d DURATION]

DESCRIPTION
klockstat traces kernel mutex lock events and display locks statistics and displays following data:

                        Caller Avg Spin Count Max spin Total spin
                      psi_avgs_work+0x2e 3675 5 5468 18379
                     flush_to_ldisc+0x22 2833 2 4210 5667
                       n_tty_write+0x30c 3914 1 3914 3914
                        isig+0x5d 2390 1 2390 2390
                   tty_buffer_flush+0x2a 1604 1 1604 1604
                      commit_echoes+0x22 1400 1 1400 1400
          n_tty_receive_buf_common+0x3b9 1399 1 1399 1399

                        Caller Avg Hold Count Max hold Total hold
                     flush_to_ldisc+0x22 42558 2 76135 85116
                      psi_avgs_work+0x2e 14821 5 20446 74106
          n_tty_receive_buf_common+0x3b9 12300 1 12300 12300
                       n_tty_write+0x30c 10712 1 10712 10712
                        isig+0x5d 3362 1 3362 3362
                   tty_buffer_flush+0x2a 3078 1 3078 3078
                      commit_echoes+0x22 3017 1 3017 3017

Every caller to using kernel's mutex is displayed on every line.

First portion of lines show the lock acquiring data, showing the amount of time it took to acquired given lock.

  'Caller' - symbol acquiring the mutex
  'Average Spin' - average time to acquire the mutex
  'Count' - number of times mutex was acquired
  'Max spin' - maximum time to acquire the mutex
  'Total spin' - total time spent in acquiring the mutex

Second portion of lines show the lock holding data, showing the amount of time it took to hold given lock.

  'Caller' - symbol holding the mutex
  'Average Hold' - average time mutex was held
  'Count' - number of times mutex was held
  'Max hold' - maximum time mutex was held
  'Total hold' - total time spent in holding the mutex

This works by tracing mutex_lock/unlock kprobes, updating the lock stats in maps and processing them in the python part.

Since this uses BPF, only the root user can use this tool.

REQUIREMENTS
CONFIG_BPF and bcc.

OPTIONS

-h  Print usage message.

-i SEC
    print summary at this interval (seconds)

-c CALLER
    print locks taken by given caller filter (e.g., pipe_)

-S FIELDS
    sort data on specific columns defined by FIELDS string (by default the data is sorted by Max columns)

    FIELDS string contains 1 or 2 fields describing columns to sort on for both acquiring and holding data. Following fields are available:

      acq_max for 'Max spin' column
      acq_total for 'Total spin' column
      acq_count for 'Count' column

      hld_max for 'Max hold' column
      hld_total for 'Total hold' column
      hld_count for 'Count' column

    See EXAMPLES.

-n COUNT
    print COUNT number of locks

-s COUNT
    print COUNT number of stack entries

-p PID
    Trace this process ID only (filtered in-kernel).

-t TID
    Trace this thread ID only (filtered in-kernel).

-d DURATION
    Total duration of trace in seconds.

--stack-storage-size STACK_STORAGE_SIZE
    Change the number of unique stack traces that can be stored and displayed.

EXAMPLES

Sort lock acquired results on acquired count:
    # klockstat -S acq_count

Sort lock held results on total held time:
    # klockstat -S hld_total

Combination of above:
    # klockstat -S acq_count,hld_total

Trace system wide:
    # klockstat

Trace for 5 seconds only:
    # klockstat -d 5

Display stats every 5 seconds
    # klockstat -i 5

Trace locks for PID 123:
    # klockstat -p 123

Trace locks for TID 321:
    # klockstat -t 321

Display stats only for lock callers with 'pipe_' substring
    # klockstat -c pipe_

Display 3 locks:
    # klockstat -n 3

Display 10 levels of stack for the most expensive lock:
    # klockstat -n 1 -s 10

    Tracing lock events... Hit Ctrl-C to end. ^C
                            Caller Avg Spin Count Max spin Total spin
                            pipe_wait+0xa9 670 397691 17273 266775437
                            pipe_wait+0xa9
                            pipe_read+0x206
                         new_sync_read+0x12a
                            vfs_read+0x9d
                            ksys_read+0x5f
                          do_syscall_64+0x5b
         entry_SYSCALL_64_after_hwframe+0x44

                            Caller Avg Hold Count Max hold Total hold
                         flush_to_ldisc+0x22 28381 3 65484 85144
                         flush_to_ldisc+0x22
                      process_one_work+0x1b0
                          worker_thread+0x50
                            kthread+0xfb
                          ret_from_fork+0x35

SOURCE
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.

OS
Linux

STABILITY
Unstable - in development.

CREDITS
This tool is based on work of David Valin <dvalin@redhat.com> and his script.

AUTHOR
Jiri Olsa