getting logback to scale on multitenant app
Hi I'd appreciate guidance on how to get Logback to use less resources in our multitenant app. It seems every time we add a new tenant, log back creates a few more async appender threads. This affects the scalability of our software. In our app, each tenant has an audit and a debug log. Async apppender is being used to write to each log respectively. Our problem is that whenever a new tenant is added, many more threads get created. it seems a new worker thread is assigned to each appender. Is there a way to get Logback to rather use a shared thread pool? Stacks at 2017-12-14 10:33:57 PM (uptime 22m 24s) AsyncAppender-Worker-audit-template [WAITING] [DAEMON] sun.misc.Unsafe.park(boolean, long) Unsafe.java (native) java.util.concurrent.locks.LockSupport.park(Object) LockSupport.java:175 java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await() AbstractQueuedSynchronizer.java:2039 java.util.concurrent.ArrayBlockingQueue.take() ArrayBlockingQueue.java:403 ch.qos.logback.core.AsyncAppenderBase$Worker.run() AsyncAppenderBase.java:289 Thanks in advance Jamie
Hi Jamie, It’s not clear how your “multi-tennent” approach affects the loading of logback. I guess somehow you are creating new instances of logback? Each instance of AsyncAppender is blocking, and thus requires one thread per per AsyncAppender. Dave
On 14 Dec 2017, at 21:28, Jamie <jamie@stimulussoft.com> wrote:
Hi
I'd appreciate guidance on how to get Logback to use less resources in our multitenant app. It seems every time we add a new tenant, log back creates a few more async appender threads. This affects the scalability of our software. In our app, each tenant has an audit and a debug log. Async apppender is being used to write to each log respectively. Our problem is that whenever a new tenant is added, many more threads get created. it seems a new worker thread is assigned to each appender. Is there a way to get Logback to rather use a shared thread pool?
Stacks at 2017-12-14 10:33:57 PM (uptime 22m 24s)
AsyncAppender-Worker-audit-template [WAITING] [DAEMON] sun.misc.Unsafe.park(boolean, long) Unsafe.java (native) java.util.concurrent.locks.LockSupport.park(Object) LockSupport.java:175 java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await() AbstractQueuedSynchronizer.java:2039 java.util.concurrent.ArrayBlockingQueue.take() ArrayBlockingQueue.java:403 ch.qos.logback.core.AsyncAppenderBase$Worker.run() AsyncAppenderBase.java:289
Thanks in advance
Jamie
_______________________________________________ logback-user mailing list logback-user@qos.ch http://mailman.qos.ch/mailman/listinfo/logback-user
David Thanks for your consideration. You seem to imply this shouldn't be happening. If so, that's great. The below initAppenders() function is called on startup of the server. Perhaps the way the appenders are being initialized and startedis causing the behavior. Is there an alternative? private void initAppenders() { RollOverAppenderSettings debugAppender = AppendersFactory.getAppenderSettings(APPENDER.DEBUG); assert debugAppender != null; debugAppender.setLoggerName(application.getLoggerName()); debugAppender.setLogFile(getDebugLogFile()); LogUtil.addAppender(debugAppender); RollOverAppenderSettings auditAppender = AppendersFactory.getAppenderSettings(APPENDER.AUDIT); assert auditAppender != null; auditAppender.setLoggerName("audit-" + application.getLoggerName()); auditAppender.setLogFile(getAuditLogFile()); LogUtil.addAppender(auditAppender); LogUtil.applyLogLevel("audit-" + application.getLoggerName(), "info"); RollOverAppenderSettings trashAppender = AppendersFactory.getAppenderSettings(APPENDER.TRASH); assert trashAppender != null; trashAppender.setLoggerName("trash-" + application.getLoggerName()); trashAppender.setLogFile(getTrashLogFile()); LogUtil.addAppender(trashAppender); LogUtil.applyLogLevel("trash-" + application.getLoggerName(), "info"); } Where the following methods are defined in LogUtil: public static void addAppender(RollOverAppenderSettings appender) { LoggerContext loggerContext = (LoggerContext) LoggerFactory.getILoggerFactory(); File logFile = appender.getLogFile(); RollingFileAppender<ILoggingEvent> rfAppender = new RollingFileAppender<>(); rfAppender.setName(appender.getLoggerName()); rfAppender.setContext(loggerContext); rfAppender.setFile(logFile.getPath()); RollingPolicy rollingPolicy = appender.getRollingPolicy(); rollingPolicy.setParent(rfAppender); rollingPolicy.start(); TriggeringPolicy<ILoggingEvent> triggeringPolicy = appender.getTriggeringPolicy(); triggeringPolicy.start(); PatternLayoutEncoder encoder = new PatternLayoutEncoder(); encoder.setContext(loggerContext); encoder.setPattern(appender.getLogEntryPattern()); encoder.start(); rfAppender.setEncoder(encoder); rfAppender.setRollingPolicy(rollingPolicy); rfAppender.setTriggeringPolicy(triggeringPolicy); rfAppender.start(); AsyncAppender asyncAppender = new AsyncAppender(); asyncAppender.setName(appender.getLoggerName()); asyncAppender.setContext(loggerContext); asyncAppender.setQueueSize(1024); asyncAppender.addAppender(rfAppender); asyncAppender.start(); ch.qos.logback.classic.Logger logbackLogger = loggerContext.getLogger(appender.getLoggerName()); logbackLogger.setAdditive(false); logbackLogger.addAppender(asyncAppender); if (System.getProperty("stdout") != null) { ConsoleAppender<ILoggingEvent> consoleAppender = new ConsoleAppender<>(); PatternLayoutEncoder stdoutEncoder = new PatternLayoutEncoder(); stdoutEncoder.setContext(loggerContext); stdoutEncoder.setPattern("%d{yyyy-MM-dd HH:mm:ss} %c{1} [%p] %m%n"); stdoutEncoder.start(); consoleAppender.setEncoder(stdoutEncoder); consoleAppender.start(); logbackLogger.addAppender(consoleAppender); } StatusPrinter.print(loggerContext); logger = LoggerFactory.getLogger(appender.getLoggerName()); } public static void applyLogLevel(String loggerName, String logLevel) { Logger log = LoggerFactory.getLogger(loggerName); if (!(log instanceof ch.qos.logback.classic.Logger)) { logger.debug("cannot set log level. not using logback"); return; } ch.qos.logback.classic.Logger logger = (ch.qos.logback.classic.Logger) LoggerFactory.getLogger(loggerName); Level level = Level.INFO; try { level = Level.valueOf(logLevel.toUpperCase(Locale.ENGLISH)); } catch (Exception e) { logger.error("invalid new log level value {level='" + logLevel+ "'}"); } logger.setLevel(level); } On 2017/12/15 00:04, David Roussel wrote:
Hi Jamie,
It’s not clear how your “multi-tennent” approach affects the loading of logback. I guess somehow you are creating new instances of logback?
Each instance of AsyncAppender is blocking, and thus requires one thread per per AsyncAppender.
Dave
On 14 Dec 2017, at 21:28, Jamie <jamie@stimulussoft.com> wrote:
Hi
I'd appreciate guidance on how to get Logback to use less resources in our multitenant app. It seems every time we add a new tenant, log back creates a few more async appender threads. This affects the scalability of our software. In our app, each tenant has an audit and a debug log. Async apppender is being used to write to each log respectively. Our problem is that whenever a new tenant is added, many more threads get created. it seems a new worker thread is assigned to each appender. Is there a way to get Logback to rather use a shared thread pool?
Stacks at 2017-12-14 10:33:57 PM (uptime 22m 24s)
AsyncAppender-Worker-audit-template [WAITING] [DAEMON] sun.misc.Unsafe.park(boolean, long) Unsafe.java (native) java.util.concurrent.locks.LockSupport.park(Object) LockSupport.java:175 java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await() AbstractQueuedSynchronizer.java:2039 java.util.concurrent.ArrayBlockingQueue.take() ArrayBlockingQueue.java:403 ch.qos.logback.core.AsyncAppenderBase$Worker.run() AsyncAppenderBase.java:289
Thanks in advance
Jamie
_______________________________________________ logback-user mailing list logback-user@qos.ch http://mailman.qos.ch/mailman/listinfo/logback-user
logback-user mailing list logback-user@qos.ch http://mailman.qos.ch/mailman/listinfo/logback-user
-- Stimulus Software Stimulus Software Office: +1-713-343-8824 / Fax: +1 713 357 6647 http://www.stimulussoft.com
David To follow up: I examined the Logback source code in the repo. Specifically, the class AsyncAppenderBase <https://github.com/qos-ch/logback/blob/master/logback-core/src/main/java/ch/qos/logback/core/AsyncAppenderBase.java>. It appears as if this is a design issue. To get it to work the way we want, Logback code would need to be refactored. Each appender is assigned its own worker thread. The worker thread is started when the appender is started. I guess the designers of logback hadn't anticipated a scenario where many appenders would be used. public void start() { .. worker.setDaemon(true); worker.setName("AsyncAppender-Worker-" + getName()); super.start(); worker.start(); } Cheers Jamie On 2017/12/15 09:37, Jamie wrote:
David
Thanks for your consideration. You seem to imply this shouldn't be happening. If so, that's great. The below initAppenders() function is called on startup of the server. Perhaps the way the appenders are being initialized and startedis causing the behavior. Is there an alternative?
participants (2)
-
David Roussel -
Jamie