Refactor verbose and debug outputs #3203

viktormalik · 2024-05-28T14:08:54Z

Consolidate and cleanup information that is being printed in the verbose (-v) and debugging output (-d). The main idea is:

the verbose output is intended for users to get more information on what bpftrace is doing and where it is (possibly) failing,
the debug output is intended for developers to help them debugging bpftrace by providing very detailed outputs of individual stages of bpftrace runtime.

The main (user-facing) change this brings is that it introduces a mandatory argument to the -d option which allows to pick the stage whose output should be printed.

The currently supported stages are:

ast - prints the AST after each pass,
codegen - prints the LLVM IR code as emit by CodegenLLVM,
codegen-opt - prints the LLVM IR code after it is optimized by LLVM (i.e. what is actually compiled to BPF bytecode),
libbpf - captures and prints libbpf log for all libbpf operations that we use,
verifier - captures and prints the BPF verifier log.

On top of that, -d can be used multiple times with different arguments and the argument all activates all of the above.

In addition, there are more user-facing changes:

remove the -dd option,
allow to use -v and -d simultaneously,
add --debug as a long version of -d.

Also, some minor refactorings were done:

make sure the verbosity output always goes to stderr while the debugging output always goes to stdout,
improve some formatting of verbose outputs.

Checklist

Language changes are updated in man/adoc/bpftrace.adoc
User-visible and non-trivial changes updated in CHANGELOG.md
The new behaviour is covered by tests

viktormalik · 2024-05-28T14:12:53Z

Since this does several user-facing changes, I added multiple changelog entries.

CHANGELOG.md

src/main.cpp

src/ast/pass_manager.cpp

src/bpftrace.cpp

src/main.cpp

viktormalik · 2024-05-31T11:23:22Z

Update: the -d option still works as a "dry run" but now we need to stop bpftrace only after probes are attached.

man/adoc/bpftrace.adoc

jordalgo

LGTM.

The one additional thing we could consider doing is moving all the the stage level checking into log.cpp and changing LOG(DEBUG) to something like LOG(DEBUG, stage). At the moment LOG(DEBUG) is only used in 1 place so I think it's fine to modify it if we want.

viktormalik · 2024-06-03T06:28:23Z

The one additional thing we could consider doing is moving all the the stage level checking into log.cpp and changing LOG(DEBUG) to something like LOG(DEBUG, stage). At the moment LOG(DEBUG) is only used in 1 place so I think it's fine to modify it if we want.

I like this. Let's do it in a follow-up PR, though.

jordalgo · 2024-06-03T10:37:58Z

So the -d flag now implicitly adds the --dry-run flag? Also should this new flag be mentioned in the changelog?

viktormalik · 2024-06-03T11:17:35Z

So the -d flag now implicitly adds the --dry-run flag? Also should this new flag be mentioned in the changelog?

Yes, it does. I added it into the changelog.

viktormalik · 2024-06-03T11:26:50Z

Update: the -d option still works as a "dry run" but now we need to stop bpftrace only after probes are attached.

Ok, this caused more trouble than I originally anticipated. The main reason is tools-parsing-test.sh. Originally, the test would use -d to do a dry run of each tool. To preserve the same behaviour, I added a new --dry-run CLI option and I'm using it along with verbose output -v in tools-parsing-test.sh. An advantage of this is that now we even try to load and attach the tools instead of just generating the bytecode.

The reason why I'm not using -d all in tools-parsing-test.sh is twofold:

It is very verbose. When a tool test fails, it's impossible to navigate in the hundreds of lines of output in the GHA environment. We could potentially print just some stage but I wouldn't be sure which one. Dry run with a verbose output (which will, among others, show verifier log in case of failure) seems like a reasonable option.
Some tools fail to load with -d verifier. This is strange as the only thing this does is that it sets bpf_prog_load_opts.log_level to 15. This may be a kernel bug (or feature, as a matter of fact) so I'll need to investigate more. Since it's just occurring in a debug run, I don't think that this is a blocker for merging this PR.

src/main.cpp

danobi

I like this a lot.

My only feedback is that I think it'd be nice to not make --dry-run and -d duplicate the action of early exit. I suggest to make -d only control debug output and not affect execution. We are already departing from having -d emit output and not attach, so I think we are free to change it further.

That way -d and --dry-run remain orthogonal and thus more composable.

viktormalik · 2024-06-12T05:47:14Z

I like this a lot.

My only feedback is that I think it'd be nice to not make --dry-run and -d duplicate the action of early exit. I suggest to make -d only control debug output and not affect execution. We are already departing from having -d emit output and not attach, so I think we are free to change it further.

That way -d and --dry-run remain orthogonal and thus more composable.

That's a good idea. I changed -d not to terminate execution.

danobi

lgtm! but CI is failing now

viktormalik · 2024-06-12T20:21:31Z

lgtm! but CI is failing now

That's because of #3235. I'd love to hear your opinion on that one.

viktormalik · 2024-06-17T07:08:31Z

This needs #3246 to be merged first to fix the tools check.

viktormalik · 2024-06-27T12:38:55Z

Rebased on top of master. In case no one has objections, I'll merge this today.

viktormalik · 2024-06-27T13:42:25Z

Rebased on top of master. In case no one has objections, I'll merge this today.

Or not, unfortunately undump.bt is broken, see #3280.

(We really need this merged ASAP to test tools loading and attachment in the CI)

danobi · 2024-06-27T15:10:49Z

I'm looking at the regression. If you wanna TOOLS_TEST_DISABLE the broken one for now, I can remove it after I fix the regression

It seems that the CI machines were updated to a kernel which has the tcp_drop function inlined. Therefore, we need to use the new version of tcpdrop.bt.

Consolidate and cleanup information that is being printed in the verbose (-v) and debugging output (-d). The main idea is: - the verbose output is intended for users to get more information on what bpftrace is doing and where it is (possibly) failing, - the debug output is intended for developers to help them debugging bpftrace by providing very detailed outputs of individual stages of bon pftrace runtime. The main (user-facing) change this brings is that it introduces a mandatory argument to the -d option which allows to pick the stage whose output should be printed. The currently supported stages are: - 'ast' - prints the AST after each pass - 'codegen' - prints the LLVM IR code as emit by CodegenLLVM - 'codegen-opt' - prints the LLVM IR code after it is optimized by LLVM (i.e. what is actually compiled to BPF bytecode) - 'libbpf' - captures and prints libbpf log for all libbpf operations that we use - 'verifier' - captures and prints the BPF verifier log On top of that, -d can be used multiple times with different arguments and the argument 'all' activates all of the above. Another change is that -d no longer executes a dry run. The reason is that we're printing information from later stages so we need to let bpftrace run all the time. A new option for dry run will be added in the following patch. In addition, there are more user-facing changes: - remove the -dd option, - allow simultaneous use of -v and -d, - add --debug as a long version of -d. Also, some minor refactorings were done: - make sure the verbosity output always goes to stderr while the debugging output always goes to stdout, - improve some formatting of verbose outputs.

The option terminates bpftrace right after all the probes are attached. This can be useful to test that the script can be parsed, loaded, and attached, without actually executing it. We use this in the tools parsing test since the -d option no longer does a dry run.

viktormalik requested review from ajor, danobi and fbs as code owners May 28, 2024 14:08

viktormalik force-pushed the refactor-verbose-debug branch from 38213cd to 5f1936f Compare May 28, 2024 14:11

viktormalik force-pushed the refactor-verbose-debug branch from 5f1936f to 601e811 Compare May 28, 2024 14:43