Merge #14519: tests: add utility to easily profile node performance with perf

13782b8ba8 docs: add perf section to developer docs (James O'Beirne)
58180b5fd4 tests: add utility to easily profile node performance with perf (James O'Beirne)

Pull request description:

  Adds a context manager to easily (and selectively) profile node performance during functional test execution using `perf`.

  While writing some tests, I encountered some odd bitcoind slowness. I wrote up a utility (`TestNode.profile_with_perf`) that generates performance diagnostics for a node by running `perf` during the execution of a particular region of test code.

  `perf` usage is detailed in the excellent (and sadly unmerged) https://github.com/bitcoin/bitcoin/pull/12649; all due props to @eklitzke.

  ### Example

  ```python
  with node.profile_with_perf("large-msgs"):
      for i in range(200):
          node.p2p.send_message(some_large_msg)
      node.p2p.sync_with_ping()
  ```

  This generates a perf data file in the test node's datadir (`/tmp/testtxmpod0y/node0/node-0-TestName-large-msgs.perf.data`).

  Running `perf report` generates nice output about where the node spent most of its time while running that part of the test:

  ```bash
  $ perf report -i /tmp/testtxmpod0y/node0/node-0-TestName-large-msgs.perf.data --stdio \
    | c++filt \
    | less

  # To display the perf.data header info, please use --header/--header-only options.
  #
  #
  # Total Lost Samples: 0
  #
  # Samples: 135  of event 'cycles:pp'
  # Event count (approx.): 1458205679493582
  #
  # Children      Self  Command          Shared Object        Symbol
  # ........  ........  ...............  ...................  ........................................................................................................................................................................................................................................................................
  #
      70.14%     0.00%  bitcoin-net      bitcoind             [.] CNode::ReceiveMsgBytes(char const*, unsigned int, bool&)
                  |
                  ---CNode::ReceiveMsgBytes(char const*, unsigned int, bool&)

      70.14%     0.00%  bitcoin-net      bitcoind             [.] CNetMessage::readData(char const*, unsigned int)
                  |
                  ---CNetMessage::readData(char const*, unsigned int)
                     CNode::ReceiveMsgBytes(char const*, unsigned int, bool&)

      35.52%     0.00%  bitcoin-net      bitcoind             [.] std::vector<char, zero_after_free_allocator<char> >::_M_fill_insert(__gnu_cxx::__normal_iterator<char*, std::vector<char, zero_after_free_allocator<char> > >, unsigned long, char const&)
                  |
                  ---std::vector<char, zero_after_free_allocator<char> >::_M_fill_insert(__gnu_cxx::__normal_iterator<char*, std::vector<char, zero_after_free_allocator<char> > >, unsigned long, char const&)
                     CNetMessage::readData(char const*, unsigned int)
                     CNode::ReceiveMsgBytes(char const*, unsigned int, bool&)

  ...
  ```

Tree-SHA512: 9ac4ceaa88818d5eca00994e8e3c8ad42ae019550d6583972a0a4f7b0c4f61032e3d0c476b4ae58756bc5eb8f8015a19a7fc26c095bd588f31d49a37ed0c6b3e

1 files changed, 97 insertions, 1 deletions

diff --git a/test/functional/test_framework/test_node.py b/test/functional/test_framework/test_node.py
index 6745409964..d6e31457d1 100755
--- a/test/functional/test_framework/test_node.py
+++ b/test/functional/test_framework/test_node.py
@@ -18,6 +18,8 @@ import tempfile
 import time
 import urllib.parse
 import collections
+import shlex
+import sys
 
 from .authproxy import JSONRPCException
 from .util import (
@@ -59,7 +61,13 @@ class TestNode():
     To make things easier for the test writer, any unrecognised messages will
     be dispatched to the RPC connection."""
 
-    def __init__(self, i, datadir, *, rpchost, timewait, bitcoind, bitcoin_cli, mocktime, coverage_dir, extra_conf=None, extra_args=None, use_cli=False):
+    def __init__(self, i, datadir, *, rpchost, timewait, bitcoind, bitcoin_cli, mocktime, coverage_dir, extra_conf=None, extra_args=None, use_cli=False, start_perf=False):
+        """
+        Kwargs:
+            start_perf (bool): If True, begin profiling the node with `perf` as soon as
+                the node starts.
+        """
+
         self.index = i
         self.datadir = datadir
         self.stdout_dir = os.path.join(self.datadir, "stdout")
@@ -87,6 +95,7 @@ class TestNode():
 
         self.cli = TestNodeCLI(bitcoin_cli, self.datadir)
         self.use_cli = use_cli
+        self.start_perf = start_perf
 
         self.running = False
         self.process = None
@@ -95,6 +104,8 @@ class TestNode():
         self.url = None
         self.log = logging.getLogger('TestFramework.node%d' % i)
         self.cleanup_on_exit = True # Whether to kill the node when this object goes away
+        # Cache perf subprocesses here by their data output filename.
+        self.perf_subprocesses = {}
 
         self.p2ps = []
 
@@ -186,6 +197,9 @@ class TestNode():
         self.running = True
         self.log.debug("bitcoind started, waiting for RPC to come up")
 
+        if self.start_perf:
+            self._start_perf()
+
     def wait_for_rpc_connection(self):
         """Sets up an RPC connection to the bitcoind process. Returns False if unable to connect."""
         # Poll at a rate of four times per second
@@ -238,6 +252,10 @@ class TestNode():
         except http.client.CannotSendRequest:
             self.log.exception("Unable to stop node.")
 
+        # If there are any running perf processes, stop them.
+        for profile_name in tuple(self.perf_subprocesses.keys()):
+            self._stop_perf(profile_name)
+
         # Check that stderr is as expected
         self.stderr.seek(0)
         stderr = self.stderr.read().decode('utf-8').strip()
@@ -317,6 +335,84 @@ class TestNode():
                     increase_allowed * 100, before_memory_usage, after_memory_usage,
                     perc_increase_memory_usage * 100))
 
+    @contextlib.contextmanager
+    def profile_with_perf(self, profile_name):
+        """
+        Context manager that allows easy profiling of node activity using `perf`.
+
+        See `test/functional/README.md` for details on perf usage.
+
+        Args:
+            profile_name (str): This string will be appended to the
+                profile data filename generated by perf.
+        """
+        subp = self._start_perf(profile_name)
+
+        yield
+
+        if subp:
+            self._stop_perf(profile_name)
+
+    def _start_perf(self, profile_name=None):
+        """Start a perf process to profile this node.
+
+        Returns the subprocess running perf."""
+        subp = None
+
+        def test_success(cmd):
+            return subprocess.call(
+                # shell=True required for pipe use below
+                cmd, shell=True,
+                stderr=subprocess.DEVNULL, stdout=subprocess.DEVNULL) == 0
+
+        if not sys.platform.startswith('linux'):
+            self.log.warning("Can't profile with perf; only availabe on Linux platforms")
+            return None
+
+        if not test_success('which perf'):
+            self.log.warning("Can't profile with perf; must install perf-tools")
+            return None
+
+        if not test_success('readelf -S {} | grep .debug_str'.format(shlex.quote(self.binary))):
+            self.log.warning(
+                "perf output won't be very useful without debug symbols compiled into bitcoind")
+
+        output_path = tempfile.NamedTemporaryFile(
+            dir=self.datadir,
+            prefix="{}.perf.data.".format(profile_name or 'test'),
+            delete=False,
+        ).name
+
+        cmd = [
+            'perf', 'record',
+            '-g',                     # Record the callgraph.
+            '--call-graph', 'dwarf',  # Compatibility for gcc's --fomit-frame-pointer.
+            '-F', '101',              # Sampling frequency in Hz.
+            '-p', str(self.process.pid),
+            '-o', output_path,
+        ]
+        subp = subprocess.Popen(cmd, stdout=subprocess.PIPE, stderr=subprocess.PIPE)
+        self.perf_subprocesses[profile_name] = subp
+
+        return subp
+
+    def _stop_perf(self, profile_name):
+        """Stop (and pop) a perf subprocess."""
+        subp = self.perf_subprocesses.pop(profile_name)
+        output_path = subp.args[subp.args.index('-o') + 1]
+
+        subp.terminate()
+        subp.wait(timeout=10)
+
+        stderr = subp.stderr.read().decode()
+        if 'Consider tweaking /proc/sys/kernel/perf_event_paranoid' in stderr:
+            self.log.warning(
+                "perf couldn't collect data! Try "
+                "'sudo sysctl -w kernel.perf_event_paranoid=-1'")
+        else:
+            report_cmd = "perf report -i {}".format(output_path)
+            self.log.info("See perf output by running '{}'".format(report_cmd))
+
     def assert_start_raises_init_error(self, extra_args=None, expected_msg=None, match=ErrorMatch.FULL_TEXT, *args, **kwargs):
         """Attempt to start the node and expect it to raise an error.