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 }