Skip to content

Conversation

jamesob
Copy link
Contributor

@jamesob jamesob commented Sep 4, 2019

It's currently annoying to detect FlushStateToDisk() calls when benchmarking since they have to be inferred from a drop in coins count from the UpdateTip: log messages. This adds a new logging utility, BCLog::Timer, and some related macros that are generally useful for printing timing-related logging messages, and a message that is unconditionally written when the coins cache is flushed to disk.

2019-09-04T20:17:51Z FlushStateToDisk: write block and undo data to disk completed (3ms)
2019-09-04T20:17:51Z FlushStateToDisk: write block index to disk completed (370ms)
2019-09-04T20:17:51Z FlushStateToDisk: write coins cache to disk (2068451 coins, 294967kB) completed (21481ms)

@DrahtBot
Copy link
Contributor

DrahtBot commented Sep 4, 2019

The following sections might be updated with supplementary metadata relevant to reviewers and maintainers.

Conflicts

No conflicts as of last run.

@hebasto
Copy link
Member

hebasto commented Sep 9, 2019

Concept ACK

Copy link
Contributor

@promag promag left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Concept ACK, not so fond of the approach because you have to deal with state (assert(time_started == 0)). I think you could use RAII style, see this draft:

#define PROFILE(msg) Profile profile(msg)

            {
                PROFILE("write block and undo data to disk");
                // First make sure all block and undo data is flushed to disk.
                FlushBlockFile();
            }

@jamesob
Copy link
Contributor Author

jamesob commented Sep 19, 2019

Thanks for the looks so far. I've taken @promag's advice and have added a more generally useful RAII utility for logging times, BCLog::Timer.

@maflcko
Copy link
Member

maflcko commented Sep 19, 2019

ACK cad68f5

@jamesob jamesob force-pushed the 2019-09-flush-logs branch 3 times, most recently from 90df23b to 8dbd959 Compare September 19, 2019 21:15
Copy link
Contributor

@ryanofsky ryanofsky left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

utACK 8dbd959

Copy link
Contributor Author

@jamesob jamesob left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

flushlogs.4 -> flushlogs.5 (diff)

Thanks for all the good feedback.

Copy link
Member

@maflcko maflcko left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

unsigned ACK 1cff8d2

src/logging.h Outdated

//! Forwarded on to LogPrint if specified - has the effect of only
//! outputing the timing log when a particular debug= category is specified.
BCLog::LogFlags m_log_category{};
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

style-nit: Any reason the members are not const and private?

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Nah, will change if rebase happens.

Copy link
Contributor

@ryanofsky ryanofsky left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

utACK 1cff8d2. Since last review now logs a message at start of timing, also implements various suggestions above. I left a new suggestion, but it's not important so feel to ignore / merge this as-is.

src/logging.h Outdated
m_start_t(GetTime<std::chrono::microseconds>()),
m_log_category(log_category)
{
this->Log(strprintf("%s started", m_title), false);
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Maybe wait to initialize m_start_t until after the Log call, so the elapsed time doesn't include the time spent logging. This would also let you eliminate the show_elapsed_time bool arguments (could just check m_start_t != 0 instead).

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Oh that's a good point. Will do.

@jamesob
Copy link
Contributor Author

jamesob commented Sep 27, 2019

Thanks for the looks, have incorporated all feedback.

Copy link
Contributor

@ryanofsky ryanofsky left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

utACK 07b8f83. Overall looks good, but third commit is changing code added by the second commit, so it looks like there might have been a problem squashing commits.

Copy link
Contributor

@ryanofsky ryanofsky left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

utACK e75b176. No changes since last review, just squashed previous updates into the right commit.

src/logging.h Outdated
const std::string m_title{};

//! Forwarded on to LogPrint if specified - has the effect of only
//! outputing the timing log when a particular debug= category is specified.
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Should be "outputting" :)

@laanwj laanwj added this to the 0.20.0 milestone Sep 30, 2019
@laanwj laanwj added the Feature label Sep 30, 2019
laanwj added a commit that referenced this pull request Oct 8, 2019
0d86f4d refactor: consolidate PASTE macros (James O'Beirne)

Pull request description:

  Really dumb move-only stolen from #16805. Some of my pull requests also depend on this, so I split it up to not depend on #16805.

ACKs for top commit:
  practicalswift:
    ACK 0d86f4d -- diff looks correct
  hebasto:
    ACK 0d86f4d, I have reviewed the code and it looks OK, I agree it can be merged.
  promag:
    ACK 0d86f4d.

Tree-SHA512: 19208a8cbf83034b1ef25138d8f08d8f32ace7775f654b1597fc4599dd576f0758145f592f161cfdcaaa29d4907ac9aa5553f6f524e2b960205c760605a05901
sidhujag pushed a commit to syscoin/syscoin that referenced this pull request Oct 8, 2019
0d86f4d refactor: consolidate PASTE macros (James O'Beirne)

Pull request description:

  Really dumb move-only stolen from bitcoin#16805. Some of my pull requests also depend on this, so I split it up to not depend on bitcoin#16805.

ACKs for top commit:
  practicalswift:
    ACK 0d86f4d -- diff looks correct
  hebasto:
    ACK 0d86f4d, I have reviewed the code and it looks OK, I agree it can be merged.
  promag:
    ACK 0d86f4d.

Tree-SHA512: 19208a8cbf83034b1ef25138d8f08d8f32ace7775f654b1597fc4599dd576f0758145f592f161cfdcaaa29d4907ac9aa5553f6f524e2b960205c760605a05901
@hebasto
Copy link
Member

hebasto commented Oct 12, 2019

Compiled and tested on ODROID-HC1 (ARMv7). Due to the #17010 issue all commits from this PR (0d86f4d, 51ab646 and e75b176) were cherry-picked and applied on top of the 0.19.0rc1 tag.

Without applied commits (on v0.19.0rc1):

$ time bitcoin-cli -rpcclienttimeout=86400 gettxoutsetinfo
{
  "height": 599066,
  "bestblock": "000000000000000000153a21ef9fad22d4c2b04cee7df6da7c2ff217ad476a1c",
  "transactions": 36733277,
  "txouts": 63062142,
  "bogosize": 4743097104,
  "hash_serialized_2": "8c2d70e7e0fc6bec531b7c63806713da0526dbb4eb89242a28d93fb43743d31a",
  "disk_size": 3773406726,
  "total_amount": 17988154.82195437
}

real	5m16.144s
user	0m0.000s
sys	0m0.024s

With applied commits:

$ git log -4 --oneline
e6945685f (HEAD) logs: add timing information to FlushStateToDisk()
16875b2fb logs: add BCLog::Timer and related macros
732cb046b refactor: consolidate PASTE macros
913972944 (tag: v0.19.0rc1) doc: Update manpages

$ time bitcoin-cli -rpcclienttimeout=86400 gettxoutsetinfo
{
  "height": 599087,
  "bestblock": "0000000000000000000d1c471cbcf2819e59c344507fc5ce939021b23a6b932f",
  "transactions": 36743836,
  "txouts": 63075327,
  "bogosize": 4744073610,
  "hash_serialized_2": "fde22357f7ada7dbb81f7f303d66cbd543a1dda3430de664c56ea9ab0546ba8b",
  "disk_size": 3775232343,
  "total_amount": 17988417.32195437
}

real	60m27.968s
user	0m0.009s
sys	0m0.021s

debug.log contains:

2019-10-12T18:53:14Z FlushStateToDisk: write coins cache to disk (6260 coins, 730kB) started
2019-10-12T18:53:14Z FlushStateToDisk: write coins cache to disk (6260 coins, 730kB) completed (0.01s)

Maybe related to #16008 and #16979.

UPDATE: It seems the described issue does not relate to this PR directly. The root of observed behavior could be in ARM big.LITTLE architecture.

@laanwj
Copy link
Member

laanwj commented Oct 30, 2019

@hebasto I do not believe the changes in this PR can have such a performance impact.

@hebasto
Copy link
Member

hebasto commented Oct 30, 2019

@laanwj

I do not believe the changes in this PR can have such a performance impact.

You are right. The ARM big.LITTLE Heterogeneous Multi-Processing causes such a performance impact if any of threads runs on LITTLE core.

@laanwj
Copy link
Member

laanwj commented Oct 30, 2019

Maybe open a new issue for that (don't know how much control applications have over the thread affinity in that case?).

@jamesob jamesob force-pushed the 2019-09-flush-logs branch 2 times, most recently from 0a02920 to 2593679 Compare November 4, 2019 19:10
@jamesob jamesob force-pushed the 2019-09-flush-logs branch from 2593679 to dcef9a2 Compare November 4, 2019 19:14
@jamesob
Copy link
Contributor Author

jamesob commented Nov 4, 2019

flushlogs.8 -> flushlogs.11

Separated BCLog::Timer out into its own header per @laanwj's recommendation.

Copy link
Contributor

@ryanofsky ryanofsky left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Code review ACK dcef9a2. No changes since last review other than moving code to new timer.h header

@laanwj
Copy link
Member

laanwj commented Nov 5, 2019

Thanks, ACK dcef9a2

laanwj added a commit that referenced this pull request Nov 5, 2019
dcef9a2 logs: add timing information to FlushStateToDisk() (James O'Beirne)
41edaf2 logs: add BCLog::Timer and related macros (James O'Beirne)

Pull request description:

  It's currently annoying to detect FlushStateToDisk() calls when benchmarking since they have to be inferred from a drop in coins count from the `UpdateTip: ` log messages. This adds a new logging utility, `BCLog::Timer`, and some related macros that are generally useful for printing timing-related logging messages, and a message that is unconditionally written when the coins cache is flushed to disk.

  ```
  2019-09-04T20:17:51Z FlushStateToDisk: write block and undo data to disk completed (3ms)
  2019-09-04T20:17:51Z FlushStateToDisk: write block index to disk completed (370ms)
  2019-09-04T20:17:51Z FlushStateToDisk: write coins cache to disk (2068451 coins, 294967kB) completed (21481ms)
  ```

ACKs for top commit:
  laanwj:
    Thanks, ACK dcef9a2
  ryanofsky:
    Code review ACK dcef9a2. No changes since last review other than moving code to new timer.h header

Tree-SHA512: 6d61e48a062d3edb48d0e056a6f0b1f8031773cc99289ee4544f8349d24526b88519e1e304009d56e428f1eaf76c857bf8e7e1c0b6873a6f270306accb5edc3d
@laanwj laanwj merged commit dcef9a2 into bitcoin:master Nov 5, 2019
@@ -2023,15 +2025,23 @@ bool CChainState::FlushStateToDisk(
static int64_t nLastFlush = 0;
std::set<int> setFilesToPrune;
bool full_flush_completed = false;

const size_t coins_count = CoinsTip().GetCacheSize();
const size_t coins_mem_usage = CoinsTip().DynamicMemoryUsage();
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

How is this different from the existing cacheSize?

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Ah yeah, guess it's not. Oops.

sidhujag pushed a commit to syscoin/syscoin that referenced this pull request Nov 7, 2019
dcef9a2 logs: add timing information to FlushStateToDisk() (James O'Beirne)
41edaf2 logs: add BCLog::Timer and related macros (James O'Beirne)

Pull request description:

  It's currently annoying to detect FlushStateToDisk() calls when benchmarking since they have to be inferred from a drop in coins count from the `UpdateTip: ` log messages. This adds a new logging utility, `BCLog::Timer`, and some related macros that are generally useful for printing timing-related logging messages, and a message that is unconditionally written when the coins cache is flushed to disk.

  ```
  2019-09-04T20:17:51Z FlushStateToDisk: write block and undo data to disk completed (3ms)
  2019-09-04T20:17:51Z FlushStateToDisk: write block index to disk completed (370ms)
  2019-09-04T20:17:51Z FlushStateToDisk: write coins cache to disk (2068451 coins, 294967kB) completed (21481ms)
  ```

ACKs for top commit:
  laanwj:
    Thanks, ACK dcef9a2
  ryanofsky:
    Code review ACK dcef9a2. No changes since last review other than moving code to new timer.h header

Tree-SHA512: 6d61e48a062d3edb48d0e056a6f0b1f8031773cc99289ee4544f8349d24526b88519e1e304009d56e428f1eaf76c857bf8e7e1c0b6873a6f270306accb5edc3d
fanquake added a commit that referenced this pull request May 4, 2020
0ae8f18 build: add -Wgnu to compile flags (fanquake)
3a0fd77 Remove use of non-standard zero variadic macros (Ben Woosley)
49f6178 Drop unused LOG_TIME_MICROS helper (Ben Woosley)
5d49999 prevector: Avoid unnamed struct, which is a GNU extension (DesWurstes)

Pull request description:

  Since we [started using](#7165) the `ax_cxx_compile_stdcxx.m4` macro we've been passing `[noext]` to indicate that we don't want to use an extended mode, i.e GNU extensions. Speaking to Cory he clarified that the intention was to "require only vanilla c++11 and turn _off_ extension support so they would fail to compile".

  However in the codebase we are currently making use of some GNU extensions. We should either remove there usage, or at least amend our CXX compiler checks. I'd prefer the former.

  #### anonymous structs
  ```bash
  ./prevector.h:153:9: warning: anonymous structs are a GNU extension [-Wgnu-anonymous-struct]
          struct {
  ```

  This is fixed in b849212.

  #### variadic macros

  ```bash
  ./undo.h:57:50: warning: must specify at least one argument for '...' parameter of variadic macro [-Wgnu-zero-variadic-macro-arguments]
              ::Unserialize(s, VARINT(nVersionDummy));
  ```

  This is taken care of in #18087.

  The `LOG_TIME_*` macros introduced in #16805 make use of a [GNU extension](https://gcc.gnu.org/onlinedocs/cpp/Variadic-Macros.html).

  ```bash
  In file included from validation.cpp:22:
  ./logging/timer.h:99:99: warning: token pasting of ',' and __VA_ARGS__ is a GNU extension [-Wgnu-zero-variadic-macro-arguments]
      BCLog::Timer<std::chrono::milliseconds> PASTE2(logging_timer, __COUNTER__)(__func__, end_msg, ## __VA_ARGS__)
                                                                                                    ^
  ./logging/timer.h:99:99: warning: token pasting of ',' and __VA_ARGS__ is a GNU extension [-Wgnu-zero-variadic-macro-arguments]
  ./logging/timer.h:99:99: warning: token pasting of ',' and __VA_ARGS__ is a GNU extension [-Wgnu-zero-variadic-macro-arguments]
  ./logging/timer.h:99:99: warning: token pasting of ',' and __VA_ARGS__ is a GNU extension [-Wgnu-zero-variadic-macro-arguments]
  ./logging/timer.h:99:99: warning: token pasting of ',' and __VA_ARGS__ is a GNU extension [-Wgnu-zero-variadic-macro-arguments]
  ./logging/timer.h:101:92: warning: token pasting of ',' and __VA_ARGS__ is a GNU extension [-Wgnu-zero-variadic-macro-arguments]
      BCLog::Timer<std::chrono::seconds> PASTE2(logging_timer, __COUNTER__)(__func__, end_msg, ## __VA_ARGS__)
                                                                                             ^
  6 warnings generated.
  ```

  This is fixed in 081a0ab and 612e8e1.

  #### prevention
  To ensure that usage doesn't creep back in we can add [`-Wgnu`](https://clang.llvm.org/docs/DiagnosticsReference.html#wgnu) to our compile time flags, which will make Clang warn whenever it encounters GNU extensions.

  This would close #14130.
  Also related to #17230, where it's suggested we use a GNU extension, the `gnu::pure` attribute.

ACKs for top commit:
  practicalswift:
    ACK 0ae8f18 -- diff looks correct
  MarcoFalke:
    ACK 0ae8f18
  vasild:
    utACK 0ae8f18
  dongcarl:
    ACK 0ae8f18

Tree-SHA512: c517404681ef8edf04c785731d26105bac9f3c9c958605aa24cbe399c649e7c5ee0c4aa8e714fd2b2d335e2fbea4d571e09b0dec36678ef871f0a6683ba6bb7f
sidhujag pushed a commit to syscoin/syscoin that referenced this pull request May 5, 2020
0ae8f18 build: add -Wgnu to compile flags (fanquake)
3a0fd77 Remove use of non-standard zero variadic macros (Ben Woosley)
49f6178 Drop unused LOG_TIME_MICROS helper (Ben Woosley)
5d49999 prevector: Avoid unnamed struct, which is a GNU extension (DesWurstes)

Pull request description:

  Since we [started using](bitcoin#7165) the `ax_cxx_compile_stdcxx.m4` macro we've been passing `[noext]` to indicate that we don't want to use an extended mode, i.e GNU extensions. Speaking to Cory he clarified that the intention was to "require only vanilla c++11 and turn _off_ extension support so they would fail to compile".

  However in the codebase we are currently making use of some GNU extensions. We should either remove there usage, or at least amend our CXX compiler checks. I'd prefer the former.

  #### anonymous structs
  ```bash
  ./prevector.h:153:9: warning: anonymous structs are a GNU extension [-Wgnu-anonymous-struct]
          struct {
  ```

  This is fixed in bitcoin@b849212.

  #### variadic macros

  ```bash
  ./undo.h:57:50: warning: must specify at least one argument for '...' parameter of variadic macro [-Wgnu-zero-variadic-macro-arguments]
              ::Unserialize(s, VARINT(nVersionDummy));
  ```

  This is taken care of in bitcoin#18087.

  The `LOG_TIME_*` macros introduced in bitcoin#16805 make use of a [GNU extension](https://gcc.gnu.org/onlinedocs/cpp/Variadic-Macros.html).

  ```bash
  In file included from validation.cpp:22:
  ./logging/timer.h:99:99: warning: token pasting of ',' and __VA_ARGS__ is a GNU extension [-Wgnu-zero-variadic-macro-arguments]
      BCLog::Timer<std::chrono::milliseconds> PASTE2(logging_timer, __COUNTER__)(__func__, end_msg, ## __VA_ARGS__)
                                                                                                    ^
  ./logging/timer.h:99:99: warning: token pasting of ',' and __VA_ARGS__ is a GNU extension [-Wgnu-zero-variadic-macro-arguments]
  ./logging/timer.h:99:99: warning: token pasting of ',' and __VA_ARGS__ is a GNU extension [-Wgnu-zero-variadic-macro-arguments]
  ./logging/timer.h:99:99: warning: token pasting of ',' and __VA_ARGS__ is a GNU extension [-Wgnu-zero-variadic-macro-arguments]
  ./logging/timer.h:99:99: warning: token pasting of ',' and __VA_ARGS__ is a GNU extension [-Wgnu-zero-variadic-macro-arguments]
  ./logging/timer.h:101:92: warning: token pasting of ',' and __VA_ARGS__ is a GNU extension [-Wgnu-zero-variadic-macro-arguments]
      BCLog::Timer<std::chrono::seconds> PASTE2(logging_timer, __COUNTER__)(__func__, end_msg, ## __VA_ARGS__)
                                                                                             ^
  6 warnings generated.
  ```

  This is fixed in 081a0ab and 612e8e1.

  #### prevention
  To ensure that usage doesn't creep back in we can add [`-Wgnu`](https://clang.llvm.org/docs/DiagnosticsReference.html#wgnu) to our compile time flags, which will make Clang warn whenever it encounters GNU extensions.

  This would close bitcoin#14130.
  Also related to bitcoin#17230, where it's suggested we use a GNU extension, the `gnu::pure` attribute.

ACKs for top commit:
  practicalswift:
    ACK 0ae8f18 -- diff looks correct
  MarcoFalke:
    ACK 0ae8f18
  vasild:
    utACK 0ae8f18
  dongcarl:
    ACK 0ae8f18

Tree-SHA512: c517404681ef8edf04c785731d26105bac9f3c9c958605aa24cbe399c649e7c5ee0c4aa8e714fd2b2d335e2fbea4d571e09b0dec36678ef871f0a6683ba6bb7f
sidhujag pushed a commit to syscoin-core/syscoin that referenced this pull request Nov 10, 2020
dcef9a2 logs: add timing information to FlushStateToDisk() (James O'Beirne)
41edaf2 logs: add BCLog::Timer and related macros (James O'Beirne)

Pull request description:

  It's currently annoying to detect FlushStateToDisk() calls when benchmarking since they have to be inferred from a drop in coins count from the `UpdateTip: ` log messages. This adds a new logging utility, `BCLog::Timer`, and some related macros that are generally useful for printing timing-related logging messages, and a message that is unconditionally written when the coins cache is flushed to disk.

  ```
  2019-09-04T20:17:51Z FlushStateToDisk: write block and undo data to disk completed (3ms)
  2019-09-04T20:17:51Z FlushStateToDisk: write block index to disk completed (370ms)
  2019-09-04T20:17:51Z FlushStateToDisk: write coins cache to disk (2068451 coins, 294967kB) completed (21481ms)
  ```

ACKs for top commit:
  laanwj:
    Thanks, ACK dcef9a2
  ryanofsky:
    Code review ACK dcef9a2. No changes since last review other than moving code to new timer.h header

Tree-SHA512: 6d61e48a062d3edb48d0e056a6f0b1f8031773cc99289ee4544f8349d24526b88519e1e304009d56e428f1eaf76c857bf8e7e1c0b6873a6f270306accb5edc3d
Fabcien pushed a commit to Bitcoin-ABC/bitcoin-abc that referenced this pull request Dec 24, 2020
Summary:
dcef9a2922317cb2849f397366b6c56d755db6c9 logs: add timing information to FlushStateToDisk() (James O'Beirne)
41edaf227a69bc4846d5996675e8763fdfe0f367 logs: add BCLog::Timer and related macros (James O'Beirne)

Pull request description:

  It's currently annoying to detect FlushStateToDisk() calls when benchmarking since they have to be inferred from a drop in coins count from the `UpdateTip: ` log messages. This adds a new logging utility, `BCLog::Timer`, and some related macros that are generally useful for printing timing-related logging messages, and a message that is unconditionally written when the coins cache is flushed to disk.

  ```
  2019-09-04T20:17:51Z FlushStateToDisk: write block and undo data to disk completed (3ms)
  2019-09-04T20:17:51Z FlushStateToDisk: write block index to disk completed (370ms)
  2019-09-04T20:17:51Z FlushStateToDisk: write coins cache to disk (2068451 coins, 294967kB) completed (21481ms)
  ```

---

Backport of Core [[bitcoin/bitcoin#16805 | PR16805]]

Test Plan:
  ninja all check check-functional

Reviewers: #bitcoin_abc, PiRK

Reviewed By: #bitcoin_abc, PiRK

Differential Revision: https://reviews.bitcoinabc.org/D8754
kwvg added a commit to kwvg/dash that referenced this pull request Jun 16, 2021
kwvg added a commit to kwvg/dash that referenced this pull request Jun 17, 2021
PastaPastaPasta added a commit to dashpay/dash that referenced this pull request Jun 21, 2021
@bitcoin bitcoin locked as resolved and limited conversation to collaborators Dec 16, 2021
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Projects
None yet
Development

Successfully merging this pull request may close these issues.

8 participants