diff options
author | MarcoFalke <falke.marco@gmail.com> | 2019-02-05 17:40:11 -0500 |
---|---|---|
committer | MarcoFalke <falke.marco@gmail.com> | 2019-02-05 17:40:16 -0500 |
commit | 5029e94f855c73bad2e0ea6dc0378f33787ae131 (patch) | |
tree | 99544c3e6d4b5bb037fdc1e41cc79d75e81482e9 /test/functional/test_framework/test_node.py | |
parent | baf125b31d0b4d37fc54123bc2563dac9ffde024 (diff) | |
parent | 13782b8ba84c5033a59a5234410a763393eafb8d (diff) | |
download | bitcoin-5029e94f855c73bad2e0ea6dc0378f33787ae131.tar.xz |
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
Diffstat (limited to 'test/functional/test_framework/test_node.py')
-rwxr-xr-x | test/functional/test_framework/test_node.py | 98 |
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. |