You are viewing a plain text version of this content. The canonical link for it is here.
Posted to log4j-dev@logging.apache.org by "Tiago Cardoso (JIRA)" <ji...@apache.org> on 2014/03/13 13:19:48 UTC
[jira] [Comment Edited] (LOG4J2-565) Log4j2 loading time
[ https://issues.apache.org/jira/browse/LOG4J2-565?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13933160#comment-13933160 ]
Tiago Cardoso edited comment on LOG4J2-565 at 3/13/14 12:19 PM:
----------------------------------------------------------------
I was in fact extracting all jars into my application Jar.
I have redone the tests while keeping the log4j-api-2.0-rc1.jar and the log4j-core-2.0-rc1.jar separate. The AppJar.jar has only 4KB and 3 classes with it (only one is being used). Now I've got the following results:
Starting application:1394712834342
Getting the first logger:1394712834355
2014-03-13 12:14:08,847 DEBUG Generated plugins in 0.000383692 seconds
2014-03-13 12:14:08,919 DEBUG Found Plugin Map at jar:file:/tmp/AppJar_lib/log4j-core-2.0-rc1.jar!/org/apache/logging/log4j/core/config/plugins/Log4j2Plugins.dat
2014-03-13 12:14:18,214 DEBUG Generated plugins in 9.338745544 seconds
2014-03-13 12:14:23,052 DEBUG Generated plugins in 4.723707079 seconds
2014-03-13 12:14:23,484 DEBUG Calling createLayout on class org.apache.logging.log4j.core.layout.PatternLayout for element PatternLayout with params(pattern="[%d{dd MMM yyyy - HH:mm:ss.SSS}] %p - %m%n", Configuration(/tmp/log4j2.xml), null, charset="null", alwaysWriteExceptions="null", noConsoleNoAnsi="null")
2014-03-13 12:14:28,500 DEBUG Generated plugins in 5.000661231 seconds
2014-03-13 12:14:28,643 DEBUG Calling createAppender on class org.apache.logging.log4j.core.appender.ConsoleAppender for element Console with params(PatternLayout([%d{dd MMM yyyy - HH:mm:ss.SSS}] %p - %m%n), null, target="SYSTEM_OUT", name="Console", follow="null", ignoreExceptions="null")
2014-03-13 12:14:28,717 DEBUG Calling createLayout on class org.apache.logging.log4j.core.layout.PatternLayout for element PatternLayout with params(pattern="[%d{dd MMM yyyy - HH:mm:ss.SSS}] %p - %m%n", Configuration(/tmp/log4j2.xml), null, charset="null", alwaysWriteExceptions="null", noConsoleNoAnsi="null")
2014-03-13 12:14:28,793 DEBUG Calling createPolicy on class org.apache.logging.log4j.core.appender.rolling.SizeBasedTriggeringPolicy for element SizeBasedTriggeringPolicy with params(size="100 KB")
2014-03-13 12:14:28,894 DEBUG Calling createPolicy on class org.apache.logging.log4j.core.appender.rolling.CompositeTriggeringPolicy for element Policies with params(Policies={SizeBasedTriggeringPolicy(size=102400)})
2014-03-13 12:14:29,006 DEBUG Calling createStrategy on class org.apache.logging.log4j.core.appender.rolling.DefaultRolloverStrategy for element DefaultRolloverStrategy with params(max="200", min="null", fileIndex="null", compressionLevel="1", Configuration(/tmp/log4j2.xml))
2014-03-13 12:14:29,125 DEBUG Calling createAppender on class org.apache.logging.log4j.core.appender.RollingRandomAccessFileAppender for element RollingRandomAccessFile with params(fileName="/tmp/teste.log", filePattern="/tmp/testingLog.PART_%i.gz", append="null", name="RollingRandomAccessFile", immediateFlush="true", Policies(CompositeTriggeringPolicy{SizeBasedTriggeringPolicy(size=102400)}), DefaultRolloverStrategy(DefaultRolloverStrategy(min=1, max=200)), PatternLayout([%d{dd MMM yyyy - HH:mm:ss.SSS}] %p - %m%n), null, ignoreExceptions="null", advertise="null", advertiseURI="null", Configuration(/tmp/log4j2.xml))
2014-03-13 12:14:29,212 TRACE RandomAccessFile /tmp/teste.log seek to 548
2014-03-13 12:14:29,229 DEBUG Starting RollingRandomAccessFileManager /tmp/teste.log
2014-03-13 12:14:34,857 DEBUG Generated plugins in 5.581791074 seconds
2014-03-13 12:14:34,893 DEBUG Calling createAppenders on class org.apache.logging.log4j.core.config.plugins.AppendersPlugin for element Appenders with params(Appenders={Console, RollingRandomAccessFile})
2014-03-13 12:14:34,926 DEBUG Calling createAppenderRef on class org.apache.logging.log4j.core.config.AppenderRef for element AppenderRef with params(ref="RollingRandomAccessFile", level="null", null)
2014-03-13 12:14:34,955 DEBUG Calling createAppenderRef on class org.apache.logging.log4j.core.config.AppenderRef for element AppenderRef with params(ref="Console", level="null", null)
2014-03-13 12:14:35,012 DEBUG Calling createLogger on class org.apache.logging.log4j.core.config.LoggerConfig$RootLogger for element Root with params(additivity="null", level="trace", includeLocation="null", AppenderRef={RollingRandomAccessFile, Console}, Properties={}, Configuration(/tmp/log4j2.xml), null)
2014-03-13 12:14:35,050 DEBUG Calling createLoggers on class org.apache.logging.log4j.core.config.plugins.LoggersPlugin for element Loggers with params(Loggers={root})
2014-03-13 12:14:37,687 DEBUG Registering MBean org.apache.logging.log4j2:type=sun.misc.Launcher$AppClassLoader@cac268
2014-03-13 12:14:37,782 DEBUG Registering MBean org.apache.logging.log4j2:type=sun.misc.Launcher$AppClassLoader@cac268,component=StatusLogger
2014-03-13 12:14:37,847 DEBUG Registering MBean org.apache.logging.log4j2:type=sun.misc.Launcher$AppClassLoader@cac268,component=ContextSelector
2014-03-13 12:14:37,954 DEBUG Registering MBean org.apache.logging.log4j2:type=sun.misc.Launcher$AppClassLoader@cac268,component=Loggers,name=
2014-03-13 12:14:38,039 DEBUG Registering MBean org.apache.logging.log4j2:type=sun.misc.Launcher$AppClassLoader@cac268,component=Appenders,name=Console
2014-03-13 12:14:38,104 DEBUG Registering MBean org.apache.logging.log4j2:type=sun.misc.Launcher$AppClassLoader@cac268,component=Appenders,name=RollingRandomAccessFile
2014-03-13 12:14:38,128 DEBUG Reconfiguration completed
Loggers are fully loaded:
[13 Mar 2014 - 12:14:38.441] TRACE - Entering application.
[13 Mar 2014 - 12:14:38.514] TRACE - Going to leave application.1394712878514
2014-03-13 12:14:38,565 DEBUG Shutting down RollingRandomAccessFileManager /tmp/teste.log
2014-03-13 12:14:38,585 DEBUG Shutting down OutputStreamManager SYSTEM_OUT
2014-03-13 12:14:38,613 DEBUG Unregistering MBean org.apache.logging.log4j2:type=sun.misc.Launcher$AppClassLoader@cac268
2014-03-13 12:14:38,636 DEBUG Unregistering MBean org.apache.logging.log4j2:type=sun.misc.Launcher$AppClassLoader@cac268,component=StatusLogger
2014-03-13 12:14:38,653 DEBUG Unregistering MBean org.apache.logging.log4j2:type=sun.misc.Launcher$AppClassLoader@cac268,component=ContextSelector
2014-03-13 12:14:38,719 DEBUG Unregistering MBean org.apache.logging.log4j2:type=sun.misc.Launcher$AppClassLoader@cac268,component=Loggers,name=
2014-03-13 12:14:38,757 DEBUG Unregistering MBean org.apache.logging.log4j2:type=sun.misc.Launcher$AppClassLoader@cac268,component=Appenders,name=RollingRandomAccessFile
2014-03-13 12:14:38,770 DEBUG Unregistering MBean org.apache.logging.log4j2:type=sun.misc.Launcher$AppClassLoader@cac268,component=Appenders,name=Console
was (Author: matutano):
I was in fact extracting all jars into my application Jar.
I have redone the tests while keeping the log4j-api-2.0-rc1.jar and the log4j-core-2.0-rc1.jar separate with the following results:
Starting application:1394712834342
Getting the first logger:1394712834355
2014-03-13 12:14:08,847 DEBUG Generated plugins in 0.000383692 seconds
2014-03-13 12:14:08,919 DEBUG Found Plugin Map at jar:file:/tmp/AppJar_lib/log4j-core-2.0-rc1.jar!/org/apache/logging/log4j/core/config/plugins/Log4j2Plugins.dat
2014-03-13 12:14:18,214 DEBUG Generated plugins in 9.338745544 seconds
2014-03-13 12:14:23,052 DEBUG Generated plugins in 4.723707079 seconds
2014-03-13 12:14:23,484 DEBUG Calling createLayout on class org.apache.logging.log4j.core.layout.PatternLayout for element PatternLayout with params(pattern="[%d{dd MMM yyyy - HH:mm:ss.SSS}] %p - %m%n", Configuration(/tmp/log4j2.xml), null, charset="null", alwaysWriteExceptions="null", noConsoleNoAnsi="null")
2014-03-13 12:14:28,500 DEBUG Generated plugins in 5.000661231 seconds
2014-03-13 12:14:28,643 DEBUG Calling createAppender on class org.apache.logging.log4j.core.appender.ConsoleAppender for element Console with params(PatternLayout([%d{dd MMM yyyy - HH:mm:ss.SSS}] %p - %m%n), null, target="SYSTEM_OUT", name="Console", follow="null", ignoreExceptions="null")
2014-03-13 12:14:28,717 DEBUG Calling createLayout on class org.apache.logging.log4j.core.layout.PatternLayout for element PatternLayout with params(pattern="[%d{dd MMM yyyy - HH:mm:ss.SSS}] %p - %m%n", Configuration(/tmp/log4j2.xml), null, charset="null", alwaysWriteExceptions="null", noConsoleNoAnsi="null")
2014-03-13 12:14:28,793 DEBUG Calling createPolicy on class org.apache.logging.log4j.core.appender.rolling.SizeBasedTriggeringPolicy for element SizeBasedTriggeringPolicy with params(size="100 KB")
2014-03-13 12:14:28,894 DEBUG Calling createPolicy on class org.apache.logging.log4j.core.appender.rolling.CompositeTriggeringPolicy for element Policies with params(Policies={SizeBasedTriggeringPolicy(size=102400)})
2014-03-13 12:14:29,006 DEBUG Calling createStrategy on class org.apache.logging.log4j.core.appender.rolling.DefaultRolloverStrategy for element DefaultRolloverStrategy with params(max="200", min="null", fileIndex="null", compressionLevel="1", Configuration(/tmp/log4j2.xml))
2014-03-13 12:14:29,125 DEBUG Calling createAppender on class org.apache.logging.log4j.core.appender.RollingRandomAccessFileAppender for element RollingRandomAccessFile with params(fileName="/tmp/teste.log", filePattern="/tmp/testingLog.PART_%i.gz", append="null", name="RollingRandomAccessFile", immediateFlush="true", Policies(CompositeTriggeringPolicy{SizeBasedTriggeringPolicy(size=102400)}), DefaultRolloverStrategy(DefaultRolloverStrategy(min=1, max=200)), PatternLayout([%d{dd MMM yyyy - HH:mm:ss.SSS}] %p - %m%n), null, ignoreExceptions="null", advertise="null", advertiseURI="null", Configuration(/tmp/log4j2.xml))
2014-03-13 12:14:29,212 TRACE RandomAccessFile /tmp/teste.log seek to 548
2014-03-13 12:14:29,229 DEBUG Starting RollingRandomAccessFileManager /tmp/teste.log
2014-03-13 12:14:34,857 DEBUG Generated plugins in 5.581791074 seconds
2014-03-13 12:14:34,893 DEBUG Calling createAppenders on class org.apache.logging.log4j.core.config.plugins.AppendersPlugin for element Appenders with params(Appenders={Console, RollingRandomAccessFile})
2014-03-13 12:14:34,926 DEBUG Calling createAppenderRef on class org.apache.logging.log4j.core.config.AppenderRef for element AppenderRef with params(ref="RollingRandomAccessFile", level="null", null)
2014-03-13 12:14:34,955 DEBUG Calling createAppenderRef on class org.apache.logging.log4j.core.config.AppenderRef for element AppenderRef with params(ref="Console", level="null", null)
2014-03-13 12:14:35,012 DEBUG Calling createLogger on class org.apache.logging.log4j.core.config.LoggerConfig$RootLogger for element Root with params(additivity="null", level="trace", includeLocation="null", AppenderRef={RollingRandomAccessFile, Console}, Properties={}, Configuration(/tmp/log4j2.xml), null)
2014-03-13 12:14:35,050 DEBUG Calling createLoggers on class org.apache.logging.log4j.core.config.plugins.LoggersPlugin for element Loggers with params(Loggers={root})
2014-03-13 12:14:37,687 DEBUG Registering MBean org.apache.logging.log4j2:type=sun.misc.Launcher$AppClassLoader@cac268
2014-03-13 12:14:37,782 DEBUG Registering MBean org.apache.logging.log4j2:type=sun.misc.Launcher$AppClassLoader@cac268,component=StatusLogger
2014-03-13 12:14:37,847 DEBUG Registering MBean org.apache.logging.log4j2:type=sun.misc.Launcher$AppClassLoader@cac268,component=ContextSelector
2014-03-13 12:14:37,954 DEBUG Registering MBean org.apache.logging.log4j2:type=sun.misc.Launcher$AppClassLoader@cac268,component=Loggers,name=
2014-03-13 12:14:38,039 DEBUG Registering MBean org.apache.logging.log4j2:type=sun.misc.Launcher$AppClassLoader@cac268,component=Appenders,name=Console
2014-03-13 12:14:38,104 DEBUG Registering MBean org.apache.logging.log4j2:type=sun.misc.Launcher$AppClassLoader@cac268,component=Appenders,name=RollingRandomAccessFile
2014-03-13 12:14:38,128 DEBUG Reconfiguration completed
Loggers are fully loaded:
[13 Mar 2014 - 12:14:38.441] TRACE - Entering application.
[13 Mar 2014 - 12:14:38.514] TRACE - Going to leave application.1394712878514
2014-03-13 12:14:38,565 DEBUG Shutting down RollingRandomAccessFileManager /tmp/teste.log
2014-03-13 12:14:38,585 DEBUG Shutting down OutputStreamManager SYSTEM_OUT
2014-03-13 12:14:38,613 DEBUG Unregistering MBean org.apache.logging.log4j2:type=sun.misc.Launcher$AppClassLoader@cac268
2014-03-13 12:14:38,636 DEBUG Unregistering MBean org.apache.logging.log4j2:type=sun.misc.Launcher$AppClassLoader@cac268,component=StatusLogger
2014-03-13 12:14:38,653 DEBUG Unregistering MBean org.apache.logging.log4j2:type=sun.misc.Launcher$AppClassLoader@cac268,component=ContextSelector
2014-03-13 12:14:38,719 DEBUG Unregistering MBean org.apache.logging.log4j2:type=sun.misc.Launcher$AppClassLoader@cac268,component=Loggers,name=
2014-03-13 12:14:38,757 DEBUG Unregistering MBean org.apache.logging.log4j2:type=sun.misc.Launcher$AppClassLoader@cac268,component=Appenders,name=RollingRandomAccessFile
2014-03-13 12:14:38,770 DEBUG Unregistering MBean org.apache.logging.log4j2:type=sun.misc.Launcher$AppClassLoader@cac268,component=Appenders,name=Console
> Log4j2 loading time
> -------------------
>
> Key: LOG4J2-565
> URL: https://issues.apache.org/jira/browse/LOG4J2-565
> Project: Log4j 2
> Issue Type: Bug
> Components: API
> Affects Versions: 2.0-rc1
> Environment: Using ejre1.6.0_25 in an ARM926EJ-S rev 5 (v5l)
> Reporter: Tiago Cardoso
>
> Everything runs fine on the Desktop computer, but the embedded system struggles to obtain the Logger.
> It takes 17 seconds just to run this line:
> Logger logger = LogManager.getLogger("testLogger");
> The classpath is empty and the whole applications is just:
> public static void main(String[] arg){
> System.out.println("Starting application:" + System.currentTimeMillis());
> Logger logger = LogManager.getLogger("testLogger");
> logger.trace("Going to leave application." + System.currentTimeMillis());
> System.exit(1);
> }
> The same system is able to run a client graphic application without this kind of event.
--
This message was sent by Atlassian JIRA
(v6.2#6252)
---------------------------------------------------------------------
To unsubscribe, e-mail: log4j-dev-unsubscribe@logging.apache.org
For additional commands, e-mail: log4j-dev-help@logging.apache.org