-
Notifications
You must be signed in to change notification settings - Fork 37.7k
logs: add timing information to FlushStateToDisk() #16805
New issue
Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.
By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.
Already on GitHub? Sign in to your account
Conversation
9834625
to
6fa89ed
Compare
The following sections might be updated with supplementary metadata relevant to reviewers and maintainers. ConflictsNo conflicts as of last run. |
Concept ACK |
6fa89ed
to
0b100b8
Compare
There was a problem hiding this 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();
}
22d1183
to
cad68f5
Compare
Thanks for the looks so far. I've taken @promag's advice and have added a more generally useful RAII utility for logging times, |
ACK cad68f5 |
90df23b
to
8dbd959
Compare
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
utACK 8dbd959
8dbd959
to
1cff8d2
Compare
There was a problem hiding this 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.
There was a problem hiding this 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{}; |
There was a problem hiding this comment.
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?
There was a problem hiding this comment.
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.
There was a problem hiding this 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); |
There was a problem hiding this comment.
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).
There was a problem hiding this comment.
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.
1cff8d2
to
07b8f83
Compare
Thanks for the looks, have incorporated all feedback. |
There was a problem hiding this 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.
07b8f83
to
e75b176
Compare
There was a problem hiding this 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. |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Should be "outputting" :)
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
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
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 Without applied commits (on v0.19.0rc1):
With applied commits:
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. |
@hebasto 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. |
Maybe open a new issue for that (don't know how much control applications have over the thread affinity in that case?). |
0a02920
to
2593679
Compare
Makes logging timing information about a block of code easier.
2593679
to
dcef9a2
Compare
Separated |
There was a problem hiding this 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
Thanks, ACK dcef9a2 |
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
@@ -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(); |
There was a problem hiding this comment.
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
?
There was a problem hiding this comment.
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.
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
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
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
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
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
merge bitcoin#17925, bitcoin#16805: auxilliary backports
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.