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

Enhance logging with Async and high performance appenders #602

Merged
merged 7 commits into from
Apr 23, 2024

Conversation

AndreKurait
Copy link
Member

@AndreKurait AndreKurait commented Apr 23, 2024

Description

Move log4j2 appenders to high performance async loggers:

  • Existing logging was performed synchronous and blocking based on appender behavior. Moves this logic to be async with higher performance appender configuration.
  • Note: This will still eventually block on flushing out the appenders, but there will be a buffer between logging and io streams.
  • Existing Data Flow (All Blocking Calls):
    Application → Log4j2 Appender → Standard Out → ECSLogDriver → Cloudwatch Logs
  • New Data Flow (Blocking unless specified):
    Application → AsyncLogger (async)→ Log4j2 Appender → ECSLogDriver → Cloudwatch Logs

The AsyncLogger internally buffers so the rest can be "blocking" and still not block the application flow until it's internal queue is full

Enhance logging with microsecond clock and enhanced performance options
* Added precision on logging and moved console appender to direct reference instead of through standard output stream.

Add multilinePattern to log driver

Fixed some logging unreliable unit tests with specifying a synchronous logger.

Documentation on Proxy Behavior added in PR#595

  • Category: Enhancement/Bug Fix
  • Why these changes are required?
  • What is the old behavior before changes and new behavior after changes? In AWS, logs were one line per line, now combined (e.g. stack trace together). Now microsecond instead of millisecond timing. Higher throughput replayer when debug/trace logging is enabled.

Issues Resolved

MIGRATIONS-1663

Is this a backport? If so, please add backport PR # and/or commits #

Testing

Deployed to AWS and tested in high performance scenarios with high logging (Debug/Trace). Verified multiline behavior in AWS.

Check List

  • New functionality includes testing
    • All tests pass, including unit test, integration test and doctest
  • New functionality has been documented
  • Commits are signed per the DCO using --signoff

By submitting this pull request, I confirm that my contribution is made under the terms of the Apache 2.0 license.
For more information on following Developer Certificate of Origin and signing off your commits, please check here.

Copy link

codecov bot commented Apr 23, 2024

Codecov Report

All modified and coverable lines are covered by tests ✅

Project coverage is 75.94%. Comparing base (987125c) to head (643e8e9).
Report is 1 commits behind head on main.

Additional details and impacted files
@@             Coverage Diff              @@
##               main     #602      +/-   ##
============================================
- Coverage     76.02%   75.94%   -0.08%     
  Complexity     1494     1494              
============================================
  Files           162      162              
  Lines          6348     6348              
  Branches        572      572              
============================================
- Hits           4826     4821       -5     
- Misses         1145     1149       +4     
- Partials        377      378       +1     
Flag Coverage Δ
unittests 75.94% <ø> (-0.08%) ⬇️

Flags with carried forward coverage won't be shown. Click here to find out more.

☔ View full report in Codecov by Sentry.
📢 Have feedback on the report? Share it here.

Signed-off-by: Andre Kurait <akurait@amazon.com>
Signed-off-by: Andre Kurait <akurait@amazon.com>
Signed-off-by: Andre Kurait <akurait@amazon.com>
Signed-off-by: Andre Kurait <akurait@amazon.com>
Signed-off-by: Andre Kurait <akurait@amazon.com>
Signed-off-by: Andre Kurait <akurait@amazon.com>
appender.console.layout.pattern = [%-5level] %d{yyyy-MM-dd HH:mm:ss,SSS}{UTC} [%t] %c{1} - %msg%equals{ ctx=%mdc}{ ctx=\{\}}{}%n
appender.console.layout.pattern = [%-5level] %d{DEFAULT_MICROS}{UTC} [%t] %c{1} - %msg%equals{ ctx=%mdc}{ ctx=\{\}}{}%n
appender.console.direct = true
appender.console.includeLocation = true
Copy link
Collaborator

Choose a reason for hiding this comment

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

Can you elaborate on including this/why it's important?

https://logging.apache.org/log4j/2.x/manual/async.html#location-location-location

The performance impact of taking a stack trace snapshot is even higher for asynchronous loggers: logging with location is 30-100 times slower than without location.

Copy link
Member Author

Choose a reason for hiding this comment

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

Removed, had originally included it due to the %c{1} in our layout pattern, though reading now that %c means logger name whereas %C means class which would have necessitated location

implementation group: 'org.apache.logging.log4j', name: 'log4j-core', version: '2.23.1'
implementation group: 'org.apache.logging.log4j', name: 'log4j-slf4j2-impl', version: '2.23.1'
implementation group: 'org.slf4j', name: 'slf4j-api', version: '2.0.13'
implementation group: 'com.lmax', name: 'disruptor', version: '4.0.0'
Copy link
Collaborator

Choose a reason for hiding this comment

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

Mostly a side note -- it's very weird that Mend decided it didn't need to run on this push (see here). You're adding and updating dependencies!

Copy link
Member Author

Choose a reason for hiding this comment

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

Does it ever run on a PR, or only once it's merged?

A scan is initiated via a valid GitHub 'push' command. A valid 'push' command...

Copy link
Collaborator

Choose a reason for hiding this comment

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

Yeah, usually I can see the results when I modify build.gradle files before merging. But it's currently doing this same thing to me on the werkzeug PR.

But definitely not a blocker for this!

Signed-off-by: Andre Kurait <akurait@amazon.com>
@AndreKurait AndreKurait merged commit d8b4ba8 into opensearch-project:main Apr 23, 2024
7 of 8 checks passed
@AndreKurait AndreKurait deleted the EnhancedLogging branch April 23, 2024 22:57
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.

3 participants