Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

added funclatency, a tool for summarizing kernel function latencies #43

Closed
wants to merge 1 commit into from
Closed

added funclatency, a tool for summarizing kernel function latencies #43

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
1 commit
Select commit
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
1 change: 1 addition & 0 deletions README.md
View file
Open in desktop
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
Open in desktop
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
Open in desktop
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:

# ./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:

$ ./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