Full sync with logging for very slow state block commits

[teor2345]

Motivation

We want to find out which parts of state block commits are slow in CI, because we can't reproduce them locally.

These are diagnostics for ticket #4937, where some blocks take 15 minutes to write to the state.

Solution

• change info threshold to 5 minutes and warn to 9 minutes
• add slow code logging for block commits, block writes, and note commitment tree updates

Review

This PR doesn't need review.

Reviewer Checklist

• Logging works

Follow Up Work

Read the logs to work out why #4937 is happening

[arya2]

Looks good to me

[codecov]

Codecov Report

Merging #4952 (89c8cad) into main (c322533) will increase coverage by 0.01%.
The diff coverage is 100.00%.

@@            Coverage Diff             @@
##             main    #4952      +/-   ##
==========================================
+ Coverage   79.20%   79.21%   +0.01%     
==========================================
  Files         310      310              
  Lines       38883    39073     +190     
==========================================
+ Hits        30796    30952     +156     
- Misses       8087     8121      +34     

[oxarbitrage]

The code looks good for sure but i dont think we should be merging this things into the main branch.

This seems more suitable for a local test or for a specific branch outside main.

[teor2345]

The code looks good for sure but i dont think we should be merging this things into the main branch.

This seems more suitable for a local test or for a specific branch outside main.

Unfortunately, I can't reproduce this issue on my local machine, so I need to add this debugging to the main branch.
Once we know what the issue is, we can remove it.

[oxarbitrage]

Sorry, still dont understand why you need to add it to the main branch. Can't you run the CI without merging ?

[teor2345]

Sorry, still dont understand why you need to add it to the main branch. Can't you run the CI without merging ?

I'm not sure if it will work, but I can try.

I'll open a new PR to disable the logs for #4932, because that needs to go into main. Then I can make this PR and draft and do a full sync on it.

[teor2345]

I'm running a full sync here with these extra logs:
https://github.com/ZcashFoundation/zebra/actions/runs/2953663804

[teor2345]

@Mergifyio update

[mergify]

update

✅ Branch has been successfully updated

[teor2345]

Let's try that full sync again, after the concurrency fixes in PR #5000:
https://github.com/ZcashFoundation/zebra/actions/runs/2959955933

[teor2345]

The logs I added didn't actually show any extra information, which is a bit of a surprise. It's possible we're just committing a large number of slow blocks at a time.

I added some more logging and started another full sync:
https://github.com/ZcashFoundation/zebra/actions/runs/2968581615

[teor2345]

It appears that committing blocks hangs because we sometimes commit over 1000 blocks at the same time, then return the result to the state caller (checkpointer or non-finalized state block committer):

2022-09-01T22:50:25.650944Z WARN state: run time: very long queue_and_commit_finalized: 1774457..=1775638, 1181 blocks time=11m 24s module=zebra_state::service::finalized_state line=173
2022-09-01T22:50:25.650981Z WARN state: run time: very long CommitFinalizedBlock time=11m 24s module=zebra_state::service line=697

https://github.com/ZcashFoundation/zebra/runs/8147047219?check_suite_focus=true#step:6:165

I'll update ticket #4937 with the details.

[teor2345]

This PR has achieved its goals, but we'll need the extra logging to test any fixes.

[teor2345]

This PR was only used for testing slow block commits, we can re-open it if we need to re-test.