Use slf4j message formatter when possible or consider conditional logging

[planetf1]

When debugging a performance issue using Java Profiler, I noticed a large number of string operations.

A big proportion of these is coming from ch.qos.logback.classic.Logger.debug(String) Logger.java

We are using slf4j, but logback is the bound implementation.

Whilst these are only in DEBUG log statements in many cases, the overhead of the string processing adds up, and in most cases the output is never used.

We could likely optimize a lot of these by using slf4j's own message formatter http://www.slf4j.org/api/org/slf4j/helpers/MessageFormatter.html since the processing will be skipped when logging isn't enabled

See http://www.slf4j.org/faq.html#logging_performance for a clearer explanation of best practices

Further investigation may help to evaluate which are the hottest areas & which optimization works best (given that some log statements use the results of other method calls, it's not just string ops)

To put this into context, jackson serialization/deserialization , valid string processing when dealing with properties, date handling in a request, are all 10x more significant in overall workload, as is Thread.setName() slightly which is called on each request

[mandy-chessell]

Should we be updating the thread name? This is done on entry and exit for a REST API call to add the server name and method name to the thread name so it appears in the diagnostics. If this is a significant performance overhead then probably not worth it.

This is a very cheap fix to do because the thread name update occurs in the org.odpi.openmetadata.commonservices.ffdc.RESTCallToken.

Looking further, it would be easy to add the test to see if debug is turned on before setting thread name and formatting the start/stop strings and calling log.debug(). This is in org.odpi.openmetadata.commonservices.ffdc.RESTCallLogger. If we did this then only the overhead of updating the thread name would occur if debug was turned on for the REST call class.

[planetf1]

I'm looking at this now, and see some inconsistency ie:

2021-07-29 14:12:46.433 DEBUG 65508 --- [ValueDefinition] o.o.o.a.d.s.ValidValuesRESTServices      : 12:Digital Architecture OMAS:myserver:createValidValueDefinition call invoked by myserverUserId
2021-07-29 14:12:46.815 DEBUG 65508 --- [nio-9443-exec-1] o.o.o.a.d.s.ValidValuesRESTServices      : 12:Digital Architecture OMAS:myserver:createValidValueDefinition call invoked by myserverUserId returned with response GUIDResponse{GUID='db608d0a-a81f-4f21-85d2-0d06b84f1569', exceptionClassName='null', exceptionCausedBy='null', actionDescription='null', relatedHTTPCode=200, exceptionErrorMessage='null', exceptionErrorMessageId='null', exceptionErrorMessageParameters=null, exceptionSystemAction='null', exceptionUserAction='null', exceptionProperties=null}; Duration: 0seconds

• in some cases the thread id is updated. My feeling would be to leave as is , but add another correlator in if needed (I also noticed in profiling that the updating of the thread id wasn't a cheap operation it seemed)
• For tracking a particular performance issue with valid values, knowing the thread id of the http executor is really important -- to see if there are any particular synchronization points (ie limited number of http executors) - the log entries here make this rather difficult. Though there is a request number (callId) which ties them together
• In this particular trace, the 'Duration' is set to '0 seconds' - needs checking

However the issue with slf4f formatting is a general one. The result is we are doing expensive string operations in some cases where tracing isn't enabled. Worth considering if we want to optimize or not (there's also an argument that making the debug performance similar to real performance is a good thing!)

[planetf1]

Agree on point of condition for RESTCallLogger - though the general slf4j point applies more broadly throughout the call. In a few places replaceable parms are used. Mostly they aren't (the condition check is just as valid and more flexible)

[github-actions[bot]]

This issue has been automatically marked as stale because it has not had recent activity. It will be closed in 20 days if no further activity occurs. Thank you for your contributions.