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

DEBUG: Add logs between fetch data and caching #755

Merged
merged 2 commits into from
Feb 29, 2024
Merged

Conversation

aakoshh
Copy link
Contributor

@aakoshh aakoshh commented Feb 28, 2024

Following the log debug session on Slack I see that these lines can take up to 15 minutes to execute. It could be some freakishly slow API calls or STM live- or deadlocking.

The PR adds some logging in between these.

Suspicious logs:

"2024-02-27T19:44:01.278908Z", "message":"syncing heights","chain_head":1391238,"pointers":"{tail: {height: 1391199, hash: 9bdf3eae78d33514b3cf262cc16eca91a75845361a906606b660afadbba72390}, head: 1391199}"},"filename":"fendermint/vm/topdown/src/sync/syncer.rs","line_number":96}
"2024-02-27T19:44:01.278919Z", "message":"previous non null parent is the pending confirmation block","pending_height":1391199},"filename":"fendermint/vm/topdown/src/sync/syncer.rs","line_number":276}
"2024-02-27T19:44:01.278923Z", "message":"polling height with parent hash","height":1391200,"parent_block_hash":"9bdf3eae78d33514b3cf262cc16eca91a75845361a906606b660afadbba72390"},"filename":"fendermint/vm/topdown/src/sync/syncer.rs","line_number":156}
"2024-02-27T19:57:35.657267Z", "message":"non-null round at height, confirmed previous height","height":1391200,"confirm":1391199},"filename":"fendermint/vm/topdown/src/sync/syncer.rs","line_number":188}
"2024-02-27T19:57:38.369043Z", "message":"non-null block pushed to cache","height":1391199},"filename":"fendermint/vm/topdown/src/sync/syncer.rs","line_number":217}

In this ☝️ instance it looks like 12 minutes spent between polling the parent hash and just before fetching the data, then 3s to fetch the data and write to cache.

"2024-02-27T19:58:31.807000Z", "message":"previous non null parent is the pending confirmation block","pending_height":1391211},"filename":"fendermint/vm/topdown/src/sync/syncer.rs","line_number":276}
"2024-02-27T19:58:31.807003Z", "message":"polling height with parent hash","height":1391212,"parent_block_hash":"dd0bb9a330d94a6d2de94f496192bf4eee57930dfaac2b59cc03ea388488d3eb"},"filename":"fendermint/vm/topdown/src/sync/syncer.rs","line_number":156}
"2024-02-27T19:58:32.996770Z", "message":"non-null round at height, confirmed previous height","height":1391212,"confirm":1391211},"filename":"fendermint/vm/topdown/src/sync/syncer.rs","line_number":188}
"2024-02-27T20:15:04.075883Z", "message":"non-null block pushed to cache","height":1391211},"filename":"fendermint/vm/topdown/src/sync/syncer.rs","line_number":217}

In this ☝️ one 17 minutes go past that include fetching data and writing it to the cache.

@aakoshh aakoshh marked this pull request as ready for review February 29, 2024 10:57
@aakoshh aakoshh merged commit 2bc4ed0 into main Feb 29, 2024
30 of 31 checks passed
@aakoshh aakoshh deleted the debug-slow-sync branch February 29, 2024 11:07
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

2 participants