[Linuxptp-users] reboot when using -E linreg on phc2sys results in 2 second offset.

[Brian Olson]

I just started using linuxptp version 1.8, so this may be a misunderstanding on my part. I’m seeing slightly better performance from phc2sys using -E linreg. The problem is that when I reboot, it seems to semi-stabilize at an offset near -2 seconds. If I restart only phc2sys without changing anything else, it works properly. Here are some logs from a reboot, I added some spaces to align columns a bit better.

if I drop the -E linreg (using PI loop) I don’t have this issue. Any thoughts? I’m using "-a -r -N 25 -E linreg"

I added some extra logs in clockadj.c to log ticks and freq, I can include those if it would be helpful.

2017-06-12T19:00:17.551561-04:00 bco2 phc2sys: [25.183] failed to adjust the clock: Invalid argument
2017-06-12T19:00:18.551709-04:00 bco2 phc2sys: [26.183] reconfiguring after port state change
2017-06-12T19:00:18.551721-04:00 bco2 phc2sys: [26.183] selecting CLOCK_REALTIME for synchronization
2017-06-12T19:00:18.551726-04:00 bco2 phc2sys: [26.183] selecting eth2 as the master clock
2017-06-12T19:00:18.551790-04:00 bco2 phc2sys: [26.183] phc offset 196930623 s0 freq [phone] delay 51
2017-06-12T19:00:19.551917-04:00 bco2 phc2sys: [27.183] phc offset 196905268 s0 freq [phone] delay 56
2017-06-12T19:00:20.552050-04:00 bco2 phc2sys: [28.183] phc offset 196880154 s0 freq [phone] delay 57
2017-06-12T19:00:21.355353-04:00 bco2 phc2sys: [29.183] phc offset 196855592 s1 freq [phone] delay 1713
2017-06-12T19:00:22.355485-04:00 bco2 phc2sys: [30.183] phc offset -111043198 s2 freq [phone] delay 1539
2017-06-12T19:00:23.355900-04:00 bco2 phc2sys: [31.184] phc offset -222219586 s2 freq [phone] delay 41
2017-06-12T19:00:24.356082-04:00 bco2 phc2sys: [32.184] phc offset -333383570 s2 freq [phone] delay 41
2017-06-12T19:00:25.356227-04:00 bco2 phc2sys: [33.184] phc offset -444540013 s2 freq [phone] delay 44
2017-06-12T19:00:26.356366-04:00 bco2 phc2sys: [34.184] phc offset -555693635 s2 freq [phone] delay 44
2017-06-12T19:00:27.356490-04:00 bco2 phc2sys: [35.184] phc offset -666847284 s2 freq [phone] delay 57
2017-06-12T19:00:28.356649-04:00 bco2 phc2sys: [36.185] phc offset -777999637 s2 freq [phone] delay 40
2017-06-12T19:00:29.356792-04:00 bco2 phc2sys: [37.185] phc offset -889157226 s2 freq [phone] delay 40
2017-06-12T19:00:30.356914-04:00 bco2 phc2sys: [38.185] phc offset -1000312121 s2 freq [phone] delay 43
2017-06-12T19:00:31.357051-04:00 bco2 phc2sys: [39.185] phc offset -1111463984 s2 freq [phone] delay 86
2017-06-12T19:00:32.357145-04:00 bco2 phc2sys: [40.185] phc offset -1222616536 s2 freq [phone] delay 43
2017-06-12T19:00:33.357248-04:00 bco2 phc2sys: [41.185] phc offset -1333765929 s2 freq [phone] delay 1437
2017-06-12T19:00:34.357387-04:00 bco2 phc2sys: [42.185] phc offset -1444922024 s2 freq [phone] delay 46
2017-06-12T19:00:35.357542-04:00 bco2 phc2sys: [43.186] phc offset -1556079842 s2 freq [phone] delay 42
2017-06-12T19:00:36.357656-04:00 bco2 phc2sys: [44.186] phc offset -1667230540 s2 freq [phone] delay 43
2017-06-12T19:00:37.357787-04:00 bco2 phc2sys: [45.186] phc offset -1778384396 s2 freq [phone] delay 53
2017-06-12T19:00:38.357918-04:00 bco2 phc2sys: [46.186] phc offset -1889538277 s2 freq [phone] delay 47
2017-06-12T19:00:39.358041-04:00 bco2 phc2sys: [47.186] phc offset -2000692669 s2 freq [phone] delay 1453
2017-06-12T19:00:40.358152-04:00 bco2 phc2sys: [48.186] phc offset -2111845429 s2 freq -560981 delay 1423
2017-06-12T19:00:41.358303-04:00 bco2 phc2sys: [49.186] phc offset -2111300380 s2 freq -55880536 delay 60
2017-06-12T19:00:42.358492-04:00 bco2 phc2sys: [50.186] phc offset -2058356966 s2 freq -84947498 delay 59
2017-06-12T19:00:43.358696-04:00 bco2 phc2sys: [51.187] phc offset -1980071281 s2 freq -45492825 delay 67
2017-06-12T19:00:44.358855-04:00 bco2 phc2sys: [52.187] phc offset -1936565859 s2 freq +2726509 delay 52
2017-06-12T19:00:45.359001-04:00 bco2 phc2sys: [53.187] phc offset -1939296933 s2 freq [phone] delay 44
2017-06-12T19:00:46.359123-04:00 bco2 phc2sys: [54.187] phc offset -1981527504 s2 freq [phone] delay 44
2017-06-12T19:00:47.359241-04:00 bco2 phc2sys: [55.187] phc offset -2024402721 s2 freq [phone] delay 46
2017-06-12T19:00:48.359646-04:00 bco2 phc2sys: [56.188] phc offset -2043022503 s2 freq -12112771 delay 1583
2017-06-12T19:00:49.359906-04:00 bco2 phc2sys: [57.188] phc offset -2031094619 s2 freq -27456863 delay 1603
2017-06-12T19:00:50.360091-04:00 bco2 phc2sys: [58.188] phc offset -2004393943 s2 freq -23399703 delay 66
2017-06-12T19:00:51.360270-04:00 bco2 phc2sys: [59.188] phc offset -1981550186 s2 freq -6106846 delay 1618
2017-06-12T19:00:52.360476-04:00 bco2 phc2sys: [60.188] phc offset -1975497514 s2 freq [phone] delay 1619
2017-06-12T19:00:53.360673-04:00 bco2 phc2sys: [61.189] phc offset -1985894666 s2 freq [phone] delay 1579
2017-06-12T19:00:54.360804-04:00 bco2 phc2sys: [62.189] phc offset -2002672476 s2 freq [phone] delay 1571
2017-06-12T19:00:55.360962-04:00 bco2 phc2sys: [63.189] phc offset -2013916914 s2 freq +238342 delay 55
2017-06-12T19:00:56.361093-04:00 bco2 phc2sys: [64.189] phc offset -2014185661 s2 freq -8292577 delay 64
2017-06-12T19:00:57.361281-04:00 bco2 phc2sys: [65.189] phc offset -2005985697 s2 freq -9802301 delay 62
2017-06-12T19:00:58.361439-04:00 bco2 phc2sys: [66.189] phc offset -1996302200 s2 freq -5083480 delay 59
2017-06-12T19:00:59.361597-04:00 bco2 phc2sys: [67.190] phc offset -1991269736 s2 freq +1539388 delay 47
2017-06-12T19:01:00.361742-04:00 bco2 phc2sys: [68.190] phc offset -1992833854 s2 freq +5604798 delay 44
2017-06-12T19:01:01.361894-04:00 bco2 phc2sys: [69.190] phc offset -1998496667 s2 freq +5273009 delay 43
2017-06-12T19:01:02.362030-04:00 bco2 phc2sys: [70.190] phc offset -2003823803 s2 freq +1804365 delay 57
2017-06-12T19:01:03.362182-04:00 bco2 phc2sys: [71.190] phc offset -2005655728 s2 freq -1923388 delay 43
2017-06-12T19:01:04.362316-04:00 bco2 phc2sys: [72.190] phc offset -2003759785 s2 freq -3644365 delay 58
2017-06-12T19:01:05.362472-04:00 bco2 phc2sys: [73.190] phc offset -2000152641 s2 freq -2772461 delay 48
2017-06-12T19:01:06.362607-04:00 bco2 phc2sys: [74.191] phc offset -1997412732 s2 freq -437308 delay 46
2017-06-12T19:01:07.362772-04:00 bco2 phc2sys: [75.191] phc offset -1996999757 s2 freq +1583367 delay 47
2017-06-12T19:01:08.362912-04:00 bco2 phc2sys: [76.191] phc offset -1998611717 s2 freq +2131027 delay 56
2017-06-12T19:01:09.363056-04:00 bco2 phc2sys: [77.191] phc offset -2000772602 s2 freq +1247206 delay 57
2017-06-12T19:01:10.363209-04:00 bco2 phc2sys: [78.191] phc offset -2002046815 s2 freq -183359 delay 56
2017-06-12T19:01:11.363356-04:00 bco2 phc2sys: [79.191] phc offset -2001887859 s2 freq -1176955 delay 45
2017-06-12T19:01:12.363488-04:00 bco2 phc2sys: [80.191] phc offset -2000737109 s2 freq -1243613 delay 59
2017-06-12T19:01:13.363617-04:00 bco2 phc2sys: [81.192] phc offset -1999519966 s2 freq -577278 delay 130
2017-06-12T19:01:14.363742-04:00 bco2 phc2sys: [82.192] phc offset -1998967780 s2 freq +291828 delay 50
2017-06-12T19:01:15.363866-04:00 bco2 phc2sys: [83.192] phc offset -1999285374 s2 freq +732762 delay 48
2017-06-12T19:01:16.363991-04:00 bco2 phc2sys: [84.192] phc offset -2000043233 s2 freq +605879 delay 46
2017-06-12T19:01:17.364129-04:00 bco2 phc2sys: [85.192] phc offset -2000674819 s2 freq +145709 delay 50
2017-06-12T19:01:18.364266-04:00 bco2 phc2sys: [86.192] phc offset -2000845943 s2 freq -312543 delay 58
2017-06-12T19:01:19.364412-04:00 bco2 phc2sys: [87.192] phc offset -2000558636 s2 freq -478808 delay 48
2017-06-12T19:01:20.364576-04:00 bco2 phc2sys: [88.193] phc offset -2000104053 s2 freq -323273 delay 1598
2017-06-12T19:01:21.364749-04:00 bco2 phc2sys: [89.193] phc offset -1999806420 s2 freq -10156 delay 1597
2017-06-12T19:01:22.364908-04:00 bco2 phc2sys: [90.193] phc offset -1999822277 s2 freq +198055 delay 45
2017-06-12T19:01:23.365082-04:00 bco2 phc2sys: [91.193] phc offset -2000044565 s2 freq +240083 delay 1599
2017-06-12T19:01:24.365228-04:00 bco2 phc2sys: [92.193] phc offset -2000310301 s2 freq +112863 delay 1598
2017-06-12T19:01:25.365388-04:00 bco2 phc2sys: [93.193] phc offset -2000449082 s2 freq -102722 delay 47
2017-06-12T19:01:26.365761-04:00 bco2 phc2sys: [94.194] phc offset -2000370876 s2 freq -80148 delay 1596
2017-06-12T19:01:27.366142-04:00 bco2 phc2sys: [95.194] phc offset -2000316912 s2 freq +7256 delay 63
2017-06-12T19:01:28.366319-04:00 bco2 phc2sys: [96.194] phc offset -2000348629 s2 freq -81909 delay 1716
2017-06-12T19:01:29.366440-04:00 bco2 phc2sys: [97.194] phc offset -2000292879 s2 freq -153499 delay 47
2017-06-12T19:01:30.366586-04:00 bco2 phc2sys: [98.195] phc offset -2000164565 s2 freq -121041 delay 47
2017-06-12T19:01:31.366723-04:00 bco2 phc2sys: [99.195] phc offset -2000069225 s2 freq -41185 delay 55

[Miroslav Lichvar]

I just started using linuxptp version 1.8, so this may be a misunderstanding on my part. I’m seeing slightly better performance from phc2sys using -E linreg. The problem is that when I reboot, it seems to semi-stabilize at an offset near -2 seconds. If I restart only phc2sys without changing anything else, it works properly. Here are some logs from a reboot, I added some spaces to align columns a bit better.
if I drop the -E linreg (using PI loop) I don’t have this issue. Any thoughts? I’m using "-a -r -N 25 -E linreg"
I added some extra logs in clockadj.c to log ticks and freq, I can include those if it would be helpful.
2017-06-12T19:00:17.551561-04:00 bco2 phc2sys: [25.183] failed to adjust the clock: Invalid argument

This is odd.

2017-06-12T19:00:18.551709-04:00 bco2 phc2sys: [26.183] reconfiguring after port state change
2017-06-12T19:00:18.551721-04:00 bco2 phc2sys: [26.183] selecting CLOCK_REALTIME for synchronization
2017-06-12T19:00:18.551726-04:00 bco2 phc2sys: [26.183] selecting eth2 as the master clock
2017-06-12T19:00:18.551790-04:00 bco2 phc2sys: [26.183] phc offset 196930623 s0 freq [phone] delay 51

Hm, the initial frequency offset is 1, so the servo thinks the clock
is stopped. This explains the weird 2 second offset.

What kernel, arch, and libc is this? Can you please check what value
has the realtime_hz variable in clockadj.c?

[Brian Olson]

Brian Olson

Post by Miroslav Lichvar

Post by Brian Olson
I just started using linuxptp version 1.8, so this may be a misunderstanding on my part. I’m seeing slightly better performance from phc2sys using -E linreg. The problem is that when I reboot, it seems to semi-stabilize at an offset near -2 seconds. If I restart only phc2sys without changing anything else, it works properly. Here are some logs from a reboot, I added some spaces to align columns a bit better.
if I drop the -E linreg (using PI loop) I don’t have this issue. Any thoughts? I’m using "-a -r -N 25 -E linreg"
I added some extra logs in clockadj.c to log ticks and freq, I can include those if it would be helpful.
2017-06-12T19:00:17.551561-04:00 bco2 phc2sys: [25.183] failed to adjust the clock: Invalid argument

This is odd.

Got this to occur in the debugger by turning off the auto start and manually starting ptp4l and phc2sys at the same time.

215 clockadj_set_freq(c->clkid, ppb);
(gdb) info locals
c = 0x61aa70
clkid = 0
max_ppb = 0
ppb = -1000000000

it’s calling clockadj_set_freq(0, -1000000000)

print realtime_hz
$1 = 100
print realtime_nominal_tick
$2 = 10000
p (double)-1000000000/1e3/realtime_hz + realtime_nominal_tick
$5 = 0

so, it tries to set

tx.tick = round(freq / 1e3 / realtime_hz) + realtime_nominal_tick;
which is 0.

the next line re-computes freq:

freq -= 1e3 * realtime_hz * (tx.tick - realtime_nominal_tick)

p 1e3 * realtime_hz * (0-realtime_nominal_tick)
$7 = -1000000000

this ends up making freq 0 as well, causing the call to clock_adjtime to fail.

I added some debug:

void clockadj_set_freq(clockid_t clkid, double freq)
{
struct timex tx;
memset(&tx, 0, sizeof(tx));

pr_notice("clockadj_set_freq(%d), freq: %f",clkid, freq );
/* With system clock set also the tick length. */
if (clkid == CLOCK_REALTIME && realtime_nominal_tick) {
tx.modes |= ADJ_TICK;
tx.tick = round(freq / 1e3 / realtime_hz) + realtime_nominal_tick;
freq -= 1e3 * realtime_hz * (tx.tick - realtime_nominal_tick);
}

tx.modes |= ADJ_FREQUENCY;
tx.freq = (long) (freq * 65.536);
pr_notice("clock_adjtime(%d), freq: %ld tick: %ld realtime_hz: %ld realtime_nominal_tick: %ld",
clkid, tx.freq, tx.tick, realtime_hz, realtime_nominal_tick);
if (clock_adjtime(clkid, &tx) < 0)
pr_err("failed to adjust the clock: %m");
}

double clockadj_get_freq(clockid_t clkid)
{
double f = 0.0;
struct timex tx;
memset(&tx, 0, sizeof(tx));
if (clock_adjtime(clkid, &tx) < 0) {
pr_err("failed to read out the clock frequency adjustment: %m");
} else {
pr_notice("clockadj_get_freq(%d), freq: %ld tick: %ld realtime_hz: %ld realtime_nominal_tick: %ld",
clkid, tx.freq, tx.tick, realtime_hz, realtime_nominal_tick);
f = tx.freq / 65.536;
if (clkid == CLOCK_REALTIME && realtime_nominal_tick)
f += 1e3 * realtime_hz * (tx.tick - realtime_nominal_tick);
}
return f;
}


This is the non-converging case with linreg:

2017-06-13T12:22:21.373678-04:00 bco2 phc2sys: [26.004] clockadj_get_freq(-37), freq: 2062359 tick: 0 realtime_hz: 0 realtime_nominal_tick: 0
2017-06-13T12:22:21.373691-04:00 bco2 phc2sys: [26.005] clockadj_set_freq(-37), freq: 31469.100952
2017-06-13T12:22:21.373696-04:00 bco2 phc2sys: [26.005] clock_adjtime(-37), freq: 2062359 tick: 0 realtime_hz: 0 realtime_nominal_tick: 0
2017-06-13T12:22:21.373769-04:00 bco2 phc2sys: [26.005] clockadj_get_freq(0), freq: 0 tick: 0 realtime_hz: 100 realtime_nominal_tick: 10000
2017-06-13T12:22:21.373780-04:00 bco2 phc2sys: [26.005] clockadj_set_freq(0), freq: -1000000000.000000
2017-06-13T12:22:21.373785-04:00 bco2 phc2sys: [26.005] clock_adjtime(0), freq: 0 tick: 0 realtime_hz: 100 realtime_nominal_tick: 10000
2017-06-13T12:22:21.373799-04:00 bco2 phc2sys: [26.005] failed to adjust the clock: Invalid argument
2017-06-13T12:22:22.373948-04:00 bco2 phc2sys: [27.005] reconfiguring after port state change
2017-06-13T12:22:22.373961-04:00 bco2 phc2sys: [27.005] selecting CLOCK_REALTIME for synchronization
2017-06-13T12:22:22.373965-04:00 bco2 phc2sys: [27.005] selecting eth2 as the master clock
2017-06-13T12:22:22.374022-04:00 bco2 phc2sys: [27.005] phc offset 24218755166 s0 freq [phone] delay 59
2017-06-13T12:22:23.374155-04:00 bco2 phc2sys: [28.005] phc offset 24218730288 s0 freq [phone] delay 65
2017-06-13T12:22:24.374285-04:00 bco2 phc2sys: [29.005] phc offset 24218704438 s0 freq [phone] delay 43
2017-06-13T12:22:01.155746-04:00 bco2 phc2sys: [30.005] clockadj_set_freq(0), freq: -100000000.000000
2017-06-13T12:22:01.155757-04:00 bco2 phc2sys: [30.005] clock_adjtime(0), freq: 0 tick: 9000 realtime_hz: 100 realtime_nominal_tick: 10000
2017-06-13T12:22:01.155762-04:00 bco2 phc2sys: [30.005] phc offset 24218679583 s1 freq [phone] delay 48
2017-06-13T12:22:02.155878-04:00 bco2 phc2sys: [31.005] clockadj_set_freq(0), freq: -100000000.000000
2017-06-13T12:22:02.155886-04:00 bco2 phc2sys: [31.005] clock_adjtime(0), freq: 0 tick: 9000 realtime_hz: 100 realtime_nominal_tick: 10000
2017-06-13T12:22:02.155890-04:00 bco2 phc2sys: [31.005] phc offset -111039777 s2 freq [phone] delay 42
2017-06-13T12:22:03.156010-04:00 bco2 phc2sys: [32.006] clockadj_set_freq(0), freq: -100000000.000000
2017-06-13T12:22:03.156019-04:00 bco2 phc2sys: [32.006] clock_adjtime(0), freq: 0 tick: 9000 realtime_hz: 100 realtime_nominal_tick: 10000
2017-06-13T12:22:03.156023-04:00 bco2 phc2sys: [32.006] phc offset -222196244 s2 freq [phone] delay 40
2017-06-13T12:22:04.156146-04:00 bco2 phc2sys: [33.006] clockadj_set_freq(0), freq: -100000000.000000
2017-06-13T12:22:04.156153-04:00 bco2 phc2sys: [33.006] clock_adjtime(0), freq: 0 tick: 9000 realtime_hz: 100 realtime_nominal_tick: 10000
2017-06-13T12:22:04.156162-04:00 bco2 phc2sys: [33.006] phc offset -333347709 s2 freq [phone] delay 1537
2017-06-13T12:22:05.156286-04:00 bco2 phc2sys: [34.006] clockadj_set_freq(0), freq: -100000000.000000
2017-06-13T12:22:05.156294-04:00 bco2 phc2sys: [34.006] clock_adjtime(0), freq: 0 tick: 9000 realtime_hz: 100 realtime_nominal_tick: 10000
2017-06-13T12:22:05.156301-04:00 bco2 phc2sys: [34.006] phc offset -444502693 s2 freq [phone] delay 53
2017-06-13T12:22:06.156435-04:00 bco2 phc2sys: [35.006] clockadj_set_freq(0), freq: -100000000.000000
2017-06-13T12:22:06.156443-04:00 bco2 phc2sys: [35.006] clock_adjtime(0), freq: 0 tick: 9000 realtime_hz: 100 realtime_nominal_tick: 10000
2017-06-13T12:22:06.156452-04:00 bco2 phc2sys: [35.006] phc offset -555656704 s2 freq [phone] delay 1543
2017-06-13T12:22:07.156550-04:00 bco2 phc2sys: [36.006] clockadj_set_freq(0), freq: -100000000.000000
2017-06-13T12:22:07.156559-04:00 bco2 phc2sys: [36.006] clock_adjtime(0), freq: 0 tick: 9000 realtime_hz: 100 realtime_nominal_tick: 10000
2017-06-13T12:22:07.156563-04:00 bco2 phc2sys: [36.006] phc offset -666810759 s2 freq [phone] delay 1537
2017-06-13T12:22:08.156627-04:00 bco2 phc2sys: [37.006] clockadj_set_freq(0), freq: -100000000.000000
2017-06-13T12:22:08.156636-04:00 bco2 phc2sys: [37.006] clock_adjtime(0), freq: 0 tick: 9000 realtime_hz: 100 realtime_nominal_tick: 10000
2017-06-13T12:22:08.156643-04:00 bco2 phc2sys: [37.006] phc offset -777959931 s2 freq [phone] delay 41
2017-06-13T12:22:09.156790-04:00 bco2 phc2sys: [38.006] clockadj_set_freq(0), freq: -100000000.000000
2017-06-13T12:22:09.156799-04:00 bco2 phc2sys: [38.006] clock_adjtime(0), freq: 0 tick: 9000 realtime_hz: 100 realtime_nominal_tick: 10000
2017-06-13T12:22:09.156803-04:00 bco2 phc2sys: [38.006] phc offset -889114149 s2 freq [phone] delay 1542
2017-06-13T12:22:10.156910-04:00 bco2 phc2sys: [39.006] clockadj_set_freq(0), freq: -100000000.000000
2017-06-13T12:22:10.156917-04:00 bco2 phc2sys: [39.006] clock_adjtime(0), freq: 0 tick: 9000 realtime_hz: 100 realtime_nominal_tick: 10000
2017-06-13T12:22:10.156926-04:00 bco2 phc2sys: [39.006] phc offset -1000269276 s2 freq [phone] delay 1540
2017-06-13T12:22:11.157045-04:00 bco2 phc2sys: [40.007] clockadj_set_freq(0), freq: -100000000.000000
2017-06-13T12:22:11.157055-04:00 bco2 phc2sys: [40.007] clock_adjtime(0), freq: 0 tick: 9000 realtime_hz: 100 realtime_nominal_tick: 10000
2017-06-13T12:22:11.157060-04:00 bco2 phc2sys: [40.007] phc offset -1111422421 s2 freq [phone] delay 44
2017-06-13T12:22:12.157424-04:00 bco2 phc2sys: [41.007] clockadj_set_freq(0), freq: -100000000.000000
2017-06-13T12:22:12.157430-04:00 bco2 phc2sys: [41.007] clock_adjtime(0), freq: 0 tick: 9000 realtime_hz: 100 realtime_nominal_tick: 10000
2017-06-13T12:22:12.157433-04:00 bco2 phc2sys: [41.007] phc offset -1222578884 s2 freq [phone] delay 1538
2017-06-13T12:22:13.157348-04:00 bco2 phc2sys: [42.007] clockadj_set_freq(0), freq: -100000000.000000
2017-06-13T12:22:13.157357-04:00 bco2 phc2sys: [42.007] clock_adjtime(0), freq: 0 tick: 9000 realtime_hz: 100 realtime_nominal_tick: 10000
2017-06-13T12:22:13.157361-04:00 bco2 phc2sys: [42.007] phc offset -1333734169 s2 freq [phone] delay 1539
2017-06-13T12:22:14.157452-04:00 bco2 phc2sys: [43.007] clockadj_set_freq(0), freq: -100000000.000000
2017-06-13T12:22:14.157462-04:00 bco2 phc2sys: [43.007] clock_adjtime(0), freq: 0 tick: 9000 realtime_hz: 100 realtime_nominal_tick: 10000
2017-06-13T12:22:14.157467-04:00 bco2 phc2sys: [43.007] phc offset -1444884887 s2 freq [phone] delay 1537
2017-06-13T12:22:15.157557-04:00 bco2 phc2sys: [44.007] clockadj_set_freq(0), freq: -100000000.000000
2017-06-13T12:22:15.157565-04:00 bco2 phc2sys: [44.007] clock_adjtime(0), freq: 0 tick: 9000 realtime_hz: 100 realtime_nominal_tick: 10000
2017-06-13T12:22:15.157573-04:00 bco2 phc2sys: [44.007] phc offset -1556035586 s2 freq [phone] delay 54
2017-06-13T12:22:16.157687-04:00 bco2 phc2sys: [45.007] clockadj_set_freq(0), freq: -100000000.000000
2017-06-13T12:22:16.157695-04:00 bco2 phc2sys: [45.007] clock_adjtime(0), freq: 0 tick: 9000 realtime_hz: 100 realtime_nominal_tick: 10000
2017-06-13T12:22:16.157700-04:00 bco2 phc2sys: [45.007] phc offset -1667187655 s2 freq [phone] delay 41
2017-06-13T12:22:17.157786-04:00 bco2 phc2sys: [46.007] clockadj_set_freq(0), freq: -100000000.000000
2017-06-13T12:22:17.157795-04:00 bco2 phc2sys: [46.007] clock_adjtime(0), freq: 0 tick: 9000 realtime_hz: 100 realtime_nominal_tick: 10000
2017-06-13T12:22:17.157803-04:00 bco2 phc2sys: [46.007] phc offset -1778339915 s2 freq [phone] delay 43
2017-06-13T12:22:18.157929-04:00 bco2 phc2sys: [47.007] clockadj_set_freq(0), freq: -100000000.000000
2017-06-13T12:22:18.157936-04:00 bco2 phc2sys: [47.007] clock_adjtime(0), freq: 0 tick: 9000 realtime_hz: 100 realtime_nominal_tick: 10000
2017-06-13T12:22:18.157952-04:00 bco2 phc2sys: [47.007] phc offset -1889494895 s2 freq [phone] delay 1540
2017-06-13T12:22:19.158079-04:00 bco2 phc2sys: [48.008] clockadj_set_freq(0), freq: -100000000.000000
2017-06-13T12:22:19.158085-04:00 bco2 phc2sys: [48.008] clock_adjtime(0), freq: 0 tick: 9000 realtime_hz: 100 realtime_nominal_tick: 10000
2017-06-13T12:22:19.158096-04:00 bco2 phc2sys: [48.008] phc offset -2000652121 s2 freq [phone] delay 1535
2017-06-13T12:22:20.158220-04:00 bco2 phc2sys: [49.008] clockadj_set_freq(0), freq: 496048.120488
2017-06-13T12:22:20.158228-04:00 bco2 phc2sys: [49.008] clock_adjtime(0), freq: -258990 tick: 10005 realtime_hz: 100 realtime_nominal_tick: 10000
2017-06-13T12:22:20.158244-04:00 bco2 phc2sys: [49.008] phc offset -2111807640 s2 freq -496048 delay 1536
2017-06-13T12:22:21.158441-04:00 bco2 phc2sys: [50.008] clockadj_set_freq(0), freq: 55835273.114441
2017-06-13T12:22:21.158450-04:00 bco2 phc2sys: [50.008] clock_adjtime(0), freq: 2311658 tick: 10558 realtime_hz: 100 realtime_nominal_tick: 10000
2017-06-13T12:22:21.158454-04:00 bco2 phc2sys: [50.008] phc offset -2111362285 s2 freq -55835273 delay 1710
2017-06-13T12:22:22.158622-04:00 bco2 phc2sys: [51.008] clockadj_set_freq(0), freq: 84972630.111600
2017-06-13T12:22:22.158630-04:00 bco2 phc2sys: [51.008] clock_adjtime(0), freq: -1793713 tick: 10850 realtime_hz: 100 realtime_nominal_tick: 10000
2017-06-13T12:22:22.158640-04:00 bco2 phc2sys: [51.008] phc offset -2058521298 s2 freq -84972630 delay 1808
2017-06-13T12:22:23.158848-04:00 bco2 phc2sys: [52.008] clockadj_set_freq(0), freq: 45591125.104173
2017-06-13T12:22:23.158858-04:00 bco2 phc2sys: [52.008] clock_adjtime(0), freq: -581625 tick: 10456 realtime_hz: 100 realtime_nominal_tick: 10000
2017-06-13T12:22:23.158863-04:00 bco2 phc2sys: [52.008] phc offset -1980216701 s2 freq -45591125 delay 1861
2017-06-13T12:22:24.159025-04:00 bco2 phc2sys: [53.009] clockadj_set_freq(0), freq: -2633890.896787
2017-06-13T12:22:24.159037-04:00 bco2 phc2sys: [53.009] clock_adjtime(0), freq: -2221073 tick: 9974 realtime_hz: 100 realtime_nominal_tick: 10000
2017-06-13T12:22:24.159042-04:00 bco2 phc2sys: [53.009] phc offset -1936616985 s2 freq +2633891 delay 45
2017-06-13T12:22:25.159247-04:00 bco2 phc2sys: [54.009] clockadj_set_freq(0), freq: -40456698.895661
2017-06-13T12:22:25.159257-04:00 bco2 phc2sys: [54.009] clock_adjtime(0), freq: 2837781 tick: 9595 realtime_hz: 100 realtime_nominal_tick: 10000
2017-06-13T12:22:25.159261-04:00 bco2 phc2sys: [54.009] phc offset -1939247537 s2 freq [phone] delay 47
2017-06-13T12:22:26.159360-04:00 bco2 phc2sys: [55.009] clockadj_set_freq(0), freq: -41129627.891637
2017-06-13T12:22:26.159371-04:00 bco2 phc2sys: [55.009] clock_adjtime(0), freq: -1941693 tick: 9589 realtime_hz: 100 realtime_nominal_tick: 10000
2017-06-13T12:22:26.159375-04:00 bco2 phc2sys: [55.009] phc offset -1981443852 s2 freq [phone] delay 51
2017-06-13T12:22:26.460028-04:00 bco2 phc2sys: [55.310] clockadj_set_freq(0), freq: 100000000.000000
2017-06-13T12:22:26.460043-04:00 bco2 phc2sys: [55.310] clock_adjtime(0), freq: 0 tick: 11000 realtime_hz: 100 realtime_nominal_tick: 10000

converging case with PI loop:

2017-06-13T12:00:54.243763-04:00 bco2 phc2sys: [25.874] clockadj_get_freq(-37), freq: 2122149 tick: 0 realtime_hz: 0 realtime_nominal_tick: 0
2017-06-13T12:00:54.243778-04:00 bco2 phc2sys: [25.874] clockadj_set_freq(-37), freq: 32381.423950
2017-06-13T12:00:54.243782-04:00 bco2 phc2sys: [25.874] clock_adjtime(-37), freq: 2122149 tick: 0 realtime_hz: 0 realtime_nominal_tick: 0
2017-06-13T12:00:54.243859-04:00 bco2 phc2sys: [25.874] clockadj_get_freq(0), freq: 0 tick: 0 realtime_hz: 100 realtime_nominal_tick: 10000
2017-06-13T12:00:54.243866-04:00 bco2 phc2sys: [25.874] clockadj_set_freq(0), freq: -1000000000.000000
2017-06-13T12:00:54.243869-04:00 bco2 phc2sys: [25.874] clock_adjtime(0), freq: 0 tick: 0 realtime_hz: 100 realtime_nominal_tick: 10000
2017-06-13T12:00:54.243880-04:00 bco2 phc2sys: [25.874] failed to adjust the clock: Invalid argument
2017-06-13T12:00:55.244040-04:00 bco2 phc2sys: [26.875] reconfiguring after port state change
2017-06-13T12:00:55.244052-04:00 bco2 phc2sys: [26.875] selecting CLOCK_REALTIME for synchronization
2017-06-13T12:00:55.244064-04:00 bco2 phc2sys: [26.875] selecting eth2 as the master clock
2017-06-13T12:00:55.244114-04:00 bco2 phc2sys: [26.875] phc offset 221607705 s0 freq [phone] delay 54
2017-06-13T12:00:56.022680-04:00 bco2 phc2sys: [27.875] clockadj_set_freq(0), freq: -100000000.000000
2017-06-13T12:00:56.022691-04:00 bco2 phc2sys: [27.875] clock_adjtime(0), freq: 0 tick: 9000 realtime_hz: 100 realtime_nominal_tick: 10000
2017-06-13T12:00:56.022695-04:00 bco2 phc2sys: [27.875] phc offset 221582147 s1 freq [phone] delay 47
2017-06-13T12:00:57.022772-04:00 bco2 phc2sys: [28.875] clockadj_set_freq(0), freq: 11035768.000000
2017-06-13T12:00:57.022784-04:00 bco2 phc2sys: [28.875] clock_adjtime(0), freq: 2344091 tick: 10110 realtime_hz: 100 realtime_nominal_tick: 10000
2017-06-13T12:00:57.022792-04:00 bco2 phc2sys: [28.875] phc offset -111035768 s2 freq -11035768 delay 48
2017-06-13T12:00:58.022928-04:00 bco2 phc2sys: [29.875] clockadj_set_freq(0), freq: 33446162.400000
2017-06-13T12:00:58.022939-04:00 bco2 phc2sys: [29.875] clock_adjtime(0), freq: 3025299 tick: 10334 realtime_hz: 100 realtime_nominal_tick: 10000
2017-06-13T12:00:58.022952-04:00 bco2 phc2sys: [29.875] phc offset -100135432 s2 freq -33446162 delay 46
2017-06-13T12:00:59.023131-04:00 bco2 phc2sys: [30.875] clockadj_set_freq(0), freq: 31133332.000000
2017-06-13T12:00:59.023140-04:00 bco2 phc2sys: [30.875] clock_adjtime(0), freq: 2184445 tick: 10311 realtime_hz: 100 realtime_nominal_tick: 10000
2017-06-13T12:00:59.023145-04:00 bco2 phc2sys: [30.875] phc offset -67781972 s2 freq -31133332 delay 1771
2017-06-13T12:01:00.023283-04:00 bco2 phc2sys: [31.875] clockadj_set_freq(0), freq: 21296424.600000
2017-06-13T12:01:00.023293-04:00 bco2 phc2sys: [31.875] clock_adjtime(0), freq: -234317 tick: 10213 realtime_hz: 100 realtime_nominal_tick: 10000
2017-06-13T12:01:00.023303-04:00 bco2 phc2sys: [31.875] phc offset -37610473 s2 freq -21296425 delay 58
2017-06-13T12:01:01.023480-04:00 bco2 phc2sys: [32.876] clockadj_set_freq(0), freq: 11746891.500000
2017-06-13T12:01:01.023489-04:00 bco2 phc2sys: [32.876] clock_adjtime(0), freq: 3073081 tick: 10117 realtime_hz: 100 realtime_nominal_tick: 10000
2017-06-13T12:01:01.023494-04:00 bco2 phc2sys: [32.876] phc offset -16777798 s2 freq -11746891 delay 1757
2017-06-13T12:01:02.023622-04:00 bco2 phc2sys: [33.876] clockadj_set_freq(0), freq: 5188251.900000
2017-06-13T12:01:02.023632-04:00 bco2 phc2sys: [33.876] clock_adjtime(0), freq: -769923 tick: 10052 realtime_hz: 100 realtime_nominal_tick: 10000

Post by Miroslav Lichvar

Post by Brian Olson
2017-06-12T19:00:18.551709-04:00 bco2 phc2sys: [26.183] reconfiguring after port state change
2017-06-12T19:00:18.551721-04:00 bco2 phc2sys: [26.183] selecting CLOCK_REALTIME for synchronization
2017-06-12T19:00:18.551726-04:00 bco2 phc2sys: [26.183] selecting eth2 as the master clock
2017-06-12T19:00:18.551790-04:00 bco2 phc2sys: [26.183] phc offset 196930623 s0 freq [phone] delay 51

Hm, the initial frequency offset is 1, so the servo thinks the clock
is stopped. This explains the weird 2 second offset.
What kernel, arch, and libc is this? Can you please check what value
has the realtime_hz variable in clockadj.c?

print realtime_hz
$1 = 100

Linux 2.6.32-504.el6.x86_64 #1 SMP Tue Sep 16 01:56:35 EDT 2014 x86_64 x86_64 x86_64 GNU/Linux
glibc.i686 2.12-1.149.el6
glibc.x86_64 2.12-1.149.el6

Post by Miroslav Lichvar
--
Miroslav Lichvar

[Miroslav Lichvar]

Post by Brian Olson
double clockadj_get_freq(clockid_t clkid)
{
double f = 0.0;
struct timex tx;
memset(&tx, 0, sizeof(tx));
if (clock_adjtime(clkid, &tx) < 0) {

From your logs it seems the problem is that clock_adjtime() returns
zero ticks instead of 10000 for the REALTIME clock. I suspect it's a
kernel or possibly glibc bug.

[Brian Olson]

I agree.

I made a change and now it converges:
2017-06-13T13:59:05.703456-04:00 bco2 phc2sys: [27.336] reconfiguring after port state change
2017-06-13T13:59:05.703467-04:00 bco2 phc2sys: [27.336] selecting CLOCK_REALTIME for synchronization
2017-06-13T13:59:05.703474-04:00 bco2 phc2sys: [27.336] selecting eth2 as the master clock
2017-06-13T13:59:05.703523-04:00 bco2 phc2sys: [27.336] phc offset 168017291 s0 freq -0 delay 47
2017-06-13T13:59:06.703660-04:00 bco2 phc2sys: [28.337] phc offset 167991798 s0 freq -0 delay 49
2017-06-13T13:59:07.703828-04:00 bco2 phc2sys: [29.337] phc offset 167966620 s0 freq -0 delay 42
2017-06-13T13:59:08.536030-04:00 bco2 phc2sys: [30.337] phc offset 167941573 s1 freq -25332 delay 45
2017-06-13T13:59:09.536165-04:00 bco2 phc2sys: [31.337] phc offset -360 s2 freq -25469 delay 50
2017-06-13T13:59:10.536299-04:00 bco2 phc2sys: [32.337] phc offset 168 s2 freq -25200 delay 45


diff --git a/clockadj.c b/clockadj.c
index 5eb7cce..86c7b33 100644
--- a/clockadj.c
+++ b/clockadj.c
@@ -73,7 +73,7 @@ double clockadj_get_freq(clockid_t clkid)
pr_err("failed to read out the clock frequency adjustment: %m");
} else {
f = tx.freq / 65.536;
- if (clkid == CLOCK_REALTIME && realtime_nominal_tick)
+ if (clkid == CLOCK_REALTIME && realtime_nominal_tick && tx.tick)
f += 1e3 * realtime_hz * (tx.tick - realtime_nominal_tick);


I think this older version of the kernel (2.6.32-504.el6.x86_64) is returning 0 for tx.tick.

Any thoughts on whether this is a valid fix?

I also had to make another small change to get the latest code to build on RHEL 6.8:

diff --git a/rtnl.c b/rtnl.c
index 251b5f3..1266731 100644
--- a/rtnl.c
+++ b/rtnl.c
@@ -17,6 +17,7 @@
* 51 Franklin Street, Fifth Floor, Boston, MA 02110-1301 USA.
*/
#include <asm/types.h>
+#include <sys/socket.h>
#include <linux/netlink.h>
#include <linux/rtnetlink.h>
#include <net/if.h>

thanks for looking at this.

Brian Olson
***@amergint.com
719-522-2808
"we mutually pledge to each other our Lives, our Fortunes and our sacred Honor."

Post by Miroslav Lichvar

Post by Brian Olson
double clockadj_get_freq(clockid_t clkid)
{
double f = 0.0;
struct timex tx;
memset(&tx, 0, sizeof(tx));
if (clock_adjtime(clkid, &tx) < 0) {

From your logs it seems the problem is that clock_adjtime() returns
zero ticks instead of 10000 for the REALTIME clock. I suspect it's a
kernel or possibly glibc bug.
--
Miroslav Lichvar

[Brian Olson]

I believe it would be the kernel and not glibc, since I think I’m ending up with this code from missing.h, which directly issues a syscall:

#ifndef HAVE_CLOCK_ADJTIME
static inline int clock_adjtime(clockid_t id, struct timex *tx)
{
return syscall(__NR_clock_adjtime, id, tx);
}
#endif

Brian Olson
***@amergint.com
719-522-2808
"we mutually pledge to each other our Lives, our Fortunes and our sacred Honor."

Post by Brian Olson
I agree.
2017-06-13T13:59:05.703456-04:00 bco2 phc2sys: [27.336] reconfiguring after port state change
2017-06-13T13:59:05.703467-04:00 bco2 phc2sys: [27.336] selecting CLOCK_REALTIME for synchronization
2017-06-13T13:59:05.703474-04:00 bco2 phc2sys: [27.336] selecting eth2 as the master clock
2017-06-13T13:59:05.703523-04:00 bco2 phc2sys: [27.336] phc offset 168017291 s0 freq -0 delay 47
2017-06-13T13:59:06.703660-04:00 bco2 phc2sys: [28.337] phc offset 167991798 s0 freq -0 delay 49
2017-06-13T13:59:07.703828-04:00 bco2 phc2sys: [29.337] phc offset 167966620 s0 freq -0 delay 42
2017-06-13T13:59:08.536030-04:00 bco2 phc2sys: [30.337] phc offset 167941573 s1 freq -25332 delay 45
2017-06-13T13:59:09.536165-04:00 bco2 phc2sys: [31.337] phc offset -360 s2 freq -25469 delay 50
2017-06-13T13:59:10.536299-04:00 bco2 phc2sys: [32.337] phc offset 168 s2 freq -25200 delay 45
diff --git a/clockadj.c b/clockadj.c
index 5eb7cce..86c7b33 100644
--- a/clockadj.c
+++ b/clockadj.c
@@ -73,7 +73,7 @@ double clockadj_get_freq(clockid_t clkid)
pr_err("failed to read out the clock frequency adjustment: %m");
} else {
f = tx.freq / 65.536;
- if (clkid == CLOCK_REALTIME && realtime_nominal_tick)
+ if (clkid == CLOCK_REALTIME && realtime_nominal_tick && tx.tick)
f += 1e3 * realtime_hz * (tx.tick - realtime_nominal_tick);
I think this older version of the kernel (2.6.32-504.el6.x86_64) is returning 0 for tx.tick.
Any thoughts on whether this is a valid fix?
diff --git a/rtnl.c b/rtnl.c
index 251b5f3..1266731 100644
--- a/rtnl.c
+++ b/rtnl.c
@@ -17,6 +17,7 @@
* 51 Franklin Street, Fifth Floor, Boston, MA 02110-1301 USA.
*/
#include <asm/types.h>
+#include <sys/socket.h>
#include <linux/netlink.h>
#include <linux/rtnetlink.h>
#include <net/if.h>
thanks for looking at this.
Brian Olson
719-522-2808
"we mutually pledge to each other our Lives, our Fortunes and our sacred Honor."

Post by Miroslav Lichvar

Post by Brian Olson
double clockadj_get_freq(clockid_t clkid)
{
double f = 0.0;
struct timex tx;
memset(&tx, 0, sizeof(tx));
if (clock_adjtime(clkid, &tx) < 0) {

From your logs it seems the problem is that clock_adjtime() returns
zero ticks instead of 10000 for the REALTIME clock. I suspect it's a
kernel or possibly glibc bug.
--
Miroslav Lichvar

[Miroslav Lichvar]

Post by Brian Olson
@@ -73,7 +73,7 @@ double clockadj_get_freq(clockid_t clkid)
pr_err("failed to read out the clock frequency adjustment: %m");
} else {
f = tx.freq / 65.536;
- if (clkid == CLOCK_REALTIME && realtime_nominal_tick)
+ if (clkid == CLOCK_REALTIME && realtime_nominal_tick && tx.tick)
f += 1e3 * realtime_hz * (tx.tick - realtime_nominal_tick);
I think this older version of the kernel (2.6.32-504.el6.x86_64) is returning 0 for tx.tick.

Now I recall this is a known bug that was fixed in linux-3.9.
clock_adjtime() updated the struct timex when it returned zero, but
not with positive values (e.g. TIME_ERROR).

The linuxptp code actually has a workaround for this bug, allowing
clockadj_get_freq() to return 0 even if it's not the correct value,
but apparently I broke it later with the ticks.

Post by Brian Olson
Any thoughts on whether this is a valid fix?

Yes, that should fix the workaround. Can you please submit it as a git
patch to linuxptp-devel?

Another is to run "ntptime -m 0 -s 0" before starting phc2sys, so
clock_adjtime() returns valid data.

Post by Brian Olson
diff --git a/rtnl.c b/rtnl.c
index 251b5f3..1266731 100644
--- a/rtnl.c
+++ b/rtnl.c
@@ -17,6 +17,7 @@
* 51 Franklin Street, Fifth Floor, Boston, MA 02110-1301 USA.
*/
#include <asm/types.h>
+#include <sys/socket.h>
#include <linux/netlink.h>
#include <linux/rtnetlink.h>
#include <net/if.h>

It would be nice to fix this too.

Thanks,