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

Fix performance issue caused by invalid logging configuration #8908

Merged
merged 1 commit into from
Dec 11, 2020

Conversation

lhotari
Copy link
Member

@lhotari lhotari commented Dec 11, 2020

Motivation

Profiling a 3 node Pulsar cluster running with 2.7.0 version showed allocation hotspots in log.debug methods. This indicated that the root logger level was set to debug.

Modifications

  • Configure the root log level in bin/pulsar startup script to
    use info level by default. This can be done by setting
    the pulsar.log.root.level system property.

  • since the root log level was debug, all code blocks within
    log.isDebugEnabled() got executed.
    This caused a lot of unnecessary memory allocations and wasted CPU cycles.

- Configure the root log level in bin/pulsar startup script to
  use "info" level by default. This can be done by setting
  the "pulsar.log.root.level" system property.

- since the root log level was debug, all code blocks within
  log.isDebugEnabled() got executed.
  This caused a lot of unnecessary memory allocations and wasted CPU cycles.
@lhotari
Copy link
Member Author

lhotari commented Dec 11, 2020

Here's an allocation flamegraph for ManagedLedgerImpl.asyncReadEntries method.

Pulsar 2.7.0, a lot of logging calls are present:

image

After applying this fix, the logging calls are gone:

image

@lhotari
Copy link
Member Author

lhotari commented Dec 11, 2020

/pulsarbot run-failure-checks

@merlimat merlimat added the type/bug The PR fixed a bug or issue reported a bug label Dec 11, 2020
@merlimat merlimat added this to the 2.8.0 milestone Dec 11, 2020
@lhotari
Copy link
Member Author

lhotari commented Dec 11, 2020

/pulsarbot run-failure-checks

Copy link
Contributor

@eolivelli eolivelli left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Good catch!

+1

@sijie sijie merged commit 18f539e into apache:master Dec 11, 2020
@lhotari
Copy link
Member Author

lhotari commented Dec 12, 2020

This fix would be needed on branch-2.6 . There's a reported issue #8875 about excessive GC

@lhotari
Copy link
Member Author

lhotari commented Dec 13, 2020

Related to log4j2 configuration and performance optimizations, there's a separate pull request to enable Log4j2's Garbage Free logging mode: #8944 . The Garbage Free logging mode hasn't been used by now. PR #8944 will fix this and enable Log4j2's Garbage Free logging mode.

@codelipenghui codelipenghui added the cherry-picked/branch-2.7 Archived: 2.7 is end of life label Dec 21, 2020
codelipenghui pushed a commit that referenced this pull request Dec 21, 2020
### Motivation

Profiling a 3 node Pulsar cluster running with 2.7.0 version showed allocation hotspots in `log.debug` methods. This indicated that the root logger level was set to debug.

### Modifications

- Configure the root log level in `bin/pulsar` startup script to
  use `info` level by default. This can be done by setting
  the `pulsar.log.root.level` system property.

- since the root log level was debug, all code blocks within
  `log.isDebugEnabled()` got executed.
  This caused a lot of unnecessary memory allocations and wasted CPU cycles.

(cherry picked from commit 18f539e)
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
cherry-picked/branch-2.7 Archived: 2.7 is end of life release/2.7.1 type/bug The PR fixed a bug or issue reported a bug
Projects
None yet
Development

Successfully merging this pull request may close these issues.

5 participants