From 067f4f291c2063d86abe0a526ef211e03a4f1258 Mon Sep 17 00:00:00 2001 From: Andrii Nakryiko Date: Fri, 23 Sep 2022 10:59:09 -0700 Subject: [PATCH 1/5] selftests/bpf: add sign-file to .gitignore Add sign-file to .gitignore to avoid accidentally checking it in. Signed-off-by: Andrii Nakryiko Link: https://lore.kernel.org/r/20220923175913.3272430-2-andrii@kernel.org Signed-off-by: Alexei Starovoitov --- tools/testing/selftests/bpf/.gitignore | 1 + 1 file changed, 1 insertion(+) diff --git a/tools/testing/selftests/bpf/.gitignore b/tools/testing/selftests/bpf/.gitignore index 3b288562963e..07d2d0a8c5cb 100644 --- a/tools/testing/selftests/bpf/.gitignore +++ b/tools/testing/selftests/bpf/.gitignore @@ -40,6 +40,7 @@ test_cpp /runqslower /bench /veristat +/sign-file *.ko *.tmp xskxceiver From c2488d70ceee352611e55943c25abf30117e3b67 Mon Sep 17 00:00:00 2001 From: Andrii Nakryiko Date: Fri, 23 Sep 2022 10:59:10 -0700 Subject: [PATCH 2/5] selftests/bpf: make veristat's verifier log parsing faster and more robust Make sure veristat doesn't spend ridiculous amount of time parsing verifier stats from verifier log, especially for very large logs or truncated logs (e.g., when verifier returns -ENOSPC due to too small buffer). For this, parse lines from the end of the log and make sure we parse only up to 100 last lines, where stats should be, if at all. Suggested-by: Alexei Starovoitov Signed-off-by: Andrii Nakryiko Link: https://lore.kernel.org/r/20220923175913.3272430-3-andrii@kernel.org Signed-off-by: Alexei Starovoitov --- tools/testing/selftests/bpf/veristat.c | 29 ++++++++++++++++++-------- 1 file changed, 20 insertions(+), 9 deletions(-) diff --git a/tools/testing/selftests/bpf/veristat.c b/tools/testing/selftests/bpf/veristat.c index 51030234b60a..77bdfd6fe302 100644 --- a/tools/testing/selftests/bpf/veristat.c +++ b/tools/testing/selftests/bpf/veristat.c @@ -419,19 +419,30 @@ static void free_verif_stats(struct verif_stats *stats, size_t stat_cnt) static char verif_log_buf[64 * 1024]; -static int parse_verif_log(const char *buf, size_t buf_sz, struct verif_stats *s) +#define MAX_PARSED_LOG_LINES 100 + +static int parse_verif_log(char * const buf, size_t buf_sz, struct verif_stats *s) { - const char *next; - int pos; + const char *cur; + int pos, lines; - for (pos = 0; buf[0]; buf = next) { - if (buf[0] == '\n') - buf++; - next = strchrnul(&buf[pos], '\n'); + buf[buf_sz - 1] = '\0'; - if (1 == sscanf(buf, "verification time %ld usec\n", &s->stats[DURATION])) + for (pos = strlen(buf) - 1, lines = 0; pos >= 0 && lines < MAX_PARSED_LOG_LINES; lines++) { + /* find previous endline or otherwise take the start of log buf */ + for (cur = &buf[pos]; cur > buf && cur[0] != '\n'; cur--, pos--) { + } + /* next time start from end of previous line (or pos goes to <0) */ + pos--; + /* if we found endline, point right after endline symbol; + * otherwise, stay at the beginning of log buf + */ + if (cur[0] == '\n') + cur++; + + if (1 == sscanf(cur, "verification time %ld usec\n", &s->stats[DURATION])) continue; - if (6 == sscanf(buf, "processed %ld insns (limit %*d) max_states_per_insn %ld total_states %ld peak_states %ld mark_read %ld", + if (6 == sscanf(cur, "processed %ld insns (limit %*d) max_states_per_insn %ld total_states %ld peak_states %ld mark_read %ld", &s->stats[TOTAL_INSNS], &s->stats[MAX_STATES_PER_INSN], &s->stats[TOTAL_STATES], From 518fee8bfaf2c628007909c0fc5336930b9b6ee4 Mon Sep 17 00:00:00 2001 From: Andrii Nakryiko Date: Fri, 23 Sep 2022 10:59:11 -0700 Subject: [PATCH 3/5] selftests/bpf: make veristat skip non-BPF and failing-to-open BPF objects Make veristat ignore non-BPF object files. This allows simpler mass-verification (e.g., `sudo ./veristat *.bpf.o` in selftests/bpf directory). Note that `sudo ./veristat *.o` would also work, but with selftests's multiple copies of BPF object files (.bpf.o and .bpf.linked{1,2,3}.o) it's 4x slower. Also, given some of BPF object files could be incomplete in the sense that they are meant to be statically linked into final BPF object file (like linked_maps, linked_funcs, linked_vars), note such instances in stderr, but proceed anyways. This seems like a better trade off between completely silently ignoring BPF object file and aborting mass-verification altogether. Signed-off-by: Andrii Nakryiko Link: https://lore.kernel.org/r/20220923175913.3272430-4-andrii@kernel.org Signed-off-by: Alexei Starovoitov --- tools/testing/selftests/bpf/veristat.c | 78 +++++++++++++++++++++++--- 1 file changed, 70 insertions(+), 8 deletions(-) diff --git a/tools/testing/selftests/bpf/veristat.c b/tools/testing/selftests/bpf/veristat.c index 77bdfd6fe302..f09dd143a8df 100644 --- a/tools/testing/selftests/bpf/veristat.c +++ b/tools/testing/selftests/bpf/veristat.c @@ -15,6 +15,8 @@ #include #include #include +#include +#include enum stat_id { VERDICT, @@ -78,6 +80,11 @@ static struct env { struct filter *deny_filters; int allow_filter_cnt; int deny_filter_cnt; + + int files_processed; + int files_skipped; + int progs_processed; + int progs_skipped; } env; static int libbpf_print_fn(enum libbpf_print_level level, const char *format, va_list args) @@ -226,8 +233,41 @@ static bool should_process_file(const char *filename) return false; } -static bool should_process_prog(const char *filename, const char *prog_name) +static bool is_bpf_obj_file(const char *path) { + Elf64_Ehdr *ehdr; + int fd, err = -EINVAL; + Elf *elf = NULL; + + fd = open(path, O_RDONLY | O_CLOEXEC); + if (fd < 0) + return true; /* we'll fail later and propagate error */ + + /* ensure libelf is initialized */ + (void)elf_version(EV_CURRENT); + + elf = elf_begin(fd, ELF_C_READ, NULL); + if (!elf) + goto cleanup; + + if (elf_kind(elf) != ELF_K_ELF || gelf_getclass(elf) != ELFCLASS64) + goto cleanup; + + ehdr = elf64_getehdr(elf); + /* Old LLVM set e_machine to EM_NONE */ + if (!ehdr || ehdr->e_type != ET_REL || (ehdr->e_machine && ehdr->e_machine != EM_BPF)) + goto cleanup; + + err = 0; +cleanup: + if (elf) + elf_end(elf); + close(fd); + return err == 0; +} + +static bool should_process_prog(const char *path, const char *prog_name) { + const char *filename = basename(path); int i; if (env.deny_filter_cnt > 0) { @@ -303,7 +343,7 @@ static int append_filter_file(const char *path) f = fopen(path, "r"); if (!f) { err = -errno; - fprintf(stderr, "Failed to open '%s': %d\n", path, err); + fprintf(stderr, "Failed to open filters in '%s': %d\n", path, err); return err; } @@ -463,8 +503,10 @@ static int process_prog(const char *filename, struct bpf_object *obj, struct bpf int err = 0; void *tmp; - if (!should_process_prog(basename(filename), bpf_program__name(prog))) + if (!should_process_prog(filename, bpf_program__name(prog))) { + env.progs_skipped++; return 0; + } tmp = realloc(env.prog_stats, (env.prog_stat_cnt + 1) * sizeof(*env.prog_stats)); if (!tmp) @@ -487,6 +529,7 @@ static int process_prog(const char *filename, struct bpf_object *obj, struct bpf verif_log_buf[0] = '\0'; err = bpf_object__load(obj); + env.progs_processed++; stats->file_name = strdup(basename(filename)); stats->prog_name = strdup(bpf_program__name(prog)); @@ -513,18 +556,37 @@ static int process_obj(const char *filename) LIBBPF_OPTS(bpf_object_open_opts, opts); int err = 0, prog_cnt = 0; - if (!should_process_file(basename(filename))) + if (!should_process_file(basename(filename))) { + if (env.verbose) + printf("Skipping '%s' due to filters...\n", filename); + env.files_skipped++; return 0; + } + if (!is_bpf_obj_file(filename)) { + if (env.verbose) + printf("Skipping '%s' as it's not a BPF object file...\n", filename); + env.files_skipped++; + return 0; + } old_libbpf_print_fn = libbpf_set_print(libbpf_print_fn); obj = bpf_object__open_file(filename, &opts); if (!obj) { - err = -errno; - fprintf(stderr, "Failed to open '%s': %d\n", filename, err); + /* if libbpf can't open BPF object file, it could be because + * that BPF object file is incomplete and has to be statically + * linked into a final BPF object file; instead of bailing + * out, report it into stderr, mark it as skipped, and + * proceeed + */ + fprintf(stderr, "Failed to open '%s': %d\n", filename, -errno); + env.files_skipped++; + err = 0; goto cleanup; } + env.files_processed++; + bpf_object__for_each_program(prog, obj) { prog_cnt++; } @@ -732,8 +794,8 @@ static void output_stats(const struct verif_stats *s, enum resfmt fmt, bool last if (last && fmt == RESFMT_TABLE) { output_header_underlines(); - printf("Done. Processed %d object files, %d programs.\n", - env.filename_cnt, env.prog_stat_cnt); + printf("Done. Processed %d files, %d programs. Skipped %d files, %d programs.\n", + env.files_processed, env.files_skipped, env.progs_processed, env.progs_skipped); } } From c511d009ceb8cd980e4a823b7ca74abbdc7cdccc Mon Sep 17 00:00:00 2001 From: Andrii Nakryiko Date: Fri, 23 Sep 2022 10:59:12 -0700 Subject: [PATCH 4/5] selftests/bpf: emit processing progress and add quiet mode to veristat Emit "Processing ..." for each BPF object file to be processed, to show progress. But also add -q (--quiet) flag to silence such messages. Doing something more clever (like overwriting same output line) is to cumbersome and easily breakable if there is any other console output (e.g., errors from libbpf). Signed-off-by: Andrii Nakryiko Link: https://lore.kernel.org/r/20220923175913.3272430-5-andrii@kernel.org Signed-off-by: Alexei Starovoitov --- tools/testing/selftests/bpf/veristat.c | 15 ++++++++++++++- 1 file changed, 14 insertions(+), 1 deletion(-) diff --git a/tools/testing/selftests/bpf/veristat.c b/tools/testing/selftests/bpf/veristat.c index f09dd143a8df..85a77f1dd863 100644 --- a/tools/testing/selftests/bpf/veristat.c +++ b/tools/testing/selftests/bpf/veristat.c @@ -63,6 +63,7 @@ static struct env { char **filenames; int filename_cnt; bool verbose; + bool quiet; enum resfmt out_fmt; bool comparison_mode; @@ -107,6 +108,7 @@ const char argp_program_doc[] = static const struct argp_option opts[] = { { NULL, 'h', NULL, OPTION_HIDDEN, "Show the full help" }, { "verbose", 'v', NULL, 0, "Verbose mode" }, + { "quiet", 'q', NULL, 0, "Quiet mode" }, { "emit", 'e', "SPEC", 0, "Specify stats to be emitted" }, { "sort", 's', "SPEC", 0, "Specify sort order" }, { "output-format", 'o', "FMT", 0, "Result output format (table, csv), default is table." }, @@ -131,6 +133,9 @@ static error_t parse_arg(int key, char *arg, struct argp_state *state) case 'v': env.verbose = true; break; + case 'q': + env.quiet = true; + break; case 'e': err = parse_stats(arg, &env.output_spec); if (err) @@ -569,8 +574,10 @@ static int process_obj(const char *filename) return 0; } - old_libbpf_print_fn = libbpf_set_print(libbpf_print_fn); + if (!env.quiet && env.out_fmt == RESFMT_TABLE) + printf("Processing '%s'...\n", basename(filename)); + old_libbpf_print_fn = libbpf_set_print(libbpf_print_fn); obj = bpf_object__open_file(filename, &opts); if (!obj) { /* if libbpf can't open BPF object file, it could be because @@ -1268,6 +1275,12 @@ int main(int argc, char **argv) if (argp_parse(&argp, argc, argv, 0, NULL, NULL)) return 1; + if (env.verbose && env.quiet) { + fprintf(stderr, "Verbose and quiet modes are incompatible, please specify just one or neither!\n"); + argp_help(&argp, stderr, ARGP_HELP_USAGE, "veristat"); + return 1; + } + if (env.output_spec.spec_cnt == 0) env.output_spec = default_output_spec; if (env.sort_spec.spec_cnt == 0) From e310efc5ddde04c41aa0501b5a7235b134c5fc6c Mon Sep 17 00:00:00 2001 From: Andrii Nakryiko Date: Fri, 23 Sep 2022 10:59:13 -0700 Subject: [PATCH 5/5] selftests/bpf: allow to adjust BPF verifier log level in veristat Add -l (--log-level) flag to override default BPF verifier log lever. This only matters in verbose mode, which is the mode in which veristat emits verifier log for each processed BPF program. This is important because for successfully verified BPF programs log_level 1 is empty, as BPF verifier truncates all the successfully verified paths. So -l2 is the only way to actually get BPF verifier log in practice. It looks sometihng like this: [vmuser@archvm bpf]$ sudo ./veristat xdp_tx.bpf.o -vl2 Processing 'xdp_tx.bpf.o'... PROCESSING xdp_tx.bpf.o/xdp_tx, DURATION US: 19, VERDICT: success, VERIFIER LOG: func#0 @0 0: R1=ctx(off=0,imm=0) R10=fp0 ; return XDP_TX; 0: (b4) w0 = 3 ; R0_w=3 1: (95) exit verification time 19 usec stack depth 0 processed 2 insns (limit 1000000) max_states_per_insn 0 total_states 0 peak_states 0 mark_read 0 File Program Verdict Duration (us) Total insns Total states Peak states ------------ ------- ------- ------------- ----------- ------------ ----------- xdp_tx.bpf.o xdp_tx success 19 2 0 0 ------------ ------- ------- ------------- ----------- ------------ ----------- Done. Processed 1 files, 0 programs. Skipped 1 files, 0 programs. Signed-off-by: Andrii Nakryiko Link: https://lore.kernel.org/r/20220923175913.3272430-6-andrii@kernel.org Signed-off-by: Alexei Starovoitov --- tools/testing/selftests/bpf/veristat.c | 14 +++++++++++++- 1 file changed, 13 insertions(+), 1 deletion(-) diff --git a/tools/testing/selftests/bpf/veristat.c b/tools/testing/selftests/bpf/veristat.c index 85a77f1dd863..b0d83a28e348 100644 --- a/tools/testing/selftests/bpf/veristat.c +++ b/tools/testing/selftests/bpf/veristat.c @@ -64,6 +64,7 @@ static struct env { int filename_cnt; bool verbose; bool quiet; + int log_level; enum resfmt out_fmt; bool comparison_mode; @@ -108,6 +109,7 @@ const char argp_program_doc[] = static const struct argp_option opts[] = { { NULL, 'h', NULL, OPTION_HIDDEN, "Show the full help" }, { "verbose", 'v', NULL, 0, "Verbose mode" }, + { "log-level", 'l', "LEVEL", 0, "Verifier log level (default 0 for normal mode, 1 for verbose mode)" }, { "quiet", 'q', NULL, 0, "Quiet mode" }, { "emit", 'e', "SPEC", 0, "Specify stats to be emitted" }, { "sort", 's', "SPEC", 0, "Specify sort order" }, @@ -156,6 +158,14 @@ static error_t parse_arg(int key, char *arg, struct argp_state *state) return -EINVAL; } break; + case 'l': + errno = 0; + env.log_level = strtol(arg, NULL, 10); + if (errno) { + fprintf(stderr, "invalid log level: %s\n", arg); + argp_usage(state); + } + break; case 'C': env.comparison_mode = true; break; @@ -526,7 +536,7 @@ static int process_prog(const char *filename, struct bpf_object *obj, struct bpf if (!buf) return -ENOMEM; bpf_program__set_log_buf(prog, buf, buf_sz); - bpf_program__set_log_level(prog, 1 | 4); /* stats + log */ + bpf_program__set_log_level(prog, env.log_level | 4); /* stats + log */ } else { bpf_program__set_log_buf(prog, buf, buf_sz); bpf_program__set_log_level(prog, 4); /* only verifier stats */ @@ -1280,6 +1290,8 @@ int main(int argc, char **argv) argp_help(&argp, stderr, ARGP_HELP_USAGE, "veristat"); return 1; } + if (env.verbose && env.log_level == 0) + env.log_level = 1; if (env.output_spec.spec_cnt == 0) env.output_spec = default_output_spec;