Fixup some stale comments:
60 seconds is outdated. It should say 120 seconds. However, just clarify that there is a timeout.TODO, but keep the advice.Also, remove an unnecessary time.sleep(1). If there is a need for it, a comment should explain why.
The following sections might be updated with supplementary metadata relevant to reviewers and maintainers.
See the guideline for information on the review process.
| Type | Reviewers |
|---|---|
| ACK | l0rinc |
| Stale ACK | willcl-ark |
If your review is incorrectly listed, please copy-paste <!–meta-tag:bot-skip–> into the comment that the bot should ignore.
76@@ -77,7 +77,7 @@ def restart_node(self, node_index, expected_tip):
77 """Start up a given node id, wait for the tip to reach the given block hash, and calculate the utxo hash.
78
79 Exceptions on startup should indicate node crash (due to -dbcrashratio), in which case we try again. Give up
The comment explicitly states: https://github.com/bitcoin/bitcoin/blob/fa5f29774872d18febc0df38831a6e45f3de69cc/test/functional/feature_dbcrash.py#L85
So it’s also not completely accurate to claim it’s only startup:
0 Exceptions during startup or subsequent RPC calls should indicate node crash (due to -dbcrashratio), in which case we try again. Give up
92@@ -93,12 +93,11 @@ def restart_node(self, node_index, expected_tip):
93 # should raise an exception if bitcoind doesn't exit.
94 self.wait_for_node_exit(node_index, timeout=10)
95 self.crashed_on_restart += 1
96- time.sleep(1)
Also, remove an unused time.sleep(1)
This seems to be a simple retry backoff between attempts, are you suggesting the startup should just succeed without any grace period and it just slows down execution? Let me check that…
I tried the disabledextended test locally, it’s is insanely slow on my machine:
0TEST | STATUS | DURATION
1
2feature_dbcrash.py | ✓ Passed | 522 s
and without the sleep it may be a bit faster (or maybe it’s just a fluke):
0TEST | STATUS | DURATION
1
2feature_dbcrash.py | ✓ Passed | 516 s
Measured it properly on an Rpi5 it’s basically the same speed with or without the sleep:
0COMMITS="5f6bfa3649c3301a7c5f244450ba43e1287eb8e7 ffff716dc4271eec6de29149205c093898333a11 dd714ebaff41fb912baa4870ab1b68ae497dccec"; \
1CC=gcc; CXX=g++; \
2(echo ""; for c in $COMMITS; do git fetch -q origin $c && git log -1 --pretty='%h %s' $c || exit 1; done) && \
3(echo "" && echo "$(date -I) | functional tests | $(hostname) | $(uname -m) | $(lscpu | grep 'Model name' | head -1 | cut -d: -f2 | xargs) | $(nproc) cores | $(free -h | awk '/^Mem:/{print $2}') RAM"; echo "") && \
4hyperfine \
5 --sort command \
6 --runs 3 \
7 --parameter-list COMMIT ${COMMITS// /,} \
8 --prepare "git checkout {COMMIT} && git clean -fxd && git reset --hard && \
9 cmake -B build -G Ninja -DCMAKE_BUILD_TYPE=Release && ninja -C build -j$(nproc)" \
10 "build/test/functional/test_runner.py feature_dbcrash"
5f6bfa3649 Merge bitcoin/bitcoin#34057: test: add tests for cluster chunks ffff716dc4 Fixup TODO comment in feature_dbcrash.py; remove unused sleep dd714ebaff test: only call gettxoutsetinfo when nodei_utxo_hash is calculated
0Benchmark 1: build/test/functional/test_runner.py feature_dbcrash (COMMIT = 5f6bfa3649c3301a7c5f244450ba43e1287eb8e7)
1 Time (mean ± σ): 2829.872 s ± 33.415 s [User: 2796.205 s, System: 87.889 s]
2 Range (min … max): 2792.286 s … 2856.218 s 3 runs
3
4Benchmark 2: build/test/functional/test_runner.py feature_dbcrash (COMMIT = ffff716dc4271eec6de29149205c093898333a11)
5 Time (mean ± σ): 2832.783 s ± 8.394 s [User: 2824.483 s, System: 88.198 s]
6 Range (min … max): 2823.098 s … 2837.963 s 3 runs
7
8Benchmark 3: build/test/functional/test_runner.py feature_dbcrash (COMMIT = dd714ebaff41fb912baa4870ab1b68ae497dccec)
9 Time (mean ± σ): 2794.477 s ± 57.106 s [User: 2765.743 s, System: 87.325 s]
10 Range (min … max): 2730.499 s … 2840.294 s 3 runs
0diff --git a/test/functional/feature_dbcrash.py b/test/functional/feature_dbcrash.py
1--- a/test/functional/feature_dbcrash.py (revision 5f6bfa3649c3301a7c5f244450ba43e1287eb8e7)
2+++ b/test/functional/feature_dbcrash.py (revision dd714ebaff41fb912baa4870ab1b68ae497dccec)
3@@ -130,7 +130,7 @@
4 If any nodes crash while updating, we'll compare utxo hashes to
5 ensure recovery was successful."""
6
7- node3_utxo_hash = self.nodes[3].gettxoutsetinfo()['hash_serialized_3']
8+ node3_utxo_hash = None
9
10 # Retrieve all the blocks from node3
11 blocks = []
12@@ -165,6 +165,8 @@
13 # - we only update the utxo cache after a node restart, since flushing
14 # the cache is a no-op at that point
15 if nodei_utxo_hash is not None:
16+ if node3_utxo_hash is None:
17+ node3_utxo_hash = self.nodes[3].gettxoutsetinfo()['hash_serialized_3']
18 self.log.debug(f"Checking txoutsetinfo matches for node {i}")
19 assert_equal(nodei_utxo_hash, node3_utxo_hash)
0diff --git a/test/functional/feature_dbcrash.py b/test/functional/feature_dbcrash.py
1--- a/test/functional/feature_dbcrash.py (revision dcc66439dd549d49af814a2560b9733aedd9b695)
2+++ b/test/functional/feature_dbcrash.py (date 1770714020785)
3@@ -93,7 +93,7 @@
4 # should raise an exception if bitcoind doesn't exit.
5 self.wait_for_node_exit(node_index, timeout=10)
6 self.crashed_on_restart += 1
7- time.sleep(1)
8+ raise Exception("time.sleep(1)")
9
10 # If we got here, bitcoind isn't coming back up on restart. Could be a
11 # bug in bitcoind, or we've gotten unlucky with our dbcrash ratio --
indicates the sleep is not “unused” just possibly “unnecessary”, if you reword that, I’m happy to ack.
0Traceback (most recent call last):
1 File "/Users/lorinc/CLionProjects/bitcoin/test/functional/test_framework/test_framework.py", line 142, in main
2 self.run_test()
3 ~~~~~~~~~~~~~^^
4 File "/Users/lorinc/CLionProjects/bitcoin/build/test/functional/feature_dbcrash.py", line 263, in run_test
5 self.sync_node3blocks(block_hashes)
6 ~~~~~~~~~~~~~~~~~~~~~^^^^^^^^^^^^^^
7 File "/Users/lorinc/CLionProjects/bitcoin/build/test/functional/feature_dbcrash.py", line 152, in sync_node3blocks
8 nodei_utxo_hash = self.restart_node(i, block_hash)
9 File "/Users/lorinc/CLionProjects/bitcoin/build/test/functional/feature_dbcrash.py", line 96, in restart_node
10 raise Exception("time.sleep(1)")
11Exception: time.sleep(1)
Also, please consider the gettxoutsetinfo patch above, it ain’ much but at least it’s measurable.
As this is inside the loop I did wonder if we might get into a tight restart loop without it. But the crash can only happen during a flush (not during startup), which takes some time on restart+recovery. With -dbcache=4 and -dbcrashratio=8 it’s not obvious this always takes more than a second. Previously the sleep was bounding us to at most <120 restarts…
Anyway, I think it’s OK for a test, and OK as you suggest to revert (and comment) it if necessary.
indicates the sleep is not “unused” just possibly “unnecessary”, if you reword that, I’m happy to ack.
thx, done.
Also, please consider the
gettxoutsetinfopatch above, it ain’ much but at least it’s measurable.
I don’t think it is measurable. The error bars overlap with the mean
I don’t think it is measurable.
yes, it’s insignificant (~1%), but I’d argue it’s measurable, we just need to run it multiple times to get reliable results. But it’s not important, was just surprised how slow it was.
ACK ffff716dc4271eec6de29149205c093898333a11
Looks OK to me. Left a non-blocking comment about the unused timeout.
Co-authored-by: l0rinc <pap.lorinc@gmail.com>