Uploaded image for project: 'Log4j 2'
  1. Log4j 2
  2. LOG4J2-1858

Memory issues with ParameterizedMessage

    Details

    • Type: Bug
    • Status: Closed
    • Priority: Major
    • Resolution: Fixed
    • Affects Version/s: None
    • Fix Version/s: 2.9.0
    • Component/s: None
    • Labels:
      None

      Description

      ParameterizedMessage keeps track of a ThreadLocal<StringBuilder> in order to save object creations. However, the reused string builders can only grow over time, which may end up causing memory issues after some large messages have been logged. This is especially true if the application uses a fixed thread pool since the string builders cannot be collected at all.

      One way to address that issue would be to drop the string builder if it grows too large, but I have concerns that this could cause garbage collection issues if this happens too often (since those string builders might not die young). So maybe this class should go back to create the StringBuilder on demand and make sure it always dies young?

      For the record, this problem seems to have been introduced in LOG4J2-1271 / https://git-wip-us.apache.org/repos/asf?p=logging-log4j2.git;a=blobdiff;f=log4j-api/src/main/java/org/apache/logging/log4j/message/ParameterizedMessage.java;h=d315c1345b5fb72c8d88f5e1aa177011c7376fb9;hp=334e19ba7c188e8ac862863830cf17dca7b7007c;hb=dca586c;hpb=047565e8928b0c9893c25ee92ffdf48dbcd6965c.

        Activity

        Hide
        jpountz Adrien Grand added a comment -

        I haven't submitted a patch as it should be trivial to fix, but in case that would make things any easier on your end I can provide one.

        Show
        jpountz Adrien Grand added a comment - I haven't submitted a patch as it should be trivial to fix, but in case that would make things any easier on your end I can provide one.
        Hide
        jpountz Adrien Grand added a comment -

        Can anyone comment about this issue?

        Show
        jpountz Adrien Grand added a comment - Can anyone comment about this issue?
        Hide
        remkop@yahoo.com Remko Popma added a comment -

        The way we handle this issue in other places is to trimToLength the StringBuilder if it exceeds some reasonable maximum. Looks like this one slipped through the cracks.

        You have a point that the old char[] array will likely be moved to the oldgen space, but we found that constructing a new StringBuilder for each message has significant performance impact.

        You may be aware that since version 2.6 Log4j can be configured to be garbage free, in which case ReusableParameterizedMessage is used instead of ParameterizedMessage. This is where StringBuilders are trimmed when they exceed some threshold. The threshold is configurable, so you can adjust if your system frequently logs large messages.

        Show
        remkop@yahoo.com Remko Popma added a comment - The way we handle this issue in other places is to trimToLength the StringBuilder if it exceeds some reasonable maximum. Looks like this one slipped through the cracks. You have a point that the old char[] array will likely be moved to the oldgen space, but we found that constructing a new StringBuilder for each message has significant performance impact. You may be aware that since version 2.6 Log4j can be configured to be garbage free, in which case ReusableParameterizedMessage is used instead of ParameterizedMessage. This is where StringBuilders are trimmed when they exceed some threshold. The threshold is configurable, so you can adjust if your system frequently logs large messages.
        Hide
        jpountz Adrien Grand added a comment -

        Thanks for having a look and the pointer to ReusableParameterizedMessage! Can you point me to the place where the trimming happens, I had a quick look at this class at https://github.com/apache/logging-log4j2/blob/master/log4j-api/src/main/java/org/apache/logging/log4j/message/ReusableParameterizedMessage.java and could not figure out where it happens. By the way, the call to Math.min at https://github.com/apache/logging-log4j2/blob/master/log4j-api/src/main/java/org/apache/logging/log4j/message/ReusableParameterizedMessage.java#L301 looks wrong to me, I think it should be a call to Math.max otherwise the name of the MIN_BUILDER_SIZE constant is misleading.

        Show
        jpountz Adrien Grand added a comment - Thanks for having a look and the pointer to ReusableParameterizedMessage ! Can you point me to the place where the trimming happens, I had a quick look at this class at https://github.com/apache/logging-log4j2/blob/master/log4j-api/src/main/java/org/apache/logging/log4j/message/ReusableParameterizedMessage.java and could not figure out where it happens. By the way, the call to Math.min at https://github.com/apache/logging-log4j2/blob/master/log4j-api/src/main/java/org/apache/logging/log4j/message/ReusableParameterizedMessage.java#L301 looks wrong to me, I think it should be a call to Math.max otherwise the name of the MIN_BUILDER_SIZE constant is misleading.
        Hide
        remkop@yahoo.com Remko Popma added a comment - - edited

        Thanks for spotting that min/max mistake!

        Trimming happens in a few places.

        FYI, ReusableParameterizedMessage also has a StringBuilder field, but this is rarely used because in garbage-free mode, the formatTo(StringBuilder) method is used instead of getFormattedMessage. The StringBuilder passed to formatTo is owned by the caller (MutableLogEvent or RingBufferLogEvent). The owner does the trimming.

        Show
        remkop@yahoo.com Remko Popma added a comment - - edited Thanks for spotting that min/max mistake! Trimming happens in a few places . FYI, ReusableParameterizedMessage also has a StringBuilder field, but this is rarely used because in garbage-free mode, the formatTo(StringBuilder) method is used instead of getFormattedMessage . The StringBuilder passed to formatTo is owned by the caller (MutableLogEvent or RingBufferLogEvent). The owner does the trimming.
        Hide
        jira-bot ASF subversion and git services added a comment -

        Commit f1b71ea775e04731f3a03c2657474fcda205987a in logging-log4j2's branch refs/heads/master from rpopma
        [ https://git-wip-us.apache.org/repos/asf?p=logging-log4j2.git;h=f1b71ea ]

        LOG4J2-1858 create trimToMaxSize utility method in StringBuilders, with test

        Show
        jira-bot ASF subversion and git services added a comment - Commit f1b71ea775e04731f3a03c2657474fcda205987a in logging-log4j2's branch refs/heads/master from rpopma [ https://git-wip-us.apache.org/repos/asf?p=logging-log4j2.git;h=f1b71ea ] LOG4J2-1858 create trimToMaxSize utility method in StringBuilders, with test
        Hide
        jira-bot ASF subversion and git services added a comment -

        Commit a903427c5f373e476736a07f259afb463a7001fd in logging-log4j2's branch refs/heads/master from rpopma
        [ https://git-wip-us.apache.org/repos/asf?p=logging-log4j2.git;h=a903427 ]

        LOG4J2-1858 make the MAX_REUSABLE_MESSAGE_SIZE available in log4j-api's Constants class

        Show
        jira-bot ASF subversion and git services added a comment - Commit a903427c5f373e476736a07f259afb463a7001fd in logging-log4j2's branch refs/heads/master from rpopma [ https://git-wip-us.apache.org/repos/asf?p=logging-log4j2.git;h=a903427 ] LOG4J2-1858 make the MAX_REUSABLE_MESSAGE_SIZE available in log4j-api's Constants class
        Hide
        jira-bot ASF subversion and git services added a comment -

        Commit 28553e1d44b41fcf53796633b56431b259fc9411 in logging-log4j2's branch refs/heads/master from rpopma
        [ https://git-wip-us.apache.org/repos/asf?p=logging-log4j2.git;h=28553e1 ]

        LOG4J2-1858 ensure ThreadLocal StringBuffer won't hold excessively much memory after logging a long message

        Show
        jira-bot ASF subversion and git services added a comment - Commit 28553e1d44b41fcf53796633b56431b259fc9411 in logging-log4j2's branch refs/heads/master from rpopma [ https://git-wip-us.apache.org/repos/asf?p=logging-log4j2.git;h=28553e1 ] LOG4J2-1858 ensure ThreadLocal StringBuffer won't hold excessively much memory after logging a long message
        Hide
        jira-bot ASF subversion and git services added a comment -

        Commit 0f70fe7e16aefee30a9ece78c33717c8abe97efc in logging-log4j2's branch refs/heads/master from rpopma
        [ https://git-wip-us.apache.org/repos/asf?p=logging-log4j2.git;h=0f70fe7 ]

        LOG4J2-1858 ensure ThreadLocal StringBuffer won't hold excessively much memory after logging a long message, also fix Math.min -> Math.max bug

        Show
        jira-bot ASF subversion and git services added a comment - Commit 0f70fe7e16aefee30a9ece78c33717c8abe97efc in logging-log4j2's branch refs/heads/master from rpopma [ https://git-wip-us.apache.org/repos/asf?p=logging-log4j2.git;h=0f70fe7 ] LOG4J2-1858 ensure ThreadLocal StringBuffer won't hold excessively much memory after logging a long message, also fix Math.min -> Math.max bug
        Hide
        jira-bot ASF subversion and git services added a comment -

        Commit fd331b217536ef354e72922d14b26c9694e8c38c in logging-log4j2's branch refs/heads/master from rpopma
        [ https://git-wip-us.apache.org/repos/asf?p=logging-log4j2.git;h=fd331b2 ]

        LOG4J2-1858 refactor existing places that trim a StringBuilder to max size to use the StringBuilders utility method

        Show
        jira-bot ASF subversion and git services added a comment - Commit fd331b217536ef354e72922d14b26c9694e8c38c in logging-log4j2's branch refs/heads/master from rpopma [ https://git-wip-us.apache.org/repos/asf?p=logging-log4j2.git;h=fd331b2 ] LOG4J2-1858 refactor existing places that trim a StringBuilder to max size to use the StringBuilders utility method
        Hide
        jira-bot ASF subversion and git services added a comment -

        Commit e1d334efdc45b72a27c4b2ede1b802c3d2308fee in logging-log4j2's branch refs/heads/master from rpopma
        [ https://git-wip-us.apache.org/repos/asf?p=logging-log4j2.git;h=e1d334e ]

        LOG4J2-1858 update change log

        Show
        jira-bot ASF subversion and git services added a comment - Commit e1d334efdc45b72a27c4b2ede1b802c3d2308fee in logging-log4j2's branch refs/heads/master from rpopma [ https://git-wip-us.apache.org/repos/asf?p=logging-log4j2.git;h=e1d334e ] LOG4J2-1858 update change log
        Hide
        remkop@yahoo.com Remko Popma added a comment -

        Fixed in master. Please verify and close.

        Show
        remkop@yahoo.com Remko Popma added a comment - Fixed in master. Please verify and close.
        Hide
        jpountz Adrien Grand added a comment -

        The changes look good to me, thank you!

        Show
        jpountz Adrien Grand added a comment - The changes look good to me, thank you!
        Hide
        jpountz Adrien Grand added a comment -

        I understand release scheduling is hard, but do you have any rough estimate of when 2.9 is going to be released?

        Show
        jpountz Adrien Grand added a comment - I understand release scheduling is hard, but do you have any rough estimate of when 2.9 is going to be released?
        Hide
        jvz Matt Sicker added a comment -

        Considering we just released 2.8.2 last week, probably not anytime soon. I suppose that depends on what features we're working on finishing for 2.9. We also have related work in breaking out some code from the core repo into separate repos and release trains, and I think we'd like to get as much of that done for 2.9 as possible. Currently, we're working on separating the Scala API and some network server code.

        Show
        jvz Matt Sicker added a comment - Considering we just released 2.8.2 last week, probably not anytime soon. I suppose that depends on what features we're working on finishing for 2.9. We also have related work in breaking out some code from the core repo into separate repos and release trains, and I think we'd like to get as much of that done for 2.9 as possible. Currently, we're working on separating the Scala API and some network server code.
        Hide
        jira-bot ASF subversion and git services added a comment -

        Commit a903427c5f373e476736a07f259afb463a7001fd in logging-log4j2's branch refs/heads/java9NoMultiRelease from rpopma
        [ https://git-wip-us.apache.org/repos/asf?p=logging-log4j2.git;h=a903427 ]

        LOG4J2-1858 make the MAX_REUSABLE_MESSAGE_SIZE available in log4j-api's Constants class

        Show
        jira-bot ASF subversion and git services added a comment - Commit a903427c5f373e476736a07f259afb463a7001fd in logging-log4j2's branch refs/heads/java9NoMultiRelease from rpopma [ https://git-wip-us.apache.org/repos/asf?p=logging-log4j2.git;h=a903427 ] LOG4J2-1858 make the MAX_REUSABLE_MESSAGE_SIZE available in log4j-api's Constants class
        Hide
        jira-bot ASF subversion and git services added a comment -

        Commit 28553e1d44b41fcf53796633b56431b259fc9411 in logging-log4j2's branch refs/heads/java9NoMultiRelease from rpopma
        [ https://git-wip-us.apache.org/repos/asf?p=logging-log4j2.git;h=28553e1 ]

        LOG4J2-1858 ensure ThreadLocal StringBuffer won't hold excessively much memory after logging a long message

        Show
        jira-bot ASF subversion and git services added a comment - Commit 28553e1d44b41fcf53796633b56431b259fc9411 in logging-log4j2's branch refs/heads/java9NoMultiRelease from rpopma [ https://git-wip-us.apache.org/repos/asf?p=logging-log4j2.git;h=28553e1 ] LOG4J2-1858 ensure ThreadLocal StringBuffer won't hold excessively much memory after logging a long message
        Hide
        jira-bot ASF subversion and git services added a comment -

        Commit 0f70fe7e16aefee30a9ece78c33717c8abe97efc in logging-log4j2's branch refs/heads/java9NoMultiRelease from rpopma
        [ https://git-wip-us.apache.org/repos/asf?p=logging-log4j2.git;h=0f70fe7 ]

        LOG4J2-1858 ensure ThreadLocal StringBuffer won't hold excessively much memory after logging a long message, also fix Math.min -> Math.max bug

        Show
        jira-bot ASF subversion and git services added a comment - Commit 0f70fe7e16aefee30a9ece78c33717c8abe97efc in logging-log4j2's branch refs/heads/java9NoMultiRelease from rpopma [ https://git-wip-us.apache.org/repos/asf?p=logging-log4j2.git;h=0f70fe7 ] LOG4J2-1858 ensure ThreadLocal StringBuffer won't hold excessively much memory after logging a long message, also fix Math.min -> Math.max bug
        Hide
        jira-bot ASF subversion and git services added a comment -

        Commit fd331b217536ef354e72922d14b26c9694e8c38c in logging-log4j2's branch refs/heads/java9NoMultiRelease from rpopma
        [ https://git-wip-us.apache.org/repos/asf?p=logging-log4j2.git;h=fd331b2 ]

        LOG4J2-1858 refactor existing places that trim a StringBuilder to max size to use the StringBuilders utility method

        Show
        jira-bot ASF subversion and git services added a comment - Commit fd331b217536ef354e72922d14b26c9694e8c38c in logging-log4j2's branch refs/heads/java9NoMultiRelease from rpopma [ https://git-wip-us.apache.org/repos/asf?p=logging-log4j2.git;h=fd331b2 ] LOG4J2-1858 refactor existing places that trim a StringBuilder to max size to use the StringBuilders utility method
        Hide
        jira-bot ASF subversion and git services added a comment -

        Commit e1d334efdc45b72a27c4b2ede1b802c3d2308fee in logging-log4j2's branch refs/heads/java9NoMultiRelease from rpopma
        [ https://git-wip-us.apache.org/repos/asf?p=logging-log4j2.git;h=e1d334e ]

        LOG4J2-1858 update change log

        Show
        jira-bot ASF subversion and git services added a comment - Commit e1d334efdc45b72a27c4b2ede1b802c3d2308fee in logging-log4j2's branch refs/heads/java9NoMultiRelease from rpopma [ https://git-wip-us.apache.org/repos/asf?p=logging-log4j2.git;h=e1d334e ] LOG4J2-1858 update change log
        Hide
        jira-bot ASF subversion and git services added a comment -

        Commit 0577c15a43c3d8d5b59688537796bda4d3ddd576 in logging-log4j2's branch refs/heads/master from Gary Gregory
        [ https://git-wip-us.apache.org/repos/asf?p=logging-log4j2.git;h=0577c15 ]

        LOG4J2-1858 Add Javadoc @since tag.

        Show
        jira-bot ASF subversion and git services added a comment - Commit 0577c15a43c3d8d5b59688537796bda4d3ddd576 in logging-log4j2's branch refs/heads/master from Gary Gregory [ https://git-wip-us.apache.org/repos/asf?p=logging-log4j2.git;h=0577c15 ] LOG4J2-1858 Add Javadoc @since tag.

          People

          • Assignee:
            remkop@yahoo.com Remko Popma
            Reporter:
            jpountz Adrien Grand
          • Votes:
            0 Vote for this issue
            Watchers:
            6 Start watching this issue

            Dates

            • Created:
              Updated:
              Resolved:

              Development