java.awt event processing performance degradation on JRE7 - linux

[Anthony Petrov]

Hi Nicolas,

The fix looks good to me, too. I've published a webrev at:

http://cr.openjdk.java.net/~anthony/8-30-doLog-7163898.0/

and in fact I've just pushed it:

http://hg.openjdk.java.net/jdk8/awt/jdk/rev/9ed029a0326d

Thank you very much for the contribution!

--
best regards,
Anthony

On 4/23/2012 10:06 AM, Nicolas Carranza wrote:
> hi Anthony,
> 
> The little patch against the current
> http://hg.openjdk.java.net/jdk8/jdk8/jdk repo is attached.
> Running:
>   time -f '%P' java PerformanceRegressionTest2 useLogging
> 3 times using the (JRE 1.7.0_03-b04 + escapeDoLog.patch) gives the
> following CPU usages: 14%, 13%, 13%.
>  
> Please let me know if I can be of further help.
> 
> Cheers,
> Nicolas
> 
> On 04/18/2012 05:08 AM, Anthony Petrov wrote:
>> Hi Nicolas,
>>
>> Frederico's patch is needed - with that patch we avoid string
>> concatenation operations in XAWT code if logging has been disabled.
>> These operations caused heavy memory usage, and eliminating them
>> resolved the issue reported by Frederico. We don't want to revert that
>> patch. In fact, I think that analyzing AWT logging code on other
>> platforms (Windows and Mac) and developing a similar fix for them
>> makes very much sense as well.
>>
>> However, your suggestion is also valid. This is because in cases when
>> we don't build complex strings for logging in AWT code, we don't
>> usually guard such logging statements with if (...loggable...) checks.
>> Your suggested change will address these specific cases, too, by
>> eliminating some internal string building operations in the logger
>> code itself, thus boosting performance even further.
>>
>> Could you prepare a patch please, test it, and send it out for a review?
>>
>> -- 
>> best regards,
>> Anthony
>>
>> On 4/18/2012 5:01 AM, Nicolas Carranza wrote:
>>> Federico's patch solves  the performance regression (see:
>>> http://mail.openjdk.java.net/pipermail/jdk7u-dev/2012-April/002694.html
>>> ). But instead of this patch I find better to change the PlatformLogger
>>> class: insert "if(!isLoggable(level)) return;" at the beginning of the
>>> method sun.util.logging.PlatformLogger.JavaLogger.doLog(int level,
>>> String msg, Object... params) . The string convertion affecting the
>>> performance is done on the PlatformLogger.JavaLogger.doLog (even when
>>> the message is not loggable) and it is there where the problem should be
>>> fixed (to be more clear and also cover more use cases). Fixing it there
>>> also clears why the performance regression does not happen when
>>> redirectPlatformLoggers has not been called (when logging is not used):
>>> PlatformLogger.LoggerProxy.doLog(int level, String msg, Object...
>>> params) does not do the string convertion  when the message is not
>>> loggable.
>>>
>>> Federico's patch has already been pushed to the jdk8 repository, when
>>> will it be applied to jdk7 (or my propossed change if it is preferred)?
>>>
>>> [ Here is a jvisualvm memory profiling snapshot of
>>> PerformanceRegresionTest3:
>>> http://www.java.net/forum/topic/performance/general-performance-discussion/jre7s-javaawt-performance-degradation-caused-javautillogging-linux#comment-823486
>>>
>>> . ]
>>>
>>> Cheers,
>>> Nicolas
>>>
>>> On 04/16/2012 09:40 PM, Mandy Chung wrote:
>>>> Nicolas,
>>>>
>>>> Thanks for reporting the problem.   I am curious if you have collected
>>>> any profiling data that shows
>>>> sun.util.logging.PlatformLogger.redirectPlatformLoggers() is the cause
>>>> of the performance degradation.  This redirection is done as part of
>>>> the logging initialization before JFrame is initialized.  Since the
>>>> performance degradation you observed is after the JFrame has been
>>>> instantiated, it could be something else.  If it's logging-related, it
>>>> would be sun.util.logging.PlatformLogger.
>>>>
>>>> Mandy
>>>>
>>>> On 4/16/2012 6:18 AM, Daniel D. Daugherty wrote:
>>>>> java.util.logging is currently handled by the Serviceability Team.
>>>>> Adding that alias to this e-mail thread...
>>>>>
>>>>> Dan
>>>>>
>>>>>
>>>>> On 4/16/12 12:17 AM, Nicolas Carranza wrote:
>>>>>> Moving the mouse pointer over a java.awt.Window using JRE7 consumes
>>>>>> aprox. twice the CPU time as with JRE6 when logging is used (when a
>>>>>> call
>>>>>> to java.util.logging.getLogger(String)---even without using the
>>>>>> returned
>>>>>> Logger--- has been done). Keyboard key event processing suffers the
>>>>>> same
>>>>>> performance penalty. For steps to reproduce this problem please look
>>>>>> at:
>>>>>> http://www.java.net/forum/topic/performance/general-performance-discussion/jre7s-javaawt-performance-degradation-caused-javautillogging-linux
>>>>>>
>>>>>>
>>>>>> .
>>>>>>
>>>>>> The performance degradation seems to be "enabled" by the call of
>>>>>> sun.util.logging.PlatformLogger.redirectPlatformLoggers() done inside
>>>>>> java.util.LogManager.readPrimorialConfiguration() on JRE7. Call
>>>>>> chain:
>>>>>> Logger.getLogger()->LogManager.getLogManager()->
>>>>>> LogManager.readPrimordialConfiguration()->sun.util.logging.PlatformLogger.redirectPlatformLoggers().
>>>>>>
>>>>>>
>>>>>>
>>>>>> This call is not made on JRE6. If this problem is not easy to solve
>>>>>> then
>>>>>> I guess is better to remove this call from JRE7's
>>>>>> readPrimordialConfiguration as it does more harm than good.
>>>>>>
>>>>>> Please let me know if there is a better place to report this
>>>>>> problem. A
>>>>>> couple of weeks ago I "opened" a bug report on bugs.sun.com but I
>>>>>> received no response at all.
>>>>>>
>>>>>> Cheers,
>>>>>> Nicolas
>