Replace the LogPrint function with a macro #17218

jkczyz · 2019-10-22T18:27:58Z

Calling LogPrint with a category that is not enabled results in
evaluating the remaining function arguments, which may be arbitrarily
complex (and possibly expensive) expressions. Defining LogPrint as a
macro prevents this unnecessary expression evaluation.

This is a partial revert of #14209. The decision to revert is discussed
in #16688, which adds verbose logging for validation event notification.

JeremyRubin · 2019-10-22T18:55:58Z

Is it known to be true that every call to LogPrint has no expressions with side effects?

…

On Tue, Oct 22, 2019, 11:28 AM Jeffrey Czyz ***@***.***> wrote: Calling LogPrint with a category that is not enabled results in evaluating the remaining function arguments, which may be arbitrarily complex (and possibly expensive) expressions. Defining LogPrint as a macro prevents this unnecessary expression evaluation. This is a partial revert of #14209 <#14209>. The decision to revert is discussed in #16688 <#16688>, which adds verbose logging for validation event notification. ------------------------------ You can view, comment on, or merge this pull request online at: #17218 Commit Summary - Replace the LogPrint function with a macro File Changes - *M* src/logging.h <https://github.com/bitcoin/bitcoin/pull/17218/files#diff-0> (12) Patch Links: - https://github.com/bitcoin/bitcoin/pull/17218.patch - https://github.com/bitcoin/bitcoin/pull/17218.diff — You are receiving this because you are subscribed to this thread. Reply to this email directly, view it on GitHub <#17218?email_source=notifications&email_token=AAGYN67LZZ4C7NCSPBAFEVDQP5A4VA5CNFSM4JDTSZXKYY3PNVWWK3TUL52HS4DFUVEXG43VMWVGG33NNVSW45C7NFSM4HTSVB2A>, or unsubscribe <https://github.com/notifications/unsubscribe-auth/AAGYN67C6XATDCTWFXGPE6TQP5A4VANCNFSM4JDTSZXA> .

ryanofsky · 2019-10-22T19:16:14Z

src/logging.h

-        LogPrintf(args...);
-    }
-}
+#define LogPrint(category, ...) do { \


Just a suggestion, but it might be good to leave existing LogPrint function alone, and instead just add a new LOG_CATEGORY(category, format, ...) macro. This would avoid issue the Jeremy raised about side effects in existing code, and also be nicer in my opinion because uppercase naming would be more consistent with other macros.

My feeling is that providing two ways to log where one is subtly different than the other adds unnecessary cognitive load to readers and reviewers. Will address Jeremey's comment in a follow-up.

My feeling is that providing two ways to log where one is subtly different than the other adds unnecessary cognitive load to readers and reviewers. Will address Jeremey's comment in a follow-up.

If the concern is cognitive load, I'd think the current:

LogPrintf - log unconditionally

LogPrint - log for category

is more confusing than what I'm proposing:

LogPrintf - log unconditionally

LOG_CATEGORY - log for category with macro magic

But if it would take a long time to deprecate LogPrint (not sure why it would), then I agree inconsistency would not look nice in the interim.

I don't feel strongly any way about this, so please ignore this suggestion if doesn't suit you.

Ah, I thought you were suggesting LogPrint, LogPrintf, and LOG_CATEGORY.

I'm not completely opposed to changing call sites to LOG_CATEGORY (and checking for side effects in the process). But I would like to be sure such a change would be welcome before putting in the work. :)

I would like to be sure such a change would be welcome before putting in the work. :)

To be clear, suggestion is not to do more work. My suggestion is:

Add your new macro with a name like LOG_CATEGORY, to be clear that it is a macro and not something that evaluated like a normal function.

Leave LogPrint alone, mark it deprecated and add a note like "LOG_CATEGORY is preferred over LogPrint in new code as a more performant alternative"

Separately after that, I do not think it would take a lot of work to replace instances of LogPrint and remove it. We could start with a simple scripted-diff to replace simple variable references that obviously don't have side effects.

git grep -l LogPrint | xargs sed -i 's/LogPrint\((BCLog::[A-Z]\+, "[^"]\+"\(, [A-Za-z_]\+\)*)\)/LOG_CATEGORY\1/g'

As for organizing these changes, I might consider closing this PR, and instead adding the new macro directly where you intend to use it in #16688.

Understood. I would be fine with that assuming there is agreement that LogPrint should be deprecated in favor of the LOG_CATEGORY macro.

src/logging.h

practicalswift · 2019-10-22T20:08:15Z

Is this a pure optimisation PR, or can we think of reasons beyond that?

Do we have any examples of slow LogPrint(…) calls where this would make a significant difference?

Can we benchmark this in any way?

Calling LogPrint with a category that is not enabled results in evaluating the remaining function arguments, which may be arbitrarily complex (and possibly expensive) expressions. Defining LogPrint as a macro prevents this unnecessary expression evaluation. This is a partial revert of bitcoin#14209. The decision to revert is discussed in bitcoin#16688, which adds verbose logging for validation event notification.

JeremyRubin · 2019-10-22T21:01:46Z

I've thought about it a bit and I think for the reason I gave above I'd want to NACK this change. If there are motivating examples for not evaluating the calls, they should be fixed one by one. It would also seem like perfect forwarding and inline can help with some of these concerns too to nudge the compiler to defer constructing strings or whatever.

…

On Tue, Oct 22, 2019, 1:47 PM Jeffrey Czyz ***@***.***> wrote: ***@***.**** commented on this pull request. ------------------------------ In src/logging.h <#17218 (comment)>: > @@ -155,12 +155,10 @@ static inline void LogPrintf(const char* fmt, const Args&... args) } } -template <typename... Args> -static inline void LogPrint(const BCLog::LogFlags& category, const Args&... args) -{ - if (LogAcceptCategory((category))) { - LogPrintf(args...); - } -} +#define LogPrint(category, ...) do { \ Done in 8734c85 <8734c85> . — You are receiving this because you commented. Reply to this email directly, view it on GitHub <#17218?email_source=notifications&email_token=AAGYN6ZCEVD7RSKFT4WLQPTQP5RGBA5CNFSM4JDTSZXKYY3PNVWWK3TUL52HS4DFWFIHK3DMKJSXC5LFON2FEZLWNFSXPKTDN5WW2ZLOORPWSZGOCI2YLLA#discussion_r337741803>, or unsubscribe <https://github.com/notifications/unsubscribe-auth/AAGYN636IOUCRCYGJ2VKPFDQP5RGBANCNFSM4JDTSZXA> .

jkczyz · 2019-10-22T22:00:29Z

Is it known to be true that every call to LogPrint has no expressions with side effects?

I grepped over call sites to check if anything suspicious stood out, but I did not thoroughly check if each expression was free of side effects.

Note that this PR simply reverts the unintended behavioral change of #14209. Any side effects would have been introduced by that PR or subsequent changes.

If there are motivating examples for not evaluating the calls, they should
be fixed one by one.

The motivating example is #16688. I think this change is relatively low risk and restores the previous behavior of LogPrint. The alternative of adding a separate logging function would move the codebase into a worse state, IMHO. That should be weighed against the perceived risk of removing any unintended side effects.

It would also seem like perfect forwarding and inline can help with some of
these concerns too to nudge the compiler to defer constructing strings or
whatever.

I don't believe perfect forwarding will prevent an argument expression from being evaluated, which is the reason for the PR. The compiler is also free to ignore inline.

jkczyz · 2019-10-22T22:19:02Z

Is this a pure optimisation PR, or can we think of reasons beyond that?

Do we have any examples of slow LogPrint(…) calls where this would make a significant difference?

Can we benchmark this in any way?

I see it more as restoring the previous behavior of only paying for the logging that you want. Thus, anyone is free to add very verbose logging to their module without others incurring a cost when logging for that category isn't enabled.

JeremyRubin · 2019-10-22T22:48:31Z

Ah didn't catch that it's reverting behavior. I think that given that it's a revert it's more ok. It's tricky to tell by glance if there are no side effects because of atomics autoderef loading and stuff, which is why I felt it deserves careful consideration. I don't care to bikeshed too much, but I think that making it IF_CAT(cat, expr) would be semantic in terms of implying the arguments may not be evaluated, and then expr can be an unconditional Logprint. But that's a few extra characters... I wouldn't object if expr is passed to LogPrint in the macro, but feel it's a bit harder to comprehend at a glance.

…

On Tue, Oct 22, 2019, 3:34 PM Jeffrey Czyz ***@***.***> wrote: ***@***.**** commented on this pull request. ------------------------------ In src/logging.h <#17218 (comment)>: > @@ -155,12 +155,10 @@ static inline void LogPrintf(const char* fmt, const Args&... args) } } -template <typename... Args> -static inline void LogPrint(const BCLog::LogFlags& category, const Args&... args) -{ - if (LogAcceptCategory((category))) { - LogPrintf(args...); - } -} +#define LogPrint(category, ...) do { \ Ah, I thought you were suggesting LogPrint, LogPrintf, and LOG_CATEGORY. I'm not completely opposed to changing call sites to LOG_CATEGORY (and checking for side effects in the process). But I would like to be sure such a change would be welcome before putting in the work. :) — You are receiving this because you commented. Reply to this email directly, view it on GitHub <#17218?email_source=notifications&email_token=AAGYN67PZ3X5Z2MVSRXTJFDQP55W5A5CNFSM4JDTSZXKYY3PNVWWK3TUL52HS4DFWFIHK3DMKJSXC5LFON2FEZLWNFSXPKTDN5WW2ZLOORPWSZGOCI3EIYQ#discussion_r337779900>, or unsubscribe <https://github.com/notifications/unsubscribe-auth/AAGYN6Z3TFDBZLZOUXAEQITQP55W5ANCNFSM4JDTSZXA> .

practicalswift · 2019-10-23T06:08:22Z

I see it more as restoring the previous behavior of only paying for the logging that you want. Thus, anyone is free to add very verbose logging to their module without others incurring a cost when logging for that category isn't enabled.

In other types of software that is universally a good idea, but it could be argued that in Bitcoin Core we want to make sure that execution of consensus critical code should be as identical as possible across clients. See sipas arguments in #4576 regarding always evaluating arguments to not have uncertainty what performance impact consistency checks.

When it comes to consensus critical code it could be argued that consistency in taken code paths is often more important than raw execution speed.

If we want to put that principle aside we should have good reasons for doing so: that's why it is important to benchmark a change like this. Is the performance impact measurable in practice?

laanwj · 2019-10-23T08:35:04Z

~~Concept NACK, this used to be a macro in the past. We changed it to a function for argument hygiene as is common in modern C++.~~

~~If you really need to log in performance-critical contexts, then you could do a special thing there, but I'm very much against changing the general log system for this.~~

Never mind, I was confused here. It still uses an internal function for that. The whole point here was to be able to shortcut in case logging for the category was disabled…

I think the assumption in #14209 was that an inline was just as good as a macro in this regard. Have you benchmarked this?

ryanofsky · 2019-10-23T10:05:57Z

I think the assumption in #14209 was that an inline was just as good as a macro in this regard. Have you benchmarked this?

Practicalswift asked the same question yesterday and this hasn't been benchmarked yet. It might be the case that performance is roughly equivalent, but if by "just as good" you mean actually equivalent, it's probably not a good assumption that compilers are going to be able to deduce that calls like pindex->GetBlockHash().GetHex() have no side-effects and inline them out.

jkczyz · 2019-10-23T17:00:54Z

I see it more as restoring the previous behavior of only paying for the logging that you want. Thus, anyone is free to add very verbose logging to their module without others incurring a cost when logging for that category isn't enabled.

In other types of software that is universally a good idea, but it could be argued that in Bitcoin Core we want to make sure that execution of consensus critical code should be as identical as possible across clients. See sipas arguments in #4576 regarding always evaluating arguments to not have uncertainty what performance impact consistency checks.

When it comes to consensus critical code it could be argued that consistency in taken code paths is often more important than raw execution speed.

Hmmm, in that case the current behavior is actually inconsistent. If the compiler decides to inline the code at a particular call site, then the arguments will not be evaluated whereas they will be evaluated at call sites that are not inlined.

jkczyz · 2019-10-23T17:06:45Z

I think the assumption in #14209 was that an inline was just as good as a macro in this regard. Have you benchmarked this?

Practicalswift asked the same question yesterday and this hasn't been benchmarked yet. It might be the case that performance is roughly equivalent, but if by "just as good" you mean actually equivalent, it's probably not a good assumption that compilers are going to be able to deduce that calls like pindex->GetBlockHash().GetHex() have no side-effects and inline them out.

Correct, I have not benchmarked the code. I'm not even sure how to adequately devise such a benchmark given the compiler can decide which call sites will have the code inlined. At very least, use of a macro will result in consistent behavior with regards to argument evaluation.

JeremyRubin · 2019-10-23T17:45:20Z

t's probably not a good assumption that compilers are going to be able to deduce that calls like pindex->GetBlockHash().GetHex() have no side-effects and inline them out.

Maybe we should look at the gnu::pure attribute (which have pretty wide support in gcc/clang/llvm and others, except MSVC) and noexcept, which would allow the compiler to better optimize such functions if this is an issue https://stackoverflow.com/questions/2798188/pure-const-function-attributes-in-different-compilers

gmaxwell · 2019-10-29T21:49:55Z

So, uh, no real direct input but at one point while reworking the logging for categories I changed the handling around and benchmarking as a function vs macro vs a few other things and found measurably slower validation (in particular early chain IBD which is already pretty fast), it was also easy to see it doing string parsing in the disassembly.

There is another option beyond making this a macro: find the few performance critical logging spots and block them off with category tests (potentially just copying the current logging state into a local variable). This should be even faster than the macro, since you could eliminate many logging lines with potentially just one access to the contended global state.

laanwj · 2019-10-30T16:07:35Z

I think it's fine to do this. I strongly doubt there is any logging (especially categorized debug logging) with important side-effects. Not too long ago this was a macro. At least I've always treated it as one.

If @MarcoFalke's concerns in #14209 no longer hold, ACK.

jamesob · 2019-10-30T16:49:59Z

Concept ACK. I think it's safer if this lives as a macro for the reasons described in the original post, and this especially shouldn't be controversial since (as others have noted) this was up until fairly recently a macro.

maflcko · 2019-10-30T17:22:35Z

My motivation for #14209 was to get code coverage test run, which was impossible prior to my fix. I don't care whether it is a function or macro.

Someone should do a benchmark, though if the rationale for this change is "speed up".

laanwj · 2019-10-30T18:22:23Z

Someone should do a benchmark, though if the rationale for this change is "speed up".

From what I understand it's not a benchmark issue but a conceptual one. Macros don't have the guarantee to evaluate their arguments, but functions (even inline functions) do. Given arguments that are expensive to compute (e.g. string formatting, allocation, conversions), that's will always make a difference in the disabled case.

maflcko · 2019-10-31T19:04:05Z

Our bench runner has a full testing setup, so in theory LogPrint* could be microbenched

jnewbery · 2019-10-31T21:20:08Z

ACK 8734c85

My motivation for #14209 was to get code coverage test run, which was impossible prior to my fix. I don't care whether it is a function or macro.

Whether it is a function or macro seems completely orthogonal to this. The simple fix in #14209 would have just been to remove the ifdef preprocessor directive added here: c8914b9#diff-772f489c7d0a32de3badbfbcb5fd200dR133.

The renaming LogPrintf -> LOG_CATEGORY suggested here #17218 (comment) seems like a good follow-up.

Here are all the LogPrintf changes since #14209 was merged:

git log fae3fbd61a89c7a35bc0eda91b1df61371dc0936..HEAD -SLogPrintf -p | grep "^[+-]" | grep LogPrintf
-                pwallet->WalletLogPrintf("Skipping import of %s (key already present)\n", EncodeDestination(PKHash(keyid)));
+                pwallet->WalletLogPrintf("Error importing key for %s\n", EncodeDestination(PKHash(keyid)));
-                pwallet->WalletLogPrintf("Skipping import of %s (script already present)\n", HexStr(script));
+        LogPrintf("Error reading from database: %s\n", e.what());
-            LogPrintf("Error reading from database: %s\n", e.what());
+            WalletLogPrintf("Already have script %s, skipping\n", HexStr(entry));
+            WalletLogPrintf("Already have key with pubkey %s, skipping\n", HexStr(pubkey));
+            WalletLogPrintf("Already have pubkey %s, skipping\n", HexStr(temp));
-            LogPrintf("The wallet is probably corrupted: Some keys decrypt but not all.\n");
+            LogPrintf("The wallet is probably corrupted: Some keys decrypt but not all.\n");
-    // This can be called during exceptions by LogPrintf(), so we cache the
-    // This can be called during exceptions by LogPrintf(), so we cache the
-    LogPrintf("\n\n\n\n\n");
-        LogPrintf("%s: Connecting genesis block...\n", __func__);
-            LogPrintf("%s: failed to activate chain (%s)\n", __func__, FormatStateMessage(state));
-    LogPrintf("Using wallet directory %s\n", GetWalletDir().string());
+    LogPrintf("Using wallet directory %s\n", GetWalletDir().string());
+        LogPrintf("* Using %.1f MiB for %s block filter index database\n",
+            LogPrintf("%s: Failed to open filter file %d\n", __func__, pos.nFile);
+            LogPrintf("%s: Failed to truncate filter file %d\n", __func__, pos.nFile);
+            LogPrintf("%s: Failed to commit filter file %d\n", __func__, pos.nFile);
+        LogPrintf("%s: out of disk space\n", __func__);
+        LogPrintf("%s: Failed to open filter file %d\n", __func__, pos.nFile);
+    if (ec) LogPrintf("%s: %s %s\n", __func__, ec.message(), path.string());
+            LogPrintf("%s: %s %s\n", __func__, ec.message(), it->path().string());
+                LogPrintf("%s\n", e.what());
+                LogPrintf("Pre-allocating up to position 0x%x in %s%05u.dat\n", new_size, m_prefix, pos.nFile);
-                    LogPrintf("Pre-allocating up to position 0x%x in blk%05u.dat\n", nNewChunks * BLOCKFILE_CHUNK_SIZE, pos.nFile);
-                LogPrintf("Pre-allocating up to position 0x%x in rev%05u.dat\n", nNewChunks * UNDOFILE_CHUNK_SIZE, pos.nFile);
+        LogPrintf("Unable to open file %s\n", path.string());
+            LogPrintf("Unable to seek to position %u of %s\n", pos.nPos, path.string());
-        LogPrintf("Unable to open file %s\n", path.string());
-            LogPrintf("Unable to seek to position %u of %s\n", pos.nPos, path.string());
+        LogPrintf("Using RdSeed as additional entropy source\n");
+            LogPrintf("%s: Unable to remove PID file: File does not exist\n", __func__);
-        LogPrintf("%s: Unable to remove pidfile: %s\n", __func__, e.what());
+        LogPrintf("%s: Unable to remove PID file: %s\n", __func__, e.what());
+    wallet->WalletLogPrintf("Releasing wallet\n");
-            LogPrintf("%s: Warning: RegQueryValueExA(HKEY_PERFORMANCE_DATA) failed with code %i\n", __func__, ret);
+        LogPrintf("Invalid or missing banlist.dat; recreating\n");
-        LogPrintf("Invalid or missing banlist.dat; recreating\n");
-            LogPrintf("HTTP event loop did not exit within allotted time, sending loopbreak\n");
+                LogPrintf("WARNING: the RPC server is not safe to expose to untrusted networks such as the public internet\n");
+            LogPrintf("WARNING: option -rpcallowip was specified without -rpcbind; this doesn't usually make sense\n");
-        LogPrintf("Warning: Config setting for %s only applied on %s network when in [%s] section.\n", arg, m_network, m_network);
+- #10265 `ff13f59` Make sure pindex is non-null before possibly referencing in LogPrintf call. (Karl-Johan Alm)
+                LogPrintf("Setting version bits activation parameters for %s to start=%ld, timeout=%ld\n", vDeploymentParams[0], nStartTime, nTimeout);
-                    LogPrintf("Setting version bits activation parameters for %s to start=%ld, timeout=%ld\n", vDeploymentParams[0], nStartTime, nTimeout);
+                LogPrintf("[%d%%]...", percentageDone); /* Continued */

None of the new logs with printf args have side-effects:

+            WalletLogPrintf("Already have script %s, skipping\n", HexStr(entry));   // HexStr() has no side-effects
+            WalletLogPrintf("Already have key with pubkey %s, skipping\n", HexStr(pubkey));   // HexStr() has no side-effects
+            WalletLogPrintf("Already have pubkey %s, skipping\n", HexStr(temp));   // HexStr() has no side-effects
+        LogPrintf("* Using %.1f MiB for %s block filter index database\n",    // BlockFilterTypeName() has no side-effects
+            LogPrintf("%s: Failed to open filter file %d\n", __func__, pos.nFile);   // no side-effects
+            LogPrintf("%s: Failed to truncate filter file %d\n", __func__, pos.nFile);   // no side-effects
+            LogPrintf("%s: Failed to commit filter file %d\n", __func__, pos.nFile);   // no side-effects
+        LogPrintf("%s: out of disk space\n", __func__);   // no side-effects
+        LogPrintf("%s: Failed to open filter file %d\n", __func__, pos.nFile);   // no side-effects
+    if (ec) LogPrintf("%s: %s %s\n", __func__, ec.message(), path.string());   // boost::system::error_code::message() and boost::filesystem::path::string() have no side-effects
+            LogPrintf("%s: %s %s\n", __func__, ec.message(), it->path().string());   // boost::system::error_code::message() and boost::filesystem::path::string() have no side-effects
+                LogPrintf("%s\n", e.what());   // std::exception::what() has no side-effects
+                LogPrintf("Pre-allocating up to position 0x%x in %s%05u.dat\n", new_size, m_prefix, pos.nFile);   // no side-effects
+                LogPrintf("[%d%%]...", percentageDone); /* Continued */   // no side-effects

So merging this is at least as safe as we were prior to #14209.

jkczyz · 2019-10-31T22:56:09Z

Our bench runner has a full testing setup, so in theory LogPrint* could be microbenched

I ran the following benchmark configured with --enable-debug:

#include <bench/bench.h>
#include <logging.h>
#include <validation.h>

static void BenchmarkLogPrint(benchmark::State& state)
{
    LOCK(cs_main);
    CBlockIndex* tip = ::ChainActive().Tip();
    assert(tip != nullptr);

    while (state.KeepRunning()) {
        LogPrint(BCLog::NET, "%s: new block hash=%s", __func__, tip->GetBlockHash().ToString());
    }
}

BENCHMARK(BenchmarkLogPrint, 10 * 1000 * 1000);

LogPrint as an inline function:

# Benchmark, evals, iterations, total, min, max, median
BenchmarkLogPrint, 5, 10000000, 28.4183, 5.64534e-07, 5.76267e-07, 5.66845e-07

LogPrint as a macro:

# Benchmark, evals, iterations, total, min, max, median
BenchmarkLogPrint, 5, 10000000, 0.356953, 6.8946e-09, 7.80663e-09, 6.92364e-09

Looks like it's a couple of orders of magnitude faster as a macro. Let me know if there is something more representative to run.

jkczyz · 2019-11-01T06:02:13Z

The renaming LogPrintf -> LOG_CATEGORY suggested here #17218 (comment) seems like a good follow-up.

Here are all the LogPrintf changes since #14209 was merged:

I believe we want LogPrint here as LogPrintf is the unconditional one.

maflcko · 2019-11-01T13:07:10Z

re-run ci

jnewbery · 2019-11-01T13:44:49Z

I believe we want LogPrint here as LogPrintf is the unconditional one.

Oops. You're right. Same exercise for LogPrint:

+        LogPrint(BCLog::NET, "peer=%d: %s\n", nodeid, message);  // no side-effects
+        LogPrint(BCLog::NET, "CHECKSUM ERROR (%s, %u bytes), expected %s was %s\n",  // no side-effects (SanitizeString() and HexString() args are const)
+            LogPrint(BCLog::NET, "Ignoring \"getaddr\" from block-relay-only connection. peer=%d\n", pfrom->GetId());  // no side-effects (GetId() is const)
+                    LogPrint(BCLog::NET, "timeout of inflight tx %s from peer=%d\n", it->first.ToString(), pto->GetId());  // no side-effects (GetId() is const)
+            LogPrint(BCLog::NET, "%s(%s, %u bytes): Exception '%s' caught\n", __func__, SanitizeString(strCommand), nMessageSize, e.what());  // no side-effects (std::exception::what() is const)
+            LogPrint(BCLog::NET, "%s(%s, %u bytes): Exception '%s' caught\n", __func__, SanitizeString(strCommand), nMessageSize, e.what());  // no side-effects (std::exception::what() is const)
+        LogPrint(BCLog::NET, "peer=%d: %s\n", nodeid, message);  // no side-effects
+            LogPrint(BCLog::NET, "Unexpected cmpctblock message received from peer %d\n", pfrom->GetId());  // no side-effects (GetId() is const)
+            LogPrint(BCLog::NET, "Unexpected blocktxn message received from peer %d\n", pfrom->GetId());  // no side-effects (GetId() is const)
+            LogPrint(BCLog::NET, "Unexpected headers message received from peer %d\n", pfrom->GetId());  // no side-effects (GetId() is const)
+            LogPrint(BCLog::NET, "Unexpected block message received from peer %d\n", pfrom->GetId());  // no side-effects (GetId() is const)
+                    LogPrint(BCLog::ADDRMAN, "Unable to test; swapping %s for %s in tried table anyway\n", info_new.ToString(), info_old.ToString());  // no side-effects (ToString() is const)
+        LogPrint(BCLog::ZMQ, "zmq: Outbound message high water mark for %s at %s is %d\n", type, address, outbound_message_high_water_mark);  // no side-effects
+        LogPrint(BCLog::HTTP, "HTTP request from %s rejected: Client network is not allowed RPC access\n",  // no side-effects (GetPeer() and ToString() are const)
+        LogPrint(BCLog::HTTP, "HTTP request from %s rejected: Unknown HTTP request method\n",  // no side-effects (GetPeer() and ToString() are const)
+        LogPrint(BCLog::ZMQ, "zmq: Outbound message high water mark for %s at %s is %d\n", type, address, outbound_message_high_water_mark);  // no side-effects
+    LogPrint(BCLog::ZMQ, "zmq: version %d.%d.%d\n", major, minor, patch);  // no side-effects

8734c85 Replace the LogPrint function with a macro (Jeffrey Czyz) Pull request description: Calling `LogPrint` with a category that is not enabled results in evaluating the remaining function arguments, which may be arbitrarily complex (and possibly expensive) expressions. Defining `LogPrint` as a macro prevents this unnecessary expression evaluation. This is a partial revert of #14209. The decision to revert is discussed in #16688, which adds verbose logging for validation event notification. ACKs for top commit: jnewbery: ACK 8734c85 Tree-SHA512: 19e995eaef0ff008a9f8c1fd6f3882f1fbf6794dd7e2dcf5c68056be787eee198d2956037d4ffba2b01e7658b47eba276cd7132feede78832373b3304203961e

8734c85 Replace the LogPrint function with a macro (Jeffrey Czyz) Pull request description: Calling `LogPrint` with a category that is not enabled results in evaluating the remaining function arguments, which may be arbitrarily complex (and possibly expensive) expressions. Defining `LogPrint` as a macro prevents this unnecessary expression evaluation. This is a partial revert of bitcoin#14209. The decision to revert is discussed in bitcoin#16688, which adds verbose logging for validation event notification. ACKs for top commit: jnewbery: ACK 8734c85 Tree-SHA512: 19e995eaef0ff008a9f8c1fd6f3882f1fbf6794dd7e2dcf5c68056be787eee198d2956037d4ffba2b01e7658b47eba276cd7132feede78832373b3304203961e

@jkczyz

faf6e4b Use str.splitlines where appropriate (MarcoFalke) Pull request description: Before (only tested github-merge): ``` [pull/17218/local-merge e3ecb347e4] Merge #17218: Replace the LogPrint function with a macro Date: Fri Nov 1 10:08:05 2019 -0400 #17218 Replace the LogPrint function with a macro into master * 8734c856f85cb506fa97596383dd7e7b9edd7e03 Replace the LogPrint function with a macro (Jeffrey Czyz) (pull/17218/head) ACKs: * I've thought about it a bit and I think for the reason I gave above I'd want to NACK this change. If there are motivating examples for not evaluating the calls, they should be fixed one by one. It would also seem like perfect forwarding and inline can help with some of these concerns too to nudge the compiler to defer constructing strings or whatever. On Tue, Oct 22, 2019, 1:47 PM Jeffrey Czyz <notifications@github.com> wrote: > *@jkczyz* commented on this pull request. > ------------------------------ > > In src/logging.h > <bitcoin/bitcoin#17218 (comment)>: > > > @@ -155,12 +155,10 @@ static inline void LogPrintf(const char* fmt, const Args&... args) > } > } > > -template <typename... Args> > -static inline void LogPrint(const BCLog::LogFlags& category, const Args&... args) > -{ > - if (LogAcceptCategory((category))) { > - LogPrintf(args...); > - } > -} > +#define LogPrint(category, ...) do { \ > > Done in 8734c85 > <bitcoin/bitcoin@8734c85> > . > > — > You are receiving this because you commented. > Reply to this email directly, view it on GitHub > <bitcoin/bitcoin#17218>, > or unsubscribe > <https://github.com/notifications/unsubscribe-auth/AAGYN636IOUCRCYGJ2VKPFDQP5RGBANCNFSM4JDTSZXA> > . > (JeremyRubin) * ACK 8734c856f85cb506fa97596383dd7e7b9edd7e03 (jnewbery) Type 's' to sign off on the above merge, or 'x' to reject and exit. x ``` After: ``` [pull/17218/local-merge 74208557d0] Merge #17218: Replace the LogPrint function with a macro Date: Fri Nov 1 10:14:07 2019 -0400 #17218 Replace the LogPrint function with a macro into master * 8734c856f85cb506fa97596383dd7e7b9edd7e03 Replace the LogPrint function with a macro (Jeffrey Czyz) (pull/17218/head) ACKs: * ACK 8734c856f85cb506fa97596383dd7e7b9edd7e03 (jnewbery) Type 's' to sign off on the above merge, or 'x' to reject and exit. s ``` ACKs for top commit: laanwj: ACK faf6e4b Tree-SHA512: e573cce5b8ff382e05374d857258a5036eebbb1cc76ec130d663c9bd688bb556b9e4ebfeb6a0ea5e58c12494fb3c494c738db370136926adad976ceff0cfda8c

- rpc/wallet: initialize nFeeRequired to avoid using garbage value on failure bitcoin#18274 - httpserver: use own HTTP status codes bitcoin#18168 - tests: Add fuzzing harnesses for various Base{32,58,64} and hex related functions bitcoin#17229 - util: Don't allow Base32/64-decoding or ParseMoney(…) on strings with embedded NUL characters. Add tests. bitcoin#17753 - util: Fail to parse empty string in ParseMoney bitcoin#18225 - util: Fail to parse whitespace-only strings in ParseMoney(...) (instead of parsing as zero) bitcoin#18270 - Replace the LogPrint function with a macro bitcoin#17218 - Fix wallet unload race condition bitcoin#18338 - qt: Fix Window -> Minimize menu item bitcoin#18549 - windows: Enable heap terminate-on-corruption bitcoin#17916

8734c85 Replace the LogPrint function with a macro (Jeffrey Czyz) Pull request description: Calling `LogPrint` with a category that is not enabled results in evaluating the remaining function arguments, which may be arbitrarily complex (and possibly expensive) expressions. Defining `LogPrint` as a macro prevents this unnecessary expression evaluation. This is a partial revert of bitcoin#14209. The decision to revert is discussed in bitcoin#16688, which adds verbose logging for validation event notification. ACKs for top commit: jnewbery: ACK 8734c85 Tree-SHA512: 19e995eaef0ff008a9f8c1fd6f3882f1fbf6794dd7e2dcf5c68056be787eee198d2956037d4ffba2b01e7658b47eba276cd7132feede78832373b3304203961e

…egular function 14f2239 [Util] Replace LogPrintf (but not LogPrint) macro with regular function (random-zebra) Pull request description: This commit combines together bitcoin#14209 [MarcoFalke] and bitcoin#17218 [jkczyz] - The first one replaces `LogPrintf` and `LogPrint` macros with functions: > It is not possible to run the full test suite when configured with --enable-lcov, since logging is disabled currently so that "unnecessary branches are not analyzed". (See c8914b9) > > Fix this instead by replacing the macros with functions. - The second one restores the `LogPrint` macro: > Calling LogPrint with a category that is not enabled results in evaluating the remaining function arguments, which may be arbitrarily complex (and possibly expensive) expressions. Defining LogPrint as a macro prevents this unnecessary expression evaluation. > > This is a partial revert of 14209. The decision to revert is discussed in 16688, which adds verbose logging for validation event notification. ACKs for top commit: furszy: ACK 14f2239 Fuzzbawls: ACK 14f2239 Tree-SHA512: bbbe475aae784e18acaf8f4f1eae8f6114f9ddb5eff460225fd0a1d40f999826bac99fb63f1359d71d03c6694d9c56fa697bfdee546188fe4fdf1a2f3de3eb22

8734c85 Replace the LogPrint function with a macro (Jeffrey Czyz) Pull request description: Calling `LogPrint` with a category that is not enabled results in evaluating the remaining function arguments, which may be arbitrarily complex (and possibly expensive) expressions. Defining `LogPrint` as a macro prevents this unnecessary expression evaluation. This is a partial revert of bitcoin#14209. The decision to revert is discussed in bitcoin#16688, which adds verbose logging for validation event notification. ACKs for top commit: jnewbery: ACK 8734c85 Tree-SHA512: 19e995eaef0ff008a9f8c1fd6f3882f1fbf6794dd7e2dcf5c68056be787eee198d2956037d4ffba2b01e7658b47eba276cd7132feede78832373b3304203961e

fanquake added the Utils/log/libs label Oct 22, 2019

ryanofsky reviewed Oct 22, 2019

View reviewed changes

maflcko reviewed Oct 22, 2019

View reviewed changes

src/logging.h Outdated Show resolved Hide resolved

jkczyz force-pushed the 2019-10-log-print branch from 93e8f7a to 8734c85 Compare October 22, 2019 20:45

JeremyRubin mentioned this pull request Oct 23, 2019

Use Pure function attribute #17230

Closed

jkczyz mentioned this pull request Oct 31, 2019

log: Add validation interface logging #16688

Merged

maflcko closed this Nov 1, 2019

maflcko reopened this Nov 1, 2019

maflcko merged commit 8734c85 into bitcoin:master Nov 1, 2019

MarkLTZ mentioned this pull request Apr 4, 2020

Bitcoin PR tracking litecoinz-core/litecoinz#14

Closed

maflcko mentioned this pull request Apr 30, 2020

bench: Add logging benchmark #18815

Merged

random-zebra mentioned this pull request Sep 10, 2021

[Util] Replace LogPrintf (but not LogPrint) macro with regular function PIVX-Project/PIVX#2547

Merged

bitcoin locked as resolved and limited conversation to collaborators Dec 16, 2021

Replace the LogPrint function with a macro #17218

Replace the LogPrint function with a macro #17218

Uh oh!

Conversation

jkczyz commented Oct 22, 2019

Uh oh!

JeremyRubin commented Oct 22, 2019 via email

Uh oh!

ryanofsky Oct 22, 2019

Choose a reason for hiding this comment

Uh oh!

jkczyz Oct 22, 2019

Choose a reason for hiding this comment

Uh oh!

ryanofsky Oct 22, 2019 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Choose a reason for hiding this comment

Uh oh!

jkczyz Oct 22, 2019

Choose a reason for hiding this comment

Uh oh!

ryanofsky Oct 23, 2019

Choose a reason for hiding this comment

Uh oh!

jkczyz Oct 23, 2019

Choose a reason for hiding this comment

Uh oh!

Uh oh!

practicalswift commented Oct 22, 2019

Uh oh!

JeremyRubin commented Oct 22, 2019 via email

Uh oh!

jkczyz commented Oct 22, 2019

Uh oh!

jkczyz commented Oct 22, 2019

Uh oh!

JeremyRubin commented Oct 22, 2019 via email

Uh oh!

practicalswift commented Oct 23, 2019 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

laanwj commented Oct 23, 2019 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

ryanofsky commented Oct 23, 2019 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

jkczyz commented Oct 23, 2019 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

jkczyz commented Oct 23, 2019

Uh oh!

JeremyRubin commented Oct 23, 2019

Uh oh!

gmaxwell commented Oct 29, 2019

Uh oh!

laanwj commented Oct 30, 2019 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

jamesob commented Oct 30, 2019

Uh oh!

maflcko commented Oct 30, 2019

Uh oh!

laanwj commented Oct 30, 2019 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

maflcko commented Oct 31, 2019

Uh oh!

jnewbery commented Oct 31, 2019

Uh oh!

jkczyz commented Oct 31, 2019 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

jkczyz commented Nov 1, 2019 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

maflcko commented Nov 1, 2019

Uh oh!

jnewbery commented Nov 1, 2019

Uh oh!

ryanofsky Oct 22, 2019 •

edited

Loading

practicalswift commented Oct 23, 2019 •

edited

Loading

laanwj commented Oct 23, 2019 •

edited

Loading

ryanofsky commented Oct 23, 2019 •

edited

Loading

jkczyz commented Oct 23, 2019 •

edited

Loading

laanwj commented Oct 30, 2019 •

edited

Loading

laanwj commented Oct 30, 2019 •

edited

Loading

jkczyz commented Oct 31, 2019 •

edited

Loading

jkczyz commented Nov 1, 2019 •

edited

Loading