Elongated system startup-time because of Logback configuration

Hi, I have a startup_batch file in which I make a call to JAVA application which is responsible for starting up my application with SWT window which displays system running information. Issue is the elongated start up time for application, as I executes my batch file, it stops for a while (as if it's doing nothing) though I know that in background batch file is loooking for logback.grrovy or logback.xml file in the classpath then configures it, but meanwhile my SWT window is not even started and I need to wait for around 45-50 Secs whenever I restart my application. As I can't afford delay in application start so I am looking for some workaround to reduce this logback configuration time by my application everytime. Any helps/inputs/thoughts are welcome. ~Thanks Nikhil

Hi Nikhil, Are you sure the slowness is due to logback? What happens when you replace logback-classic.jar with slf4j-nop.jar? On 19/11/2010 7:35 PM, nikhil diwan wrote:
Hi,
I have a startup_batch file in which I make a call to JAVA application which is responsible for starting up my application with SWT window which displays system running information.
Issue is the elongated start up time for application, as I executes my batch file, it stops for a while (as if it's doing nothing) though I know that in background batch file is loooking for logback.grrovy or logback.xml file in the classpath then configures it, but meanwhile my SWT window is not even started and I need to wait for around 45-50 Secs whenever I restart my application.
As I can't afford delay in application start so I am looking for some workaround to reduce this logback configuration time by my application everytime.
Any helps/inputs/thoughts are welcome.
~Thanks Nikhil

Thanks Ceki for your input...unfortunately It didn't work for me. Jars added in lib for logback:- - groovy-all-1.6.5 - logback-core-0.9.24 - logback-classic-0.9.24 - slf4j-api-1.6.0 As suggested by you, replaced logback-classic with "slf4j-nop-1.3.0", then I got an error saying SLF4J: slf4j-api 1.6.x (or later) is incompatible with this binding. SLF4J: Your binding is version 1.5.5 or earlier. SLF4J: Upgrade your binding to version 1.6.x. or 2.0.x java.lang.NoSuchMethodError: org.slf4j.impl.StaticLoggerBinder.getSingleton()Lor g/slf4j/impl/StaticLoggerBinder; at org.slf4j.LoggerFactory.bind(LoggerFactory.java:121) at org.slf4j.LoggerFactory.performInitialization(LoggerFactory.java:111) at org.slf4j.LoggerFactory.getILoggerFactory(LoggerFactory.java:268) at org.slf4j.LoggerFactory.getLogger(LoggerFactory.java:241) at org.slf4j.LoggerFactory.getLogger(LoggerFactory.java:254) So I replaced slf4j-api-1.6.0 with lower version(i.e. slf4j-api-1.5.5), error gone but no logging in my system! Interestingly, no errors, no warnings and no logging though I jars and groovy file is in the classpath. Did I do anything wrong? - Any light on this ~Nikhil

On Nov 22, 2010, at 6:49 AM, Nikhil Diwan wrote:
Thanks Ceki for your input...unfortunately It didn't work for me.
Jars added in lib for logback:- - groovy-all-1.6.5 - logback-core-0.9.24 - logback-classic-0.9.24 - slf4j-api-1.6.0 As suggested by you, replaced logback-classic with "slf4j-nop-1.3.0", then I got an error saying
SLF4J: slf4j-api 1.6.x (or later) is incompatible with this binding. SLF4J: Your binding is version 1.5.5 or earlier. SLF4J: Upgrade your binding to version 1.6.x. or 2.0.x java.lang.NoSuchMethodError: org.slf4j.impl.StaticLoggerBinder.getSingleton()Lor g/slf4j/impl/StaticLoggerBinder; at org.slf4j.LoggerFactory.bind(LoggerFactory.java:121) at org.slf4j.LoggerFactory.performInitialization(LoggerFactory.java:111)
at org.slf4j.LoggerFactory.getILoggerFactory(LoggerFactory.java:268) at org.slf4j.LoggerFactory.getLogger(LoggerFactory.java:241) at org.slf4j.LoggerFactory.getLogger(LoggerFactory.java:254)
So I replaced slf4j-api-1.6.0 with lower version(i.e. slf4j-api-1.5.5), error gone but no logging in my system!
Interestingly, no errors, no warnings and no logging though I jars and groovy file is in the classpath.
Did I do anything wrong? - Any light on this
The point of this exercise was to remove logback from the picture, which it appears you have successfully done. If you are still having slow startup time then it probably means Logback isn't at fault. Ralph

The point of this exercise was to remove logback from the picture, which it appears you have successfully done. If you are still having slow startup time then it probably means Logback isn't at fault.
Ralph
Hey Ralph, Above steps removed logging, that is true. Sorry, I forgot to mention about improvement in start-up time with no logging. One more thing, there are 25 loggers attached as I need separate loggers in my application. Hence 25 loggers thread are being configured at the start-up time that's gobbling up more time for configuration.

On Nov 22, 2010, at 7:28 AM, Nikhil Diwan wrote:
The point of this exercise was to remove logback from the picture, which it appears you have successfully done. If you are still having slow startup time then it probably means Logback isn't at fault.
Ralph
Hey Ralph,
Above steps removed logging, that is true. Sorry, I forgot to mention about improvement in start-up time with no logging.
You still didn't mention whether there was any improvement.
One more thing, there are 25 loggers attached as I need separate loggers in my application. Hence 25 loggers thread are being configured at the start-up time that's gobbling up more time for configuration.
Loggers don't require their own thread and don't create one. 25 loggers shouldn't be a big deal. Can you send you logback.xml? Ralph

You still didn't mention whether there was any improvement. Yes there is improvement in start-up time, if there is no logging using logabck in my system.
Loggers don't require their own thread and don't create one. 25 loggers shouldn't be a big deal. Can you send you logback.xml?
I am using "logbafck.groovy", see below:- import ch.qos.logback.classic.encoder.PatternLayoutEncoder import ch.qos.logback.core.FileAppender import ch.qos.logback.core.rolling.FixedWindowRollingPolicy import ch.qos.logback.core.rolling.RollingFileAppender import ch.qos.logback.core.rolling.SizeBasedTriggeringPolicy import static ch.qos.logback.classic.Level.DEBUG import static ch.qos.logback.classic.Level.INFO scan('60 seconds') // Defining flag on OS type def isWindows = System.getenv('OS').contains('Windows') // Declaring default location for logging def LOG_HOME = "C:/dvs/client/logs" // Defining log file location for Non-Windows OS if (!isWindows) { LOG_HOME = "/dvs/client/logs" } def filePatternFormat = "%d %-5level %logger - %msg%n" def serviceList = [ "Service_1", "Service_2", "Service_3", "Service_4", "Service_5", "Service_6", "Service_7", "Service_8", "Service_9", "Service_10", "Service_11", "Service_12", "Service_13", "Service_14", "Service_15", "Service_16", "Service_17", "Service_18", "Service_19", "Service_20", "Service_21", "Service_22", "Service_23", "Service_24", "Service_25", "Service_26", "Service_27" ] // Defining appender for root appender('FILE', FileAppender) { file = "${LOG_HOME}/root.log" encoder(PatternLayoutEncoder) { pattern = filePatternFormat } } // Creating appenders for all services for (service in serviceList) { appender("${service}", RollingFileAppender) { file = "${LOG_HOME}/${service}/${service}.log" rollingPolicy(FixedWindowRollingPolicy) { fileNamePattern = "${LOG_HOME}/${service}/${service}.%i.log.zip" minIndex = 1 maxIndex = 10 } triggeringPolicy(SizeBasedTriggeringPolicy) { maxFileSize = "100MB" } encoder(PatternLayoutEncoder) { pattern = filePatternFormat } } } // Defining logger per service logger 'Control.Service_1', INFO, ['Service_1'], false logger 'Control.Service_2', INFO, ['Service_2'], false logger 'Build_Services.Service_3', INFO, ['Service_3'], false logger 'Build_Services.Service_4', INFO, ['Service_4'], false logger 'Build_Services.Service_5', INFO, ['Service_5'], false logger 'Build_Services.Service_6', INFO, ['Service_6'], false logger 'Build_Services.Service_7', INFO, ['Service_7'], false logger 'Build_Services.Service_8', INFO, ['Service_8'], false logger 'Build_Services.Service_9', INFO, ['Service_9'], false logger 'Build_Services.Service_10', INFO, ['Service_10'], false logger 'Build_Services.Service_11', INFO, ['Service_11'], false logger 'Build_Services.Service_12', INFO, ['Service_12'], false logger 'Build_Services.Service_13', INFO, ['Service_13'], false logger 'Build_Services.Service_14', INFO, ['Service_14'], false logger 'Build_Services.Service_15', INFO, ['Service_15'], false logger 'Regression_Services.Service_16', INFO, ['Service_16'], false logger 'Regression_Services.Service_17', INFO, ['Service_17'], false logger 'Regression_Services.Service_18', INFO, ['Service_18'], false logger 'Regression_Services.Service_19', INFO, ['Service_19'], false logger 'Regression_Services.Service_20', INFO, ['Service_20'], false logger 'Regression_Services.Service_21', INFO, ['Service_21'], false logger 'Regression_Services.Service_22', INFO, ['Service_22'], false logger 'Regression_Services.Service_23', INFO, ['Service_23'], false logger 'Regression_Services.Service_24', INFO, ['Service_24'], false logger 'Regression_Services.Service_25', INFO, ['Service_25'], false logger 'Regression_Services.Service_26', INFO, ['Service_26'], false logger 'Regression_Services.Service_27', INFO, ['Service_27'], false root DEBUG, ['FILE']

Off topic, but how about using: def serviceList = (1..27).collect { "Service_$it" } to define your service list? Much less noisy and repetitive. On 23 Nov 2010, at 07:39, Nikhil Diwan wrote:
def serviceList = [ "Service_1", "Service_2", "Service_3", "Service_4", "Service_5", "Service_6", "Service_7", "Service_8", "Service_9", "Service_10", "Service_11", "Service_12", "Service_13", "Service_14", "Service_15", "Service_16", "Service_17", "Service_18", "Service_19", "Service_20", "Service_21", "Service_22", "Service_23", "Service_24", "Service_25", "Service_26", "Service_27" ]
_______________________________________________ Logback-user mailing list Logback-user@qos.ch http://qos.ch/mailman/listinfo/logback-user

On my machine it takes 900 milliseconds to parse and run your config file. It takes about 500 millis to parse and empty config file. So while 900 millis is not particularly fast, it's still much faster than the 45 seconds you report. Is it possible that the config file is located on the network (and the network suffers from DNS timeouts)? On 23.11.2010 08:39, Nikhil Diwan wrote:
You still didn't mention whether there was any improvement. Yes there is improvement in start-up time, if there is no logging using logabck in my system.
Loggers don't require their own thread and don't create one. 25 loggers shouldn't be a big deal. Can you send you logback.xml?
I am using "logbafck.groovy", see below:-
import ch.qos.logback.classic.encoder.PatternLayoutEncoder import ch.qos.logback.core.FileAppender import ch.qos.logback.core.rolling.FixedWindowRollingPolicy import ch.qos.logback.core.rolling.RollingFileAppender import ch.qos.logback.core.rolling.SizeBasedTriggeringPolicy
import static ch.qos.logback.classic.Level.DEBUG import static ch.qos.logback.classic.Level.INFO
scan('60 seconds')
// Defining flag on OS type def isWindows = System.getenv('OS').contains('Windows')
// Declaring default location for logging def LOG_HOME = "C:/dvs/client/logs"
// Defining log file location for Non-Windows OS if (!isWindows) { LOG_HOME = "/dvs/client/logs" }
def filePatternFormat = "%d %-5level %logger - %msg%n" def serviceList = [ "Service_1", "Service_2", "Service_3", "Service_4", "Service_5", "Service_6", "Service_7", "Service_8", "Service_9", "Service_10", "Service_11", "Service_12", "Service_13", "Service_14", "Service_15", "Service_16", "Service_17", "Service_18", "Service_19", "Service_20", "Service_21", "Service_22", "Service_23", "Service_24", "Service_25", "Service_26", "Service_27" ]
// Defining appender for root appender('FILE', FileAppender) { file = "${LOG_HOME}/root.log" encoder(PatternLayoutEncoder) { pattern = filePatternFormat } }
// Creating appenders for all services for (service in serviceList) { appender("${service}", RollingFileAppender) { file = "${LOG_HOME}/${service}/${service}.log" rollingPolicy(FixedWindowRollingPolicy) { fileNamePattern = "${LOG_HOME}/${service}/${service}.%i.log.zip" minIndex = 1 maxIndex = 10 } triggeringPolicy(SizeBasedTriggeringPolicy) { maxFileSize = "100MB" } encoder(PatternLayoutEncoder) { pattern = filePatternFormat } } }
// Defining logger per service logger 'Control.Service_1', INFO, ['Service_1'], false logger 'Control.Service_2', INFO, ['Service_2'], false logger 'Build_Services.Service_3', INFO, ['Service_3'], false logger 'Build_Services.Service_4', INFO, ['Service_4'], false logger 'Build_Services.Service_5', INFO, ['Service_5'], false logger 'Build_Services.Service_6', INFO, ['Service_6'], false logger 'Build_Services.Service_7', INFO, ['Service_7'], false logger 'Build_Services.Service_8', INFO, ['Service_8'], false logger 'Build_Services.Service_9', INFO, ['Service_9'], false logger 'Build_Services.Service_10', INFO, ['Service_10'], false logger 'Build_Services.Service_11', INFO, ['Service_11'], false logger 'Build_Services.Service_12', INFO, ['Service_12'], false logger 'Build_Services.Service_13', INFO, ['Service_13'], false logger 'Build_Services.Service_14', INFO, ['Service_14'], false logger 'Build_Services.Service_15', INFO, ['Service_15'], false logger 'Regression_Services.Service_16', INFO, ['Service_16'], false logger 'Regression_Services.Service_17', INFO, ['Service_17'], false logger 'Regression_Services.Service_18', INFO, ['Service_18'], false logger 'Regression_Services.Service_19', INFO, ['Service_19'], false logger 'Regression_Services.Service_20', INFO, ['Service_20'], false logger 'Regression_Services.Service_21', INFO, ['Service_21'], false logger 'Regression_Services.Service_22', INFO, ['Service_22'], false logger 'Regression_Services.Service_23', INFO, ['Service_23'], false logger 'Regression_Services.Service_24', INFO, ['Service_24'], false logger 'Regression_Services.Service_25', INFO, ['Service_25'], false logger 'Regression_Services.Service_26', INFO, ['Service_26'], false logger 'Regression_Services.Service_27', INFO, ['Service_27'], false
root DEBUG, ['FILE']

On my machine it takes 900 milliseconds to parse and run your config file. It takes about 500 millis to parse and empty config file. So while 900 millis is not particularly fast, it's still much faster than the 45 seconds you report. Is it possible that the config file is located on the network (and the network suffers from DNS timeouts)?
It's true that groovy config file is on shared drive which is mounted first on local machine and then my application uses it. But I don't think that there will be any DNS timeouts in my case. Will check and inform U on this soon. Thanks for suggestion.
participants (6)
-
Ceki Gulcu
-
Ceki Gülcü
-
nikhil diwan
-
Nikhil Diwan
-
Ralph Goers
-
Robert Elliot