Shenandoah experimental flags

[Cristian Velazquez]

Thanks for the prompt response. I'm using the docker jdk8 image
(shipilev/openjdk-shenandoah:8). I'll share more details and the gc logs:

The first test was (gc-stab1024.log):
java -Xms2G -Xmx2G -XX:+AlwaysPreTouch \
  -XX:+UseShenandoahGC -XX:+PrintHeapAtGC -XX:+PrintGCDetails \
  -XX:+PrintGCDateStamps -XX:+UnlockExperimentalVMOptions \
  -Xloggc:./gc-httpbin.log \
  -XX:ShenandoahMinFreeThreshold=25 \
  -XX:ShenandoahRefProcFrequency=0 \
  -XX:ShenandoahSATBBufferSize=1024 \
  -jar
./java-httpbin/target/httpbin-1.3.1-SNAPSHOT-jar-with-dependencies.jar

The second (gc-stab1024-1ms.log):
java -Xms2G -Xmx2G -XX:+AlwaysPreTouch \
  -XX:+UseShenandoahGC -XX:+PrintHeapAtGC -XX:+PrintGCDetails \
  -XX:+PrintGCDateStamps -XX:+UnlockExperimentalVMOptions \
  -Xloggc:./gc-httpbin.log \
  -XX:ShenandoahMinFreeThreshold=25 \
  -XX:ShenandoahRefProcFrequency=0 \
  -XX:ShenandoahSATBBufferSize=1024 \
  -XX:ShenandoahSATBBufferFlushInterval=1 \
  -jar
./java-httpbin/target/httpbin-1.3.1-SNAPSHOT-jar-with-dependencies.jar

The one that has the impact I would expect (gc-stab32.log):
java -Xms2G -Xmx2G -XX:+AlwaysPreTouch \
  -XX:+UseShenandoahGC -XX:+PrintHeapAtGC -XX:+PrintGCDetails \
  -XX:+PrintGCDateStamps -XX:+UnlockExperimentalVMOptions \
  -Xloggc:./gc-httpbin.log \
  -XX:ShenandoahMinFreeThreshold=25 \
  -XX:ShenandoahRefProcFrequency=0 \
  -XX:ShenandoahSATBBufferSize=32 \
  -jar
./java-httpbin/target/httpbin-1.3.1-SNAPSHOT-jar-with-dependencies.jar

Thanks, regards
    Cristian V


On Thu, Apr 30, 2020 at 2:05 AM Roman Kennke <rkennke at redhat.com> wrote:

> I kinda suspect it's running into degen GC, and lowering buffer size
> slows it down enough to avoid this. Need to see GC logs to confirm it.
>
> Roman
>
> > Hi Cristian,
> >
> > On 4/29/20 12:42 AM, Cristian Velazquez wrote:
> >> Hi everyone:
> >>
> >> I'm testing out shenandoah on https://github.com/gaul/java-httpbin. I'm
> >> using wrk to send a huge amount of traffic: wrk -d 300 -t 1 -c 32
> >> http://127.0.0.1:8080/gzip. I'm using the default flags with 2G heap.
> >
> > Does not seem to reproduce on current head. What build/version are you
> using?
> >
> >> I'm getting pause times from 100-300ms due to the time spent on finish
> queues.
> >
> > Please show the part of GC log where you see this?
> >
> >> I tried the following (I used as reference this
> >>
> https://mail.openjdk.java.net/pipermail/shenandoah-dev/2018-July/006630.html
> >> ):
> >> - Reduce ShenandoahSATBBufferFlushInterval to 1 ms. This didn't make any
> >> difference.
> >> - Reduce ShenandoahSATBBufferSize to 32. This fixed the issue and now
> see
> >> better pause times.
> >
> > Really! That is odd. The periodic SATB buffer is supposed to flush
> anything leftover before you hit
> > this problem.
> >
> >> I have run it for quite a while and I haven't seen any issue with this
> >> configuration. Although, I would like to know what is the
> recommendation in
> >> this scenario? is it safe to decrease the buffer size? what is the
> impact
> >> of doing so?
> >
> > Mostly throughput performance. SATB buffer is the thing that accumulates
> the old field values before
> > each store to maintain marking invariants. Without this buffer, every
> reference store would need to
> > call into VM, which would be costly. So the buffer is deliberately quite
> large to keep application
> > from calling into VM too often, and do that only for buffer flushes.
> >
> > But, that matters only when marking is running. In my quick tests, your
> workload seems to be almost
> > fully young:
> >
> > [93.298s][info][gc] Trigger: Free (204M) is below minimum threshold
> (204M)
> > [93.298s][info][gc] GC(12) Concurrent reset 0.218ms
> > [93.299s][info][gc] GC(12) Pause Init Mark (unload classes) 0.191ms
> > [93.301s][info][gc] GC(12) Concurrent marking (unload classes) 1.918ms
> > [93.301s][info][gc] GC(12) Pause Final Mark (unload classes) 0.221ms
> > [93.301s][info][gc] GC(12) Concurrent weak roots 0.362ms
> > [93.302s][info][gc] GC(12) Concurrent cleanup 1766M->102M(2021M) 0.269ms
> > [93.303s][info][gc] GC(12) Concurrent class unloading 1.403ms
> >
> > ...so marking is way too short for you to notice this.
> >
> > What I suspect is happening in your case is that marking is *so short*
> that buffer flush never
> > happens until Final Mark, where we discover some work to do. But it is
> puzzling why that work is
> >> 100ms, when the workload does not have a lot of live data.
> >
> > Need more info...
> >
>
>

-- 
Atentamente.
       Cristian D. Velázquez Ramírez.