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

[Jie Fu]

Very nice.
Feel much better when debugging now.
Thank you, Per.

Best regards,
Jie

On 2019/5/17 下午4:03, Per Liden wrote:
> A slight refinement and also removing ZMetronome::nticks() as it's not 
> very useful anymore.
>
> http://cr.openjdk.java.net/~pliden/8223961/webrev.0
>
> /Per
>
> On 5/17/19 8:14 AM, Per Liden wrote:
>> Let's wait for a second Reviewer to give thumbs up, then I'll go 
>> ahead and sponsor/push this.
>>
>> cheers,
>> Per
>>
>> On 5/16/19 11:21 AM, Jie Fu wrote:
>>> It's much clearer and more reasonable.
>>> I like your patch.
>>> Thanks Per.
>>>
>>> On 2019/5/16 下午4:40, Per Liden wrote:
>>>> 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
>>>>>>
>>>>>>
>>>