perf: don't use boost time in validation.cpp #5616

PastaPastaPasta · 2023-10-16T16:37:16Z

(over a 13 minute segment of reindex) boost time took about 9+9+9 = 27%!! of total cycles!!!

During the same time segment, GetTimeMicros() used roughly 0.2% of total cycles! (even though it's used a lot more)

Over my entire roughly 40 minute profiling session, boost time appears to use about 6% of cycles; still too much, while GetTimeMicros used about 0.4%

Checklist:

Go over all the following points, and put an x in all the boxes that apply.

I have performed a self-review of my own code
I have commented my code, particularly in hard-to-understand areas
I have added or updated relevant unit/integration/functional/e2e tests
I have made corresponding changes to the documentation
I have assigned this pull request to a milestone (for repository code-owners and collaborators only)

src/validation.cpp

knst · 2023-10-16T20:00:40Z

src/validation.cpp

@@ -944,7 +942,7 @@ bool MemPoolAccept::Finalize(ATMPArgs& args, Workspace& ws)

 bool MemPoolAccept::AcceptSingleTransaction(const CTransactionRef& ptx, ATMPArgs& args)
 {
-    boost::posix_time::ptime start = boost::posix_time::microsec_clock::local_time();
+    auto start = GetTimeMicros();


imo better to switch just to std::chrono::microseconds rather than int64_t counter.

Helper GetTimeMicro has been introduced back in 2014 year:

+int64_t GetTimeMicros() +{ + return (boost::posix_time::ptime(boost::posix_time::microsec_clock::universal_time()) - + boost::posix_time::ptime(boost::gregorian::date(1970,1,1))).total_microseconds(); +}

But now wrapper over std::chrono is useful only for the old already written code; it has std::chrono inside since this commit a3bc3fd

int64_t GetTimeMicros() { - int64_t now = (boost::posix_time::microsec_clock::universal_time() - - boost::posix_time::ptime(boost::gregorian::date(1970,1,1))).total_microseconds(); + int64_t now = std::chrono::time_point_cast<std::chrono::microseconds>(std::chrono::system_clock::now()).time_since_epoch().count(); assert(now > 0); return now; }

Let's use std::chrono directly instead wrappers.

Btw, conceptually ACK, bitcoin switched from posix time to std::chrono long time ago, for example this PR: https://github.com/bitcoin/bitcoin/pull/18234/files

Suggested change

auto start = GetTimeMicros();

auto start = std::chrono::system_clock::now()

(over a 13 minute segment of reindex) boost time took about 9+9+9 = 27%!! of total cycles!!! During the same time segment, GetTimeMicros() used roughly 0.2% of total cycles! (even though it's used a lot more) Over my entire roughly 40 minute profiling session, boost time appears to use about 6% of cycles; still too much, while GetTimeMicros used about 0.4% (now using std::chrono directly)

PastaPastaPasta · 2023-10-17T15:10:55Z

Updated to std::chrono directly; should be (very marginally) faster also as we avoid an assert here now inside of GetTimeMicros()

UdjinM6 · 2023-10-17T17:14:06Z

CI fails

knst

several nits

knst · 2023-10-17T17:09:06Z

src/validation.cpp

@@ -1498,7 +1496,7 @@ void InitScriptExecutionCache() {
 */
 bool CheckInputScripts(const CTransaction& tx, TxValidationState &state, const CCoinsViewCache &inputs, unsigned int flags, bool cacheSigStore, bool cacheFullScriptStore, PrecomputedTransactionData& txdata, std::vector<CScriptCheck> *pvChecks) EXCLUSIVE_LOCKS_REQUIRED(cs_main)
 {
-    boost::posix_time::ptime start = boost::posix_time::microsec_clock::local_time();
+    auto start = std::chrono::system_clock::now();


nit: maybe const here (and similar places)?

Suggested change

auto start = std::chrono::system_clock::now();

const auto start = std::chrono::system_clock::now();

knst · 2023-10-17T17:12:02Z

src/validation.cpp

-    statsClient.timing("CheckInputScripts_ms", diff.total_milliseconds(), 1.0f);
+    auto finish = std::chrono::system_clock::now();
+    auto diff = finish - start;
+    statsClient.timing("CheckInputScripts_ms", count_microseconds(diff), 1.0f);


nit: doesn't seems as finish is used anywhere else

- auto finish = std::chrono::system_clock::now(); - auto diff = finish - start; + const auto diff = std::chrono::system_clock::now() - start; statsClient.timing("CheckInputScripts_ms", count_microseconds(diff), 1.0f);

knst · 2023-10-17T17:12:59Z

src/validation.cpp

-    statsClient.timing("CheckInputScripts_ms", diff.total_milliseconds(), 1.0f);
+    auto finish = std::chrono::system_clock::now();
+    auto diff = finish - start;
+    statsClient.timing("CheckInputScripts_ms", count_microseconds(diff), 1.0f);


Suggested change

statsClient.timing("CheckInputScripts_ms", count_microseconds(diff), 1.0f);

statsClient.timing("CheckInputScripts_µs", count_microseconds(diff), 1.0f);

or

Suggested change

statsClient.timing("CheckInputScripts_ms", count_microseconds(diff), 1.0f);

statsClient.timing("CheckInputScripts_us", count_microseconds(diff), 1.0f);

UPD: should be miliseconds

validation.cpp: In member function ‘bool CChainState::ActivateBestChain(BlockValidationState&, std::shared_ptr<const CBlock>)’: validation.cpp:3203:67: error: could not convert ‘diff’ from ‘duration<[...],ratio<[...],1000000000>>’ to ‘duration<[...],ratio<[...],1000000>>’ 3203 | statsClient.timing("ActivateBestChain_ms", count_microseconds(diff), 1.0f);

knst · 2023-10-17T17:14:06Z

src/validation.cpp

-    statsClient.timing("ActivateBestChain_ms", diff.total_milliseconds(), 1.0f);
+    auto finish = std::chrono::system_clock::now();
+    auto diff = finish - start;
+    statsClient.timing("ActivateBestChain_ms", count_microseconds(diff), 1.0f);


Suggested change

statsClient.timing("ActivateBestChain_ms", count_microseconds(diff), 1.0f);

statsClient.timing("ActivateBestChain_us", count_microseconds(diff), 1.0f);

knst

(CI)

UdjinM6 · 2023-10-17T21:20:27Z

src/validation.cpp

-    statsClient.timing("AcceptToMemoryPool_ms", diff.total_milliseconds(), 1.0f);
+    auto finish = std::chrono::system_clock::now();
+    auto diff = finish - start;
+    statsClient.timing("AcceptToMemoryPool_us", count_microseconds(diff), 1.0f);


hmm... I think this is going to break stats on already running instances (if there any). Should keep string the same and use count_milliseconds instead imo. (same for similar changes below)

If I change it to count_milliseconds it doesn't compile; I'd probably need to duration_cast it to milliseconds or something like that. Do you think would be good?

We could do it like 4b57881 maybe?

Class std::chrono::steady_clock represents a monotonic clock. The time points of this clock cannot decrease as physical time moves forward and the time between ticks of this clock is constant. This clock is not related to wall clock time (for example, it can be time since last reboot), and is most suitable for measuring intervals.

https://en.cppreference.com/w/cpp/chrono/steady_clock

Yeah, that seems pretty reasonable to me

UdjinM6

utACK

knst

utACK

## Issue being fixed or feature implemented We went from milliseconds to microseconds for these silently in #5616 🙈 ## What was done? make it milliseconds again ## How Has This Been Tested? n/a ## Breaking Changes n/a ## Checklist: - [x] I have performed a self-review of my own code - [ ] I have commented my code, particularly in hard-to-understand areas - [ ] I have added or updated relevant unit/integration/functional/e2e tests - [ ] I have made corresponding changes to the documentation - [x] I have assigned this pull request to a milestone _(for repository code-owners and collaborators only)_

PastaPastaPasta added this to the 20 milestone Oct 16, 2023

PastaPastaPasta requested a review from UdjinM6 October 16, 2023 16:37

UdjinM6 requested changes Oct 16, 2023

View reviewed changes

src/validation.cpp Outdated Show resolved Hide resolved

src/validation.cpp Outdated Show resolved Hide resolved

src/validation.cpp Outdated Show resolved Hide resolved

knst reviewed Oct 16, 2023

View reviewed changes

PastaPastaPasta force-pushed the perf-boost-time branch from 7a9235e to 56c3e6d Compare October 17, 2023 15:09

PastaPastaPasta requested review from UdjinM6 and knst October 17, 2023 15:11

knst approved these changes Oct 17, 2023

View reviewed changes

knst requested changes Oct 17, 2023

View reviewed changes

fix: ms->us where needed

cecf1f5

UdjinM6 reviewed Oct 17, 2023

View reviewed changes

use steady_clock

e80cb7c

UdjinM6 approved these changes Oct 18, 2023

View reviewed changes

PastaPastaPasta requested a review from knst October 19, 2023 14:32

knst approved these changes Oct 19, 2023

View reviewed changes

PastaPastaPasta merged commit 59d6442 into dashpay:develop Oct 19, 2023
8 checks passed

UdjinM6 mentioned this pull request Oct 20, 2023

fix: ConnectBlock/Tip stats are in ms (5616 follow-up) #5629

Merged

5 tasks

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

perf: don't use boost time in validation.cpp #5616

perf: don't use boost time in validation.cpp #5616

PastaPastaPasta commented Oct 16, 2023

knst Oct 16, 2023 •

edited

Loading

PastaPastaPasta commented Oct 17, 2023

UdjinM6 commented Oct 17, 2023

knst left a comment •

edited

Loading

knst Oct 17, 2023

knst Oct 17, 2023

knst Oct 17, 2023 •

edited

Loading

knst Oct 17, 2023

knst left a comment

UdjinM6 Oct 17, 2023

PastaPastaPasta Oct 17, 2023

UdjinM6 Oct 17, 2023

PastaPastaPasta Oct 18, 2023

UdjinM6 left a comment

knst left a comment

	auto start = GetTimeMicros();
	auto start = std::chrono::system_clock::now()

	auto start = std::chrono::system_clock::now();
	const auto start = std::chrono::system_clock::now();

	statsClient.timing("CheckInputScripts_ms", count_microseconds(diff), 1.0f);
	statsClient.timing("CheckInputScripts_µs", count_microseconds(diff), 1.0f);

	statsClient.timing("CheckInputScripts_ms", count_microseconds(diff), 1.0f);
	statsClient.timing("CheckInputScripts_us", count_microseconds(diff), 1.0f);

	statsClient.timing("ActivateBestChain_ms", count_microseconds(diff), 1.0f);
	statsClient.timing("ActivateBestChain_us", count_microseconds(diff), 1.0f);

perf: don't use boost time in validation.cpp #5616

perf: don't use boost time in validation.cpp #5616

Conversation

PastaPastaPasta commented Oct 16, 2023

Checklist:

knst Oct 16, 2023 • edited Loading

Choose a reason for hiding this comment

PastaPastaPasta commented Oct 17, 2023

UdjinM6 commented Oct 17, 2023

knst left a comment • edited Loading

Choose a reason for hiding this comment

knst Oct 17, 2023

Choose a reason for hiding this comment

knst Oct 17, 2023

Choose a reason for hiding this comment

knst Oct 17, 2023 • edited Loading

Choose a reason for hiding this comment

knst Oct 17, 2023

Choose a reason for hiding this comment

knst left a comment

Choose a reason for hiding this comment

UdjinM6 Oct 17, 2023

Choose a reason for hiding this comment

PastaPastaPasta Oct 17, 2023

Choose a reason for hiding this comment

UdjinM6 Oct 17, 2023

Choose a reason for hiding this comment

PastaPastaPasta Oct 18, 2023

Choose a reason for hiding this comment

UdjinM6 left a comment

Choose a reason for hiding this comment

knst left a comment

Choose a reason for hiding this comment

knst Oct 16, 2023 •

edited

Loading

knst left a comment •

edited

Loading

knst Oct 17, 2023 •

edited

Loading