isc.Log.logInfo logging performance issue with 12.0 compared to 10.0

[senordhuff]

Hi there,

I am continuing an in-depth investigation into why our application is performing more slowly with 12.0 compared to 10.0. I found something that looks like a smoking gun. It actually ended up being a debug line.

isc.Log.logInfo("in calculateSubGroupStatList, for subGroupProperty=" + subGroupObj.subGroupAssetProperty + " calculating subGroupStats...")

My dev console wasn't even set to display INFO statements. So, i wasn't seeing this in the dev console. But, the attempt to resolve subGroupObj.subGroupAssetProperty and turn it into a string was causing massive slowdowns for us in 12.0. When I change this line like this to force the property to a string, the performance impact is eliminnated

isc.Log.logInfo("in calculateSubGroupStatList, for subGroupProperty=" + subGroupObj.subGroupAssetProperty.toString() + " calculating subGroupStats...")


I can easily comb over my code and make sure we are not suffering from this penalty anywhere else. But, I wanted to ask if you know why this is happening in 12.0 when it doesn't in 10.0? Also curious if there is a way to avoid the penalty if the Dev Console settings are configured to not even display this message?

[Isomorphic]

What kind of object is being toString()’d there and what’s the output? Unless it’s an instance of a SmartClient class, SmartClient is not even involved. Further, explicitly calling toString() should be equivalent to not doing so. This really looks like measurement error.

Note that if you have a log statement that is expensive to prepare, you should guard it with a check for logIsInfoEnabled(). There is no way for us to optimize preparing of the log statement if that happens prior to calling our APIs.

[Blama]

Hi senordhuff,

w.r.t to you logging best practice question, there is this method, which can save you expensive logging calls: logIsInfoEnabled().
It uses the same technique for the same reason e.g. the Apache project uses here:

Performance is often a logging concern. By examining the appropriate property, a component can avoid expensive operations (producing information to be logged).

For example,
if (log.isDebugEnabled()) { ... do something expensive ... log.debug(theResult); }

Isomorphic:
The method in the docs mentions a default - this is not possible in Java.
Also, there is logIsInfoEnabled() and logIsDebugEnabled(), but no such methods for Echo and Warn.
Also, are log levels Error and Fatal reserved for internal components? These are not visible at all as methods.

Best regards
Blama

[Isomorphic]

Rather than suppressing warnings, applications should correct their usage. If you believe a warning is spurious, that should be reported to us as a bug, as the alternative of suppressing warnings could lead to suppressing other warnings which are not spurious.

There is no such thing as “echo” logging. There are “Echo”’ methods which produce strings that can be used in logs, or used for other purposes.

Yes, a fatal or error warning is the framework indicating a problem which is not a normal application error.

[senordhuff]

Hi there, so after more debugging trying to make sense of this, the problem I am seeing is related to the change with 12.0 where messages are now logged to the browser console in addition to the smartclient dev console:

isc.Log.addToMasterLog

if(window.console!=null&&isc.Log.showLogsInConsole!=false){
window.console.warn("*"+message)
}

So, a few follow up questions
1. Why log everything with "warn". My tests suggest that warn comes with a performance penalty because Chrome's console puts out a stacktrace with warn logs to the console. Why not enhance this to use console.info() when appropriate?
2. Why have this turned on by default? It took a lot of time to track this new behavior down and understand that having the Browser Console open was dramatically impacting performance since this was never a concern in previous versions of smartclient?
3. Why is showLogsInConsole a private API that developers have to hunt down in the source code? This seems like an important change where the developers should have clear control to turn this off.

[senordhuff]

Oh yes forgot to mention that it does appear that Chrome logging statements are slower as well when they have to convert a number to a string which was happening with my logging statements. So, you were correct that Smartclient is not involved in one sense but Smartclient is involved because it is now passing these statements to another system that was causing a performance impact.

[Isomorphic]

Reassuring that the toString() was not actually the problem.

It looks like what has actually introduced the problem here is recent changes in Chrome, which introduced a console variable which previously only existed in Firefox, and then added stack traces which are a very strange default, and are also slow.

We will work around Chrome’s issues here..

Can you confirm this slowdown is only occurring for developers who have Chrome’s developer tools open?

[senordhuff]

Thank you. yes, appears to only occur when the Chrome developer tools is open.

[Isomorphic]

We've switched off browser console reporting of SmartClient logs in Chrome going back to SGWT 10.1/SC 5.1p. The changes should be in today's builds dated 2018-07-25.

[senordhuff]

Hi there, I pulled down a more recent version of smartclient 12 since this thread last year and noticed that isc.Log.showLogsInConsole was commented out thus causing the logging to turn back on by default? I added this patch to my environment to avoid but thought you should know:
isc.Log.addClassProperties({
showLogsInConsole:false
});

[Isomorphic]

In our testing, this was no longer an inappropriate performance issue because we are no longer causing stack traces for info level logs.

Did you verify it was creating a performance issue for you before turning it off? Please let us know.

[senordhuff]

I did not verify the performance change. I prefer to have it off for now to leave the dev console uncluttered either way.