Speedup EventBus.PublishEventTx #2869

ValarDragon · 2024-04-23T06:49:40Z

Feature Request

Summary

In a block sync of 5000 blocks on Osmosis mainnet, we see 23 seconds out of 1050 in EventBus.PublishEventTx (2.1% of the ApplyBlock time), this should likely also impact live syncing blocks as it affects ApplyBlock.

Most of this time is time that doesn't even need to be spent!

Proposal

First notice that we spend 10.4 seconds in zerologger.With which is only here! However in the function we pass it into here, that time is only used in Debug logs. So we should just refactor the API's to only pay that cost if we are in debug mode. We just need to refactor that API to pass the base logger in, and only do the With call as a LazyLogger I think, that also only gets called if we are in that error case.
The fmt.Sprintf call taking 3.5 seocnds here should be able to live in a cache, since there should be a small number of composite tags. Perhaps we add an LRU cache of size (say) 20000 to cache these?

We should be able to speed this up notably more beyond these two improvements, but figured it may be worth writing up these two and getting it deployed in benchmarks first

The text was updated successfully, but these errors were encountered:

…#2911) Component of #2869 This on its own is an expected 1% speedup to blocksync on osmosis mainnet right now. I originally considered keeping the log lines but with only creating the logger cost if there is an error, but these are debug logs I've never seen. I think its better to just remove these debug logs directly, rather than worry about maintaining them. These aren't even that concerning scenarios I feel like, as more of the stack moves away from these. --- #### PR checklist - [x] Tests written/updated - Covered by existing tests - [x] Changelog entry added in `.changelog` (we use [unclog](https://github.com/informalsystems/unclog) to manage our changelog) - [X] Updated relevant documentation (`docs/` or `spec/`) and code comments - [X] Title follows the [Conventional Commits](https://www.conventionalcommits.org/en/v1.0.0/) spec

…#2911) Component of #2869 This on its own is an expected 1% speedup to blocksync on osmosis mainnet right now. I originally considered keeping the log lines but with only creating the logger cost if there is an error, but these are debug logs I've never seen. I think its better to just remove these debug logs directly, rather than worry about maintaining them. These aren't even that concerning scenarios I feel like, as more of the stack moves away from these. --- #### PR checklist - [x] Tests written/updated - Covered by existing tests - [x] Changelog entry added in `.changelog` (we use [unclog](https://github.com/informalsystems/unclog) to manage our changelog) - [X] Updated relevant documentation (`docs/` or `spec/`) and code comments - [X] Title follows the [Conventional Commits](https://www.conventionalcommits.org/en/v1.0.0/) spec (cherry picked from commit ce68e90) # Conflicts: # types/event_bus.go

…#2911) Component of #2869 This on its own is an expected 1% speedup to blocksync on osmosis mainnet right now. I originally considered keeping the log lines but with only creating the logger cost if there is an error, but these are debug logs I've never seen. I think its better to just remove these debug logs directly, rather than worry about maintaining them. These aren't even that concerning scenarios I feel like, as more of the stack moves away from these. --- #### PR checklist - [x] Tests written/updated - Covered by existing tests - [x] Changelog entry added in `.changelog` (we use [unclog](https://github.com/informalsystems/unclog) to manage our changelog) - [X] Updated relevant documentation (`docs/` or `spec/`) and code comments - [X] Title follows the [Conventional Commits](https://www.conventionalcommits.org/en/v1.0.0/) spec (cherry picked from commit ce68e90)

…#2911) Component of #2869 This on its own is an expected 1% speedup to blocksync on osmosis mainnet right now. I originally considered keeping the log lines but with only creating the logger cost if there is an error, but these are debug logs I've never seen. I think its better to just remove these debug logs directly, rather than worry about maintaining them. These aren't even that concerning scenarios I feel like, as more of the stack moves away from these. --- #### PR checklist - [x] Tests written/updated - Covered by existing tests - [x] Changelog entry added in `.changelog` (we use [unclog](https://github.com/informalsystems/unclog) to manage our changelog) - [X] Updated relevant documentation (`docs/` or `spec/`) and code comments - [X] Title follows the [Conventional Commits](https://www.conventionalcommits.org/en/v1.0.0/) spec (cherry picked from commit ce68e90) # Conflicts: # types/event_bus.go

… (backport #2911) (#2935) Component of #2869 This on its own is an expected 1% speedup to blocksync on osmosis mainnet right now. I originally considered keeping the log lines but with only creating the logger cost if there is an error, but these are debug logs I've never seen. I think its better to just remove these debug logs directly, rather than worry about maintaining them. These aren't even that concerning scenarios I feel like, as more of the stack moves away from these. --- #### PR checklist - [x] Tests written/updated - Covered by existing tests - [x] Changelog entry added in `.changelog` (we use [unclog](https://github.com/informalsystems/unclog) to manage our changelog) - [X] Updated relevant documentation (`docs/` or `spec/`) and code comments - [X] Title follows the [Conventional Commits](https://www.conventionalcommits.org/en/v1.0.0/) spec <hr>This is an automatic backport of pull request #2911 done by [Mergify](https://mergify.com). Co-authored-by: Dev Ojha <ValarDragon@users.noreply.github.com>

… (backport #2911) (#2936) Component of #2869 This on its own is an expected 1% speedup to blocksync on osmosis mainnet right now. I originally considered keeping the log lines but with only creating the logger cost if there is an error, but these are debug logs I've never seen. I think its better to just remove these debug logs directly, rather than worry about maintaining them. These aren't even that concerning scenarios I feel like, as more of the stack moves away from these. --- #### PR checklist - [x] Tests written/updated - Covered by existing tests - [x] Changelog entry added in `.changelog` (we use [unclog](https://github.com/informalsystems/unclog) to manage our changelog) - [X] Updated relevant documentation (`docs/` or `spec/`) and code comments - [X] Title follows the [Conventional Commits](https://www.conventionalcommits.org/en/v1.0.0/) spec <hr>This is an automatic backport of pull request #2911 done by [Mergify](https://mergify.com). --------- Co-authored-by: Dev Ojha <ValarDragon@users.noreply.github.com> Co-authored-by: Andy Nogueira <me@andynogueira.dev>

… (backport #2911) (#2937) Component of #2869 This on its own is an expected 1% speedup to blocksync on osmosis mainnet right now. I originally considered keeping the log lines but with only creating the logger cost if there is an error, but these are debug logs I've never seen. I think its better to just remove these debug logs directly, rather than worry about maintaining them. These aren't even that concerning scenarios I feel like, as more of the stack moves away from these. --- #### PR checklist - [x] Tests written/updated - Covered by existing tests - [x] Changelog entry added in `.changelog` (we use [unclog](https://github.com/informalsystems/unclog) to manage our changelog) - [X] Updated relevant documentation (`docs/` or `spec/`) and code comments - [X] Title follows the [Conventional Commits](https://www.conventionalcommits.org/en/v1.0.0/) spec <hr>This is an automatic backport of pull request #2911 done by [Mergify](https://mergify.com). --------- Co-authored-by: Dev Ojha <ValarDragon@users.noreply.github.com> Co-authored-by: Andy Nogueira <me@andynogueira.dev>

adizere · 2024-05-01T14:37:36Z

closed by #2911

ValarDragon · 2024-05-01T17:27:06Z

No we should re-open this, that PR only closed the first checkbox of this issue!

andynog · 2024-05-02T12:50:01Z

Re-opened as per @ValarDragon comment

… (backport cometbft#2911) (cometbft#2937) Component of cometbft#2869 This on its own is an expected 1% speedup to blocksync on osmosis mainnet right now. I originally considered keeping the log lines but with only creating the logger cost if there is an error, but these are debug logs I've never seen. I think its better to just remove these debug logs directly, rather than worry about maintaining them. These aren't even that concerning scenarios I feel like, as more of the stack moves away from these. --- #### PR checklist - [x] Tests written/updated - Covered by existing tests - [x] Changelog entry added in `.changelog` (we use [unclog](https://github.com/informalsystems/unclog) to manage our changelog) - [X] Updated relevant documentation (`docs/` or `spec/`) and code comments - [X] Title follows the [Conventional Commits](https://www.conventionalcommits.org/en/v1.0.0/) spec <hr>This is an automatic backport of pull request cometbft#2911 done by [Mergify](https://mergify.com). --------- Co-authored-by: Dev Ojha <ValarDragon@users.noreply.github.com> Co-authored-by: Andy Nogueira <me@andynogueira.dev>

… (backport cometbft#2911) (cometbft#2937) (#38) Component of cometbft#2869 This on its own is an expected 1% speedup to blocksync on osmosis mainnet right now. I originally considered keeping the log lines but with only creating the logger cost if there is an error, but these are debug logs I've never seen. I think its better to just remove these debug logs directly, rather than worry about maintaining them. These aren't even that concerning scenarios I feel like, as more of the stack moves away from these. --- #### PR checklist - [x] Tests written/updated - Covered by existing tests - [x] Changelog entry added in `.changelog` (we use [unclog](https://github.com/informalsystems/unclog) to manage our changelog) - [X] Updated relevant documentation (`docs/` or `spec/`) and code comments - [X] Title follows the [Conventional Commits](https://www.conventionalcommits.org/en/v1.0.0/) spec <hr>This is an automatic backport of pull request cometbft#2911 done by [Mergify](https://mergify.com). --------- Co-authored-by: mergify[bot] <37929162+mergify[bot]@users.noreply.github.com> Co-authored-by: Dev Ojha <ValarDragon@users.noreply.github.com> Co-authored-by: Andy Nogueira <me@andynogueira.dev>

… (backport cometbft#2911) (cometbft#2937) (#38) Component of cometbft#2869 This on its own is an expected 1% speedup to blocksync on osmosis mainnet right now. I originally considered keeping the log lines but with only creating the logger cost if there is an error, but these are debug logs I've never seen. I think its better to just remove these debug logs directly, rather than worry about maintaining them. These aren't even that concerning scenarios I feel like, as more of the stack moves away from these. --- #### PR checklist - [x] Tests written/updated - Covered by existing tests - [x] Changelog entry added in `.changelog` (we use [unclog](https://github.com/informalsystems/unclog) to manage our changelog) - [X] Updated relevant documentation (`docs/` or `spec/`) and code comments - [X] Title follows the [Conventional Commits](https://www.conventionalcommits.org/en/v1.0.0/) spec <hr>This is an automatic backport of pull request cometbft#2911 done by [Mergify](https://mergify.com). --------- Co-authored-by: mergify[bot] <37929162+mergify[bot]@users.noreply.github.com> Co-authored-by: Dev Ojha <ValarDragon@users.noreply.github.com> Co-authored-by: Andy Nogueira <me@andynogueira.dev> (cherry picked from commit a9991fd)

… (backport cometbft#2911) (cometbft#2937) (#38) (#44) Component of cometbft#2869 This on its own is an expected 1% speedup to blocksync on osmosis mainnet right now. I originally considered keeping the log lines but with only creating the logger cost if there is an error, but these are debug logs I've never seen. I think its better to just remove these debug logs directly, rather than worry about maintaining them. These aren't even that concerning scenarios I feel like, as more of the stack moves away from these. --- #### PR checklist - [x] Tests written/updated - Covered by existing tests - [x] Changelog entry added in `.changelog` (we use [unclog](https://github.com/informalsystems/unclog) to manage our changelog) - [X] Updated relevant documentation (`docs/` or `spec/`) and code comments - [X] Title follows the [Conventional Commits](https://www.conventionalcommits.org/en/v1.0.0/) spec <hr>This is an automatic backport of pull request cometbft#2911 done by [Mergify](https://mergify.com). --------- Co-authored-by: mergify[bot] <37929162+mergify[bot]@users.noreply.github.com> Co-authored-by: Dev Ojha <ValarDragon@users.noreply.github.com> Co-authored-by: Andy Nogueira <me@andynogueira.dev> (cherry picked from commit a9991fd) Co-authored-by: Adam Tucker <adam@osmosis.team>

… (backport cometbft#2911) (cometbft#2937) (#38) (#45) Component of cometbft#2869 This on its own is an expected 1% speedup to blocksync on osmosis mainnet right now. I originally considered keeping the log lines but with only creating the logger cost if there is an error, but these are debug logs I've never seen. I think its better to just remove these debug logs directly, rather than worry about maintaining them. These aren't even that concerning scenarios I feel like, as more of the stack moves away from these. --- #### PR checklist - [x] Tests written/updated - Covered by existing tests - [x] Changelog entry added in `.changelog` (we use [unclog](https://github.com/informalsystems/unclog) to manage our changelog) - [X] Updated relevant documentation (`docs/` or `spec/`) and code comments - [X] Title follows the [Conventional Commits](https://www.conventionalcommits.org/en/v1.0.0/) spec <hr>This is an automatic backport of pull request cometbft#2911 done by [Mergify](https://mergify.com). --------- Co-authored-by: mergify[bot] <37929162+mergify[bot]@users.noreply.github.com> Co-authored-by: Dev Ojha <ValarDragon@users.noreply.github.com> Co-authored-by: Andy Nogueira <me@andynogueira.dev> (cherry picked from commit a9991fd) Co-authored-by: Adam Tucker <adam@osmosis.team>

ValarDragon added enhancement New feature or request needs-triage This issue/PR has not yet been triaged by the team. labels Apr 23, 2024

ValarDragon mentioned this issue Apr 27, 2024

perf(event bus): Remove expensive Logger debug call in PublishEventTx #2911

Merged

4 tasks

adizere added this to CometBFT Apr 29, 2024

github-project-automation bot moved this to Todo in CometBFT Apr 29, 2024

adizere added this to the 2024-Q2 milestone Apr 29, 2024

mergify bot mentioned this issue Apr 29, 2024

perf(event bus): Remove expensive Logger debug call in PublishEventTx (backport #2911) #2935

Merged

4 tasks

This was referenced Apr 29, 2024

perf(event bus): Remove expensive Logger debug call in PublishEventTx (backport #2911) #2936

Merged

perf(event bus): Remove expensive Logger debug call in PublishEventTx (backport #2911) #2937

Merged

adizere closed this as completed May 1, 2024

github-project-automation bot moved this from Todo to Done in CometBFT May 1, 2024

andynog reopened this May 2, 2024

czarcas7ic mentioned this issue May 2, 2024

perf(event bus): Remove expensive Logger debug call in PublishEventTx… osmosis-labs/cometbft#38

Merged

7 tasks

This was referenced May 2, 2024

perf(event bus): Remove expensive Logger debug call in PublishEventTx… (backport #38) osmosis-labs/cometbft#44

Merged

perf(event bus): Remove expensive Logger debug call in PublishEventTx… (backport #38) osmosis-labs/cometbft#45

Merged

adizere modified the milestones: 2024-Q2, 2024-Q3 Jul 18, 2024

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Uh oh!

Speedup EventBus.PublishEventTx #2869

Speedup EventBus.PublishEventTx #2869

Uh oh!

Uh oh!

Uh oh!

Speedup EventBus.PublishEventTx #2869

Speedup EventBus.PublishEventTx #2869

Comments

Uh oh!

Feature Request

Summary

Proposal

Uh oh!

Uh oh!

Uh oh!