Note: This bug is displayed in read-only format because the product is no longer active in Red Hat Bugzilla.
RHEL Engineering is moving the tracking of its product development work on RHEL 6 through RHEL 9 to Red Hat Jira (issues.redhat.com). If you're a Red Hat customer, please continue to file support cases via the Red Hat customer portal. If you're not, please head to the "RHEL project" in Red Hat Jira and file new tickets here. Individual Bugzilla bugs in the statuses "NEW", "ASSIGNED", and "POST" are being migrated throughout September 2023. Bugs of Red Hat partners with an assigned Engineering Partner Manager (EPM) are migrated in late September as per pre-agreed dates. Bugs against components "kernel", "kernel-rt", and "kpatch" are only migrated if still in "NEW" or "ASSIGNED". If you cannot log in to RH Jira, please consult article #7032570. That failing, please send an e-mail to the RH Jira admins at rh-issues@redhat.com to troubleshoot your issue as a user management inquiry. The email creates a ServiceNow ticket with Red Hat. Individual Bugzilla bugs that are migrated will be moved to status "CLOSED", resolution "MIGRATED", and set with "MigratedToJIRA" in "Keywords". The link to the successor Jira issue will be found under "Links", have a little "two-footprint" icon next to it, and direct you to the "RHEL project" in Red Hat Jira (issue links are of type "https://issues.redhat.com/browse/RHEL-XXXX", where "X" is a digit). This same link will be available in a blue banner at the top of the page informing you that that bug has been migrated.

Bug 2150815

Summary: RFE: detect conflicting processes controlling clock
Product: Red Hat Enterprise Linux 9 Reporter: Miroslav Lichvar <mlichvar>
Component: linuxptpAssignee: Miroslav Lichvar <mlichvar>
Status: CLOSED ERRATA QA Contact: Yalin.Li <yalli>
Severity: unspecified Docs Contact:
Priority: unspecified    
Version: 9.1CC: psklenar, yalli
Target Milestone: rcKeywords: FutureFeature, Triaged
Target Release: ---Flags: pm-rhel: mirror+
Hardware: Unspecified   
OS: Unspecified   
Whiteboard:
Fixed In Version: linuxptp-3.1.1-6.el9 Doc Type: If docs needed, set a value
Doc Text:
Story Points: ---
Clone Of: Environment:
Last Closed: 2023-05-09 07:48:10 UTC Type: Bug
Regression: --- Mount Type: ---
Documentation: --- CRM:
Verified Versions: Category: ---
oVirt Team: --- RHEL 7.3 requirements from Atomic Host:
Cloudforms Team: --- Target Upstream Version:
Embargoed:
Deadline: 2023-01-16   

Description Miroslav Lichvar 2022-12-05 11:13:12 UTC 
Description of problem:
The latest upstream code has an improved clockcheck detecting unexpected changes in the frequency offset of the controlled clock. This can detect misconfigurations (or possibly bugs) where multiple processes are trying to control the same clock, which has an impact on timekeeping performance and it's hard to see in the ptp4l/phc2sys logs.

Version-Release number of selected component (if applicable):
linuxptp-3.1.1-3.el8.x86_64

How reproducible:
Always

Steps to Reproduce:
1. start a client ptp4l instance with phc2sys synchronizing the system clock 
2. start a second ptp4l+phc2sys instance or chronyd
3. observe logs of the first ptp4l/phc2sys instance

Actual results:
no complaints

Expected results:
warning messages that the clock is adjusted unexpectedly

Additional info:
Comment 3 Yalin.Li 2023-01-10 06:19:26 UTC 
Tested the two ptp4l+phc2sys instances in one system, warning message appeared as expected.
# ptp4l -f 8.cfg -i ens1f0 --tx_timestamp_timeout=100 -m
ptp4l[12171.245]: selected /dev/ptp5 as PTP clock
ptp4l[12171.260]: port 1: INITIALIZING to LISTENING on INIT_COMPLETE
ptp4l[12171.260]: port 0: INITIALIZING to LISTENING on INIT_COMPLETE
ptp4l[12171.260]: port 0: INITIALIZING to LISTENING on INIT_COMPLETE
ptp4l[12171.332]: port 1: new foreign master b08bd0.fffe.0a733b-97
ptp4l[12171.583]: selected best master clock ec4670.fffe.004292
ptp4l[12171.583]: port 1: LISTENING to UNCALIBRATED on RS_SLAVE
ptp4l[12171.942]: port 1: UNCALIBRATED to SLAVE on MASTER_CLOCK_SELECTED
ptp4l[12172.693]: rms   14 max   27 freq  -9888 +/-  28 delay   248 +/-   1
ptp4l[12173.696]: rms   25 max   30 freq  -9845 +/-  14 delay   247 +/-   2
ptp4l[12174.713]: rms   13 max   27 freq  -9838 +/-  10 delay   248 +/-   1
ptp4l[12175.702]: rms    7 max   14 freq  -9849 +/-  11 delay   248 +/-   1
ptp4l[12176.713]: rms    7 max   13 freq  -9845 +/-  11 delay   246 +/-   1
ptp4l[12177.716]: rms    5 max   10 freq  -9853 +/-   7 delay   249 +/-   1
ptp4l[12178.715]: rms    7 max   12 freq  -9842 +/-  10 delay   245 +/-   1
ptp4l[12179.715]: rms    5 max   10 freq  -9847 +/-   9 delay   247 +/-   2
ptp4l[12180.718]: rms    6 max   11 freq  -9849 +/-  10 delay   247 +/-   1
...
ptp4l[12410.248]: rms    7 max   11 freq  -9860 +/-  11 delay   246 +/-   2
ptp4l[12410.549]: clockcheck: clock frequency changed unexpectedly!
ptp4l[12411.250]: rms 111936 max 222252 freq -216190 +/- 132564 delay  -861 +/- 1567
ptp4l[12411.553]: clockcheck: clock frequency changed unexpectedly!
ptp4l[12412.242]: rms 32795 max 50100 freq -87915 +/- 44646 delay -1554 +/- 893
ptp4l[12412.554]: clockcheck: clock frequency changed unexpectedly!
ptp4l[12413.261]: rms 40159 max 51067 freq  -2219 +/- 8709 delay   189 +/- 223
ptp4l[12413.557]: clockcheck: clock frequency changed unexpectedly!
ptp4l[12414.264]: rms 15904 max 29851 freq  -2984 +/- 9152 delay   510 +/- 191
ptp4l[12414.563]: clockcheck: clock frequency changed unexpectedly!
ptp4l[12415.255]: rms 7673 max 13347 freq -24018 +/- 12382 delay   273 +/- 140
ptp4l[12415.563]: clockcheck: clock frequency changed unexpectedly!
ptp4l[12416.259]: rms 9340 max 20397 freq -35977 +/- 12896 delay  -230 +/- 210
ptp4l[12416.568]: clockcheck: clock frequency changed unexpectedly!
ptp4l[12417.269]: rms 10510 max 23244 freq -42867 +/- 15803 delay  -196 +/-  70


# phc2sys -s ens1f0 -c CLOCK_REALTIME -n 24 -wm
phc2sys[12365.415]: CLOCK_REALTIME phc offset       150 s0 freq   +9497 delay    542
phc2sys[12366.415]: CLOCK_REALTIME phc offset       185 s2 freq   +9532 delay    551
phc2sys[12367.416]: CLOCK_REALTIME phc offset       214 s2 freq   +9746 delay    544
phc2sys[12368.416]: CLOCK_REALTIME phc offset         4 s2 freq   +9600 delay    548
phc2sys[12369.416]: CLOCK_REALTIME phc offset       -55 s2 freq   +9542 delay    546
phc2sys[12370.416]: CLOCK_REALTIME phc offset       -31 s2 freq   +9550 delay    546
phc2sys[12371.416]: CLOCK_REALTIME phc offset       -32 s2 freq   +9540 delay    548
phc2sys[12372.416]: CLOCK_REALTIME phc offset       -47 s2 freq   +9515 delay    554
phc2sys[12373.416]: CLOCK_REALTIME phc offset        12 s2 freq   +9560 delay    551
phc2sys[12374.416]: CLOCK_REALTIME phc offset       -14 s2 freq   +9537 delay    547
phc2sys[12375.416]: CLOCK_REALTIME phc offset        11 s2 freq   +9558 delay    552
...
phc2sys[12441.483]: clockcheck: clock frequency changed unexpectedly!
phc2sys[12441.483]: CLOCK_REALTIME phc offset      3260 s2 freq   +6190 delay    552
phc2sys[12442.483]: clockcheck: clock frequency changed unexpectedly!
phc2sys[12442.483]: CLOCK_REALTIME phc offset     28226 s2 freq  +32134 delay    487
phc2sys[12443.483]: clockcheck: clock frequency changed unexpectedly!
phc2sys[12443.483]: CLOCK_REALTIME phc offset     18044 s2 freq  +30420 delay    552
phc2sys[12444.483]: clockcheck: clock frequency changed unexpectedly!
phc2sys[12444.483]: CLOCK_REALTIME phc offset     -6383 s2 freq  +11406 delay    551
phc2sys[12445.484]: clockcheck: clock frequency changed unexpectedly!
phc2sys[12445.484]: CLOCK_REALTIME phc offset    -16870 s2 freq    -996 delay    547
phc2sys[12446.484]: clockcheck: clock frequency changed unexpectedly!
phc2sys[12446.484]: CLOCK_REALTIME phc offset    -13684 s2 freq   -2871 delay    541
phc2sys[12447.484]: clockcheck: clock frequency changed unexpectedly!
phc2sys[12447.484]: CLOCK_REALTIME phc offset     -9976 s2 freq   -3268 delay    546
phc2sys[12448.484]: clockcheck: clock frequency changed unexpectedly!
Comment 6 Yalin.Li 2023-01-29 04:54:04 UTC 
(In reply to Yalin.Li from comment #3)
> Tested the two ptp4l+phc2sys instances in one system, warning message
> appeared as expected.
> # ptp4l -f 8.cfg -i ens1f0 --tx_timestamp_timeout=100 -m
> ptp4l[12171.245]: selected /dev/ptp5 as PTP clock
> ptp4l[12171.260]: port 1: INITIALIZING to LISTENING on INIT_COMPLETE
> ptp4l[12171.260]: port 0: INITIALIZING to LISTENING on INIT_COMPLETE
> ptp4l[12171.260]: port 0: INITIALIZING to LISTENING on INIT_COMPLETE
> ptp4l[12171.332]: port 1: new foreign master b08bd0.fffe.0a733b-97
> ptp4l[12171.583]: selected best master clock ec4670.fffe.004292
> ptp4l[12171.583]: port 1: LISTENING to UNCALIBRATED on RS_SLAVE
> ptp4l[12171.942]: port 1: UNCALIBRATED to SLAVE on MASTER_CLOCK_SELECTED
> ptp4l[12172.693]: rms   14 max   27 freq  -9888 +/-  28 delay   248 +/-   1
> ptp4l[12173.696]: rms   25 max   30 freq  -9845 +/-  14 delay   247 +/-   2
> ptp4l[12174.713]: rms   13 max   27 freq  -9838 +/-  10 delay   248 +/-   1
> ptp4l[12175.702]: rms    7 max   14 freq  -9849 +/-  11 delay   248 +/-   1
> ptp4l[12176.713]: rms    7 max   13 freq  -9845 +/-  11 delay   246 +/-   1
> ptp4l[12177.716]: rms    5 max   10 freq  -9853 +/-   7 delay   249 +/-   1
> ptp4l[12178.715]: rms    7 max   12 freq  -9842 +/-  10 delay   245 +/-   1
> ptp4l[12179.715]: rms    5 max   10 freq  -9847 +/-   9 delay   247 +/-   2
> ptp4l[12180.718]: rms    6 max   11 freq  -9849 +/-  10 delay   247 +/-   1
> ...
> ptp4l[12410.248]: rms    7 max   11 freq  -9860 +/-  11 delay   246 +/-   2
> ptp4l[12410.549]: clockcheck: clock frequency changed unexpectedly!
> ptp4l[12411.250]: rms 111936 max 222252 freq -216190 +/- 132564 delay  -861
> +/- 1567
> ptp4l[12411.553]: clockcheck: clock frequency changed unexpectedly!
> ptp4l[12412.242]: rms 32795 max 50100 freq -87915 +/- 44646 delay -1554 +/-
> 893
> ptp4l[12412.554]: clockcheck: clock frequency changed unexpectedly!
> ptp4l[12413.261]: rms 40159 max 51067 freq  -2219 +/- 8709 delay   189 +/-
> 223
> ptp4l[12413.557]: clockcheck: clock frequency changed unexpectedly!
> ptp4l[12414.264]: rms 15904 max 29851 freq  -2984 +/- 9152 delay   510 +/-
> 191
> ptp4l[12414.563]: clockcheck: clock frequency changed unexpectedly!
> ptp4l[12415.255]: rms 7673 max 13347 freq -24018 +/- 12382 delay   273 +/-
> 140
> ptp4l[12415.563]: clockcheck: clock frequency changed unexpectedly!
> ptp4l[12416.259]: rms 9340 max 20397 freq -35977 +/- 12896 delay  -230 +/-
> 210
> ptp4l[12416.568]: clockcheck: clock frequency changed unexpectedly!
> ptp4l[12417.269]: rms 10510 max 23244 freq -42867 +/- 15803 delay  -196 +/- 
> 70
> 
> 
> # phc2sys -s ens1f0 -c CLOCK_REALTIME -n 24 -wm
> phc2sys[12365.415]: CLOCK_REALTIME phc offset       150 s0 freq   +9497
> delay    542
> phc2sys[12366.415]: CLOCK_REALTIME phc offset       185 s2 freq   +9532
> delay    551
> phc2sys[12367.416]: CLOCK_REALTIME phc offset       214 s2 freq   +9746
> delay    544
> phc2sys[12368.416]: CLOCK_REALTIME phc offset         4 s2 freq   +9600
> delay    548
> phc2sys[12369.416]: CLOCK_REALTIME phc offset       -55 s2 freq   +9542
> delay    546
> phc2sys[12370.416]: CLOCK_REALTIME phc offset       -31 s2 freq   +9550
> delay    546
> phc2sys[12371.416]: CLOCK_REALTIME phc offset       -32 s2 freq   +9540
> delay    548
> phc2sys[12372.416]: CLOCK_REALTIME phc offset       -47 s2 freq   +9515
> delay    554
> phc2sys[12373.416]: CLOCK_REALTIME phc offset        12 s2 freq   +9560
> delay    551
> phc2sys[12374.416]: CLOCK_REALTIME phc offset       -14 s2 freq   +9537
> delay    547
> phc2sys[12375.416]: CLOCK_REALTIME phc offset        11 s2 freq   +9558
> delay    552
> ...
> phc2sys[12441.483]: clockcheck: clock frequency changed unexpectedly!
> phc2sys[12441.483]: CLOCK_REALTIME phc offset      3260 s2 freq   +6190
> delay    552
> phc2sys[12442.483]: clockcheck: clock frequency changed unexpectedly!
> phc2sys[12442.483]: CLOCK_REALTIME phc offset     28226 s2 freq  +32134
> delay    487
> phc2sys[12443.483]: clockcheck: clock frequency changed unexpectedly!
> phc2sys[12443.483]: CLOCK_REALTIME phc offset     18044 s2 freq  +30420
> delay    552
> phc2sys[12444.483]: clockcheck: clock frequency changed unexpectedly!
> phc2sys[12444.483]: CLOCK_REALTIME phc offset     -6383 s2 freq  +11406
> delay    551
> phc2sys[12445.484]: clockcheck: clock frequency changed unexpectedly!
> phc2sys[12445.484]: CLOCK_REALTIME phc offset    -16870 s2 freq    -996
> delay    547
> phc2sys[12446.484]: clockcheck: clock frequency changed unexpectedly!
> phc2sys[12446.484]: CLOCK_REALTIME phc offset    -13684 s2 freq   -2871
> delay    541
> phc2sys[12447.484]: clockcheck: clock frequency changed unexpectedly!
> phc2sys[12447.484]: CLOCK_REALTIME phc offset     -9976 s2 freq   -3268
> delay    546
> phc2sys[12448.484]: clockcheck: clock frequency changed unexpectedly!

PTP regression test passed on linuxptp-3.1.1-6.el9.
https://beaker.engineering.redhat.com/jobs/7475122
https://beaker.engineering.redhat.com/jobs/7475153
Comment 8 errata-xmlrpc 2023-05-09 07:48:10 UTC 
Since the problem described in this bug report should be
resolved in a recent advisory, it has been closed with a
resolution of ERRATA.

For information on the advisory (linuxptp bug fix and enhancement update), and where to find the updated
files, follow the link below.

If the solution does not work for you, open a new bug report.

https://access.redhat.com/errata/RHBA-2023:2349