Indeed, "busy-wait" was the first thing that came to my mind as well...
I did some more investigation on this issue. Below is the jvm-top output for the test while initially running without extra latency:
JvmTop 0.8.0 alpha - 14:39:29, amd64, 16 cpus, Linux 3.10.0-86, load avg 0.46
PID 10036: /l/disk0/apdsno12/msgs/wildfly-15.0.0.Final/jboss-modules.jar
ARGS: -mp /l/disk0/apdsno12/msgs/wildfly-15.0.0.Final/modules org.jboss.a[...]
VMARGS: -D[Server:spotdsno12] -D[pcid:316534345] -Xms2048m -Xmx8192m -XX:[...]
VM: Oracle Corporation Java HotSpot(TM) 64-Bit Server VM 1.8.0_144
UP: 3:26m #THR: 111 #THRPEAK: 187 #THRCREATED: 415 USER: apdsno12
GC-Time: 0: 0m #GC-Runs: 186 #TotalLoadedClasses: 33674
CPU: 5.63% GC: 0.00% HEAP:1633m /8192m NONHEAP: 294m /1520m
TID NAME STATE CPU TOTALCPU BLOCKEDBY
403 default task-61 TIMED_WAITING 10.02% 0.64%
416 default task-64 TIMED_WAITING 8.11% 0.07%
422 default task-68 TIMED_WAITING 7.60% 0.07%
414 default task-63 TIMED_WAITING 6.84% 0.07%
424 default task-69 TIMED_WAITING 6.02% 0.07%
428 default task-70 TIMED_WAITING 6.00% 0.07%
423 default task-67 TIMED_WAITING 5.82% 0.07%
421 default task-66 TIMED_WAITING 5.06% 0.06%
415 default task-65 TIMED_WAITING 4.27% 0.07%
427 pool-24-thread-77 TIMED_WAITING 4.22% 0.02%
Note: Only top 10 threads (according cpu load) are shown!
<<<
And after introducing 5ms of latency at the database server network interface using "tc", I immediately see this:
>>>
JvmTop 0.8.0 alpha - 12:00:49, amd64, 16 cpus, Linux 3.10.0-86, load avg 0.02
PID 10036: /l/disk0/apdsno12/msgs/wildfly-15.0.0.Final/jboss-modules.jar
ARGS: -mp /l/disk0/apdsno12/msgs/wildfly-15.0.0.Final/modules org.jboss.a[...]
VMARGS: -D[Server:spotdsno12] -D[pcid:316534345] -Xms2048m -Xmx8192m -XX:[...]
VM: Oracle Corporation Java HotSpot(TM) 64-Bit Server VM 1.8.0_144
UP: 0:47m #THR: 111 #THRPEAK: 187 #THRCREATED: 395 USER: apdsno12
GC-Time: 0: 0m #GC-Runs: 174 #TotalLoadedClasses: 33673
CPU: 21.85% GC: 0.00% HEAP:2933m /8192m NONHEAP: 294m /1520m
TID NAME STATE CPU TOTALCPU BLOCKEDBY
351 pool-24-thread-44 RUNNABLE 40.37% 2.13%
318 pool-24-thread-20 TIMED_WAITING 40.35% 2.20%
406 pool-24-thread-65 TIMED_WAITING 37.40% 1.30%
388 pool-24-thread-47 TIMED_WAITING 36.59% 2.06%
409 pool-24-thread-68 RUNNABLE 33.47% 1.29%
329 pool-24-thread-31 TIMED_WAITING 31.20% 2.11%
349 pool-24-thread-36 RUNNABLE 13.69% 2.23%
396 pool-24-thread-60 RUNNABLE 13.64% 2.21%
410 pool-24-thread-69 RUNNABLE 10.64% 1.28%
371 default task-38 TIMED_WAITING 10.04% 1.43%
Note: Only top 10 threads (according cpu load) are shown!
<<<
The thread dump from jstack at that moment shows something like this for a "pool-24-thread" that is in RUNNABLE state:
>>>
"pool-24-thread-24" #358 prio=5 os_prio=0 tid=0x000000000f20c000 nid=0x2a4c runnable [0x00007f88230d7000]
java.lang.Thread.State: RUNNABLE
at java.lang.Thread.yield(Native Method)
at com.conversantmedia.util.concurrent.Condition.progressiveYield(Condition.java:68)
at com.conversantmedia.util.concurrent.AbstractWaitingCondition.await(AbstractWaitingCondition.java:144)
at com.conversantmedia.util.concurrent.PushPullBlockingQueue.take(PushPullBlockingQueue.java:193)
at org.geotools.renderer.lite.StreamingRenderer$RenderingBlockingQueue.take(StreamingRenderer.java:3823)
...
<<<
And the code for Condition.progressiveYield() is:
>>>
static int progressiveYield(final int n) {
if(n > 500) {
if(n<1000) {
// "randomly" yield 1:8
if((n & 0x7) == 0) {
LockSupport.parkNanos(PARK_TIMEOUT);
} else {
onSpinWait();
}
} else if(n<MAX_PROG_YIELD) {
// "randomly" yield 1:4
if((n & 0x3) == 0) {
Thread.yield();
} else {
onSpinWait();
}
} else {
Thread.yield();
return n;
}
} else {
onSpinWait();
}
return n+1;
}
static void onSpinWait() {
// Java 9 hint for spin waiting PAUSE instruction
// Thread.onSpinWait();
}
<<<
So, it seems like the Conversant Disruptor (version 1.2.13) is doing some "busy-wait" here. Please correct me if this is not the case.
Regards,
Joao