[jira] [Commented] (LOG4J2-2795) Make LogManager/LoggerContext creation time reasonable
[
https://issues.apache.org/jira/browse/LOG4J2-2795?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=1779#comment-1779
]
Matt Sicker commented on LOG4J2-2795:
-
This likely depends on [https://github.com/apache/logging-log4j2/issues/1344]
(moving JMX stuff to its own module) and
[https://github.com/apache/logging-log4j2/issues/1977] (remove support for
specifying classes via strings like system properties). To better support Java
modules and GraalVM, I might end up enhancing the plugin processor to generate
more metadata at compile time not only to make sure I _have_ that data in the
first place, but it should also help reduce startup time, too, as reflection
will be involved far less.
> Make LogManager/LoggerContext creation time reasonable
> --
>
> Key: LOG4J2-2795
> URL: https://issues.apache.org/jira/browse/LOG4J2-2795
> Project: Log4j 2
> Issue Type: Task
> Components: Core
>Affects Versions: 2.13.0
>Reporter: Romain Manni-Bucau
>Priority: Major
> Attachments: image-2020-03-06-08-58-21-169.png, log4j2.png
>
>
> Currently (2.13), LogManager.getLogger("xxx") takes ~600ms on a cold JVM by
> itself.
> For a logging framework it is likely way too much (by comparison a CDI test
> with classpath scanning takes ~50ms).
>
> This ticket is about trying to be faster (maybe by removing java
> serialization usage and reducing registry usage + reflection of plugins by
> generating java code?).
--
This message was sent by Atlassian Jira
(v8.20.10#820010)
[jira] [Commented] (LOG4J2-2795) Make LogManager/LoggerContext creation time reasonable
[
https://issues.apache.org/jira/browse/LOG4J2-2795?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=17516345#comment-17516345
]
Romain Manni-Bucau commented on LOG4J2-2795:
[~mattsicker] tested master right now and got 405ms (really regular around 40x
ms for some dozen of startups) for:
{code:java}
public class Run {
public static void main(final String... args) {
final long start = System.nanoTime();
LogManager.getLogger(Run.class).info("foo");
final long end = System.nanoTime();
System.out.println(TimeUnit.NANOSECONDS.toMillis(end - start) + "ms");
}
} {code}
> Make LogManager/LoggerContext creation time reasonable
> --
>
> Key: LOG4J2-2795
> URL: https://issues.apache.org/jira/browse/LOG4J2-2795
> Project: Log4j 2
> Issue Type: Task
> Components: Core
>Affects Versions: 2.13.0
>Reporter: Romain Manni-Bucau
>Priority: Major
> Attachments: image-2020-03-06-08-58-21-169.png, log4j2.png
>
>
> Currently (2.13), LogManager.getLogger("xxx") takes ~600ms on a cold JVM by
> itself.
> For a logging framework it is likely way too much (by comparison a CDI test
> with classpath scanning takes ~50ms).
>
> This ticket is about trying to be faster (maybe by removing java
> serialization usage and reducing registry usage + reflection of plugins by
> generating java code?).
--
This message was sent by Atlassian Jira
(v8.20.1#820001)
[jira] [Commented] (LOG4J2-2795) Make LogManager/LoggerContext creation time reasonable
[
https://issues.apache.org/jira/browse/LOG4J2-2795?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=17515450#comment-17515450
]
Matt Sicker commented on LOG4J2-2795:
-
I should note that I've also made several static init blocks lazy, though not
all of them (some looked fairly trivial), and many of those will still end up
being executed once you start logging. Try out master again and let me know
what you think.
> Make LogManager/LoggerContext creation time reasonable
> --
>
> Key: LOG4J2-2795
> URL: https://issues.apache.org/jira/browse/LOG4J2-2795
> Project: Log4j 2
> Issue Type: Task
> Components: Core
>Affects Versions: 2.13.0
>Reporter: Romain Manni-Bucau
>Priority: Major
> Attachments: image-2020-03-06-08-58-21-169.png, log4j2.png
>
>
> Currently (2.13), LogManager.getLogger("xxx") takes ~600ms on a cold JVM by
> itself.
> For a logging framework it is likely way too much (by comparison a CDI test
> with classpath scanning takes ~50ms).
>
> This ticket is about trying to be faster (maybe by removing java
> serialization usage and reducing registry usage + reflection of plugins by
> generating java code?).
--
This message was sent by Atlassian Jira
(v8.20.1#820001)
[jira] [Commented] (LOG4J2-2795) Make LogManager/LoggerContext creation time reasonable
[
https://issues.apache.org/jira/browse/LOG4J2-2795?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=17515448#comment-17515448
]
Matt Sicker commented on LOG4J2-2795:
-
Collecting plugins only loads the metadata for each plugin, not the plugin
class itself. The class isn't loaded until we need to first create a plugin of
that type. Basically, the configuration nodes are matched to PluginType
instances which contain the metadata and a way to load the corresponding plugin
class. Only when a plugin is referenced in a configuration do we attempt to
load its corresponding plugin class and then construct it.
As for the cache file decoding, that's for backward compatibility with 2.x. We
don't generate any plugin cache file anymore, so that shouldn't be adding any
time except for looking to see if a resource exists in the ClassLoader.
Basically, it might help to do some profiling here to find what's really taking
so much time.
> Make LogManager/LoggerContext creation time reasonable
> --
>
> Key: LOG4J2-2795
> URL: https://issues.apache.org/jira/browse/LOG4J2-2795
> Project: Log4j 2
> Issue Type: Task
> Components: Core
>Affects Versions: 2.13.0
>Reporter: Romain Manni-Bucau
>Priority: Major
> Attachments: image-2020-03-06-08-58-21-169.png, log4j2.png
>
>
> Currently (2.13), LogManager.getLogger("xxx") takes ~600ms on a cold JVM by
> itself.
> For a logging framework it is likely way too much (by comparison a CDI test
> with classpath scanning takes ~50ms).
>
> This ticket is about trying to be faster (maybe by removing java
> serialization usage and reducing registry usage + reflection of plugins by
> generating java code?).
--
This message was sent by Atlassian Jira
(v8.20.1#820001)
[jira] [Commented] (LOG4J2-2795) Make LogManager/LoggerContext creation time reasonable
[
https://issues.apache.org/jira/browse/LOG4J2-2795?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=17515116#comment-17515116
]
Romain Manni-Bucau commented on LOG4J2-2795:
[~mattsicker] AFAIK it is not the case on master since
org.apache.logging.log4j.plugins.util.PluginManager#collectPlugins(java.util.List)
is still called and
org.apache.logging.log4j.plugins.util.PluginRegistry#decodeCacheFiles is still
there so there is nothing really lazy or matching only the configuration
surface and not the full scope of log4j. Hope I didn't miss something.
> Make LogManager/LoggerContext creation time reasonable
> --
>
> Key: LOG4J2-2795
> URL: https://issues.apache.org/jira/browse/LOG4J2-2795
> Project: Log4j 2
> Issue Type: Task
> Components: Core
>Affects Versions: 2.13.0
>Reporter: Romain Manni-Bucau
>Priority: Major
> Attachments: image-2020-03-06-08-58-21-169.png, log4j2.png
>
>
> Currently (2.13), LogManager.getLogger("xxx") takes ~600ms on a cold JVM by
> itself.
> For a logging framework it is likely way too much (by comparison a CDI test
> with classpath scanning takes ~50ms).
>
> This ticket is about trying to be faster (maybe by removing java
> serialization usage and reducing registry usage + reflection of plugins by
> generating java code?).
--
This message was sent by Atlassian Jira
(v8.20.1#820001)
[jira] [Commented] (LOG4J2-2795) Make LogManager/LoggerContext creation time reasonable
[
https://issues.apache.org/jira/browse/LOG4J2-2795?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=17515011#comment-17515011
]
Matt Sicker commented on LOG4J2-2795:
-
{quote}Wonder if you evaluated to not collect plugins but just try to load them
lazily when they are referenced. Concretely, ConsoleAppender wouldnt be loaded
until it appears in some configuration etc...Also loading it using a registrar
class (kind of ServiceLoader mecanism but with a name deduced from the name
encoutered by log4j) can enable to simplify the serialization too and get back
to something closer to the previous (v1) configuration where it was loaded per
class directly (even if it still has an indirection with the resource lookup
but it is a bit better).
{quote}
This is exactly how it works in master right now.
The static init stuff is something I'll have to look into. It's possible that
the remaining lag is from things in log4j-api that could be refactored.
> Make LogManager/LoggerContext creation time reasonable
> --
>
> Key: LOG4J2-2795
> URL: https://issues.apache.org/jira/browse/LOG4J2-2795
> Project: Log4j 2
> Issue Type: Task
> Components: Core
>Affects Versions: 2.13.0
>Reporter: Romain Manni-Bucau
>Priority: Major
> Attachments: image-2020-03-06-08-58-21-169.png, log4j2.png
>
>
> Currently (2.13), LogManager.getLogger("xxx") takes ~600ms on a cold JVM by
> itself.
> For a logging framework it is likely way too much (by comparison a CDI test
> with classpath scanning takes ~50ms).
>
> This ticket is about trying to be faster (maybe by removing java
> serialization usage and reducing registry usage + reflection of plugins by
> generating java code?).
--
This message was sent by Atlassian Jira
(v8.20.1#820001)
[jira] [Commented] (LOG4J2-2795) Make LogManager/LoggerContext creation time reasonable
[
https://issues.apache.org/jira/browse/LOG4J2-2795?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=17514949#comment-17514949
]
Romain Manni-Bucau commented on LOG4J2-2795:
To give another metrics for my computer: a real "small" application (johnzon +
cdi + yupiik-logging/JUL) starts in ~250ms (with scanning not optimized and
some startup init code) which is 30ms faster than log4j alone for a
getLogger().info() main - just enables to compare why I speak about a few
dozens of ms to init the logging.
Wonder if you evaluated to not collect plugins but just try to load them lazily
when they are referenced. Concretely, ConsoleAppender wouldnt be loaded until
it appears in some configuration etc...Also loading it using a registrar class
(kind of ServiceLoader mecanism but with a name deduced from the name
encoutered by log4j) can enable to simplify the serialization too and get back
to something closer to the previous (v1) configuration where it was loaded per
class directly (even if it still has an indirection with the resource lookup
but it is a bit better).
That + dropping most of static init would be great I think even if I can't
evaluate the gain yet.
> Make LogManager/LoggerContext creation time reasonable
> --
>
> Key: LOG4J2-2795
> URL: https://issues.apache.org/jira/browse/LOG4J2-2795
> Project: Log4j 2
> Issue Type: Task
> Components: Core
>Affects Versions: 2.13.0
>Reporter: Romain Manni-Bucau
>Priority: Major
> Attachments: image-2020-03-06-08-58-21-169.png, log4j2.png
>
>
> Currently (2.13), LogManager.getLogger("xxx") takes ~600ms on a cold JVM by
> itself.
> For a logging framework it is likely way too much (by comparison a CDI test
> with classpath scanning takes ~50ms).
>
> This ticket is about trying to be faster (maybe by removing java
> serialization usage and reducing registry usage + reflection of plugins by
> generating java code?).
--
This message was sent by Atlassian Jira
(v8.20.1#820001)
[jira] [Commented] (LOG4J2-2795) Make LogManager/LoggerContext creation time reasonable
[
https://issues.apache.org/jira/browse/LOG4J2-2795?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=17514812#comment-17514812
]
Gary D. Gregory commented on LOG4J2-2795:
-
Another use case that would benefit from faster start-up time is
unit/integration testing. Some apps I test have to perform some init and
shutdown for each test to provide just enough of an environment for these tests
to run, and some of that is logging configuration/shutdown.
> Make LogManager/LoggerContext creation time reasonable
> --
>
> Key: LOG4J2-2795
> URL: https://issues.apache.org/jira/browse/LOG4J2-2795
> Project: Log4j 2
> Issue Type: Task
> Components: Core
>Affects Versions: 2.13.0
>Reporter: Romain Manni-Bucau
>Priority: Major
> Attachments: image-2020-03-06-08-58-21-169.png, log4j2.png
>
>
> Currently (2.13), LogManager.getLogger("xxx") takes ~600ms on a cold JVM by
> itself.
> For a logging framework it is likely way too much (by comparison a CDI test
> with classpath scanning takes ~50ms).
>
> This ticket is about trying to be faster (maybe by removing java
> serialization usage and reducing registry usage + reflection of plugins by
> generating java code?).
--
This message was sent by Atlassian Jira
(v8.20.1#820001)
[jira] [Commented] (LOG4J2-2795) Make LogManager/LoggerContext creation time reasonable
[
https://issues.apache.org/jira/browse/LOG4J2-2795?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=17514807#comment-17514807
]
Matt Sicker commented on LOG4J2-2795:
-
Well, compare the startup time of instantiating DefaultInjector (and even
running init() on it) versus the rest of the system. The DI container is the
easy part at this point. I'd expect that our implementation is faster than CDI
or Guice because it doesn't have the same huge list of features and added
indirection (interceptors, etc). At this point, I'd like to try to figure out
what remaining aspects are causing this slowdown. While I wouldn't expect this
to be much of an issue in typical applications, it would certainly be annoying
in CLI tools or cloud native micro services where you deploy super often and
startup time matters more. I know just how annoying it is to set up liveness
probes in K8s to wait for Spring Boot to start up, for example, so I know what
you mean and would love to see how else we can improve this.
I'll note in contrast, running the same thing on my machine executes in less
than 100ms, so it's gotten harder for me to find the remaining low hanging
fruit as they're all blending together at this point. If you're willing to test
out a few combinations of things, can you compare how different versions of
Java perform here? Would be nice to see how it compares with different types of
disk, too (e.g., if a cloud service is using something like EBS versus using a
local NVMe drive), to see how much of an issue this is caused by loading files
rather than executing anything redundant.
> Make LogManager/LoggerContext creation time reasonable
> --
>
> Key: LOG4J2-2795
> URL: https://issues.apache.org/jira/browse/LOG4J2-2795
> Project: Log4j 2
> Issue Type: Task
> Components: Core
>Affects Versions: 2.13.0
>Reporter: Romain Manni-Bucau
>Priority: Major
> Attachments: image-2020-03-06-08-58-21-169.png, log4j2.png
>
>
> Currently (2.13), LogManager.getLogger("xxx") takes ~600ms on a cold JVM by
> itself.
> For a logging framework it is likely way too much (by comparison a CDI test
> with classpath scanning takes ~50ms).
>
> This ticket is about trying to be faster (maybe by removing java
> serialization usage and reducing registry usage + reflection of plugins by
> generating java code?).
--
This message was sent by Atlassian Jira
(v8.20.1#820001)
[jira] [Commented] (LOG4J2-2795) Make LogManager/LoggerContext creation time reasonable
[
https://issues.apache.org/jira/browse/LOG4J2-2795?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=17514460#comment-17514460
]
Romain Manni-Bucau commented on LOG4J2-2795:
[~mattsicker] right but still, the first "info" logging time should be almost
free compared to an IoC startup when it includes scanning (CDI in my original
reference). It is also way more than JUL or any other alternative so it is
quite important for modern deployment (thinking to k8s in particular).
> Make LogManager/LoggerContext creation time reasonable
> --
>
> Key: LOG4J2-2795
> URL: https://issues.apache.org/jira/browse/LOG4J2-2795
> Project: Log4j 2
> Issue Type: Task
> Components: Core
>Affects Versions: 2.13.0
>Reporter: Romain Manni-Bucau
>Priority: Major
> Attachments: image-2020-03-06-08-58-21-169.png, log4j2.png
>
>
> Currently (2.13), LogManager.getLogger("xxx") takes ~600ms on a cold JVM by
> itself.
> For a logging framework it is likely way too much (by comparison a CDI test
> with classpath scanning takes ~50ms).
>
> This ticket is about trying to be faster (maybe by removing java
> serialization usage and reducing registry usage + reflection of plugins by
> generating java code?).
--
This message was sent by Atlassian Jira
(v8.20.1#820001)
[jira] [Commented] (LOG4J2-2795) Make LogManager/LoggerContext creation time reasonable
[
https://issues.apache.org/jira/browse/LOG4J2-2795?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=17514441#comment-17514441
]
Matt Sicker commented on LOG4J2-2795:
-
I see a bit of time in the beginning is spent loading all the Java classes
needed to run from jar files. Some of that startup time could be dependent on
the specific version of Java you're using.
> Make LogManager/LoggerContext creation time reasonable
> --
>
> Key: LOG4J2-2795
> URL: https://issues.apache.org/jira/browse/LOG4J2-2795
> Project: Log4j 2
> Issue Type: Task
> Components: Core
>Affects Versions: 2.13.0
>Reporter: Romain Manni-Bucau
>Priority: Major
> Attachments: image-2020-03-06-08-58-21-169.png, log4j2.png
>
>
> Currently (2.13), LogManager.getLogger("xxx") takes ~600ms on a cold JVM by
> itself.
> For a logging framework it is likely way too much (by comparison a CDI test
> with classpath scanning takes ~50ms).
>
> This ticket is about trying to be faster (maybe by removing java
> serialization usage and reducing registry usage + reflection of plugins by
> generating java code?).
--
This message was sent by Atlassian Jira
(v8.20.1#820001)
[jira] [Commented] (LOG4J2-2795) Make LogManager/LoggerContext creation time reasonable
[
https://issues.apache.org/jira/browse/LOG4J2-2795?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=17513182#comment-17513182
]
Romain Manni-Bucau commented on LOG4J2-2795:
Hi [~mattsicker] , I'm around 362 with the defaults, 278ms without jmx so a bit
better but still very high IMHO.
> Make LogManager/LoggerContext creation time reasonable
> --
>
> Key: LOG4J2-2795
> URL: https://issues.apache.org/jira/browse/LOG4J2-2795
> Project: Log4j 2
> Issue Type: Task
> Components: Core
>Affects Versions: 2.13.0
>Reporter: Romain Manni-Bucau
>Priority: Major
> Attachments: image-2020-03-06-08-58-21-169.png, log4j2.png
>
>
> Currently (2.13), LogManager.getLogger("xxx") takes ~600ms on a cold JVM by
> itself.
> For a logging framework it is likely way too much (by comparison a CDI test
> with classpath scanning takes ~50ms).
>
> This ticket is about trying to be faster (maybe by removing java
> serialization usage and reducing registry usage + reflection of plugins by
> generating java code?).
--
This message was sent by Atlassian Jira
(v8.20.1#820001)
[jira] [Commented] (LOG4J2-2795) Make LogManager/LoggerContext creation time reasonable
[
https://issues.apache.org/jira/browse/LOG4J2-2795?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=17513102#comment-17513102
]
Matt Sicker commented on LOG4J2-2795:
-
StrLookup plugins are now lazily loaded, so worth checking out the startup time
for both the default case and the JMX disabled case.
> Make LogManager/LoggerContext creation time reasonable
> --
>
> Key: LOG4J2-2795
> URL: https://issues.apache.org/jira/browse/LOG4J2-2795
> Project: Log4j 2
> Issue Type: Task
> Components: Core
>Affects Versions: 2.13.0
>Reporter: Romain Manni-Bucau
>Priority: Major
> Attachments: image-2020-03-06-08-58-21-169.png, log4j2.png
>
>
> Currently (2.13), LogManager.getLogger("xxx") takes ~600ms on a cold JVM by
> itself.
> For a logging framework it is likely way too much (by comparison a CDI test
> with classpath scanning takes ~50ms).
>
> This ticket is about trying to be faster (maybe by removing java
> serialization usage and reducing registry usage + reflection of plugins by
> generating java code?).
--
This message was sent by Atlassian Jira
(v8.20.1#820001)
[jira] [Commented] (LOG4J2-2795) Make LogManager/LoggerContext creation time reasonable
[
https://issues.apache.org/jira/browse/LOG4J2-2795?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=17513069#comment-17513069
]
Matt Sicker commented on LOG4J2-2795:
-
Sweet, thanks. I'm still finishing up plugin inversion here that would enable
lazy loading of some unnecessary things (particularly StrLookup and
PatternConverter plugins) which should help to some extent. Another existing
configuration option you could try to compare startup time with would be
defining the system property {{log4j2.disable.jmx}} to {{{}true{}}}. This
should give a more reasonable measurement for what Log4j itself is doing as JMX
itself initializes quite a few classes. Once I can make StrLookup plugins lazy,
then the {{jvmrunargs}} lookup will stop causing some other JMX classes to be
loaded until that lookup is actually used.
> Make LogManager/LoggerContext creation time reasonable
> --
>
> Key: LOG4J2-2795
> URL: https://issues.apache.org/jira/browse/LOG4J2-2795
> Project: Log4j 2
> Issue Type: Task
> Components: Core
>Affects Versions: 2.13.0
>Reporter: Romain Manni-Bucau
>Priority: Major
> Attachments: image-2020-03-06-08-58-21-169.png, log4j2.png
>
>
> Currently (2.13), LogManager.getLogger("xxx") takes ~600ms on a cold JVM by
> itself.
> For a logging framework it is likely way too much (by comparison a CDI test
> with classpath scanning takes ~50ms).
>
> This ticket is about trying to be faster (maybe by removing java
> serialization usage and reducing registry usage + reflection of plugins by
> generating java code?).
--
This message was sent by Atlassian Jira
(v8.20.1#820001)
[jira] [Commented] (LOG4J2-2795) Make LogManager/LoggerContext creation time reasonable
[
https://issues.apache.org/jira/browse/LOG4J2-2795?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=17512695#comment-17512695
]
Romain Manni-Bucau commented on LOG4J2-2795:
Here it is https://gist.github.com/rmannibucau/f077856a9e4d51226cffe5e8d4af512f
> Make LogManager/LoggerContext creation time reasonable
> --
>
> Key: LOG4J2-2795
> URL: https://issues.apache.org/jira/browse/LOG4J2-2795
> Project: Log4j 2
> Issue Type: Task
> Components: Core
>Affects Versions: 2.13.0
>Reporter: Romain Manni-Bucau
>Priority: Major
> Attachments: image-2020-03-06-08-58-21-169.png, log4j2.png
>
>
> Currently (2.13), LogManager.getLogger("xxx") takes ~600ms on a cold JVM by
> itself.
> For a logging framework it is likely way too much (by comparison a CDI test
> with classpath scanning takes ~50ms).
>
> This ticket is about trying to be faster (maybe by removing java
> serialization usage and reducing registry usage + reflection of plugins by
> generating java code?).
--
This message was sent by Atlassian Jira
(v8.20.1#820001)
[jira] [Commented] (LOG4J2-2795) Make LogManager/LoggerContext creation time reasonable
[
https://issues.apache.org/jira/browse/LOG4J2-2795?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=17512587#comment-17512587
]
Matt Sicker commented on LOG4J2-2795:
-
Try invoking your benchmark program with {{-Xlog:class=debug:file=class.log}}
and attach the results here. Based on my own log file, I identified those above
issues so far, though there could be more.
> Make LogManager/LoggerContext creation time reasonable
> --
>
> Key: LOG4J2-2795
> URL: https://issues.apache.org/jira/browse/LOG4J2-2795
> Project: Log4j 2
> Issue Type: Task
> Components: Core
>Affects Versions: 2.13.0
>Reporter: Romain Manni-Bucau
>Priority: Major
> Attachments: image-2020-03-06-08-58-21-169.png, log4j2.png
>
>
> Currently (2.13), LogManager.getLogger("xxx") takes ~600ms on a cold JVM by
> itself.
> For a logging framework it is likely way too much (by comparison a CDI test
> with classpath scanning takes ~50ms).
>
> This ticket is about trying to be faster (maybe by removing java
> serialization usage and reducing registry usage + reflection of plugins by
> generating java code?).
--
This message was sent by Atlassian Jira
(v8.20.1#820001)
[jira] [Commented] (LOG4J2-2795) Make LogManager/LoggerContext creation time reasonable
[
https://issues.apache.org/jira/browse/LOG4J2-2795?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=17512568#comment-17512568
]
Romain Manni-Bucau commented on LOG4J2-2795:
Yes it is there on ubuntu.
> Make LogManager/LoggerContext creation time reasonable
> --
>
> Key: LOG4J2-2795
> URL: https://issues.apache.org/jira/browse/LOG4J2-2795
> Project: Log4j 2
> Issue Type: Task
> Components: Core
>Affects Versions: 2.13.0
>Reporter: Romain Manni-Bucau
>Priority: Major
> Attachments: image-2020-03-06-08-58-21-169.png, log4j2.png
>
>
> Currently (2.13), LogManager.getLogger("xxx") takes ~600ms on a cold JVM by
> itself.
> For a logging framework it is likely way too much (by comparison a CDI test
> with classpath scanning takes ~50ms).
>
> This ticket is about trying to be faster (maybe by removing java
> serialization usage and reducing registry usage + reflection of plugins by
> generating java code?).
--
This message was sent by Atlassian Jira
(v8.20.1#820001)
[jira] [Commented] (LOG4J2-2795) Make LogManager/LoggerContext creation time reasonable
[
https://issues.apache.org/jira/browse/LOG4J2-2795?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=17512547#comment-17512547
]
Matt Sicker commented on LOG4J2-2795:
-
On the OS you're testing this on, do you have your hostname defined in
/etc/hosts? As described on [https://logging.apache.org/log4j/2.x/build.html]
there's a fun little feature in Java which uses a reverse DNS lookup to figure
out the local hostname if it's not already pre-loaded from the hosts file.
> Make LogManager/LoggerContext creation time reasonable
> --
>
> Key: LOG4J2-2795
> URL: https://issues.apache.org/jira/browse/LOG4J2-2795
> Project: Log4j 2
> Issue Type: Task
> Components: Core
>Affects Versions: 2.13.0
>Reporter: Romain Manni-Bucau
>Priority: Major
> Attachments: image-2020-03-06-08-58-21-169.png, log4j2.png
>
>
> Currently (2.13), LogManager.getLogger("xxx") takes ~600ms on a cold JVM by
> itself.
> For a logging framework it is likely way too much (by comparison a CDI test
> with classpath scanning takes ~50ms).
>
> This ticket is about trying to be faster (maybe by removing java
> serialization usage and reducing registry usage + reflection of plugins by
> generating java code?).
--
This message was sent by Atlassian Jira
(v8.20.1#820001)
[jira] [Commented] (LOG4J2-2795) Make LogManager/LoggerContext creation time reasonable
[
https://issues.apache.org/jira/browse/LOG4J2-2795?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=17510930#comment-17510930
]
Matt Sicker commented on LOG4J2-2795:
-
I did a class init trace log on 2.17.2 and found some potential improvements in
LOG4J2-3441, LOG4J2-3442, and LOG4J2-3443.
> Make LogManager/LoggerContext creation time reasonable
> --
>
> Key: LOG4J2-2795
> URL: https://issues.apache.org/jira/browse/LOG4J2-2795
> Project: Log4j 2
> Issue Type: Task
> Components: Core
>Affects Versions: 2.13.0
>Reporter: Romain Manni-Bucau
>Priority: Major
> Attachments: image-2020-03-06-08-58-21-169.png, log4j2.png
>
>
> Currently (2.13), LogManager.getLogger("xxx") takes ~600ms on a cold JVM by
> itself.
> For a logging framework it is likely way too much (by comparison a CDI test
> with classpath scanning takes ~50ms).
>
> This ticket is about trying to be faster (maybe by removing java
> serialization usage and reducing registry usage + reflection of plugins by
> generating java code?).
--
This message was sent by Atlassian Jira
(v8.20.1#820001)
[jira] [Commented] (LOG4J2-2795) Make LogManager/LoggerContext creation time reasonable
[
https://issues.apache.org/jira/browse/LOG4J2-2795?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=17510806#comment-17510806
]
Romain Manni-Bucau commented on LOG4J2-2795:
I did a nanotime around the getLogger().info(), time measurement is worse but
also takes into account way more so we can't only blame log4j there ;)
> Make LogManager/LoggerContext creation time reasonable
> --
>
> Key: LOG4J2-2795
> URL: https://issues.apache.org/jira/browse/LOG4J2-2795
> Project: Log4j 2
> Issue Type: Task
> Components: Core
>Affects Versions: 2.13.0
>Reporter: Romain Manni-Bucau
>Priority: Major
> Attachments: image-2020-03-06-08-58-21-169.png, log4j2.png
>
>
> Currently (2.13), LogManager.getLogger("xxx") takes ~600ms on a cold JVM by
> itself.
> For a logging framework it is likely way too much (by comparison a CDI test
> with classpath scanning takes ~50ms).
>
> This ticket is about trying to be faster (maybe by removing java
> serialization usage and reducing registry usage + reflection of plugins by
> generating java code?).
--
This message was sent by Atlassian Jira
(v8.20.1#820001)
[jira] [Commented] (LOG4J2-2795) Make LogManager/LoggerContext creation time reasonable
[
https://issues.apache.org/jira/browse/LOG4J2-2795?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=17510722#comment-17510722
]
Matt Sicker commented on LOG4J2-2795:
-
So just running it with the time command? Or are you measuring the time inside
Java?
> Make LogManager/LoggerContext creation time reasonable
> --
>
> Key: LOG4J2-2795
> URL: https://issues.apache.org/jira/browse/LOG4J2-2795
> Project: Log4j 2
> Issue Type: Task
> Components: Core
>Affects Versions: 2.13.0
>Reporter: Romain Manni-Bucau
>Priority: Major
> Attachments: image-2020-03-06-08-58-21-169.png, log4j2.png
>
>
> Currently (2.13), LogManager.getLogger("xxx") takes ~600ms on a cold JVM by
> itself.
> For a logging framework it is likely way too much (by comparison a CDI test
> with classpath scanning takes ~50ms).
>
> This ticket is about trying to be faster (maybe by removing java
> serialization usage and reducing registry usage + reflection of plugins by
> generating java code?).
--
This message was sent by Atlassian Jira
(v8.20.1#820001)
[jira] [Commented] (LOG4J2-2795) Make LogManager/LoggerContext creation time reasonable
[
https://issues.apache.org/jira/browse/LOG4J2-2795?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=17510263#comment-17510263
]
Romain Manni-Bucau commented on LOG4J2-2795:
I'm just testing a plain main doing a logger.info (and i just have log4j-core
dep tree, not even a real classpath).
> Make LogManager/LoggerContext creation time reasonable
> --
>
> Key: LOG4J2-2795
> URL: https://issues.apache.org/jira/browse/LOG4J2-2795
> Project: Log4j 2
> Issue Type: Task
> Components: Core
>Affects Versions: 2.13.0
>Reporter: Romain Manni-Bucau
>Priority: Major
> Attachments: image-2020-03-06-08-58-21-169.png, log4j2.png
>
>
> Currently (2.13), LogManager.getLogger("xxx") takes ~600ms on a cold JVM by
> itself.
> For a logging framework it is likely way too much (by comparison a CDI test
> with classpath scanning takes ~50ms).
>
> This ticket is about trying to be faster (maybe by removing java
> serialization usage and reducing registry usage + reflection of plugins by
> generating java code?).
--
This message was sent by Atlassian Jira
(v8.20.1#820001)
[jira] [Commented] (LOG4J2-2795) Make LogManager/LoggerContext creation time reasonable
[
https://issues.apache.org/jira/browse/LOG4J2-2795?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=17510169#comment-17510169
]
Matt Sicker commented on LOG4J2-2795:
-
I'd imagine a lot of the static init stuff was for aggressive caching which
made more sense for long-running applications. Now that there's a proper IoC
container, a lot of that can be refactored, though I'll have to find the
applicable code first!
If there's a lot of time spent waiting on locks from lazy-initialized objects,
then that would be interesting to know.
Do you have any test code for this? Or are you just timing the launch of a
trivial app with log4j in it?
> Make LogManager/LoggerContext creation time reasonable
> --
>
> Key: LOG4J2-2795
> URL: https://issues.apache.org/jira/browse/LOG4J2-2795
> Project: Log4j 2
> Issue Type: Task
> Components: Core
>Affects Versions: 2.13.0
>Reporter: Romain Manni-Bucau
>Priority: Major
> Attachments: image-2020-03-06-08-58-21-169.png, log4j2.png
>
>
> Currently (2.13), LogManager.getLogger("xxx") takes ~600ms on a cold JVM by
> itself.
> For a logging framework it is likely way too much (by comparison a CDI test
> with classpath scanning takes ~50ms).
>
> This ticket is about trying to be faster (maybe by removing java
> serialization usage and reducing registry usage + reflection of plugins by
> generating java code?).
--
This message was sent by Atlassian Jira
(v8.20.1#820001)
[jira] [Commented] (LOG4J2-2795) Make LogManager/LoggerContext creation time reasonable
[
https://issues.apache.org/jira/browse/LOG4J2-2795?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=17510073#comment-17510073
]
Romain Manni-Bucau commented on LOG4J2-2795:
[~mattsicker] I didn't reprofile it since the ton of static inits is one of the
issue and requires a drastical change in the code. Technically a single
singleton - manager or context - abusing of static data is needed (rest are
plain instances with fields) so think using the internal reflection-less IoC to
align the code design on something more modern and less time consuming at
startup can be worth it to solve this issue. Taking 10 times more than an
actual IoC is weirdish to get logs ;).
> Make LogManager/LoggerContext creation time reasonable
> --
>
> Key: LOG4J2-2795
> URL: https://issues.apache.org/jira/browse/LOG4J2-2795
> Project: Log4j 2
> Issue Type: Task
> Components: Core
>Affects Versions: 2.13.0
>Reporter: Romain Manni-Bucau
>Priority: Major
> Attachments: image-2020-03-06-08-58-21-169.png, log4j2.png
>
>
> Currently (2.13), LogManager.getLogger("xxx") takes ~600ms on a cold JVM by
> itself.
> For a logging framework it is likely way too much (by comparison a CDI test
> with classpath scanning takes ~50ms).
>
> This ticket is about trying to be faster (maybe by removing java
> serialization usage and reducing registry usage + reflection of plugins by
> generating java code?).
--
This message was sent by Atlassian Jira
(v8.20.1#820001)
[jira] [Commented] (LOG4J2-2795) Make LogManager/LoggerContext creation time reasonable
[
https://issues.apache.org/jira/browse/LOG4J2-2795?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=17509986#comment-17509986
]
Matt Sicker commented on LOG4J2-2795:
-
Ah, I was also having that issue in Java 17. It seems like using MethodHandles
instead of reflection doesn't work so well on non-public things there. Could
also be a bug elsewhere. I think I may need to keep the reflection-based
approach as a backup there.
I did start working last night on centralizing creation of PluginManager
classes into Injector to avoid repeated work, though I haven't committed that
yet.
If you profile this, do you see any interesting code paths that might be
contributing to the slow start? It's quite possible that the hostname lookup
thing is what's causing the bulk of that startup time (which is something I
noticed long ago in unit tests if you didn't have an entry in /etc/hosts for
your localhost domain name as the lookup is forced to find out via DNS instead
which takes time). A simple way to verify this might be to ensure your
/etc/hosts file has an entry for 127.0.0.1 (and optionally one or more for your
actual network interface, though I don't think that's as relevant here) and see
how that affects the startup time.
> Make LogManager/LoggerContext creation time reasonable
> --
>
> Key: LOG4J2-2795
> URL: https://issues.apache.org/jira/browse/LOG4J2-2795
> Project: Log4j 2
> Issue Type: Task
> Components: Core
>Affects Versions: 2.13.0
>Reporter: Romain Manni-Bucau
>Priority: Major
> Attachments: image-2020-03-06-08-58-21-169.png, log4j2.png
>
>
> Currently (2.13), LogManager.getLogger("xxx") takes ~600ms on a cold JVM by
> itself.
> For a logging framework it is likely way too much (by comparison a CDI test
> with classpath scanning takes ~50ms).
>
> This ticket is about trying to be faster (maybe by removing java
> serialization usage and reducing registry usage + reflection of plugins by
> generating java code?).
--
This message was sent by Atlassian Jira
(v8.20.1#820001)
[jira] [Commented] (LOG4J2-2795) Make LogManager/LoggerContext creation time reasonable
[
https://issues.apache.org/jira/browse/LOG4J2-2795?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=17509699#comment-17509699
]
Romain Manni-Bucau commented on LOG4J2-2795:
Hi
Just tested master.
For Java 17 it does not work: `java.lang.IllegalAccessError: Cannot access
field protected org.apache.logging.log4j.plugins.di.Injector
org.apache.logging.log4j.core.selector.ClassLoaderContextSelector.injector`.
On Java 11 I'm around 430ms (vs 45ms for a simple implementation) so looks like
it is still way too slow.
> Make LogManager/LoggerContext creation time reasonable
> --
>
> Key: LOG4J2-2795
> URL: https://issues.apache.org/jira/browse/LOG4J2-2795
> Project: Log4j 2
> Issue Type: Task
> Components: Core
>Affects Versions: 2.13.0
>Reporter: Romain Manni-Bucau
>Priority: Major
> Attachments: image-2020-03-06-08-58-21-169.png, log4j2.png
>
>
> Currently (2.13), LogManager.getLogger("xxx") takes ~600ms on a cold JVM by
> itself.
> For a logging framework it is likely way too much (by comparison a CDI test
> with classpath scanning takes ~50ms).
>
> This ticket is about trying to be faster (maybe by removing java
> serialization usage and reducing registry usage + reflection of plugins by
> generating java code?).
--
This message was sent by Atlassian Jira
(v8.20.1#820001)
[jira] [Commented] (LOG4J2-2795) Make LogManager/LoggerContext creation time reasonable
[
https://issues.apache.org/jira/browse/LOG4J2-2795?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=17509532#comment-17509532
]
Matt Sicker commented on LOG4J2-2795:
-
Could be interesting to check this out again. I've made some major overhauls to
the plugin system which may have an impact here.
> Make LogManager/LoggerContext creation time reasonable
> --
>
> Key: LOG4J2-2795
> URL: https://issues.apache.org/jira/browse/LOG4J2-2795
> Project: Log4j 2
> Issue Type: Task
> Components: Core
>Affects Versions: 2.13.0
>Reporter: Romain Manni-Bucau
>Priority: Major
> Attachments: image-2020-03-06-08-58-21-169.png, log4j2.png
>
>
> Currently (2.13), LogManager.getLogger("xxx") takes ~600ms on a cold JVM by
> itself.
> For a logging framework it is likely way too much (by comparison a CDI test
> with classpath scanning takes ~50ms).
>
> This ticket is about trying to be faster (maybe by removing java
> serialization usage and reducing registry usage + reflection of plugins by
> generating java code?).
--
This message was sent by Atlassian Jira
(v8.20.1#820001)
[jira] [Commented] (LOG4J2-2795) Make LogManager/LoggerContext creation time reasonable
[
https://issues.apache.org/jira/browse/LOG4J2-2795?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=17259766#comment-17259766
]
Romain Manni-Bucau commented on LOG4J2-2795:
Up :)
Any hope it gets better in the coming months or is it completely out of the
radar for the project?
> Make LogManager/LoggerContext creation time reasonable
> --
>
> Key: LOG4J2-2795
> URL: https://issues.apache.org/jira/browse/LOG4J2-2795
> Project: Log4j 2
> Issue Type: Task
> Components: Core
>Affects Versions: 2.13.0
>Reporter: Romain Manni-Bucau
>Priority: Major
> Attachments: image-2020-03-06-08-58-21-169.png, log4j2.png
>
>
> Currently (2.13), LogManager.getLogger("xxx") takes ~600ms on a cold JVM by
> itself.
> For a logging framework it is likely way too much (by comparison a CDI test
> with classpath scanning takes ~50ms).
>
> This ticket is about trying to be faster (maybe by removing java
> serialization usage and reducing registry usage + reflection of plugins by
> generating java code?).
--
This message was sent by Atlassian Jira
(v8.3.4#803005)
[jira] [Commented] (LOG4J2-2795) Make LogManager/LoggerContext creation time reasonable
[
https://issues.apache.org/jira/browse/LOG4J2-2795?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=17082215#comment-17082215
]
Romain Manni-Bucau commented on LOG4J2-2795:
Hi [~rgoers], guess 1 at least should be solved (it depends your classpath so
can be very slow). Others can wait and guess then starting time is acceptable
even if still slow compared to concurrents.
> Make LogManager/LoggerContext creation time reasonable
> --
>
> Key: LOG4J2-2795
> URL: https://issues.apache.org/jira/browse/LOG4J2-2795
> Project: Log4j 2
> Issue Type: Task
> Components: Core
>Affects Versions: 2.13.0
>Reporter: Romain Manni-Bucau
>Priority: Major
> Attachments: image-2020-03-06-08-58-21-169.png, log4j2.png
>
>
> Currently (2.13), LogManager.getLogger("xxx") takes ~600ms on a cold JVM by
> itself.
> For a logging framework it is likely way too much (by comparison a CDI test
> with classpath scanning takes ~50ms).
>
> This ticket is about trying to be faster (maybe by removing java
> serialization usage and reducing registry usage + reflection of plugins by
> generating java code?).
--
This message was sent by Atlassian Jira
(v8.3.4#803005)
[jira] [Commented] (LOG4J2-2795) Make LogManager/LoggerContext creation time reasonable
[
https://issues.apache.org/jira/browse/LOG4J2-2795?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=17082035#comment-17082035
]
Ralph Goers commented on LOG4J2-2795:
-
I am not aware of any work left to do on this issue. Please provide feedback if
you don't agree.
> Make LogManager/LoggerContext creation time reasonable
> --
>
> Key: LOG4J2-2795
> URL: https://issues.apache.org/jira/browse/LOG4J2-2795
> Project: Log4j 2
> Issue Type: Task
> Components: Core
>Affects Versions: 2.13.0
>Reporter: Romain Manni-Bucau
>Priority: Major
> Attachments: image-2020-03-06-08-58-21-169.png, log4j2.png
>
>
> Currently (2.13), LogManager.getLogger("xxx") takes ~600ms on a cold JVM by
> itself.
> For a logging framework it is likely way too much (by comparison a CDI test
> with classpath scanning takes ~50ms).
>
> This ticket is about trying to be faster (maybe by removing java
> serialization usage and reducing registry usage + reflection of plugins by
> generating java code?).
--
This message was sent by Atlassian Jira
(v8.3.4#803005)
[jira] [Commented] (LOG4J2-2795) Make LogManager/LoggerContext creation time reasonable
[
https://issues.apache.org/jira/browse/LOG4J2-2795?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=17053534#comment-17053534
]
Ralph Goers commented on LOG4J2-2795:
-
Here are my comments regarding the items on your list:
# The driving force behind Log4j 2 3.x is to fully conform with the Java
Platform Module System. This means that Log4j Core can only have a required
dependency on java.base. The work to accomplish this will be handled under
LOG4J2-2802, which would include the ScriptEngine, which is now part of
java.scripting. That said, according to my profiling the ScriptManager
constructor only uses 16 ms.
# This doesn't make sense to me. Plugins are packaged as 1 class per jar. All
the plugin definitions in that jar are loaded at once. All the plugin
definitions have to be loaded otherwise the plugin won't be found when the
configuration is processed. I have already optimized this as much as possible
by not loading the plugin classes until they are referenced.
# ConfigurationFactory does have a static extension. If you provide a system
property naming your ConfigurationFactory it will be used. The current system
allows users to create their own custom configuration factories as plugins,
which is much simpler for users to implement.
# The Interpolator has to load the initial list of Lookups because the
PluginManager isn't available yet and variable resolution has to work while
processing the configuration but before the PluginManager is created. Creating
Lookups should generally be inexpensive. Without this values specified in the
properties section of the Log4j configuration would not be allowed to reference
Lookups.
> Make LogManager/LoggerContext creation time reasonable
> --
>
> Key: LOG4J2-2795
> URL: https://issues.apache.org/jira/browse/LOG4J2-2795
> Project: Log4j 2
> Issue Type: Task
> Components: Core
>Affects Versions: 2.13.0
>Reporter: Romain Manni-Bucau
>Priority: Major
> Attachments: image-2020-03-06-08-58-21-169.png, log4j2.png
>
>
> Currently (2.13), LogManager.getLogger("xxx") takes ~600ms on a cold JVM by
> itself.
> For a logging framework it is likely way too much (by comparison a CDI test
> with classpath scanning takes ~50ms).
>
> This ticket is about trying to be faster (maybe by removing java
> serialization usage and reducing registry usage + reflection of plugins by
> generating java code?).
--
This message was sent by Atlassian Jira
(v8.3.4#803005)
[jira] [Commented] (LOG4J2-2795) Make LogManager/LoggerContext creation time reasonable
[
https://issues.apache.org/jira/browse/LOG4J2-2795?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=17053143#comment-17053143
]
Romain Manni-Bucau commented on LOG4J2-2795:
Hi [~rgoers], I have a few questions about some code parts and in particular
org.apache.logging.log4j.core.config.AbstractConfiguration#initialize and
friends:
# why a ScriptManager is created there? can't it be created lazily in
org.apache.logging.log4j.core.config.AbstractConfiguration#doConfigure, it
triggers some serious loading for nothing most of the time
# why PluginManager isnt cached per package?
# why we can't get a static extension support in configuration factory
(@ConfigurationFactoryConfiguration(suffixes = \{".xml"})) to avoid to load the
class and instantiate it if not needed, the processor would store it avoid a
bunch of classloading for nothing
# Same in
org.apache.logging.log4j.core.lookup.Interpolator#Interpolator(org.apache.logging.log4j.core.lookup.StrLookup,
java.util.List), why eveything is early instantiated?
Will not solve everything but at least the ScriptManager drop helps for me.
> Make LogManager/LoggerContext creation time reasonable
> --
>
> Key: LOG4J2-2795
> URL: https://issues.apache.org/jira/browse/LOG4J2-2795
> Project: Log4j 2
> Issue Type: Task
> Components: Core
>Affects Versions: 2.13.0
>Reporter: Romain Manni-Bucau
>Priority: Major
> Attachments: image-2020-03-06-08-58-21-169.png, log4j2.png
>
>
> Currently (2.13), LogManager.getLogger("xxx") takes ~600ms on a cold JVM by
> itself.
> For a logging framework it is likely way too much (by comparison a CDI test
> with classpath scanning takes ~50ms).
>
> This ticket is about trying to be faster (maybe by removing java
> serialization usage and reducing registry usage + reflection of plugins by
> generating java code?).
--
This message was sent by Atlassian Jira
(v8.3.4#803005)
[jira] [Commented] (LOG4J2-2795) Make LogManager/LoggerContext creation time reasonable
[
https://issues.apache.org/jira/browse/LOG4J2-2795?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=17052617#comment-17052617
]
ASF subversion and git services commented on LOG4J2-2795:
-
Commit 039ae0bb7c77b9993a8684b12f0518187001f358 in logging-log4j2's branch
refs/heads/master from Ralph Goers
[ https://gitbox.apache.org/repos/asf?p=logging-log4j2.git;h=039ae0b ]
LOG4J2-2795 - Reduce Log4j 2 initialization time by deferring loading Plugin
classes.
> Make LogManager/LoggerContext creation time reasonable
> --
>
> Key: LOG4J2-2795
> URL: https://issues.apache.org/jira/browse/LOG4J2-2795
> Project: Log4j 2
> Issue Type: Task
> Components: Core
>Affects Versions: 2.13.0
>Reporter: Romain Manni-Bucau
>Priority: Major
> Attachments: log4j2.png
>
>
> Currently (2.13), LogManager.getLogger("xxx") takes ~600ms on a cold JVM by
> itself.
> For a logging framework it is likely way too much (by comparison a CDI test
> with classpath scanning takes ~50ms).
>
> This ticket is about trying to be faster (maybe by removing java
> serialization usage and reducing registry usage + reflection of plugins by
> generating java code?).
--
This message was sent by Atlassian Jira
(v8.3.4#803005)
[jira] [Commented] (LOG4J2-2795) Make LogManager/LoggerContext creation time reasonable
[
https://issues.apache.org/jira/browse/LOG4J2-2795?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=17052407#comment-17052407
]
Ralph Goers commented on LOG4J2-2795:
-
I modified loading the plugins so that the classes are not loaded when the
plugins definitions are read and are instead loaded when the plugin system
actually needs the class. The cost of calling collectPlugins() is now greatly
reduced. but the overall startup time didn't really change much from the
previous 3.0.0 implementation I tested. Compared to 2.13.2-SNAPSHOT the
overall startup has been cut in half. Creating the PatternParser is slightly
better but still spends 80 ms in PluginType.getPluginClass(), which is where
the class loading was moved to, so essentially collectPlugins went from 300-400
ms in the prior test to 130-150 ms with this implementation.
||Logger Count||2.13.2-SNAPSHOT Elapsed||2.13.2-SNAPSHOT CollectPlugins
||3.0.0-SNAPSHOT Elapsed||3.0.0-SNAPSHOT Collect Plugins||3.0.0-SNAPSHOT Lazy
Elapsed||3.0.0-SNAPSHOT CollectPlugins||
|1|2,654 ms| 1,315 ms|864 ms|350 ms|1,175 ms|59 ms|
|100| 1,927 ms| 969 ms|1,206 ms|375 ms|1,152 ms|52 ms|
|1000| 2,339 ms| 1,259 ms|1,703 ms|468 ms|1,429 ms|67 ms|
> Make LogManager/LoggerContext creation time reasonable
> --
>
> Key: LOG4J2-2795
> URL: https://issues.apache.org/jira/browse/LOG4J2-2795
> Project: Log4j 2
> Issue Type: Task
> Components: Core
>Affects Versions: 2.13.0
>Reporter: Romain Manni-Bucau
>Priority: Major
> Attachments: log4j2.png
>
>
> Currently (2.13), LogManager.getLogger("xxx") takes ~600ms on a cold JVM by
> itself.
> For a logging framework it is likely way too much (by comparison a CDI test
> with classpath scanning takes ~50ms).
>
> This ticket is about trying to be faster (maybe by removing java
> serialization usage and reducing registry usage + reflection of plugins by
> generating java code?).
--
This message was sent by Atlassian Jira
(v8.3.4#803005)
[jira] [Commented] (LOG4J2-2795) Make LogManager/LoggerContext creation time reasonable
[
https://issues.apache.org/jira/browse/LOG4J2-2795?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=17051845#comment-17051845
]
Romain Manni-Bucau commented on LOG4J2-2795:
Even if it is true most JVM will have JIT, it still does not justify this
slowness. Concretely just adding log4j - so not changing anything to your
functional - makes your single test passing from 30ms to > 1s which is likely
not acceptable just for logs. Indeed it is possible to exclude log4j to use
something else most of the time but I don't see a reason it is that slow to
init - in particular when you know a CDI container starts 3-4 faster. This is
why i reported this issue.
> Make LogManager/LoggerContext creation time reasonable
> --
>
> Key: LOG4J2-2795
> URL: https://issues.apache.org/jira/browse/LOG4J2-2795
> Project: Log4j 2
> Issue Type: Task
> Components: Core
>Affects Versions: 2.13.0
>Reporter: Romain Manni-Bucau
>Priority: Major
> Attachments: log4j2.png
>
>
> Currently (2.13), LogManager.getLogger("xxx") takes ~600ms on a cold JVM by
> itself.
> For a logging framework it is likely way too much (by comparison a CDI test
> with classpath scanning takes ~50ms).
>
> This ticket is about trying to be faster (maybe by removing java
> serialization usage and reducing registry usage + reflection of plugins by
> generating java code?).
--
This message was sent by Atlassian Jira
(v8.3.4#803005)
[jira] [Commented] (LOG4J2-2795) Make LogManager/LoggerContext creation time reasonable
[
https://issues.apache.org/jira/browse/LOG4J2-2795?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=17051842#comment-17051842
]
Ralph Goers commented on LOG4J2-2795:
-
I should add that in all the profile snapshots I have looked at collectPlugins
is being called when the DefaultConfiguration is trying to create a
PatternLayout and the PatternConverters need to be located.
> Make LogManager/LoggerContext creation time reasonable
> --
>
> Key: LOG4J2-2795
> URL: https://issues.apache.org/jira/browse/LOG4J2-2795
> Project: Log4j 2
> Issue Type: Task
> Components: Core
>Affects Versions: 2.13.0
>Reporter: Romain Manni-Bucau
>Priority: Major
> Attachments: log4j2.png
>
>
> Currently (2.13), LogManager.getLogger("xxx") takes ~600ms on a cold JVM by
> itself.
> For a logging framework it is likely way too much (by comparison a CDI test
> with classpath scanning takes ~50ms).
>
> This ticket is about trying to be faster (maybe by removing java
> serialization usage and reducing registry usage + reflection of plugins by
> generating java code?).
--
This message was sent by Atlassian Jira
(v8.3.4#803005)
[jira] [Commented] (LOG4J2-2795) Make LogManager/LoggerContext creation time reasonable
[
https://issues.apache.org/jira/browse/LOG4J2-2795?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=17051838#comment-17051838
]
Ralph Goers commented on LOG4J2-2795:
-
One other thing I should note. Due to the way the JVM works I would expect much
of the code executed during startup to be considerably slower than it would be
if the JVM had been running for a while as code is typically not optimized
until it has been executed quite a few times. That is one reason why when
running benchmarks it is usually recommended to run many warmup iterations
before actually starting to capture statistics. It would also explain to some
degree why getting 100 Loggers is somehow faster in two of the tests than
getting a single Logger.
> Make LogManager/LoggerContext creation time reasonable
> --
>
> Key: LOG4J2-2795
> URL: https://issues.apache.org/jira/browse/LOG4J2-2795
> Project: Log4j 2
> Issue Type: Task
> Components: Core
>Affects Versions: 2.13.0
>Reporter: Romain Manni-Bucau
>Priority: Major
> Attachments: log4j2.png
>
>
> Currently (2.13), LogManager.getLogger("xxx") takes ~600ms on a cold JVM by
> itself.
> For a logging framework it is likely way too much (by comparison a CDI test
> with classpath scanning takes ~50ms).
>
> This ticket is about trying to be faster (maybe by removing java
> serialization usage and reducing registry usage + reflection of plugins by
> generating java code?).
--
This message was sent by Atlassian Jira
(v8.3.4#803005)
[jira] [Commented] (LOG4J2-2795) Make LogManager/LoggerContext creation time reasonable
[
https://issues.apache.org/jira/browse/LOG4J2-2795?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=17051836#comment-17051836
]
Ralph Goers commented on LOG4J2-2795:
-
Without plugins you can only have the DefaultConfiguration. Plugins are lazily
loaded in a sense. The collectPlugins method is called from 1 of 4 places: 1)
AbstractConfiguration.initialize() when a Configuration is being created. 2)
Interpolator's constructor when Lookups need to be found 3) PatternParser's
constructor when PatternConverters need to be located, and 4) WatcherFactory's
constructor when Watchers are located. These are basically the 4 classes of
plugins currently supported in Log4j 2. Only the first one of these to be
called actually loads the plugins - it wouldn't make any sense to do it any
other way as they are all defined in the same file (Log4jPlugins.dat in 2.x and
Log4jPlugins.java in 3.x). As I said, it 3.x the major cost is in
ServiceLoader locating Log4jPlugins.java, not in loading the actual plugins.
> Make LogManager/LoggerContext creation time reasonable
> --
>
> Key: LOG4J2-2795
> URL: https://issues.apache.org/jira/browse/LOG4J2-2795
> Project: Log4j 2
> Issue Type: Task
> Components: Core
>Affects Versions: 2.13.0
>Reporter: Romain Manni-Bucau
>Priority: Major
> Attachments: log4j2.png
>
>
> Currently (2.13), LogManager.getLogger("xxx") takes ~600ms on a cold JVM by
> itself.
> For a logging framework it is likely way too much (by comparison a CDI test
> with classpath scanning takes ~50ms).
>
> This ticket is about trying to be faster (maybe by removing java
> serialization usage and reducing registry usage + reflection of plugins by
> generating java code?).
--
This message was sent by Atlassian Jira
(v8.3.4#803005)
[jira] [Commented] (LOG4J2-2795) Make LogManager/LoggerContext creation time reasonable
[
https://issues.apache.org/jira/browse/LOG4J2-2795?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=17051832#comment-17051832
]
Romain Manni-Bucau commented on LOG4J2-2795:
Well the ipv4 workaround can be a doc highlighting I guess.
About dropping the plugins, the idea was to measure the cost of the
pluggability vs the cost of the earger loading. If on 1s, 800ms are taken
without any plugging there is a big issue. If plugins take 800ms then they can
be lazily loaded using a lookup convention and it would already help IMHO.
> Make LogManager/LoggerContext creation time reasonable
> --
>
> Key: LOG4J2-2795
> URL: https://issues.apache.org/jira/browse/LOG4J2-2795
> Project: Log4j 2
> Issue Type: Task
> Components: Core
>Affects Versions: 2.13.0
>Reporter: Romain Manni-Bucau
>Priority: Major
> Attachments: log4j2.png
>
>
> Currently (2.13), LogManager.getLogger("xxx") takes ~600ms on a cold JVM by
> itself.
> For a logging framework it is likely way too much (by comparison a CDI test
> with classpath scanning takes ~50ms).
>
> This ticket is about trying to be faster (maybe by removing java
> serialization usage and reducing registry usage + reflection of plugins by
> generating java code?).
--
This message was sent by Atlassian Jira
(v8.3.4#803005)
[jira] [Commented] (LOG4J2-2795) Make LogManager/LoggerContext creation time reasonable
[
https://issues.apache.org/jira/browse/LOG4J2-2795?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=17051824#comment-17051824
]
Ralph Goers commented on LOG4J2-2795:
-
Which part can be done lazily? Getting the hostname?
Drop all plugins from core? That would make Log4j unusable.
> Make LogManager/LoggerContext creation time reasonable
> --
>
> Key: LOG4J2-2795
> URL: https://issues.apache.org/jira/browse/LOG4J2-2795
> Project: Log4j 2
> Issue Type: Task
> Components: Core
>Affects Versions: 2.13.0
>Reporter: Romain Manni-Bucau
>Priority: Major
> Attachments: log4j2.png
>
>
> Currently (2.13), LogManager.getLogger("xxx") takes ~600ms on a cold JVM by
> itself.
> For a logging framework it is likely way too much (by comparison a CDI test
> with classpath scanning takes ~50ms).
>
> This ticket is about trying to be faster (maybe by removing java
> serialization usage and reducing registry usage + reflection of plugins by
> generating java code?).
--
This message was sent by Atlassian Jira
(v8.3.4#803005)
[jira] [Commented] (LOG4J2-2795) Make LogManager/LoggerContext creation time reasonable
[
https://issues.apache.org/jira/browse/LOG4J2-2795?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=17051821#comment-17051821
]
Romain Manni-Bucau commented on LOG4J2-2795:
Hmm, this part can depend the machine, wonder if it should be done lazily since
it is not always used. Also add {{-Djava.net.preferIPv4Stack=true}} on the JVM
can help but still the reflection init cost is quite huge. An interesting test
can be to drop all plugins from core to split the "infra" init cost and actual
loading cost.
> Make LogManager/LoggerContext creation time reasonable
> --
>
> Key: LOG4J2-2795
> URL: https://issues.apache.org/jira/browse/LOG4J2-2795
> Project: Log4j 2
> Issue Type: Task
> Components: Core
>Affects Versions: 2.13.0
>Reporter: Romain Manni-Bucau
>Priority: Major
> Attachments: log4j2.png
>
>
> Currently (2.13), LogManager.getLogger("xxx") takes ~600ms on a cold JVM by
> itself.
> For a logging framework it is likely way too much (by comparison a CDI test
> with classpath scanning takes ~50ms).
>
> This ticket is about trying to be faster (maybe by removing java
> serialization usage and reducing registry usage + reflection of plugins by
> generating java code?).
--
This message was sent by Atlassian Jira
(v8.3.4#803005)
[jira] [Commented] (LOG4J2-2795) Make LogManager/LoggerContext creation time reasonable
[
https://issues.apache.org/jira/browse/LOG4J2-2795?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=17051807#comment-17051807
]
Ralph Goers commented on LOG4J2-2795:
-
I did some profiling with YourKit. I created a class that gets a variable
number of Loggers. As the table below shows, the number of Loggers being
retrieved doesn't much matter as it is the cost of initializing Log4j the first
time that incurs the cost.
||Count||2.13.2-SNAPSHOT Elapsed||2.13.2-SNAPSHOT
CollectPlugins||3.0.0-SNAPSHOT
Elpased||3.0.0-SNAPSHOT-CollectPlugins||LOG4J2-2783 Elapsed||LOG4J2-2783
CollectPlugins||
|1|2,654|1,315 ms|864 ms|350 ms|1,414 ms|402 ms|
|100|1,927 ms|969 ms|1,206|375 ms|1,301 ms|313 ms|
|1000|2,339 ms|1,259 ms|1,703|468|1,521 ms|312 ms|
The main difference between 2.13.2 is that the majority of the CPU time in
CollectPlugins is spent in ResolverUtil while in 3.0.0 it is spent in
java.util.ServliceLoader. The change done by LOG4J2-2783 doesn't seem to have
made a large difference, probably since either way the plugin classes are still
being loaded.
As part of the profiling I also noticed that
java.net.InetAddress.getLocalHost() is taking a fair amount of time, mostly in
java.net.Inet6AddressImpl.lookupAllHostHaddr. This makes me wonder if the code
should skip ipV6 if it can.
> Make LogManager/LoggerContext creation time reasonable
> --
>
> Key: LOG4J2-2795
> URL: https://issues.apache.org/jira/browse/LOG4J2-2795
> Project: Log4j 2
> Issue Type: Task
> Components: Core
>Affects Versions: 2.13.0
>Reporter: Romain Manni-Bucau
>Priority: Major
> Attachments: log4j2.png
>
>
> Currently (2.13), LogManager.getLogger("xxx") takes ~600ms on a cold JVM by
> itself.
> For a logging framework it is likely way too much (by comparison a CDI test
> with classpath scanning takes ~50ms).
>
> This ticket is about trying to be faster (maybe by removing java
> serialization usage and reducing registry usage + reflection of plugins by
> generating java code?).
--
This message was sent by Atlassian Jira
(v8.3.4#803005)
[jira] [Commented] (LOG4J2-2795) Make LogManager/LoggerContext creation time reasonable
[
https://issues.apache.org/jira/browse/LOG4J2-2795?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=17049963#comment-17049963
]
Romain Manni-Bucau commented on LOG4J2-2795:
Right, but in the context of the test it is quite reasonable (junit5 so a bit
more than junit4 but not an EE stack ;)). In any case it can't justify the
overhead compared to throwing an exception which stays negligible. I can
request to use the tccl if needed but not sure it would impact the perf.
Will attach the hotspots i got yesterday with 2.13.
> Make LogManager/LoggerContext creation time reasonable
> --
>
> Key: LOG4J2-2795
> URL: https://issues.apache.org/jira/browse/LOG4J2-2795
> Project: Log4j 2
> Issue Type: Task
> Components: Core
>Affects Versions: 2.13.0
>Reporter: Romain Manni-Bucau
>Priority: Major
> Attachments: log4j2.png
>
>
> Currently (2.13), LogManager.getLogger("xxx") takes ~600ms on a cold JVM by
> itself.
> For a logging framework it is likely way too much (by comparison a CDI test
> with classpath scanning takes ~50ms).
>
> This ticket is about trying to be faster (maybe by removing java
> serialization usage and reducing registry usage + reflection of plugins by
> generating java code?).
--
This message was sent by Atlassian Jira
(v8.3.4#803005)
[jira] [Commented] (LOG4J2-2795) Make LogManager/LoggerContext creation time reasonable
[
https://issues.apache.org/jira/browse/LOG4J2-2795?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=17049958#comment-17049958
]
Ralph Goers commented on LOG4J2-2795:
-
I guess I wasn't clear. When you call getLogger the FQCN of the Logging
implementation is passed in so that the calling class can be identified. This
is necessary because the ClassLoaderContextSelector uses that to determine
which ClassLoader was used, and hence, which LoggerContext should be used. For
example, if you are running in tomcat with the jars in Tomcat's lib directory
and you use Log4j 2 to log Tomcat then when Tomcat logs it will use the
LoggerContext associated with Tomcat's ClassLoader. Web apps will use the
LoggerContext associated with the WebApp ClassLoader. This should allow you to
have multiple logging configurations.
So the point is, the ClassLoaderContextSelector has to walk the stack to locate
the calling Class. This has some overhead, but it is only performed once for
each Logger that is obtained.
> Make LogManager/LoggerContext creation time reasonable
> --
>
> Key: LOG4J2-2795
> URL: https://issues.apache.org/jira/browse/LOG4J2-2795
> Project: Log4j 2
> Issue Type: Task
> Components: Core
>Affects Versions: 2.13.0
>Reporter: Romain Manni-Bucau
>Priority: Major
>
> Currently (2.13), LogManager.getLogger("xxx") takes ~600ms on a cold JVM by
> itself.
> For a logging framework it is likely way too much (by comparison a CDI test
> with classpath scanning takes ~50ms).
>
> This ticket is about trying to be faster (maybe by removing java
> serialization usage and reducing registry usage + reflection of plugins by
> generating java code?).
--
This message was sent by Atlassian Jira
(v8.3.4#803005)
[jira] [Commented] (LOG4J2-2795) Make LogManager/LoggerContext creation time reasonable
[
https://issues.apache.org/jira/browse/LOG4J2-2795?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=17049949#comment-17049949
]
Romain Manni-Bucau commented on LOG4J2-2795:
Hi Ralph,
Yes Plugin API helps, for the same line (on another computer) I went from 2.5s
to 1.4s so guess only part of the reflection can still need some precomputation
but it is better on master.
Side note: getting a caller is expensive but not the *functional* case here
since I don't log anything.
> Make LogManager/LoggerContext creation time reasonable
> --
>
> Key: LOG4J2-2795
> URL: https://issues.apache.org/jira/browse/LOG4J2-2795
> Project: Log4j 2
> Issue Type: Task
> Components: Core
>Affects Versions: 2.13.0
>Reporter: Romain Manni-Bucau
>Priority: Major
>
> Currently (2.13), LogManager.getLogger("xxx") takes ~600ms on a cold JVM by
> itself.
> For a logging framework it is likely way too much (by comparison a CDI test
> with classpath scanning takes ~50ms).
>
> This ticket is about trying to be faster (maybe by removing java
> serialization usage and reducing registry usage + reflection of plugins by
> generating java code?).
--
This message was sent by Atlassian Jira
(v8.3.4#803005)
[jira] [Commented] (LOG4J2-2795) Make LogManager/LoggerContext creation time reasonable
[
https://issues.apache.org/jira/browse/LOG4J2-2795?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=17049594#comment-17049594
]
Ralph Goers commented on LOG4J2-2795:
-
It is possible that the improvements with LOG4J2-2621 combined with LOG4J2-2783
on master might help. But without some sort of profiling it isn't possible to
know exactly where improvements are needed. I do know that obtaining the caller
class when creating a Logger is also expensive but I haven't actually profiled
it or testing it using Java 9+.
> Make LogManager/LoggerContext creation time reasonable
> --
>
> Key: LOG4J2-2795
> URL: https://issues.apache.org/jira/browse/LOG4J2-2795
> Project: Log4j 2
> Issue Type: Task
> Components: Core
>Affects Versions: 2.13.0
>Reporter: Romain Manni-Bucau
>Priority: Major
>
> Currently (2.13), LogManager.getLogger("xxx") takes ~600ms on a cold JVM by
> itself.
> For a logging framework it is likely way too much (by comparison a CDI test
> with classpath scanning takes ~50ms).
>
> This ticket is about trying to be faster (maybe by removing java
> serialization usage and reducing registry usage + reflection of plugins by
> generating java code?).
--
This message was sent by Atlassian Jira
(v8.3.4#803005)
[jira] [Commented] (LOG4J2-2795) Make LogManager/LoggerContext creation time reasonable
[
https://issues.apache.org/jira/browse/LOG4J2-2795?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=17049460#comment-17049460
]
Matt Sicker commented on LOG4J2-2795:
-
This is tangentially related to LOG4J2-2694 and the new dependency injection
system which is adapted from how CDI works which should allow for generated
java code as an alternative to reflection, though use of GraalVM could also
help as those reflective operations turn into metadata lookups.
> Make LogManager/LoggerContext creation time reasonable
> --
>
> Key: LOG4J2-2795
> URL: https://issues.apache.org/jira/browse/LOG4J2-2795
> Project: Log4j 2
> Issue Type: Task
> Components: Core
>Affects Versions: 2.13.0
>Reporter: Romain Manni-Bucau
>Priority: Major
>
> Currently (2.13), LogManager.getLogger("xxx") takes ~600ms on a cold JVM by
> itself.
> For a logging framework it is likely way too much (by comparison a CDI test
> with classpath scanning takes ~50ms).
>
> This ticket is about trying to be faster (maybe by removing java
> serialization usage and reducing registry usage + reflection of plugins by
> generating java code?).
--
This message was sent by Atlassian Jira
(v8.3.4#803005)
