1 /* SPDX-License-Identifier: (LGPL-2.1 OR BSD-2-Clause) */
2
3 /*
4 * fsslower Trace file system operations slower than a threshold.
5 *
6 * Copyright (c) 2020 Wenbo Zhang
7 * Copyright (c) 2021 Hengqi Chen
8 *
9 * Based on xfsslower(8) from BCC by Brendan Gregg & Dina Goldshtein.
10 * 9-Mar-2020 Wenbo Zhang Created this.
11 * 27-May-2021 Hengqi Chen Migrated to fsslower.
12 */
13 #include <argp.h>
14 #include <libgen.h>
15 #include <signal.h>
16 #include <stdio.h>
17 #include <stdlib.h>
18 #include <string.h>
19 #include <time.h>
20 #include <unistd.h>
21
22 #include <bpf/libbpf.h>
23 #include <bpf/bpf.h>
24
25 #include "fsslower.h"
26 #include "fsslower.skel.h"
27 #include "trace_helpers.h"
28
29 #define PERF_BUFFER_PAGES 64
30 #define PERF_POLL_TIMEOUT_MS 100
31
32 #define warn(...) fprintf(stderr, __VA_ARGS__)
33
34 enum fs_type {
35 NONE,
36 BTRFS,
37 EXT4,
38 NFS,
39 XFS,
40 };
41
42 static struct fs_config {
43 const char *fs;
44 const char *op_funcs[MAX_OP];
45 } fs_configs[] = {
46 [BTRFS] = { "btrfs", {
47 [READ] = "btrfs_file_read_iter",
48 [WRITE] = "btrfs_file_write_iter",
49 [OPEN] = "btrfs_file_open",
50 [FSYNC] = "btrfs_sync_file",
51 }},
52 [EXT4] = { "ext4", {
53 [READ] = "ext4_file_read_iter",
54 [WRITE] = "ext4_file_write_iter",
55 [OPEN] = "ext4_file_open",
56 [FSYNC] = "ext4_sync_file",
57 }},
58 [NFS] = { "nfs", {
59 [READ] = "nfs_file_read",
60 [WRITE] = "nfs_file_write",
61 [OPEN] = "nfs_file_open",
62 [FSYNC] = "nfs_file_fsync",
63 }},
64 [XFS] = { "xfs", {
65 [READ] = "xfs_file_read_iter",
66 [WRITE] = "xfs_file_write_iter",
67 [OPEN] = "xfs_file_open",
68 [FSYNC] = "xfs_file_fsync",
69 }},
70 };
71
72 static char file_op[] = {
73 [READ] = 'R',
74 [WRITE] = 'W',
75 [OPEN] = 'O',
76 [FSYNC] = 'F',
77 };
78
79 static volatile sig_atomic_t exiting = 0;
80
81 /* options */
82 static enum fs_type fs_type = NONE;
83 static pid_t target_pid = 0;
84 static time_t duration = 0;
85 static __u64 min_lat_ms = 10;
86 static bool csv = false;
87 static bool verbose = false;
88
89 const char *argp_program_version = "fsslower 0.1";
90 const char *argp_program_bug_address =
91 "https://github.com/iovisor/bcc/tree/master/libbpf-tools";
92 const char argp_program_doc[] =
93 "Trace file system operations slower than a threshold.\n"
94 "\n"
95 "Usage: fsslower [-h] [-t FS] [-p PID] [-m MIN] [-d DURATION] [-c]\n"
96 "\n"
97 "EXAMPLES:\n"
98 " fsslower -t ext4 # trace ext4 operations slower than 10 ms\n"
99 " fsslower -t nfs -p 1216 # trace nfs operations with PID 1216 only\n"
100 " fsslower -t xfs -c -d 1 # trace xfs operations for 1s with csv output\n";
101
102 static const struct argp_option opts[] = {
103 { "csv", 'c', NULL, 0, "Output as csv" },
104 { "duration", 'd', "DURATION", 0, "Total duration of trace in seconds" },
105 { "pid", 'p', "PID", 0, "Process ID to trace" },
106 { "min", 'm', "MIN", 0, "Min latency to trace, in ms (default 10)" },
107 { "type", 't', "Filesystem", 0, "Which filesystem to trace, [btrfs/ext4/nfs/xfs]" },
108 { "verbose", 'v', NULL, 0, "Verbose debug output" },
109 { NULL, 'h', NULL, OPTION_HIDDEN, "Show the full help" },
110 {},
111 };
112
parse_arg(int key,char * arg,struct argp_state * state)113 static error_t parse_arg(int key, char *arg, struct argp_state *state)
114 {
115 switch (key) {
116 case 'v':
117 verbose = true;
118 break;
119 case 'c':
120 csv = true;
121 break;
122 case 'd':
123 errno = 0;
124 duration = strtol(arg, NULL, 10);
125 if (errno || duration <= 0) {
126 warn("invalid DURATION: %s\n", arg);
127 argp_usage(state);
128 }
129 break;
130 case 'm':
131 errno = 0;
132 min_lat_ms = strtoll(arg, NULL, 10);
133 if (errno || min_lat_ms < 0) {
134 warn("invalid latency (in ms): %s\n", arg);
135 }
136 break;
137 case 't':
138 if (!strcmp(arg, "btrfs")) {
139 fs_type = BTRFS;
140 } else if (!strcmp(arg, "ext4")) {
141 fs_type = EXT4;
142 } else if (!strcmp(arg, "nfs")) {
143 fs_type = NFS;
144 } else if (!strcmp(arg, "xfs")) {
145 fs_type = XFS;
146 } else {
147 warn("invalid filesystem\n");
148 argp_usage(state);
149 }
150 break;
151 case 'p':
152 errno = 0;
153 target_pid = strtol(arg, NULL, 10);
154 if (errno || target_pid <= 0) {
155 warn("invalid PID: %s\n", arg);
156 argp_usage(state);
157 }
158 break;
159 case 'h':
160 argp_state_help(state, stderr, ARGP_HELP_STD_HELP);
161 break;
162 default:
163 return ARGP_ERR_UNKNOWN;
164 }
165 return 0;
166 }
167
alias_parse(char * prog)168 static void alias_parse(char *prog)
169 {
170 char *name = basename(prog);
171
172 if (!strcmp(name, "btrfsslower")) {
173 fs_type = BTRFS;
174 } else if (!strcmp(name, "ext4slower")) {
175 fs_type = EXT4;
176 } else if (!strcmp(name, "nfsslower")) {
177 fs_type = NFS;
178 } else if (!strcmp(name, "xfsslower")) {
179 fs_type = XFS;
180 }
181 }
182
libbpf_print_fn(enum libbpf_print_level level,const char * format,va_list args)183 static int libbpf_print_fn(enum libbpf_print_level level, const char *format, va_list args)
184 {
185 if (level == LIBBPF_DEBUG && !verbose)
186 return 0;
187 return vfprintf(stderr, format, args);
188 }
189
sig_int(int signo)190 static void sig_int(int signo)
191 {
192 exiting = 1;
193 }
194
check_fentry()195 static bool check_fentry()
196 {
197 int i;
198 const char *fn_name, *module;
199 bool support_fentry = true;
200
201 for (i = 0; i < MAX_OP; i++) {
202 fn_name = fs_configs[fs_type].op_funcs[i];
203 module = fs_configs[fs_type].fs;
204 if (fn_name && !fentry_can_attach(fn_name, module)) {
205 support_fentry = false;
206 break;
207 }
208 }
209 return support_fentry;
210 }
211
fentry_set_attach_target(struct fsslower_bpf * obj)212 static int fentry_set_attach_target(struct fsslower_bpf *obj)
213 {
214 struct fs_config *cfg = &fs_configs[fs_type];
215 int err = 0;
216
217 err = err ?: bpf_program__set_attach_target(obj->progs.file_read_fentry, 0, cfg->op_funcs[READ]);
218 err = err ?: bpf_program__set_attach_target(obj->progs.file_read_fexit, 0, cfg->op_funcs[READ]);
219 err = err ?: bpf_program__set_attach_target(obj->progs.file_write_fentry, 0, cfg->op_funcs[WRITE]);
220 err = err ?: bpf_program__set_attach_target(obj->progs.file_write_fexit, 0, cfg->op_funcs[WRITE]);
221 err = err ?: bpf_program__set_attach_target(obj->progs.file_open_fentry, 0, cfg->op_funcs[OPEN]);
222 err = err ?: bpf_program__set_attach_target(obj->progs.file_open_fexit, 0, cfg->op_funcs[OPEN]);
223 err = err ?: bpf_program__set_attach_target(obj->progs.file_sync_fentry, 0, cfg->op_funcs[FSYNC]);
224 err = err ?: bpf_program__set_attach_target(obj->progs.file_sync_fexit, 0, cfg->op_funcs[FSYNC]);
225 return err;
226 }
227
disable_fentry(struct fsslower_bpf * obj)228 static void disable_fentry(struct fsslower_bpf *obj)
229 {
230 bpf_program__set_autoload(obj->progs.file_read_fentry, false);
231 bpf_program__set_autoload(obj->progs.file_read_fexit, false);
232 bpf_program__set_autoload(obj->progs.file_write_fentry, false);
233 bpf_program__set_autoload(obj->progs.file_write_fexit, false);
234 bpf_program__set_autoload(obj->progs.file_open_fentry, false);
235 bpf_program__set_autoload(obj->progs.file_open_fexit, false);
236 bpf_program__set_autoload(obj->progs.file_sync_fentry, false);
237 bpf_program__set_autoload(obj->progs.file_sync_fexit, false);
238 }
239
disable_kprobes(struct fsslower_bpf * obj)240 static void disable_kprobes(struct fsslower_bpf *obj)
241 {
242 bpf_program__set_autoload(obj->progs.file_read_entry, false);
243 bpf_program__set_autoload(obj->progs.file_read_exit, false);
244 bpf_program__set_autoload(obj->progs.file_write_entry, false);
245 bpf_program__set_autoload(obj->progs.file_write_exit, false);
246 bpf_program__set_autoload(obj->progs.file_open_entry, false);
247 bpf_program__set_autoload(obj->progs.file_open_exit, false);
248 bpf_program__set_autoload(obj->progs.file_sync_entry, false);
249 bpf_program__set_autoload(obj->progs.file_sync_exit, false);
250 }
251
attach_kprobes(struct fsslower_bpf * obj)252 static int attach_kprobes(struct fsslower_bpf *obj)
253 {
254 long err = 0;
255 struct fs_config *cfg = &fs_configs[fs_type];
256
257 /* READ */
258 obj->links.file_read_entry = bpf_program__attach_kprobe(obj->progs.file_read_entry, false, cfg->op_funcs[READ]);
259 if (!obj->links.file_read_entry)
260 goto errout;
261 obj->links.file_read_exit = bpf_program__attach_kprobe(obj->progs.file_read_exit, true, cfg->op_funcs[READ]);
262 if (!obj->links.file_read_exit)
263 goto errout;
264 /* WRITE */
265 obj->links.file_write_entry = bpf_program__attach_kprobe(obj->progs.file_write_entry, false, cfg->op_funcs[WRITE]);
266 if (!obj->links.file_write_entry)
267 goto errout;
268 obj->links.file_write_exit = bpf_program__attach_kprobe(obj->progs.file_write_exit, true, cfg->op_funcs[WRITE]);
269 if (!obj->links.file_write_exit)
270 goto errout;
271 /* OPEN */
272 obj->links.file_open_entry = bpf_program__attach_kprobe(obj->progs.file_open_entry, false, cfg->op_funcs[OPEN]);
273 if (!obj->links.file_open_entry)
274 goto errout;
275 obj->links.file_open_exit = bpf_program__attach_kprobe(obj->progs.file_open_exit, true, cfg->op_funcs[OPEN]);
276 if (!obj->links.file_open_exit)
277 goto errout;
278 /* FSYNC */
279 obj->links.file_sync_entry = bpf_program__attach_kprobe(obj->progs.file_sync_entry, false, cfg->op_funcs[FSYNC]);
280 if (!obj->links.file_sync_entry)
281 goto errout;
282 obj->links.file_sync_exit = bpf_program__attach_kprobe(obj->progs.file_sync_exit, true, cfg->op_funcs[FSYNC]);
283 if (!obj->links.file_sync_exit)
284 goto errout;
285 return 0;
286
287 errout:
288 err = -errno;
289 warn("failed to attach kprobe: %ld\n", err);
290 return err;
291 }
292
print_headers()293 static void print_headers()
294 {
295 const char *fs = fs_configs[fs_type].fs;
296
297 if (csv) {
298 printf("ENDTIME_ns,TASK,PID,TYPE,BYTES,OFFSET_b,LATENCY_us,FILE\n");
299 return;
300 }
301
302 if (min_lat_ms)
303 printf("Tracing %s operations slower than %llu ms", fs, min_lat_ms);
304 else
305 printf("Tracing %s operations", fs);
306
307 if (duration)
308 printf(" for %ld secs.\n", duration);
309 else
310 printf("... Hit Ctrl-C to end.\n");
311
312 printf("%-8s %-16s %-7s %1s %-7s %-8s %7s %s\n",
313 "TIME", "COMM", "PID", "T", "BYTES", "OFF_KB", "LAT(ms)", "FILENAME");
314 }
315
handle_event(void * ctx,int cpu,void * data,__u32 data_sz)316 static void handle_event(void *ctx, int cpu, void *data, __u32 data_sz)
317 {
318 const struct event *e = data;
319 struct tm *tm;
320 char ts[32];
321 time_t t;
322
323 if (csv) {
324 printf("%lld,%s,%d,%c,", e->end_ns, e->task, e->pid, file_op[e->op]);
325 if (e->size == LLONG_MAX)
326 printf("LL_MAX,");
327 else
328 printf("%ld,", e->size);
329 printf("%lld,%lld,%s\n", e->offset, e->delta_us, e->file);
330 return;
331 }
332
333 time(&t);
334 tm = localtime(&t);
335 strftime(ts, sizeof(ts), "%H:%M:%S", tm);
336
337 printf("%-8s %-16s %-7d %c ", ts, e->task, e->pid, file_op[e->op]);
338 if (e->size == LLONG_MAX)
339 printf("%-7s ", "LL_MAX");
340 else
341 printf("%-7ld ", e->size);
342 printf("%-8lld %7.2f %s\n", e->offset / 1024, (double)e->delta_us / 1000, e->file);
343 }
344
handle_lost_events(void * ctx,int cpu,__u64 lost_cnt)345 static void handle_lost_events(void *ctx, int cpu, __u64 lost_cnt)
346 {
347 warn("lost %llu events on CPU #%d\n", lost_cnt, cpu);
348 }
349
main(int argc,char ** argv)350 int main(int argc, char **argv)
351 {
352 static const struct argp argp = {
353 .options = opts,
354 .parser = parse_arg,
355 .doc = argp_program_doc,
356 };
357 struct perf_buffer *pb = NULL;
358 struct fsslower_bpf *skel;
359 __u64 time_end = 0;
360 int err;
361 bool support_fentry;
362
363 alias_parse(argv[0]);
364 err = argp_parse(&argp, argc, argv, 0, NULL, NULL);
365 if (err)
366 return err;
367 if (fs_type == NONE) {
368 warn("filesystem must be specified using -t option.\n");
369 return 1;
370 }
371
372 libbpf_set_strict_mode(LIBBPF_STRICT_ALL);
373 libbpf_set_print(libbpf_print_fn);
374
375 skel = fsslower_bpf__open();
376 if (!skel) {
377 warn("failed to open BPF object\n");
378 return 1;
379 }
380
381 skel->rodata->target_pid = target_pid;
382 skel->rodata->min_lat_ns = min_lat_ms * 1000 * 1000;
383
384 /*
385 * before load
386 * if fentry is supported, we set attach target and disable kprobes
387 * otherwise, we disable fentry and attach kprobes after loading
388 */
389 support_fentry = check_fentry();
390 if (support_fentry) {
391 err = fentry_set_attach_target(skel);
392 if (err) {
393 warn("failed to set attach target: %d\n", err);
394 goto cleanup;
395 }
396 disable_kprobes(skel);
397 } else {
398 disable_fentry(skel);
399 }
400
401 err = fsslower_bpf__load(skel);
402 if (err) {
403 warn("failed to load BPF object: %d\n", err);
404 goto cleanup;
405 }
406
407 /*
408 * after load
409 * if fentry is supported, let libbpf do auto load
410 * otherwise, we attach to kprobes manually
411 */
412 err = support_fentry ? fsslower_bpf__attach(skel) : attach_kprobes(skel);
413 if (err) {
414 warn("failed to attach BPF programs: %d\n", err);
415 goto cleanup;
416 }
417
418 pb = perf_buffer__new(bpf_map__fd(skel->maps.events), PERF_BUFFER_PAGES,
419 handle_event, handle_lost_events, NULL, NULL);
420 if (!pb) {
421 err = -errno;
422 warn("failed to open perf buffer: %d\n", err);
423 goto cleanup;
424 }
425
426 print_headers();
427
428 if (duration)
429 time_end = get_ktime_ns() + duration * NSEC_PER_SEC;
430
431 if (signal(SIGINT, sig_int) == SIG_ERR) {
432 warn("can't set signal handler: %s\n", strerror(errno));
433 err = 1;
434 goto cleanup;
435 }
436
437 /* main: poll */
438 while (!exiting) {
439 err = perf_buffer__poll(pb, PERF_POLL_TIMEOUT_MS);
440 if (err < 0 && err != -EINTR) {
441 fprintf(stderr, "error polling perf buffer: %s\n", strerror(-err));
442 goto cleanup;
443 }
444 if (duration && get_ktime_ns() > time_end)
445 goto cleanup;
446 /* reset err to return 0 if exiting */
447 err = 0;
448 }
449
450 cleanup:
451 perf_buffer__free(pb);
452 fsslower_bpf__destroy(skel);
453
454 return err != 0;
455 }
456