extend Block validation timing logs to measure just the CLVM and conditions (#17275)

extend Block validation timing logs to measure just the CLVM and condition parsing
This commit is contained in:
Arvid Norberg 2024-01-19 21:12:44 +01:00 committed by GitHub
parent e26c2de739
commit 28942934ff
No known key found for this signature in database
GPG Key ID: B5690EEEBB952194
8 changed files with 57 additions and 28 deletions

View File

@ -728,7 +728,7 @@ class Blockchain(BlockchainInterface):
required_iters, error = await self.validate_unfinished_block_header(block, skip_overflow_ss_validation)
if error is not None:
return PreValidationResult(uint16(error.value), None, None, False)
return PreValidationResult(uint16(error.value), None, None, False, uint32(0))
prev_height = (
-1
@ -753,9 +753,9 @@ class Blockchain(BlockchainInterface):
)
if error_code is not None:
return PreValidationResult(uint16(error_code.value), None, None, False)
return PreValidationResult(uint16(error_code.value), None, None, False, uint32(0))
return PreValidationResult(None, required_iters, cost_result, False)
return PreValidationResult(None, required_iters, cost_result, False, uint32(0))
async def pre_validate_blocks_multiprocessing(
self,

View File

@ -2,6 +2,7 @@ from __future__ import annotations
import asyncio
import logging
import time
import traceback
from concurrent.futures import Executor
from dataclasses import dataclass
@ -45,6 +46,7 @@ class PreValidationResult(Streamable):
required_iters: Optional[uint64] # Iff error is None
npc_result: Optional[NPCResult] # Iff error is None and block is a transaction block
validated_signature: bool
timing: uint32 # the time (in milliseconds) it took to pre-validate the block
def batch_pre_validate_blocks(
@ -70,6 +72,7 @@ def batch_pre_validate_blocks(
if full_blocks_pickled is not None:
for i in range(len(full_blocks_pickled)):
try:
validation_start = time.monotonic()
block: FullBlock = FullBlock.from_bytes(full_blocks_pickled[i])
tx_additions: List[Coin] = []
removals: List[bytes32] = []
@ -97,7 +100,12 @@ def batch_pre_validate_blocks(
)
removals, tx_additions = tx_removals_and_additions(npc_result.conds)
if npc_result is not None and npc_result.error is not None:
results.append(PreValidationResult(uint16(npc_result.error), None, npc_result, False))
validation_time = time.monotonic() - validation_start
results.append(
PreValidationResult(
uint16(npc_result.error), None, npc_result, False, uint32(validation_time * 1000)
)
)
continue
header_block = get_block_header(block, tx_additions, removals)
@ -132,17 +140,28 @@ def batch_pre_validate_blocks(
else:
successfully_validated_signatures = True
validation_time = time.monotonic() - validation_start
results.append(
PreValidationResult(error_int, required_iters, npc_result, successfully_validated_signatures)
PreValidationResult(
error_int,
required_iters,
npc_result,
successfully_validated_signatures,
uint32(validation_time * 1000),
)
)
except Exception:
error_stack = traceback.format_exc()
log.error(f"Exception: {error_stack}")
results.append(PreValidationResult(uint16(Err.UNKNOWN.value), None, None, False))
validation_time = time.monotonic() - validation_start
results.append(
PreValidationResult(uint16(Err.UNKNOWN.value), None, None, False, uint32(validation_time * 1000))
)
# In this case, we are validating header blocks
elif header_blocks_pickled is not None:
for i in range(len(header_blocks_pickled)):
try:
validation_start = time.monotonic()
header_block = HeaderBlock.from_bytes(header_blocks_pickled[i])
required_iters, error = validate_finished_header_block(
constants,
@ -155,11 +174,17 @@ def batch_pre_validate_blocks(
error_int = None
if error is not None:
error_int = uint16(error.code.value)
results.append(PreValidationResult(error_int, required_iters, None, False))
validation_time = time.monotonic() - validation_start
results.append(
PreValidationResult(error_int, required_iters, None, False, uint32(validation_time * 1000))
)
except Exception:
validation_time = time.monotonic() - validation_start
error_stack = traceback.format_exc()
log.error(f"Exception: {error_stack}")
results.append(PreValidationResult(uint16(Err.UNKNOWN.value), None, None, False))
results.append(
PreValidationResult(uint16(Err.UNKNOWN.value), None, None, False, uint32(validation_time * 1000))
)
return [bytes(r) for r in results]
@ -199,7 +224,7 @@ async def pre_validate_blocks_multiprocessing(
if blocks[0].height > 0:
curr = await block_records.get_block_record_from_db(blocks[0].prev_header_hash)
if curr is None:
return [PreValidationResult(uint16(Err.INVALID_PREV_BLOCK_HASH.value), None, None, False)]
return [PreValidationResult(uint16(Err.INVALID_PREV_BLOCK_HASH.value), None, None, False, uint32(0))]
num_sub_slots_to_look_for = 3 if curr.overflow else 2
header_hash = curr.header_hash
while (
@ -270,7 +295,7 @@ async def pre_validate_blocks_multiprocessing(
for i, block_i in enumerate(blocks):
if not block_record_was_present[i] and block_records.contains_block(block_hashes[i]):
block_records.remove_block_record(block_hashes[i])
return [PreValidationResult(uint16(Err.INVALID_POSPACE.value), None, None, False)]
return [PreValidationResult(uint16(Err.INVALID_POSPACE.value), None, None, False, uint32(0))]
required_iters: uint64 = calculate_iterations_quality(
constants.DIFFICULTY_CONSTANT_FACTOR,
@ -289,14 +314,14 @@ async def pre_validate_blocks_multiprocessing(
None,
)
except ValueError:
return [PreValidationResult(uint16(Err.INVALID_SUB_EPOCH_SUMMARY.value), None, None, False)]
return [PreValidationResult(uint16(Err.INVALID_SUB_EPOCH_SUMMARY.value), None, None, False, uint32(0))]
if block_rec.sub_epoch_summary_included is not None and wp_summaries is not None:
idx = int(block.height / constants.SUB_EPOCH_BLOCKS) - 1
next_ses = wp_summaries[idx]
if not block_rec.sub_epoch_summary_included.get_hash() == next_ses.get_hash():
log.error("sub_epoch_summary does not match wp sub_epoch_summary list")
return [PreValidationResult(uint16(Err.INVALID_SUB_EPOCH_SUMMARY.value), None, None, False)]
return [PreValidationResult(uint16(Err.INVALID_SUB_EPOCH_SUMMARY.value), None, None, False, uint32(0))]
# Makes sure to not override the valid blocks already in block_records
if not block_records.contains_block(block_rec.header_hash):
block_records.add_block_record(block_rec) # Temporarily add block to dict
@ -346,7 +371,7 @@ async def pre_validate_blocks_multiprocessing(
except ValueError:
return [
PreValidationResult(
uint16(Err.FAILED_GETTING_GENERATOR_MULTIPROCESSING.value), None, None, False
uint16(Err.FAILED_GETTING_GENERATOR_MULTIPROCESSING.value), None, None, False, uint32(0)
)
]
if block_generator is not None:

View File

@ -1288,7 +1288,8 @@ class FullNode:
self.log.log(
logging.WARNING if pre_validate_time > 10 else logging.DEBUG,
f"Block pre-validation time: {pre_validate_end - pre_validate_start:0.2f} seconds "
f"Block pre-validation: {pre_validate_end - pre_validate_start:0.2f}s "
f"CLVM: {sum([pvr.timing/1000.0 for pvr in pre_validation_results]):0.2f}s "
f"({len(blocks_to_validate)} blocks, start height: {blocks_to_validate[0].height})",
)
for i, block in enumerate(blocks_to_validate):
@ -1804,9 +1805,10 @@ class FullNode:
)
self.log.log(
logging.WARNING if validation_time > 2 else logging.DEBUG,
f"Block validation time: {validation_time:0.2f} seconds, "
f"pre_validation time: {pre_validation_time:0.2f} seconds, "
f"post-process time: {post_process_time:0.2f} seconds, "
f"Block validation: {validation_time:0.2f}s, "
f"pre_validation: {pre_validation_time:0.2f}s, "
f"CLVM: {pre_validation_results[0].timing/1000.0:0.2f}s, "
f"post-process: {post_process_time:0.2f}s, "
f"cost: {block.transactions_info.cost if block.transactions_info is not None else 'None'}"
f"{percent_full_str} header_hash: {header_hash.hex()} height: {block.height}",
)

View File

@ -7,7 +7,7 @@ from chia.consensus.blockchain import AddBlockResult, Blockchain
from chia.consensus.multiprocess_validation import PreValidationResult
from chia.types.full_block import FullBlock
from chia.util.errors import Err
from chia.util.ints import uint64
from chia.util.ints import uint32, uint64
async def check_block_store_invariant(bc: Blockchain):
@ -56,7 +56,7 @@ async def _validate_and_add_block(
await check_block_store_invariant(blockchain)
if skip_prevalidation:
results = PreValidationResult(None, uint64(1), None, False)
results = PreValidationResult(None, uint64(1), None, False, uint32(0))
else:
# Do not change this, validate_signatures must be False
pre_validation_results: List[PreValidationResult] = await blockchain.pre_validate_blocks_multiprocessing(

View File

@ -2543,7 +2543,7 @@ class TestBodyValidation:
height=softfork_height,
constants=bt.constants,
)
err = (await b.add_block(blocks[-1], PreValidationResult(None, uint64(1), npc_result, True)))[1]
err = (await b.add_block(blocks[-1], PreValidationResult(None, uint64(1), npc_result, True, uint32(0))))[1]
assert err in [Err.BLOCK_COST_EXCEEDS_MAX]
results: List[PreValidationResult] = await b.pre_validate_blocks_multiprocessing(
@ -2604,7 +2604,7 @@ class TestBodyValidation:
height=softfork_height,
constants=bt.constants,
)
result, err, _ = await b.add_block(block_2, PreValidationResult(None, uint64(1), npc_result, False))
result, err, _ = await b.add_block(block_2, PreValidationResult(None, uint64(1), npc_result, False, uint32(0)))
assert err == Err.INVALID_BLOCK_COST
# too low
@ -2629,7 +2629,7 @@ class TestBodyValidation:
height=softfork_height,
constants=bt.constants,
)
result, err, _ = await b.add_block(block_2, PreValidationResult(None, uint64(1), npc_result, False))
result, err, _ = await b.add_block(block_2, PreValidationResult(None, uint64(1), npc_result, False, uint32(0)))
assert err == Err.INVALID_BLOCK_COST
# too high
@ -2655,7 +2655,7 @@ class TestBodyValidation:
constants=bt.constants,
)
result, err, _ = await b.add_block(block_2, PreValidationResult(None, uint64(1), npc_result, False))
result, err, _ = await b.add_block(block_2, PreValidationResult(None, uint64(1), npc_result, False, uint32(0)))
assert err == Err.INVALID_BLOCK_COST
# when the CLVM program exceeds cost during execution, it will fail with

View File

@ -122,7 +122,9 @@ async def test_basic_store(
# Add/get unfinished block
for height, unf_block in enumerate(unfinished_blocks):
assert store.get_unfinished_block(unf_block.partial_hash) is None
store.add_unfinished_block(uint32(height), unf_block, PreValidationResult(None, uint64(123532), None, False))
store.add_unfinished_block(
uint32(height), unf_block, PreValidationResult(None, uint64(123532), None, False, uint32(0))
)
assert store.get_unfinished_block(unf_block.partial_hash) == unf_block
store.remove_unfinished_block(unf_block.partial_hash)
assert store.get_unfinished_block(unf_block.partial_hash) is None

View File

@ -15,7 +15,7 @@ from chia.full_node.hint_store import HintStore
from chia.simulator.block_tools import test_constants
from chia.types.blockchain_format.sized_bytes import bytes32
from chia.util.db_wrapper import DBWrapper2
from chia.util.ints import uint64
from chia.util.ints import uint32, uint64
from tests.util.temp_file import TempFile
@ -74,7 +74,7 @@ async def test_blocks(default_1000_blocks, with_hints: bool):
for block in blocks:
# await _validate_and_add_block(bc, block)
results = PreValidationResult(None, uint64(1), None, False)
results = PreValidationResult(None, uint64(1), None, False, uint32(0))
result, err, _ = await bc.add_block(block, results)
assert err is None

View File

@ -18,7 +18,7 @@ from chia.simulator.block_tools import test_constants
from chia.types.blockchain_format.sized_bytes import bytes32
from chia.types.full_block import FullBlock
from chia.util.db_wrapper import DBWrapper2
from chia.util.ints import uint64
from chia.util.ints import uint32, uint64
from tests.util.temp_file import TempFile
@ -141,7 +141,7 @@ async def make_db(db_file: Path, blocks: List[FullBlock]) -> None:
bc = await Blockchain.create(coin_store, block_store, test_constants, Path("."), reserved_cores=0)
for block in blocks:
results = PreValidationResult(None, uint64(1), None, False)
results = PreValidationResult(None, uint64(1), None, False, uint32(0))
result, err, _ = await bc.add_block(block, results)
assert err is None