Refactor PassportLoggingHandler to reduce unnecessary heap allocation #1095
Conversation
| // Some logging of session states if certain criteria match: | ||
| if (LOG.isInfoEnabled()) { | ||
| if (passport.wasProxyAttempt()) { | ||
| StartAndEnd inReqToOutResp = passport.findFirstStartAndLastEndStates(PassportState.IN_REQ_HEADERS_RECEIVED, PassportState.OUT_REQ_LAST_CONTENT_SENT); |
There was a problem hiding this comment.
There is a if (LOG.isDebugEnabled()) { conditional at the top of this block.
| } else { | ||
| if (ctx != null && !isHealthcheckRequest(request)) { | ||
| // Why did we fail to attempt to proxy this request? | ||
| if (LOG.isDebugEnabled()) { |
There was a problem hiding this comment.
This is redundant, and no longer necessary with the log4j implementation of slf4j.
It'd actually make sense to clean up the conditionals here.
There was a problem hiding this comment.
The input to LOG.debug below is evaluated before the logger method itself does the log level check. The advice I received is to wrap the call with this conditional if we're constructing a log message dynamically.
There was a problem hiding this comment.
Hmm, I left a separate comment around string concat but there have been optimizations there.
It's difficult to discuss this without an allocation profile imo.
| if (passport.wasProxyAttempt()) { | ||
| StartAndEnd inReqToOutResp = passport.findFirstStartAndLastEndStates(PassportState.IN_REQ_HEADERS_RECEIVED, PassportState.OUT_REQ_LAST_CONTENT_SENT); | ||
| if (passport.calculateTimeBetween(inReqToOutResp) > WARN_REQ_PROCESSING_TIME_NS.get()) { | ||
| LOG.debug("Request processing took longer than threshold! toplevelid = " + topLevelRequestId + ", " |
There was a problem hiding this comment.
If we actually want to improve allocation, avoiding string concatenation is a much better low hanging fruit here imo.
There was a problem hiding this comment.
We want to primarily reduce logging noise, and secondarily improve allocation.
There was a problem hiding this comment.
The PR description calls out that this is for the purpose of reducing allocation.
There was a problem hiding this comment.
what would be a better alternative to not doing String concatenation, using a StringBuilder or StringBuffer to build the string only once and then LOG.debug once?
The "slow response/request processing" INFO level adds too much noise when a slow GC pause slows down our filter processing.
This PR: