Add log timings

chia/consensus/block_body_validation.py

@@ -1,5 +1,6 @@
 import collections
 import logging
+import time
 from typing import Dict, List, Optional, Set, Tuple, Union, Callable
 
 from chiabip158 import PyBIP158
@@ -59,10 +60,12 @@ async def validate_block_body(
     the result of running the generator with the previous generators refs. It is only present for transaction
     blocks which have spent coins.
     """
+    start = time.time()
     if isinstance(block, FullBlock):
         assert height == block.height
     prev_transaction_block_height: uint32 = uint32(0)
 
+
     # 1. For non transaction-blocs: foliage block, transaction filter, transactions info, and generator must
     # be empty. If it is a block but not a transaction block, there is no body to validate. Check that all fields are
     # None
@@ -82,7 +85,8 @@ async def validate_block_body(
             return Err.NOT_BLOCK_BUT_HAS_DATA, None
 
         return None, None  # This means the block is valid
-
+    log.warning(f"block_body_validation timings 1: {time.time() - start}")
+    start = time.time()
     # All checks below this point correspond to transaction blocks
     # 2. For blocks, foliage block, transactions info must not be empty
     if block.foliage_transaction_block is None or block.transactions_info is None:
@@ -150,7 +154,8 @@ async def validate_block_body(
 
     if len(block.transactions_info.reward_claims_incorporated) != len(expected_reward_coins):
         return Err.INVALID_REWARD_COINS, None
-
+    log.warning(f"block_body_validation timings 2: {time.time() - start}")
+    start = time.time()
     removals: List[bytes32] = []
     coinbase_additions: List[Coin] = list(expected_reward_coins)
     additions: List[Coin] = []
@@ -191,13 +196,16 @@ async def validate_block_body(
             return Err.TOO_MANY_GENERATOR_REFS, None
         if any([index >= height for index in block.transactions_generator_ref_list]):
             return Err.FUTURE_GENERATOR_REFS, None
-
+    log.warning(f"block_body_validation timings 3: {time.time() - start}")
+    start = time.time()
     if block.transactions_generator is not None:
         # Get List of names removed, puzzles hashes for removed coins and conditions created
 
         assert npc_result is not None
         cost = calculate_cost_of_program(block.transactions_generator, npc_result, constants.COST_PER_BYTE)
         npc_list = npc_result.npc_list
+        log.warning(f"block_body_validation timings 4: {time.time() - start}")
+        start = time.time()
 
         # 7. Check that cost <= MAX_BLOCK_COST_CLVM
         log.debug(
@@ -244,7 +252,8 @@ async def validate_block_body(
     )
     if root_error:
         return root_error, None
-
+    log.warning(f"block_body_validation timings 5: {time.time() - start}")
+    start = time.time()
     # 12. The additions and removals must result in the correct filter
     byte_array_tx: List[bytes32] = []
 
@@ -286,7 +295,8 @@ async def validate_block_body(
     # timestamp of the block in which it was confirmed
     additions_since_fork: Dict[bytes32, Tuple[Coin, uint32, uint64]] = {}  # This includes coinbase additions
     removals_since_fork: Set[bytes32] = set()
-
+    log.warning(f"block_body_validation timings 6: {time.time() - start}")
+    start = time.time()
     # For height 0, there are no additions and removals before this block, so we can skip
     if height > 0:
         # First, get all the blocks in the fork > fork_h, < block.height
@@ -342,7 +352,8 @@ async def validate_block_body(
                 break
             curr = reorg_blocks[curr.height - 1]
             assert curr is not None
-
+    log.warning(f"block_body_validation timings 7: {time.time() - start}")
+    start = time.time()
     removal_coin_records: Dict[bytes32, CoinRecord] = {}
     for rem in removals:
         if rem in additions_dic:
@@ -388,7 +399,8 @@ async def validate_block_body(
             if rem in removals_since_fork:
                 # This coin was spent in the fork
                 return Err.DOUBLE_SPEND_IN_FORK, None
-
+    log.warning(f"block_body_validation timings 8: {time.time() - start}")
+    start = time.time()
     removed = 0
     for unspent in removal_coin_records.values():
         removed += unspent.coin.amount
@@ -446,7 +458,8 @@ async def validate_block_body(
 
     # create hash_key list for aggsig check
     pairs_pks, pairs_msgs = pkm_pairs(npc_list, constants.AGG_SIG_ME_ADDITIONAL_DATA)
-
+    log.warning(f"block_body_validation timings 9: {time.time() - start}")
+    start = time.time()
     # 22. Verify aggregated signature
     # TODO: move this to pre_validate_blocks_multiprocessing so we can sync faster
     if not block.transactions_info.aggregated_signature:
@@ -462,5 +475,6 @@ async def validate_block_body(
         pairs_pks, pairs_msgs, block.transactions_info.aggregated_signature, force_cache
     ):
         return Err.BAD_AGGREGATE_SIGNATURE, None
-
+    log.warning(f"block_body_validation timings 10: {time.time() - start}")
+    start = time.time()
     return None, npc_result