RFR: 8223961: ZGC: Unexpected behaviour was observed caused by the incorrect update of _nticks in ZMetronome::wait_for_tick()

[Per Liden]

On 05/16/2019 08:25 AM, Per Liden wrote:
> Hi,
> 
> There is code in ZStat that assumes ZMetronome::ntick() never skips over 
> ticks. That would need to be addressed if we do something like this. 
> Otherwise we risk not getting statistics print outs just because the 
> metronome overslept. I'll take a look at it.

I was thinking something like this:

diff --git a/src/hotspot/share/gc/z/zMetronome.cpp 
b/src/hotspot/share/gc/z/zMetronome.cpp
--- a/src/hotspot/share/gc/z/zMetronome.cpp
+++ b/src/hotspot/share/gc/z/zMetronome.cpp
@@ -45,7 +45,9 @@
      _start_ms = TimeHelper::counter_to_millis(now.value());
    }

-  for (;;) {
+  MonitorLocker ml(&_monitor, Monitor::_no_safepoint_check_flag);
+
+  while (!_stopped) {
      // We might wake up spuriously from wait, so always recalculate
      // the timeout after a wakeup to see if we need to wait again.
      const Ticks now = Ticks::now();
@@ -53,15 +55,24 @@
      const uint64_t next_ms = _start_ms + (_interval_ms * _nticks);
      const int64_t timeout_ms = next_ms - now_ms;

-    MonitorLocker ml(&_monitor, Monitor::_no_safepoint_check_flag);
-    if (!_stopped && timeout_ms > 0) {
+    if (timeout_ms > 0) {
        // Wait
        ml.wait(timeout_ms);
      } else {
        // Tick
-      return !_stopped;
+      if (timeout_ms < -_interval_ms) {
+        // Missed one or more ticks. Bump _nticks accordingly to
+        // avoid firing a string of immediate ticks to make up
+        // for the ones we missed.
+        _nticks += -timeout_ms / _interval_ms;
+      }
+
+      return true;
      }
    }
+
+  // Stopped
+  return false;
  }

  void ZMetronome::stop() {
diff --git a/src/hotspot/share/gc/z/zMetronome.hpp 
b/src/hotspot/share/gc/z/zMetronome.hpp
--- a/src/hotspot/share/gc/z/zMetronome.hpp
+++ b/src/hotspot/share/gc/z/zMetronome.hpp
@@ -29,11 +29,11 @@

  class ZMetronome : public StackObj {
  private:
-  Monitor        _monitor;
-  const uint64_t _interval_ms;
-  uint64_t       _start_ms;
-  uint64_t       _nticks;
-  bool           _stopped;
+  Monitor       _monitor;
+  const int64_t _interval_ms;
+  uint64_t      _start_ms;
+  uint64_t      _nticks;
+  bool          _stopped;

  public:
    ZMetronome(uint64_t hz);
diff --git a/src/hotspot/share/gc/z/zStat.cpp 
b/src/hotspot/share/gc/z/zStat.cpp
--- a/src/hotspot/share/gc/z/zStat.cpp
+++ b/src/hotspot/share/gc/z/zStat.cpp
@@ -850,7 +850,16 @@
  }

  bool ZStat::should_print(LogTargetHandle log) const {
-  return log.is_enabled() && (_metronome.nticks() % ZStatisticsInterval 
== 0);
+  static uint64_t print_at_nticks = ZStatisticsInterval;
+  uint64_t nticks = _metronome.nticks();
+
+  if (nticks < print_at_nticks) {
+    return false;
+  }
+
+  print_at_nticks = ((nticks / ZStatisticsInterval) * 
ZStatisticsInterval) + ZStatisticsInterval;
+
+  return log.is_enabled();
  }

  void ZStat::print(LogTargetHandle log, const ZStatSamplerHistory* 
history) const {


cheers,
Per

> 
> cheers,
> Per
> 
> On 05/15/2019 04:33 PM, Jie Fu wrote:
>> Hi all,
>>
>> JBS: https://bugs.openjdk.java.net/browse/JDK-8223961
>>
>> Please review the following patch which fixes the update of "_nticks" 
>> in ZMetronome::wait_for_tick()
>> -----------------------------------
>> diff -r b0b20413d853 src/hotspot/share/gc/z/zMetronome.cpp
>> --- a/src/hotspot/share/gc/z/zMetronome.cpp     Wed May 15 11:53:47 
>> 2019 +0200
>> +++ b/src/hotspot/share/gc/z/zMetronome.cpp     Wed May 15 20:15:39 
>> 2019 +0800
>> @@ -57,6 +57,8 @@
>>       if (!_stopped && timeout_ms > 0) {
>>         // Wait
>>         ml.wait(timeout_ms);
>> +    } else if (timeout_ms < -1 * (int64_t)_interval_ms) {
>> +      _nticks += -timeout_ms / _interval_ms;
>>       } else {
>>         // Tick
>>         return !_stopped;
>> -----------------------------------
>> For more info, please see the JBS.
>>
>> Testing:
>>    - make test TEST="hotspot_gc" CONF=release
>>
>> Thanks a lot.
>> Best regards,
>> Jie
>>
>>