Bug 640608

Thanks for the report.
There is definitely a bug in there somewhere.
I wonder if this is ruby-specific.  I suspect Xen, not ruby.

What does this print for you:

  perl '-MTime::HiRes "time"' -le '$t=time; sleep 1; print time - $t'

If that shows the same problem, then please reassign the bug.
If it does not, please run the following and attach the resulting "log" file:

  strace -o log ruby -e 't=Time.now; sleep 1; puts Time.now - t'

(In reply to comment #1)
> Thanks for the report.
> There is definitely a bug in there somewhere.
> I wonder if this is ruby-specific.  I suspect Xen, not ruby.

That's right, but weird is, that Perl or C doesn't suffer with this kind of problem.

> What does this print for you:
> 
>   perl '-MTime::HiRes "time"' -le '$t=time; sleep 1; print time - $t'

This one works fine:

perl '-MTime::HiRes "time"' -le '$t=time; sleep 1; print time - $t'
1.00364589691162

> 
> If that shows the same problem, then please reassign the bug.
> If it does not, please run the following and attach the resulting "log" file:
> 
>   strace -o log ruby -e 't=Time.now; sleep 1; puts Time.now - t'

Log file attached.

Created attachment 452057 [details]
strace output

Thanks for the info.
Note that Perl does not use gettimeofday, but rather the superior "nanosleep" function.

Contrast your output:

  gettimeofday({1286441633, 652023}, NULL) = 0
  time(NULL)                              = 1286441633
  select(0, NULL, NULL, NULL, {1, 0})     = 0 (Timeout)
  time(NULL)                              = 1286441634
  gettimeofday({1286441634, 651329}, NULL) = 0

with what I see on RHEL6:

  rt_sigprocmask(SIG_BLOCK, NULL, [], 8)  = 0
  select(0, NULL, NULL, NULL, {1, 0})     = 0 (Timeout)

It may be that RHEL5's gettimeofday isn't working quite right.

This discussion suggests that your problem could be due to how your virtual system is configured:

   http://thread.gmane.org/gmane.comp.emulators.xen.user/55086/focus=55117

Here is a related bug.  Make sure that you have that fix:

   https://bugzilla.redhat.com/show_bug.cgi?id=427588

(In reply to comment #4)
> Thanks for the info.
> Note that Perl does not use gettimeofday, but rather the superior "nanosleep"
> function.
> 
> Contrast your output:
> 
>   gettimeofday({1286441633, 652023}, NULL) = 0
>   time(NULL)                              = 1286441633
>   select(0, NULL, NULL, NULL, {1, 0})     = 0 (Timeout)
>   time(NULL)                              = 1286441634
>   gettimeofday({1286441634, 651329}, NULL) = 0
> 
> with what I see on RHEL6:
> 
>   rt_sigprocmask(SIG_BLOCK, NULL, [], 8)  = 0
>   select(0, NULL, NULL, NULL, {1, 0})     = 0 (Timeout)
> 
> It may be that RHEL5's gettimeofday isn't working quite right.
> 
> This discussion suggests that your problem could be due to how your virtual
> system is configured:
> 
>    http://thread.gmane.org/gmane.comp.emulators.xen.user/55086/focus=55117
> 
> Here is a related bug.  Make sure that you have that fix:
> 
>    https://bugzilla.redhat.com/show_bug.cgi?id=427588

Hi, we tried several combinations of kernel parameters and also kernel update but nothing works :-(
So I thought this bug is not Ruby related as you said before but XEN. I'm changing component to XEN then.

Please describe the host and guest completely; kernel revisions for both, type of guest (pv|fv), x86_64 or i386. Also take a look at dmesg for both host and guest and 'xm dmesg' on the host. If there's anything interesting, please attach it.

Thanks,
Drew

Guest:
 * PV XEN guest
 * 2.6.18-194.17.1.el5xen
 * x86_64
 * 1 VCPU

Host: 
 * RHEL5.5
 * 2.6.18-194.11.3.el5xen
 * x86_64
 * 8 CPU

Do you need anything else?

I captured some data for a variety of systems.

-------------------------------------------------------------------------------
config                mean     standard          max          min         diff
                              deviation                                 from 1
-------------------------------------------------------------------------------
dom0              0.997042     0.000655     1.005585     0.996048     0.002958
f12_bm            1.000866     0.000346     1.003212     1.000062     0.000866
rhel55-64pv       0.997907     0.000720     1.005739     0.993254     0.002093
rhel6-32pv        1.001077     0.000053     1.001859     1.000138     0.001077
rhel6-64fv        1.001599     0.000296     1.002114     1.001069     0.001599
rhel6-64pv        1.001071     0.000058     1.001999     1.000136     0.001071

The f12_bm is my f12 bare-metal notebook. dom0 is a latest rhel 5.6 candidate and was the dom0 used for all the other cases, which are xen guests.  We see that bare-metal has the closest mean to 1, but it's standard deviation isn't the best. This indicates that we have error here even without virtualization. With respect to virtualization we see that the rhel5 systems (dom0 and rhel55-64pv) are generally less than 1, as was observed when this bug was opened, but not always. They also have the worst standard deviation and difference of the mean from 1. However, the rhel6 guests are all generally higher and have differences closer to that of the bare-metal, but with even less standard deviation.

What all this tells us is that if there's a problem, and not just some expected error, then it's at least in the kernel, not the hypervisor, or it could be even higher up the stack.  I'll move this bug over to the kernel for now to get comments from them.

Note, I also quickly scanned the data by eye to see if it looked the results were increasing or decreasing -- indicating some cumulative error on time accounting. I didn't see any obvious patterns.

This Bugzilla has been reviewed by Red Hat and is not planned on being
addressed in Red Hat Enterprise Linux 5, and therefore is being closed.
If this bug is critical to production systems, please contact your Red
Hat support representative and provide a sufficient business justification
in order to re-open it.