TMDX654IDKEVM: Clock jump of PTP device for ICSSG.

Important note, mentioned clock jump occurs without clock sync via phc2sys also.

It is always in up time:
 - around 4436s for SDK 7.1
 - around 1659s for SDK 8

Hi Lukas,

Sorry for the delay.

I will try to recreate the setup and get back to you within 3-4 days.

Regards,

Tanmay

HI Lukas,

I have reproduced this issue and it is under further investigation. I will get back you.

Regards,

Tanmay

Unlocking the thread

The fix for this is available in our official ti-linux-5.10.y branch:

https://git.ti.com/cgit/ti-linux-kernel/ti-linux-kernel/commit/?h=ti-linux-5.10.y&id=b958a39927c5035afe878db07be85ec94fc501d8&context=3&ignorews=0&dt=0

It’s also included in the TI Kernel tag 08.01.00.001, so it is already part of our official AM65x Processor SDK since 12/19/2021, see www.ti.com/.../PROCESSOR-SDK-LINUX-AM65X.

Regards, Andreas

Hi Andreas,

the issue is not still fully fixed.

Test with image from SDK PROCESSOR-SDK-LINUX-RT-AM65X_08.02.00.01
 -> Clock of PTP device for PRU jumps at 16777s to 8389s. And also for each multiple of 16777s.

Steps how to reproduce faster with clock settings
 - get working IDK with image from SDK
 - download and compile phc_ctl tool from linuxptp-3.1.1 on IDK
 - set clock of PTP near to 16777s
   $ phc_ctl eth1 set 16760
 - get clock from PTP for check
   $ phc_ctl eth1 get
 - wait some time (when time is over 16777s)
 - get clock from PTP
   $ phc_ctl eth1 get
   -> read clock jumped back to 8389

Regards,

Lukas

Hello Lukas,

Andreas is out of town for the next week and a half. In the meantime, I have passed your observations to the developers to see if we can get some feedback from them.

Regards,

Nick

Hello,

it has been a month and I would like to know if there is something new.

Hi Marek,

Nick is out of the office until e/o this month and I don't have a record of where the discussion with the developer stands but I just pinged one of the developers directly to see what the status is. Surprised to see the issue wasn't fully resolved, we'll figure out where the disconnect is. Will update here as soon as I hear back.

Regards, Andreas

Unlocking the thread for Danish to comment

-Nick

Hello,

the thread was unlocked to comment. Week gone and there is no new comment.

Do you have some status update?

Regards,
Lukas

Hello Lukas,

Apologies for the delay. Looks like we had the forum outage last week, and Danish was on vacation the first half of this week. I will ping him over email.

Regards,

Nick

From Danish:

I was able to reproduce this issue on AM65x SR 2.0 with 8.4 SDK
(Nick note: this is an internal build, AM65x SDK 8.2 is the latest released SDK. The next AM65x Linux SDK is planned for spring 2023) 

Running phc2sys with default configuration on ICSSG port  [eth6 is the ICSSG interface], the clock is jumping backward at around 2699 seconds.

Logs :-

Command :-   phc2sys -s CLOCK_REALTIME -c eth6 -O 0 -R 10 -mphc2sys[2698.700]: eth6 sys offset         0 s2 freq     +28 delay    420
phc2sys[2698.800]: eth6 sys offset         4 s2 freq     +32 delay    425
phc2sys[2698.900]: eth6 sys offset         0 s2 freq     +30 delay    425
phc2sys[2699.001]: eth6 sys offset         0 s2 freq     +30 delay    425
phc2sys[2699.101]: eth6 sys offset         3 s2 freq     +33 delay    425
phc2sys[2699.201]: clockcheck: clock jumped backward or running slower than expected!
phc2sys[2699.201]: eth6 sys offset -8388607999997 s0 freq     +33 delay    425
phc2sys[2699.301]: eth6 sys offset -8388608000003 s2 freq     -29 delay    425
phc2sys[2699.401]: eth6 sys offset -8388608000001 s2 freq -10000000 delay    425
phc2sys[2699.502]: eth6 sys offset -8388606998592 s2 freq -10000000 delay    425

Fix :-

However by adding  the below line to phc2sys configuration file and passing the new configuration  with -f option while running phc2sys, the clock jumping issue was not seen.

step_threshold     0.0002

I ran phc2sys for more than 2 days (48+ hours)  and I didn't see any clock jump issue during this time.

Logs :-

Command :- phc2sys -s CLOCK_REALTIME -c eth6 -O 0 -R 10 -f phc2sys.conf -m 

phc2sys[5578.142]: eth6 sys offset       103 s2 freq    +273 delay    425
phc2sys[5578.242]: eth6 sys offset        77 s2 freq    +278 delay    425
phc2sys[5578.342]: eth6 sys offset        53 s2 freq    +277 delay    425
phc2sys[5578.442]: eth6 sys offset        30 s2 freq    +270 delay    425

...

...

...

phc2sys[332153.994]: eth6 sys offset       -15 s2 freq     -45 delay    420
phc2sys[332154.094]: eth6 sys offset        -8 s2 freq     -42 delay    425
phc2sys[332154.194]: eth6 sys offset        -7 s2 freq     -44 delay    425
phc2sys[332154.243]: eth6 sys offset        -8 s2 freq     -47 delay    425

Configuration file:

[global]
verbose               1
time_stamping         software
step_threshold        0.00002
[em3]

Full log for the error case:

phc2sys[2696.897]: eth6 sys offset         1 s2 freq     +26 delay    425
phc2sys[2696.997]: eth6 sys offset         2 s2 freq     +27 delay    425
phc2sys[2697.097]: eth6 sys offset         1 s2 freq     +26 delay    425
phc2sys[2697.197]: eth6 sys offset         2 s2 freq     +28 delay    425
phc2sys[2697.297]: eth6 sys offset         1 s2 freq     +27 delay    420
phc2sys[2697.398]: eth6 sys offset         2 s2 freq     +29 delay    425
phc2sys[2697.498]: eth6 sys offset         2 s2 freq     +29 delay    425
phc2sys[2697.598]: eth6 sys offset        -1 s2 freq     +27 delay    415
phc2sys[2697.698]: eth6 sys offset        -1 s2 freq     +27 delay    420
phc2sys[2697.798]: eth6 sys offset         1 s2 freq     +28 delay    420
phc2sys[2697.899]: eth6 sys offset         0 s2 freq     +28 delay    425
phc2sys[2697.999]: eth6 sys offset         0 s2 freq     +28 delay    425
phc2sys[2698.099]: eth6 sys offset         1 s2 freq     +29 delay    425
phc2sys[2698.199]: eth6 sys offset         1 s2 freq     +29 delay    420
phc2sys[2698.299]: eth6 sys offset        -2 s2 freq     +26 delay    420
phc2sys[2698.399]: eth6 sys offset         1 s2 freq     +29 delay    420
phc2sys[2698.500]: eth6 sys offset         1 s2 freq     +29 delay    420
phc2sys[2698.600]: eth6 sys offset         1 s2 freq     +29 delay    425
phc2sys[2698.700]: eth6 sys offset         0 s2 freq     +28 delay    420
phc2sys[2698.800]: eth6 sys offset         4 s2 freq     +32 delay    425
phc2sys[2698.900]: eth6 sys offset         0 s2 freq     +30 delay    425
phc2sys[2699.001]: eth6 sys offset         0 s2 freq     +30 delay    425
phc2sys[2699.101]: eth6 sys offset         3 s2 freq     +33 delay    425
phc2sys[2699.201]: clockcheck: clock jumped backward or running slower than expected!
phc2sys[2699.201]: eth6 sys offset -8388607999997 s0 freq     +33 delay    425
phc2sys[2699.301]: eth6 sys offset -8388608000003 s2 freq     -29 delay    425
phc2sys[2699.401]: eth6 sys offset -8388608000001 s2 freq -10000000 delay    425
phc2sys[2699.502]: eth6 sys offset -8388606998592 s2 freq -10000000 delay    425
phc2sys[2699.602]: eth6 sys offset -8388605996891 s2 freq -10000000 delay    420
phc2sys[2699.702]: eth6 sys offset -8388604995031 s2 freq -10000000 delay    425
phc2sys[2699.802]: eth6 sys offset -8388603993362 s2 freq -10000000 delay    425
phc2sys[2699.902]: eth6 sys offset -8388602991636 s2 freq -10000000 delay    425
phc2sys[2700.002]: eth6 sys offset -8388601989991 s2 freq -10000000 delay    425
phc2sys[2700.103]: eth6 sys offset -8388600988384 s2 freq -10000000 delay    425
phc2sys[2700.203]: eth6 sys offset -8388599986799 s2 freq -10000000 delay    420
phc2sys[2700.303]: eth6 sys offset -8388598985268 s2 freq -10000000 delay    420
phc2sys[2700.403]: eth6 sys offset -8388597983520 s2 freq -10000000 delay    425
phc2sys[2700.503]: eth6 sys offset -8388596981868 s2 freq -10000000 delay    425
phc2sys[2700.603]: eth6 sys offset -8388595980270 s2 freq -10000000 delay    425
phc2sys[2700.704]: eth6 sys offset -8388594978264 s2 freq -10000000 delay    425
phc2sys[2700.804]: eth6 sys offset -8388593976575 s2 freq -10000000 delay    425
phc2sys[2700.904]: eth6 sys offset -8388592975052 s2 freq -10000000 delay    420
phc2sys[2701.004]: eth6 sys offset -8388591973381 s2 freq -10000000 delay    425
phc2sys[2701.104]: eth6 sys offset -8388590971819 s2 freq -10000000 delay    420
phc2sys[2701.204]: eth6 sys offset -8388589970128 s2 freq -10000000 delay    425
phc2sys[2701.305]: eth6 sys offset -8388588968376 s2 freq -10000000 delay    425
phc2sys[2701.405]: eth6 sys offset -8388587966580 s2 freq -10000000 delay    425
phc2sys[2701.505]: eth6 sys offset -8388586964808 s2 freq -10000000 delay    425
phc2sys[2701.605]: eth6 sys offset -8388585963224 s2 freq -10000000 delay    425
phc2sys[2701.705]: eth6 sys offset -8388584961312 s2 freq -10000000 delay    425
phc2sys[2701.806]: eth6 sys offset -8388583959603 s2 freq -10000000 delay    420
phc2sys[2701.906]: eth6 sys offset -8388582957975 s2 freq -10000000 delay    420
phc2sys[2702.006]: eth6 sys offset -8388581956115 s2 freq -10000000 delay    425
phc2sys[2702.106]: eth6 sys offset -8388580953855 s2 freq -10000000 delay    425
phc2sys[2702.206]: eth6 sys offset -8388579951991 s2 freq -10000000 delay    425
phc2sys[2702.307]: eth6 sys offset -8388578950220 s2 freq -10000000 delay    425
phc2sys[2702.407]: eth6 sys offset -8388577948474 s2 freq -10000000 delay    425
phc2sys[2702.507]: eth6 sys offset -8388576946807 s2 freq -10000000 delay    425
phc2sys[2702.607]: eth6 sys offset -8388575945154 s2 freq -10000000 delay    425
phc2sys[2702.707]: eth6 sys offset -8388574943324 s2 freq -10000000 delay    425
phc2sys[2702.807]: eth6 sys offset -8388573941700 s2 freq -10000000 delay    425
phc2sys[2702.908]: eth6 sys offset -8388572939904 s2 freq -10000000 delay    425
phc2sys[2703.008]: eth6 sys offset -8388571938139 s2 freq -10000000 delay    425
phc2sys[2703.108]: eth6 sys offset -8388570936447 s2 freq -10000000 delay    420
phc2sys[2703.208]: eth6 sys offset -8388569934781 s2 freq -10000000 delay    425
phc2sys[2703.308]: eth6 sys offset -8388568933174 s2 freq -10000000 delay    425
phc2sys[2703.408]: eth6 sys offset -8388567931459 s2 freq -10000000 delay    420
phc2sys[2703.509]: eth6 sys offset -8388566929873 s2 freq -10000000 delay    425
phc2sys[2703.609]: eth6 sys offset -8388565928200 s2 freq -10000000 delay    425
phc2sys[2703.709]: eth6 sys offset -8388564926411 s2 freq -10000000 delay    425
phc2sys[2703.809]: eth6 sys offset -8388563924765 s2 freq -10000000 delay    425
phc2sys[2703.909]: eth6 sys offset -8388562922722 s2 freq -10000000 delay    425
phc2sys[2704.010]: eth6 sys offset -8388561920816 s2 freq -10000000 delay    425
phc2sys[2704.110]: eth6 sys offset -8388560919133 s2 freq -10000000 delay    425
phc2sys[2704.210]: eth6 sys offset -8388559917526 s2 freq -10000000 delay    425
phc2sys[2704.310]: eth6 sys offset -8388558915955 s2 freq -10000000 delay    420
phc2sys[2704.410]: eth6 sys offset -8388557914338 s2 freq -10000000 delay    425
phc2sys[2704.510]: eth6 sys offset -8388556912675 s2 freq -10000000 delay    420
phc2sys[2704.611]: eth6 sys offset -8388555911004 s2 freq -10000000 delay    425
phc2sys[2704.711]: eth6 sys offset -8388554909191 s2 freq -10000000 delay    425
phc2sys[2704.811]: eth6 sys offset -8388553907519 s2 freq -10000000 delay    420
phc2sys[2704.911]: eth6 sys offset -8388552906011 s2 freq -10000000 delay    425
phc2sys[2705.011]: eth6 sys offset -8388551904237 s2 freq -10000000 delay    425
phc2sys[2705.111]: eth6 sys offset -8388550902114 s2 freq -10000000 delay    425
phc2sys[2705.212]: eth6 sys offset -8388549900127 s2 freq -10000000 delay    425
phc2sys[2705.312]: eth6 sys offset -8388548898304 s2 freq -10000000 delay    425
phc2sys[2705.412]: eth6 sys offset -8388547896560 s2 freq -10000000 delay    425
phc2sys[2705.512]: eth6 sys offset -8388546894846 s2 freq -10000000 delay    425
phc2sys[2705.612]: eth6 sys offset -8388545893180 s2 freq -10000000 delay    425
phc2sys[2705.713]: eth6 sys offset -8388544891195 s2 freq -10000000 delay    420
phc2sys[2705.813]: eth6 sys offset -8388543889683 s2 freq -10000000 delay    420
phc2sys[2705.913]: eth6 sys offset -8388542888058 s2 freq -10000000 delay    420
phc2sys[2706.013]: eth6 sys offset -8388541886426 s2 freq -10000000 delay    425
phc2sys[2706.113]: eth6 sys offset -8388540884735 s2 freq -10000000 delay    420
phc2sys[2706.213]: eth6 sys offset -8388539883006 s2 freq -10000000 delay    425
phc2sys[2706.314]: eth6 sys offset -8388538881296 s2 freq -10000000 delay    425
phc2sys[2706.414]: eth6 sys offset -8388537879735 s2 freq -10000000 delay    425
phc2sys[2706.514]: eth6 sys offset -8388536878027 s2 freq -10000000 delay    425
phc2sys[2706.614]: eth6 sys offset -8388535876347 s2 freq -10000000 delay    420
phc2sys[2706.714]: eth6 sys offset -8388534874431 s2 freq -10000000 delay    425
phc2sys[2706.815]: eth6 sys offset -8388533872720 s2 freq -10000000 delay    425
phc2sys[2706.915]: eth6 sys offset -8388532871169 s2 freq -10000000 delay    415
phc2sys[2707.015]: eth6 sys offset -8388531869234 s2 freq -10000000 delay    425
phc2sys[2707.115]: eth6 sys offset -8388530867091 s2 freq -10000000 delay    425
phc2sys[2707.215]: eth6 sys offset -8388529865283 s2 freq -10000000 delay    420
phc2sys[2707.315]: eth6 sys offset -8388528863468 s2 freq -10000000 delay    425
phc2sys[2707.416]: eth6 sys offset -8388527861215 s2 freq -10000000 delay    425
phc2sys[2707.516]: eth6 sys offset -8388526859362 s2 freq -10000000 delay    420
phc2sys[2707.616]: eth6 sys offset -8388525857547 s2 freq -10000000 delay    420
phc2sys[2707.716]: eth6 sys offset -8388524855636 s2 freq -10000000 delay    425
phc2sys[2707.816]: eth6 sys offset -8388523853871 s2 freq -10000000 delay    425
phc2sys[2707.917]: eth6 sys offset -8388522852228 s2 freq -10000000 delay    425
phc2sys[2708.017]: eth6 sys offset -8388521850253 s2 freq -10000000 delay    420
phc2sys[2708.117]: eth6 sys offset -8388520847902 s2 freq -10000000 delay    425
phc2sys[2708.217]: eth6 sys offset -8388519846019 s2 freq -10000000 delay    425
phc2sys[2708.317]: eth6 sys offset -8388518844261 s2 freq -10000000 delay    425
phc2sys[2708.418]: eth6 sys offset -8388517842534 s2 freq -10000000 delay    425
phc2sys[2708.518]: eth6 sys offset -8388516840857 s2 freq -10000000 delay    425
phc2sys[2708.618]: eth6 sys offset -8388515839155 s2 freq -10000000 delay    420
phc2sys[2708.718]: eth6 sys offset -8388514837119 s2 freq -10000000 delay    420
phc2sys[2708.818]: eth6 sys offset -8388513835410 s2 freq -10000000 delay    425
phc2sys[2708.919]: eth6 sys offset -8388512833475 s2 freq -10000000 delay    420
phc2sys[2709.019]: eth6 sys offset -8388511831787 s2 freq -10000000 delay    420
phc2sys[2709.119]: eth6 sys offset -8388510830016 s2 freq -10000000 delay    425
phc2sys[2709.219]: eth6 sys offset -8388509828347 s2 freq -10000000 delay    425
phc2sys[2709.319]: eth6 sys offset -8388508826657 s2 freq -10000000 delay    425
phc2sys[2709.419]: eth6 sys offset -8388507825031 s2 freq -10000000 delay    420
phc2sys[2709.520]: eth6 sys offset -8388506823428 s2 freq -10000000 delay    425
phc2sys[2709.620]: eth6 sys offset -8388505821766 s2 freq -10000000 delay    425
phc2sys[2709.720]: eth6 sys offset -8388504819831 s2 freq -10000000 delay    420
phc2sys[2709.820]: eth6 sys offset -8388503818184 s2 freq -10000000 delay    425
phc2sys[2709.920]: eth6 sys offset -8388502816475 s2 freq -10000000 delay    420
phc2sys[2710.020]: eth6 sys offset -8388501814991 s2 freq -10000000 delay    420
phc2sys[2710.121]: eth6 sys offset -8388500813331 s2 freq -10000000 delay    420
phc2sys[2710.221]: eth6 sys offset -8388499811752 s2 freq -10000000 delay    425
phc2sys[2710.321]: eth6 sys offset -8388498810063 s2 freq -10000000 delay    420
phc2sys[2710.421]: eth6 sys offset -8388497808416 s2 freq -10000000 delay    425
phc2sys[2710.521]: eth6 sys offset -8388496806891 s2 freq -10000000 delay    425
phc2sys[2710.622]: eth6 sys offset -8388495805136 s2 freq -10000000 delay    425
phc2sys[2710.722]: eth6 sys offset -8388494803171 s2 freq -10000000 delay    420
phc2sys[2710.822]: eth6 sys offset -8388493801520 s2 freq -10000000 delay    425
phc2sys[2710.922]: eth6 sys offset -8388492799882 s2 freq -10000000 delay    425
phc2sys[2711.022]: eth6 sys offset -8388491798036 s2 freq -10000000 delay    425
phc2sys[2711.122]: eth6 sys offset -8388490795774 s2 freq -10000000 delay    425
phc2sys[2711.223]: eth6 sys offset -8388489793879 s2 freq -10000000 delay    420
phc2sys[2711.323]: eth6 sys offset -8388488792091 s2 freq -10000000 delay    425
phc2sys[2711.423]: eth6 sys offset -8388487790371 s2 freq -10000000 delay    425
phc2sys[2711.523]: eth6 sys offset -8388486788690 s2 freq -10000000 delay    425
phc2sys[2711.623]: eth6 sys offset -8388485787031 s2 freq -10000000 delay    425
phc2sys[2711.724]: eth6 sys offset -8388484785175 s2 freq -10000000 delay    420
phc2sys[2711.824]: eth6 sys offset -8388483783328 s2 freq -10000000 delay    425
phc2sys[2711.924]: eth6 sys offset -8388482780456 s2 freq -10000000 delay    425
phc2sys[2712.024]: eth6 sys offset -8388481778555 s2 freq -10000000 delay    425
phc2sys[2712.124]: eth6 sys offset -8388480776737 s2 freq -10000000 delay    420
phc2sys[2712.225]: eth6 sys offset -8388479774930 s2 freq -10000000 delay    425
phc2sys[2712.325]: eth6 sys offset -8388478773178 s2 freq -10000000 delay    425
phc2sys[2712.425]: eth6 sys offset -8388477771500 s2 freq -10000000 delay    425
phc2sys[2712.525]: eth6 sys offset -8388476769896 s2 freq -10000000 delay    425
phc2sys[2712.625]: eth6 sys offset -8388475768202 s2 freq -10000000 delay    425
phc2sys[2712.726]: eth6 sys offset -8388474766210 s2 freq -10000000 delay    425
phc2sys[2712.826]: eth6 sys offset -8388473764504 s2 freq -10000000 delay    425
phc2sys[2712.926]: eth6 sys offset -8388472762800 s2 freq -10000000 delay    425
phc2sys[2713.026]: eth6 sys offset -8388471761151 s2 freq -10000000 delay    420
phc2sys[2713.126]: eth6 sys offset -8388470759507 s2 freq -10000000 delay    425
phc2sys[2713.226]: eth6 sys offset -8388469757827 s2 freq -10000000 delay    420
phc2sys[2713.327]: eth6 sys offset -8388468756204 s2 freq -10000000 delay    425
phc2sys[2713.427]: eth6 sys offset -8388467754600 s2 freq -10000000 delay    425
phc2sys[2713.527]: eth6 sys offset -8388466752921 s2 freq -10000000 delay    425
phc2sys[2713.627]: eth6 sys offset -8388465751267 s2 freq -10000000 delay    425
phc2sys[2713.727]: eth6 sys offset -8388464749352 s2 freq -10000000 delay    425
phc2sys[2713.827]: eth6 sys offset -8388463747570 s2 freq -10000000 delay    420
phc2sys[2713.928]: eth6 sys offset -8388462745316 s2 freq -10000000 delay    425
phc2sys[2714.028]: eth6 sys offset -8388461743195 s2 freq -10000000 delay    420
phc2sys[2714.128]: eth6 sys offset -8388460740983 s2 freq -10000000 delay    420
phc2sys[2714.228]: eth6 sys offset -8388459739140 s2 freq -10000000 delay    425
phc2sys[2714.328]: eth6 sys offset -8388458737387 s2 freq -10000000 delay    420
phc2sys[2714.429]: eth6 sys offset -8388457735854 s2 freq -10000000 delay    425
phc2sys[2714.529]: eth6 sys offset -8388456734307 s2 freq -10000000 delay    420
phc2sys[2714.629]: eth6 sys offset -8388455732664 s2 freq -10000000 delay    425
phc2sys[2714.729]: eth6 sys offset -8388454730743 s2 freq -10000000 delay    425
phc2sys[2714.829]: eth6 sys offset -8388453729027 s2 freq -10000000 delay    425
phc2sys[2714.930]: eth6 sys offset -8388452727311 s2 freq -10000000 delay    425
phc2sys[2715.030]: eth6 sys offset -8388451725747 s2 freq -10000000 delay    420
phc2sys[2715.130]: eth6 sys offset -8388450724140 s2 freq -10000000 delay    425
phc2sys[2715.230]: eth6 sys offset -8388449722509 s2 freq -10000000 delay    425
phc2sys[2715.330]: eth6 sys offset -8388448720800 s2 freq -10000000 delay    425
phc2sys[2715.430]: eth6 sys offset -8388447719108 s2 freq -10000000 delay    425
phc2sys[2715.531]: eth6 sys offset -8388446717552 s2 freq -10000000 delay    425
phc2sys[2715.631]: eth6 sys offset -8388445715955 s2 freq -10000000 delay    425
phc2sys[2715.731]: eth6 sys offset -8388444714116 s2 freq -10000000 delay    425
phc2sys[2715.831]: eth6 sys offset -8388443712499 s2 freq -10000000 delay    420
phc2sys[2715.931]: eth6 sys offset -8388442710906 s2 freq -10000000 delay    425
phc2sys[2716.031]: eth6 sys offset -8388441709276 s2 freq -10000000 delay    425
phc2sys[2716.132]: eth6 sys offset -8388440707716 s2 freq -10000000 delay    425
phc2sys[2716.232]: eth6 sys offset -8388439706112 s2 freq -10000000 delay    420
phc2sys[2716.332]: eth6 sys offset -8388438704483 s2 freq -10000000 delay    420
phc2sys[2716.432]: eth6 sys offset -8388437702757 s2 freq -10000000 delay    420
phc2sys[2716.532]: eth6 sys offset -8388436701088 s2 freq -10000000 delay    425
phc2sys[2716.632]: eth6 sys offset -8388435699455 s2 freq -10000000 delay    420
phc2sys[2716.733]: eth6 sys offset -8388434697675 s2 freq -10000000 delay    425

Hello,

thank you for update.

Nick Saulnier said:

Fix :-

However by adding  the below line to phc2sys configuration file and passing the new configuration  with -f option while running phc2sys, the clock jumping issue was not seen.

step_threshold     0.0002

I ran phc2sys for more than 2 days (48+ hours)  and I didn't see any clock jump issue during this time.

This "fix" is only way how to cover up real bug.

1. How I mentioned in post, the clock jump is not related to clock synchronization. https://e2e.ti.com/support/processors-group/processors/f/processors-forum/1037027/tmdx654idkevm-clock-jump-of-ptp-device-for-icssg/4145195

2. I thin the configuration of "step_threshold" causes that the phc2sys set the clock back after 2 synchronization steps. Did you check whole output for "clockcheck" message, or you did only check offset values after 2 days? See output with configured "step_threshold"

root@am65xx-evm:~/linuxptp-3.1.1# ./phc2sys -s CLOCK_REALTIME -c eth1 -O 0 -R 10 -S 0.00002 -m
phc2sys[1550.383]: eth1 sys offset 17612133791 s0 freq   +1408 delay    425
phc2sys[1550.484]: eth1 sys offset 17612133649 s1 freq      -3 delay    425
phc2sys[1550.585]: eth1 sys offset     -2931 s2 freq   -2934 delay    425
phc2sys[1550.685]: eth1 sys offset     -2640 s2 freq   -3523 delay    425
phc2sys[1550.785]: eth1 sys offset     -2287 s2 freq   -3962 delay    425
phc2sys[1550.885]: eth1 sys offset     -1891 s2 freq   -4252 delay    425
...
phc2sys[1555.899]: eth1 sys offset       452 s2 freq    +211 delay    420
phc2sys[1556.000]: eth1 sys offset       431 s2 freq    +326 delay    425
phc2sys[1556.100]: eth1 sys offset       400 s2 freq    +424 delay    425
phc2sys[1556.200]: eth1 sys offset       362 s2 freq    +506 delay    425
phc2sys[1556.301]: clockcheck: clock jumped backward or running slower than expected!
phc2sys[1556.301]: eth1 sys offset -8388607999688 s0 freq    +506 delay    425
phc2sys[1556.402]: eth1 sys offset -8388607999741 s1 freq    -275 delay    425
phc2sys[1556.502]: eth1 sys offset     -2977 s2 freq   -3252 delay    425
phc2sys[1556.603]: eth1 sys offset     -2652 s2 freq   -3821 delay    420
phc2sys[1556.703]: eth1 sys offset     -2271 s2 freq   -4235 delay    425
phc2sys[1556.803]: eth1 sys offset     -1845 s2 freq   -4490 delay    425
phc2sys[1556.903]: eth1 sys offset     -1398 s2 freq   -4597 delay    425
phc2sys[1557.004]: eth1 sys offset      -939 s2 freq   -4557 delay    425
phc2sys[1557.104]: eth1 sys offset      -483 s2 freq   -4383 delay    425
phc2sys[1557.204]: eth1 sys offset       -49 s2 freq   -4094 delay    425
phc2sys[1557.304]: eth1 sys offset       363 s2 freq   -3697 delay    425

For the clarification I do not able to verify behavior, until I have the same version. But, based on provided information, the bug still exists also on your version.

Best regards,
Lukas

Hello Lukas,

I have passed your feedback along to the developer. Please ping the thread if I have not provided a response (or if they have not responded) within a couple of days.

Regards,

Nick

Hello Lukas,

Double-checking: what software are you testing on?

The developer has run tests on both SDK 8.4 (ti-linux-kernel 5.10.140, mentioned in the above response) and SDK 8.3 (ti-linux-kernel 5.10.109, mentioned below). I'll provide a link to both versions of the Linux kernel.
SDK 8.4: https://git.ti.com/cgit/ti-linux-kernel/ti-linux-kernel/tag/?h=08.04.01.003
ti-linux-kernel 5.10.109: https://git.ti.com/cgit/ti-linux-kernel/ti-linux-kernel/commit/?h=ti-linux-5.10.y&id=d9c5818a0bc09e4cc9fe663edb69e4d6cdae4f70

Have you tried testing with either of these Linux releases? Or have you only tested on SDK 8.2?

If you have not tried testing with a later release, can you please try testing with one of the above releases to see if the issue is resolved?

Additional follow-up from developer:

>> Did you check whole output for "clockcheck" message, or you did only check offset values after 2 days? See output with configured "step_threshold"

I checked the entire output of clockcheck or jumped message. Still there was no clockcheck or jumped messege after 2 days.

I'll try to check again tomorrow if the issue is still coming.

....

[the next day]

I tried reproducing the issue again. The issue is not seen after providing step threshold as 0.00002.

I am using ti-linux-kernel 5.10.109 branch and on this branch by providing step threshold as 0.00002, the clocks are getting synchronized as expected and I don't see any clock jumps as well.

Based on this observation the issue does not exist on the 5.10.109 branch with the provided fix (step threshold as 0.00002)

Logs :-

root@am65xx-evm:~ phc2sys -s CLOCK_REALTIME -c eth1 -O 0 -R 10 -S 0.00002 -m

phc2sys[263.794]: eth6 sys offset -138636624 s0 freq      +0 delay    425
phc2sys[263.896]: eth6 sys offset -138636624 s1 freq      +0 delay    425
phc2sys[263.996]: eth6 sys offset     -3182 s2 freq   -3182 delay    425
phc2sys[264.096]: eth6 sys offset     -2866 s2 freq   -3821 delay    425
phc2sys[264.196]: eth6 sys offset     -2484 s2 freq   -4298 delay    425
phc2sys[264.297]: eth6 sys offset     -2057 s2 freq   -4617 delay    425
phc2sys[264.397]: eth6 sys offset     -1599 s2 freq   -4776 delay    425
phc2sys[264.497]: eth6 sys offset     -1124 s2 freq   -4780 delay    425
phc2sys[264.597]: eth6 sys offset      -646 s2 freq   -4640 delay    425
phc2sys[264.697]: eth6 sys offset      -184 s2 freq   -4371 delay    425

... .... ...

phc2sys[324.703]: eth6 sys offset        10 s2 freq     +45 delay    420
phc2sys[324.803]: eth6 sys offset         6 s2 freq     +44 delay    420
phc2sys[324.904]: eth6 sys offset         2 s2 freq     +42 delay    420
phc2sys[325.004]: eth6 sys offset        -2 s2 freq     +39 delay    420
phc2sys[325.104]: eth6 sys offset        -1 s2 freq     +39 delay    425

Hello Nick,

I retested the issue on newer kernel tagged like a 08.04.01.003-rt (version what you mention for test, with RT patches) 
Base image for kernel update I take from  PROCESSOR-SDK-LINUX-RT-AM65X_08.02.00.01

See my log:

U-Boot SPL 2021.01-g44a87e3ab8 (Mar 24 2022 - 06:00:43 +0000)
SYSFW ABI: 3.1 (firmware rev 0x0016 '22.1.1--v2022.01 (Terrific Llam')
SPL initial stack usage: 1416 bytes
Trying to boot from MMC2
spl_load_fit_image: Skip load 'dm': image size is 0!
Starting ATF on ARM64 core...

NOTICE:  BL31: v2.5(release):08.01.00.006-dirty
NOTICE:  BL31: Built : 05:29:41, Mar 24 2022

U-Boot SPL 2021.01-g44a87e3ab8 (Mar 24 2022 - 05:30:44 +0000)
SYSFW ABI: 3.1 (firmware rev 0x0016 '22.1.1--v2022.01 (Terrific Llam')
Detected: Silicon SR2.0
i2c_omap i2c@42120000: pinctrl_select_state_full: uclass_get_device_by_phandle_id: err=-19
Detected: AM6-IDKAPPEVM rev A
Detected: SER-PCIE2LEVM rev A
Trying to boot from MMC2


U-Boot 2021.01-g44a87e3ab8 (Mar 24 2022 - 05:30:44 +0000)

SoC:   AM65X SR2.0
Model: Texas Instruments AM654 Base Board
Board: AM6-COMPROCEVM rev A
DRAM:  4 GiB
MMC:   sdhci@4f80000: 0, sdhci@4fa0000: 1
Loading Environment from MMC... OK
In:    serial
Out:   serial
Err:   serial
am65_cpsw_nuss ethernet@46000000: K3 CPSW: nuss_ver: 0x6BA00102 cpsw_ver: 0x6BA80102 ale_ver: 0x00293904 Ports:1 mdio_freq:1000000
Detected: Silicon SR2.0
Detected: AM6-IDKAPPEVM rev A
Detected: SER-PCIE2LEVM rev A
Net:   eth1: icssg2-eth, eth0: ethernet@46000000port@1
Hit any key to stop autoboot:  0
switch to partitions #0, OK
mmc1 is current device
SD/MMC found on device 1
Failed to load 'boot.scr'
1011 bytes read in 4 ms (246.1 KiB/s)
Loaded env from uEnv.txt
Importing environment from mmc1 ...
Running uenvcmd ...
Using board_name = am65x
18762240 bytes read in 776 ms (23.1 MiB/s)
64339 bytes read in 7 ms (8.8 MiB/s)
11268 bytes read in 5 ms (2.1 MiB/s)
2333 bytes read in 5 ms (455.1 KiB/s)
## Flattened Device Tree blob at 88000000
   Booting using the fdt blob at 0x88000000
   Loading Device Tree to 000000008feed000, end 000000008fffffff ... OK

Starting kernel ...

[    0.000000] Booting Linux on physical CPU 0x0000000000 [0x410fd034]
[    0.000000] Linux version 5.10.131-rt72 (liballuk@IPC847D) (aarch64-none-linux-gnu-gcc (GNU Toolchain for the A-profile Architecture 10.3-2021.07 (arm-10.29)) 10.3.1 20210621, GNU ld (GNU Toolchain for the A-profile Architecture 10.3-2021.07 (arm-10.29)) 2.36.1.20210621) #1 SMP PREEMPT Mon Oct 24 10:25:51 CEST 2022
[    0.000000] Machine model: Texas Instruments AM654 Base Board
[    0.000000] earlycon: ns16550a0 at MMIO32 0x0000000002800000 (options '')
[    0.000000] printk: bootconsole [ns16550a0] enabled
[    0.000000] efi: UEFI not found.
[    0.000000] Reserved memory: created DMA memory pool at 0x00000000a0000000, size 1 MiB
[    0.000000] OF: reserved mem: initialized node r5f-dma-memory@a0000000, compatible id shared-dma-pool
[    0.000000] Reserved memory: created DMA memory pool at 0x00000000a0100000, size 15 MiB
[    0.000000] OF: reserved mem: initialized node r5f-memory@a0100000, compatible id shared-dma-pool
[    0.000000] Reserved memory: created DMA memory pool at 0x00000000a1000000, size 1 MiB
[    0.000000] OF: reserved mem: initialized node r5f-dma-memory@a1000000, compatible id shared-dma-pool
[    0.000000] Reserved memory: created DMA memory pool at 0x00000000a1100000, size 15 MiB
[    0.000000] OF: reserved mem: initialized node r5f-memory@a1100000, compatible id shared-dma-pool
[    0.000000] Zone ranges:
[    0.000000]   DMA      [mem 0x0000000080000000-0x00000000ffffffff]
[    0.000000]   DMA32    empty
[    0.000000]   Normal   [mem 0x0000000100000000-0x00000008ffffffff]
[    0.000000] Movable zone start for each node
[    0.000000] Early memory node ranges
[    0.000000]   node   0: [mem 0x0000000080000000-0x000000009e7fffff]
[    0.000000]   node   0: [mem 0x000000009e800000-0x00000000a20fffff]
[    0.000000]   node   0: [mem 0x00000000a2100000-0x00000000ffffffff]
[    0.000000]   node   0: [mem 0x0000000880000000-0x00000008ffffffff]
[    0.000000] Initmem setup node 0 [mem 0x0000000080000000-0x00000008ffffffff]
[    0.000000] On node 0 totalpages: 1048576
[    0.000000]   DMA zone: 8192 pages used for memmap
[    0.000000]   DMA zone: 0 pages reserved
[    0.000000]   DMA zone: 524288 pages, LIFO batch:63
[    0.000000]   Normal zone: 8192 pages used for memmap
[    0.000000]   Normal zone: 524288 pages, LIFO batch:63
[    0.000000] cma: Reserved 512 MiB at 0x00000000e0000000
[    0.000000] psci: probing for conduit method from DT.
[    0.000000] psci: PSCIv1.1 detected in firmware.
[    0.000000] psci: Using standard PSCI v0.2 function IDs
[    0.000000] psci: Trusted OS migration not required
[    0.000000] psci: SMC Calling Convention v1.2
[    0.000000] percpu: Embedded 18 pages/cpu s33816 r8192 d31720 u73728
[    0.000000] pcpu-alloc: s33816 r8192 d31720 u73728 alloc=18*4096
[    0.000000] pcpu-alloc: [0] 0 [0] 1 [0] 2 [0] 3
[    0.000000] Detected VIPT I-cache on CPU0
[    0.000000] CPU features: detected: ARM erratum 845719
[    0.000000] CPU features: detected: GIC system register CPU interface
[    0.000000] Built 1 zonelists, mobility grouping on.  Total pages: 1032192
[    0.000000] Kernel command line: console=ttyS2,115200n8 earlycon=ns16550a,mmio32,0x02800000 mtdparts=47040000.spi.0:512k(ospi.tiboot3),2m(ospi.tispl),4m(ospi.u-boot),128k(ospi.env),128k(ospi.env.backup),1m(ospi.sysfw),57216k@8m(ospi.rootfs),128k(ospi.phypattern) root=PARTUUID=83b8ba56-02 rw rootfstype=ext4 rootwait
[    0.000000] Dentry cache hash table entries: 524288 (order: 10, 4194304 bytes, linear)
[    0.000000] Inode-cache hash table entries: 262144 (order: 9, 2097152 bytes, linear)
[    0.000000] mem auto-init: stack:off, heap alloc:off, heap free:off
[    0.000000] software IO TLB: mapped [mem 0x00000000dc000000-0x00000000e0000000] (64MB)
[    0.000000] Memory: 3446488K/4194304K available (11072K kernel code, 1170K rwdata, 4152K rodata, 1792K init, 420K bss, 223528K reserved, 524288K cma-reserved)
[    0.000000] SLUB: HWalign=64, Order=0-3, MinObjects=0, CPUs=4, Nodes=1
[    0.000000] rcu: Preemptible hierarchical RCU implementation.
[    0.000000] rcu:     RCU event tracing is enabled.
[    0.000000] rcu:     RCU restricting CPUs from NR_CPUS=256 to nr_cpu_ids=4.
[    0.000000]  Trampoline variant of Tasks RCU enabled.
[    0.000000] rcu: RCU calculated value of scheduler-enlistment delay is 25 jiffies.
[    0.000000] rcu: Adjusting geometry for rcu_fanout_leaf=16, nr_cpu_ids=4
[    0.000000] NR_IRQS: 64, nr_irqs: 64, preallocated irqs: 0
[    0.000000] GICv3: GIC: Using split EOI/Deactivate mode
[    0.000000] GICv3: 960 SPIs implemented
[    0.000000] GICv3: 0 Extended SPIs implemented
[    0.000000] GICv3: Distributor has no Range Selector support
[    0.000000] GICv3: 16 PPIs implemented
[    0.000000] GICv3: CPU0: found redistributor 0 region 0:0x0000000001880000
[    0.000000] ITS [mem 0x01820000-0x0182ffff]
[    0.000000] GIC: enabling workaround for ITS: Socionext Synquacer pre-ITS
[    0.000000] ITS@0x0000000001820000: Devices Table too large, reduce ids 20->19
[    0.000000] ITS@0x0000000001820000: allocated 524288 Devices @880800000 (flat, esz 8, psz 64K, shr 0)
[    0.000000] ITS: using cache flushing for cmd queue
[    0.000000] GICv3: using LPI property table @0x0000000880030000
[    0.000000] GIC: using cache flushing for LPI property table
[    0.000000] GICv3: CPU0: using allocated LPI pending table @0x0000000880040000
[    0.000000] arch_timer: cp15 timer(s) running at 200.00MHz (phys).
[    0.000000] clocksource: arch_sys_counter: mask: 0xffffffffffffff max_cycles: 0x2e2049d3e8, max_idle_ns: 440795210634 ns
[    0.000001] sched_clock: 56 bits at 200MHz, resolution 5ns, wraps every 4398046511102ns
[    0.008713] Console: colour dummy device 80x25
[    0.013326] Calibrating delay loop (skipped), value calculated using timer frequency.. 400.00 BogoMIPS (lpj=800000)
[    0.024048] pid_max: default: 32768 minimum: 301
[    0.028900] LSM: Security Framework initializing
[    0.033713] Mount-cache hash table entries: 8192 (order: 4, 65536 bytes, linear)
[    0.041328] Mountpoint-cache hash table entries: 8192 (order: 4, 65536 bytes, linear)
[    0.051442] rcu: Hierarchical SRCU implementation.
[    0.056742] Platform MSI: msi-controller@1820000 domain created
[    0.063067] PCI/MSI: /bus@100000/interrupt-controller@1800000/msi-controller@1820000 domain created
[    0.072480] EFI services will not be available.
[    0.077460] smp: Bringing up secondary CPUs ...
[    0.083241] Detected VIPT I-cache on CPU1
[    0.087390] GICv3: CPU1: found redistributor 1 region 0:0x00000000018a0000
[    0.094455] GICv3: CPU1: using allocated LPI pending table @0x0000000880050000
[    0.101917] CPU1: Booted secondary processor 0x0000000001 [0x410fd034]
[    0.109974] Detected VIPT I-cache on CPU2
[    0.114139] GICv3: CPU2: found redistributor 100 region 0:0x00000000018c0000
[    0.121383] GICv3: CPU2: using allocated LPI pending table @0x0000000880060000
[    0.128853] CPU2: Booted secondary processor 0x0000000100 [0x410fd034]
[    0.136866] Detected VIPT I-cache on CPU3
[    0.141003] GICv3: CPU3: found redistributor 101 region 0:0x00000000018e0000
[    0.148241] GICv3: CPU3: using allocated LPI pending table @0x0000000880070000
[    0.155688] CPU3: Booted secondary processor 0x0000000101 [0x410fd034]
[    0.162547] smp: Brought up 1 node, 4 CPUs
[    0.166786] SMP: Total of 4 processors activated.
[    0.171623] CPU features: detected: 32-bit EL0 Support
[    0.176921] CPU features: detected: CRC32 instructions
[    0.197796] CPU: All CPU(s) started at EL2
[    0.202042] alternatives: patching kernel code
[    0.208077] devtmpfs: initialized
[    0.223274] KASLR disabled due to lack of seed
[    0.228105] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 7645041785100000 ns
[    0.238130] futex hash table entries: 1024 (order: 4, 65536 bytes, linear)
[    0.263091] pinctrl core: initialized pinctrl subsystem
[    0.269208] DMI not present or invalid.
[    0.273959] NET: Registered protocol family 16
[    0.280339] DMA: preallocated 512 KiB GFP_KERNEL pool for atomic allocations
[    0.287822] DMA: preallocated 512 KiB GFP_KERNEL|GFP_DMA pool for atomic allocations
[    0.296135] DMA: preallocated 512 KiB GFP_KERNEL|GFP_DMA32 pool for atomic allocations
[    0.304895] thermal_sys: Registered thermal governor 'step_wise'
[    0.304903] thermal_sys: Registered thermal governor 'power_allocator'
[    0.305476] hw-breakpoint: found 6 breakpoint and 4 watchpoint registers.
[    0.325441] ASID allocator initialised with 65536 entries
[    0.375444] HugeTLB registered 1.00 GiB page size, pre-allocated 0 pages
[    0.382356] HugeTLB registered 32.0 MiB page size, pre-allocated 0 pages
[    0.389264] HugeTLB registered 2.00 MiB page size, pre-allocated 0 pages
[    0.396150] HugeTLB registered 64.0 KiB page size, pre-allocated 0 pages
[    0.404893] cryptd: max_cpu_qlen set to 1000
[    0.414048] k3-chipinfo 43000014.chipid: Family:AM65X rev:SR2.0 JTAGID[0x1bb5a02f] Detected
[    0.423354] vcc3v3_io: supplied by evm_12v0
[    0.429031] iommu: Default domain type: Translated
[    0.434455] SCSI subsystem initialized
[    0.438979] mc: Linux media interface: v0.10
[    0.443423] videodev: Linux video capture interface: v2.00
[    0.449165] pps_core: LinuxPPS API ver. 1 registered
[    0.454269] pps_core: Software ver. 5.3.6 - Copyright 2005-2007 Rodolfo Giometti <giometti@linux.it>
[    0.463664] PTP clock support registered
[    0.467731] EDAC MC: Ver: 3.0.0
[    0.472457] FPGA manager framework
[    0.476075] Advanced Linux Sound Architecture Driver Initialized.
[    0.483405] clocksource: Switched to clocksource arch_sys_counter
[    0.489926] VFS: Disk quotas dquot_6.6.0
[    0.494040] VFS: Dquot-cache hash table entries: 512 (order 0, 4096 bytes)
[    0.508705] NET: Registered protocol family 2
[    0.513573] IP idents hash table entries: 65536 (order: 7, 524288 bytes, linear)
[    0.523951] tcp_listen_portaddr_hash hash table entries: 2048 (order: 3, 32768 bytes, linear)
[    0.532882] TCP established hash table entries: 32768 (order: 6, 262144 bytes, linear)
[    0.541346] TCP bind hash table entries: 32768 (order: 7, 524288 bytes, linear)
[    0.549544] TCP: Hash tables configured (established 32768 bind 32768)
[    0.556529] UDP hash table entries: 2048 (order: 4, 65536 bytes, linear)
[    0.563550] UDP-Lite hash table entries: 2048 (order: 4, 65536 bytes, linear)
[    0.571198] NET: Registered protocol family 1
[    0.576501] RPC: Registered named UNIX socket transport module.
[    0.582623] RPC: Registered udp transport module.
[    0.587456] RPC: Registered tcp transport module.
[    0.592285] RPC: Registered tcp NFSv4.1 backchannel transport module.
[    0.598905] PCI: CLS 0 bytes, default 64
[    0.604045] hw perfevents: enabled with armv8_cortex_a53 PMU driver, 7 counters available
[    0.618866] Initialise system trusted keyrings
[    0.623713] workingset: timestamp_bits=46 max_order=20 bucket_order=0
[    0.635747] squashfs: version 4.0 (2009/01/31) Phillip Lougher
[    0.642448] NFS: Registering the id_resolver key type
[    0.647691] Key type id_resolver registered
[    0.651997] Key type id_legacy registered
[    0.656212] nfs4filelayout_init: NFSv4 File Layout Driver Registering...
[    0.663101] nfs4flexfilelayout_init: NFSv4 Flexfile Layout Driver Registering...
[    0.670909] 9p: Installing v9fs 9p2000 file system support
[    0.730080] Key type asymmetric registered
[    0.734299] Asymmetric key parser 'x509' registered
[    0.739351] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 243)
[    0.746953] io scheduler mq-deadline registered
[    0.751607] io scheduler kyber registered
[    0.758863] pinctrl-single 4301c000.pinctrl: 70 pins, size 280
[    0.765567] pinctrl-single 11c000.pinctrl: 185 pins, size 740
[    0.771656] pinctrl-single 11c2e8.pinctrl: 9 pins, size 36
[    0.784472] k3-ringacc 2b800000.ringacc: Failed to get MSI domain
[    0.790880] k3-ringacc 3c000000.ringacc: Failed to get MSI domain
[    0.801803] Serial: 8250/16550 driver, 10 ports, IRQ sharing enabled
[    0.828063] brd: module loaded
[    0.840376] loop: module loaded
[    0.844643] megasas: 07.714.04.00-rc1
[    0.853931] tun: Universal TUN/TAP device driver, 1.6
[    0.860029] igbvf: Intel(R) Gigabit Virtual Function Network Driver
[    0.866470] igbvf: Copyright (c) 2009 - 2012 Intel Corporation.
[    0.872615] sky2: driver version 1.30
[    0.877864] VFIO - User Level meta-driver version: 0.3
[    0.884485] i2c /dev entries driver
[    0.890123] sdhci: Secure Digital Host Controller Interface driver
[    0.896477] sdhci: Copyright(c) Pierre Ossman
[    0.901528] sdhci-pltfm: SDHCI platform and OF driver helper
[    0.909072] ledtrig-cpu: registered to indicate activity on CPUs
[    0.915376] ti-sci bus@100000:bus@28380000:bus@42040000:dmsc: invalid resource
[    0.923036] SMCCC: SOC_ID: ARCH_SOC_ID not implemented, skipping ....
[    0.931192] optee: probing for conduit method.
[    0.935802] optee: revision 3.12 (3d47a131)
[    0.936355] optee: initialized driver
[    0.947243] NET: Registered protocol family 17
[    0.952002] 9pnet: Installing 9P2000 support
[    0.956482] Key type dns_resolver registered
[    0.961251] printk: bootconsole [ns16550a0]: printing thread started
[    0.961305] Loading compiled-in X.509 certificates
[    0.973201] k3-ringacc 2b800000.ringacc: Failed to get MSI domain
[    0.973496] k3-ringacc 3c000000.ringacc: Failed to get MSI domain
[    0.980328] ti-sci bus@100000:bus@28380000:bus@42040000:dmsc: invalid resource
[    0.980667] ti-sci bus@100000:bus@28380000:bus@42040000:dmsc: ABI: 3.1 (firmware rev 0x0016 '22.1.1--v2022.01 (Terrific Llam')
[    1.064141] omap_i2c 42120000.i2c: bus 0 rev0.12 at 400 kHz
[    1.065460] omap_i2c 40b00000.i2c: bus 1 rev0.12 at 100 kHz
[    1.067655] pca953x 2-0021: supply vcc not found, using dummy regulator
[    1.067794] pca953x 2-0021: using no AI
[    1.092182] omap_i2c 2000000.i2c: bus 2 rev0.12 at 400 kHz
[    1.093312] omap_i2c 2010000.i2c: bus 3 rev0.12 at 400 kHz
[    1.094355] omap_i2c 2020000.i2c: bus 4 rev0.12 at 400 kHz
[    1.095323] omap_i2c 2030000.i2c: bus 5 rev0.12 at 100 kHz
[    1.096686] ti-sci-intr bus@100000:bus@28380000:bus@42040000:interrupt-controller2: Interrupt Router 156 domain created
[    1.096945] ti-sci-intr bus@100000:interrupt-controller0: Interrupt Router 100 domain created
[    1.097172] ti-sci-intr bus@100000:main-navss:interrupt-controller1: Interrupt Router 182 domain created
[    1.097566] ti-sci-inta 33d00000.interrupt-controller: Interrupt Aggregator domain 179 created
[    1.111263] keystone-pcie 5500000.pcie: host bridge /bus@100000/pcie@5500000 ranges:
[    1.111299] OF: /bus@100000/pcie@5500000: Missing device_type
[    1.111334] keystone-pcie 5500000.pcie:       IO 0x0010020000..0x001002ffff -> 0x0000000000
[    1.111360] keystone-pcie 5500000.pcie:      MEM 0x0010030000..0x0017ffffff -> 0x0010030000
[    2.111942] keystone-pcie 5500000.pcie: Phy link never came up
[    2.112131] keystone-pcie 5500000.pcie: PCI host bridge to bus 0000:00
[    2.112143]▒▒▒▒}▒▒́▒▒▒▒҂▒▒▒▒▒с▒́▒▒ͽ▒ɍ▒▒▒%▒́▒▒j2▒u5R▒[    2.112155] pci_bus 0000:00: root bus resource [io  0x0000-0xffff]
[    2.134100] printk: console [ttyS2]: printing thread started
[    2.112163] pci_bus 0000:00: root bus resource [mem 0x10030000-0x17ffffff]
[    2.134124] printk: console [ttyS2] enabled
[    2.134130] printk: bootconsole [ns16550a0] disabled
[    2.153301] printk: bootconsole [ns16550a0]: printing thread stopped
[    2.157951] 2810000.serial: ttyS3 at MMIO 0x2810000 (irq = 30, base_baud = 3000000) is a 8250
[    2.162877] 2820000.serial: ttyS4 at MMIO 0x2820000 (irq = 31, base_baud = 3000000) is a 8250
[    2.199795] davinci_mdio 46000f00.mdio: Configuring MDIO in manual mode
[    2.239430] davinci_mdio 46000f00.mdio: davinci mdio revision 9.7, bus freq 1000000
[    2.241617] davinci_mdio 46000f00.mdio: phy[0]: device 46000f00.mdio:00, driver TI DP83867
[    2.241733] am65-cpsw-nuss 46000000.ethernet: initializing am65 cpsw nuss version 0x6BA00102, cpsw version 0x6BA80102 Ports: 2 quirks:00000000
[    2.251754] am65-cpts 310d0000.cpts: CPTS ver 0x4e8a010b, freq:200000000, add_val:4 pps:0
[    2.281461] mmc0: CQHCI version 5.10
[    2.296423] pca953x 0-0039: supply vcc not found, using dummy regulator
[    2.296602] pca953x 0-0039: using no AI
[    2.320016] mmc0: SDHCI controller on 4f80000.mmc [4f80000.mmc] using ADMA 64-bit
[    2.321385] omap-mailbox 31f80000.mailbox: omap mailbox rev 0x66fc7100
[    2.321953] omap-mailbox 31f81000.mailbox: omap mailbox rev 0x66fc7100
[    2.323887] ti-udma 285c0000.dma-controller: Channels: 28 (tchan: 14, rchan: 14, gp-rflow: 16)
[    2.347942] ti-udma 31150000.dma-controller: Channels: 119 (tchan: 53, rchan: 66, gp-rflow: 64)
[    2.366059] spi-nor spi7.0: mt35xu512aba (65536 Kbytes)
[    2.366105] 8 cmdlinepart partitions found on MTD device 47040000.spi.0
[    2.366112] Creating 8 MTD partitions on "47040000.spi.0":
[    2.366120] 0x000000000000-0x000000080000 : "ospi.tiboot3"
[    2.367673] 0x000000080000-0x000000280000 : "ospi.tispl"
[    2.368943] 0x000000280000-0x000000680000 : "ospi.u-boot"
[    2.370231] 0x000000680000-0x0000006a0000 : "ospi.env"
[    2.371497] 0x0000006a0000-0x0000006c0000 : "ospi.env.backup"
[    2.372735] 0x0000006c0000-0x0000007c0000 : "ospi.sysfw"
[    2.373997] 0x000000800000-0x000003fe0000 : "ospi.rootfs"
[    2.375200] 0x000003fe0000-0x000004000000 : "ospi.phypattern"
[    2.435638] spi-nor spi9.0: n25q128a13 (16384 Kbytes)
[    2.439642] davinci_mdio 46000f00.mdio: Configuring MDIO in manual mode
[    2.462009] mmc0: Command Queue Engine enabled
[    2.462036] mmc0: new HS200 MMC card at address 0001
[    2.462859] mmcblk0: mmc0:0001 S0J56X 14.8 GiB
[    2.463118] mmcblk0boot0: mmc0:0001 S0J56X partition 1 31.5 MiB
[    2.463352] mmcblk0boot1: mmc0:0001 S0J56X partition 2 31.5 MiB
[    2.463708] mmcblk0rpmb: mmc0:0001 S0J56X partition 3 4.00 MiB, chardev (237:0)
[    2.479507] davinci_mdio 46000f00.mdio: davinci mdio revision 9.7, bus freq 1000000
[    2.481889] davinci_mdio 46000f00.mdio: phy[0]: device 46000f00.mdio:00, driver TI DP83867
[    2.482030] am65-cpsw-nuss 46000000.ethernet: initializing am65 cpsw nuss version 0x6BA00102, cpsw version 0x6BA80102 Ports: 2 quirks:00000000
[    2.504566] am65-cpsw-nuss 46000000.ethernet: set new flow-id-base 48
[    2.532019] am65-cpsw-nuss 46000000.ethernet: initialized cpsw ale version 1.4
[    2.532033] am65-cpsw-nuss 46000000.ethernet: ALE Table size 64
[    2.533182] am65-cpsw-nuss 46000000.ethernet: CPTS ver 0x4e8a010b, freq:200000000, add_val:4 pps:0
[    2.558066] vdd_mmc1_sd: supplied by vcc3v3_io
[    2.559859] debugfs: Directory 'pd:121' with parent 'pm_genpd' already present!
[    2.559914] debugfs: Directory 'pd:120' with parent 'pm_genpd' already present!
[    2.560439] mmc1: CQHCI version 5.10
[    2.562580] input: gpio-keys as /devices/platform/gpio-keys/input/input0
[    2.583661] ALSA device list:
[    2.583670]   No soundcards found.
[    3.340491] mmc1: SDHCI controller on 4fa0000.mmc [4fa0000.mmc] using ADMA 64-bit
[    3.341055] Waiting for root device PARTUUID=83b8ba56-02...
[    3.397853] mmc1: new ultra high speed SDR104 SDHC card at address aaaa
[    3.398603] mmcblk1: mmc1:aaaa SA08G 7.40 GiB
[    3.400460]  mmcblk1: p1 p2
[    3.727352] EXT4-fs (mmcblk1p2): 4 orphan inodes deleted
[    3.727377] EXT4-fs (mmcblk1p2): recovery complete
[    3.746976] EXT4-fs (mmcblk1p2): mounted filesystem with ordered data mode. Opts: (null)
[    3.747075] VFS: Mounted root (ext4 filesystem) on device 179:98.
[    3.757581] devtmpfs: mounted
[    3.758886] Freeing unused kernel memory: 1792K
[    3.759056] Run /sbin/init as init process
[    3.878683] systemd[1]: System time before build time, advancing clock.
[    3.935104] NET: Registered protocol family 10
[    3.936377] Segment Routing with IPv6
[    3.953049] systemd[1]: systemd 244.5+ running in system mode. (+PAM -AUDIT -SELINUX +IMA -APPARMOR -SMACK +SYSVINIT +UTMP -LIBCRYPTSETUP -GCRYPT -GNUTLS +ACL +XZ -LZ4 -SECCOMP +BLKID -ELFUTILS +KMOD -IDN2 -IDN -PCRE2 default-hierarchy=hybrid)
[    3.953655] systemd[1]: Detected architecture arm64.

Welcome to Arago 2021.09!

[    4.024841] systemd[1]: Set hostname to <am65xx-evm>.
[    4.363580] systemd[1]: /lib/systemd/system/docker.socket:6: ListenStream= references a path below legacy directory /var/run/, updating /var/run/docker.sock → /run/docker.sock; please update the unit file accordingly.
[    4.487378] random: systemd: uninitialized urandom read (16 bytes read)
[    4.487763] systemd[1]: system-getty.slice: unit configures an IP firewall, but the local system does not support BPF/cgroup firewalling.
[    4.487783] systemd[1]: (This warning is only shown for the first unit using IP firewalling.)
[    4.491993] systemd[1]: Created slice system-getty.slice.
[  OK  ] Created slice system-getty.slice.
[  OK  ] Created slice system-serial\x2dgett[    4.539608] random: systemd: uninitialized urandom read (16 bytes read)
y.slice.
[    4.541599] systemd[1]: Created slice system-serial\x2dgetty.slice.
[  OK  ] Created slice User and Session Slic[    4.561573] random: systemd: uninitialized urandom read (16 bytes read)
e.
[    4.563231] systemd[1]: Created slice User and Session Slice.
[  OK  ] Started Dispatch Password …ts to [    4.582458] systemd[1]: Started Dispatch Password Requests to Console Directory Watch.
Console Directory Watch.
[  OK  ] Started Forward Password R…uests [    4.607757] systemd[1]: Started Forward Password Requests to Wall Directory Watch.
to Wall Directory Watch.
[  OK  ] Reached target Paths.
[    4.631739] systemd[1]: Reached target Paths.
[  OK  ] Reached target Remote File Systems systemd[1]: Reached target Remote File Systems.
[0m.
[  OK  ] Reached target Slices.
[    4.663544] systemd[1]: Reached target Slices.
[  OK  ] Reached target Swap.
[    4.675583] systemd[1]: Reached target Swap.
[  OK  ] Listening on RPCbind Server Activat[    4.690211] systemd[1]: Listening on RPCbind Server Activation Socket.
ion Socket.
[  OK  ] Reached target RPC Port Mapper.[    4.711657] systemd[1]: Reached target RPC Port Mapper.

[  OK  ] Listening on Process Core Dump Sock[    4.738547] systemd[1]: Listening on Process Core Dump Socket.
et.
[  OK  ] Listening on initctl Compatibility [    4.759868] systemd[1]: Listening on initctl Compatibility Named Pipe.
Named Pipe.
[  OK  ] Listening on Journal Socket (/dev/l[    4.794224] systemd[1]: Condition check resulted in Journal Audit Socket being skipped.
og).
[    4.795040] systemd[1]: Listening on Journal Socket (/dev/log).
[  OK  ] Listening on Journal Socket.
[    4.816354] systemd[1]: Listening on Journal Socket.
[  OK  ] Listening on Network Service Netlin[    4.828309] systemd[1]: Listening on Network Service Netlink Socket.
k Socket.
[  OK  ] Listening on udev Control Socket    4.852081] systemd[1]: Listening on udev Control Socket.
m.
[  OK  ] Listening on udev Kernel Socket[    4.871904] systemd[1]: Listening on udev Kernel Socket.
.
         Mounting Huge Pages File System...
[    4.897421] systemd[1]: Mounting Huge Pages File System...
         Mounting POSIX Message Queue File System..[    4.914132] systemd[1]: Mounting POSIX Message Queue File System...
.
         Mounting Kernel Debug File System...
[    4.941383] systemd[1]: Mounting Kernel Debug File System...
         Mounting Temporary Directory (/tmp)...
[    4.959608] systemd[1]: Mounting Temporary Directory (/tmp)...
         Starting Create list of st…odes for the curr[    4.977842] systemd[1]: Starting Create list of static device nodes for the current kernel...
ent kernel...
         Starting Start psplash boot splash screen.[    5.009231] systemd[1]: Starting Start psplash boot splash screen...
..
         Starting RPC Bind...
[    5.038866] systemd[1]: Starting RPC Bind...
[    5.052037] systemd[1]: Condition check resulted in File System Check on Root Device being skipped.
[    5.059563] systemd[1]: Starting Journal Service...
         Starting Journal Service...
         Starting Load Kernel Modules...
[    5.087716] systemd[1]: Starting Load Kernel Modules...
         Starting Remount Root and Kernel File Systems systemd[1]: Starting Remount Root and Kernel File Systems...
[0m...
[    5.130255] EXT4-fs (mmcblk1p2): re-mounted. Opts: (null)
[    5.134459] systemd[1]: Starting udev Coldplug all Devices...
         Starting udev Coldplug all Devices...
[  OK  ] Started RPC Bind.
[    5.160334] systemd[1]: Started RPC Bind.
[  OK  ] Mounted Huge Pages File System.[    5.172543] systemd[1]: Mounted Huge Pages File System.

[  OK  ] Started Journal Service.
[    5.200393] systemd[1]: Started Journal Service.
[  OK  ] Mounted POSIX Message Queue File System.
[  OK  ] Mounted Kernel Debug File System.
[  OK  ] Mounted Temporary Directory (/tmp).
[  OK  ] Started Create list of sta… nodes for the current kernel.
[FAILED] Failed to start Start psplash boot splash screen.
See 'systemctl status psplash-start.service' for details.
[DEPEND] Dependency failed for Star…progress communication helper.
[  OK  ] Started Load Kernel Modules.
[  OK  ] Started Remount Root and Kernel File Systems.
         Mounting Kernel Configuration File System...
         Starting Flush Journal to Persistent Storage...
[    5.418288] systemd-journald[188]: Received client request to flush runtime journal.
         Starting Apply Kernel Variables...
         Starting Create Static Device Nodes in /dev...
[  OK  ] Mounted Kernel Configuration File System.
[  OK  ] Started Flush Journal to Persistent Storage.
[  OK  ] Started Apply Kernel Variables.
[  OK  ] Started Create Static Device Nodes in /dev.
[  OK  ] Reached target Local File Systems ([    5.544743] random: systemd: uninitialized urandom read (16 bytes read)
Pre).
[    5.567743] random: systemd: uninitialized urandom read (16 bytes read)
[    5.576935] random: systemd-journal: uninitialized urandom read (16 bytes read)
         Mounting /media/ram...
         Mounting /var/volatile...
         Starting udev Kernel Device Manager...
[  OK  ] Mounted /media/ram.
[  OK  ] Mounted /var/volatile.
         Starting Load/Save Random Seed...
[  OK  ] Reached target Local File Systems.
         Starting Create Volatile Files and Directories...
[  OK  ] Started Create Volatile Files and Directories.
         Starting Network Time Synchronization...
         Starting Update UTMP about System Boot/Shutdown...
[  OK  ] Started udev Kernel Device Manager.
[  OK  ] Started udev Coldplug all Devices.
         Starting udev Wait for Complete Device Initialization...
[  OK  ] Started Update UTMP about System Boot/Shutdown.
[  OK  ] Started Network Time Synchronization.
[  OK  ] Reached target System Time Set.
[  OK  ] Reached target System Time Synchronized.
[    6.529360] cal 6f03000.cal: Neither port is configured, no point in staying up
[    6.667075] CAN device driver interface
[    6.783247] davinci_mdio b032400.mdio: Configuring MDIO in manual mode
[    6.831673] davinci_mdio b032400.mdio: davinci mdio revision 1.7, bus freq 1000000
[    6.864613] davinci_mdio b032400.mdio: phy[0]: device b032400.mdio:00, driver TI DP83867
[    6.864637] davinci_mdio b032400.mdio: phy[3]: device b032400.mdio:03, driver TI DP83867
[    6.898151] random: systemd: uninitialized urandom read (16 bytes read)
[    6.898287] random: systemd: uninitialized urandom read (16 bytes read)
[    6.923304] davinci_mdio b132400.mdio: Configuring MDIO in manual mode
[    6.947874] platform 41000000.r5f: configured R5F for remoteproc mode
[    6.949349] platform 41000000.r5f: assigned reserved memory node r5f-dma-memory@a0000000
[    6.949789] remoteproc remoteproc0: 41000000.r5f is available
[    6.967470] davinci_mdio b132400.mdio: davinci mdio revision 1.7, bus freq 1000000
[    6.970729] remoteproc remoteproc0: powering up 41000000.r5f
[    6.970752] remoteproc remoteproc0: Booting fw image am65x-mcu-r5f0_0-fw, size 82412
[    6.978996]  remoteproc0#vdev0buffer: assigned reserved memory node r5f-dma-memory@a0000000
[    6.979614] virtio_rpmsg_bus virtio0: rpmsg host is online
[    6.979701]  remoteproc0#vdev0buffer: registered virtio0 (type 7)
[    6.979713] remoteproc remoteproc0: remote processor 41000000.r5f is now up
[    6.993020] davinci_mdio b132400.mdio: phy[0]: device b132400.mdio:00, driver TI DP83867
[    6.993044] davinci_mdio b132400.mdio: phy[3]: device b132400.mdio:03, driver TI DP83867
[    6.999642] virtio_rpmsg_bus virtio0: creating channel ti.ipc4.ping-pong addr 0xd
[    6.999876] virtio_rpmsg_bus virtio0: creating channel rpmsg_chrdev addr 0xe
[    7.037282] davinci_mdio b232400.mdio: Configuring MDIO in manual mode
[    7.083285] m_can_platform 40568000.mcan: m_can device registered (irq=25, version=32)
[    7.085019] davinci_mdio b232400.mdio: davinci mdio revision 1.7, bus freq 1000000
[    7.094731] m_can_platform 40528000.mcan: m_can device registered (irq=23, version=32)
[    7.108281] davinci_mdio b232400.mdio: phy[0]: device b232400.mdio:00, driver TI DP83867
[    7.108306] davinci_mdio b232400.mdio: phy[3]: device b232400.mdio:03, driver TI DP83867
[    7.667930] random: systemd: uninitialized urandom read (16 bytes read)
[    7.671479] random: crng init done
[    7.671497] random: 73 urandom warning(s) missed due to ratelimiting
[  OK  ] Started Load/Save Random Seed.
[    7.982855] remoteproc remoteproc1: b034000.pru is available
[    7.989561] remoteproc remoteproc2: b004000.rtu is available
[    7.990326] remoteproc remoteproc3: b00a000.txpru is available
[    7.990818] remoteproc remoteproc4: b038000.pru is available
[    7.996019] remoteproc remoteproc5: b006000.rtu is available
[    7.996777] remoteproc remoteproc6: b00c000.txpru is available
[    7.997311] remoteproc remoteproc7: b134000.pru is available
[    7.997914] remoteproc remoteproc8: b104000.rtu is available
[    7.998424] remoteproc remoteproc9: b10a000.txpru is available
[    7.998782] remoteproc remoteproc10: b138000.pru is available
[    7.999292] remoteproc remoteproc11: b106000.rtu is available
[    8.007604] remoteproc remoteproc12: b10c000.txpru is available
[    8.008189] remoteproc remoteproc13: b234000.pru is available
[    8.008857] remoteproc remoteproc14: b204000.rtu is available
[    8.011179] remoteproc remoteproc15: b20a000.txpru is available
[    8.015697] remoteproc remoteproc16: b238000.pru is available
[    8.016463] remoteproc remoteproc17: b206000.rtu is available
[    8.017061] remoteproc remoteproc18: b20c000.txpru is available
[    8.879324] OF: graph: no port node found in /bus@100000/phy@4110000
[    8.933333] TI DP83867 b032400.mdio:00: attached PHY driver [TI DP83867] (mii_bus:phy_addr=b032400.mdio:00, irq=POLL)
[    8.956776] TI DP83867 b032400.mdio:03: attached PHY driver [TI DP83867] (mii_bus:phy_addr=b032400.mdio:03, irq=POLL)
[    8.956828] icssg-prueth icssg0-eth: TI PRU ethernet driver initialized: dual EMAC mode
[    9.001107] TI DP83867 b232400.mdio:00: attached PHY driver [TI DP83867] (mii_bus:phy_addr=b232400.mdio:00, irq=POLL)
[    9.018869] TI DP83867 b232400.mdio:03: attached PHY driver [TI DP83867] (mii_bus:phy_addr=b232400.mdio:03, irq=POLL)
[    9.018918] icssg-prueth icssg2-eth: TI PRU ethernet driver initialized: dual EMAC mode
[    9.031756] TI DP83867 b132400.mdio:00: attached PHY driver [TI DP83867] (mii_bus:phy_addr=b132400.mdio:00, irq=POLL)
[    9.040131] TI DP83867 b132400.mdio:03: attached PHY driver [TI DP83867] (mii_bus:phy_addr=b132400.mdio:03, irq=POLL)
[    9.040169] icssg-prueth icssg1-eth: TI PRU ethernet driver initialized: dual EMAC mode
[  OK  ] Created slice system-systemd\x2dfsck.slice.
[  OK  ] Reached target Hardware activated USB gadget.
[    9.356539] usbcore: registered new interface driver usbfs
[    9.359727] usbcore: registered new interface driver hub
[    9.359837] usbcore: registered new device driver usb
[    9.386697] xhci-hcd xhci-hcd.2.auto: xHCI Host Controller
[    9.386748] xhci-hcd xhci-hcd.2.auto: new USB bus registered, assigned bus number 1
[    9.386904] xhci-hcd xhci-hcd.2.auto: hcc params 0x0298fe6d hci version 0x110 quirks 0x0000000000010010
[    9.387001] xhci-hcd xhci-hcd.2.auto: irq 594, io mem 0x04010000
[    9.387616] usb usb1: New USB device found, idVendor=1d6b, idProduct=0002, bcdDevice= 5.10
[    9.387633] usb usb1: New USB device strings: Mfr=3, Product=2, SerialNumber=1
[    9.387642] usb usb1: Product: xHCI Host Controller
[    9.387648] usb usb1: Manufacturer: Linux 5.10.131-rt72 xhci-hcd
[    9.387655] usb usb1: SerialNumber: xhci-hcd.2.auto
[    9.396158] hub 1-0:1.0: USB hub found
[    9.396230] hub 1-0:1.0: 1 port detected
[    9.396881] xhci-hcd xhci-hcd.2.auto: xHCI Host Controller
[    9.396906] xhci-hcd xhci-hcd.2.auto: new USB bus registered, assigned bus number 2
[    9.396928] xhci-hcd xhci-hcd.2.auto: Host supports USB 3.0 SuperSpeed
[    9.397038] usb usb2: We don't know the algorithms for LPM for this host, disabling LPM.
[    9.397197] usb usb2: New USB device found, idVendor=1d6b, idProduct=0003, bcdDevice= 5.10
[    9.397210] usb usb2: New USB device strings: Mfr=3, Product=2, SerialNumber=1
[    9.397219] usb usb2: Product: xHCI Host Controller
[    9.397226] usb usb2: Manufacturer: Linux 5.10.131-rt72 xhci-hcd
[    9.397233] usb usb2: SerialNumber: xhci-hcd.2.auto
[    9.397946] hub 2-0:1.0: USB hub found
[    9.397994] hub 2-0:1.0: 1 port detected
[  OK  ] Found device /dev/mmcblk1p1.
[  OK  ] Started udev Wait for Complete Device Initialization.
[  OK  ] Started Hardware RNG Entropy Gatherer Daemon.
[  OK  ] Reached target System Initialization.
[  OK  ] Started Daily rotation of log files.
[  OK  ] Started Daily Cleanup of Temporary Directories.
[  OK  ] Reached target Timers.
[  OK  ] Listening on Avahi mDNS/DNS-SD Stack Activation Socket.
[  OK  ] Listening on D-Bus System Message Bus Socket.
         Starting Docker Socket for the API.
[  OK  ] Listening on dropbear.socket.
         Starting Reboot and dump vmcore via kexec...
         Starting File System Check on /dev/mmcblk1p1...
[  OK  ] Listening on Docker Socket for the API.
[  OK  ] Started Reboot and dump vmcore via kexec.
[  OK  ] Reached target Sockets.
[  OK  ] Reached target Basic System.
[  OK  ] Started Job spooling tools.
[  OK  ] Started Periodic Command Scheduler.
[  OK  ] Started D-Bus System Message Bus.
         Starting Print notice about GPLv3 packages...
         Starting IPv6 Packet Filtering Framework...
         Starting IPv4 Packet Filtering Framework...
[  OK  ] Started irqbalance daemon.
         Starting Telephony service...
         Starting rc.pvr.service...
         Starting Login Service...
[  OK  ] Started TEE Supplicant.
[  OK  ] Started IPv6 Packet Filtering Framework.
[  OK  ] Started File System Check on /dev/mmcblk1p1.
[  OK  ] Started IPv4 Packet Filtering Framework.
[  OK  ] Reached target Network (Pre).
         Mounting /run/media/mmcblk1p1...
         Starting Network Service...
[  OK  ] Mounted /run/media/mmcblk1p1.
[  OK  ] Started Telephony service.
[  OK  ] Listening on Load/Save RF …itch Status /dev/rfkill Watch.
[   10.551165] Bluetooth: Core ver 2.22
[   10.551348] NET: Registered protocol family 31
[   10.551355] Bluetooth: HCI device and connection manager initialized
[   10.551383] Bluetooth: HCI socket layer initialized
[   10.551471] Bluetooth: L2CAP socket layer initialized
[   10.551502] Bluetooth: SCO socket layer initialized
[  OK  ] Started Network Service.
         Starting Wait for Network to be Configured...
         Starting Network Name Resolution...
[   10.716825] remoteproc remoteproc10: powering up b138000.pru
[   10.718890] remoteproc remoteproc10: Booting fw image ti-pruss/am65x-sr2-pru1-prueth-fw.elf, size 37540
[   10.718928] remoteproc remoteproc10: unsupported resource 5
[   10.718959] remoteproc remoteproc10: remote processor b138000.pru is now up
[   10.718996] remoteproc remoteproc11: powering up b106000.rtu
[   10.735617] remoteproc remoteproc11: Booting fw image ti-pruss/am65x-sr2-rtu1-prueth-fw.elf, size 30088
[   10.735666] remoteproc remoteproc11: remote processor b106000.rtu is now up
[   10.735698] remoteproc remoteproc12: powering up b10c000.txpru
[   10.751187] remoteproc remoteproc12: Booting fw image ti-pruss/am65x-sr2-txpru1-prueth-fw.elf, size 35264
[   10.751253] remoteproc remoteproc12: remote processor b10c000.txpru is now up
[   10.756570] icssg-prueth icssg1-eth: settime timeout
[   10.756939] pps pps0: new PPS source ptp2
[   10.762472] net eth6: started
[   10.817981] remoteproc remoteproc7: powering up b134000.pru
[   10.819848] remoteproc remoteproc7: Booting fw image ti-pruss/am65x-sr2-pru0-prueth-fw.elf, size 37264
[   10.819881] remoteproc remoteproc7: unsupported resource 5
[   10.819914] remoteproc remoteproc7: remote processor b134000.pru is now up
[   10.819954] remoteproc remoteproc8: powering up b104000.rtu
[   10.822443] remoteproc remoteproc8: Booting fw image ti-pruss/am65x-sr2-rtu0-prueth-fw.elf, size 30832
[   10.822497] remoteproc remoteproc8: remote processor b104000.rtu is now up
[   10.822548] remoteproc remoteproc9: powering up b10a000.txpru
[   10.828967] remoteproc remoteproc9: Booting fw image ti-pruss/am65x-sr2-txpru0-prueth-fw.elf, size 36656
[   10.829022] remoteproc remoteproc9: remote processor b10a000.txpru is now up
[   10.833697] net eth5: started
[   10.913362] remoteproc remoteproc16: powering up b238000.pru
[   10.913623] remoteproc remoteproc16: Booting fw image ti-pruss/am65x-sr2-pru1-prueth-fw.elf, size 37540
[   10.913651] remoteproc remoteproc16: unsupported resource 5
[   10.913682] remoteproc remoteproc16: remote processor b238000.pru is now up
[   10.913709] remoteproc remoteproc17: powering up b206000.rtu
[  OK  ] Started Login Service.
[   10.913881] remoteproc remoteproc17: Booting fw image ti-pruss/am65x-sr2-rtu1-prueth-fw.elf, size 30088
[   10.913914] remoteproc remoteproc17: remote processor b206000.rtu is now up
[   10.913935] remoteproc remoteproc18: powering up b20c000.txpru
[   10.914084] remoteproc remoteproc18: Booting fw image ti-pruss/am65x-sr2-txpru1-prueth-fw.elf, size 35264
[   10.914123] remoteproc remoteproc18: remote processor b20c000.txpru is now up
[   10.924224] icssg-prueth icssg2-eth: settime timeout
[   10.924588] pps pps1: new PPS source ptp3
[   10.947376] net eth4: started
[   11.014957] remoteproc remoteproc13: powering up b234000.pru
[   11.015222] remoteproc remoteproc13: Booting fw image ti-pruss/am65x-sr2-pru0-prueth-fw.elf, size 37264
[   11.015250] remoteproc remoteproc13: unsupported resource 5
[   11.015280] remoteproc remoteproc13: remote processor b234000.pru is now up
[   11.015313] remoteproc remoteproc14: powering up b204000.rtu
[   11.019099] remoteproc remoteproc14: Booting fw image ti-pruss/am65x-sr2-rtu0-prueth-fw.elf, size 30832
[   11.019147] remoteproc remoteproc14: remote processor b204000.rtu is now up
[   11.019179] remoteproc remoteproc15: powering up b20a000.txpru
[   11.019371] remoteproc remoteproc15: Booting fw image ti-pruss/am65x-sr2-txpru0-prueth-fw.elf, size 36656
[   11.019525] remoteproc remoteproc15: remote processor b20a000.txpru is now up
[   11.038703] net eth3: started
[   11.090746] remoteproc remoteproc4: powering up b038000.pru
[   11.090988] remoteproc remoteproc4: Booting fw image ti-pruss/am65x-sr2-pru1-prueth-fw.elf, size 37540
[   11.091017] remoteproc remoteproc4: unsupported resource 5
[   11.091047] remoteproc remoteproc4: remote processor b038000.pru is now up
[   11.091078] remoteproc remoteproc5: powering up b006000.rtu
[   11.091571] remoteproc remoteproc5: Booting fw image ti-pruss/am65x-sr2-rtu1-prueth-fw.elf, size 30088
[   11.091614] remoteproc remoteproc5: remote processor b006000.rtu is now up
[  OK  ] Started Network Name Resolution[   11.091642] remoteproc remoteproc6: powering up b00c000.txpru
.
[   11.091802] remoteproc remoteproc6: Booting fw image ti-pruss/am65x-sr2-txpru1-prueth-fw.elf, size 35264
[  OK  ] Reached target Network.
[  OK  ] Reached target Host and Network Nam[   11.091843] remoteproc remoteproc6: remote processor b00c000.txpru is now up
e Lookups.
         Starting Avahi mDNS/DNS-SD Stack...
[   11.104530] icssg-prueth icssg0-eth: settime timeout
         Starting Enable and configure wl18xx bluetooth[   11.104877] pps pps2: new PPS source ptp4
 stack...
[   11.126838] net eth2: started
[  OK  ] Started NFS status monitor for NFSv[   11.197951] remoteproc remoteproc1: powering up b034000.pru
2/3 locking..
         Starting Simple Network Ma…ent Protocol (SNMP) Daemon....
[   11.198212] remoteproc remoteproc1: Booting fw image ti-pruss/am65x-sr2-pru0-prueth-fw.elf, size 37264
         Starting Permit User Sessions...
[   11.198242] remoteproc remoteproc1: unsupported resource 5
[   11.198276] remoteproc remoteproc1: remote processor b034000.pru is now up
[   11.198307] remoteproc remoteproc2: powering up b004000.rtu
[   11.198444] remoteproc remoteproc2: Booting fw image ti-pruss/am65x-sr2-rtu0-prueth-fw.elf, size 30832
[   11.198481] remoteproc remoteproc2: remote processor b004000.rtu is now up
[  OK  ] Started Avahi mDNS/DNS-SD Stack[   11.198503] remoteproc remoteproc3: powering up b00a000.txpru
.
[  OK  ] Started Permit User Sessions.
[   11.198640] remoteproc remoteproc3: Booting fw image ti-pruss/am65x-sr2-txpru0-prueth-fw.elf, size 36656
[   11.198680] remoteproc remoteproc3: remote processor b00a000.txpru is now up
[   11.239678] net eth1: started
[  OK  ] Started Getty on tty1.
[   11.486168] am65-cpsw-nuss 46000000.ethernet eth0: PHY [46000f00.mdio:00] driver [TI DP83867] (irq=POLL)
[   11.486207] am65-cpsw-nuss 46000000.ethernet eth0: configuring for phy/rgmii-rxid link mode
[  OK  ] Started Serial Getty on ttyS1.
[  OK  ] Started Serial Getty on ttyS2.
[  OK  ] Reached target Login Prompts.
         Starting Synchronize System and HW clocks...
[  OK  ] Started Enable and configure wl18xx bluetooth stack.
[FAILED] Failed to start Synchronize System and HW clocks.
See 'systemctl status sync-clocks.service' for details.
[  OK  ] Started Simple Network Man…ement Protocol (SNMP) Daemon..
[  OK  ] Started rc.pvr.service.
         Starting weston.service...
[  OK  ] Started weston.service.
         Starting telnetd.service...
[  OK  ] Started telnetd.service.
[   13.892520] icssg-prueth icssg1-eth eth5: Link is Up - 1Gbps/Full - flow control off
[   13.892638] IPv6: ADDRCONF(NETDEV_CHANGE): eth5: link becomes ready
[   14.312484] icssg-prueth icssg0-eth eth1: Link is Up - 1Gbps/Full - flow control off
[   14.312600] IPv6: ADDRCONF(NETDEV_CHANGE): eth1: link becomes ready
***************************************************************
***************************************************************
NOTICE: This file system contains the following GPLv3 packages:
        autoconf
        bash-dev
        bash
        bc
        binutils
        cifs-utils
        coreutils-stdbuf
        coreutils
        cpio
        cpp-symlinks
        cpp
        dosfstools
        elfutils
        g++-symlinks
        g++
        gawk
        gcc-symlinks
        gcc
        gdb
        gdbserver
        gettext
        glmark2
        gstreamer1.0-libav-dev
        gstreamer1.0-libav
        gzip
        less
        libasm1
        libbfd
        libdw1
        libelf1
        libgdbm-compat4
        libgdbm-dev
        libgdbm6
        libgettextlib
        libgettextsrc
        libgmp-dev
        libgmp10
        libgmpxx4
        libidn2-0
        libidn2-dev
        libmpc3
        libmpfr6
        libreadline-dev
        libreadline8
        libunistring-dev
        libunistring2
        m4-dev
        m4
        make
        nettle-dev
        nettle
        parted
        pdm-anomaly-detection
        python3-rfc3987
        python3-strict-rfc3339
        tar
        which
        zeromq

If you do not wish to distribute GPLv3 components please remove
the above packages prior to distribution.  This can be done using
the opkg remove command.  i.e.:
    opkg remove <package>
Where <package> is the name printed in the list above

NOTE: If the package is a dependency of another package you
      will be notified of the dependent packages.  You should
      use the --force-removal-of-dependent-packages option to
      also remove the dependent packages as well
***************************************************************
***************************************************************
[  OK  ] Started Print notice about GPLv3 packages.

 _____                    _____           _         _
|  _  |___ ___ ___ ___   |  _  |___ ___  |_|___ ___| |_
|     |  _| .'| . | . |  |   __|  _| . | | | -_|  _|  _|
|__|__|_| |__,|_  |___|  |__|  |_| |___|_| |___|___|_|
              |___|                    |___|

Arago Project http://arago-project.org am65xx-evm ttyS2

Arago 2021.09 am65xx-evm ttyS2

am65xx-evm login: root
root@am65xx-evm:~# cd linuxptp-3.1.1/
root@am65xx-evm:~/linuxptp-3.1.1# uname -a
Linux am65xx-evm 5.10.131-rt72 #1 SMP PREEMPT Mon Oct 24 10:25:51 CEST 2022 aarch64 aarch64 aarch64 GNU/Linux
root@am65xx-evm:~/linuxptp-3.1.1# ./phc_ctl CLOCK_REALTIME set 16770
phc_ctl[36.745]: set clock time to 16770.000000000 or Thu Jan  1 04:39:30 1970

root@am65xx-evm:~/linuxptp-3.1.1# phc2sys -s CLOCK_REALTIME -c eth6 -O 0 -R 10 -S 0.00002 -m
phc2sys[39.094]: eth6 sys offset 1648082366919426906 s0 freq      +0 delay    410
phc2sys[39.195]: eth6 sys offset 1648082366919426907 s1 freq     +10 delay    410
phc2sys[39.295]: eth6 sys offset     -2862 s2 freq   -2852 delay    410
phc2sys[39.396]: eth6 sys offset     -2578 s2 freq   -3427 delay    410
phc2sys[39.496]: eth6 sys offset     -2239 s2 freq   -3861 delay    410
phc2sys[39.596]: eth6 sys offset     -1856 s2 freq   -4150 delay    410
phc2sys[39.696]: eth6 sys offset     -1444 s2 freq   -4295 delay    410
phc2sys[39.796]: eth6 sys offset     -1016 s2 freq   -4300 delay    410
phc2sys[39.897]: eth6 sys offset      -585 s2 freq   -4174 delay    410
phc2sys[39.997]: eth6 sys offset      -171 s2 freq   -3935 delay    410
phc2sys[40.097]: eth6 sys offset       222 s2 freq   -3593 delay    410
phc2sys[40.197]: eth6 sys offset       581 s2 freq   -3168 delay    410
phc2sys[40.297]: eth6 sys offset       898 s2 freq   -2676 delay    410
phc2sys[40.398]: eth6 sys offset      1163 s2 freq   -2142 delay    410
phc2sys[40.498]: eth6 sys offset      1379 s2 freq   -1577 delay    410
phc2sys[40.598]: eth6 sys offset      1534 s2 freq   -1008 delay    410
phc2sys[40.698]: eth6 sys offset      1633 s2 freq    -449 delay    405
phc2sys[40.798]: eth6 sys offset      1678 s2 freq     +86 delay    410
phc2sys[40.898]: eth6 sys offset      1670 s2 freq    +581 delay    410
phc2sys[40.999]: eth6 sys offset      1612 s2 freq   +1024 delay    410
phc2sys[41.099]: eth6 sys offset      1512 s2 freq   +1408 delay    410
phc2sys[41.199]: eth6 sys offset      1372 s2 freq   +1721 delay    410
phc2sys[41.299]: eth6 sys offset      1202 s2 freq   +1963 delay    410
phc2sys[41.399]: eth6 sys offset      1007 s2 freq   +2128 delay    410
phc2sys[41.500]: eth6 sys offset       795 s2 freq   +2219 delay    410
phc2sys[41.600]: eth6 sys offset       575 s2 freq   +2237 delay    410
phc2sys[41.700]: eth6 sys offset       348 s2 freq   +2183 delay    410
phc2sys[41.800]: eth6 sys offset       135 s2 freq   +2074 delay    415
phc2sys[41.901]: eth6 sys offset       -73 s2 freq   +1906 delay    410
phc2sys[42.001]: eth6 sys offset      -258 s2 freq   +1700 delay    410
phc2sys[42.101]: eth6 sys offset      -427 s2 freq   +1453 delay    410
phc2sys[42.201]: eth6 sys offset      -573 s2 freq   +1179 delay    410
phc2sys[42.301]: eth6 sys offset      -688 s2 freq    +892 delay    410
phc2sys[42.401]: eth6 sys offset      -776 s2 freq    +598 delay    410
phc2sys[42.502]: eth6 sys offset      -830 s2 freq    +311 delay    410
phc2sys[42.602]: eth6 sys offset      -857 s2 freq     +35 delay    410
phc2sys[42.702]: eth6 sys offset      -860 s2 freq    -225 delay    410
phc2sys[42.802]: eth6 sys offset      -839 s2 freq    -462 delay    410
phc2sys[42.902]: eth6 sys offset      -793 s2 freq    -668 delay    410
phc2sys[43.002]: eth6 sys offset      -730 s2 freq    -843 delay    410
phc2sys[43.103]: eth6 sys offset      -645 s2 freq    -977 delay    410
phc2sys[43.203]: eth6 sys offset      -550 s2 freq   -1075 delay    410
phc2sys[43.303]: eth6 sys offset      -447 s2 freq   -1137 delay    405
phc2sys[43.403]: eth6 sys offset      -334 s2 freq   -1158 delay    410
phc2sys[43.503]: eth6 sys offset      -222 s2 freq   -1147 delay    410
phc2sys[43.604]: eth6 sys offset      -109 s2 freq   -1100 delay    410
phc2sys[43.704]: eth6 sys offset        -2 s2 freq   -1026 delay    410
phc2sys[43.804]: eth6 sys offset        96 s2 freq    -928 delay    410
phc2sys[43.904]: eth6 sys offset       190 s2 freq    -806 delay    410
phc2sys[44.004]: clockcheck: clock jumped backward or running slower than expected!
phc2sys[44.004]: eth6 sys offset -8388607999733 s0 freq    -806 delay    410
phc2sys[44.105]: eth6 sys offset -8388607999649 s1 freq    -101 delay    410
phc2sys[44.206]: eth6 sys offset     -2828 s2 freq   -2929 delay    410
phc2sys[44.306]: eth6 sys offset     -2533 s2 freq   -3482 delay    410
phc2sys[44.406]: eth6 sys offset     -2185 s2 freq   -3894 delay    410
phc2sys[44.506]: eth6 sys offset     -1798 s2 freq   -4162 delay    410
phc2sys[44.607]: eth6 sys offset     -1381 s2 freq   -4285 delay    410
phc2sys[44.707]: eth6 sys offset      -954 s2 freq   -4272 delay    410
phc2sys[44.807]: eth6 sys offset      -530 s2 freq   -4134 delay    410
phc2sys[44.907]: eth6 sys offset      -116 s2 freq   -3879 delay    410
phc2sys[45.007]: eth6 sys offset       275 s2 freq   -3523 delay    410
phc2sys[45.108]: eth6 sys offset       624 s2 freq   -3092 delay    410
phc2sys[45.208]: eth6 sys offset       935 s2 freq   -2593 delay    410
^Cphc2sys[45.275]: eth6 sys offset      1104 s2 freq   -2144 delay    410
root@am65xx-evm:~/linuxptp-3.1.1#
root@am65xx-evm:~/linuxptp-3.1.1#
root@am65xx-evm:~/linuxptp-3.1.1# ./phc_ctl eth6 set 16770
phc_ctl[68.562]: set clock time to 16770.000000000 or Thu Jan  1 04:39:30 1970

root@am65xx-evm:~/linuxptp-3.1.1# ./phc_ctl eth6 get
phc_ctl[71.861]: clock time is 16773.299947324 or Thu Jan  1 04:39:33 1970

root@am65xx-evm:~/linuxptp-3.1.1# ./phc_ctl eth6 get
phc_ctl[77.321]: clock time is 8390.151947468 or Thu Jan  1 02:19:50 1970

root@am65xx-evm:~/linuxptp-3.1.1# ^C
root@am65xx-evm:~/linuxptp-3.1.1#

How I stated in my last post based on your log. The bug still exists on updated system. The bug you can catch by phc2sys also by simple clock check without synchronization, how you can see in log.

Please to be sure that you are sharing all my provided information to developers. 

1. The bug appears without clock synchronization also. Forum post
2. Configuration of step_treshold only partially cover up the bug - definitely it is not a fix.
3. Does not exist whole official public AM65x LINUX RT SDK > 8.2.

Hello Lukas,

Thank you for running the test on an updated kernel, this is a useful data point. The developer is on vacation for the next couple of days, but I have a meeting scheduled with him for the end of the week to discuss exactly how he is running tests. That way we can make sure we are not missing anything (e.g., if you would need to use a different PRU Ethernet firmware, or if the developer was only testing on non-RT Linux and the issue was only visible on RT Linux).

Just to set expectations, the ti-linux-kernel version linked above is NOT an official fix version of software for AM65x. A fully validated bug fix will be released later (please talk with Frank W for details). For now, I just want to make sure the issue is actually resolved (and keep the bug on the developer's TODO list if it is not resolved).

I will have the next response for you by Friday.

Regards,

Nick

Hello Nick,

do you have new information from developer, regarding the bug? Do we need to use different versions or do you have the same observation?

Thank you for your update.

Regards,
Lukas

Hello Lukas,

Thanks for the ping. I am attaching a link to the filesystem image that the developer is using to test. This is from our internal 08.04.01.005-rt build. It should line up with https://git.ti.com/cgit/ti-linux-kernel/ti-linux-kernel/tag/?h=08.04.01.005-rt . 

https://txn.box.com/s/sguvmanf0insoydhjvd3tf3f9uepkfgx 

The PRU Ethernet firmware in this image is different from the firmware in AM65x SDK 8.2. (in the filesystem under /lib/firmware/ti-pruss/am65x-sr2-XXX) I am not totally sure of what the differences are in the firmware, but you want to use the updated firmware when you are testing with an updated version of Linux. The developer is not changing any of the default kernel configs.

Since this is a WIC image, you can write it to an SD card using a tool like BalenaEtcher, as documented here: https://software-dl.ti.com/processor-sdk-linux/esd/AM64X/08_04_01_04/exports/docs/linux/Overview/Processor_SDK_Linux_create_SD_card.html 

Regards,

Nick

also, it looks like the link will expire in 7 days and I'm not sure if I can make the link last longer. So make sure you download the needed files.

-Nick

Hello Lukas,

FYI, I found where the PRU firmware from each SDK release is stored:
https://git.ti.com/cgit/processor-firmware/ti-linux-firmware/tree/ti-pruss
and then you can just select the tag that matches the SDK release you are looking at. e.g., it looks like SDK 8.2 for AM65x was 8.2.0.2, so I would go here:
https://git.ti.com/cgit/processor-firmware/ti-linux-firmware/refs/tags and select tag 08.02.00.002

Regards,

Nick

Hello Nick,

Test on provided image - the bug is still exists.

The clock of PTP device jumps within one hour of the start. The clock jump at ~16777s is also still occurs, see console output bellow for both.

U-Boot SPL 2021.01-g2dd2e1d366 (Sep 24 2022 - 23:09:07 +0000)
SYSFW ABI: 3.1 (firmware rev 0x0016 '22.1.1--v2022.01 (Terrific Llam')
SPL initial stack usage: 1416 bytes
Trying to boot from MMC2
spl_load_fit_image: Skip load 'dm': image size is 0!
Starting ATF on ARM64 core...

NOTICE:  BL31: v2.7(release):v2.7.0-dirty
NOTICE:  BL31: Built : 23:09:26, Sep 24 2022
I/TC:
I/TC: OP-TEE version: 3.18.0-62-g8e155bae3 (gcc version 9.2.1 20191025 (GNU Toolchain for the A-profile Architecture 9.2-2019.12 (arm-9.10))) #1 Sat Sep 24 23:09:29 UTC 2022 aarch64
I/TC: WARNING: This OP-TEE configuration might be insecure!
I/TC: WARNING: Please check https://optee.readthedocs.io/en/latest/architecture/porting_guidelines.html
I/TC: Primary CPU initializing
I/TC: SYSFW ABI: 3.1 (firmware rev 0x0016 '22.1.1--v2022.01 (Terrific Llam')
E/TC:0 0 tee_otp_get_hw_unique_key:87 Could not get HUK
E/TC:0 0 call_initcalls:43 Initcall __text_start + 0x0005b380 failed
I/TC: Activated SA2UL device
I/TC: Fixing SA2UL firewall owner for GP device
I/TC: Enabled firewalls for SA2UL TRNG device
I/TC: SA2UL TRNG initialized
I/TC: SA2UL Drivers initialized
I/TC: Primary CPU switching to normal world boot

U-Boot SPL 2021.01-g2dd2e1d366 (Sep 24 2022 - 23:09:44 +0000)
SYSFW ABI: 3.1 (firmware rev 0x0016 '22.1.1--v2022.01 (Terrific Llam')
Detected: Silicon SR2.0
i2c_omap i2c@42120000: pinctrl_select_state_full: uclass_get_device_by_phandle_id: err=-19
Detected: AM6-IDKAPPEVM rev A
Detected: SER-PCIE2LEVM rev A
Trying to boot from MMC2


U-Boot 2021.01-g2dd2e1d366 (Sep 24 2022 - 23:09:44 +0000)

SoC:   AM65X SR2.0 GP
Model: Texas Instruments AM654 Base Board
Board: AM6-COMPROCEVM rev A
DRAM:  4 GiB
MMC:   sdhci@4f80000: 0, sdhci@4fa0000: 1
Loading Environment from MMC... OK
In:    serial
Out:   serial
Err:   serial
am65_cpsw_nuss ethernet@46000000: K3 CPSW: nuss_ver: 0x6BA00102 cpsw_ver: 0x6BA80102 ale_ver: 0x00293904 Ports:1 mdio_freq:1000000
Detected: Silicon SR2.0
Detected: AM6-IDKAPPEVM rev A
Detected: SER-PCIE2LEVM rev A
Net:   eth1: icssg2-eth, eth0: ethernet@46000000port@1
Hit any key to stop autoboot:  0
switch to partitions #0, OK
mmc1 is current device
SD/MMC found on device 1
Failed to load 'boot.scr'
574 bytes read in 2 ms (280.3 KiB/s)
Loaded env from uEnv.txt
Importing environment from mmc1 ...
18536960 bytes read in 739 ms (23.9 MiB/s)
64339 bytes read in 6 ms (10.2 MiB/s)
11268 bytes read in 3 ms (3.6 MiB/s)
2333 bytes read in 3 ms (758.8 KiB/s)
## Flattened Device Tree blob at 88000000
   Booting using the fdt blob at 0x88000000
   Loading Device Tree to 000000008feed000, end 000000008fffffff ... OK

Starting kernel ...

[    0.000000] Booting Linux on physical CPU 0x0000000000 [0x410fd034]
[    0.000000] Linux version 5.10.140-g5e63ae91b2 (oe-user@oe-host) (aarch64-none-linux-gnu-gcc (GNU Toolchain for the A-profile Architecture 9.2-2019.12 (arm-9.10)) 9.2.1 20191025, GNU ld (GNU Toolchain for the A-profile Architecture 9.2-2019.12 (arm-9.10)) 2.33.1.20191209) #1 SMP PREEMPT Sat Sep 24 23:11:05 UTC 2022
[    0.000000] Machine model: Texas Instruments AM654 Base Board
[    0.000000] earlycon: ns16550a0 at MMIO32 0x0000000002800000 (options '')
[    0.000000] printk: bootconsole [ns16550a0] enabled
[    0.000000] efi: UEFI not found.
[    0.000000] Reserved memory: created DMA memory pool at 0x00000000a0000000, size 1 MiB
[    0.000000] OF: reserved mem: initialized node r5f-dma-memory@a0000000, compatible id shared-dma-pool
[    0.000000] Reserved memory: created DMA memory pool at 0x00000000a0100000, size 15 MiB
[    0.000000] OF: reserved mem: initialized node r5f-memory@a0100000, compatible id shared-dma-pool
[    0.000000] Reserved memory: created DMA memory pool at 0x00000000a1000000, size 1 MiB
[    0.000000] OF: reserved mem: initialized node r5f-dma-memory@a1000000, compatible id shared-dma-pool
[    0.000000] Reserved memory: created DMA memory pool at 0x00000000a1100000, size 15 MiB
[    0.000000] OF: reserved mem: initialized node r5f-memory@a1100000, compatible id shared-dma-pool
[    0.000000] Zone ranges:
[    0.000000]   DMA      [mem 0x0000000080000000-0x00000000ffffffff]
[    0.000000]   DMA32    empty
[    0.000000]   Normal   [mem 0x0000000100000000-0x00000008ffffffff]
[    0.000000] Movable zone start for each node
[    0.000000] Early memory node ranges
[    0.000000]   node   0: [mem 0x0000000080000000-0x000000009e7fffff]
[    0.000000]   node   0: [mem 0x000000009e800000-0x00000000a20fffff]
[    0.000000]   node   0: [mem 0x00000000a2100000-0x00000000ffffffff]
[    0.000000]   node   0: [mem 0x0000000880000000-0x00000008ffffffff]
[    0.000000] Initmem setup node 0 [mem 0x0000000080000000-0x00000008ffffffff]
[    0.000000] cma: Reserved 512 MiB at 0x00000000e0000000
[    0.000000] psci: probing for conduit method from DT.
[    0.000000] psci: PSCIv1.1 detected in firmware.
[    0.000000] psci: Using standard PSCI v0.2 function IDs
[    0.000000] psci: Trusted OS migration not required
[    0.000000] psci: SMC Calling Convention v1.2
[    0.000000] percpu: Embedded 22 pages/cpu s50008 r8192 d31912 u90112
[    0.000000] Detected VIPT I-cache on CPU0
[    0.000000] CPU features: detected: ARM erratum 845719
[    0.000000] CPU features: detected: GIC system register CPU interface
[    0.000000] Built 1 zonelists, mobility grouping on.  Total pages: 1032192
[    0.000000] Kernel command line: console=ttyS2,115200n8 earlycon=ns16550a,mmio32,0x02800000 mtdparts=47040000.spi.0:512k(ospi.tiboot3),2m(ospi.tispl),4m(ospi.u-boot),128k(ospi.env),128k(ospi.env.backup),1m(ospi.sysfw),57216k@8m(ospi.rootfs),128k(ospi.phypattern) root=PARTUUID=2ae061e0-02 rw rootfstype=ext4 rootwait
[    0.000000] Dentry cache hash table entries: 524288 (order: 10, 4194304 bytes, linear)
[    0.000000] Inode-cache hash table entries: 262144 (order: 9, 2097152 bytes, linear)
[    0.000000] mem auto-init: stack:off, heap alloc:off, heap free:off
[    0.000000] software IO TLB: mapped [mem 0x00000000dc000000-0x00000000e0000000] (64MB)
[    0.000000] Memory: 3446680K/4194304K available (10880K kernel code, 1142K rwdata, 4196K rodata, 1792K init, 430K bss, 223336K reserved, 524288K cma-reserved)
[    0.000000] SLUB: HWalign=64, Order=0-3, MinObjects=0, CPUs=4, Nodes=1
[    0.000000] rcu: Preemptible hierarchical RCU implementation.
[    0.000000] rcu:     RCU event tracing is enabled.
[    0.000000] rcu:     RCU restricting CPUs from NR_CPUS=256 to nr_cpu_ids=4.
[    0.000000]  Trampoline variant of Tasks RCU enabled.
[    0.000000] rcu: RCU calculated value of scheduler-enlistment delay is 25 jiffies.
[    0.000000] rcu: Adjusting geometry for rcu_fanout_leaf=16, nr_cpu_ids=4
[    0.000000] NR_IRQS: 64, nr_irqs: 64, preallocated irqs: 0
[    0.000000] GICv3: GIC: Using split EOI/Deactivate mode
[    0.000000] GICv3: 960 SPIs implemented
[    0.000000] GICv3: 0 Extended SPIs implemented
[    0.000000] GICv3: Distributor has no Range Selector support
[    0.000000] GICv3: 16 PPIs implemented
[    0.000000] GICv3: CPU0: found redistributor 0 region 0:0x0000000001880000
[    0.000000] ITS [mem 0x01820000-0x0182ffff]
[    0.000000] GIC: enabling workaround for ITS: Socionext Synquacer pre-ITS
[    0.000000] ITS@0x0000000001820000: Devices Table too large, reduce ids 20->19
[    0.000000] ITS@0x0000000001820000: allocated 524288 Devices @880800000 (flat, esz 8, psz 64K, shr 0)
[    0.000000] ITS: using cache flushing for cmd queue
[    0.000000] GICv3: using LPI property table @0x0000000880030000
[    0.000000] GIC: using cache flushing for LPI property table
[    0.000000] GICv3: CPU0: using allocated LPI pending table @0x0000000880040000
[    0.000000] arch_timer: cp15 timer(s) running at 200.00MHz (phys).
[    0.000000] clocksource: arch_sys_counter: mask: 0xffffffffffffff max_cycles: 0x2e2049d3e8, max_idle_ns: 440795210634 ns
[    0.000006] sched_clock: 56 bits at 200MHz, resolution 5ns, wraps every 4398046511102ns
[    0.008728] Console: colour dummy device 80x25
[    0.013341] Calibrating delay loop (skipped), value calculated using timer frequency.. 400.00 BogoMIPS (lpj=800000)
[    0.024066] pid_max: default: 32768 minimum: 301
[    0.028918] LSM: Security Framework initializing
[    0.033735] Mount-cache hash table entries: 8192 (order: 4, 65536 bytes, linear)
[    0.041348] Mountpoint-cache hash table entries: 8192 (order: 4, 65536 bytes, linear)
[    0.051492] rcu: Hierarchical SRCU implementation.
[    0.056780] Platform MSI: msi-controller@1820000 domain created
[    0.063142] PCI/MSI: /bus@100000/interrupt-controller@1800000/msi-controller@1820000 domain created
[    0.072548] EFI services will not be available.
[    0.077536] smp: Bringing up secondary CPUs ...
I/TC: Secondary CPU 1 initializing
I/TC: Secondary CPU 1 switching to normal world boot
I/TC: Secondary CPU 2 initializing
I/TC: Secondary CPU 2 switching to normal world boot
I/TC: Secondary CPU 3 initializing
I/TC: Secondary CPU 3 switching to normal world boot
[    0.091343] Detected VIPT I-cache on CPU1
[    0.091389] GICv3: CPU1: found redistributor 1 region 0:0x00000000018a0000
[    0.091407] GICv3: CPU1: using allocated LPI pending table @0x0000000880050000
[    0.091470] CPU1: Booted secondary processor 0x0000000001 [0x410fd034]
[    0.100873] Detected VIPT I-cache on CPU2
[    0.100918] GICv3: CPU2: found redistributor 100 region 0:0x00000000018c0000
[    0.100936] GICv3: CPU2: using allocated LPI pending table @0x0000000880060000
[    0.101004] CPU2: Booted secondary processor 0x0000000100 [0x410fd034]
[    0.110336] Detected VIPT I-cache on CPU3
[    0.110367] GICv3: CPU3: found redistributor 101 region 0:0x00000000018e0000
[    0.110381] GICv3: CPU3: using allocated LPI pending table @0x0000000880070000
[    0.110427] CPU3: Booted secondary processor 0x0000000101 [0x410fd034]
[    0.110576] smp: Brought up 1 node, 4 CPUs
[    0.190964] SMP: Total of 4 processors activated.
[    0.195799] CPU features: detected: 32-bit EL0 Support
[    0.201094] CPU features: detected: CRC32 instructions
[    0.222663] CPU: All CPU(s) started at EL2
[    0.226910] alternatives: patching kernel code
[    0.233103] devtmpfs: initialized
[    0.248143] KASLR disabled due to lack of seed
[    0.252988] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 7645041785100000 ns
[    0.263006] futex hash table entries: 1024 (order: 4, 65536 bytes, linear)
[    0.287940] pinctrl core: initialized pinctrl subsystem
[    0.294033] DMI not present or invalid.
[    0.298859] NET: Registered protocol family 16
[    0.305223] DMA: preallocated 512 KiB GFP_KERNEL pool for atomic allocations
[    0.312696] DMA: preallocated 512 KiB GFP_KERNEL|GFP_DMA pool for atomic allocations
[    0.320988] DMA: preallocated 512 KiB GFP_KERNEL|GFP_DMA32 pool for atomic allocations
[    0.329745] thermal_sys: Registered thermal governor 'step_wise'
[    0.329752] thermal_sys: Registered thermal governor 'power_allocator'
[    0.336614] hw-breakpoint: found 6 breakpoint and 4 watchpoint registers.
[    0.350425] ASID allocator initialised with 65536 entries
[    0.403649] HugeTLB registered 1.00 GiB page size, pre-allocated 0 pages
[    0.410570] HugeTLB registered 32.0 MiB page size, pre-allocated 0 pages
[    0.417452] HugeTLB registered 2.00 MiB page size, pre-allocated 0 pages
[    0.424333] HugeTLB registered 64.0 KiB page size, pre-allocated 0 pages
[    0.433070] cryptd: max_cpu_qlen set to 1000
[    0.442135] k3-chipinfo 43000014.chipid: Family:AM65X rev:SR2.0 JTAGID[0x1bb5a02f] Detected
[    0.451476] vcc3v3_io: supplied by evm_12v0
[    0.457194] iommu: Default domain type: Translated
[    0.462661] SCSI subsystem initialized
[    0.467210] mc: Linux media interface: v0.10
[    0.471636] videodev: Linux video capture interface: v2.00
[    0.477359] pps_core: LinuxPPS API ver. 1 registered
[    0.482459] pps_core: Software ver. 5.3.6 - Copyright 2005-2007 Rodolfo Giometti <giometti@linux.it>
[    0.491848] PTP clock support registered
[    0.495914] EDAC MC: Ver: 3.0.0
[    0.500568] FPGA manager framework
[    0.504315] Advanced Linux Sound Architecture Driver Initialized.
[    0.511787] clocksource: Switched to clocksource arch_sys_counter
[    0.518311] VFS: Disk quotas dquot_6.6.0
[    0.522411] VFS: Dquot-cache hash table entries: 512 (order 0, 4096 bytes)
[    0.536874] NET: Registered protocol family 2
[    0.541761] IP idents hash table entries: 65536 (order: 7, 524288 bytes, linear)
[    0.552041] tcp_listen_portaddr_hash hash table entries: 2048 (order: 3, 32768 bytes, linear)
[    0.560901] TCP established hash table entries: 32768 (order: 6, 262144 bytes, linear)
[    0.569380] TCP bind hash table entries: 32768 (order: 7, 524288 bytes, linear)
[    0.577578] TCP: Hash tables configured (established 32768 bind 32768)
[    0.584560] UDP hash table entries: 2048 (order: 4, 65536 bytes, linear)
[    0.591579] UDP-Lite hash table entries: 2048 (order: 4, 65536 bytes, linear)
[    0.599208] NET: Registered protocol family 1
[    0.604428] RPC: Registered named UNIX socket transport module.
[    0.610525] RPC: Registered udp transport module.
[    0.615358] RPC: Registered tcp transport module.
[    0.620198] RPC: Registered tcp NFSv4.1 backchannel transport module.
[    0.626821] PCI: CLS 0 bytes, default 64
[    0.632115] hw perfevents: enabled with armv8_cortex_a53 PMU driver, 7 counters available
[    0.646905] Initialise system trusted keyrings
[    0.651741] workingset: timestamp_bits=46 max_order=20 bucket_order=0
[    0.663877] squashfs: version 4.0 (2009/01/31) Phillip Lougher
[    0.670600] NFS: Registering the id_resolver key type
[    0.675858] Key type id_resolver registered
[    0.680163] Key type id_legacy registered
[    0.684380] nfs4filelayout_init: NFSv4 File Layout Driver Registering...
[    0.691267] nfs4flexfilelayout_init: NFSv4 Flexfile Layout Driver Registering...
[    0.699073] 9p: Installing v9fs 9p2000 file system support
[    0.759961] Key type asymmetric registered
[    0.764181] Asymmetric key parser 'x509' registered
[    0.769229] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 243)
[    0.776828] io scheduler mq-deadline registered
[    0.781481] io scheduler kyber registered
[    0.788972] pinctrl-single 4301c000.pinctrl: 70 pins, size 280
[    0.795650] pinctrl-single 11c000.pinctrl: 185 pins, size 740
[    0.801738] pinctrl-single 11c2e8.pinctrl: 9 pins, size 36
[    0.814825] k3-ringacc 2b800000.ringacc: Failed to get MSI domain
[    0.821222] k3-ringacc 3c000000.ringacc: Failed to get MSI domain
[    0.832369] Serial: 8250/16550 driver, 10 ports, IRQ sharing enabled
[    0.859355] brd: module loaded
[    0.871647] loop: module loaded
[    0.876177] megasas: 07.714.04.00-rc1
[    0.885689] tun: Universal TUN/TAP device driver, 1.6
[    0.891838] igbvf: Intel(R) Gigabit Virtual Function Network Driver
[    0.898281] igbvf: Copyright (c) 2009 - 2012 Intel Corporation.
[    0.904461] sky2: driver version 1.30
[    0.909828] VFIO - User Level meta-driver version: 0.3
[    0.916321] i2c /dev entries driver
[    0.922045] sdhci: Secure Digital Host Controller Interface driver
[    0.928396] sdhci: Copyright(c) Pierre Ossman
[    0.933441] sdhci-pltfm: SDHCI platform and OF driver helper
[    0.941065] ledtrig-cpu: registered to indicate activity on CPUs
[    0.947360] ti-sci bus@100000:bus@28380000:bus@42040000:dmsc: invalid resource
[    0.955030] SMCCC: SOC_ID: ARCH_SOC_ID not implemented, skipping ....
[    0.963258] optee: probing for conduit method.
[    0.967867] optee: revision 3.18 (8e155bae)
[    0.968188] optee: dynamic shared memory is enabled
[    0.977991] optee: initialized driver
[    0.984691] NET: Registered protocol family 17
[    0.989433] 9pnet: Installing 9P2000 support
[    0.993932] Key type dns_resolver registered
[    0.998594] Loading compiled-in X.509 certificates
[    1.016016] k3-ringacc 2b800000.ringacc: Failed to get MSI domain
[    1.022615] k3-ringacc 3c000000.ringacc: Failed to get MSI domain
[    1.035752] ti-sci bus@100000:bus@28380000:bus@42040000:dmsc: invalid resource
[    1.043519] ti-sci bus@100000:bus@28380000:bus@42040000:dmsc: ABI: 3.1 (firmware rev 0x0016 '22.1.1--v2022.01 (Terrific Llam')
[    1.139514] omap_i2c 42120000.i2c: bus 0 rev0.12 at 400 kHz
[    1.146647] omap_i2c 40b00000.i2c: bus 1 rev0.12 at 100 kHz
[    1.154716] pca953x 2-0021: supply vcc not found, using dummy regulator
[    1.161678] pca953x 2-0021: using no AI
[    1.188645] omap_i2c 2000000.i2c: bus 2 rev0.12 at 400 kHz
[    1.195503] omap_i2c 2010000.i2c: bus 3 rev0.12 at 400 kHz
[    1.202250] omap_i2c 2020000.i2c: bus 4 rev0.12 at 400 kHz
[    1.208917] omap_i2c 2030000.i2c: bus 5 rev0.12 at 100 kHz
[    1.215961] ti-sci-intr bus@100000:bus@28380000:bus@42040000:interrupt-controller2: Interrupt Router 156 domain created
[    1.227283] ti-sci-intr bus@100000:interrupt-controller0: Interrupt Router 100 domain created
[    1.236279] ti-sci-intr bus@100000:main-navss:interrupt-controller1: Interrupt Router 182 domain created
[    1.246415] ti-sci-inta 33d00000.interrupt-controller: Interrupt Aggregator domain 179 created
[    1.269053] keystone-pcie 5500000.pcie: host bridge /bus@100000/pcie@5500000 ranges:
[    1.277041] OF: /bus@100000/pcie@5500000: Missing device_type
[    1.282978] keystone-pcie 5500000.pcie:       IO 0x0010020000..0x001002ffff -> 0x0000000000
[    1.291575] keystone-pcie 5500000.pcie:      MEM 0x0010030000..0x0017ffffff -> 0x0010030000
[    2.300736] keystone-pcie 5500000.pcie: Phy link never came up
[    2.306934] keystone-pcie 5500000.pcie: PCI host bridge to bus 0000:00
[    2.313667] pci_bus 0000:00: root bus resource [bus 00-ff]
[    2.319322] pci_bus 0000:00: root bus resource [io  0x0000-0xffff]
[    2.325672] pci_bus 0000:00: root bus resource [mem 0x10030000-0x17ffffff]
[    2.332776] pci 0000:00:00.0: [104c:b00c] type 01 class 0x060400
[    2.338961] pci 0000:00:00.0: reg 0x10: [mem 0x05500000-0x055fffff]
[    2.345411] pci 0000:00:00.0: reg 0x38: [mem 0x00000000-0x0000ffff pref]
[    2.352366] pci 0000:00:00.0: supports D1
[    2.356489] pci 0000:00:00.0: PME# supported from D0 D1 D3hot
[    2.370353] pci 0000:00:00.0: BAR 0: assigned [mem 0x10100000-0x101fffff]
[    2.377344] pci 0000:00:00.0: BAR 6: assigned [mem 0x10030000-0x1003ffff pref]
[    2.384768] pci 0000:00:00.0: PCI bridge to [bus 01-ff]
[    2.390612] pcieport 0000:00:00.0: PME: Signaling with IRQ 51
[    2.399544] k3-ringacc 2b800000.ringacc: Ring Accelerator probed rings:286, gp-rings[96,32] sci-dev-id:195
[    2.409492] k3-ringacc 2b800000.ringacc: dma-ring-reset-quirk: disabled
[    2.416288] k3-ringacc 2b800000.ringacc: RA Proxy rev. 66348100, num_proxies:64
[    2.427416] k3-ringacc 3c000000.ringacc: Ring Accelerator probed rings:818, gp-rings[304,100] sci-dev-id:187
[    2.437560] k3-ringacc 3c000000.ringacc: dma-ring-reset-quirk: disabled
[    2.444360] k3-ringacc 3c000000.ringacc: RA Proxy rev. 66348100, num_proxies:64
[    2.452987] 40a00000.serial: ttyS1 at MMIO 0x40a00000 (irq = 16, base_baud = 6000000) is a 8250
[    2.463258] 2800000.serial: ttyS2 at MMIO 0x2800000 (irq = 29, base_baud = 3000000) is a 8250
[    2.472078] printk: console [ttyS2] enabled
[    2.472078] printk: console [ttyS2] enabled
[    2.480549] printk: bootconsole [ns16550a0] disabled
[    2.480549] printk: bootconsole [ns16550a0] disabled
[    2.491831] 2810000.serial: ttyS3 at MMIO 0x2810000 (irq = 30, base_baud = 3000000) is a 8250
[    2.501459] 2820000.serial: ttyS4 at MMIO 0x2820000 (irq = 31, base_baud = 3000000) is a 8250
[    2.525593] davinci_mdio 46000f00.mdio: Configuring MDIO in manual mode
[    2.571795] davinci_mdio 46000f00.mdio: davinci mdio revision 9.7, bus freq 1000000
[    2.581760] davinci_mdio 46000f00.mdio: phy[0]: device 46000f00.mdio:00, driver TI DP83867
[    2.590163] am65-cpsw-nuss 46000000.ethernet: initializing am65 cpsw nuss version 0x6BA00102, cpsw version 0x6BA80102 Ports: 2 quirks:00000000
[    2.603056] am65-cpsw-nuss 46000000.ethernet: initialized cpsw ale version 1.4
[    2.610279] am65-cpsw-nuss 46000000.ethernet: ALE Table size 64
[    2.617473] am65-cpsw-nuss 46000000.ethernet: CPTS ver 0x4e8a010b, freq:200000000, add_val:4 pps:0
[    2.629462] am65-cpts 310d0000.cpts: CPTS ver 0x4e8a010b, freq:200000000, add_val:4 pps:0
[    2.641226] mmc0: CQHCI version 5.10
[    2.653514] pca953x 0-0039: supply vcc not found, using dummy regulator
[    2.660327] pca953x 0-0039: using no AI
[    2.682552] mmc0: SDHCI controller on 4f80000.mmc [4f80000.mmc] using ADMA 64-bit
[    2.689638] omap-mailbox 31f80000.mailbox: omap mailbox rev 0x66fc7100
[    2.697206] omap-mailbox 31f81000.mailbox: omap mailbox rev 0x66fc7100
[    2.705642] ti-udma 285c0000.dma-controller: Channels: 28 (tchan: 14, rchan: 14, gp-rflow: 16)
[    2.720825] ti-udma 31150000.dma-controller: Channels: 119 (tchan: 53, rchan: 66, gp-rflow: 64)
[    2.741967] spi-nor spi7.0: mt35xu512aba (65536 Kbytes)
[    2.747254] 8 cmdlinepart partitions found on MTD device 47040000.spi.0
[    2.753882] Creating 8 MTD partitions on "47040000.spi.0":
[    2.759372] 0x000000000000-0x000000080000 : "ospi.tiboot3"
[    2.766399] 0x000000080000-0x000000280000 : "ospi.tispl"
[    2.773042] 0x000000280000-0x000000680000 : "ospi.u-boot"
[    2.778878] mmc0: Command Queue Engine enabled
[    2.779830] 0x000000680000-0x0000006a0000 : "ospi.env"
[    2.783378] mmc0: new HS200 MMC card at address 0001
[    2.789742] 0x0000006a0000-0x0000006c0000 : "ospi.env.backup"
[    2.794261] mmcblk0: mmc0:0001 S0J56X 14.8 GiB
[    2.800619] 0x0000006c0000-0x0000007c0000 : "ospi.sysfw"
[    2.804056] mmcblk0boot0: mmc0:0001 S0J56X partition 1 31.5 MiB
[    2.810421] 0x000000800000-0x000003fe0000 : "ospi.rootfs"
[    2.815274] mmcblk0boot1: mmc0:0001 S0J56X partition 2 31.5 MiB
[    2.821881] 0x000003fe0000-0x000004000000 : "ospi.phypattern"
[    2.826648] mmcblk0rpmb: mmc0:0001 S0J56X partition 3 4.00 MiB, chardev (237:0)
[    2.843595] spi-nor spi9.0: n25q128a13 (16384 Kbytes)
[    2.852163] vdd_mmc1_sd: supplied by vcc3v3_io
[    2.858373] debugfs: Directory 'pd:121' with parent 'pm_genpd' already present!
[    2.858821] mmc1: CQHCI version 5.10
[    2.865777] debugfs: Directory 'pd:120' with parent 'pm_genpd' already present!
[    2.879165] input: gpio-keys as /devices/platform/gpio-keys/input/input0
[    2.907051] ALSA device list:
[    2.910039]   No soundcards found.
[    3.712514] mmc1: SDHCI controller on 4fa0000.mmc [4fa0000.mmc] using ADMA 64-bit
[    3.720560] Waiting for root device PARTUUID=2ae061e0-02...
[    3.776484] mmc1: new ultra high speed SDR104 SDHC card at address aaaa
[    3.783953] mmcblk1: mmc1:aaaa SM16G 14.8 GiB
[    3.791693]  mmcblk1: p1 p2
[    4.023051] EXT4-fs (mmcblk1p2): recovery complete
[    4.028572] EXT4-fs (mmcblk1p2): mounted filesystem with ordered data mode. Opts: (null)
[    4.036754] VFS: Mounted root (ext4 filesystem) on device 179:98.
[    4.045015] devtmpfs: mounted
[    4.049359] Freeing unused kernel memory: 1792K
[    4.054107] Run /sbin/init as init process
[    4.161504] systemd[1]: System time before build time, advancing clock.
[    4.216033] NET: Registered protocol family 10
[    4.221971] Segment Routing with IPv6
[    4.241085] systemd[1]: systemd 244.5+ running in system mode. (+PAM -AUDIT -SELINUX +IMA -APPARMOR -SMACK +SYSVINIT +UTMP -LIBCRYPTSETUP -GCRYPT -GNUTLS +ACL +XZ -LZ4 -SECCOMP +BLKID -ELFUTILS +KMOD -IDN2 -IDN -PCRE2 default-hierarchy=hybrid)
[    4.263355] systemd[1]: Detected architecture arm64.

Welcome to Arago 2021.09!

[    4.302244] systemd[1]: Set hostname to <am65xx-evm>.
[    4.624186] systemd[1]: /lib/systemd/system/docker.socket:6: ListenStream= references a path below legacy directory /var/run/, updating /var/run/docker.sock → /run/docker.sock; please update the unit file accordingly.
[    4.754681] random: systemd: uninitialized urandom read (16 bytes read)
[    4.761679] systemd[1]: system-getty.slice: unit configures an IP firewall, but the local system does not support BPF/cgroup firewalling.
[    4.774039] systemd[1]: (This warning is only shown for the first unit using IP firewalling.)
[    4.786767] systemd[1]: Created slice system-getty.slice.
[  OK  ] Created slice system-getty.slice.
[    4.808058] random: systemd: uninitialized urandom read (16 bytes read)
[    4.816682] systemd[1]: Created slice system-serial\x2dgetty.slice.
[  OK  ] Created slice system-serial\x2dgetty.slice.
[    4.839949] random: systemd: uninitialized urandom read (16 bytes read)
[    4.848336] systemd[1]: Created slice User and Session Slice.
[  OK  ] Created slice User and Session Slice.
[    4.872275] systemd[1]: Started Dispatch Password Requests to Console Directory Watch.
[  OK  ] Started Dispatch Password …ts to Console Directory Watch.
[    4.896136] systemd[1]: Started Forward Password Requests to Wall Directory Watch.
[  OK  ] Started Forward Password R…uests to Wall Directory Watch.
[    4.920143] systemd[1]: Reached target Paths.
[  OK  ] Reached target Paths.
[    4.935969] systemd[1]: Reached target Remote File Systems.
[  OK  ] Reached target Remote File Systems.
[    4.955936] systemd[1]: Reached target Slices.
[  OK  ] Reached target Slices.
[    4.971963] systemd[1]: Reached target Swap.
[  OK  ] Reached target Swap.
[    4.991472] systemd[1]: Listening on RPCbind Server Activation Socket.
[  OK  ] Listening on RPCbind Server Activation Socket.
[    5.016072] systemd[1]: Reached target RPC Port Mapper.
[  OK  ] Reached target RPC Port Mapper.
[    5.043831] systemd[1]: Listening on Process Core Dump Socket.
[  OK  ] Listening on Process Core Dump Socket.
[    5.064312] systemd[1]: Listening on initctl Compatibility Named Pipe.
[  OK  ] Listening on initctl Compatibility Named Pipe.
[    5.098012] systemd[1]: Condition check resulted in Journal Audit Socket being skipped.
[    5.106904] systemd[1]: Listening on Journal Socket (/dev/log).
[  OK  ] Listening on Journal Socket (/dev/log).
[    5.128676] systemd[1]: Listening on Journal Socket.
[  OK  ] Listening on Journal Socket.
[    5.144744] systemd[1]: Listening on Network Service Netlink Socket.
[  OK  ] Listening on Network Service Netlink Socket.
[    5.168443] systemd[1]: Listening on udev Control Socket.
[  OK  ] Listening on udev Control Socket.
[    5.188278] systemd[1]: Listening on udev Kernel Socket.
[  OK  ] Listening on udev Kernel Socket.
[    5.213833] systemd[1]: Mounting Huge Pages File System...
         Mounting Huge Pages File System...
[    5.237604] systemd[1]: Mounting POSIX Message Queue File System...
         Mounting POSIX Message Queue File System...
[    5.265662] systemd[1]: Mounting Kernel Debug File System...
         Mounting Kernel Debug File System...
[    5.291540] systemd[1]: Mounting Temporary Directory (/tmp)...
         Mounting Temporary Directory (/tmp)...
[    5.314309] systemd[1]: Starting Create list of static device nodes for the current kernel...
         Starting Create list of st…odes for the current kernel...
[    5.345376] systemd[1]: Starting Start psplash boot splash screen...
         Starting Start psplash boot splash screen...
[    5.374947] systemd[1]: Starting RPC Bind...
         Starting RPC Bind...
[    5.388367] systemd[1]: Condition check resulted in File System Check on Root Device being skipped.
[    5.404753] systemd[1]: Starting Journal Service...
         Starting Journal Service...
[    5.428651] systemd[1]: Starting Load Kernel Modules...
         Starting Load Kernel Modules...
[    5.449959] systemd[1]: Starting Remount Root and Kernel File Systems...
[    5.449968] cryptodev: loading out-of-tree module taints kernel.
[    5.457865] cryptodev: driver 1.10 loaded.
         Starting Remount Root and Kernel File Systems...
[    5.483166] EXT4-fs (mmcblk1p2): re-mounted. Opts: (null)
[    5.494689] systemd[1]: Starting udev Coldplug all Devices...
         Starting udev Coldplug all Devices...
[    5.528641] systemd[1]: Started RPC Bind.
[  OK  ] Started RPC Bind.
[    5.548822] systemd[1]: Started Journal Service.
[  OK  ] Started Journal Service.
[  OK  ] Mounted Huge Pages File System.
[  OK  ] Mounted POSIX Message Queue File System.
[  OK  ] Mounted Kernel Debug File System.
[  OK  ] Mounted Temporary Directory (/tmp).
[  OK  ] Started Create list of sta… nodes for the current kernel.
[FAILED] Failed to start Start psplash boot splash screen.
See 'systemctl status psplash-start.service' for details.
[DEPEND] Dependency failed for Star…progress communication helper.
[  OK  ] Started Load Kernel Modules.
[  OK  ] Started Remount Root and Kernel File Systems.
         Mounting Kernel Configuration File System.[    5.762081] random: systemd-journal: uninitialized urandom read (16 bytes read)
..
[    5.791646] random: systemd: uninitialized urandom read (16 bytes read)
         Starting Flush Journal to Persistent Storage    5.805763] random: systemd-journal: uninitialized urandom read (16 bytes read)
0m...
[    5.821474] systemd-journald[189]: Received client request to flush runtime journal.
         Starting Apply Kernel Variables...
         Starting Create Static Device Nodes in /dev...
[  OK  ] Mounted Kernel Configuration File System.
[  OK  ] Started Flush Journal to Persistent Storage.
[  OK  ] Started Apply Kernel Variables.
[  OK  ] Started Create Static Device Nodes in /dev.
[  OK  ] Reached target Local File Systems (Pre).
         Mounting /media/ram...
         Mounting /var/volatile...
         Starting udev Kernel Device Manager...
[  OK  ] Mounted /media/ram.
[  OK  ] Mounted /var/volatile.
         Starting Load/Save Random Seed...
[  OK  ] Started udev Kernel Device Manager.
[  OK  ] Started udev Coldplug all Devices.
         Starting udev Wait for Complete Device Initialization...
[    6.515344] random: crng init done
[    6.519331] random: 56 urandom warning(s) missed due to ratelimiting
[  OK  ] Started Load/Save Random Seed.
[    6.914642] davinci_mdio b032400.mdio: Configuring MDIO in manual mode
[    6.915221] [drm] Initialized pvr 1.17.4948957 20110701 for 7000000.gpu on minor 0
[    6.937425] cal 6f03000.cal: Neither port is configured, no point in staying up
[    6.959894] davinci_mdio b032400.mdio: davinci mdio revision 1.7, bus freq 1000000
[    7.005314] davinci_mdio b032400.mdio: phy[0]: device b032400.mdio:00, driver TI DP83867
[    7.013544] davinci_mdio b032400.mdio: phy[3]: device b032400.mdio:03, driver TI DP83867
[    7.030983] CAN device driver interface
[    7.083142] davinci_mdio b132400.mdio: Configuring MDIO in manual mode
[    7.107703] platform 41000000.r5f: configured R5F for remoteproc mode
[    7.128345] platform 41000000.r5f: assigned reserved memory node r5f-dma-memory@a0000000
[    7.137858] davinci_mdio b132400.mdio: davinci mdio revision 1.7, bus freq 1000000
[    7.162849] remoteproc remoteproc0: 41000000.r5f is available
[    7.173527] davinci_mdio b132400.mdio: phy[0]: device b132400.mdio:00, driver TI DP83867
[    7.187467] remoteproc remoteproc0: powering up 41000000.r5f
[    7.193335] remoteproc remoteproc0: Booting fw image am65x-mcu-r5f0_0-fw, size 82412
[    7.205611]  remoteproc0#vdev0buffer: assigned reserved memory node r5f-dma-memory@a0000000
[    7.214814] virtio_rpmsg_bus virtio0: rpmsg host is online
[    7.220530]  remoteproc0#vdev0buffer: registered virtio0 (type 7)
[    7.226533] virtio_rpmsg_bus virtio0: creating channel ti.ipc4.ping-pong addr 0xd
[    7.226709] remoteproc remoteproc0: remote processor 41000000.r5f is now up
[    7.234551] virtio_rpmsg_bus virtio0: creating channel rpmsg_chrdev addr 0xe
[    7.243864] davinci_mdio b132400.mdio: phy[3]: device b132400.mdio:03, driver TI DP83867
[    7.416702] davinci_mdio b232400.mdio: Configuring MDIO in manual mode
[    7.463916] davinci_mdio b232400.mdio: davinci mdio revision 1.7, bus freq 1000000
[    7.492509] davinci_mdio b232400.mdio: phy[0]: device b232400.mdio:00, driver TI DP83867
[    7.502075] davinci_mdio b232400.mdio: phy[3]: device b232400.mdio:03, driver TI DP83867
[    7.599140] m_can_platform 40568000.mcan: m_can device registered (irq=25, version=32)
[    7.621876] m_can_platform 40528000.mcan: m_can device registered (irq=23, version=32)
[    7.645757] remoteproc remoteproc1: b034000.pru is available
[    7.652575] remoteproc remoteproc2: b004000.rtu is available
[    7.659375] remoteproc remoteproc3: b00a000.txpru is available
[    7.666301] remoteproc remoteproc4: b038000.pru is available
[    7.672722] remoteproc remoteproc5: b006000.rtu is available
[    7.679270] remoteproc remoteproc6: b00c000.txpru is available
[    7.686266] remoteproc remoteproc7: b134000.pru is available
[    7.756572] remoteproc remoteproc8: b104000.rtu is available
[    7.781667] remoteproc remoteproc9: b10a000.txpru is available
[    7.888513] remoteproc remoteproc10: b138000.pru is available
[    7.971927] remoteproc remoteproc11: b106000.rtu is available
[    8.057959] remoteproc remoteproc12: b10c000.txpru is available
[    8.109868] remoteproc remoteproc13: b234000.pru is available
[    8.154014] remoteproc remoteproc14: b204000.rtu is available
[    8.225102] remoteproc remoteproc15: b20a000.txpru is available
[    8.232041] remoteproc remoteproc16: b238000.pru is available
[    8.240077] remoteproc remoteproc17: b206000.rtu is available
[    8.251108] remoteproc remoteproc18: b20c000.txpru is available
[    8.970058] OF: graph: no port node found in /bus@100000/phy@4110000
[    9.000166] TI DP83867 b032400.mdio:00: attached PHY driver [TI DP83867] (mii_bus:phy_addr=b032400.mdio:00, irq=POLL)
[    9.020692] TI DP83867 b032400.mdio:03: attached PHY driver [TI DP83867] (mii_bus:phy_addr=b032400.mdio:03, irq=POLL)
[    9.031398] icssg-prueth icssg0-eth: TI PRU ethernet driver initialized: dual EMAC mode
[    9.058896] TI DP83867 b232400.mdio:00: attached PHY driver [TI DP83867] (mii_bus:phy_addr=b232400.mdio:00, irq=POLL)
[    9.078973] TI DP83867 b232400.mdio:03: attached PHY driver [TI DP83867] (mii_bus:phy_addr=b232400.mdio:03, irq=POLL)
[    9.089673] icssg-prueth icssg2-eth: TI PRU ethernet driver initialized: dual EMAC mode
[    9.123607] TI DP83867 b132400.mdio:00: attached PHY driver [TI DP83867] (mii_bus:phy_addr=b132400.mdio:00, irq=POLL)
[    9.145651] TI DP83867 b132400.mdio:03: attached PHY driver [TI DP83867] (mii_bus:phy_addr=b132400.mdio:03, irq=POLL)
[    9.159889] icssg-prueth icssg1-eth: TI PRU ethernet driver initialized: dual EMAC mode
[  OK  ] Reached target Hardware activated USB gadget.
[    9.569915] usbcore: registered new interface driver usbfs
[    9.575592] usbcore: registered new interface driver hub
[    9.596168] usbcore: registered new device driver usb
[    9.647154] xhci-hcd xhci-hcd.2.auto: xHCI Host Controller
[    9.664850] xhci-hcd xhci-hcd.2.auto: new USB bus registered, assigned bus number 1
[    9.684728] xhci-hcd xhci-hcd.2.auto: hcc params 0x0298fe6d hci version 0x110 quirks 0x0000000000010010
[    9.699296] xhci-hcd xhci-hcd.2.auto: irq 594, io mem 0x04010000
[    9.706722] usb usb1: New USB device found, idVendor=1d6b, idProduct=0002, bcdDevice= 5.10
[    9.715375] usb usb1: New USB device strings: Mfr=3, Product=2, SerialNumber=1
[    9.722852] usb usb1: Product: xHCI Host Controller
[    9.728791] usb usb1: Manufacturer: Linux 5.10.140-g5e63ae91b2 xhci-hcd
[    9.738707] usb usb1: SerialNumber: xhci-hcd.2.auto
[    9.748437] hub 1-0:1.0: USB hub found
[    9.756401] hub 1-0:1.0: 1 port detected
[    9.769365] xhci-hcd xhci-hcd.2.auto: xHCI Host Controller
[    9.777876] xhci-hcd xhci-hcd.2.auto: new USB bus registered, assigned bus number 2
[    9.791574] xhci-hcd xhci-hcd.2.auto: Host supports USB 3.0 SuperSpeed
[    9.825155] usb usb2: We don't know the algorithms for LPM for this host, disabling LPM.
[    9.835547] usb usb2: New USB device found, idVendor=1d6b, idProduct=0003, bcdDevice= 5.10
[    9.844077] usb usb2: New USB device strings: Mfr=3, Product=2, SerialNumber=1
[    9.858922] usb usb2: Product: xHCI Host Controller
[    9.866578] usb usb2: Manufacturer: Linux 5.10.140-g5e63ae91b2 xhci-hcd
[    9.878477] usb usb2: SerialNumber: xhci-hcd.2.auto
[    9.885032] hub 2-0:1.0: USB hub found
[    9.889118] hub 2-0:1.0: 1 port detected
[  OK  ] Found device /dev/disk/by-uuid/795D-0E20.
[  OK  ] Started udev Wait for Complete Device Initialization.
         Mounting /boot...
[  OK  ] Started Hardware RNG Entropy Gather[   10.155662] FAT-fs (mmcblk1p1): Volume was not properly unmounted. Some data may be corrupt. Please run fsck.
er Daemon.
[  OK  ] Mounted /boot.
[  OK  ] Reached target Local File Systems.
         Starting Create Volatile Files and Directories...
[  OK  ] Started Create Volatile Files and Directories.
         Starting Network Time Synchronization...
         Starting Update UTMP about System Boot/Shutdown...
[  OK  ] Started Update UTMP about System Boot/Shutdown.
[  OK  ] Started Network Time Synchronization.
[  OK  ] Reached target System Initialization.
[  OK  ] Started Daily Cleanup of Temporary Directories.
[  OK  ] Reached target System Time Set.
[  OK  ] Reached target System Time Synchronized.
[  OK  ] Started Daily rotation of log files.
[  OK  ] Reached target Timers.
[  OK  ] Listening on Avahi mDNS/DNS-SD Stack Activation Socket.
[  OK  ] Listening on D-Bus System Message Bus Socket.
         Starting Docker Socket for the API.
[  OK  ] Listening on dropbear.socket.
         Starting Reboot and dump vmcore via kexec...
[  OK  ] Listening on Docker Socket for the API.
[  OK  ] Started Reboot and dump vmcore via kexec.
[  OK  ] Reached target Sockets.
[  OK  ] Reached target Basic System.
[  OK  ] Started Job spooling tools.
[  OK  ] Started Periodic Command Scheduler.
[  OK  ] Started D-Bus System Message Bus.
         Starting Print notice about GPLv3 packages...
         Starting IPv6 Packet Filtering Framework...
         Starting IPv4 Packet Filtering Framework...
[  OK  ] Started irqbalance daemon.
         Starting rc.pvr.service...
         Starting Login Service...
[  OK  ] Started TEE Supplicant.
[  OK  ] Started IPv6 Packet Filtering Framework.
[  OK  ] Started IPv4 Packet Filtering Framework.
[  OK  ] Reached target Network (Pre).
         Starting Network Service...
[   11.012195] PVR_K: UM DDK-(4948957) and KM DDK-(4948957) match. [ OK ]
[  OK  ] Started rc.pvr.service.
         Starting weston.service...
[  OK  ] Started weston.service.
         Starting Matrix GUI...
         Starting telnetd.service...
[  OK  ] Started telnetd.service.
[  OK  ] Started Matrix GUI.
[  OK  ] Started Network Service.
         Starting Wait for Network to be Configured...
         Starting Network Name Resolution...
[   11.394397] remoteproc remoteproc10: powering up b138000.pru
[   11.406798] remoteproc remoteproc10: Booting fw image ti-pruss/am65x-sr2-pru1-prueth-fw.elf, size 37920
[   11.424001] remoteproc remoteproc10: unsupported resource 5
[   11.429815] remoteproc remoteproc10: remote processor b138000.pru is now up
[   11.438716] remoteproc remoteproc11: powering up b106000.rtu
[   11.451637] remoteproc remoteproc11: Booting fw image ti-pruss/am65x-sr2-rtu1-prueth-fw.elf, size 30100
[   11.464125] remoteproc remoteproc11: remote processor b106000.rtu is now up
[   11.480705] remoteproc remoteproc12: powering up b10c000.txpru
[   11.516118] remoteproc remoteproc12: Booting fw image ti-pruss/am65x-sr2-txpru1-prueth-fw.elf, size 35596
[   11.539930] remoteproc remoteproc12: remote processor b10c000.txpru is now up
[   11.572952] icssg-prueth icssg1-eth: settime timeout
[   11.578440] pps pps0: new PPS source ptp2
[   11.596836] net eth6: started
[   11.651544] remoteproc remoteproc7: powering up b134000.pru
[  OK  ] Started Login Service.
[   11.674242] remoteproc remoteproc7: Booting fw image ti-pruss/am65x-sr2-pru0-prueth-fw.elf, size 37644
[   11.685716] remoteproc remoteproc7: unsupported resource 5
[   11.699240] remoteproc remoteproc7: remote processor b134000.pru is now up
[   11.709751] remoteproc remoteproc8: powering up b104000.rtu
[   11.732109] remoteproc remoteproc8: Booting fw image ti-pruss/am65x-sr2-rtu0-prueth-fw.elf, size 30860
[   11.756483] remoteproc remoteproc8: remote processor b104000.rtu is now up
[   11.766800] remoteproc remoteproc9: powering up b10a000.txpru
[   11.777531] remoteproc remoteproc9: Booting fw image ti-pruss/am65x-sr2-txpru0-prueth-fw.elf, size 36948
[   11.790047] remoteproc remoteproc9: remote processor b10a000.txpru is now up
[   11.809811] net eth5: started
[   11.835004] remoteproc remoteproc16: powering up b238000.pru
[   11.843198] remoteproc remoteproc16: Booting fw image ti-pruss/am65x-sr2-pru1-prueth-fw.elf, size 37920
[   11.859886] remoteproc remoteproc16: unsupported resource 5
[   11.866865] remoteproc remoteproc16: remote processor b238000.pru is now up
[   11.879876] remoteproc remoteproc17: powering up b206000.rtu
[   11.887261] remoteproc remoteproc17: Booting fw image ti-pruss/am65x-sr2-rtu1-prueth-fw.elf, size 30100
[   11.897958] remoteproc remoteproc17: remote processor b206000.rtu is now up
[   11.907905] remoteproc remoteproc18: powering up b20c000.txpru
[   11.916577] remoteproc remoteproc18: Booting fw image ti-pruss/am65x-sr2-txpru1-prueth-fw.elf, size 35596
[   11.929804] remoteproc remoteproc18: remote processor b20c000.txpru is now up
[   11.946049] icssg-prueth icssg2-eth: settime timeout
[   11.951561] pps pps1: new PPS source ptp3
[   11.968486] net eth4: started
[   11.988177] remoteproc remoteproc13: powering up b234000.pru
[   11.994795] remoteproc remoteproc13: Booting fw image ti-pruss/am65x-sr2-pru0-prueth-fw.elf, size 37644
[   12.010496] remoteproc remoteproc13: unsupported resource 5
[   12.018172] remoteproc remoteproc13: remote processor b234000.pru is now up
[   12.029881] remoteproc remoteproc14: powering up b204000.rtu
[   12.038735] remoteproc remoteproc14: Booting fw image ti-pruss/am65x-sr2-rtu0-prueth-fw.elf, size 30860
[   12.052296] remoteproc remoteproc14: remote processor b204000.rtu is now up
[   12.064503] remoteproc remoteproc15: powering up b20a000.txpru
[   12.072990] remoteproc remoteproc15: Booting fw image ti-pruss/am65x-sr2-txpru0-prueth-fw.elf, size 36948
[   12.088936] remoteproc remoteproc15: remote processor b20a000.txpru is now up
[   12.101696] net eth3: started
[  OK  ] Started Network Name Resolution.
[  OK  ] Reached target Network.
[  OK  ] Reached target Host and Network Name L[   12.123604] remoteproc remoteproc4: powering up b038000.pru
ookups.
         Starting Avahi mDNS/DNS-SD Stack remoteproc remoteproc4: Booting fw image ti-pruss/am65x-sr2-pru1-prueth-fw.elf, size 37920
[0m...
         Starting Enable and configure wl18xx bluetooth stack...
[  OK  ] Started NFS status monitor for NFSv2/3 locking..
[   12.163020] remoteproc remoteproc4: unsupported resource 5
         Starting Simple Network Ma…ent Protocol (SNM[   12.173771] remoteproc remoteproc4: remote processor b038000.pru is now up
P) Daemon....
[   12.183945] remoteproc remoteproc5: powering up b006000.rtu
         Starting Permit User Sessions...
[   12.190101] remoteproc remoteproc5: Booting fw image ti-pruss/am65x-sr2-rtu1-prueth-fw.elf, size 30100
[   12.208457] remoteproc remoteproc5: remote processor b006000.rtu is now up
[  OK  ] Started Enable and configure wl18xx[   12.220749] remoteproc remoteproc6: powering up b00c000.txpru
 bluetooth stack.
[   12.229329] remoteproc remoteproc6: Booting fw image ti-pruss/am65x-sr2-txpru1-prueth-fw.elf, size 35596
[   12.243973] remoteproc remoteproc6: remote processor b00c000.txpru is now up
[  OK  ] Started Permit User Sessions.
[   12.256566] icssg-prueth icssg0-eth: settime timeout
[  OK  ] Started Avahi mDNS/DNS-SD Stack[   12.265698] pps pps2: new PPS source ptp4
.
[  OK  ] Started Getty on tty1.
[  OK  ] Started Getty on tty4.
[   12.289482] net eth2: started
[  OK  ] Started Serial Getty on ttyS1.
[  OK  ] Started Serial Getty on ttyS2.
[  OK  ] Reached target Login Prompts.
         Starting Synchronize System and HW clocks...
[FAILED] Failed to start Synchronize System and HW clocks.
See 'systemctl status sync-clocks.service'[   12.375166] remoteproc remoteproc1: powering up b034000.pru
 for details.
[   12.384205] remoteproc remoteproc1: Booting fw image ti-pruss/am65x-sr2-pru0-prueth-fw.elf, size 37644
[   12.403964] remoteproc remoteproc1: unsupported resource 5
[   12.409565] remoteproc remoteproc1: remote processor b034000.pru is now up
[   12.419881] remoteproc remoteproc2: powering up b004000.rtu
[   12.425894] remoteproc remoteproc2: Booting fw image ti-pruss/am65x-sr2-rtu0-prueth-fw.elf, size 30860
[   12.439889] remoteproc remoteproc2: remote processor b004000.rtu is now up
[   12.446950] remoteproc remoteproc3: powering up b00a000.txpru
[  OK  ] Created slice system-systemd\x2dcor[   12.456063] remoteproc remoteproc3: Booting fw image ti-pruss/am65x-sr2-txpru0-prueth-fw.elf, size 36948
edump.slice.
[  OK  ] Started Process Core Dump (PID 962/UID 0).
[   12.475918] remoteproc remoteproc3: remote processor b00a000.txpru is now up
[   12.490045] net eth1: started
[   12.530531] am65-cpsw-nuss 46000000.ethernet: down msc_sl f0000000 tmo 0
[   12.555136] am65-cpsw-nuss 46000000.ethernet: set new flow-id-base 48
[   12.588447] am65-cpsw-nuss 46000000.ethernet eth0: PHY [46000f00.mdio:00] driver [TI DP83867] (irq=POLL)
[   12.600340] am65-cpsw-nuss 46000000.ethernet eth0: configuring for phy/rgmii-rxid link mode
[  OK  ] Started Simple Network Man…ement Protocol (SNMP) Daemon..
***************************************************************
***************************************************************
NOTICE: This file system contains the following GPLv3 packages:
        autoconf
        bash
        bc
        binutils
        cifs-utils
        coreutils-stdbuf
        coreutils
        cpio
        cpp-symlinks
        cpp
        dosfstools
        elfutils
        g++-symlinks
        g++
        gawk
        gcc-symlinks
        gcc
        gdb
        gdbserver
        gettext
        glmark2
        gstreamer1.0-libav
        gzip
        less
        libasm1
        libbfd
        libdw1
        libelf1
        libgdbm-compat4
        libgdbm6
        libgettextlib
        libgettextsrc
        libgmp10
        libidn2-0
        libmpc3
        libmpfr6
        libreadline8
        libunistring2
        m4
        make
        nettle
        parted
        pdm-anomaly-detection
        tar
        which

If you do not wish to distribute GPLv3 components please remove
the above packages prior to distribution.  This can be done using
the opkg remove command.  i.e.:
    opkg remove <package>
Where <package> is the name printed in the list above

NOTE: If the package is a dependency of another package you
      will be notified of the dependent packages.  You should
      use the --force-removal-of-dependent-packages option to
      also remove the dependent packages as well
***************************************************************
***************************************************************
[  OK  ] Started Print notice about GPLv3 packages.

 _____                    _____           _         _
|  _  |___ ___ ___ ___   |  _  |___ ___  |_|___ ___| |_
|     |  _| .'| . | . |  |   __|  _| . | | | -_|  _|  _|
|__|__|_| |__,|_  |___|  |__|  |_| |___|_| |___|___|_|
              |___|                    |___|

Arago Project am65xx-evm ttyS2

Arago 2021.09 am65xx-evm ttyS2

am65xx-evm login: root
root@am65xx-evm:~# uname -a
Linux am65xx-evm 5.10.140-g5e63ae91b2 #1 SMP PREEMPT Sat Sep 24 23:11:05 UTC 2022 aarch64 aarch64 aarch64 GNU/Linux
root@am65xx-evm:~# cd linuxptp-3.1.1/
root@am65xx-evm:~/linuxptp-3.1.1# while true; do ./phc_ctl eth1 get; sleep 600; done;
phc_ctl[32.460]: clock time is 1663978486.146100236 or Sat Sep 24 00:14:46 2022

[  132.425837] Initializing XFRM netlink socket
[  133.486083] bridge: filtering via arp/ip/ip6tables is no longer available by default. Update your scripts to load br_netfilter if you need this.
[  133.504628] Bridge firewalling registered
[  134.447714] process 'docker/tmp/qemu-check441653340/check' started with executable stack
phc_ctl[632.477]: clock time is 1663979086.162740768 or Sat Sep 24 00:24:46 2022

phc_ctl[1232.488]: clock time is 1663979686.174027264 or Sat Sep 24 00:34:46 2022

phc_ctl[1832.499]: clock time is 1663980286.185235344 or Sat Sep 24 00:44:46 2022

phc_ctl[2432.510]: clock time is 1663980886.196480636 or Sat Sep 24 00:54:46 2022

phc_ctl[3032.522]: clock time is 1663973097.599631892 or Fri Sep 23 22:44:57 2022

^C
root@am65xx-evm:~/linuxptp-3.1.1# ./phc_ctl eth1 set 16770
phc_ctl[3083.646]: set clock time to 16770.000000000 or Thu Jan  1 04:39:30 1970

root@am65xx-evm:~/linuxptp-3.1.1# ./phc_ctl eth1 get
phc_ctl[3086.997]: clock time is 16773.351796776 or Thu Jan  1 04:39:33 1970

root@am65xx-evm:~/linuxptp-3.1.1# ./phc_ctl eth1 get
phc_ctl[3093.861]: clock time is 8391.607976620 or Thu Jan  1 02:19:51 1970

root@am65xx-evm:~/linuxptp-3.1.1# ^C
root@am65xx-evm:~/linuxptp-3.1.1#

Please do proper testing for future provided fix. Use steps how to reproduce in 100% cases (on all versions) of my forum post.

Thank you for support,
Lukas

Hello Lukas,

Thank you for testing with the SDK 8.4 Linux image and firmware. I am passing your observations to the developer.

I am also working on replicating your observations on my end. So far I have replicated your results on SDK 8.2. I will try to replicate your observations on SDK 8.4 either Tuesday or Wednesday.

Double-checking: These tests seem to be with no any PTP communication over Ethernet. I assume this is not your actual usecase? (synchronizing the PRU Ethernet clock with the system clock without anything else going on).

Regards,

Nick

Hello Nick,

In my setup for clock jump bug is no Ethernet connection so no PTP communication. Sure it is not a usecase.

There is isolated bug which occurs in 100% cases without other external influence. Clock of PTP device (PRU) jumps itself.

Regards,

Lukas

Hello Lukas,

Makes sense. The developer said they would take another look at replicating your results. I will run tests on SDK 8.4 tomorrow.

Regards,

Nick

Hello Lukas,

I have validated your observations on SDK 8.4 as well. No updates from the developer yet. I'll be on vacation later this week, but please ping the thread if I have not provided an update by early next week.

Regards,

Nick

Hello Lukas,

Linux developer replicated your observations. They are discussing with the firmware team. Please feel free to ping the thread if I have not provided another update by the middle of next week.

Regards,

Nick

Hello Lukas,

No major updates yet. I have pinged the developers to make sure the discussion continues.

Regards,

Nick

Hello Nick,

do you have some outcome of the developer discussion?

Regards,
Lukas

Hello Lucas,

No major updates at this point, I just sent a message checking in with the developer. We are still tracking this clock jump behavior to resolve by the middle of December, as aligned in offline communication a while back.

Regards,

Nick

Hello Lucas,

Summary

The team is still working on the issue. It looks like the IEP counter is not incrementing the way the Linux driver is expecting. I have been provided a potential Linux driver workaround (included below). However, we still need to hear back from the firmware team on expected IEP timer behavior between SR1 and SR2, and whether any firmware side patches are required.

More information from the developer 

Observation :-

The actual implementation of icss_iep_gettime() API is different for SR1.0 and SR2.0 because of which the issue is only seen on SR2.0.

In SR2.0, in icss_iep_gettime() API, two different counters are maintained.

1. iepcount_hi [ Reads the value from ICSS_IEP_COUNT_REG1 register ].
2. hi_rollover_count [ Reads the value from "prueth->shram.va + TIMESYNC_FW_WC_HI_ROLLOVER_COUNT_OFFSET" ]

From the driver implementation it looks like, the iepcount_hi counter keeps the time count and it overflows once it reaches 2^23 [ = 8388608 ]and hi_rollover_count is incremented.
Timestamp is calculated by doing OR between hi_rollover_count*2^23 and iep_count_hi.

Below is the implementation of calculating timestamp.

    ts = ((u64)hi_rollover_count) << 23 | iepcount_hi;
    ts = ts * (u64)IEP_DEFAULT_CYCLE_TIME_NS + iepcount_lo;

The issue here is that the driver is expecting iepcount_hi to overflow once it reaches 2^23 and hi_rollover_count to be incremented. But this is not happening.
Even after reaching 2^23 the iepcount_hi keeps getting incremented and does not overflow. Also the rollover count doesn't get incremented. Because of which the bit-wise OR operation results in different value and time jump is seen.

When we set the clock, all the counters value is configured properly. But when the time passes and we do a gettime, the iepcount_hi increases beyond 2^23 and the rollover counter doesn't increase. Resulting in the issue.

Example :-

 We have seen that the first time jump is happening at 16770 Seconds. When we set the clock to 16770, below are the counter values.

root@am65xx-evm:~/linuxptp-3.1.1# ./phc_ctl eth6 get      
phc_ctl[119.409]: clock time is 16774.525879396 or Thu Jan  1 04[  119.472828]

[  119.472879]  iepcount_hi 8385917
[  119.472879]  hi_rollover_count 1

Here the iepcount_hi is 8385917 which is less than 2^23 (8388608)

the timestamp calculated = hi_rollover_count << 23 | iepcount_hi = 1<<23 | 8385917 = 16774525
after adding the converting it to nanoseconds and adding iepcount_l,

timestamp = 16774525807120 = 16774 Seconds.

After 4 seconds, the expectation is the time will be 16778 seconds but it jumps. Below is the counter values after 3-4 Seconds

[  122.840977]  iepcount_hi 8389285
[  122.840977]  hi_rollover_count 1

We can see here the iep count is going above the 2^23 [ 8388608 ]. And the rollover counter is still the same. Due to which the timestamp calculated is not what we expect.

the timestamp calculated = hi_rollover_count << 23 | iepcount_hi = 1<<23 | 8389285 = 8389285
after adding the converting it to nanoseconds and adding iepcount_l,

timestamp = 8389285380200 = 8389 Seconds.

The OR of rollover counter << 23 and iepcount_hi will always be same as iepcount_hi is greater than 2^23. The difference is almost half of the expected value.
Due to which the time instead of being 16778 seconds, jumps to 8389 seconds.

The rollover counter needs to increase as expected.

Workaround :-

I have added the below code in driver to increase the rollover counter and decrease the iepcount_hi when iepcount_hi reaches 2^23.

if(iepcount_hi >  1 << 23){
        hi_rollover_count++;
        iepcount_hi -= (1 << 23);
}

After adding this code. Clock jump was not observed.

Regards,

Nick

I send a post to prevent auto close. Still interested for proper fix of the clock.

Hello Lukas,

Thanks for the ping here. We filed a bug against the firmware back in December, but I have not heard any updates from the firmware team at this point. I have reached out to them again to ask for comment.

In the meantime, does the driver workaround get rid of the issue on your side?

Regards,

Nick

Hello Nick,

no I did not test the workaround. How you mentioned the workaround is based on observation in driver and I guess for this one exact case. There is no information about this behavior from firmware team.

I would like to get at least confirmation from firmware team, that the firmware behaves in all times like this. Then I can start workaround testing in long time period. Even so, I won't be able to test the immediate vicinity of the iepcount_hi overflow when reaching 2^23.

I still prefer final proper fix based on outcome from clarification between firmware and driver implementation.

Regards,
Lukas

Hello Nick, 

Thank you for good news.

Is the new firmware already in related repository https://git.ti.com/cgit/processor-firmware/ti-linux-firmware?

The clock jump has no changes in driver, the driver updates are related to others, XDP etc.. So should I use currently latest available?

Regards,
Lukas

Hello Lukas,

Apologies for the delayed response, been dealing with medical issues. Jumping on this evening before I have to go offline for medical reasons for at least another couple of days.

I would expect this was fixed before the AM64x SDK 8.6 release, so I would expect that the ti-linux-firmware was updated for that SDK release.

Regards,

Nick