You are viewing a plain text version of this content. The canonical link for it is here.
Posted to issues@karaf.apache.org by Jaroslav Tóth <jt...@frinx.io> on 2019/04/11 10:12:11 UTC
Copying of PaxLoggingEvent
Hi,
I would like to ask you about reason why it is necessary to copy contents of PaxLoggingEvent to new KarafLogEvent object in the method org.apache.karaf.log.core.internal. LogServiceImpl. doAppend(..). In our environment under high load (a lot of threads that log messages to karaf) we notice long-term (in range of several seconds) BLOCKED state at the monitor of this method because demanding Throwable.getOurStackTrace(..) is invoked very often. Is it safe to just directly push input log event to buffer and broke it to subsribed appenders?
NOTE: The logged messages have stack trace usually about 30 lines long (there are not any logged messages with extremelly long stack trace or long message body).
@Override
public synchronized void doAppend(PaxLoggingEvent event) {
event.getProperties(); // ensure MDC properties are copied
this.buffer.add(event);
for (PaxAppender appender : appenders) {
try {
appender.doAppend(event);
} catch (Throwable t) {
// Ignore
}
}
}
Slice from the jstack - logging that causes blocked state at other threads that try to log something (blocked at 0x00000004c1148e90):
"remote-connector-processing-executor-7" #484 prio=5 os_prio=0 tid=0x00007f6c6dead800 nid=0x2db runnable [0x00007f6bebf58000]
java.lang.Thread.State: RUNNABLE
at java.lang.Throwable.getStackTraceElement(Native Method)
at java.lang.Throwable.getOurStackTrace(Throwable.java:827)
- locked <0x0000000798726d78> (a org.opendaylight.controller.md.sal.common.api.data.ReadFailedException)
at java.lang.Throwable.getStackTrace(Throwable.java:816)
at org.apache.logging.log4j.core.impl.ThrowableProxy.<init>(ThrowableProxy.java:148)
at org.apache.logging.log4j.core.impl.ThrowableProxy.<init>(ThrowableProxy.java:125)
at org.apache.logging.log4j.core.impl.MutableLogEvent.getThrownProxy(MutableLogEvent.java:338)
at org.ops4j.pax.logging.log4j2.internal.PaxLoggingEventImpl.getThrowableStrRep(PaxLoggingEventImpl.java:76)
at org.apache.karaf.log.core.internal.KarafLogEvent.<init>(KarafLogEvent.java:45)
at org.apache.karaf.log.core.internal.LogServiceImpl.doAppend(LogServiceImpl.java:169)
- locked <0x00000004c1148e90> (a org.apache.karaf.log.core.internal.LogServiceImpl)
at org.ops4j.pax.logging.log4j2.internal.PaxAppenderProxy.doAppend(PaxAppenderProxy.java:65)
at org.ops4j.pax.logging.log4j2.appender.PaxOsgiAppender.append(PaxOsgiAppender.java:82)
at org.apache.logging.log4j.core.config.AppenderControl.tryCallAppender(AppenderControl.java:156)
at org.apache.logging.log4j.core.config.AppenderControl.callAppender0(AppenderControl.java:129)
at org.apache.logging.log4j.core.config.AppenderControl.callAppenderPreventRecursion(AppenderControl.java:120)
at org.apache.logging.log4j.core.config.AppenderControl.callAppender(AppenderControl.java:84)
at org.apache.logging.log4j.core.config.LoggerConfig.callAppenders(LoggerConfig.java:448)
at org.apache.logging.log4j.core.config.LoggerConfig.processLogEvent(LoggerConfig.java:433)
at org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:417)
at org.apache.logging.log4j.core.config.LoggerConfig.logParent(LoggerConfig.java:439)
at org.apache.logging.log4j.core.config.LoggerConfig.processLogEvent(LoggerConfig.java:434)
at org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:417)
at org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:403)
at org.apache.logging.log4j.core.config.AwaitCompletionReliabilityStrategy.log(AwaitCompletionReliabilityStrategy.java:63)
at org.apache.logging.log4j.core.Logger.logMessage(Logger.java:146)
at org.ops4j.pax.logging.log4j2.internal.PaxLoggerImpl.doLog0(PaxLoggerImpl.java:151)
at org.ops4j.pax.logging.log4j2.internal.PaxLoggerImpl.doLog(PaxLoggerImpl.java:144)
at org.ops4j.pax.logging.log4j2.internal.PaxLoggerImpl.inform(PaxLoggerImpl.java:176)
at org.ops4j.pax.logging.internal.TrackingLogger.inform(TrackingLogger.java:86)
at org.ops4j.pax.logging.slf4j.Slf4jLogger.info(Slf4jLogger.java:534)
...
Slice from the jstack - blocked thread:
"nioEventLoopGroupCloseable-3-14" #578 prio=10 os_prio=0 tid=0x00007f6bd21c7800 nid=0x56d waiting for monitor entry [0x00007f6be14c3000]
java.lang.Thread.State: BLOCKED (on object monitor)
at org.apache.karaf.log.core.internal.LogServiceImpl.doAppend(LogServiceImpl.java:168)
- waiting to lock <0x00000004c1148e90> (a org.apache.karaf.log.core.internal.LogServiceImpl)
at org.ops4j.pax.logging.log4j2.internal.PaxAppenderProxy.doAppend(PaxAppenderProxy.java:65)
at org.ops4j.pax.logging.log4j2.appender.PaxOsgiAppender.append(PaxOsgiAppender.java:82)
at org.apache.logging.log4j.core.config.AppenderControl.tryCallAppender(AppenderControl.java:156)
at org.apache.logging.log4j.core.config.AppenderControl.callAppender0(AppenderControl.java:129)
at org.apache.logging.log4j.core.config.AppenderControl.callAppenderPreventRecursion(AppenderControl.java:120)
at org.apache.logging.log4j.core.config.AppenderControl.callAppender(AppenderControl.java:84)
at org.apache.logging.log4j.core.config.LoggerConfig.callAppenders(LoggerConfig.java:448)
at org.apache.logging.log4j.core.config.LoggerConfig.processLogEvent(LoggerConfig.java:433)
at org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:417)
at org.apache.logging.log4j.core.config.LoggerConfig.logParent(LoggerConfig.java:439)
at org.apache.logging.log4j.core.config.LoggerConfig.processLogEvent(LoggerConfig.java:434)
at org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:417)
at org.apache.logging.log4j.core.config.LoggerConfig.log(LoggerConfig.java:403)
at org.apache.logging.log4j.core.config.AwaitCompletionReliabilityStrategy.log(AwaitCompletionReliabilityStrategy.java:63)
at org.apache.logging.log4j.core.Logger.logMessage(Logger.java:146)
at org.ops4j.pax.logging.log4j2.internal.PaxLoggerImpl.doLog0(PaxLoggerImpl.java:151)
at org.ops4j.pax.logging.log4j2.internal.PaxLoggerImpl.doLog(PaxLoggerImpl.java:144)
at org.ops4j.pax.logging.log4j2.internal.PaxLoggerImpl.inform(PaxLoggerImpl.java:176)
at org.ops4j.pax.logging.internal.TrackingLogger.inform(TrackingLogger.java:86)
at org.ops4j.pax.logging.slf4j.Slf4jLogger.info(Slf4jLogger.java:534)
...
Environment information:
karaf version - 4.1.5
uname -a
Linux localhost.localdomain 5.0.5-200.fc29.x86_64 #1 SMP Wed Mar 27 20:58:04 UTC 2019 x86_64 x86_64 x86_64 GNU/Linux
java -version
openjdk version "1.8.0_201"
OpenJDK Runtime Environment (build 1.8.0_201-b09)
OpenJDK 64-Bit Server VM (build 25.201-b09, mixed mode)
Is there also another way how to optimize logging under high load beside lowering of logging levels or thresholds?
Thank you for your help.
Best regards,
Jaroslav Tóth
Software Engineer
Frinx s.r.o.
Mlynské Nivy 48 / 821 09 Bratislava / Slovakia
02/209 101 41 / jtoth@frinx.io / www.frinx.io<http://www.frinx.io/>
[cid:image002.png@01D4F05F.C9106040]