"hwclock -w" takes 24 seconds

[Denys Vlasenko]

On Wed, Apr 14, 2010 at 8:23 AM, Piotr Grudzinski <piotr at powersmiths.com> wrote:
>> On Wednesday 14 April 2010 01:01:08 Steve Bennett wrote:
>>>
>>> On 13/04/2010, at 11:09 AM, Rob Landley wrote:
>>> > On Tuesday 13 April 2010 10:08:56 Kim B. Heino wrote:
>>> >> BusyBox 1.16.1 on a small armv4tl system:
>>> >>
>>> >> $ time hwclock -w
>>> >> real    0m 24.34s
>>> >> user    0m 0.00s
>>> >> sys     0m 0.00s
>>> >>
>>> >> $ time hwclock -w
>>> >> real    0m 24.07s
>>> >> user    0m 0.01s
>>> >> sys     0m 0.00s
>>> >>
>>> >> $ time hwclock -w
>>> >> real    0m 24.20s
>>> >> user    0m 0.00s
>>> >> sys     0m 0.00s
>>> >>
>>> >> rem_usec seems to be about 996600 after every iteration. Changing sync
>>> >> resolution from 1ms to 5ms helps, but there has to be better solution.
>>> >> Denys?
>>> >
>>> > I can confirm this on my armv4tl system image:
>>> >
>>> >  wget
>>> >
>>> > http://impactlinux/com/fwl/downloads/binaries/system-image-armv4tl.tar.bz
>>> >2 tar xvjf system-image-armv4tl.tar.bz2
>>> >  cd system-image-armv4tl
>>> >  ./run-emulator.sh
>>> >
>>> > wait through the boot messages...
>>> >
>>> >  (armv4tl) /home # time hwclock -w
>>> >  real        0m 24.98s
>>> >  user       0m 0.01s
>>> >  sys         0m 0.01s
>>> >
>>> > This assumes you have qemu 0.12.x installed.
>>> >
>>> > Rob
>>> >
>>> > P.S: As expected, application emulation is useless here:
>>> >
>>> >  $ qemu-arm ./hwclock
>>> >  Unsupported ioctl: cmd=0xffffffff80247009
>>> >  hwclock: RTC_RD_TIME: Function not implemented
>>>
>>> Interesting.
>>>
>>> BusyBox v1.17.0.git
>>>
>>> armv5teb
>>> ~ # strace hwclock -w
>>> ... blah blah ...
>>> open("/etc/adjtime", O_RDONLY)          = -1 ENOENT (No such file or
>>> directory) open("/dev/rtc", O_WRONLY)              = -1 ENOENT (No such
>>> file or directory) open("/dev/rtc0", O_WRONLY)             = 3
>>> gettimeofday({1271224598, 269609}, NULL) = 0
>>> open("/etc/config/TZ", O_RDONLY)        = 4
>>> read(4, "EST-10\n", 68)                 = 7
>>> read(4, "", 61)                         = 0
>>> close(4)                                = 0
>>>
>>> ... lots of these ...
>>>
>>> open("/etc/config/TZ", O_RDONLY)        = 4
>>> read(4, "EST-10\n", 68)                 = 7
>>> read(4, "", 61)                         = 0
>>> close(4)                                = 0
>>> gettimeofday({1271224622, 14271}, NULL) = 0
>>> nanosleep({0, 984729000}, NULL)         = 0
>>> gettimeofday({1271224623, 8166}, NULL)  = 0
>>
>> That's a largeish looking nanosleep.
>>
>> At a guess, that would be this util-linx/hwclock.c snippet:
>>
>>               /* Try to sync up by sleeping */
>>               rem_usec = 1000000 - tv.tv_usec;
>>               if (rem_usec < 1024) {
>>                       goto small_rem; /* already close, don't sleep */
>>               }
>>               /* Need to sleep.
>>                * Note that small adj on slow processors can make us
>>                * to always overshoot tv.tv_usec < 1024 check on next
>>                * iteration. That's why adj is increased on each iteration.
>>                * This also allows it to be reused as a loop limiter.
>>                */
>>               usleep(rem_usec - adj);
>>
>>
>> I'm guessing the tv.tv_usec is larger than 1000000 and thus it wraps?
>>
>> When CELF is over, I should look at what gettimeofday() is returning to
>> fill in
>> the tv field.  Right now, I'm at a conference and thus a bit
>> overscheduled...
>>
>> Rob
>
> If the condition (rem_usec < 1024) is never met, which seems to be the case
> on my system
> with timer tick of 10ms, it will take (1024-200)/32=25.75 seconds to execute
> the hwclock
> command.

I fixed syncing code so that it widens sync window very fast.
But then I disabled it anyway, it's too big and in my testing,
RTC isn't setting time with ~0.5sec precision anyway (!!!).

Fixed in git, will be in 1.16.2
-- 
vda