diff options
-rw-r--r-- | .travis.yml | 2 | ||||
-rwxr-xr-x | contrib/linearize/linearize-hashes.py | 4 | ||||
-rw-r--r-- | doc/developer-notes.md | 46 | ||||
-rw-r--r-- | doc/release-notes.md | 10 | ||||
-rw-r--r-- | src/qt/clientmodel.cpp | 4 | ||||
-rw-r--r-- | src/qt/modaloverlay.cpp | 8 | ||||
-rw-r--r-- | src/qt/modaloverlay.h | 1 | ||||
-rw-r--r-- | src/rpc/rawtransaction.cpp | 16 | ||||
-rw-r--r-- | test/README.md | 20 | ||||
-rw-r--r-- | test/functional/README.md | 33 | ||||
-rwxr-xr-x | test/functional/test_framework/test_framework.py | 16 | ||||
-rwxr-xr-x | test/functional/test_framework/test_node.py | 98 | ||||
-rwxr-xr-x | test/lint/lint-python-dead-code.sh | 2 |
13 files changed, 239 insertions, 21 deletions
diff --git a/.travis.yml b/.travis.yml index b43418f84e..873b33b05b 100644 --- a/.travis.yml +++ b/.travis.yml @@ -33,7 +33,7 @@ before_script: - set -o errexit; source .travis/test_05_before_script.sh script: - if [ $SECONDS -gt 1200 ]; then set +o errexit; echo "Travis early exit to cache current state"; false; else set -o errexit; source .travis/test_06_script_a.sh; fi - - if [ $SECONDS -gt 1500 ]; then set +o errexit; echo "Travis early exit to cache current state"; false; else set -o errexit; source .travis/test_06_script_b.sh; fi + - if [ $SECONDS -gt 1800 ]; then set +o errexit; echo "Travis early exit to cache current state"; false; else set -o errexit; source .travis/test_06_script_b.sh; fi after_script: - echo $TRAVIS_COMMIT_RANGE - echo $TRAVIS_COMMIT_LOG diff --git a/contrib/linearize/linearize-hashes.py b/contrib/linearize/linearize-hashes.py index e10b46d831..8529470e09 100755 --- a/contrib/linearize/linearize-hashes.py +++ b/contrib/linearize/linearize-hashes.py @@ -7,7 +7,7 @@ # file COPYING or http://www.opensource.org/licenses/mit-license.php. # -from http.client import HttpConnection +from http.client import HTTPConnection import json import re import base64 @@ -27,7 +27,7 @@ class BitcoinRPC: authpair = "%s:%s" % (username, password) authpair = authpair.encode('utf-8') self.authhdr = b"Basic " + base64.b64encode(authpair) - self.conn = HttpConnection(host, port=port, timeout=30) + self.conn = HTTPConnection(host, port=port, timeout=30) def execute(self, obj): try: diff --git a/doc/developer-notes.md b/doc/developer-notes.md index ec29310ffe..1deb5d791a 100644 --- a/doc/developer-notes.md +++ b/doc/developer-notes.md @@ -17,6 +17,7 @@ Developer Notes - [DEBUG_LOCKORDER](#debug_lockorder) - [Valgrind suppressions file](#valgrind-suppressions-file) - [Compiling for test coverage](#compiling-for-test-coverage) + - [Performance profiling with perf](#performance-profiling-with-perf) - [Locking/mutex usage notes](#lockingmutex-usage-notes) - [Threads](#threads) - [Ignoring IDE/editor files](#ignoring-ideeditor-files) @@ -265,6 +266,51 @@ make cov # A coverage report will now be accessible at `./test_bitcoin.coverage/index.html`. ``` +### Performance profiling with perf + +Profiling is a good way to get a precise idea of where time is being spent in +code. One tool for doing profiling on Linux platforms is called +[`perf`](http://www.brendangregg.com/perf.html), and has been integrated into +the functional test framework. Perf can observe a running process and sample +(at some frequency) where its execution is. + +Perf installation is contingent on which kernel version you're running; see +[this StackExchange +thread](https://askubuntu.com/questions/50145/how-to-install-perf-monitoring-tool) +for specific instructions. + +Certain kernel parameters may need to be set for perf to be able to inspect the +running process' stack. + +```sh +$ sudo sysctl -w kernel.perf_event_paranoid=-1 +$ sudo sysctl -w kernel.kptr_restrict=0 +``` + +Make sure you [understand the security +trade-offs](https://lwn.net/Articles/420403/) of setting these kernel +parameters. + +To profile a running bitcoind process for 60 seconds, you could use an +invocation of `perf record` like this: + +```sh +$ perf record \ + -g --call-graph dwarf --per-thread -F 140 \ + -p `pgrep bitcoind` -- sleep 60 +``` + +You could then analyze the results by running + +```sh +perf report --stdio | c++filt | less +``` + +or using a graphical tool like [Hotspot](https://github.com/KDAB/hotspot). + +See the functional test documentation for how to invoke perf within tests. + + **Sanitizers** Bitcoin Core can be compiled with various "sanitizers" enabled, which add diff --git a/doc/release-notes.md b/doc/release-notes.md index a54b08848f..c23a7f6e0a 100644 --- a/doc/release-notes.md +++ b/doc/release-notes.md @@ -254,11 +254,11 @@ in the Low-level Changes section below. - See the [Mining](#mining) section for changes to `getblocktemplate`. -- The `getrawtransaction` RPC no longer checks the unspent UTXO set for - a transaction. The remaining behaviors are as follows: 1. If a - blockhash is provided, check the corresponding block. 2. If no - blockhash is provided, check the mempool. 3. If no blockhash is - provided but txindex is enabled, also check txindex. +- The `getrawtransaction` RPC & REST endpoints no longer check the + unspent UTXO set for a transaction. The remaining behaviors are as + follows: 1. If a blockhash is provided, check the corresponding block. + 2. If no blockhash is provided, check the mempool. 3. If no blockhash + is provided but txindex is enabled, also check txindex. Graphical User Interface (GUI) ------------------------------ diff --git a/src/qt/clientmodel.cpp b/src/qt/clientmodel.cpp index 30d9e977b8..27b4c182f9 100644 --- a/src/qt/clientmodel.cpp +++ b/src/qt/clientmodel.cpp @@ -237,8 +237,8 @@ static void BlockTipChanged(ClientModel *clientmodel, bool initialSync, int heig clientmodel->cachedBestHeaderHeight = height; clientmodel->cachedBestHeaderTime = blockTime; } - // if we are in-sync, update the UI regardless of last update time - if (!initialSync || now - nLastUpdateNotification > MODEL_UPDATE_DELAY) { + // if we are in-sync or if we notify a header update, update the UI regardless of last update time + if (fHeader || !initialSync || now - nLastUpdateNotification > MODEL_UPDATE_DELAY) { //pass an async signal to the UI thread QMetaObject::invokeMethod(clientmodel, "numBlocksChanged", Qt::QueuedConnection, Q_ARG(int, height), diff --git a/src/qt/modaloverlay.cpp b/src/qt/modaloverlay.cpp index c5bedf007a..8ecc33da84 100644 --- a/src/qt/modaloverlay.cpp +++ b/src/qt/modaloverlay.cpp @@ -71,6 +71,7 @@ void ModalOverlay::setKnownBestHeight(int count, const QDateTime& blockDate) if (count > bestHeaderHeight) { bestHeaderHeight = count; bestHeaderDate = blockDate; + UpdateHeaderSyncLabel(); } } @@ -136,11 +137,16 @@ void ModalOverlay::tipUpdate(int count, const QDateTime& blockDate, double nVeri if (estimateNumHeadersLeft < HEADER_HEIGHT_DELTA_SYNC && hasBestHeader) { ui->numberOfBlocksLeft->setText(QString::number(bestHeaderHeight - count)); } else { - ui->numberOfBlocksLeft->setText(tr("Unknown. Syncing Headers (%1)...").arg(bestHeaderHeight)); + UpdateHeaderSyncLabel(); ui->expectedTimeLeft->setText(tr("Unknown...")); } } +void ModalOverlay::UpdateHeaderSyncLabel() { + int est_headers_left = bestHeaderDate.secsTo(QDateTime::currentDateTime()) / Params().GetConsensus().nPowTargetSpacing; + ui->numberOfBlocksLeft->setText(tr("Unknown. Syncing Headers (%1, %2%)...").arg(bestHeaderHeight).arg(QString::number(100.0 / (bestHeaderHeight + est_headers_left) * bestHeaderHeight, 'f', 1))); +} + void ModalOverlay::toggleVisibility() { showHide(layerIsVisible, true); diff --git a/src/qt/modaloverlay.h b/src/qt/modaloverlay.h index 66a6ad1e02..cf8b53f2b3 100644 --- a/src/qt/modaloverlay.h +++ b/src/qt/modaloverlay.h @@ -45,6 +45,7 @@ private: QVector<QPair<qint64, double> > blockProcessTime; bool layerIsVisible; bool userClosed; + void UpdateHeaderSyncLabel(); }; #endif // BITCOIN_QT_MODALOVERLAY_H diff --git a/src/rpc/rawtransaction.cpp b/src/rpc/rawtransaction.cpp index ac2e0ff4ee..b3b9d8af09 100644 --- a/src/rpc/rawtransaction.cpp +++ b/src/rpc/rawtransaction.cpp @@ -1,5 +1,5 @@ // Copyright (c) 2010 Satoshi Nakamoto -// Copyright (c) 2009-2018 The Bitcoin Core developers +// Copyright (c) 2009-2019 The Bitcoin Core developers // Distributed under the MIT software license, see the accompanying // file COPYING or http://www.opensource.org/licenses/mit-license.php. @@ -66,17 +66,21 @@ static UniValue getrawtransaction(const JSONRPCRequest& request) { if (request.fHelp || request.params.size() < 1 || request.params.size() > 3) throw std::runtime_error( - RPCHelpMan{"getrawtransaction", + RPCHelpMan{ + "getrawtransaction", + "\nReturn the raw transaction data.\n" + "\nBy default this function only works for mempool transactions. When called with a blockhash\n" "argument, getrawtransaction will return the transaction if the specified block is available and\n" "the transaction is found in that block. When called without a blockhash argument, getrawtransaction\n" "will return the transaction if it is in the mempool, or if -txindex is enabled and the transaction\n" "is in a block in the blockchain.\n" - "\nReturn the raw transaction data.\n" - "\nIf verbose is 'true', returns an Object with information about 'txid'.\n" - "If verbose is 'false' or omitted, returns a string that is serialized, hex-encoded data for 'txid'.\n" - , + "\nHint: use getmempoolentry to fetch a specific transaction from the mempool.\n" + "Or use gettransaction for wallet transactions.\n" + + "\nIf verbose is 'true', returns an Object with information about 'txid'.\n" + "If verbose is 'false' or omitted, returns a string that is serialized, hex-encoded data for 'txid'.\n", { {"txid", RPCArg::Type::STR_HEX, /* opt */ false, /* default_val */ "", "The transaction id"}, {"verbose", RPCArg::Type::BOOL, /* opt */ true, /* default_val */ "false", "If false, return a string, otherwise return a json object"}, diff --git a/test/README.md b/test/README.md index a6fb9c9d73..9d4351b1de 100644 --- a/test/README.md +++ b/test/README.md @@ -178,6 +178,26 @@ gdb /home/example/bitcoind <pid> Note: gdb attach step may require ptrace_scope to be modified, or `sudo` preceding the `gdb`. See this link for considerations: https://www.kernel.org/doc/Documentation/security/Yama.txt +##### Profiling + +An easy way to profile node performance during functional tests is provided +for Linux platforms using `perf`. + +Perf will sample the running node and will generate profile data in the node's +datadir. The profile data can then be presented using `perf report` or a graphical +tool like [hotspot](https://github.com/KDAB/hotspot). + +To generate a profile during test suite runs, use the `--perf` flag. + +To see render the output to text, run + +```sh +perf report -i /path/to/datadir/send-big-msgs.perf.data.xxxx --stdio | c++filt | less +``` + +For ways to generate more granular profiles, see the README in +[test/functional](/test/functional). + ### Util tests Util tests can be run locally by running `test/util/bitcoin-util-test.py`. diff --git a/test/functional/README.md b/test/functional/README.md index 628c77eb11..74f454b86c 100644 --- a/test/functional/README.md +++ b/test/functional/README.md @@ -122,3 +122,36 @@ Helpers for script.py #### [test_framework/blocktools.py](test_framework/blocktools.py) Helper functions for creating blocks and transactions. + +### Benchmarking with perf + +An easy way to profile node performance during functional tests is provided +for Linux platforms using `perf`. + +Perf will sample the running node and will generate profile data in the node's +datadir. The profile data can then be presented using `perf report` or a graphical +tool like [hotspot](https://github.com/KDAB/hotspot). + +There are two ways of invoking perf: one is to use the `--perf` flag when +running tests, which will profile each node during the entire test run: perf +begins to profile when the node starts and ends when it shuts down. The other +way is the use the `profile_with_perf` context manager, e.g. + +```python +with node.profile_with_perf("send-big-msgs"): + # Perform activity on the node you're interested in profiling, e.g.: + for _ in range(10000): + node.p2p.send_message(some_large_message) +``` + +To see useful textual output, run + +```sh +perf report -i /path/to/datadir/send-big-msgs.perf.data.xxxx --stdio | c++filt | less +``` + +#### See also: + +- [Installing perf](https://askubuntu.com/q/50145) +- [Perf examples](http://www.brendangregg.com/perf.html) +- [Hotspot](https://github.com/KDAB/hotspot): a GUI for perf output analysis diff --git a/test/functional/test_framework/test_framework.py b/test/functional/test_framework/test_framework.py index 6dcaff0696..8c4c0d7226 100755 --- a/test/functional/test_framework/test_framework.py +++ b/test/functional/test_framework/test_framework.py @@ -128,6 +128,8 @@ class BitcoinTestFramework(metaclass=BitcoinTestMetaClass): help="Attach a python debugger if test fails") parser.add_argument("--usecli", dest="usecli", default=False, action="store_true", help="use bitcoin-cli instead of RPC for all commands") + parser.add_argument("--perf", dest="perf", default=False, action="store_true", + help="profile running nodes with perf for the duration of the test") self.add_options(parser) self.options = parser.parse_args() @@ -202,11 +204,20 @@ class BitcoinTestFramework(metaclass=BitcoinTestMetaClass): node.cleanup_on_exit = False self.log.info("Note: bitcoinds were not stopped and may still be running") - if not self.options.nocleanup and not self.options.noshutdown and success != TestStatus.FAILED: + should_clean_up = ( + not self.options.nocleanup and + not self.options.noshutdown and + success != TestStatus.FAILED and + not self.options.perf + ) + if should_clean_up: self.log.info("Cleaning up {} on exit".format(self.options.tmpdir)) cleanup_tree_on_exit = True + elif self.options.perf: + self.log.warning("Not cleaning up dir {} due to perf data".format(self.options.tmpdir)) + cleanup_tree_on_exit = False else: - self.log.warning("Not cleaning up dir %s" % self.options.tmpdir) + self.log.warning("Not cleaning up dir {}".format(self.options.tmpdir)) cleanup_tree_on_exit = False if success == TestStatus.PASSED: @@ -310,6 +321,7 @@ class BitcoinTestFramework(metaclass=BitcoinTestMetaClass): extra_conf=extra_confs[i], extra_args=extra_args[i], use_cli=self.options.usecli, + start_perf=self.options.perf, )) def start_node(self, i, *args, **kwargs): 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. diff --git a/test/lint/lint-python-dead-code.sh b/test/lint/lint-python-dead-code.sh index 1b897cd131..863caa9d5c 100755 --- a/test/lint/lint-python-dead-code.sh +++ b/test/lint/lint-python-dead-code.sh @@ -15,5 +15,5 @@ fi vulture \ --min-confidence 60 \ - --ignore-names "argtypes,connection_lost,connection_made,converter,data_received,daemon,errcheck,get_ecdh_key,get_privkey,is_compressed,is_fullyvalid,msg_generic,on_*,optionxform,restype,set_privkey" \ + --ignore-names "argtypes,connection_lost,connection_made,converter,data_received,daemon,errcheck,get_ecdh_key,get_privkey,is_compressed,is_fullyvalid,msg_generic,on_*,optionxform,restype,set_privkey,profile_with_perf" \ $(git ls-files -- "*.py" ":(exclude)contrib/" ":(exclude)test/functional/data/invalid_txs.py") |