1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73
74
75
76
77
78
79
80
81
82
83
|
#!/usr/bin/env bpftrace
/*
* writeback Trace file system writeback events with details.
* For Linux, uses bpftrace and eBPF.
*
* This traces when file system dirtied pages are flushed to disk by kernel
* writeback, and prints details including when the event occurred, and the
* duration of the event. This can be useful for correlating these times with
* other performance problems, and if there is a match, it would be a clue
* that the problem may be caused by writeback. How quickly the kernel does
* writeback can be tuned: see the kernel docs, eg,
* vm.dirty_writeback_centisecs.
*
* Example of usage:
*
* # ./writeback.bt
* Attaching 4 probes...
* Tracing writeback... Hit Ctrl-C to end.
* TIME DEVICE PAGES REASON ms
* 23:28:47 259:1 15791 periodic 0.005
* 23:28:48 259:0 15792 periodic 0.004
* 23:28:52 259:1 15784 periodic 0.003
* 23:28:53 259:0 18682 periodic 0.003
* 23:28:55 259:0 41970 background 326.663
* 23:28:56 259:0 18418 background 332.689
* 23:28:56 259:0 60402 background 362.446
* [...]
*
* By looking a the timestamps and latency, it can be seen that the system was
* not spending much time in writeback until 23:28:55, when "background"
* writeback began, taking over 300 milliseconds per flush.
*
* If timestamps of heavy writeback coincide with times when applications suffered
* performance issues, that would be a clue that they are correlated and there
* is contention for the disk devices. There are various ways to tune this:
* eg, vm.dirty_writeback_centisecs.
*
* Copyright 2018 Netflix, Inc.
*
* 14-Sep-2018 Brendan Gregg Created this.
*/
BEGIN
{
printf("Tracing writeback... Hit Ctrl-C to end.\n");
printf("%-9s %-8s %-8s %-16s %s\n", "TIME", "DEVICE", "PAGES",
"REASON", "ms");
// see /sys/kernel/debug/tracing/events/writeback/writeback_start/format
@reason[0] = "background";
@reason[1] = "vmscan";
@reason[2] = "sync";
@reason[3] = "periodic";
@reason[4] = "laptop_timer";
@reason[5] = "free_more_memory";
@reason[6] = "fs_free_space";
@reason[7] = "forker_thread";
}
tracepoint:writeback:writeback_start
{
@start[args.sb_dev] = nsecs;
}
tracepoint:writeback:writeback_written
{
$sb_dev = args.sb_dev;
$s = @start[$sb_dev];
delete(@start, $sb_dev);
$lat = $s ? (nsecs - $s) / 1000 : 0;
time("%H:%M:%S ");
printf("%-8s %-8d %-16s %d.%03d\n", args.name,
args.nr_pages & 0xffff, // TODO: explain these bitmasks
@reason[args.reason & 0xffffffff],
$lat / 1000, $lat % 1000);
}
END
{
clear(@reason);
clear(@start);
}
|
