I think I figured out this mystery. I’m almost certain you’re right that the test has a mistake in it:
0Logging(bench, {"-logthreadnames=0", "-debug=net"}, [] { LogPrint(BCLog::VALIDATION, "%s\n", "test"); });
This is meant to specify the same category (not the different categories, “net” and VALIDATION
). But the confusion is that with this mistake, the benchmark still shows a large ns/op
, as if it’s actually logging. I ran this code with the debugger, which shows that it is indeed logging the message. The reason, I just figured out, is that the test framework enables all logging, so when the test specifies -debug=net
, that has no effect because all categories are enabled anyway.
I tried changing that line of benchmark code to:
0Logging(bench, {"-logthreadnames=0", "-debug=0", "-debug=net"}, [] { LogPrint(BCLog::VALIDATION, "%s\n", "test"); });
Note the addition of -debug=0
which should disable all logging. So now what should happen is, the test framework specifies -debug
which enables all categories (the test framework arguments occur before the ones we specify here), but then we specify -debug=0
which disables all categories, then add back just the one we want. Now, no logging should actually happen, since we haven’t enabled "validation"
. And this was the case, no logging occurred (the ns/op
was a low number).
Now, let’s just fix the bug in the test:
0Logging(bench, {"-logthreadnames=0", "-debug=0", "-debug=validation"}, [] { LogPrint(BCLog::VALIDATION, "%s\n", "test"); });
To my surprise, this also had a low ns/op
, meaning that it was not logging! How could that be, when we’re explicitly specifying -debug=validation
and we’re doing a VALIDATION
print?
Further investigation revealed that when the command line includes -debug=0
, then we do not enable any categories specified on the command line! That is, the -debug=0
causes even later -debug=category
arguments to be ignored!
Anyway, I believe this is the fix we want, this gives the expected results (actual logging, a high ns/op
):
0 static void LogPrintWithCategory(benchmark::Bench& bench)
1 {
2- Logging(bench, {"-logthreadnames=0", "-debug=net"}, [] { LogPrint(BCLog::VALIDATION, "%s\n", "test"); });
3+ // the test framework enables all categories by default
4+ Logging(bench, {"-logthreadnames=0"}, [] { LogPrint(BCLog::VALIDATION, "%s\n", "test"); });
5 }