Fix pause timer calculation. #130

heifner · 2022-04-26T00:45:56Z

Fix for the long-standing issue with not correctly accounting for WASM load times. We pause the billing timer when loading WASMs. However, we were not using the correct deadline after restarting the paused timer which sometimes would cause the transaction to fail even though it had not actually run its allotted time.

Previous code:
deadline was the user provided deadline which was either the transaction deadline calculated from max-transaction-time or the wall clock block deadline passed in from the producer_plugin. When setting the timer again, after pausing, it would restrict the run time to the deadline even if the deadline was the original transaction deadline as opposed to the block deadline. This would restrict the amount of time the transaction was allowed to run on "first call" (when WASM loaded). The transaction could then fail because it ran "too long" even though it had not actually executed for max-transaction-time.

Now:
Node configurable wall clock block deadline (configurable via cpu-effort-percent) and node configurable max-transaction-time are now provided to the transaction processor (transaction_context) so when pausing for WASM load times, the wall clock block deadline can be honored separately from the max-transaction-time.

swatanabe

This could use more explanation. Even now, I don't understand what's wrong with the old code and how this change fixes it.

libraries/chain/transaction_context.cpp

unittests/api_tests.cpp

heifner · 2022-04-26T12:56:15Z

This could use more explanation. Even now, I don't understand what's wrong with the old code and how this change fixes it.

Previous code:
deadline was the user provided deadline which often is the transaction deadline passed in from the producer_plugin. When setting the timer again to this deadline it did not add in additional time for when it was paused. This restricts the amount of time the transaction is allowed to run on "first call" (when WASM loaded).

I added this to the description.

swatanabe · 2022-04-26T13:20:31Z

Extending the deadline from producer_plugin is not correct. It's reasonable if the deadline is from --max-transaction-time, but not if it's because we need to ship out a block on time.

heifner · 2022-04-26T13:22:08Z

Extending the deadline from producer_plugin is not correct. It's reasonable if the deadline is from --max-transaction-time, but not if it's because we need to ship out a block on time.

That is why it checks block_cpu_deadline.

swatanabe · 2022-04-26T13:25:15Z

block_cpu_deadline doesn't include the pauses from previous transactions does it?

heifner · 2022-04-26T13:27:20Z

block_cpu_deadline doesn't include the pauses from previous transactions does it?

It does not, it is the deadline calculated at the start of the transaction. We want to honor that deadline regardless how long we are paused. We want to make sure we ship a block out on time. The block_cpu_usage_exceeded will cause the producer_plugin to try the transaction in the next block.

swatanabe · 2022-04-26T13:36:00Z

I agree that respecting block_cpu_deadline is necessary, but the block deadline coming from producer plugin is more restrictive and we're discarding some of that by using only block_cpu_deadline. block_cpu_deadline is mostly objective, allowing only this transaction to decrease the available time subjectively. caller_deadline is a wall-clock time limit and includes all time since the start of the block, billed or not.

heifner · 2022-04-26T13:44:37Z

I agree that respecting block_cpu_deadline is necessary, but the block deadline coming from producer plugin is more restrictive and we're discarding some of that by using only block_cpu_deadline. block_cpu_deadline is mostly objective, allowing only this transaction to decrease it subjectively. caller_deadline is a wall-clock time limit and includes all time since the start of the block, billed or not.

Often the producer plugin deadline is less restrictive because it is wall clock and not block cpu, but you are correct that it could be more restrictive, especially if cpu effort is set low. I was trying to avoid passing into push_transaction an indication if this was a block deadline.

I do need to honor that however. I'll put in some more work on this. Thanks for your thorough review.

swatanabe · 2022-04-26T13:55:10Z

Summary of the problem as I understand it:

transaction_checktime_timer manages two distinct deadlines, a wall clock deadline, and a billing clock deadline
the limit set by the command line option --max-transaction-time is incorrectly treated as a wall-clock limit.

heifner · 2022-04-26T13:59:40Z

Summary of the problem as I understand it:

transaction_checktime_timer manages two distinct deadlines, a wall clock deadline, and a billing clock deadline

the limit set by the command line option --max-transaction-time is incorrectly treated as a wall-clock limit.

Nicely stated. I'll look at this some more, but maybe the correct thing would be to provide push_transaction with the max-transaction-time and a block deadline and then let transaction_context do all this calculation. This would simplify the producer_plugin and move all this into transaction_context.

…or the wall clock block deadline. Pass both block_deadline and max_transaction_time to transaction_context so it can honor both of these correctly.

…line as calling before is a no-op.

libraries/chain/transaction_context.cpp

libraries/chain/include/eosio/chain/transaction_context.hpp

libraries/chain/transaction_context.cpp

plugins/producer_plugin/include/eosio/producer_plugin/subjective_billing.hpp

unittests/api_tests.cpp

swatanabe · 2022-05-06T13:46:59Z

unittests/api_tests.cpp

+   BOOST_CHECK( cpu_limit <= 150'000 );
+
+   // Verify that the restriction on the transaction of 24'999 is honored even though there is wall clock time to
+   // load the wasm. If this test fails it is possible that the wasm loaded faster or slower than expected.


I think we need two tests

The 24999 limit is extended by a pause (this check)

The block deadline is not extended by a pause (I don't see this)

Oh, and one more:

The cpu limit is is originally before the block deadline, but is extended past it by a pause.

Added tests.

- Add additional tests.

swatanabe · 2022-05-09T13:00:38Z

unittests/api_tests.cpp

+   // If this check fails but duration is >= 25'000 (previous check did not fail), then the check here is likely
+   // because it took longer than 2.5 ms for checktime to trigger, trace to be created, and to get to the now() call.
+   // Timer is paused during WASM load, so checktime will not trigger until after WASM is loaded.
+   BOOST_CHECK( dur < 150'000 ); // should not run to max_transaction_time


This seems too long and does not match the comment of 2.5 ms. For this test, I would expect to see:

The base timeout (25 ms) is an upper bound on the wasm load time

The expected duration is an upper bound on timeout + checktime overhead

The expected duration is a lower bound on timeout + WASM compile time (not satisfied)

A high value here means that this test will always pass even if the block deadline is extended.

If random noise makes this test too flaky, then we might have to give up on testing this condition.

I separated this test into two. One which gives time for the WASM to load but is limited to block deadline. This test I tweaked the values and comments to more closely reflect this particular test. Turns out on my machine I was seeing WASM load times of 35ms.

swatanabe · 2022-05-10T11:16:23Z

unittests/api_tests.cpp

@@ -1000,8 +1000,8 @@ BOOST_AUTO_TEST_CASE(checktime_pause_max_trx_cpu_extended_test) { try {
   // This assumes that loading the WASM takes at least 1.5 ms
   // If this check fails but duration is >= 24'999 (previous check did not fail), then the check here is likely
   // because WASM took less than 1.5 ms to load.
-   BOOST_CHECK( dur > 26'500 );
-   BOOST_CHECK( dur < 150'000 ); // Should not run to block_cpu_usage deadline
+   BOOST_CHECK_MESSAGE( dur > 26'500, "elapsed " << std::to_string(dur) << "us" );


BOOST_TEST will print dur automatically.

api_tests.cpp(1102): error: in "api_tests/checktime_pause_block_deadline_not_extended_test": check dur < 30'000 has failed It wasn't for me.

Odd. That's what I'd expect from BOOST_CHECK. BOOST_TEST is supposed to decompose the expression and has been the recommended macro to use for a long time.

Maybe you meant the to_string is not needed. Removed the to_string calls.

mandel/unittests/api_tests.cpp(1003): error: in "api_tests/checktime_pause_max_trx_cpu_extended_test": check dur < 26'500 has failed [28130 >= 26500]

BOOST_TEST( dur < 26'500 );

How did you get it to print that? Some special command line arg to unit_test?

Oh, you said BOOST_TEST. Ah, need to switch to using that in the future. Thanks.

Fix pause timer calculation.

cd4017a

heifner requested a review from arhag April 26, 2022 00:46

Do not limit checktime to int.

bdf5ebc

swatanabe reviewed Apr 26, 2022

View reviewed changes

Merge remote-tracking branch 'origin/main' into fix-pause-timer

7d6abb8

heifner mentioned this pull request Apr 30, 2022

Added checks for special cases where to not apply txn deadline #163

Closed

heifner added 3 commits April 29, 2022 20:16

The transaction_context deadline was either the transaction deadline …

bc0b0d1

…or the wall clock block deadline. Pass both block_deadline and max_transaction_time to transaction_context so it can honor both of these correctly.

Revert back to infinite deadline since this is explicit bill.

4f08b98

Backport EOSIO/eos PR#10943. Move checktime() call after setting dead…

5e43ffb

…line as calling before is a no-op.

heifner requested a review from swatanabe May 4, 2022 17:56

swatanabe reviewed May 6, 2022

View reviewed changes

heifner mentioned this pull request May 6, 2022

fix test stability in api_tests.cpp #194

Closed

heifner added 2 commits May 6, 2022 20:24

- Revert back to using deadline_exception for block wall clock deadline.

658707b

- Add additional tests.

- Disable pause tests for eos_vm_oc

ae83662

heifner requested a review from swatanabe May 7, 2022 20:19

swatanabe reviewed May 9, 2022

View reviewed changes

Add additional test and improve test

2542d25

heifner requested a review from swatanabe May 10, 2022 02:02

swatanabe approved these changes May 10, 2022

View reviewed changes

Remove unneeded to_string calls.

1fedf33

swatanabe approved these changes May 10, 2022

View reviewed changes

heifner merged commit 8cea166 into main May 10, 2022

heifner deleted the fix-pause-timer branch May 10, 2022 12:28

This was referenced May 10, 2022

Remove Unused Variable in transaction_context::init() #201

Closed

deadline timer not correctly accounting for pause during WASM load #216

Closed

heifner added the OCI OCI working this issue... label May 12, 2022

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Fix pause timer calculation. #130

Fix pause timer calculation. #130

heifner commented Apr 26, 2022 •

edited

Loading

swatanabe left a comment

heifner commented Apr 26, 2022 •

edited

Loading

swatanabe commented Apr 26, 2022

heifner commented Apr 26, 2022

swatanabe commented Apr 26, 2022

heifner commented Apr 26, 2022

swatanabe commented Apr 26, 2022 •

edited

Loading

heifner commented Apr 26, 2022 •

edited

Loading

swatanabe commented Apr 26, 2022

heifner commented Apr 26, 2022 •

edited

Loading

swatanabe May 6, 2022

swatanabe May 6, 2022

heifner May 7, 2022

swatanabe May 9, 2022

swatanabe May 9, 2022 •

edited

Loading

heifner May 10, 2022

swatanabe May 10, 2022

heifner May 10, 2022

swatanabe May 10, 2022

heifner May 10, 2022

swatanabe May 10, 2022 •

edited

Loading

swatanabe May 10, 2022

heifner May 10, 2022

heifner May 10, 2022

Fix pause timer calculation. #130

Fix pause timer calculation. #130

Conversation

heifner commented Apr 26, 2022 • edited Loading

swatanabe left a comment

Choose a reason for hiding this comment

heifner commented Apr 26, 2022 • edited Loading

swatanabe commented Apr 26, 2022

heifner commented Apr 26, 2022

swatanabe commented Apr 26, 2022

heifner commented Apr 26, 2022

swatanabe commented Apr 26, 2022 • edited Loading

heifner commented Apr 26, 2022 • edited Loading

swatanabe commented Apr 26, 2022

heifner commented Apr 26, 2022 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

swatanabe May 9, 2022 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

swatanabe May 10, 2022 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

heifner commented Apr 26, 2022 •

edited

Loading

heifner commented Apr 26, 2022 •

edited

Loading

swatanabe commented Apr 26, 2022 •

edited

Loading

heifner commented Apr 26, 2022 •

edited

Loading

heifner commented Apr 26, 2022 •

edited

Loading

swatanabe May 9, 2022 •

edited

Loading

swatanabe May 10, 2022 •

edited

Loading