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

Use slf4j message formatter when possible or consider conditional logging #5514

Open
planetf1 opened this issue Jul 29, 2021 · 4 comments
Open
Assignees
Labels
logging logging, auditing performance Performance & Scalability/reliability related pinned Keep open (do not time out)

Comments

@planetf1
Copy link
Member

planetf1 commented Jul 29, 2021

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

@planetf1 planetf1 added the performance Performance & Scalability/reliability related label Jul 29, 2021
@mandy-chessell
Copy link
Contributor

mandy-chessell commented Jul 29, 2021

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
Copy link
Member Author

planetf1 commented Jul 29, 2021

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
Copy link
Member Author

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)

mandy-chessell added a commit to mandy-chessell/egeria that referenced this issue Aug 2, 2021
@planetf1 planetf1 added the logging logging, auditing label Aug 3, 2021
@github-actions
Copy link

github-actions bot commented Oct 3, 2021

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.

@github-actions github-actions bot added the no-issue-activity Issues automatically marked as stale because they have not had recent activity. label Oct 3, 2021
@planetf1 planetf1 added pinned Keep open (do not time out) and removed no-issue-activity Issues automatically marked as stale because they have not had recent activity. labels Oct 6, 2021
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
logging logging, auditing performance Performance & Scalability/reliability related pinned Keep open (do not time out)
Projects
No open projects
Development

No branches or pull requests

2 participants