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

feat: logging time inside lock to help debugging lock contentions #6477

Draft
wants to merge 1 commit into
base: develop
Choose a base branch
from

Conversation

knst
Copy link
Collaborator

@knst knst commented Dec 11, 2024

This PR is not meant to be merged at the moment, let's try to collect real data and find-out at least one issue with this logs to proof it's useful.

Issue being fixed or feature implemented

Current log contention doesn't show information for how long time is spent inside mutex.
But this information is critical, because when looking to lock-contention you want to know which other function or method occupied it for so long time.

What was done?

Some extra logs for lock contention (for non-shared mutex only).

Debug logs have information about all cases when mutex is occupied for longer than 0.1ms:

2024-12-11T09:28:46Z [lock] lock contention m_nodes_mutex, ./net.h:1383 inside 101μs
2024-12-11T09:28:46Z [lock] lock contention pnode->cs_vSend, net.cpp:2809 inside 128μs
2024-12-11T09:28:46Z [net] SocketHandlerConnected -- remove mapReceivableNodes, peer=3
2024-12-11T09:28:46Z [lock] lock contention mutexMsgProc, net.cpp:4014 inside 261μs
2024-12-11T09:28:46Z [net] received: inv (37 bytes) peer=3
2024-12-11T09:28:46Z [net] got inv: dsq c2f442bca6a89d54a53348939c6f3aa013df034eafe4807d0ffc08e99deb27db  new peer=3
2024-12-11T09:28:46Z [net] RequestObject -- inv=(dsq c2f442bca6a89d54a53348939c6f3aa013df034eafe4807d0ffc08e99deb27db), current_time=1733909326825277, process_time=1733909386824280, delta=59999003
2024-12-11T09:28:46Z [net] SocketHandlerConnected -- remove mapReceivableNodes, peer=1
2024-12-11T09:28:46Z [lock] lock contention mutexMsgProc, net.cpp:4014 inside 4819μs
2024-12-11T09:28:46Z [net] SocketHandlerConnected -- remove mapReceivableNodes, peer=5
2024-12-11T09:28:46Z [lock] lock contention m_nodes_mutex, ./net.h:1383 inside 111μs

Please note, though, that in some cases long mutex occupation is expected because it's triggered by timer, for example:

2024-12-11T09:28:46Z [lock] lock contention mut, threadinterrupt.cpp:32 inside 100071μs

How Has This Been Tested?

Breaking Changes

N/A

Checklist:

  • I have performed a self-review of my own code
  • I have commented my code, particularly in hard-to-understand areas
  • I have added or updated relevant unit/integration/functional/e2e tests
  • I have made corresponding changes to the documentation
  • I have assigned this pull request to a milestone

@knst knst added this to the 22.1 milestone Dec 11, 2024
@DashCoreAutoGuix
Copy link

Guix Automation has began to build this PR tagged as v22.1.0-devpr6477.ce8b10fd. A new comment will be made when the image is pushed.

@knst
Copy link
Collaborator Author

knst commented Dec 11, 2024

@PastaPastaPasta can you collect data for any testnet node during sending bunch of txs, please?

@DashCoreAutoGuix
Copy link

Guix Automation has completed; a release should be present here: https://github.com/dashpay/dash-dev-branches/releases/tag/v22.1.0-devpr6477.ce8b10fd. The image should be on dockerhub soon.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Development

Successfully merging this pull request may close these issues.

2 participants