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