tme
Time is lagging substantially on Netgear ReadyNAS RN102 and RN104
January 09, 2023 04:38AM
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
Re: Time is lagging substantially on Netgear ReadyNAS RN102 and RN104
January 09, 2023 03:09PM
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 (buy bodhi a beer)
tme
Re: Time is lagging substantially on Netgear ReadyNAS RN102 and RN104
January 10, 2023 01:16AM
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
tme
Re: Time is lagging substantially on Netgear ReadyNAS RN102 and RN104
January 10, 2023 02:18PM
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
Re: Time is lagging substantially on Netgear ReadyNAS RN102 and RN104
January 10, 2023 03:31PM
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 (buy bodhi a beer)
tme
Re: Time is lagging substantially on Netgear ReadyNAS RN102 and RN104
January 13, 2023 12:10PM
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
Attachments:
open | download - dmesg.lst (27.4 KB)
Re: Time is lagging substantially on Netgear ReadyNAS RN102 and RN104
January 13, 2023 02:48PM
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 (buy bodhi a beer)
tme
Re: Time is lagging substantially on Netgear ReadyNAS RN102 and RN104
January 14, 2023 04:23AM
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
Re: Time is lagging substantially on Netgear ReadyNAS RN102 and RN104
January 14, 2023 06:17PM
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 (buy bodhi a beer)
Re: Time is lagging substantially on Netgear ReadyNAS RN102 and RN104
January 14, 2023 08:48PM
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 (buy bodhi a beer)
Attachments:
open | download - armada-370-netgear-rn102.dtb (14.7 KB)
open | download - armada-370-netgear-rn104.dtb (15.3 KB)
tme
Re: Time is lagging substantially on Netgear ReadyNAS RN102 and RN104
January 15, 2023 02:42AM
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
Attachments:
open | download - 2023-01-15-rn104-serial-console-boot.log (48.8 KB)
Re: Time is lagging substantially on Netgear ReadyNAS RN102 and RN104
January 15, 2023 02:59PM
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 (buy bodhi a beer)
Re: Time is lagging substantially on Netgear ReadyNAS RN102 and RN104
January 18, 2023 01:05AM
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 (buy bodhi a beer)



Edited 1 time(s). Last edit at 01/18/2023 01:09AM by bodhi.
tme
Re: Time is lagging substantially on Netgear ReadyNAS RN102 and RN104
January 18, 2023 01:29AM
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
Re: Time is lagging substantially on Netgear ReadyNAS RN102 and RN104
January 18, 2023 06:49PM
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 (buy bodhi a beer)
tme
Re: Time is lagging substantially on Netgear ReadyNAS RN102 and RN104
January 20, 2023 02:57AM
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
Re: Time is lagging substantially on Netgear ReadyNAS RN102 and RN104
January 21, 2023 01:26AM
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 (buy bodhi a beer)
tme
Re: Time is lagging substantially on Netgear ReadyNAS RN102 and RN104
January 22, 2023 02:09PM
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
Re: Time is lagging substantially on Netgear ReadyNAS RN102 and RN104
January 22, 2023 05:38PM
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 (buy bodhi a beer)
tme
Re: Time is lagging substantially on Netgear ReadyNAS RN102 and RN104
February 25, 2023 04:17AM
Thanks bodhi,

for powering up your Mirabox and for running the 'urandom' test!

To me it seems that the RN102 CPU and its free running timer run at the same speed as on the Mirabox. My hypothesis now is that the RN102 system clock is updated by timer interrupts from the free running timer (Timer 0) at regular intervals, and that about 1 out of 12 interrupts are missed, alternatively handled wrongly, causing RN102's time lagging issue.

From your observations, it's clear that:
  1. The Mirabox does not have the Linux system time lagging issue.
  2. The boxes must have different SOCs.

Info Depot Wiki supports the second point:

The two SOCs have different build-in I/O peripherals. From the document "88F6710, 88F6707, and 88F6W11 ARMADA ® 370 SoC Functional Specifications – Unrestricted", page 29:

Quote

The advanced I/O peripherals for these devices include:
  • 88F6710: PCI Express (PCIe) Gen2.0, USB 2.0 with integrated PHY, SATA II ports, Ethernet,
    I2S, S/PDIF, TDM, and device bus interfaces
  • 88F6707: PCI Express (PCIe) Gen2.0, USB 2.0 with integrated PHY, SATA II ports, Ethernet,
    and SDIO interfaces

I2S is Integrated Interchip Sound audio in/out interface, S/PDIF is Sony/Philips Digital Interconnect Format interface and TDM is Time Division Multiplexing Interface. The device bus interface controller is described on page 39:

Quote

The Device Bus Controller is only supported by the 88F6710 and 88F6W11.

The device bus controller supports different types of memory and I/O devices such as Flash, ROM, or an application-specific Field Programmable Gate Array (FPGA). It supports flexible timing parameters that enable accesses to slow asynchronous devices.

The device bus controller also supports a glue-less interface to NOR Flash devices on any of its 5 physical ranks. Each rank can be address mapped up to 512 MB.

The 88F6W11 and 88F6710 support an 8/16-bit multiplexed address/data interface, and provides up to 8 data beats per access.

Presumably, the missed timer interrupts are caused by missing or bad initialization of any of the 88F6710's three extra I/O peripherals or its device bus interface. These must all be properly initialized or disabled, either by modifying the device tree or by patching the kernel code. Hints are welcome.

Assuming both boxes boot at the same speed, the system clock on RN102 starts lagging from the moment it is started and lags consistently at about 8% for the first 159 ms of the boot (Mirabox time). I would like to boot my RN102 with the Mirabox device tree and compare the reported progress with that of the Mirabox. @bodhi, can you please share the first 2 seconds of your 'linux-6.1.8-mvebu-370xp-tld-1' Mirabox boot log?

Finally, both 88F6710 and 88F6707 have a "Security Engine" which I believe speeds up the generation of random numbers. I suspect this functionality is disabled in the Mirabox, causing its inferior performance in the 'urandom' test.

Regards,
Trond Melen
Re: Time is lagging substantially on Netgear ReadyNAS RN102 and RN104
February 25, 2023 03:12PM
Hi Trond,

Here is 5 second boot log.

[    0.000000][    T0] Booting Linux on physical CPU 0x0
[    0.000000][    T0] Linux version 6.1.8-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 Tue Jan 24 23:39:41 PST 2023
[    0.000000][    T0] CPU: ARMv7 Processor [561f5811] revision 1 (ARMv7), cr=10c5387d
[    0.000000][    T0] CPU: PIPT / VIPT nonaliasing data cache, PIPT instruction cache
[    0.000000][    T0] OF: fdt: Machine model: Globalscale Mirabox
[    0.000000][    T0] printk: bootconsole [earlycon0] enabled
[    0.000000][    T0] Memory policy: Data cache writeback
[    0.000000][    T0] Zone ranges:
[    0.000000][    T0]   Normal   [mem 0x0000000000000000-0x000000002fffffff]
[    0.000000][    T0]   HighMem  [mem 0x0000000030000000-0x000000003fffffff]
[    0.000000][    T0] Movable zone start for each node
[    0.000000][    T0] Early memory node ranges
[    0.000000][    T0]   node   0: [mem 0x0000000000000000-0x000000003fffffff]
[    0.000000][    T0] Initmem setup node 0 [mem 0x0000000000000000-0x000000003fffffff]
[    0.000000][    T0] CPU: All CPU(s) started in SVC mode.
[    0.000000][    T0] Built 1 zonelists, mobility grouping on.  Total pages: 260416
[    0.000000][    T0] Kernel command line: console=ttyS0,115200 root=LABEL=rootfs rootdelay=10 mtdparts=pxa3xx_nand-0:4M(u-boot),4M(linux),-(filesystem) earlyprintk=serial
[    0.000000][    T0] Dentry cache hash table entries: 131072 (order: 7, 524288 bytes, linear)
[    0.000000][    T0] Inode-cache hash table entries: 65536 (order: 6, 262144 bytes, linear)
[    0.000000][    T0] mem auto-init: stack:off, heap alloc:on, heap free:off
[    0.000000][    T0] Memory: 1007460K/1048576K available (10240K kernel code, 1525K rwdata, 3408K rodata, 1024K init, 474K bss, 41116K reserved, 0K cma-reserved, 262144K highmem)
[    0.000000][    T0] trace event string verifier disabled
[    0.000000][    T0] rcu: Preemptible hierarchical RCU implementation.
[    0.000000][    T0] 	Trampoline variant of Tasks RCU enabled.
[    0.000000][    T0] 	Tracing variant of Tasks RCU enabled.
[    0.000000][    T0] rcu: RCU calculated value of scheduler-enlistment delay is 10 jiffies.
[    0.000000][    T0] NR_IRQS: 16, nr_irqs: 16, preallocated irqs: 16
[    0.000000][    T0] L2C: DT/platform modifies aux control register: 0x12086300 -> 0x1a086302
[    0.000000][    T0] Aurora cache controller enabled, 4 ways, 256 kB
[    0.000000][    T0] Aurora: CACHE_ID 0x00000100, AUX_CTRL 0x1a086302
[    0.000000][    T0] rcu: srcu_init: Setting srcu_struct sizes based on contention.
[    0.000000][    T0] Switching to timer-based delay loop, resolution 53ns
[    0.000001][    T0] sched_clock: 32 bits at 19MHz, resolution 53ns, wraps every 114840871909ns
[    0.008586][    T0] clocksource: armada_370_xp_clocksource: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 102208375848 ns
[    0.020881][    T0] kfence: initialized - using 2097152 bytes for 255 objects at 0x(ptrval)-0x(ptrval)
[    0.030895][    T0] Console: colour dummy device 80x30
[    0.036050][    T0] Calibrating delay loop (skipped), value calculated using timer frequency.. 37.39 BogoMIPS (lpj=186996)
[    0.047066][    T0] pid_max: default: 32768 minimum: 301
[    0.052747][    T0] LSM: Security Framework initializing
[    0.058216][    T0] Mount-cache hash table entries: 2048 (order: 1, 8192 bytes, linear)
[    0.066219][    T0] Mountpoint-cache hash table entries: 2048 (order: 1, 8192 bytes, linear)
[    0.075789][    T0] CPU: Testing write buffer coherency: ok
[    0.082773][    T1] cblist_init_generic: Setting adjustable number of callback queues.
[    0.090707][    T1] cblist_init_generic: Setting shift to 0 and lim to 1.
[    0.097603][    T1] cblist_init_generic: Setting shift to 0 and lim to 1.
[    0.104550][    T1] Setting up static identity map for 0x100000 - 0x100060
[    0.111775][    T1] mvebu-soc-id: MVEBU SoC ID=0x6710, Rev=0x1
[    0.117697][    T1] mvebu-pmsu: Initializing Power Management Service Unit
[    0.124764][    T1] rcu: Hierarchical SRCU implementation.
[    0.130257][    T1] rcu: 	Max phase no-delay instances is 1000.
[    0.137360][    T1] devtmpfs: initialized
[    0.146107][    T1] VFP support v0.3: implementor 56 architecture 2 part 20 variant 9 rev 6
[    0.154874][    T1] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 19112604462750000 ns
[    0.165388][    T1] futex hash table entries: 256 (order: -1, 3072 bytes, linear)
[    0.173057][    T1] prandom: seed boundary self test passed
[    0.181138][    T1] prandom: 100 self tests passed
[    0.185911][    T1] pinctrl core: initialized pinctrl subsystem
[    0.193546][    T1] NET: Registered PF_NETLINK/PF_ROUTE protocol family
[    0.200811][    T1] DMA: preallocated 256 KiB pool for atomic coherent allocations
[    0.209119][    T1] audit: initializing netlink subsys (disabled)
[    0.216214][    T1] thermal_sys: Registered thermal governor 'step_wise'
[    0.216409][   T17] audit: type=2000 audit(0.190:1): state=initialized audit_enabled=0 res=1
[    0.231578][    T1] cpuidle: using governor ladder
[    0.236381][    T1] cpuidle: using governor menu
[    0.241172][    T1] hw-breakpoint: debug architecture 0x4 unsupported.
[    0.247770][    T1] mvebu-pmsu: CPU idle is currently broken: disabling
[    0.630222][    T1] raid6: int32x8  gen()   211 MB/s
[    0.970219][    T1] raid6: int32x4  gen()   232 MB/s
[    1.310235][    T1] raid6: int32x2  gen()   359 MB/s
[    1.650217][    T1] raid6: int32x1  gen()   407 MB/s
[    1.655169][    T1] raid6: using algorithm int32x1 gen() 407 MB/s
[    2.020218][    T1] raid6: .... xor() 170 MB/s, rmw enabled
[    2.025775][    T1] raid6: using intx1 recovery algorithm
[    2.041497][    T1] SCSI subsystem initialized
[    2.050630][    T1] usbcore: registered new interface driver usbfs
[    2.056867][    T1] usbcore: registered new interface driver hub
[    2.080367][    T1] usbcore: registered new device driver usb
[    2.086491][    T1] pps_core: LinuxPPS API ver. 1 registered
[    2.100246][    T1] pps_core: Software ver. 5.3.6 - Copyright 2005-2007 Rodolfo Giometti <giometti@linux.it>
[    2.110064][    T1] PTP clock support registered
[    2.131838][    T1] vgaarb: loaded
[    2.135843][    T1] clocksource: Switched to clocksource armada_370_xp_clocksource
[    2.156748][    T1] VFS: Disk quotas dquot_6.6.0
[    2.161414][    T1] VFS: Dquot-cache hash table entries: 1024 (order 0, 4096 bytes)
[    2.197968][    T1] NET: Registered PF_INET protocol family
[    2.215986][    T1] IP idents hash table entries: 16384 (order: 5, 131072 bytes, linear)
[    2.236278][    T1] tcp_listen_portaddr_hash hash table entries: 1024 (order: 0, 4096 bytes, linear)
[    2.245537][    T1] Table-perturb hash table entries: 65536 (order: 6, 262144 bytes, linear)
[    2.265887][    T1] TCP established hash table entries: 8192 (order: 3, 32768 bytes, linear)
[    2.274370][    T1] TCP bind hash table entries: 8192 (order: 4, 65536 bytes, linear)
[    2.296056][    T1] TCP: Hash tables configured (established 8192 bind 8192)
[    2.303412][    T1] MPTCP token hash table entries: 1024 (order: 1, 12288 bytes, linear)
[    2.335927][    T1] UDP hash table entries: 512 (order: 1, 8192 bytes, linear)
[    2.343146][    T1] UDP-Lite hash table entries: 512 (order: 1, 8192 bytes, linear)
[    2.366110][    T1] NET: Registered PF_UNIX/PF_LOCAL protocol family
[    2.373159][    T1] RPC: Registered named UNIX socket transport module.
[    2.385858][    T1] RPC: Registered udp transport module.
[    2.391238][    T1] RPC: Registered tcp transport module.
[    2.405877][    T1] RPC: Registered tcp NFSv4.1 backchannel transport module.
[    2.412991][    T1] PCI: CLS 0 bytes, default 64
[    2.436255][   T31] Trying to unpack rootfs image as initramfs...
[    2.446076][    T1] NetWinder Floating Point Emulator V0.97 (double precision)
[    2.453570][    T1] hw perfevents: enabled with armv7_cortex_a9 PMU driver, 7 counters available
[    2.615497][    T1] Initialise system trusted keyrings
[    2.626197][    T1] Key type blacklist registered
[    2.636086][    T1] workingset: timestamp_bits=14 max_order=18 bucket_order=4
[    2.643293][    T1] zbud: loaded
[    2.667842][    T1] NFS: Registering the id_resolver key type
[    2.673621][    T1] Key type id_resolver registered
[    2.685936][    T1] Key type id_legacy registered
[    2.690734][    T1] nfs4filelayout_init: NFSv4 File Layout Driver Registering...
[    2.705958][    T1] nfs4flexfilelayout_init: NFSv4 Flexfile Layout Driver Registering...
[    2.868523][    T1] xor: measuring software checksum speed
[    2.895946][    T1]    arm4regs        :  1145 MB/sec
[    2.915940][    T1]    8regs           :   961 MB/sec
[    2.946002][    T1]    32regs          :  1111 MB/sec
[    2.951061][    T1] xor: using function: arm4regs (1145 MB/sec)
[    2.965947][    T1] async_tx: api initialized (async)
[    2.971010][    T1] Key type asymmetric registered
[    2.975782][    T1] Asymmetric key parser 'x509' registered
[    3.413529][   T31] Freeing initrd memory: 11564K
[    3.452896][    T1] alg: self-tests for CTR-KDF (hmac(sha256)) passed
[    3.460053][    T1] bounce: pool size: 64 pages
[    3.465180][    T1] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 245)
[    3.473828][    T1] io scheduler bfq registered
[    3.481345][    T1] armada-370-pinctrl d0018000.pin-ctrl: registered pinctrl driver
[    3.495246][    T1] debugfs: Directory 'd0018100.gpio' with parent 'regmap' already present!
[    3.507544][    T1] debugfs: Directory 'd0018140.gpio' with parent 'regmap' already present!
[    3.520099][    T1] mvebu-pcie soc:pcie@82000000: host bridge /soc/pcie@82000000 ranges:
[    3.530731][    T1] mvebu-pcie soc:pcie@82000000:      MEM 0x00d0040000..0x00d0041fff -> 0x0000040000
[    3.540162][    T1] mvebu-pcie soc:pcie@82000000:      MEM 0x00d0080000..0x00d0081fff -> 0x0000080000
[    3.549561][    T1] mvebu-pcie soc:pcie@82000000:      MEM 0xffffffffffffffff..0x00fffffffe -> 0x0100000000
[    3.559332][    T1] mvebu-pcie soc:pcie@82000000:       IO 0xffffffffffffffff..0x00fffffffe -> 0x0100000000
[    3.569082][    T1] mvebu-pcie soc:pcie@82000000:      MEM 0xffffffffffffffff..0x00fffffffe -> 0x0200000000
[    3.578808][    T1] mvebu-pcie soc:pcie@82000000:       IO 0xffffffffffffffff..0x00fffffffe -> 0x0200000000
[    3.589269][    T1] mvebu-pcie soc:pcie@82000000: PCI host bridge to bus 0000:00
[    3.597010][    T1] pci_bus 0000:00: root bus resource [bus 00-ff]
[    3.603183][    T1] pci_bus 0000:00: root bus resource [mem 0xd0040000-0xd0041fff] (bus address [0x00040000-0x00041fff])
[    3.614115][    T1] pci_bus 0000:00: root bus resource [mem 0xd0080000-0xd0081fff] (bus address [0x00080000-0x00081fff])
[    3.625089][    T1] pci_bus 0000:00: root bus resource [mem 0xf8000000-0xffdfffff]
[    3.632687][    T1] pci_bus 0000:00: root bus resource [io  0x1000-0xeffff]
[    3.639808][    T1] pci 0000:00:01.0: [11ab:6710] type 01 class 0x060400
[    3.647111][    T1] pci 0000:00:02.0: [11ab:6710] type 01 class 0x060400
[    3.655741][    T1] PCI: bus0: Fast back to back transfers disabled
[    3.662089][    T1] pci 0000:00:01.0: bridge configuration invalid ([bus 00-00]), reconfiguring
[    3.670826][    T1] pci 0000:00:02.0: bridge configuration invalid ([bus 00-00]), reconfiguring
[    3.679924][    T1] PCI: bus1: Fast back to back transfers enabled
[    3.686469][    T1] pci_bus 0000:01: busn_res: [bus 01-ff] end is updated to 01
[    3.694469][    T1] pci 0000:02:00.0: [1b73:1009] type 00 class 0x0c0330
[    3.701294][    T1] pci 0000:02:00.0: reg 0x10: [mem 0x42000000-0x4200ffff 64bit]
[    3.708818][    T1] pci 0000:02:00.0: reg 0x18: [mem 0x42010000-0x42010fff 64bit]
[    3.716342][    T1] pci 0000:02:00.0: reg 0x20: [mem 0x42011000-0x42011fff 64bit]
[    3.723901][    T1] pci 0000:02:00.0: supports D1
[    3.728661][    T1] pci 0000:02:00.0: PME# supported from D0 D1 D3hot
[    3.735220][    T1] pci 0000:02:00.0: 2.000 Gb/s available PCIe bandwidth, limited by 2.5 GT/s PCIe x1 link at 0000:00:02.0 (capable of 4.000 Gb/s with 5.0 GT/s PCIe x1 link)
[    3.775947][    T1] PCI: bus2: Fast back to back transfers disabled
[    3.782208][    T1] pci_bus 0000:02: busn_res: [bus 02-ff] end is updated to 02
[    3.789580][    T1] pci 0000:00:02.0: BAR 14: assigned [mem 0xf8000000-0xf80fffff]
[    3.797165][    T1] pci 0000:00:01.0: PCI bridge to [bus 01]
[    3.802857][    T1] pci 0000:02:00.0: BAR 0: assigned [mem 0xf8000000-0xf800ffff 64bit]
[    3.810872][    T1] pci 0000:02:00.0: BAR 2: assigned [mem 0xf8010000-0xf8010fff 64bit]
[    3.818871][    T1] pci 0000:02:00.0: BAR 4: assigned [mem 0xf8011000-0xf8011fff 64bit]
[    3.826867][    T1] pci 0000:00:02.0: PCI bridge to [bus 02]
[    3.832510][    T1] pci 0000:00:02.0:   bridge window [mem 0xf8000000-0xf80fffff]
[    3.840376][    T1] pcieport 0000:00:02.0: enabling device (0140 -> 0142)
[    3.848384][    T1] mv_xor d0060800.xor: Marvell shared XOR driver
[    3.917099][    T1] mv_xor d0060800.xor: Marvell XOR (Registers Mode): ( xor cpy intr )
[    3.928818][    T1] mv_xor d0060900.xor: Marvell shared XOR driver
[    3.997296][    T1] mv_xor d0060900.xor: Marvell XOR (Registers Mode): ( xor cpy intr )
[    4.283184][    T1] Serial: 8250/16550 driver, 4 ports, IRQ sharing disabled
[    4.297265][    T1] printk: console [ttyS0] disabled
[    4.326127][    T1] d0012000.serial: ttyS0 at MMIO 0xd0012000 (irq = 31, base_baud = 12500000) is a 16550A
[    4.335828][    T1] printk: console [ttyS0] enabled
[    4.335828][    T1] printk: console [ttyS0] enabled
[    4.345706][    T1] printk: bootconsole [earlycon0] disabled
[    4.345706][    T1] printk: bootconsole [earlycon0] disabled
[    4.365490][    T1] nand: device found, Manufacturer ID: 0x2c, Chip ID: 0x38
[    4.372809][    T1] nand: Micron MT29F8G08ABABAWP
[    4.377810][    T1] nand: 1024 MiB, SLC, erase size: 512 KiB, page size: 4096, OOB size: 224
[    4.387414][    T1] Bad block table found at page 262016, version 0x01
[    4.394729][    T1] Bad block table found at page 261888, version 0x01
[    4.401873][    T1] 3 cmdlinepart partitions found on MTD device pxa3xx_nand-0
[    4.409195][    T1] Creating 3 MTD partitions on "pxa3xx_nand-0":
[    4.415329][    T1] 0x000000000000-0x000000400000 : "u-boot"
[    4.423252][    T1] 0x000000400000-0x000000800000 : "linux"
[    4.432393][    T1] 0x000000800000-0x000040000000 : "filesystem"
[    4.444128][    T1] wireguard: WireGuard 1.0.0 loaded. See www.wireguard.com for information.
[    4.455334][    T1] wireguard: Copyright (C) 2015-2019 Jason A. Donenfeld <Jason@zx2c4.com>. All Rights Reserved.
[    4.500630][    T1] hwmon hwmon0: temp1_input not attached to any thermal zone
[    4.524386][    T1] hwmon hwmon1: temp1_input not attached to any thermal zone
[    4.537480][    T1] mvneta d0070000.ethernet eth0: Using random mac address 9a:14:70:be:f2:c1
[    4.551910][    T1] mvneta d0074000.ethernet eth1: Using random mac address fa:de:b9:31:9b:93
[    4.564456][    T1] orion-ehci d0050000.usb: EHCI Host Controller
[    4.572389][    T1] orion-ehci d0050000.usb: new USB bus registered, assigned bus number 1
[    4.581256][    T1] orion-ehci d0050000.usb: irq 35, io mem 0xd0050000
[    4.615866][    T1] orion-ehci d0050000.usb: USB 2.0 started, EHCI 1.00
[    4.622918][    T1] usb usb1: New USB device found, idVendor=1d6b, idProduct=0002, bcdDevice= 6.01
[    4.631961][    T1] usb usb1: New USB device strings: Mfr=3, Product=2, SerialNumber=1
[    4.639936][    T1] usb usb1: Product: EHCI Host Controller
[    4.645541][    T1] usb usb1: Manufacturer: Linux 6.1.8-mvebu-370xp-tld-1 ehci_hcd
[    4.653161][    T1] usb usb1: SerialNumber: d0050000.usb
[    4.659521][    T1] hub 1-0:1.0: USB hub found
[    4.664694][    T1] hub 1-0:1.0: 1 port detected
[    4.670492][    T1] orion-ehci d0051000.usb: EHCI Host Controller
[    4.677620][    T1] orion-ehci d0051000.usb: new USB bus registered, assigned bus number 2
[    4.686278][    T1] orion-ehci d0051000.usb: irq 36, io mem 0xd0051000
[    4.715892][    T1] orion-ehci d0051000.usb: USB 2.0 started, EHCI 1.00
[    4.722899][    T1] usb usb2: New USB device found, idVendor=1d6b, idProduct=0002, bcdDevice= 6.01
[    4.731950][    T1] usb usb2: New USB device strings: Mfr=3, Product=2, SerialNumber=1
[    4.739927][    T1] usb usb2: Product: EHCI Host Controller
[    4.745532][    T1] usb usb2: Manufacturer: Linux 6.1.8-mvebu-370xp-tld-1 ehci_hcd
[    4.753153][    T1] usb usb2: SerialNumber: d0051000.usb
[    4.759438][    T1] hub 2-0:1.0: USB hub found
[    4.764608][    T1] hub 2-0:1.0: 1 port detected
[    4.770995][    T1] usbcore: registered new interface driver usblp
[    4.779078][    T1] usbcore: registered new interface driver usb-storage
[    4.786994][    T1] mousedev: PS/2 mouse device common for all mice
[    4.797299][    T1] rtc-mv d0010300.rtc: registered as rtc0
[    4.802943][    T1] rtc-mv d0010300.rtc: setting system clock to 2023-02-25T20:08:57 UTC (1677355737)
[    4.815662][    T1] i2c_dev: i2c /dev entries driver
[    4.822316][    T1] mv64xxx_i2c d0011000.i2c: can't get pinctrl, bus recovery not supported
[    4.832416][    T1] pca953x 0-0025: supply vcc not found, using dummy regulator
[    4.841166][    T1] pca953x 0-0025: using AI
[    4.845990][    T1] pca953x 0-0025: failed writing register
[    4.877760][    T1] orion_wdt: Initial timeout 229 sec
[    4.885480][    T1] device-mapper: uevent: version 1.0.3
[    4.892031][    T1] device-mapper: ioctl: 4.47.0-ioctl (2022-07-28) initialised: dm-devel@redhat.com
[    4.902037][    T1] device-mapper: multipath round-robin: version 1.2.0 loaded
[    4.909529][    T1] device-mapper: multipath queue-length: version 0.2.0 loaded
[    4.916958][    T1] device-mapper: multipath service-time: version 0.3.0 loaded
[    4.924371][    T1] device-mapper: dm-log-userspace: version 1.3.0 loaded
[    4.931252][    T1] device-mapper: raid: Loading target version 1.15.1
[    4.943412][    T1] marvell-cesa d0090000.crypto: CESA device successfully registered
[    4.951978][    T1] hid: raw HID events driver (C) Jiri Kosina
[    4.957910][   T60] usb 1-1: new high-speed USB device number 2 using orion-ehci
[    4.967649][    T1] usbcore: registered new interface driver usbhid
[    4.974005][    T1] usbhid: USB HID core driver
[    4.980238][    T1] drop_monitor: Initializing network drop monitor service
[    4.988613][    T1] NET: Registered PF_INET6 protocol family
[    4.996129][    T1] Segment Routing with IPv6
[    5.000526][    T1] RPL Segment Routing with IPv6
[    5.005304][    T1] In-situ OAM (IOAM) with IPv6
[    5.010178][    T1] sit: IPv6, IPv4 and MPLS over IPv4 tunneling driver
[    5.019118][    T1] NET: Registered PF_PACKET protocol family
[    5.026336][    T1] 8021q: 802.1Q VLAN Support v1.8
[    5.031355][    T1] Key type dns_resolver registered
[    5.036607][    T1] ThumbEE CPU extension supported.
[    5.041612][    T1] Registering SWP/SWPB emulation handler
[    5.048184][    T1] registered taskstats version 1
[    5.053030][    T1] Loading compiled-in X.509 certificates
[    5.059553][    T1] zswap: loaded using pool lzo/zbud
[    5.065177][    T1] Key type .fscrypt registered
[    5.069923][    T1] Key type fscrypt-provisioning registered
[    5.075734][    T1] Key type big_key registered
[    5.109647][    T1] Key type encrypted registered
[    5.127590][    T1] Freeing unused kernel image (initmem) memory: 1024K
[    5.138147][    T1] Checked W+X mappings: passed, no W+X pages found
[    5.144569][    T1] Run /init as init process

Attached are the new DTB and the patch to the original RN102 DTS for linux-6.1.8-mvebu-tld-1.

There is an unknown pin for the spdif (we can find out from either GPL source or Reference Manual). That pin is set to 51 right now (as copied from Armada 385), and it is probably incorrect.

-bodhi
===========================
Forum Wiki
bodhi's corner (buy bodhi a beer)
Attachments:
open | download - armada-370-netgear-rn102.dtb (15.3 KB)
open | download - armada-370-netgear-rn102.dts.patch (1.1 KB)
tme
Re: Time is lagging substantially on Netgear ReadyNAS RN102 and RN104
February 26, 2023 01:18PM
Thanks for the boot log bodhi,

As expected, booting my RN102 with a device tree for Mirabox fails, but only after 4.7 seconds:
[    4.693689][    T1] mdio_bus d0072004.mdio-mii: MDIO device at address 1 is missing.
The full boot log is attached.

Before that, there is a one-to-one correspondence between the RN102 and Mirabox boot log messages with just two exceptions:
[    0.000000][    T0] Unknown kernel command line parameters "reason=normal bdtype=rn102", will be passed to user space.
[    3.460053][    T1] bounce: pool size: 64 pages

Attached a plot showing the RN102 clock lag during the first few seconds. The red points are the 'clocksource' messages. The Octave/Matlab script 'ratio.m' generating the plot was created with the following commands:
$ wc -l mira.lst rn102.lst
  258 mira.lst
  223 rn102.lst
  481 total

$ head -146 mira.lst | grep -v 'bounce: pool size: 64 pages' | cut -c -14 > mira-clock.lst

$ head -146 rn102.lst | grep -v 'Unknown kernel command line parameters' | paste  mira-clock.lst - | sed 's/\]\t\[/\]\[/' > merged.lst

$ ( echo t=[; cut -c -28 merged.lst| grep -v 0.00000 | tr '[]' ' ' ; echo ]\'\; ; echo 'r=t(2,:)./t(1,:); cse=[1 20 49]; plot(t(1,:),r,"b+-",t(1,cse),r(cse),"rx"); grid on; title("Lagging of boot messages on RN102"); xlabel("Time [s]"); ylabel("Ratio");' ) > ratio.m

Up next is inspecting the kernel source code, I guess.

Regards,
Trond Melen
Attachments:
open | download - rn102.lst (17 KB)
open | download - Screenshot from 2023-02-26 19-42-41.png (13.4 KB)
tme
Re: Time is lagging substantially on Netgear ReadyNAS RN102 and RN104
March 19, 2023 03:44PM
Hi bodhi,

Quote

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

I installed the device tree compiler on a Netgear RN102 with you latest kernel and root file system and converted its dtb-file to dts format. There where 23 warnings:
$ sudo apt-get install device-tree-compiler

$ sudo dtc -I dtb -O dts /boot/dts/armada-370-netgear-rn102.dtb -o /dev/null

/dev/null: Warning (unit_address_vs_reg): /soc: node has a reg or ranges property, but no unit name
/dev/null: Warning (unit_address_vs_reg): /soc/devbus-bootcs: node has a reg or ranges property, but no unit name
/dev/null: Warning (unit_address_vs_reg): /soc/devbus-cs0: node has a reg or ranges property, but no unit name
/dev/null: Warning (unit_address_vs_reg): /soc/devbus-cs1: node has a reg or ranges property, but no unit name
/dev/null: Warning (unit_address_vs_reg): /soc/devbus-cs2: node has a reg or ranges property, but no unit name
/dev/null: Warning (unit_address_vs_reg): /soc/devbus-cs3: node has a reg or ranges property, but no unit name
/dev/null: Warning (unit_address_vs_reg): /soc/internal-regs: node has a reg or ranges property, but no unit name
/dev/null: Warning (unit_address_vs_reg): /soc/bootrom: node has a reg or ranges property, but no unit name
/dev/null: Warning (unit_address_vs_reg): /soc/sa-sram: node has a reg or ranges property, but no unit name
/dev/null: Warning (pci_device_reg): /soc/pcie@82000000/pcie@1,0/interrupt-controller: missing PCI reg property
/dev/null: Warning (pci_device_reg): /soc/pcie@82000000/pcie@2,0/interrupt-controller: missing PCI reg property
/dev/null: Warning (simple_bus_reg): /soc/devbus-bootcs: simple-bus unit address format error, expected "f001000000010400"
/dev/null: Warning (simple_bus_reg): /soc/devbus-cs0: simple-bus unit address format error, expected "f001000000010408"
/dev/null: Warning (simple_bus_reg): /soc/devbus-cs1: simple-bus unit address format error, expected "f001000000010410"
/dev/null: Warning (simple_bus_reg): /soc/devbus-cs2: simple-bus unit address format error, expected "f001000000010418"
/dev/null: Warning (simple_bus_reg): /soc/devbus-cs3: simple-bus unit address format error, expected "f001000000010420"
/dev/null: Warning (simple_bus_reg): /soc/internal-regs: simple-bus unit address format error, expected "f001000000000000"
/dev/null: Warning (simple_bus_reg): /soc/spi@10600: simple-bus unit address format error, expected "f001000000010600"
/dev/null: Warning (simple_bus_reg): /soc/spi@10680: simple-bus unit address format error, expected "f001000000010680"
/dev/null: Warning (simple_bus_reg): /soc/bootrom: simple-bus unit address format error, expected "1e0000000000000"
/dev/null: Warning (simple_bus_reg): /soc/pcie@82000000: simple-bus unit address format error, expected "f001000000040000"
/dev/null: Warning (simple_bus_reg): /soc/sa-sram: simple-bus unit address format error, expected "901000000000000"
/dev/null: Warning (unique_unit_address): /soc/internal-regs/timer@20300: duplicate unit-address (also used in node /soc/internal-regs/watchdog@20300)

The last warning looks ugly to me. The input file 'armada-370-mirabox.dtb' gives the same warning, but it may be more severe on the RN102 since it has an external Intersil ISL12057 RTC on the I2C bus to wake it up after a power loss. Do you think the warnings can all safely be ignored?

Regards,
Trond Melen
Re: Time is lagging substantially on Netgear ReadyNAS RN102 and RN104
March 19, 2023 07:02PM
Hi Trond,

> The last warning looks ugly to me. The input file
> 'armada-370-mirabox.dtb' gives the same warning,
> but it may be more severe on the RN102 since it
> has an external Intersil ISL12057 RTC on the I2C
> bus to wake it up after a power loss. Do you think
> the warnings can all safely be ignored?


/dev/null: Warning (simple_bus_reg): /soc/devbus-bootcs: simple-bus unit address format error, expected "f001000000010400"
/dev/null: Warning (simple_bus_reg): /soc/devbus-cs0: simple-bus unit address format error, expected "f001000000010408"
/dev/null: Warning (simple_bus_reg): /soc/devbus-cs1: simple-bus unit address format error, expected "f001000000010410"
/dev/null: Warning (simple_bus_reg): /soc/devbus-cs2: simple-bus unit address format error, expected "f001000000010418"
/dev/null: Warning (simple_bus_reg): /soc/devbus-cs3: simple-bus unit address format error, expected "f001000000010420"
/dev/null: Warning (simple_bus_reg): /soc/internal-regs: simple-bus unit address format error, expected "f001000000000000"
/dev/null: Warning (simple_bus_reg): /soc/spi@10600: simple-bus unit address format error, expected "f001000000010600"
/dev/null: Warning (simple_bus_reg): /soc/spi@10680: simple-bus unit address format error, expected "f001000000010680"
/dev/null: Warning (simple_bus_reg): /soc/bootrom: simple-bus unit address format error, expected "1e0000000000000"
/dev/null: Warning (simple_bus_reg): /soc/pcie@82000000: simple-bus unit address format error, expected "f001000000040000"
/dev/null: Warning (simple_bus_reg): /soc/sa-sram: simple-bus unit address format error, expected "901000000000000"

The above can be safely ignores. The DTS binding changed lately to use only number, no leading 0's. But it will work.

/dev/null: Warning (unit_address_vs_reg): /soc: node has a reg or ranges property, but no unit name
/dev/null: Warning (unit_address_vs_reg): /soc/devbus-bootcs: node has a reg or ranges property, but no unit name
/dev/null: Warning (unit_address_vs_reg): /soc/devbus-cs0: node has a reg or ranges property, but no unit name
/dev/null: Warning (unit_address_vs_reg): /soc/devbus-cs1: node has a reg or ranges property, but no unit name
/dev/null: Warning (unit_address_vs_reg): /soc/devbus-cs2: node has a reg or ranges property, but no unit name
/dev/null: Warning (unit_address_vs_reg): /soc/devbus-cs3: node has a reg or ranges property, but no unit name
/dev/null: Warning (unit_address_vs_reg): /soc/internal-regs: node has a reg or ranges property, but no unit name
/dev/null: Warning (unit_address_vs_reg): /soc/bootrom: node has a reg or ranges property, but no unit name
/dev/null: Warning (unit_address_vs_reg): /soc/sa-sram: node has a reg or ranges property, but no unit name

The above can be safely ignores (the DTS binding changed).

/dev/null: Warning (pci_device_reg): /soc/pcie@82000000/pcie@1,0/interrupt-controller: missing PCI reg property
/dev/null: Warning (pci_device_reg): /soc/pcie@82000000/pcie@2,0/interrupt-controller: missing PCI reg property
The above can be safely ignores. They look bad, but the 2xUSB 3.0 ports are working on Mirabox, and they are on PCIe bus.

However, we need to modernize the DTS for both boxes to avoid seeing the warnings, and eliminate unknowns.

-bodhi
===========================
Forum Wiki
bodhi's corner (buy bodhi a beer)
Re: Time is lagging substantially on Netgear ReadyNAS RN102 and RN104
March 19, 2023 07:05PM
/dev/null: Warning (unique_unit_address): /soc/internal-regs/timer@20300: duplicate unit-address (also used in node /soc/internal-regs/watchdog@20300)

This one is bad. We should fix it.

One thing I have not done is to turn on detailed warning on the DTS compilation while building kernel. I think I'll put the warning option back in.

-bodhi
===========================
Forum Wiki
bodhi's corner (buy bodhi a beer)
Re: Time is lagging substantially on Netgear ReadyNAS RN102 and RN104
March 24, 2023 03:12PM
>
> /dev/null: Warning (unique_unit_address):
> /soc/internal-regs/timer@20300: duplicate
> unit-address (also used in node
> /soc/internal-regs/watchdog@20300)
>
>
> This one is bad. We should fix it.

Actually it is OK. That's how it was coded in the armada-370-xp.dtsi.

-bodhi
===========================
Forum Wiki
bodhi's corner (buy bodhi a beer)
tme
Re: Time is lagging substantially on Netgear ReadyNAS RN102 and RN104
March 31, 2023 02:57PM
Hi bodhi,

I would like to check if the time lagging issue has been around for a long time, or if has been introduced more recently. Without success, I tried to boot the kernel in 'Debian-5.2.9-mvebu-tld-1-rootfs-bodhi.tar.bz2'. I assume it lacks support for 370xp?

As you know, the file ' Linux-5.8.5-mvebu-370xp-tld-1-bodhi.tar.bz2' has been purged from your dropbox. Is there some other outdated kernel I can try?

Regards,
Trond Melen
Re: Time is lagging substantially on Netgear ReadyNAS RN102 and RN104
March 31, 2023 03:28PM
Hi Trond,

Quote

I would like to check if the time lagging issue has been around for a long time, or if has been introduced more recently. Without success, I tried to boot the kernel in 'Debian-5.2.9-mvebu-tld-1-rootfs-bodhi.tar.bz2'. I assume it lacks support for 370xp?

Correct. Debian-5.2.9-mvebu-tld-1-rootfs-bodhi.tar.bz2 has normal MVEBU kernel. It does not have the linux*mvebu-370xp* kernel installed.

Quote

As you know, the file ' Linux-5.8.5-mvebu-370xp-tld-1-bodhi.tar.bz2' has been purged from your dropbox. Is there some other outdated kernel I can try?

Yes I see that it was no longer there. I cleaned up my Dropbox to free up space, and left only versions matching LTS kernels, or some I think interesting.

The oldest kernel for Mirabox, which should boot the RN102 with RN102 DTB:
linux-4.20.6-mvebu-mirabox-tld-12-bodhi.tar.bz2

The old kernels are slower. It might help to see if there is any lag, but should not be used as is. We'll talk about this after your tests.

Let me re-upload both kernels Linux-5.8.5-mvebu-370xp-tld-1-bodhi.tar.bz2 and linux-4.20.6-mvebu-mirabox-tld-12-bodhi.tar.bz2 to Dropbox.

If 5.8.5 run without lags, I can re-upload later versions for linux*mvebu-370xp* for you to try.

-bodhi
===========================
Forum Wiki
bodhi's corner (buy bodhi a beer)
Re: Time is lagging substantially on Netgear ReadyNAS RN102 and RN104
March 31, 2023 04:44PM
Here are the Dropbox links for the 2 linux*mvebu-370xp* kernels mentioned above. They should have the same hashes that were posted in the instllation thread.

https://www.dropbox.com/s/rz2nv7e7xqexw18/linux-4.20.6-mvebu-mirabox-tld-12-bodhi.tar.bz2
md5sum
8cf3d08dee09d000cf8b50b2df2f4047
sha256sum
fc4eb7a66e2af7f17f31041581fa6d106ba3da22ec643ab80a24aa352084f201


https://www.dropbox.com/s/5zah5amlq08mzup/linux-5.8.5-mvebu-370xp-tld-1-bodhi.tar.bz2
md5:
17c3e1784dea18b2a3587a6ebb7aa894
sha256:
655646c0bd09b047b6c9ec198579cd2e345e19c5a8f32787a0979532a3b601d4

-bodhi
===========================
Forum Wiki
bodhi's corner (buy bodhi a beer)
tme
Re: Time is lagging substantially on Netgear ReadyNAS RN102 and RN104
April 01, 2023 04:45AM
Thanks bodhi,

for providing these outdated kernels for testing. On Netgear RN102, the lagging issue is present in both Linux 4.20.6 and 5.8.5.

This is from the serial console with kernel 4.20.6 and Debian 10.0. The delay between the two 'date' commands was 60 s:
debian login: root
Password: 
Last login: Thu Sep  5 01:58:44 PDT 2019 from 192.168.0.100 on pts/0
Linux debian 4.20.6-mvebu-mirabox-tld-12 #6 SMP PREEMPT Wed Mar 13 14:43:16 PDT 2019 armv7l
[...]
192.168.1.246
NETGEAR ReadyNAS 102
Linux version 4.20.6-mvebu-mirabox-tld-12 (root@tldDebianVM) (gcc version 7.3.0 (Ubuntu/Linaro 7.3.0-27ubuntu1~18.04)) #6 SMP PREEMPT Wed Mar 13 14:43:16 PDT 2019
Debian 10.0
Sat Apr 1 02:16:00 PDT 2023 up 2 minutes
root@debian:~# date 
Sat Apr  1 02:17:07 PDT 2023
root@debian:~# date
Sat Apr  1 02:18:02 PDT 2023
root@debian:~#

So the issue has been around since at least March 2019. Then we know that it has not been introduced by any of the more resent patches to the kernel or the device tree.

Regards,
Trond Melen
Author:

Your Email:


Subject:


Spam prevention:
Please, enter the code that you see below in the input field. This is for blocking bots that try to post this form automatically. If the code is hard to read, then just try to guess it right. If you enter the wrong code, a new image is created and you get another chance to enter it right.
Message: