klockstat(8)

๐Ÿ“ฆ
version 0.35.0 ยท 2 versions
, in debian trixie, ubuntu noble, ubuntu questing, ubuntu resolute, ubuntu stonking

๐ŸŽ€ klockstat(8) ๐ŸŽ€

System Manager's Manual, the vibe is immaculate ๐Ÿ’…

๐ŸŒธ NAME ๐ŸŒธ

klockstat traces kernel mutex lock events and shows you lock stats. It's built on Linux eBPF/bcc. โœจ

๐Ÿฆ‹ SYNOPSIS ๐Ÿฆ‹

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

๐Ÿ’– DESCRIPTION ๐Ÿ’–

okay so klockstat is literally a kernel mutex detective ๐Ÿ•ต๏ธโ€โ™€๏ธ it traces mutex lock events and then serves you the lock statistics, and the output looks like this:

                                         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 the kernel's mutex gets its own line, bestie. ๐Ÿซถ

The first chunk of lines is the lock acquiring data, which tells you how long it took to actually grab a given lock. ๐Ÿ”’

  • Caller โ€” the symbol grabbing the mutex ๐Ÿ’โ€โ™€๏ธ
  • Avg Spin โ€” the average time it took to acquire the mutex ๐Ÿ“ˆ
  • Count โ€” how many times the mutex got acquired ๐Ÿ”ข
  • Max spin โ€” the longest it took to acquire the mutex ๐Ÿ˜ญ
  • Total spin โ€” the grand total of time spent acquiring the mutex ๐Ÿงฎ

The second chunk is the lock holding data, which shows how long a lock was actually held. ๐Ÿค

  • Caller โ€” the symbol holding the mutex ๐Ÿ’…
  • Avg Hold โ€” the average time the mutex was held โฑ๏ธ
  • Count โ€” how many times the mutex was held ๐Ÿ”
  • Max hold โ€” the longest the mutex was held ๐Ÿซ 
  • Total hold โ€” the total time spent holding the mutex ๐Ÿ’œ

Here's the tea โ˜• this works by tracing mutex_lock/unlock kprobes, updating the lock stats in maps, and then processing all of that in the python part. it's giving clever engineering ๐Ÿงš

โš ๏ธ bestie, this uses BPF, so only the root user can run this tool. no sudo, no tool. that's the rule ๐Ÿ™…โ€โ™€๏ธ

๐Ÿงฉ REQUIREMENTS ๐Ÿงฉ

You'll need CONFIG_BPF and bcc, periodt. ๐Ÿ› ๏ธ

โœจ OPTIONS โœจ

  • -h โ€” prints the usage message, in case you forget how to use it ๐Ÿ™ˆ
  • -i SEC โ€” prints a summary at this interval, measured in seconds โฐ
  • -c CALLER โ€” only shows the locks taken by the caller you filter for, like pipe_ ๐Ÿ”
  • -S FIELDS โ€” sorts the data by the columns you name in the FIELDS string. By default it sorts by the Max columns ๐Ÿ“Š

The FIELDS string can hold 1 or 2 fields that describe which columns to sort on, for both the acquiring and holding data. These are the options you've got:

  • acq_max โ€” for the Max spin column ๐Ÿ”
  • acq_total โ€” for the Total spin column ๐Ÿงพ
  • acq_count โ€” for the Count column ๐Ÿ”ข
  • hld_max โ€” for the Max hold column ๐Ÿ”
  • hld_total โ€” for the Total hold column ๐Ÿงพ
  • hld_count โ€” for the Count column ๐Ÿ”ข

See EXAMPLES for the vibes ๐Ÿ‘€

  • -n COUNT โ€” shows COUNT number of locks ๐ŸŽฏ
  • -s COUNT โ€” shows COUNT number of stack entries ๐Ÿฅž
  • -p PID โ€” traces only this process ID, filtered in-kernel ๐Ÿง 
  • -t TID โ€” traces only this thread ID, filtered in-kernel ๐Ÿงต
  • -d DURATION โ€” the total duration of the trace in seconds โณ
  • --stack-storage-size STACK_STORAGE_SIZE โ€” changes how many unique stack traces can be stored and displayed. Go bigger if you need more receipts ๐Ÿ“ฆ

๐Ÿ“ EXAMPLES ๐Ÿ“

Sort lock acquired results on acquired count:

# klockstat -S acq_count

Sort lock held results on total held time:

# klockstat -S hld_total

Combo of the above:

# klockstat -S acq_count,hld_total

Trace the whole system:

# klockstat

Trace for just 5 seconds:

# 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 the 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

Here's what that looks like in action ๐ŸŽฌ

          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 comes from bcc ๐Ÿฆ‹ you can find it at https://github.com/iovisor/bcc

Also, check the bcc distribution for a companion _examples.txt file. It has example usage, output, and commentary for this tool, and it's a whole mood ๐Ÿ“–

๐Ÿ–ฅ๏ธ OS ๐Ÿ–ฅ๏ธ

Linux ๐Ÿง

๐Ÿงช STABILITY ๐Ÿงช

Unstable, it's still in development ๐Ÿšง

๐Ÿซถ CREDITS ๐Ÿซถ

This tool is based on the work of David Valin <dvalin@redhat.com> and his script. Thank you, queen ๐Ÿ‘‘

๐Ÿ’œ AUTHOR ๐Ÿ’œ

Jiri Olsa ๐Ÿงš


USER COMMANDS โœจ 2019-10-22 โœจ klockstat(8) ๐ŸŒˆ๐Ÿ’– ttyl bestie!