Logback | Synchronous/ Asynchronous Logging | Thread

As Documentation of logback says that most of the appenders are synchronous in nature, but if we wrap the appender inside the ASYNC appender then threads will push the data in BlockingQueue, and if there is let's say X-Logback thread will fetch the data from BlockingQueue and append it. This is what I got a basic understanding of.

Tried to test this using the Jstack Thread dump. But return empty-handed, with no clue of logback thread.

For reference, Please check below logback.xml and Thread dump for scenarios.

FileAppender with ASYNC.

<?xml version="1.0" encoding="UTF-8"?>
<configuration scan="true" scanPeriod="30 seconds" debug = "true">

    <appender name="FILE" >
        <file>myapp.log</file>
        <encoder>
            <pattern>%logger{35} - %msg%n</pattern>
        </encoder>
    </appender>

    <appender name="ASYNC" >
        <appender-ref ref="FILE" />
    </appender>

    <root level="DEBUG">
        <appender-ref ref="ASYNC" />
    </root>
</configuration>

Thread dump

2022-05-01 20:24:28
Full thread dump OpenJDK 64-Bit Server VM (11.0.11 9-b1504.13 mixed mode):

Threads class SMR info:
_java_thread_list=0x0000600000a6bc40, length=11, elements={
0x000000013101c800, 0x000000013101a800, 0x000000013300a800, 0x0000000132077000,
0x0000000131874800, 0x0000000131852800, 0x0000000131853000, 0x0000000131025000,
0x00000001320e2800, 0x0000000125043800, 0x000000013218d000
}

"Reference Handler" #2 daemon prio=10 os_prio=31 cpu=0.51ms elapsed=386.08s tid=0x000000013101c800 nid=0x4303 waiting on condition  [0x000000016ebbe000]
   java.lang.Thread.State: RUNNABLE
    at java.lang.ref.Reference.waitForReferencePendingList([email protected]/Native Method)
    at java.lang.ref.Reference.processPendingReferences([email protected]/Reference.java:241)
    at java.lang.ref.Reference$ReferenceHandler.run([email protected]/Reference.java:213)

   Locked ownable synchronizers:
    - None

"Finalizer" #3 daemon prio=8 os_prio=31 cpu=0.41ms elapsed=386.08s tid=0x000000013101a800 nid=0x3303 in Object.wait()  [0x000000016edca000]
   java.lang.Thread.State: WAITING (on object monitor)
    at java.lang.Object.wait([email protected]/Native Method)
    - waiting on <0x000000079af0d550> (a java.lang.ref.ReferenceQueue$Lock)
    at java.lang.ref.ReferenceQueue.remove([email protected]/ReferenceQueue.java:155)
    - waiting to re-lock in wait() <0x000000079af0d550> (a java.lang.ref.ReferenceQueue$Lock)
    at java.lang.ref.ReferenceQueue.remove([email protected]/ReferenceQueue.java:176)
    at java.lang.ref.Finalizer$FinalizerThread.run([email protected]/Finalizer.java:170)

   Locked ownable synchronizers:
    - None

"Signal Dispatcher" #4 daemon prio=9 os_prio=31 cpu=1.67ms elapsed=386.07s tid=0x000000013300a800 nid=0x3d03 runnable  [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

   Locked ownable synchronizers:
    - None

"Service Thread" #5 daemon prio=9 os_prio=31 cpu=0.02ms elapsed=386.07s tid=0x0000000132077000 nid=0x5603 runnable  [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

   Locked ownable synchronizers:
    - None

"C2 CompilerThread0" #6 daemon prio=9 os_prio=31 cpu=337.48ms elapsed=386.07s tid=0x0000000131874800 nid=0x5703 waiting on condition  [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE
   No compile task

   Locked ownable synchronizers:
    - None

"C1 CompilerThread0" #9 daemon prio=9 os_prio=31 cpu=266.34ms elapsed=386.07s tid=0x0000000131852800 nid=0xa603 runnable  [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE
   No compile task

   Locked ownable synchronizers:
    - None

"Sweeper thread" #10 daemon prio=9 os_prio=31 cpu=0.05ms elapsed=386.07s tid=0x0000000131853000 nid=0x5b03 runnable  [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

   Locked ownable synchronizers:
    - None

"Common-Cleaner" #11 daemon prio=8 os_prio=31 cpu=2.86ms elapsed=386.05s tid=0x0000000131025000 nid=0xa303 in Object.wait()  [0x000000016fd36000]
   java.lang.Thread.State: TIMED_WAITING (on object monitor)
    at java.lang.Object.wait([email protected]/Native Method)
    - waiting on <0x000000079af0dfe8> (a java.lang.ref.ReferenceQueue$Lock)
    at java.lang.ref.ReferenceQueue.remove([email protected]/ReferenceQueue.java:155)
    - waiting to re-lock in wait() <0x000000079af0dfe8> (a java.lang.ref.ReferenceQueue$Lock)
    at jdk.internal.ref.CleanerImpl.run([email protected]/CleanerImpl.java:148)
    at java.lang.Thread.run([email protected]/Thread.java:829)
    at jdk.internal.misc.InnocuousThread.run([email protected]/InnocuousThread.java:134)

   Locked ownable synchronizers:
    - None

"JPS event loop" #12 prio=5 os_prio=31 cpu=33.87ms elapsed=385.71s tid=0x00000001320e2800 nid=0xa003 runnable  [0x000000016ff42000]
   java.lang.Thread.State: RUNNABLE
    at sun.nio.ch.KQueue.poll([email protected]/Native Method)
    at sun.nio.ch.KQueueSelectorImpl.doSelect([email protected]/KQueueSelectorImpl.java:122)
    at sun.nio.ch.SelectorImpl.lockAndDoSelect([email protected]/SelectorImpl.java:124)
    - locked <0x000000079af0e4c8> (a sun.nio.ch.Util$2)
    - locked <0x000000079af0e468> (a sun.nio.ch.KQueueSelectorImpl)
    at sun.nio.ch.SelectorImpl.select([email protected]/SelectorImpl.java:141)
    at io.netty.channel.nio.NioEventLoop.select(NioEventLoop.java:810)
    at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:457)
    at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:989)
    at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74)
    at java.lang.Thread.run([email protected]/Thread.java:829)

   Locked ownable synchronizers:
    - None

"DestroyJavaVM" #14 prio=5 os_prio=31 cpu=583.44ms elapsed=385.33s tid=0x0000000125043800 nid=0x1903 waiting on condition  [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

   Locked ownable synchronizers:
    - None

"Attach Listener" #16 daemon prio=9 os_prio=31 cpu=2.01ms elapsed=295.61s tid=0x000000013218d000 nid=0x9507 waiting on condition  [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

   Locked ownable synchronizers:
    - None

"VM Thread" os_prio=31 cpu=39.84ms elapsed=386.09s tid=0x0000000131016000 nid=0x3003 runnable  

"GC Thread#0" os_prio=31 cpu=6.72ms elapsed=386.10s tid=0x0000000133014800 nid=0x2d03 runnable  

"GC Thread#1" os_prio=31 cpu=6.27ms elapsed=385.62s tid=0x000000013188d800 nid=0x9e03 runnable  

"GC Thread#2" os_prio=31 cpu=5.06ms elapsed=385.62s tid=0x000000013187f800 nid=0x9c03 runnable  

"GC Thread#3" os_prio=31 cpu=5.78ms elapsed=385.62s tid=0x0000000131a79800 nid=0x9a03 runnable  

"G1 Main Marker" os_prio=31 cpu=0.25ms elapsed=386.10s tid=0x0000000132018000 nid=0x5003 runnable  

"G1 Conc#0" os_prio=31 cpu=2.57ms elapsed=386.10s tid=0x0000000133015000 nid=0x4c03 runnable  

"G1 Conc#1" os_prio=31 cpu=2.47ms elapsed=385.47s tid=0x0000000131ae8800 nid=0x9403 runnable  

"G1 Refine#0" os_prio=31 cpu=1.64ms elapsed=386.10s tid=0x0000000131819800 nid=0x4a03 runnable  

"G1 Refine#1" os_prio=31 cpu=0.53ms elapsed=385.62s tid=0x000000013311f800 nid=0x9803 runnable  

"G1 Young RemSet Sampling" os_prio=31 cpu=50.84ms elapsed=386.10s tid=0x000000013181a000 nid=0x4903 runnable  
"VM Periodic Task Thread" os_prio=31 cpu=198.90ms elapsed=386.05s tid=0x000000012580a800 nid=0x5c03 waiting on condition  

JNI global refs: 14, weak refs: 0

For ConsoleAppender also which is without ASYNC.

2022-04-28 11:59:20
Full thread dump OpenJDK 64-Bit Server VM (11.0.11 9-b1504.13 mixed mode):

Threads class SMR info:
_java_thread_list=0x00006000018d3740, length=11, elements={
0x000000014b08c800, 0x000000014b089000, 0x000000014904b800, 0x000000014b099000,
0x000000014b09e000, 0x000000014b09f000, 0x0000000149031800, 0x0000000149828000,
0x00000001498b8000, 0x0000000149172800, 0x000000014b1ba000
}

"Reference Handler" #2 daemon prio=10 os_prio=31 cpu=0.55ms elapsed=282.20s tid=0x000000014b08c800 nid=0x4b03 waiting on condition  [0x00000001702d2000]
   java.lang.Thread.State: RUNNABLE
    at java.lang.ref.Reference.waitForReferencePendingList([email protected]/Native Method)
    at java.lang.ref.Reference.processPendingReferences([email protected]/Reference.java:241)
    at java.lang.ref.Reference$ReferenceHandler.run([email protected]/Reference.java:213)

"Finalizer" #3 daemon prio=8 os_prio=31 cpu=0.33ms elapsed=282.20s tid=0x000000014b089000 nid=0x4803 in Object.wait()  [0x00000001704de000]
   java.lang.Thread.State: WAITING (on object monitor)
    at java.lang.Object.wait([email protected]/Native Method)
    - waiting on <0x0000000794cedb80> (a java.lang.ref.ReferenceQueue$Lock)
    at java.lang.ref.ReferenceQueue.remove([email protected]/ReferenceQueue.java:155)
    - waiting to re-lock in wait() <0x0000000794cedb80> (a java.lang.ref.ReferenceQueue$Lock)
    at java.lang.ref.ReferenceQueue.remove([email protected]/ReferenceQueue.java:176)
    at java.lang.ref.Finalizer$FinalizerThread.run([email protected]/Finalizer.java:170)

"Signal Dispatcher" #4 daemon prio=9 os_prio=31 cpu=0.96ms elapsed=282.18s tid=0x000000014904b800 nid=0x4203 runnable  [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"Service Thread" #5 daemon prio=9 os_prio=31 cpu=0.01ms elapsed=282.18s tid=0x000000014b099000 nid=0x5603 runnable  [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"C2 CompilerThread0" #6 daemon prio=9 os_prio=31 cpu=429.52ms elapsed=282.18s tid=0x000000014b09e000 nid=0x5903 waiting on condition  [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE
   No compile task

"C1 CompilerThread0" #9 daemon prio=9 os_prio=31 cpu=348.22ms elapsed=282.18s tid=0x000000014b09f000 nid=0x5b03 waiting on condition  [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE
   No compile task

"Sweeper thread" #10 daemon prio=9 os_prio=31 cpu=0.04ms elapsed=282.18s tid=0x0000000149031800 nid=0xa703 runnable  [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"Common-Cleaner" #11 daemon prio=8 os_prio=31 cpu=3.60ms elapsed=282.15s tid=0x0000000149828000 nid=0xa503 in Object.wait()  [0x000000017144a000]
   java.lang.Thread.State: TIMED_WAITING (on object monitor)
    at java.lang.Object.wait([email protected]/Native Method)
    - waiting on <0x0000000794cee618> (a java.lang.ref.ReferenceQueue$Lock)
    at java.lang.ref.ReferenceQueue.remove([email protected]/ReferenceQueue.java:155)
    - waiting to re-lock in wait() <0x0000000794cee618> (a java.lang.ref.ReferenceQueue$Lock)
    at jdk.internal.ref.CleanerImpl.run([email protected]/CleanerImpl.java:148)
    at java.lang.Thread.run([email protected]/Thread.java:829)
    at jdk.internal.misc.InnocuousThread.run([email protected]/InnocuousThread.java:134)

"JPS event loop" #12 prio=5 os_prio=31 cpu=40.32ms elapsed=281.67s tid=0x00000001498b8000 nid=0xa303 runnable  [0x0000000171656000]
   java.lang.Thread.State: RUNNABLE
    at sun.nio.ch.KQueue.poll([email protected]/Native Method)
    at sun.nio.ch.KQueueSelectorImpl.doSelect([email protected]/KQueueSelectorImpl.java:122)
    at sun.nio.ch.SelectorImpl.lockAndDoSelect([email protected]/SelectorImpl.java:124)
    - locked <0x0000000794cee9e0> (a sun.nio.ch.Util$2)
    - locked <0x0000000794cee980> (a sun.nio.ch.KQueueSelectorImpl)
    at sun.nio.ch.SelectorImpl.select([email protected]/SelectorImpl.java:141)
    at io.netty.channel.nio.NioEventLoop.select(NioEventLoop.java:810)
    at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:457)
    at io.netty.util.concurrent.SingleThreadEventExecutor$4.run(SingleThreadEventExecutor.java:989)
    at io.netty.util.internal.ThreadExecutorMap$2.run(ThreadExecutorMap.java:74)
    at java.lang.Thread.run([email protected]/Thread.java:829)

"DestroyJavaVM" #14 prio=5 os_prio=31 cpu=823.18ms elapsed=280.75s tid=0x0000000149172800 nid=0x2703 waiting on condition  [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"Attach Listener" #16 daemon prio=9 os_prio=31 cpu=1.41ms elapsed=7.34s tid=0x000000014b1ba000 nid=0x6407 waiting on condition  [0x0000000000000000]
   java.lang.Thread.State: RUNNABLE

"VM Thread" os_prio=31 cpu=21.10ms elapsed=282.21s tid=0x000000014a00d000 nid=0x3803 runnable  

"GC Thread#0" os_prio=31 cpu=7.63ms elapsed=282.23s tid=0x000000014b010000 nid=0x2e03 runnable  

"GC Thread#1" os_prio=31 cpu=10.22ms elapsed=281.44s tid=0x00000001499e5000 nid=0xa203 runnable  

"GC Thread#2" os_prio=31 cpu=8.88ms elapsed=281.44s tid=0x000000014a126000 nid=0xa003 runnable  

"GC Thread#3" os_prio=31 cpu=9.58ms elapsed=281.44s tid=0x000000014b16e800 nid=0x6303 runnable  

"G1 Main Marker" os_prio=31 cpu=0.39ms elapsed=282.23s tid=0x000000014b01d000 nid=0x2f03 runnable  

"G1 Conc#0" os_prio=31 cpu=3.13ms elapsed=282.23s tid=0x000000014900c000 nid=0x3203 runnable  

"G1 Conc#1" os_prio=31 cpu=3.24ms elapsed=280.98s tid=0x0000000149a00800 nid=0x6503 runnable  

"G1 Refine#0" os_prio=31 cpu=1.22ms elapsed=282.23s tid=0x0000000149022000 nid=0x3403 runnable  

"G1 Young RemSet Sampling" os_prio=31 cpu=33.96ms elapsed=282.23s tid=0x0000000149022800 nid=0x4f03 runnable  
"VM Periodic Task Thread" os_prio=31 cpu=119.50ms elapsed=282.16s tid=0x000000012b008800 nid=0xa603 waiting on condition  

JNI global refs: 14, weak refs: 0

Could anyone please help me that why Jstack is not showing any LOGBACK-THREAD waiting in parking state.

CodePudding user response：

After doing some more research, I found that I was picking the wrong PID for my application. Before I was using ps -ef and then searching by application name, which is sort of correct but I was not known that there were two instances running, and I am picking the wrong one.

Thanks to baeldung, I used Jps command and then picked the PID of my application and simply

jstack PID > app.txt

and there we go.