Time is lagging substantially on Netgear ReadyNAS RN102 and RN104

Hi bodhi,

The clock is running about 10% too slowly on Netgear ReadyNAS RN102 and RN104.

Below the transcript of the following test: My hosts 'rn104' and 'stora' share the same router and local network. Time and date on 'rn104' is synced with 'stora' using 'ssh'. 60 s later (on its own clock) 'rn104' is lagging 6 to 7 s:

tme@nr104:~$ sudo /etc/init.d/ntp stop && sudo date -s "$(ssh stora date -R)" && date -R && sleep 60 && hostname; date -R && ssh stora 'hostname;date -R'
Stopping NTP server: ntpd.
Mon Jan  9 10:53:48 CET 2023
Mon, 09 Jan 2023 10:53:48 +0100
nr104
Mon, 09 Jan 2023 10:54:48 +0100
stora
Mon, 09 Jan 2023 10:54:55 +0100

Once more:

tme@nr104:~$ sudo /etc/init.d/ntp stop && sudo date -s "$(ssh stora date -R)" && date -R && sleep 60 && hostname; date -R && ssh stora 'hostname;date -R'
Stopping NTP server: ntpd.
Mon Jan  9 10:55:05 CET 2023
Mon, 09 Jan 2023 10:55:05 +0100
nr104
Mon, 09 Jan 2023 10:56:05 +0100
stora
Mon, 09 Jan 2023 10:56:11 +0100

Is the input clock frequency given correctly in the dts file? The input clock frequency is specified here by Arnaud Ebalard, the original author of the dts file, but this is, of course, not really an authoritative source. Netgear ReadyNAS RN102 has the same flaw as the RN104.

Regards,
Trond Melen

Hi Trond,

> Is the input clock frequency given correctly in
> the
> dts
> file? The input clock frequency is specified
> here
> by Arnaud Ebalard, the original author of the dts
> file, but this is, of course, not really an
> authoritative source.

I think natisbad.org has been a quite reliable source over the years. And your problem could be the RTC driver and/or DTS. The clock node in the DTS seems fine.

> Netgear ReadyNAS RN102 has
> the same flaw as the RN104.
>

I was thinking about this is RTC battery problem, but if both boxes show the same issue then I would say we can eliminate the battery. The Stora RTC is pcf8563, very popular so I don't think its driver has problem.

So perhaps there could be a bug in the driver or DTS but nobody noticed before.

Why dont you have a sanity test. Sync your RN102 clock to you phone clock. If will be not exact, but lagging 6, 7 secs after 1 minute will be quite apparent if indeed there is lag.

-bodhi
===========================
Forum Wiki
bodhi's corner

Thanks bodhi!

Some 20 hours ago, the time on my RN102 was synced with the time of its router (where NTP is working). Since then, its system clock has been synced with its hardware clock by 'cron' every minute. (I did the same with the RN104, but it is currently remote and inaccessible.)

On the RN102:

tme@rn102:~$ sudo crontab -l | tail -2
[sudo] password for tme: 
0 * * * * /root/rearm-wakealarm
* * * * * /sbin/hwclock -s

tme@rn102:~$ ssh root@router 'hostname; date -R' && hostname; date -R
router
Tue, 10 Jan 2023 08:05:33 +0100
rn102
Tue, 10 Jan 2023 08:05:30 +0100

And again:

tme@rn102:~$ ssh root@router 'hostname; date -R' && hostname; date -R
router
Tue, 10 Jan 2023 08:05:53 +0100
rn102
Tue, 10 Jan 2023 08:05:48 +0100

The RN102 is now about 4 s ahead. I would say the RTC is off the hook?

Regards,
Trond Melen

Hi bodhi,

In the morning, on another RN102 (not running NTP), time and date was synchronized with its router (where NTP is working).

tme@nr102:~$ sudo date -s "$(ssh root@router date -R)"
root@router's password: 
Tue, 10 Jan 2023 09:08:28 +0100

In the evening, 11:56 h later, the system clock had fallen 1 h behind.

tme@nr102:~$ ssh root@router 'hostname; date -R' && hostname; date -R
root@router's password: 
router
Tue, 10 Jan 2023 21:04:04 +0100
nr102
Tue, 10 Jan 2023 20:04:04 +0100

Lagging 1 h in 11:56 h is about 8.38%.

Regards,
Trond Melen

Hi Trond,

> The RN102 is now about 4 s ahead. I would say the
> RTC is off the hook?

I would not say that RTC is off the hook. Given we know RTC is working with a cron job, the system clock should have been automatically updated using RTC without that cron job. So the issue could be somehow related to RTC driver. Did you check dmesg and syslog if there is anything interesting?

-bodhi
===========================
Forum Wiki
bodhi's corner

Hi bodhi,

My understanding is that the kernel reads the RTC when booting, but maintains it's own time thereafter. NTP normally compensates for drift, but on the RN102 and RN104 the drift is so large that NTP fails to compensate. Turning off NTP, the clock is measures to be about 8% slow. Letting 'cron' update the system time from the RTC once a minute limits the drift to a few seconds, so the RTC maintains correct time. Am I missing something?

From the attached dmesg log:

[    0.000000] Switching to timer-based delay loop, resolution 53ns
[    0.000001] sched_clock: 32 bits at 19MHz, resolution 53ns, wraps every 114537122277ns
[    0.007872] clocksource: armada_370_xp_clocksource: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 101938038664 ns
[    0.019438] Console: colour dummy device 80x30
[    0.024168] Calibrating delay loop (skipped), value calculated using timer frequency.. 37.49 BogoMIPS (lpj=187492)

Do you see something interresting here?

Regards,
Trond Melen

HI Trond,

> My understanding is that the kernel reads the RTC
> when booting, but maintains it's own time
> thereafter.

Of course, you're right. I meant to say "driver" above and instead mispoke as RTC. I'm thinking some clock/time driver is broken, not hardware.

> NTP normally compensates for drift,
> but on the RN102 and RN104 the drift is so large
> that NTP fails to compensate. Turning off NTP, the
> clock is measures to be about 8% slow. Letting
> 'cron' update the system time from the RTC once a
> minute limits the drift to a few seconds, so the
> RTC maintains correct time. Am I missing
> something?
>
> From the attached dmesg log:
>

> [    0.000000] Switching to timer-based delay
> loop, resolution 53ns
> [    0.000001] sched_clock: 32 bits at 19MHz,
> resolution 53ns, wraps every 114537122277ns
> [    0.007872] clocksource:
> armada_370_xp_clocksource: mask: 0xffffffff
> max_cycles: 0xffffffff, max_idle_ns: 101938038664
> ns
> [    0.019438] Console: colour dummy device 80x30
> [    0.024168] Calibrating delay loop (skipped),
> value calculated using timer frequency.. 37.49
> BogoMIPS (lpj=187492)
>

> Do you see something interresting here?

Let me boot up my Mirabox and see if I can see similar behavior.

-bodhi
===========================
Forum Wiki
bodhi's corner

Hi bodhi,

[    0.000001] sched_clock: 32 bits at 19MHz, resolution 53ns, wraps every 114537122277ns

A 19 MHz clock has one tick per 53 ns and if has 31 bits it would wrap every 115 s. So far so good. My hunch is that the 19 MHz input clock is actually closer to 17 MHz. That would explain the observations, right?

There is no relevant clock definition in 'armada-370-netgear-rn104.dts' so I assume the clock frequency is inherited by this line:

compatible = "netgear,readynas-104", "marvell,armada370", "marvell,armada-370-xp"

Maybe 'armada-370-netgear-rn102.dts' and 'armada-370-netgear-rn104.dts' need a new clock definition to overrule the inherited one?

Regards,
Trond Melen

Hi Trond,

Yes the clock source is the common armada_370_xp_clocksource, due to those compatible attributes in the node.

I have not booted up my Mirabox yet. But here is the old log.

Mirabox

[    0.000000] Switching to timer-based delay loop, resolution 53ns
[    0.000006] sched_clock: 32 bits at 18MHz, resolution 53ns, wraps every 114840871909ns
[    0.007894] clocksource: armada_370_xp_clocksource: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 102208375848 ns
[    0.019513] Console: colour dummy device 80x30
[    0.023962] Calibrating delay loop (skipped), value calculated using timer frequency.. 37.39 BogoMIPS (lpj=186996)

You RN102 log

[    0.000000] Switching to timer-based delay loop, resolution 53ns
[    0.000001] sched_clock: 32 bits at 19MHz, resolution 53ns, wraps every 114537122277ns
[    0.007872] clocksource: armada_370_xp_clocksource: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 101938038664 ns
[    0.019438] Console: colour dummy device 80x30
[    0.024168] Calibrating delay loop (skipped), value calculated using timer frequency.. 37.49 BogoMIPS (lpj=187492)

Note the sched_clock difference.

I think I'll need to look at the DTS files for these 2 and other Armada 370 boards.

-bodhi
===========================
Forum Wiki
bodhi's corner

Hi Trond,

Please try these 2 new DTB. Basically, the new node in this version is

+			timer@20300 {
+                                clock-frequency = <600000000>;
+				status = "okay";
+			};
+

-bodhi
===========================
Forum Wiki
bodhi's corner

Hi bodhi,

I have tested your new dtb file. It failed. I did:

root@rn104:/boot# cp -a uImage uImage.bak
root@rn104:/boot# cp -a uInitrd uInitrd.bak
root@rn104:/boot# cp -a zImage-5.19.2-mvebu-370xp-tld-1 zImage.fdt
root@rn104:/boot# cat dts/armada-370-netgear-rn104.dtb >> zImage.fdt 

root@rn104:/boot# mkimage -A arm -O linux -T kernel -C none -a 0x00008000 -e 0x00008000 -n Linux-5.19.2-mvebu-370xp-tld-1 -d zImage.fdt uImage
Image Name:   Linux-5.19.2-mvebu-370xp-tld-1
Created:      Sun Jan 15 08:22:58 2023
Image Type:   ARM Linux Kernel Image (uncompressed)
Data Size:    5074362 Bytes = 4955.43 KiB = 4.84 MiB
Load Address: 00008000
Entry Point:  00008000

root@rn104:/boot# mkimage -A arm -O linux -T ramdisk -C gzip -a 0x00000000 -e 0x00000000 -n initramfs-5.19.2-mvebu-370xp-tld-1 -d initrd.img-5.19.2-mvebu-370xp-tld-1 uInitrd
Image Name:   initramfs-5.19.2-mvebu-370xp-tld
Created:      Sun Jan 15 08:23:16 2023
Image Type:   ARM Linux RAMDisk Image (gzip compressed)
Data Size:    10392569 Bytes = 10148.99 KiB = 9.91 MiB
Load Address: 00000000
Entry Point:  00000000

root@rn104:/boot# sync
root@rn104:/boot# shutdown -r now

From the attached boot log:

[    0.000000][    T0] Switching to timer-based delay loop, resolution 53ns
[    0.000001][    T0] sched_clock: 32 bits at 19MHz, resolution 53ns, wraps every 114537122277ns
[    0.007872][    T0] clocksource: armada_370_xp_clocksource: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 101938038664 ns
[    0.019438][    T0] Console: colour dummy device 80x30
[    0.024168][    T0] Calibrating delay loop (skipped), value calculated using timer frequency.. 37.49 BogoMIPS (lpj=187492)

So no change here.

Worse, the kernel no longer finds the root file system, so it fails to boot. After 43 s, it prompts:

Gave up waiting for root file system device.  Common problems:
 - Boot args (cat /proc/cmdline)
   - Check rootdelay= (did the system wait long enough?)
 - Missing modules (cat /proc/modules; ls /dev)
ALERT!  LABEL=rootfs does not exist.  Dropping to a shell!


BusyBox v1.30.1 (Debian 1:1.30.1-6+b3) built-in shell (ash)
Enter 'help' for a list of built-in commands.

(initramfs) help
Built-in commands:
------------------
        . : [ [[ alias bg break cd chdir command continue echo eval exec
        exit export false fg getopts hash help history jobs kill let
        local printf pwd read readonly return set shift source test times
        trap true type ulimit umask unalias unset wait
(initramfs)

To revert back to the previous dtb file, I connected the SSD to my laptop and did:

root@t470s:/media/tme/rootfs/boot# mv uImage.bak uImage
root@t470s:/media/tme/rootfs/boot# mv uInitrd.bak uInitrd
root@t470s:/media/tme/rootfs/boot# cp -a zImage-5.19.2-mvebu-370xp-tld-1 zImage.fdt
root@t470s:/media/tme/rootfs/boot# cat dts/armada-370-netgear-rn104.dtb.lagging >> zImage.fdt

root@t470s:/media/tme/rootfs/boot# mkimage -A arm -O linux -T kernel -C none -a 0x00008000 -e 0x00008000 -n Linux-5.19.2-mvebu-370xp-tld-1 -d zImage.fdt uImage
Image Name:   Linux-5.19.2-mvebu-370xp-tld-1
Created:      Sun Jan 15 09:17:29 2023
Image Type:   ARM Linux Kernel Image (uncompressed)
Data Size:    5074371 Bytes = 4955.44 KiB = 4.84 MiB
Load Address: 00008000
Entry Point:  00008000

root@t470s:/media/tme/rootfs/boot# mkimage -A arm -O linux -T ramdisk -C gzip -a 0x00000000 -e 0x00000000 -n initramfs-5.19.2-mvebu-370xp-tld-1 -d initrd.img-5.19.2-mvebu-370xp-tld-1 uInitrd
Image Name:   initramfs-5.19.2-mvebu-370xp-tld
Created:      Sun Jan 15 09:17:49 2023
Image Type:   ARM Linux RAMDisk Image (gzip compressed)
Data Size:    10392569 Bytes = 10148.99 KiB = 9.91 MiB
Load Address: 00000000
Entry Point:  00000000

root@t470s:/media/tme/rootfs/boot# sync

Connected the SSD to the eSata port on the box and booted. Now everything is as before, it seems.

Is time good on your Mirabox (with NTP disabled)? Are you able to make it lag or gain by modifying it's clock definition?

Regards,
Trond Melen

Trond,

That was a shot in the dark on my part :)

> Is time good on your Mirabox (with NTP disabled)?
> Are you able to make it lag or gain by modifying
> it's clock definition?

I've been pretty busy with other things so have not booted up the Mirabox yet!

I think we need to read the driver code to see what's going on.

./drivers/clocksource/timer-armada-370-xp.c

-bodhi
===========================
Forum Wiki
bodhi's corner

Hi Trond,

It's interesting that the Mirabox seems to show different initialization. Just boot up the box.

root@Mirabox:~# myinfo

Mirabox
192.168.0.252  
Globalscale Mirabox
Linux version 5.19.2-mvebu-370xp-tld-1 (root@tldDebian) (gcc (Debian 10.2.1-6) 10.2.1 20210110, GNU ld (GNU Binutils for Debian) 2.35.2) #1.0 PREEMPT Sun Aug 21 14:07:19 PDT 2022
Debian 10.2

root@Mirabox:~# dmesg |grep -3 clocksource
[    0.000000] kfence: initialized - using 2097152 bytes for 255 objects at 0x(ptrval)-0x(ptrval)
[    0.000000] Switching to timer-based delay loop, resolution 53ns
[    0.000001] sched_clock: 32 bits at 19MHz, resolution 53ns, wraps every 114840871909ns
[    0.008585] clocksource: armada_370_xp_clocksource: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 102208375848 ns
[    0.021045] Console: colour dummy device 80x30
[    0.026200] Calibrating delay loop (skipped), value calculated using timer frequency.. 37.39 BogoMIPS (lpj=186996)
[    0.037233] pid_max: default: 32768 minimum: 301
--
[    0.120039] rcu: 	Max phase no-delay instances is 1000.
[    0.127140] devtmpfs: initialized
[    0.135209] VFP support v0.3: implementor 56 architecture 2 part 20 variant 9 rev 6
[    0.143927] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 19112604462750000 ns
[    0.154436] futex hash table entries: 256 (order: -1, 3072 bytes, linear)
[    0.162033] prandom: seed boundary self test passed
[    0.170095] prandom: 100 self tests passed
--
[    2.080222] pps_core: Software ver. 5.3.6 - Copyright 2005-2007 Rodolfo Giometti <giometti@linux.it>
[    2.090034] PTP clock support registered
[    2.111673] vgaarb: loaded
[    2.120682] clocksource: Switched to clocksource armada_370_xp_clocksource
[    2.141373] VFS: Disk quotas dquot_6.6.0
[    2.146034] VFS: Dquot-cache hash table entries: 1024 (order 0, 4096 bytes)
[    2.178996] NET: Registered PF_INET protocol family

Stop NTP and let see how much will the lag be, if any.

root@Mirabox:~# date
Tue 17 Jan 2023 11:07:41 PM PST

Another box with NTP running.
# date
Tue 17 Jan 2023 11:07:38 PM PST


root@Mirabox:~# /etc/init.d/ntp stop
[ ok ] Stopping NTP server: ntpd.

-bodhi
===========================
Forum Wiki
bodhi's corner



Edited 1 time(s). Last edit at 01/18/2023 01:09AM by bodhi.

Hi bodhi,

There are some differences, but I find them minor compared to the observed 8% time lag:

tme@t470s:~/Downloads$ grep -3 clocksource dmesg.lst 
[    0.000000] kfence: initialized - using 2097152 bytes for 255 objects at 0x(ptrval)-0x(ptrval)
[    0.000000] Switching to timer-based delay loop, resolution 53ns
[    0.000001] sched_clock: 32 bits at 19MHz, resolution 53ns, wraps every 114537122277ns
[    0.007872] clocksource: armada_370_xp_clocksource: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 101938038664 ns
[    0.019438] Console: colour dummy device 80x30
[    0.024168] Calibrating delay loop (skipped), value calculated using timer frequency.. 37.49 BogoMIPS (lpj=187492)
[    0.034290] pid_max: default: 32768 minimum: 301
--
[    0.110959] rcu: 	Max phase no-delay instances is 1000.
[    0.117666] devtmpfs: initialized
[    0.126529] VFP support v0.3: implementor 56 architecture 2 part 20 variant 9 rev 6
[    0.134613] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 19112604462750000 ns
[    0.144256] futex hash table entries: 256 (order: -1, 3072 bytes, linear)
[    0.151252] prandom: seed boundary self test passed
[    0.158862] prandom: 100 self tests passed
--
[    2.054169] pps_core: Software ver. 5.3.6 - Copyright 2005-2007 Rodolfo Giometti <giometti@linux.it>
[    2.078575] PTP clock support registered
[    2.089990] vgaarb: loaded
[    2.099139] clocksource: Switched to clocksource armada_370_xp_clocksource
[    2.120027] VFS: Disk quotas dquot_6.6.0
[    2.124320] VFS: Dquot-cache hash table entries: 1024 (order 0, 4096 bytes)
[    2.160606] NET: Registered PF_INET protocol family

Regards,
Trond Melen

Hi Trond,

Ok. So I've verified there is no lag for the Mirabox after 3 hours. But I have not found out what could be changed in the clocksource driver to intentionally cause the lag. Everything is based on the DTS (e.g the register location).

The DTS files armada-370*.dts* all make sense for both boxes.

Not sure why the timer@20300 was specificed in the Mirabox, there is no need for it, this could be old code for the L2 cache frequency.

-bodhi
===========================
Forum Wiki
bodhi's corner

Hi boidhi,

Comparing our 'dmesg' logs, I find it interesting that apparently time is lagging as soon as the kernel starts its internal timer:

RN102            0          0   0.000001   0.007872   0.019438   0.024168   0.034290   0.110959   0.117666   0.126529   0.134613   0.144256   0.151252   0.158862   2.054169   2.078575   2.089990   2.099139   2.120027   2.124320   2.160606
Mirabox          0          0   0.000001   0.008585   0.021045   0.026200   0.037233   0.120039   0.127140   0.135209   0.143927   0.154436   0.162033   0.170095   2.080222   2.090034   2.111673   2.120682   2.141373   2.146034   2.178996
Ratio          NaN        NaN   1.000000   0.916948   0.923640   0.922443   0.920957   0.924358   0.925484   0.935803   0.935287   0.934083   0.933464   0.933960   0.987476   0.994517   0.989732   0.989841   0.990032   0.989882   0.991560

I make 2 observations:

• Already after 8585 us (Mirabox time), RN102 time is lagging ~8%. This remains so for a while.
• After 2 s, time is the same within ~1% on both boxes. Time seems to have been synchronized, presumably with the RTC.

My first hypothesis was that the RN102 and Mirabox share the same CPU clock frequency setup, but that the RN102 is actually running from a slower clock source than the Mirabox. If so, however, the boot steps on the RN102 should both take longer to complete and be timed by a slower clock, so 'dmesg' should report the same progress for both boxes.

What do you make of this?

Regards,
Trond Melen

Hi Trond,

Not sure what to make of this.

Other than this fact, the schedule clock here is only 32 bits. So it wraps very quickly

[ 0.000001] sched_clock: 32 bits at 19MHz, resolution 53ns, wraps every 114 537 122 277 ns

-bodhi
===========================
Forum Wiki
bodhi's corner

Hi bodhi,

From drivers/clocksource/timer-armada-370-xp.c:

 * Timer 0 is used as free-running clocksource, while timer 1 is
 * used as clock_event_device.

define TIMER_DIVIDER_SHIFT     5

The shifting by 5 indicates that shed_clock (timer 0) is the CPU clock divided by 64, i.e. 1.2 GHz / 64 = 18.75 MHz which gives a time resolution of 53.333... ns as expected.

And from the online kernel documentation:

Quote
sched_clock() is used for scheduling and timestamping.

When the sched_clock wraps every 115 s, it just means, I believe, than the kernel must use other means to schedule events further into the future. 115 s should typically be sufficient for driver related tasks. I assume the kernel schedules update of system time by interrupt at least once a second. Maybe even once a millisecond?

I have looked for differences between the Mirabox and the RN104/RN104 that may explain the lagging of the latter. I found two candidates:

1. According to the Info Depot Wiki the Mirabox' SoC (System on a Chip) is a Marvell 88F6707, while the RN102 has a Marvell 88F6710 SoC. 88F6707 is a stripped down version of 88F6710 lacking:
   
   • Time Division Multiplexing TDM interface supporting up to two VoIP channels
   • 8/16-bit Device bus
   • Integrated Interchip Sound (I2S) audio in/out interface or S/PDIF (Sony/Philips Digital Interconnect Format) interface
2. Both SoCs has a build-in RTC (Real Time Clock). The RN102 has an additional Intersil ISL12057 I2C bus RTC. The built-in one is disabled by the RN102 DTS file.

Do you think any of these differences can explain the lagging?

Regards,
Trond Melen

Hi Trond,

> When the sched_clock wraps every 115 s, it just
> means, I believe, than the kernel must use other
> means to schedule events further into the future.
> 115 s should typically be sufficient for driver
> related tasks.

The 32-bit wrap around logic should be taken care of vs the monotonic time correctly. This monotonic time should be actually 64 bits.

It could be something about the hardware. And perhaps some quirks that we are not aware of.

Quote
https://www.kernel.org/doc/Documentation/timers/timekeeping.txt

When the wall-clock accuracy of the clock source isn't satisfactory, there
are various quirks and layers in the timekeeping code for e.g. synchronizing
the user-visible time to RTC clocks in the system or against networked time
servers using NTP, but all they do basically is update an offset against
the clock source, which provides the fundamental timeline for the system.
These measures does not affect the clock source per se, they only adapt the
system to the shortcomings of it.

-bodhi
===========================
Forum Wiki
bodhi's corner