Tuning ShenandoahGC with 420 GB heaps

[Jeroen Borgers]

Hi,

Another question. We set max pacing delay to 50 ms. However, the histogram
shows differently (weekend log file):

Actual pacing delays histogram:

      From -         To         Count         Sum
      1 ms -       2 ms:      1391036      695518 ms
      2 ms -       4 ms:      1005742     1005742 ms
      4 ms -       8 ms:       821336     1642672 ms
      8 ms -      16 ms:       702322     2809288 ms
     16 ms -      32 ms:       617988     4943904 ms
     32 ms -      64 ms:     11181201   178899216 ms
     64 ms -     128 ms:         3687      117984 ms
    128 ms -     256 ms:           12         768 ms
    256 ms -     512 ms:            0           0 ms
    512 ms -    1024 ms:            0           0 ms
   1024 ms -    2048 ms:           24       12288 ms
   2048 ms -    4096 ms:           18       18432 ms
   4096 ms -    8192 ms:          195      399360 ms
   8192 ms -   16384 ms:          478     1957888 ms
                  Total:     15724039   192503060 ms

There are many > 64 ms., while we specify 50 ms as max? I don't understand.
And the total time individual threads are stopped is huge: 192_503 s. Much
more than the STW time:

Total Pauses (G)            =  4133.93 s (a =    95487 us) (n = 43293)
(lvls, us =      525,     2969,    10938,    18750, 34999971)

If I multiply the latter by 48 (assuming every hardware thread is utilized
by 1 app thread; all are affected during STW) I get: 198_384 s. Similar to
the total pacing time.

Does this mean that our app is stopped by pacing in the same order as by
STW pauses?
-Jeroen

Op di 5 mrt. 2019 om 13:24 schreef Jeroen Borgers <jborgers at jpinpoint.com>:

>
> Op di 5 mrt. 2019 om 12:20 schreef Aleksey Shipilev <shade at redhat.com>:
>
>> On 3/5/19 10:51 AM, Jeroen Borgers wrote:
>> > Thanks for your remarks. In addition to Edwins findings:
>> > 1.1 AlwaysPreTouch seems to be on while reported as off, as shown in
>> 'ps' and in logfile it says
>> > (line 12:)
>>
>> Right. Sorry, my bad, that's Shenandoah reverting dropping AlwaysPreTouch
>> and enabling
>> ShenandoahAlwaysPretouch specifically. It needs to be that way to avoid
>> hitting serial pretouch code
>> that would wreck up NUMA interleaving.
>>
>
> Ok, good to know.
>
>
>>
>> > 3. Right, sudden high allocation rates are a problem. Getting more
>> memory will take time. We might
>> > be able to throttle the load somewhat.
>>
>> Yes, either throttle the load (for example, beef up pacing threshold), or
>> maybe beef up the
>> ConcGCThreads?
>>
>> We hope we can throttle the system that puts sudden load on our
> application. Beefing up the ConcGCThreads might also be an option, although
> we are almost at 100% CPU with high load. Application can progress slower
> and lose max 16 ms on 30 ms by getting less CPU time, so we might try e.g.
> 24 or 32.
>
>
>> > Like my colleague found, (transparent) huge pages do not seem to be
>> utilized fully. I see in the log
>> > file:
>> > Memory: 4k page, physical 528157524k(460445396k free), swap
>> 2097148k(1463356k free)
>> > and on line 12:
>> > Parallel pretouch 13440 regions with 2097152 byte pages
>> > So it seems to use both 4kB and 2MB pages. The latter area is only 26
>> GB.
>> > We don't understand this nor how to solve it. Suggestions very welcome.
>>
>> This is Shenandoah bug! Argh. Tracked here:
>>   https://bugs.openjdk.java.net/browse/JDK-8220153
>>
>> Ah, good finding! And I see your patch solves it, right? When will this
> be available?
>
>
>> -Aleksey
>>
>>
> -Jeroen
>