karaf-issues mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From Jaroslav Tóth <jt...@frinx.io>
Subject Copying of PaxLoggingEvent
Date Thu, 11 Apr 2019 10:12:11 GMT
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]


Mime
  • Unnamed multipart/related (inline, None, 0 bytes)
View raw message