Skip to content

Commit

Permalink
added funclatency, a tool for summarizing kernel function latencies
Browse files Browse the repository at this point in the history 
Signed-off-by: Richard Yao <ryao@gentoo.org>
  • Loading branch information
@ryao
ryao committed Jan 1, 2016
1 parent 0c13e83 commit 6e25ea6
Show file tree
Hide file tree
Showing 5 changed files with 518 additions and 0 deletions.
1 change: 1 addition & 0 deletions README.md
View file
Original file line number Diff line number Diff line change
Expand Up @@ -29,6 +29,7 @@ Using ftrace:
- net/[tcpretrans](net/tcpretrans): show TCP retransmits, with address and other details. [Examples](examples/tcpretrans_example.txt).
- system/[tpoint](system/tpoint): trace a given tracepoint. [Examples](examples/tpoint_example.txt).
- kernel/[funccount](kernel/funccount): count kernel function calls, matching a string with wildcards. [Examples](examples/funccount_example.txt).
- kernel/[funclatency](kernel/funclatency): summarize kernel function latency as a histogram. [Examples](examples/funclatency_example.txt).
- kernel/[functrace](kernel/functrace): trace kernel function calls, matching a string with wildcards. [Examples](examples/functrace_example.txt).
- kernel/[funcslower](kernel/funcslower): trace kernel functions slower than a threshold. [Examples](examples/funcslower_example.txt).
- kernel/[funcgraph](kernel/funcgraph): trace a graph of kernel function calls, showing children and times. [Examples](examples/funcgraph_example.txt).
Expand Down
1 change: 1 addition & 0 deletions bin/funclatency
View file
Original file line number Diff line number Diff line change
@@ -0,0 +1 @@
../kernel/funclatency
147 changes: 147 additions & 0 deletions examples/funclatency_example.txt
View file
Original file line number Diff line number Diff line change
@@ -0,0 +1,147 @@
Demonstrations of funclatency:

Here is a busy system suffering poor performance:

# ./funclatency -f vfs_write
Tracing vfs_write latencies. Output every 1 seconds. Ctrl-C to end.

>=(ms) .. <(ms) : I/O |Distribution |
0 -> 1 : 1061 |######################################|
1 -> 2 : 215 |######## |
2 -> 4 : 390 |############## |
4 -> 8 : 466 |################# |
8 -> 16 : 395 |############### |
16 -> 32 : 439 |################ |
32 -> 64 : 89 |#### |
64 -> 128 : 2 |# |

>=(ms) .. <(ms) : I/O |Distribution |
0 -> 1 : 1196 |######################################|
1 -> 2 : 308 |########## |
2 -> 4 : 360 |############ |
4 -> 8 : 400 |############# |
8 -> 16 : 326 |########### |
16 -> 32 : 265 |######### |
32 -> 64 : 139 |##### |
64 -> 128 : 4 |# |

>=(ms) .. <(ms) : I/O |Distribution |
0 -> 1 : 874 |######################################|
1 -> 2 : 159 |####### |
2 -> 4 : 293 |############# |
4 -> 8 : 408 |################## |
8 -> 16 : 292 |############# |
16 -> 32 : 426 |################### |
32 -> 64 : 137 |###### |
64 -> 128 : 9 |# |

>=(ms) .. <(ms) : I/O |Distribution |
0 -> 1 : 677 |######################################|
1 -> 2 : 196 |############ |
2 -> 4 : 207 |############ |
4 -> 8 : 175 |########## |
8 -> 16 : 293 |################# |
16 -> 32 : 311 |################## |
32 -> 64 : 180 |########### |
64 -> 128 : 28 |## |
128 -> 256 : 1 |# |
^C
Ending tracing...

This system uses SSDs, but latencies in the filesystem need to be diagnosed.
These latencies would not be obvious when using traditional iostat:

# iostat -x -d 1
Linux 3.10.0-327.3.1.el7.x86_64 (localhost.localhost) 12/31/2015 _x86_64_ (24 CPU)

Device: rrqm/s wrqm/s r/s w/s rkB/s wkB/s avgrq-sz avgqu-sz await r_await w_await svctm %util
sdb 0.00 0.00 1181.86 668.30 19754.37 15110.85 37.69 2.35 1.27 1.70 0.51 0.05 10.15
sdc 0.00 0.00 1067.27 659.67 19628.63 15027.31 40.14 2.47 1.43 1.98 0.53 0.06 10.24
sdd 0.00 0.00 1064.45 659.72 19651.65 15063.19 40.27 2.48 1.44 2.00 0.54 0.06 10.26
sda 0.00 0.04 0.02 1.19 0.92 157.92 262.37 0.01 7.47 0.51 7.62 0.07 0.01

Device: rrqm/s wrqm/s r/s w/s rkB/s wkB/s avgrq-sz avgqu-sz await r_await w_await svctm %util
sdb 0.00 0.00 1134.00 133.00 9620.00 1636.00 17.77 0.18 0.14 0.15 0.04 0.05 6.90
sdc 0.00 0.00 1182.00 132.00 10112.00 1636.00 17.88 0.18 0.14 0.15 0.04 0.05 7.20
sdd 0.00 0.00 1142.00 134.00 9328.00 1636.00 17.18 0.17 0.13 0.14 0.04 0.05 6.60
sda 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00

Device: rrqm/s wrqm/s r/s w/s rkB/s wkB/s avgrq-sz avgqu-sz await r_await w_await svctm %util
sdb 0.00 0.00 1206.00 112.00 10244.00 2104.00 18.74 0.18 0.14 0.15 0.06 0.06 7.30
sdc 0.00 0.00 1170.00 109.00 9612.00 2104.00 18.32 0.16 0.13 0.14 0.06 0.05 6.50
sdd 0.00 0.00 1161.00 109.00 9552.00 2104.00 18.36 0.16 0.13 0.13 0.06 0.05 6.40
sda 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00

iolatency is better, but it does not show the full extent of the problem:

[root@bench03 ~]# perf-tools/iolatency -i '*W*'
Tracing block I/O. Output every 1 seconds. Ctrl-C to end.

>=(ms) .. <(ms) : I/O |Distribution |
0 -> 1 : 10005 |######################################|
1 -> 2 : 3491 |############## |
2 -> 4 : 1283 |##### |

>=(ms) .. <(ms) : I/O |Distribution |
0 -> 1 : 6505 |######################################|
1 -> 2 : 3993 |######################## |
2 -> 4 : 1223 |######## |
4 -> 8 : 25 |# |
8 -> 16 : 32 |# |
16 -> 32 : 6 |# |

>=(ms) .. <(ms) : I/O |Distribution |
0 -> 1 : 17688 |######################################|
1 -> 2 : 563 |## |
2 -> 4 : 157 |# |
4 -> 8 : 35 |# |
8 -> 16 : 16 |# |
16 -> 32 : 7 |# |
32 -> 64 : 6 |# |
^C
Ending tracing...

This can be used on things outside of the vfs too, such as SyS_select on a
workstation:

$ sudo ./bin/funclatency -f SyS_select
Tracing SyS_select latencies. Output every 1 seconds. Ctrl-C to end.

>=(ms) .. <(ms) : Count |Distribution |
0 -> 1 : 314 |######################################|
1 -> 2 : 9 |## |
2 -> 4 : 35 |##### |
4 -> 8 : 43 |###### |
8 -> 16 : 305 |##################################### |
16 -> 32 : 6 |# |
32 -> 64 : 2 |# |
64 -> 128 : 4 |# |
128 -> 256 : 4 |# |

>=(ms) .. <(ms) : Count |Distribution |
0 -> 1 : 60 |######## |
1 -> 2 : 2 |# |
2 -> 4 : 0 | |
4 -> 8 : 17 |### |
8 -> 16 : 298 |######################################|
16 -> 32 : 7 |# |
32 -> 64 : 0 | |
64 -> 128 : 0 | |
128 -> 256 : 10 |## |

>=(ms) .. <(ms) : Count |Distribution |
0 -> 1 : 67 |######### |
1 -> 2 : 2 |# |
2 -> 4 : 0 | |
4 -> 8 : 16 |### |
8 -> 16 : 299 |######################################|
16 -> 32 : 11 |## |
32 -> 64 : 11 |## |
64 -> 128 : 1 |# |
128 -> 256 : 9 |## |
^C
Ending tracing...

In this case, you can see that SyS_select consumers are not particularly busy.
The majority of time outs are in the 8 -> 16 range, which correspond to Xorg's
repaint events.
Loading

0 comments on commit 6e25ea6

Please sign in to comment.