biosnoop reports unrealistic latency
- Dominant language
- C
- Stars
- 22.7k
- Forks
- 4.1k
- Avg merge
- 10d 4h
- Merged PRs (30d)
- 3
Description
Something funny is happening in `biosnoop` and `biolatency` when asked to exclude kernel queuing.
I issue 10 x 512 byte writes each followed by `fsync` directly to `/dev/sdb` that is a spinning disk and here's what I see:
* `biosnoop` (0.20ms):
```
$ sudo /usr/share/bcc/tools/biosnoop | fgrep --line-buffered sdb
0.000000000 paranoid 17553 sdb R 0 4096 0.23
0.000329000 paranoid 17553 sdb W 0 4096 0.20
4.338511000 paranoid 17553 sdb W 0 4096 0.27
5.361153000 paranoid 17553 sdb W 0 4096 0.26
6.383771000 paranoid 17553 sdb W 0 4096 0.26
7.406433000 paranoid 17553 sdb W 0 4096 0.27
8.429084000 paranoid 17553 sdb W 0 4096 0.26
9.451788000 paranoid 17553 sdb W 0 4096 0.26
10.474409000 paranoid 17553 sdb W 0 4096 0.26
```
* `biolatency` without queueing time (0.1..02ms):
```
$ sudo /usr/share/bcc/tools/biolatency -TD
Tracing block device I/O... Hit Ctrl-C to end.
^C
22:27:42
disk = 'sdb'
usecs : count distribution
0 -> 1 : 0 | |
2 -> 3 : 0 | |
4 -> 7 : 0 | |
8 -> 15 : 0 | |
16 -> 31 : 0 | |
32 -> 63 : 0 | |
64 -> 127 : 1 | |
128 -> 255 : 63 |****************************************|
256 -> 511 : 12 |******* |
```
* `biolatency` with queuing time (16-32ms):
```
$ sudo /usr/share/bcc/tools/biolatency -TDQ
Tracing block device I/O... Hit Ctrl-C to end.
^C
22:29:34
disk = 'sdb'
usecs : count distribution
0 -> 1 : 0 | |
2 -> 3 : 0 | |
4 -> 7 : 0 | |
8 -> 15 : 0 | |
16 -> 31 : 0 | |
32 -> 63 : 0 | |
64 -> 127 : 1 | |
128 -> 255 : 64 |****************************************|
256 -> 511 : 9 |***** |
512 -> 1023 : 0 | |
1024 -> 2047 : 0 | |
2048 -> 4095 : 0 | |
4096 -> 8191 : 0 | |
8192 -> 16383 : 0 | |
16384 -> 32767 : 10 |****** |
```
Note that here I see my exact 10 requests, but I don't see that without queuing.
* my program (22ms):
```
ivan@36s8:~$ sudo go run /tmp/paranoid.go -file=/dev/sdb -size=512 -count=10
2017/03/29 22:28:04 Synced in 27453 μs
2017/03/29 22:28:05 Synced in 22506 μs
2017/03/29 22:28:06 Synced in 22503 μs
2017/03/29 22:28:07 Synced in 22401 μs
2017/03/29 22:28:08 Synced in 22482 μs
2017/03/29 22:28:09 Synced in 22615 μs
2017/03/29 22:28:10 Synced in 22485 μs
2017/03/29 22:28:11 Synced in 22513 μs
2017/03/29 22:28:12 Synced in 22597 μs
2017/03/29 22:28:13 Synced in 22533 μs
```
If I write to a filesystem, latency numbers from `biosnoop` look more realistic:
```
235.470488000 paranoid 19260 sdc W 3921085456 4096 21.05
236.471146000 paranoid 19260 sdc W 18344 4096 0.36
236.513255000 paranoid 19260 sdc W 3921085464 4096 21.11
237.513787000 paranoid 19260 sdc W 18344 4096 0.26
237.555953000 paranoid 19260 sdc W 3921085472 4096 21.11
```
But then again, my app now sees 42ms latency because it has to write two sectors on disk.
This is happening on 4.4.44.
I also see similar weirdness on SSDs when reported latency is 0.09ms + 0.04ms (that's on a filesystem), but app perceives that as 1.2ms (0.09+0.04 is 0.13ms, 10x difference).
Contributor guide
No contributing guide indexed for this repository
Research direction
Start with the biosnoop and biolatency entry points and reproduce the reported writes to /dev/sdb on kernel 4.4.44, comparing biolatency with and without -Q. Compare those results with the Go program's fsync timings and the filesystem example. Done means explaining or correcting the discrepancy in reported versus observed latency.
Written by the indexing model from the issue text.
Assessment
- Tech stack
- go, linux
- Domain
- observability-sre, operating-systems, performance
- Issue type
- Bug
- Difficulty
- 4/5
- Estimated time
- 3-5 days
- Activity status
- Stale
- Clarity
- Mostly clear
- Newbie friendliness
- 35/100