[prev in list] [next in list] [prev in thread] [next in thread] 

List:       openjdk-hotspot-runtime-dev
Subject:    Long young generation GC?
From:       y.s.ramakrishna () oracle ! com (Y !  S !  Ramakrishna)
Date:       2010-10-26 17:58:44
Message-ID: 4CC716D4.2030005 () oracle ! com
[Download RAW message or body]

"real" is elapsed time too, obtained from the OS via times(2).
So if it's reported so small when users see much more time elapse physically,
it must be the case that it's a bug in times(2) in a virtual setting.
Perhaps if you can boil this down to a small and reproducible test case
you can file a bug with the VM provider and with the JVM as well, the
latter perhaps a shadow of the former.

Over to the runtime team.
-- ramki

On 10/26/10 10:49, Hi Guava wrote:
> I now believe that this phenomenon is caused by the virtual machine.
> It has nothing to do with the garbage collector or JVM. I searched in
> the old logs and found this in all 3 old logs that I have. There are
> multiple virtual machines configured the same way. This problem only
> shows up in one of the virtual machines.
> By the way, the 639 seconds GC is not a perception problem. It is
> real. The users reported stuck process and they found the CPUs of the
> virtual machine was racing during that period.
> Can I understand this discrepancy this way? the user, sys and real
> times are measured in cpu cycles. They are short as they are supposed
> to be. The 439.2720750 time is the elapsed time. Since the virtual
> machine is doing something else or not functioning correctly, GC took
> 439 seconds even though there was only 0.08 seconds of cpu time.
> 
> 72681.425: [GC 72681.426: [ParNew: 38325K->4224K(38336K), 439.2720750
> secs] 3013053K->2979055K(6549376K), 439.2720750 secs] [Times:
> user=0.08 sys=0.00, real=0.08 secs]
> 
> 
> On Tue, Oct 26, 2010 at 12:34 PM, Y. S. Ramakrishna
> <y.s.ramakrishna at oracle.com> wrote:
>>
>> On 10/26/10 07:07, Hi Guava wrote:
>>> Here is additional information about the machine running the JVM. It
>>> is a virtual machine running in a private cloud. Could it be something
>>> like swapping that caused problem?
>> Not swapping, but perhaps the management of "time" perhaps in a virtualized
>> setting (by that i mean that there may be interactions between the
>> host/hypervisor and the guest OS that could cause the JVM to observe
>> time jumps of this sort)? I'd suggest gathering more data on its
>> reproducibility (or otherwise) in both a VM and non-VM setting.
>>
>> Over to the time experts in the runtime team who may have encountered
>> issues in VM settings previously. (I have heard of occasional such reports
>> in
>> virtual settings before but don't know if any of these were definitively
>> chased
>> down.) You might also want to check with the VM provider to see if they
>> might know of such issues.
>>
>> -- ramki
>>
>>
>>> On Mon, Oct 25, 2010 at 8:51 PM, Y. Srinivas Ramakrishna
>>> <y.s.ramakrishna at oracle.com> wrote:
>>>> On 10/25/2010 5:49 PM, Y. Srinivas Ramakrishna wrote:
>>>>> On 10/25/2010 5:32 PM, Hi Guava wrote:
>>>>>> The third young generation GC took 439.2720750 secs but the user and
>>>>>> real time are only 0.08 seconds. What does it mean?
>>>>> The machine may be using NTP, and the time may have been changed?
>>>> Seems a rather large jump, so may not be NTP (which i am told uses
>>>> adjtime() to slowly accelerate the time forward or decelerate it
>>>> backward),
>>>> but rather an abrupt perhaps manual change in TOD.
>>>>
>>>> Over to the experts....
>>>>
>>>>> JVM timestamps on Linux seem still to be based on TOD rather than
>>>>> on TSC. Someone in the runtime team (cc'd) may have more detail on
>>>>> why that might still be so.
>>>>>
>>>>> -- ramki
>>>>>
>>>>>
>>>>>> 72667.213: [GC 72667.213: [ParNew: 38336K->4224K(38336K), 1.2473840
>>>>>> secs]
>>>>>> 3443948K->3420569K(6549376K), 1.2474290 secs] [Times: user=0.64
>>>>>> sys=1.10,
>>>>>> real=1.25 secs]
>>>>>> 72680.531: [GC 72680.532: [ParNew: 38336K->4221K(38336K), 0.2916570
>>>>>> secs]
>>>>>> 3008948K->2979033K(6549376K), 0.2916710 secs] [Times: user=0.26
>>>>>> sys=0.03,
>>>>>> real=0.29 secs]
>>>>>> 72681.425: [GC 72681.426: [ParNew: 38325K->4224K(38336K), 439.2720750
>>>>>> secs] 3013053K->2979055K(6549376K), 439.2720750 secs] [Times: user=0.08
>>>>>> sys=0.00, real=0.08 secs]
>>>>>>
>>>>>> Environment:
>>>>>> Java HotSpot(TM) 64-Bit Server VM Version 1.6.0_20-b02
>>>>>> Linux Version 2.6.18-128.1.1.el5 on amd64
>>>>>> -Xms6400m
>>>>>> -Xmx6400m
>>>>>> -Xss256k
>>>>>> -XX:+UseConcMarkSweepGC
>>>>>> -XX:+PrintGCDetails
>>>>>> -XX:+PrintGCTimeStamps
>>>>>> -XX:+UseCompressedOops
>>>>>> _______________________________________________
>>>>>> hotspot-gc-use mailing list
>>>>>> hotspot-gc-use at openjdk.java.net
>>>>>> http://mail.openjdk.java.net/mailman/listinfo/hotspot-gc-use

[prev in list] [next in list] [prev in thread] [next in thread]