[Logging Improvement] Using lambda invocations instead of checking debug/trace isEnabled explicitly

[sandeshkr419]

Is your feature request related to a problem? Please describe.
Debug and trace logging presently makes a call to isDebugEnabled()/isTraceEnabled() before computing the strings inside the debug/trace logs. This is because those string concatenations are expensive operations and we don't want to unnecessarily compute them everytime.

OpenSearch % grep -r "isDebugEnabled()" * | wc -l
      76
OpenSearch % grep -r "isTraceEnabled()" * | wc -l
     122

Describe the solution you'd like

Present scenario:

if (logger.isTraceEnabled()) {
    logger.trace("Some long-running operation returned {}", expensiveOperation());
}

Replace the existing checking of trace/debug logging before actual logging with lambda invocations within the debug/trace loggers:

logger.trace("Some long-running operation returned {}", () -> expensiveOperation());

This achieves the same lazy logging without having to check for logger levels. the performance improvements won't be huge as we are letting go of a single isDebug/isTrace method call.

The improvements however may arise with the way we construct our strings in most of our logger messages. At multiple places, we utilize string concatenation using + operator which is inefficient, specifically at places where more than 2 strings are combined.
With this above proposed change, we can let go of unoptimized string interpolations (eg. string1 + string2 + string3, which creates multiple string objects upon each concatenation) to get more optimized string builder formats in logging (eg. "{}{}{}", ()->string1, ()->string2, ()->string3).

Added slight benefit of readability as well with no lingering checks of trace/debug and optimized string constructions, although this is least of a concern.

Describe alternatives you've considered
References used: https://logging.apache.org/log4j/2.0/manual/api.html#Java_8_lambda_support_for_lazy_logging

Additional context
Add any other context or screenshots about the feature request here.

Suggesting breaking the implementation into 2 phases:

1. Scrubbing away all the invocations to isDebugEnabled/isTraceEnabled and replacing them with lambda invocations.
2. Additionally, other log places should get rid of string concatenations using + operator and replace them with StringBuilder/placeholder formats.

[satti-hari-krishna-reddy]

Hi, I would like to work on this issue

[satti-hari-krishna-reddy]

Thank you @dblock for considering my request to be assigned this issue.

I reviewed the issue and the proposed optimization using lambda expressions.

1. Replace isDebugEnabled() and isTraceEnabled() with lambda invocations.
2. Additionally, replace string concatenations with placeholder formats.

There are 123 instances of isTraceEnabled() and 80 instances of isDebugEnabled() throughout the codebase when i searched in vscode .Should I apply this optimization to all occurrences of logger.isTraceEnabled() and logger.isDebugEnabled() throughout the codebase? This includes instances where tracer.isTraceEnabled() is used as well.Considering I'm new to open source contributions, would it be advisable to create separate pull requests for each change or a single pull request covering all instances?

[sandeshkr419]

Thanks @satti-hari-krishna-reddy for helping on this.

I think splitting the PR into 2 parts sounds better - first for isDebugEnabled() since there are less changes in this category, second for isTraceEnabled() sounds more reasonable since reviewers can help review changes faster.

Since you mentioned you are new to open source contributions, I'd suggest you start with a couple of places, and gather feedback/comments before making changes at all places. In this way, you wouldn't have to rework if there are major comments.

The readme / development guide in the codebase should be verbose enough to get you started but feel free to call out in your PRs if you need help.

[satti-hari-krishna-reddy]

I've been actively working on the logging improvement issue, and I'd like to share a sample change that I've made in the logging code.

Before:

if (logger.isDebugEnabled()) {
logger.debug("request [" + request.getMethod() + " " + node.getHost() + getUri(request) + "] failed", e);
}

After:

logger.debug("request [{} {} {}] failed", () -> request.getMethod(), () -> node.getHost(), () -> getUri(request), e);

I'm reaching out to seek feedback on this approach. Kindly let me know if this modification aligns well with the expected optimization

[sandeshkr419]

@satti-hari-krishna-reddy Thanks for the quick turn around.
This seems correct.
I'd suggest you work on a few code files, raise a draft PR, and work iteratively by adding more commits. Once all files are worked upon, you can switch it to a final PR. This way you can get versed in the process of fixing issues (specially if there are any test or CI failures) from the beginning instead of piling all the failures towards the end.

[satti-hari-krishna-reddy]

Hey @sandeshkr419 ,

Sorry for the delay, college work has been busy. Thanks for your feedback. I've created a draft PR (#9430 ) for the logging improvement issue as you suggested.

[flooxo]

Hey, since this is still an open issue, I wanted to ask if I could be of any help? :)