Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

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

Merged
merged 2 commits into from Feb 5, 2019

Conversation

Projects
None yet
10 participants
@jamesob
Copy link
Member

commented Oct 19, 2018

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) #12649; all due props to @eklitzke.

Example

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:

$ 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&)

...

@jamesob jamesob changed the title test: add utility to easily profile node performance with perf tests: add utility to easily profile node performance with perf Oct 19, 2018

@jamesob jamesob changed the title tests: add utility to easily profile node performance with perf test: add utility to easily profile node performance with perf Oct 19, 2018

@jamesob jamesob force-pushed the jamesob:2018-10-func-test-profiling branch Oct 19, 2018

@jamesob jamesob changed the title test: add utility to easily profile node performance with perf tests: add utility to easily profile node performance with perf Oct 19, 2018

@jamesob

This comment has been minimized.

Copy link
Member Author

commented Oct 19, 2018

An example of running the generated perf data file through hotspot:

selection_109

@ryanofsky
Copy link
Contributor

left a comment

utACK b93a17c3153f050eb37292b51463b0aaa5860f1a. Context manager seems nice for writing new tests. This is just an idea, but maybe it would be useful if there were an option to collect perf data for all nodes from start to stop to gain insight into performance of existing tests.

Show resolved Hide resolved test/functional/test_framework/test_node.py Outdated
Show resolved Hide resolved test/functional/test_framework/test_node.py Outdated

@jamesob jamesob force-pushed the jamesob:2018-10-func-test-profiling branch 3 times, most recently Oct 19, 2018

@jamesob

This comment has been minimized.

Copy link
Member Author

commented Oct 19, 2018

Thanks for the review, @ryanofsky. I really like your suggestions and so I've incorporated them all into a rebase.

You can now pass --perf when running an individual test file and all nodes will be profiled for the duration of the test. Here's an example run:

$ ./test/functional/p2p_unrequested_blocks.py --perf

2018-10-19T20:36:06.542000Z TestFramework (INFO): Initializing test directory /tmp/test71_cfvsc
...
2018-10-19T20:36:09.206000Z TestFramework (INFO): Stopping nodes
2018-10-19T20:36:09.384000Z TestFramework.node0 (INFO): Wrote perf output to '/tmp/test71_cfvsc/node0/node-0-AcceptBlockTest.perf.data'
2018-10-19T20:36:09.558000Z TestFramework.node1 (INFO): Wrote perf output to '/tmp/test71_cfvsc/node1/node-1-AcceptBlockTest.perf.data'
2018-10-19T20:36:09.608000Z TestFramework (WARNING): Not cleaning up dir /tmp/test71_cfvsc due to perf data
2018-10-19T20:36:09.608000Z TestFramework (INFO): Tests successful

@jamesob jamesob force-pushed the jamesob:2018-10-func-test-profiling branch 2 times, most recently Oct 19, 2018

@promag

This comment has been minimized.

Copy link
Member

commented Oct 20, 2018

Concept ACK, very nice!

@DrahtBot

This comment has been minimized.

Copy link
Contributor

commented Oct 20, 2018

The following sections might be updated with supplementary metadata relevant to reviewers and maintainers.

Conflicts

No conflicts as of last run.

@jtimon

This comment has been minimized.

Copy link
Member

commented Oct 22, 2018

Concept ACK

@ryanofsky
Copy link
Contributor

left a comment

utACK 358e757d566d5f659901acc6f15fa9eb6eb3e741

Show resolved Hide resolved test/functional/test_framework/test_node.py Outdated
Show resolved Hide resolved test/functional/test_framework/test_node.py Outdated

@jamesob jamesob force-pushed the jamesob:2018-10-func-test-profiling branch 2 times, most recently Oct 23, 2018

@jamesob

This comment has been minimized.

Copy link
Member Author

commented Oct 23, 2018

Addressed feedback from @ryanofsky @conscott.

@MarcoFalke
Copy link
Member

left a comment

utACK

Show resolved Hide resolved test/functional/test_framework/test_node.py Outdated
Show resolved Hide resolved test/functional/test_framework/test_node.py Outdated
Show resolved Hide resolved test/functional/test_framework/test_framework.py Outdated

@jamesob jamesob force-pushed the jamesob:2018-10-func-test-profiling branch Oct 24, 2018

@jamesob

This comment has been minimized.

Copy link
Member Author

commented Oct 24, 2018

Pushed feedback from @MarcoFalke.

Show resolved Hide resolved test/functional/test_framework/test_framework.py Outdated

@jamesob jamesob force-pushed the jamesob:2018-10-func-test-profiling branch Oct 24, 2018

@ryanofsky
Copy link
Contributor

left a comment

utACK 5d8ac69be53a876d2b15ba703603cea8f4efdb1a. Just change in string formatting and simplification to file naming since last review.

@fanquake

This comment has been minimized.

Copy link
Member

commented Oct 28, 2018

utACK 5d8ac69

Can't comment on the usage of perf, but if this leads to more profiling, and performance related discussion/results in reviews, sounds great.

Also pro reviving the flamegraph docs out of #12649, however that shouldn't hold this up.

Show resolved Hide resolved test/functional/test_framework/test_node.py Outdated

@jamesob jamesob force-pushed the jamesob:2018-10-func-test-profiling branch Nov 9, 2018

@DrahtBot DrahtBot removed the Needs rebase label Nov 9, 2018

@jamesob jamesob force-pushed the jamesob:2018-10-func-test-profiling branch Nov 9, 2018

@jnewbery
Copy link
Member

left a comment

Concept ACK.

This seems cool. I haven't had a chance to play around with it yet. I've given the code a cursory glance and will review more thoroughly next week.

Show resolved Hide resolved test/functional/test_framework/test_node.py Outdated
@jnewbery
Copy link
Member

left a comment

This is really cool. I've now had a chance to play around with it and it's great. I think doing the following would make it even more useful and accessible for developers:

  • move the documentation about installing and using perf to doc/developer-notes.md
  • move the documentation about using profile_with_perf() to test/README.md, with a reference to doc/developer-notes.md for notes on perf.
Show resolved Hide resolved test/functional/test_framework/test_node.py
Show resolved Hide resolved test/functional/test_framework/test_node.py Outdated
Show resolved Hide resolved test/functional/test_framework/test_node.py
Show resolved Hide resolved test/functional/test_framework/test_node.py Outdated
Show resolved Hide resolved test/functional/test_framework/test_node.py
Show resolved Hide resolved test/functional/test_framework/test_node.py Outdated
Show resolved Hide resolved test/functional/test_framework/test_node.py
Show resolved Hide resolved test/functional/example_test.py Outdated
@laanwj

This comment has been minimized.

Copy link
Member

commented Jan 2, 2019

Concept ACK

@jamesob jamesob force-pushed the jamesob:2018-10-func-test-profiling branch to 1ae07ec Jan 2, 2019

@jamesob

This comment has been minimized.

Copy link
Member Author

commented Jan 2, 2019

Thanks for the review, @jnewbery. I've pushed a rebased tip that addresses the feedback.

Here's the diff (excluding the rebase).

@jamesob jamesob force-pushed the jamesob:2018-10-func-test-profiling branch 5 times, most recently Jan 2, 2019

@DrahtBot DrahtBot removed the Needs rebase label Jan 3, 2019

@ryanofsky
Copy link
Contributor

left a comment

utACK 27a895d72a385bcaa861e08b03bb5c817f8e253f. Changes since last review: rebase, moving & adding documentation, tweaking output paths.

```

Make sure you [understand the security
trade-offs](https://lwn.net/Articles/420403/) of setting these kernel

This comment has been minimized.

Copy link
@ryanofsky

ryanofsky Jan 4, 2019

Contributor

In commit "docs: add perf section to developer docs" (27a895d72a385bcaa861e08b03bb5c817f8e253f)

Slightly strange the link text is "understand the security tradeoffs" instead of just "security tradeoffs."

@MarcoFalke MarcoFalke added this to the 0.18.0 milestone Jan 5, 2019

@jnewbery
Copy link
Member

left a comment

Looks great James. A few comments inline.

Show resolved Hide resolved test/functional/README.md
Show resolved Hide resolved test/functional/example_test.py Outdated
Show resolved Hide resolved test/functional/test_framework/test_node.py
Show resolved Hide resolved test/functional/test_framework/test_node.py Outdated
Show resolved Hide resolved test/functional/test_framework/test_node.py
Show resolved Hide resolved test/functional/README.md Outdated

jamesob added some commits Oct 19, 2018

tests: add utility to easily profile node performance with perf
Introduces `TestNode.profile_with_perf()` context manager which
samples node execution to produce profiling data.

Also introduces a test framework flag, `--perf`, which will run
perf on all nodes for the duration of a given test.

@jamesob jamesob force-pushed the jamesob:2018-10-func-test-profiling branch to 13782b8 Jan 22, 2019

@jamesob

This comment has been minimized.

Copy link
Member Author

commented Jan 22, 2019

Pushed an update addressing feedback from @jnewbery.

@ryanofsky
Copy link
Contributor

left a comment

utACK 13782b8. Main change is removing code in example test, and adding to test README instead.

@MarcoFalke MarcoFalke merged commit 13782b8 into bitcoin:master Feb 5, 2019

2 checks passed

continuous-integration/appveyor/pr AppVeyor build succeeded
Details
continuous-integration/travis-ci/pr The Travis CI build passed
Details

MarcoFalke added a commit that referenced this pull request Feb 5, 2019

Merge #14519: tests: add utility to easily profile node performance w…
…ith perf

13782b8 docs: add perf section to developer docs (James O'Beirne)
58180b5 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) #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
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
You can’t perform that action at this time.