add feature to profile just the block validation. This exposes what i…

…s actually going on while we validate blocks. Sometimes the block validation times are affected by other tasks that hog the CPU, blocking the main co-routine from being scheduled

chia/full_node/full_node.py

@@ -94,7 +94,7 @@
 from chia.util.limited_semaphore import LimitedSemaphore
 from chia.util.log_exceptions import log_exceptions
 from chia.util.path import path_from_root
-from chia.util.profiler import mem_profile_task, profile_task
+from chia.util.profiler import enable_profiler, mem_profile_task, profile_task
 from chia.util.safe_cancel_task import cancel_task_safe
 
 
@@ -292,6 +292,11 @@ async def manage(self) -> AsyncIterator[None]:
             if self.config.get("enable_profiler", False):
                 asyncio.create_task(profile_task(self.root_path, "node", self.log))
 
+            self.profile_block_validation = self.config.get("profile_block_validation", False)
+            if self.profile_block_validation:
+                profile_dir = path_from_root(self.root_path, "block-validation-profile")
+                profile_dir.mkdir(parents=True, exist_ok=True)
+
             if self.config.get("enable_memory_profiler", False):
                 asyncio.create_task(mem_profile_task(self.root_path, "node", self.log))
 
@@ -1712,7 +1717,9 @@ async def add_block(
                 return await self.add_block(new_block, peer)
         state_change_summary: Optional[StateChangeSummary] = None
         ppp_result: Optional[PeakPostProcessingResult] = None
-        async with self.blockchain.priority_mutex.acquire(priority=BlockchainMutexPriority.high):
+        async with self.blockchain.priority_mutex.acquire(priority=BlockchainMutexPriority.high), enable_profiler(
+            self.profile_block_validation
+        ) as pr:
             # After acquiring the lock, check again, because another asyncio thread might have added it
             if self.blockchain.contains_block(header_hash):
                 return None
@@ -1805,6 +1812,11 @@ async def add_block(
             f"{percent_full_str} header_hash: {header_hash} height: {block.height}",
         )
 
+        if validation_time > 2 and pr is not None:
+            pr.create_stats()
+            profile_dir = path_from_root(self.root_path, "block-validation-profile")
+            pr.dump_stats(profile_dir / f"{block.height}-{validation_time:0.1f}.profile")
+
         # This code path is reached if added == ADDED_AS_ORPHAN or NEW_TIP
         peak = self.blockchain.get_peak()
         assert peak is not None

chia/full_node/tx_processing_queue.py

@@ -50,7 +50,7 @@ async def put(self, tx: TransactionQueueEntry, peer_id: Optional[bytes32], high_
             if self._queue_dict[peer_id].qsize() < self.peer_size_limit:
                 self._queue_dict[peer_id].put(tx)
             else:
-                self.log.warning(f"Transaction queue full for peer {peer_id}")
+                self.log.warning(f"Transaction queue full for peer {peer_id} (sz: {self._queue_dict[peer_id].qsize()})")
                 raise TransactionQueueFull(f"Transaction queue full for peer {peer_id}")
         self._queue_length.release()  # increment semaphore to indicate that we have a new item in the queue
 

chia/util/initial-config.yaml

@@ -440,6 +440,11 @@ full_node:
   # analyze with chia/utils/profiler.py
   enable_profiler: False
 
+  # when enabled, each time a block is validated, the python profiler is
+  # engaged. If the validation takes more than 2 seconds, the profile is saved
+  # to disk, in the chia root/block-validation-profile
+  profile_block_validation: False
+
   enable_memory_profiler: False
 
   # this is a debug and profiling facility that logs all SQLite commands to a

chia/util/profiler.py

@@ -5,7 +5,9 @@
 import logging
 import pathlib
 import tracemalloc
+from contextlib import asynccontextmanager
 from datetime import datetime
+from typing import AsyncIterator, Optional
 
 from chia.util.path import path_from_root
 
@@ -176,3 +178,15 @@ async def mem_profile_task(root_path: pathlib.Path, service: str, log: logging.L
             counter += 1
     finally:
         tracemalloc.stop()
+
+
+@asynccontextmanager
+async def enable_profiler(profile: bool) -> AsyncIterator[Optional[cProfile.Profile]]:
+    if not profile:
+        yield None
+        return
+
+    with cProfile.Profile() as pr:
+        pr.enable()
+        yield pr
+        pr.disable()