Message-ID: <def1073b-8997-48cd-adf3-e834662881de@fel.cvut.cz>
Date: Sat, 20 Jul 2024 04:24:33 +0200
From: Martin Pecka <peckama2@....cvut.cz>
To: irusskikh@...vell.com, epomozov@...vell.com
Cc: netdev@...r.kernel.org, linux-kernel@...r.kernel.org
Subject: net: atlantic: PHC time jumps ~4 seconds there and back on AQC107

Hello atlantic driver maintainers. This is my first kernel bugreport, so please try to be patient :)
However, I've spent full 3 working days (and nights) debugging this issue, so I hope we'll find
a way to fix it properly. So far, I've come with a workaround, but I'm not sure about its side-effects.

Summary: PHC time jumps ~4 seconds there and back on AQC107

I'm testing on multiple copper-PHY NICs with AQC107 and the problem is always the same:
- QNAP QXG-10G2TB, PCIe, FW 3.1.121
- Sanlink3 N1, Thunderbolt, FW 3.1.121
- OWC OWCTB3ADP10GBE, Thunderbolt, FW 3.1.106 (it cannot run 3.1.121)
- Sonnettech Solo10G 10GBASE-T, Thunderbolt, FW 3.1.121

I run the tests on multiple PCs with different CPU archs and the problem is always the same:
- Intel NUC (Thunderbolt, x86-64, kernel 6.8, upstream atlantic driver)
- NVidia Jetson (PCIe, aarch64, kernel 4.9.337 + out-of-tree driverhttps://github.com/Aquantia/AQtion  ).

When I enable PTP on the card (e.g. `hwstamp_ctl -i eth2 -t 1`) and run phc2sys from linuxptp
to sync the card's PHC to another clock (AQ107 is time sink), I get time jumps of the PHC clock
of ~4 secs in the future and then back (after ~5 secs). These jumps happen in random intervals
and I haven't found a pattern. Usually, it happens every 20-100 secs, but there have been even
much longer intervals. These time jumps are corrected by phc2sys quite quickly (within ~10 seconds),
but during this interval, the time is wrong.

An easy way to trigger this issue is to connect a cable to the port (say eth2) and run:

sudo hwstamp_ctl -i eth2 -t 1 -r 6 && sudo phc2sys -s CLOCK_REALTIME -c eth2 -m -l6 --step_threshold=0.001 -O0

Observe the log, and after some time, you should observe:

phc2sys[341.011]: ens5 sys offset        97 s2 freq  -39142 delay  15664
phc2sys[342.025]: ens5 sys offset        77 s2 freq  -39133 delay  15810
phc2sys[343.039]: ens5 sys offset       127 s2 freq  -39060 delay  15657
phc2sys[344.040]: clockcheck: clock jumped forward or running faster than expected!
phc2sys[344.040]: ens5 sys offset 4294967398 s0 freq  -39060 delay  15647
phc2sys[345.054]: ens5 sys offset 4294967419 s1 freq  -39128 delay  15638
phc2sys[346.054]: clockcheck: clock jumped backward or running slower than expected!
phc2sys[346.055]: ens5 sys offset -4294967181 s0 freq  -39128 delay  15576
phc2sys[347.069]: ens5 sys offset -4294967079 s1 freq  -39026 delay  15639
phc2sys[348.083]: ens5 sys offset        54 s2 freq  -38972 delay  15641
phc2sys[349.097]: ens5 sys offset        82 s2 freq  -38928 delay  15680
phc2sys[350.111]: ens5 sys offset        99 s2 freq  -38886 delay  15625
phc2sys[351.125]: ens5 sys offset        84 s2 freq  -38871 delay  15664

It's always this pair of forward jump and backward jump separated by a few seconds.
Inspecting the behavior of phc2sys, I found out that the timestamps start to be wrong
3 seconds earlier than clockcheck reports the jump. phc2sys uses clock_gettime() to read the stamps.

Digging deeper, I found that even the lowest-level read by `get_ptp_ts_val_u64(self, 0)`
called from hw_atl_b0_get_ptp_ts is wrong (this value is the LSW of the timestamp secs part).

Here's a part of my instrumented hw_atl_b0.c log logging the double value of ns/NSEC_PER_SEC computed in hw_atl_b0_get_ptp_ts().
It also logs calls of hw_atl_b0_adj_clock_freq() and prints the contents of the fwreq sent to the chip.
Finally, it logs calls of hw_atl_b0_adj_sys_clock() that happen when phc2sys jumps the clock.

Notice the sequence of increasing timestamps and the jumps 211->216 and 219->216 . These jumps happen before
phc2sys does the clock jumping (that is only a consequence).


[25893.078283] get_ptp_ts 209.935560803
[25893.078629] get_ptp_ts 209.935948717
[25893.078891] get_ptp_ts 209.936226947
[25893.079181] get_ptp_ts 209.936515385
[25893.079437] get_ptp_ts 209.936772456
[25893.079908] get_ptp_ts 209.937042884
[25893.080989] get_ptp_ts 209.938101882
[25893.090670] get_ptp_ts 209.944151607
[25893.104925] get_ptp_ts 209.957715257
[25893.119372] get_ptp_ts 209.971896511
[25893.139509] adj_clock_freq 8861 MAC 3.200028355 PHY 6.250055380 ADJ 3.232028354
[25894.159576] get_ptp_ts 211.016908359
[25894.159895] get_ptp_ts 211.017271076
[25894.160180] get_ptp_ts 211.017563795
[25894.160449] get_ptp_ts 211.017833155
[25894.160722] get_ptp_ts 211.018105944
[25894.161755] get_ptp_ts 211.019131624
[25894.162065] get_ptp_ts 211.019414257
[25894.170565] get_ptp_ts 211.023429876
[25894.184486] get_ptp_ts 211.037632396
[25894.198473] get_ptp_ts 211.051394220
[25894.218557] adj_clock_freq 8692 MAC 3.200027813 PHY 6.250054324 ADJ -2.808132466
[25895.238581] get_ptp_ts 216.390917446
[25895.238919] get_ptp_ts 216.391296310
[25895.239205] get_ptp_ts 216.391603820
[25895.239477] get_ptp_ts 216.391876808
[25895.239733] get_ptp_ts 216.392134762
[25895.240129] get_ptp_ts 216.392421901
[25895.242086] get_ptp_ts 216.394450904
[25895.250265] get_ptp_ts 216.398189797
[25895.264184] get_ptp_ts 216.412193567
[25895.278614] get_ptp_ts 216.426474997
[25896.288325] get_ptp_ts 217.440716766
[25896.290443] get_ptp_ts 217.442851114
[25896.290742] get_ptp_ts 217.443186963
[25896.291017] get_ptp_ts 217.443466620
[25896.291275] get_ptp_ts 217.443723736
[25896.291572] get_ptp_ts 217.444022427
[25896.291974] get_ptp_ts 217.444291638
[25896.300018] get_ptp_ts 217.448960031
[25896.313930] get_ptp_ts 217.461986858
[25896.328100] get_ptp_ts 217.476284109
[25897.338260] get_ptp_ts 218.490702180
[25897.338574] get_ptp_ts 218.491068993
[25897.338857] get_ptp_ts 218.491354691
[25897.339147] get_ptp_ts 218.491625836
[25897.339403] get_ptp_ts 218.491901045
[25897.339817] get_ptp_ts 218.492169380
[25897.341433] get_ptp_ts 218.493909779
[25897.349861] get_ptp_ts 218.497600672
[25897.363785] get_ptp_ts 218.511996477
[25897.377950] get_ptp_ts 218.525891574
[25898.387816] get_ptp_ts 219.540304525
[25898.388130] get_ptp_ts 219.540675076
[25898.388429] get_ptp_ts 219.540960697
[25898.389618] get_ptp_ts 219.542138730
[25898.389888] get_ptp_ts 219.542424640
[25898.390170] get_ptp_ts 219.542707529
[25898.390460] get_ptp_ts 219.542992625
[25898.399424] get_ptp_ts 219.547647552
[25898.413595] get_ptp_ts 219.561646784
[25898.427769] get_ptp_ts 219.575803535
[25898.437342] [aq_ptp_adjtime:432(eth2)]AQ PTP Adj Time 0xffffffff00000897
[25898.444205] adj_sys_clock delta -4294965097 old off 1721431199092597746 new off 1721431194797632649
[25898.468102] adj_clock_freq 7762 MAC 3.200024837 PHY 6.250048511 ADJ 7.136024837
[25899.488528] get_ptp_ts 216.346103600
[25899.489463] get_ptp_ts 216.347059908
[25899.489725] get_ptp_ts 216.347350259
[25899.490001] get_ptp_ts 216.347628386
[25899.490290] get_ptp_ts 216.347919083
[25899.490575] get_ptp_ts 216.348203853
[25899.491052] get_ptp_ts 216.348459772
[25899.499872] get_ptp_ts 216.353127373
[25899.513955] get_ptp_ts 216.367047526
[25899.528394] get_ptp_ts 216.381484444
[25900.538235] get_ptp_ts 217.395854596
[25900.538551] get_ptp_ts 217.396220167
[25900.538851] get_ptp_ts 217.396524688
[25900.539126] get_ptp_ts 217.396799192
[25900.539380] get_ptp_ts 217.397057421
[25900.539806] get_ptp_ts 217.397324867
[25900.542162] get_ptp_ts 217.399806608
[25900.549670] get_ptp_ts 217.402820103
[25900.564099] get_ptp_ts 217.417228944
[25900.578010] get_ptp_ts 217.431428978
[25901.587908] get_ptp_ts 218.445583371
[25901.588244] get_ptp_ts 218.445958248
[25901.588822] get_ptp_ts 218.446540812
[25901.589115] get_ptp_ts 218.446820859
[25901.589374] get_ptp_ts 218.447096023
[25901.589651] get_ptp_ts 218.447372767
[25901.590492] get_ptp_ts 218.448014110
[25901.599515] get_ptp_ts 218.452676252
[25901.613433] get_ptp_ts 218.467009598
[25901.627337] get_ptp_ts 218.480585921
[25902.637474] get_ptp_ts 219.495211275
[25902.637786] get_ptp_ts 219.495553191
[25902.638066] get_ptp_ts 219.495834992
[25902.638334] get_ptp_ts 219.496104568
[25902.638601] get_ptp_ts 219.496373121
[25902.639053] get_ptp_ts 219.496640950
[25902.640107] get_ptp_ts 219.497645175
[25902.648916] get_ptp_ts 219.503196028
[25902.663348] get_ptp_ts 219.516652574
[25902.677521] get_ptp_ts 219.530790661
[25902.687211] [aq_ptp_adjtime:432(eth2)]AQ PTP Adj Time 0xfffff309
[25902.692958] adj_sys_clock delta 4294963977 old off 1721431194797632649 new off 1721431199092596626
[25902.717347] adj_clock_freq 8771 MAC 3.200028066 PHY 6.250054817 ADJ 0.168028067
[25903.737052] get_ptp_ts 220.594824352
[25903.737352] get_ptp_ts 220.595167760
[25903.737629] get_ptp_ts 220.595446649
[25903.737907] get_ptp_ts 220.595724085
[25903.738166] get_ptp_ts 220.595984241
[25903.738625] get_ptp_ts 220.596254624
[25903.739683] get_ptp_ts 220.597282998
[25903.748741] get_ptp_ts 220.602286152
[25903.762916] get_ptp_ts 220.616207791
[25903.777003] get_ptp_ts 220.630048879
[25903.796717] adj_clock_freq 10043 MAC 3.200032136 PHY 6.250062767 ADJ 8.128032136
[25904.816986] get_ptp_ts 221.674793267
[25904.817305] get_ptp_ts 221.675169411
[25904.817566] get_ptp_ts 221.675436358
[25904.817845] get_ptp_ts 221.675711765
[25904.818118] get_ptp_ts 221.675976568
[25904.818634] get_ptp_ts 221.676322863

Running the `readlog` tool from Marvell diag package, there is also nothing suspicuous in the internal card log
(except the `sign` field in adjustMacClock which is always + even though the driver sends one + and one -).

�PTP Adj Freq: 3, 33354883, 6, 400411a5, 0, fbf05da4;
�PTP Adj Freq: 3, 33354282, 6, 400405e7, 5, 70a5e659;
�PTP Adj Freq: 3, 333541b3, 6, 40040453, 6, c4bc8de;
�PTP Adj Freq: 3, 33354989, 6, 400413a4, ffffffff, 831b60b6;
�PTP Adj Freq: 3, 33353e95, 6, 4003fe40, 0, aa04ce97;
�PTP Adj Freq: 3, 33353d3d, 6, 4003fba2, 3, 810f0aaf;
�PTP Adj Freq: 3, 33353ab9, 6, 4003f6b3, 6, 9fc07e4e;
�PTP Adj Freq: 3, 33353d16, 6, 4003fb51, 7, 5c2affa5;
�PTP Adj Freq: 3, 33354e44, 6, 40041cdf, 7, ae1695f2;
�PTP Adj Freq: 3, 3335448e, 6, 400409e5, 2, 7efbec7e;
�PTP Adj Freq: 3, 33355a3b, 6, 40043442, 3, 4fe83e34;
�PTP Adj Freq: 3, 33354bf4, 6, 4004185b, 8, 31290239;
�PTP Adj Freq: 3, 333541f8, 6, 400404dd, ffffffff, ed9a5300;
�142936 adjustMacClock sign=+ adj=294967295 frac=ed9a5300
�PTP Adj Freq: 3, 333537fd, 6, 4003f159, 0, dd311f6a;
�143150 adjustMacClock sign=+ adj=294967247 frac=0
�PTP Adj Freq: 3, 33356410, 6, 4004476f, 2, b022f579;
�PTP Adj Freq: 3, 333776fa, 6, 40085462, 6, b8562f4b;
�PTP Adj Freq: 3, 33367d8c, 6, 40066d35, 2, 4dd63c03;
�PTP Adj Freq: 3, 3335622f, 6, 400443c7, 9, c2918b24;

When I poked into various parts of the code, I found the following observations interesting:

1) When PTP is not enabled (aka `hwstamp_ctl -t 0 -r 0`), the issue does not happen.
2) When I forbid phc2sys to call clock_adjtime with ADJ_FREQUENCY, the issue does not happen (but the clock doesn't sync).
3) The best workaround I found that allows me to actually sync the PHC and use it for PTP is editing
    hw_atl_b0_adj_clock_freq() to zero-out mac_ns_adj and mac_fns_adj fields of the fwreq before sending
    it to the FW.
3.1) I don't even need to zero-out the values. It is enough to zero-out all negative values of the adjustment.
4) The issue is not influenced by the amount of data flowing through the NIC.
5) It happens both when I use the NIC as ptp4l master and when ptp4l doesn't use the card
    (but PTP has to be enabled by the hwstamp_ctl call).

But here I'm stuck and I can't move forward understanding what are the unintended consequences of the
workarounds from points 3 or 3.1. Even having an NDA with Marvell and access to the AQC107 collaterals doesn't provide a single
document that would describe the registers of the chip or API of the firmware. So I can just guess, and I
really don't know what this adjustment field should be doing. hw_atl_b0_mac_adj_param_calc() has a note saying
"MAC MCP counter freq is macfreq / 4", then there is a s64 variable called diff_in_mcp_overflow whose value is
slightly processed and converted to u32 (so the overflow is probably intended?). No idea what's MCP counter
and how does the adjustment field adjust it.

I've plotted the values of the adjustment field for ppb values from -10000 to 10000, which are the values
I see phc2sys usually uses (actually, it is more like 8000 - 10000). The values of this adjustment oscillate
between -5 and 20. And as I said in observation 3.1, when I clamp them to 0-20, the problem disappears,
PHC sync runs and I can use the NIC as a PTP master.

Thanks for any hints where to go next,
Martin

Mgr. Martin Pecka, Ph.D.
Researcher at Vision for Robotics and Autonomous Systems group
Faculty of Electrical Engineering
Czech Technical University in Prague


Content of type "text/html" skipped

Download attachment "smime.p7s" of type "application/pkcs7-signature" (4324 bytes)

Powered by blists - more mailing lists