[jira] [Created] (LOG4J2-812) Blocking state: org.apache​.loggin.lo​g4j.core.p​attern.Dat​ePatternCo​nverter

[Mohit Anchlia (JIRA)]

Mohit Anchlia created LOG4J2-812:
------------------------------------

Summary: Blocking state: org.apache​.loggin.lo​g4j.core.p​attern.Dat​ePatternCo​nverter
Key: LOG4J2-812
URL: https://issues.apache.org/jira/browse/LOG4J2-812
Project: Log4j 2
Issue Type: Bug
Affects Versions: 2.0.2
Reporter: Mohit Anchlia


Threads seem to be blocking on class org.apache​.loggin.lo​g4j.core.p​attern.Dat​ePatternCo​nverter. It's short lived but is visible in profiler. It also is adding on to CPU. Here is the mail conversation on the mailing list:

-------------


Ralph Goers ***@dslextreme.com via logging.apache.org


4:28 PM (10 minutes ago)








to Log4J










The converter uses a SimpleDateFormat which is not thread safe and so is synchronized. I am sure there might be minor optimizations that could be done to this

What I would do is modify DatePatternConverter to
a) use Java 8’s java.time.format.DateTimeFormatter if running on Java 8
b) use Joda Time’s DateTimeFormat if it is present.
c) create a pool of SimpleDateFormat objects and use those.

Please create a Jira issue for this.

Ralph



--
This message was sent by Atlassian JIRA
(v6.3.4#6332)

[Remko Popma (JIRA)]

[ https://issues.apache.org/jira/browse/LOG4J2-812?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]

Remko Popma updated LOG4J2-812:
-------------------------------
Assignee: Remko Popma
Summary: Performance optimization: avoid use of synchronized SimpleDateFormat in Dat​ePatternCo​nverter (was: Blocking state: org.apache​.loggin.lo​g4j.core.p​attern.Dat​ePatternCo​nverter )

Performance optimization: avoid use of synchronized SimpleDateFormat in Dat​ePatternCo​nverter
-----------------------------------------------------------------------------------------------
Key: LOG4J2-812
URL: https://issues.apache.org/jira/browse/LOG4J2-812
Project: Log4j 2
Issue Type: Bug
Affects Versions: 2.0.2
Reporter: Mohit Anchlia
Assignee: Remko Popma
-------------
4:28 PM (10 minutes ago)
to Log4J
The converter uses a SimpleDateFormat which is not thread safe and so is synchronized. I am sure there might be minor optimizations that could be done to this
What I would do is modify DatePatternConverter to
a) use Java 8’s java.time.format.DateTimeFormatter if running on Java 8
b) use Joda Time’s DateTimeFormat if it is present.
c) create a pool of SimpleDateFormat objects and use those.
Please create a Jira issue for this.
Ralph

--
This message was sent by Atlassian JIRA
(v6.3.4#6332)

[Remko Popma (JIRA)]

[ https://issues.apache.org/jira/browse/LOG4J2-812?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]

Remko Popma updated LOG4J2-812:
-------------------------------
Description:
Threads seem to be blocking on class org.apache​.loggin.lo​g4j.core.p​attern.Dat​ePatternCo​nverter. It's short lived but is visible in profiler. It also is adding on to CPU. Here is the mail conversation on the mailing list:

{quote}
Ralph Goers ***@dslextreme.com via logging.apache.org

The converter uses a SimpleDateFormat which is not thread safe and so is synchronized. I am sure there might be minor optimizations that could be done to this

What I would do is modify DatePatternConverter to
a) use Java 8’s java.time.format.DateTimeFormatter if running on Java 8
b) use Joda Time’s DateTimeFormat if it is present.
c) create a pool of SimpleDateFormat objects and use those.

Please create a Jira issue for this.

Ralph
{quote}
----

One alternative that was suggested on the mailing list is to use commons lang FastDateFormat to format log timestamps.



was:
Threads seem to be blocking on class org.apache​.loggin.lo​g4j.core.p​attern.Dat​ePatternCo​nverter. It's short lived but is visible in profiler. It also is adding on to CPU. Here is the mail conversation on the mailing list:

-------------


Ralph Goers ***@dslextreme.com via logging.apache.org


4:28 PM (10 minutes ago)








to Log4J










The converter uses a SimpleDateFormat which is not thread safe and so is synchronized. I am sure there might be minor optimizations that could be done to this

What I would do is modify DatePatternConverter to
a) use Java 8’s java.time.format.DateTimeFormatter if running on Java 8
b) use Joda Time’s DateTimeFormat if it is present.
c) create a pool of SimpleDateFormat objects and use those.

Please create a Jira issue for this.

Ralph

Post by Remko Popma (JIRA)
Performance optimization: avoid use of synchronized SimpleDateFormat in Dat​ePatternCo​nverter
-----------------------------------------------------------------------------------------------
Key: LOG4J2-812
URL: https://issues.apache.org/jira/browse/LOG4J2-812
Project: Log4j 2
Issue Type: Bug
Affects Versions: 2.0.2
Reporter: Mohit Anchlia
Assignee: Remko Popma
{quote}
The converter uses a SimpleDateFormat which is not thread safe and so is synchronized. I am sure there might be minor optimizations that could be done to this
What I would do is modify DatePatternConverter to
a) use Java 8’s java.time.format.DateTimeFormatter if running on Java 8
b) use Joda Time’s DateTimeFormat if it is present.
c) create a pool of SimpleDateFormat objects and use those.
Please create a Jira issue for this.
Ralph
{quote}
----
One alternative that was suggested on the mailing list is to use commons lang FastDateFormat to format log timestamps.

--
This message was sent by Atlassian JIRA
(v6.3.4#6332)

[Remko Popma (JIRA)]

[ https://issues.apache.org/jira/browse/LOG4J2-812?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]

Remko Popma updated LOG4J2-812:
-------------------------------
Fix Version/s: 2.2

Post by Remko Popma (JIRA)
Performance optimization: avoid use of synchronized SimpleDateFormat in Dat​ePatternCo​nverter
-----------------------------------------------------------------------------------------------
Key: LOG4J2-812
URL: https://issues.apache.org/jira/browse/LOG4J2-812
Project: Log4j 2
Issue Type: Bug
Affects Versions: 2.0.2
Reporter: Mohit Anchlia
Assignee: Remko Popma
Fix For: 2.2
{quote}
The converter uses a SimpleDateFormat which is not thread safe and so is synchronized. I am sure there might be minor optimizations that could be done to this
What I would do is modify DatePatternConverter to
a) use Java 8’s java.time.format.DateTimeFormatter if running on Java 8
b) use Joda Time’s DateTimeFormat if it is present.
c) create a pool of SimpleDateFormat objects and use those.
Please create a Jira issue for this.
Ralph
{quote}
----
One alternative that was suggested on the mailing list is to use commons lang FastDateFormat to format log timestamps.

--
This message was sent by Atlassian JIRA
(v6.3.4#6332)

[Remko Popma (JIRA)]

[ https://issues.apache.org/jira/browse/LOG4J2-812?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]

Remko Popma updated LOG4J2-812:
-------------------------------
Component/s: Performance Benchmarks
Pattern Converters

Post by Remko Popma (JIRA)
Performance optimization: avoid use of synchronized SimpleDateFormat in Dat​ePatternCo​nverter
-----------------------------------------------------------------------------------------------
Key: LOG4J2-812
URL: https://issues.apache.org/jira/browse/LOG4J2-812
Project: Log4j 2
Issue Type: Bug
Components: Pattern Converters, Performance Benchmarks
Affects Versions: 2.0.2
Reporter: Mohit Anchlia
Assignee: Remko Popma
Fix For: 2.2
{quote}
The converter uses a SimpleDateFormat which is not thread safe and so is synchronized. I am sure there might be minor optimizations that could be done to this
What I would do is modify DatePatternConverter to
a) use Java 8’s java.time.format.DateTimeFormatter if running on Java 8
b) use Joda Time’s DateTimeFormat if it is present.
c) create a pool of SimpleDateFormat objects and use those.
Please create a Jira issue for this.
Ralph
{quote}
----
One alternative that was suggested on the mailing list is to use commons lang FastDateFormat to format log timestamps.

--
This message was sent by Atlassian JIRA
(v6.3.4#6332)

[Gary Gregory (JIRA)]

[ https://issues.apache.org/jira/browse/LOG4J2-812?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=14147255#comment-14147255 ]

Gary Gregory commented on LOG4J2-812:
-------------------------------------

d) Use a thread local to for the formatter

Post by Remko Popma (JIRA)
Performance optimization: avoid use of synchronized SimpleDateFormat in Dat​ePatternCo​nverter
-----------------------------------------------------------------------------------------------
Key: LOG4J2-812
URL: https://issues.apache.org/jira/browse/LOG4J2-812
Project: Log4j 2
Issue Type: Bug
Components: Pattern Converters, Performance Benchmarks
Affects Versions: 2.0.2
Reporter: Mohit Anchlia
Assignee: Remko Popma
Fix For: 2.2
{quote}
The converter uses a SimpleDateFormat which is not thread safe and so is synchronized. I am sure there might be minor optimizations that could be done to this
What I would do is modify DatePatternConverter to
a) use Java 8’s java.time.format.DateTimeFormatter if running on Java 8
b) use Joda Time’s DateTimeFormat if it is present.
c) create a pool of SimpleDateFormat objects and use those.
Please create a Jira issue for this.
Ralph
{quote}
----
One alternative that was suggested on the mailing list is to use commons lang FastDateFormat to format log timestamps.

--
This message was sent by Atlassian JIRA
(v6.3.4#6332)

[Gary Gregory (JIRA)]

[ https://issues.apache.org/jira/browse/LOG4J2-812?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=14147282#comment-14147282 ]

Gary Gregory commented on LOG4J2-812:
-------------------------------------

I'm not sure using a different formatter would help.

In {{org.apache.logging.log4j.core.pattern.DatePatternConverter}} I see code like:

{code:java}
/**
* Append formatted date to string buffer.
*
* @param date
* date
* @param toAppendTo
* buffer to which formatted date is appended.
*/
public void format(final Date date, final StringBuilder toAppendTo) {
synchronized (this) {
toAppendTo.append(formatter.format(date.getTime()));
}
}

/**
* {@inheritDoc}
*/
@Override
public void format(final LogEvent event, final StringBuilder output) {
final long timestamp = event.getTimeMillis();

synchronized (this) {
if (timestamp != lastTimestamp) {
lastTimestamp = timestamp;
cachedDateString = formatter.format(timestamp);
}
}
output.append(cachedDateString);
}
{code}

It is not just access to the formatter that is synchronized, but to the whole caching logic.

Am I missing something?

What if the {{DatePatternConverter}} was a thread local?

Post by Remko Popma (JIRA)
Performance optimization: avoid use of synchronized SimpleDateFormat in Dat​ePatternCo​nverter
-----------------------------------------------------------------------------------------------
Key: LOG4J2-812
URL: https://issues.apache.org/jira/browse/LOG4J2-812
Project: Log4j 2
Issue Type: Bug
Components: Pattern Converters, Performance Benchmarks
Affects Versions: 2.0.2
Reporter: Mohit Anchlia
Assignee: Remko Popma
Fix For: 2.2
{quote}
The converter uses a SimpleDateFormat which is not thread safe and so is synchronized. I am sure there might be minor optimizations that could be done to this
What I would do is modify DatePatternConverter to
a) use Java 8’s java.time.format.DateTimeFormatter if running on Java 8
b) use Joda Time’s DateTimeFormat if it is present.
c) create a pool of SimpleDateFormat objects and use those.
Please create a Jira issue for this.
Ralph
{quote}
----
One alternative that was suggested on the mailing list is to use commons lang FastDateFormat to format log timestamps.

--
This message was sent by Atlassian JIRA
(v6.3.4#6332)

[Remko Popma (JIRA)]

[ https://issues.apache.org/jira/browse/LOG4J2-812?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=14147598#comment-14147598 ]

Remko Popma commented on LOG4J2-812:
------------------------------------

You're right that just dropping in FastDateFormat to replace SimpleDateFormat is not enough. It is the synchronized blocks that are the problem. You have a good point that this synchronized block is not just making SimpleDateFormat thread-safe, but is also used to cache the previous result.

Perhaps the caching logic is no longer needed if we use a faster date formatter, or a thread-local like you suggest?

I think the next step is to do some performance measurements to compare these options.

Post by Remko Popma (JIRA)
Performance optimization: avoid use of synchronized SimpleDateFormat in Dat​ePatternCo​nverter
-----------------------------------------------------------------------------------------------
Key: LOG4J2-812
URL: https://issues.apache.org/jira/browse/LOG4J2-812
Project: Log4j 2
Issue Type: Bug
Components: Pattern Converters, Performance Benchmarks
Affects Versions: 2.0.2
Reporter: Mohit Anchlia
Assignee: Remko Popma
Fix For: 2.2
{quote}
The converter uses a SimpleDateFormat which is not thread safe and so is synchronized. I am sure there might be minor optimizations that could be done to this
What I would do is modify DatePatternConverter to
a) use Java 8’s java.time.format.DateTimeFormatter if running on Java 8
b) use Joda Time’s DateTimeFormat if it is present.
c) create a pool of SimpleDateFormat objects and use those.
Please create a Jira issue for this.
Ralph
{quote}
----
One alternative that was suggested on the mailing list is to use commons lang FastDateFormat to format log timestamps.

--
This message was sent by Atlassian JIRA
(v6.3.4#6332)