[Linuxptp-users] Strange behaviour on AM5728 board

[Axel Holzinger]

Hi linuxptp community,

I could put my hands on a TI AM5728 box (Elesar Titanium) running Linux arm
4.1.6-01294--g8406366 #6 SMP PREEMPT armv7l (Debian Jessy) and ethtool is
reporting this:
***@arm:~/linuxptp-1.8$ sudo ethtool -T eth1
Time stamping parameters for eth1:
Capabilities:
hardware-transmit (SOF_TIMESTAMPING_TX_HARDWARE)
software-transmit (SOF_TIMESTAMPING_TX_SOFTWARE)
hardware-receive (SOF_TIMESTAMPING_RX_HARDWARE)
software-receive (SOF_TIMESTAMPING_RX_SOFTWARE)
software-system-clock (SOF_TIMESTAMPING_SOFTWARE)
hardware-raw-clock (SOF_TIMESTAMPING_RAW_HARDWARE)
PTP Hardware Clock: 0
Hardware Transmit Timestamp Modes:
off (HWTSTAMP_TX_OFF)
on (HWTSTAMP_TX_ON)
Hardware Receive Filter Modes:
none (HWTSTAMP_FILTER_NONE)
ptpv2-event (HWTSTAMP_FILTER_PTP_V2_EVENT)

I'm observing strange behaviour of ptp4l:
***@arm:~/linuxptp-1.8$ sudo ./ptp4l -i eth1 -s -m -q
ptp4l[296.574]: selected /dev/ptp0 as PTP clock
ptp4l[296.593]: port 1: INITIALIZING to LISTENING on INITIALIZE
ptp4l[296.593]: port 0: INITIALIZING to LISTENING on INITIALIZE
ptp4l[296.593]: port 1: link up
ptp4l[297.202]: port 1: new foreign master 0050c2.fffe.39e7e1-8
ptp4l[299.202]: selected best master clock 000b72.fffe.0587fa
ptp4l[299.202]: port 1: LISTENING to UNCALIBRATED on RS_SLAVE
ptp4l[299.301]: port 1: minimum delay request interval 2^3
ptp4l[300.202]: rms 9169381730255 max 9169405598321 freq +500000 +/- 500000
delay -15782702 +/- 0
ptp4l[302.202]: port 1: UNCALIBRATED to SLAVE on MASTER_CLOCK_SELECTED
ptp4l[302.702]: rms 140849798 max 155677350 freq +1000000 +/- 0 delay
-14387879 +/- 0
ptp4l[303.702]: rms 202019230 max 217113647 freq +1000000 +/- 0 delay
-12993056 +/- 0
ptp4l[304.702]: rms 264705365 max 279944980 freq +1000000 +/- 0
ptp4l[305.702]: rms 322793382 max 336658462 freq +1000000 +/- 0 delay
-8404950 +/- 1529368
ptp4l[306.702]: rms 384104196 max 399489358 freq +1000000 +/- 0
ptp4l[307.702]: rms 446890503 max 462320408 freq +1000000 +/- 0
ptp4l[308.702]: rms 509687509 max 525151217 freq +1000000 +/- 0
ptp4l[309.702]: rms 572309716 max 587627646 freq +1000000 +/- 0 delay
-6521028 +/- 0
ptp4l[310.702]: rms 634949321 max 650458738 freq +1000000 +/- 0
ptp4l[311.702]: rms 697764821 max 713293606 freq +1000000 +/- 0
ptp4l[312.702]: rms 760581017 max 776124411 freq +1000000 +/- 0
ptp4l[313.702]: rms 823400790 max 838959051 freq +1000000 +/- 0
ptp4l[314.701]: rms 886218407 max 901783909 freq +1000000 +/- 0
ptp4l[315.701]: rms 949038000 max 964613935 freq +1000000 +/- 0
ptp4l[316.701]: rms 1011862805 max 1027444991 freq +1000000 +/- 0
ptp4l[317.701]: rms 1074684725 max 1090275855 freq +1000000 +/- 0
ptp4l[318.701]: rms 1137696718 max 1153460190 freq +1000000 +/- 0 delay
-6875582 +/- 0
ptp4l[319.701]: rms 1200688978 max 1216292064 freq +1000000 +/- 0
ptp4l[320.701]: rms 1263514719 max 1279122947 freq +1000000 +/- 0
ptp4l[321.701]: rms 1326341090 max 1341953920 freq +1000000 +/- 0
ptp4l[322.701]: rms 1389167792 max 1404784827 freq +1000000 +/- 0
ptp4l[323.701]: rms 1451994939 max 1467616429 freq +1000000 +/- 0
ptp4l[324.701]: rms 1514822314 max 1530446698 freq +1000000 +/- 0

To me it looks like there is trouble correctly adjusting the frequency of
the PHC, it's always remaining +1000000, but also delays are ridicously high
and negative (that doesn't make sense, does it?).

Has anybody ever seen such behaviour and/or has experience with the AM5728
(or similar)?

Thank you!
Axel

[Richard Cochran]

Post by Axel Holzinger
To me it looks like there is trouble correctly adjusting the frequency of
the PHC, it's always remaining +1000000, but also delays are ridicously high
and negative (that doesn't make sense, does it?).

Does that SoC use the CPTS? Probably the input clock is wrong. Check
the data sheet and the device tree values for:

cpts_clock_mult = <0x80000000>;
cpts_clock_shift = <29>;

Thanks,
Richard

[Axel Holzinger]

This post might be inappropriate. Click to display it.

[Richard Cochran]

Post by Axel Holzinger
So the values for cpts_clock_mult and cpts_clock_shift are configured like
you proposed.

Sorry, I didn't mean that those are the correct values. Those two
properties define the clock constants:

nanoseconds = ticks * cpts_clock_mult / 2^cpts_clock_shift

The values from the beaglebone are

cpts_clock_mult = <0x80000000>;
cpts_clock_shift = <29>;

and so

nanoseconds = ticks * 2^31 / 2^29
nanoseconds = ticks * 4

which is correct if the input clock is 250 MHz. If your SoC uses a
different clock, then the values in the DTS are wrong.

Post by Axel Holzinger
Is there anything else I can check?

The two values are calculated automatically as of commit:

v4.10-rc1~202^2~61^2~1 88f0f0b net: ethernet: ti: cpts: calc mult and shift from refclk freq

You can try kernel v4.10 and remove those two properties from the DTS.
It should "just work" then.

HTH,
Richard

[Axel Holzinger]

Hi Richard,

Post by Richard Cochran
Sorry, I didn't mean that those are the correct values. Those two
nanoseconds = ticks * cpts_clock_mult / 2^cpts_clock_shift
The values from the beaglebone are
cpts_clock_mult = <0x80000000>;
cpts_clock_shift = <29>;
and so
nanoseconds = ticks * 2^31 / 2^29
nanoseconds = ticks * 4
which is correct if the input clock is 250 MHz. If your SoC uses a
different clock, then the values in the DTS are wrong.

Than you very much for the detailed explanation. Very helpful!

I dived into device tree files and couldn't yet find out how the
manufacturer configures CPTS_RFT_CLK. I have the impression that it's not
running at all. So I contacted them and asked if they can point me in the
right direction. I'll report back as soon as I have further information.

Post by Richard Cochran

Post by Axel Holzinger
Is there anything else I can check?

v4.10-rc1~202^2~61^2~1 88f0f0b net: ethernet: ti: cpts: calc mult and

shift

Post by Richard Cochran
from refclk freq
You can try kernel v4.10 and remove those two properties from the DTS.
It should "just work" then.

That's very good news. I cloned Tis v4.10.8, but currently struggle with the
manufacturers way of configuring (which is only supported by the
manufacturer for the v4.1.6). I'm also going to report back if I managed to
get v4.10.8 running.

Tnak you very much for your support!
Axel

[Richard Cochran]

This post might be inappropriate. Click to display it.

[Axel Holzinger]

Hi Richard,

Post by Richard Cochran
Or you can just hack the driver to print clk_get_rate(cpts->refclk).

Cool idea, did that and added this line to drivers/net/ethernet/ti/cpts.c
(and noticed who wrote the file) as last line in
static void cpts_clk_init() {
...
dev_err(dev, "clk_get_rate(cpts->refclk) = %lu",
clk_get_rate(cpts->refclk));
}

Output:
[ 12.012718] cpsw 48484000.ethernet: clk_get_rate(cpts->refclk) =
125000000

It's strange, because from reading CM_GMAC_GMAC_CLKCTRL (L3_CLK is selected
as a clock source) and studying the TRM of the AM5728 regarding what is
doing the boot ROM code I learned that the value should be 133MHz, but what
is printed in the output is 125MHz. Hum.

Okay, so I changed cpts_clock_shift = <29>; to cpts_clock_shift = <28>; in
arch/arm/boot/dts/dra7.dtsi.

Unfortunately that didn't help either, while it changed the ptp4l output:
***@arm:~/linuxptp-1.8$ sudo ./ptp4l -i eth1 -s -m -q
[sudo] password for user:
ptp4l[76.441]: selected /dev/ptp0 as PTP clock
ptp4l[76.463]: port 1: INITIALIZING to LISTENING on INITIALIZE
ptp4l[76.463]: port 0: INITIALIZING to LISTENING on INITIALIZE
ptp4l[76.463]: port 1: link up
ptp4l[77.442]: port 1: new foreign master 0050c2.fffe.39e7e1-8
ptp4l[79.442]: selected best master clock 000b72.fffe.0587fa
ptp4l[79.442]: port 1: LISTENING to UNCALIBRATED on RS_SLAVE
ptp4l[80.345]: port 1: minimum delay request interval 2^3
ptp4l[80.942]: rms 9552511550405 max 9552793492018 freq +500000 +/- 500000
delay -227782976 +/- 776530
ptp4l[81.942]: clockcheck: clock jumped forward or running faster than
expected!
ptp4l[82.442]: clockcheck: clock jumped forward or running faster than
expected!
ptp4l[82.941]: clockcheck: clock jumped forward or running faster than
expected!
ptp4l[83.442]: clockcheck: clock jumped forward or running faster than
expected!
ptp4l[83.941]: clockcheck: clock jumped forward or running faster than
expected!
ptp4l[84.441]: clockcheck: clock jumped forward or running faster than
expected!
ptp4l[84.941]: clockcheck: clock jumped forward or running faster than
expected!
ptp4l[85.441]: clockcheck: clock jumped forward or running faster than
expected!
ptp4l[85.941]: clockcheck: clock jumped forward or running faster than
expected!
ptp4l[86.441]: clockcheck: clock jumped forward or running faster than
expected!
ptp4l[86.941]: clockcheck: clock jumped forward or running faster than
expected!
ptp4l[87.441]: clockcheck: clock jumped forward or running faster than
expected!
ptp4l[87.941]: clockcheck: clock jumped forward or running faster than
expected!
ptp4l[88.441]: clockcheck: clock jumped forward or running faster than
expected!
ptp4l[88.941]: clockcheck: clock jumped forward or running faster than
expected!
ptp4l[89.441]: clockcheck: clock jumped forward or running faster than
expected!
ptp4l[89.941]: clockcheck: clock jumped forward or running faster than
expected!
ptp4l[90.441]: clockcheck: clock jumped forward or running faster than
expected!
ptp4l[90.941]: clockcheck: clock jumped forward or running faster than
expected!
ptp4l[91.441]: clockcheck: clock jumped forward or running faster than
expected!
ptp4l[91.941]: clockcheck: clock jumped forward or running faster than
expected!
ptp4l[92.441]: clockcheck: clock jumped forward or running faster than
expected!
ptp4l[92.941]: clockcheck: clock jumped forward or running faster than
expected!
ptp4l[93.441]: clockcheck: clock jumped forward or running faster than
expected!
ptp4l[93.941]: clockcheck: clock jumped forward or running faster than
expected!
ptp4l[94.441]: clockcheck: clock jumped forward or running faster than
expected!
ptp4l[94.941]: clockcheck: clock jumped forward or running faster than
expected!
ptp4l[95.441]: clockcheck: clock jumped forward or running faster than
expected!
ptp4l[95.441]: rms 16042529614 max 16321529908 freq +1000000 +/- 0 delay
-227006446 +/- 0
ptp4l[95.941]: clockcheck: clock jumped forward or running faster than
expected!
ptp4l[96.441]: clockcheck: clock jumped forward or running faster than
expected!
ptp4l[96.441]: rms 17168088472 max 17447241720 freq +1000000 +/- 0
ptp4l[96.941]: clockcheck: clock jumped forward or running faster than
expected!
ptp4l[97.441]: clockcheck: clock jumped forward or running faster than
expected!
ptp4l[97.441]: rms 18293668079 max 18572965183 freq +1000000 +/- 0
ptp4l[97.941]: clockcheck: clock jumped forward or running faster than
expected!
ptp4l[98.441]: clockcheck: clock jumped forward or running faster than
expected!
ptp4l[98.441]: rms 19419257020 max 19698670451 freq +1000000 +/- 0

and so on...

I will now again contact the manufacturer and tell him what I found out,
hoping that the manufacturer can fix the issue or at least shed more light
on what's going on.

Many many thanks and best regards
Axel