PTP: getting the time of the PHC can cause extts events to be lost

Start in drivers/net/phy/bcm-phy-ptp.c, especially bcm_ptp_extts_work and bcm_ptp_gettimex, and reproduce the issue with testptp while chrony or linuxptp reads the PHC. Trace PTP_SYS_OFFSET_EXTENDED alongside extts events. Done means PHC reads no longer cause external timestamp events to be lost under concurrent use.

Describe the bug

This is an issue with the PTP support introduced in #4151 (drivers/net/phy/bcm-phy-ptp.c).

When a program is reading extts events (which are generated by calls to ptp_clock_event in bcm_ptp_extts_work) and another program is reading the PHC (which will end up calling bcm_ptp_gettimex), some extts events are lost: if a PPS signal is being fed into the CM4 SYNC_OUT pin, then instead of there being one event per second, there will be sometimes be two or more seconds between events.

This causes a problem when trying to use the PTP as a grandmaster and also synchronize the system time to the PHC (e.g. to run NTP as well). The ts2phc program (part of linuxptp) is used to synchronize the PHC to a PPS signal input to the SYNC_OUT pin; this reads extts events. Then the system time is synchronized to the PHC using either phc2sys program from linuxptp or using chrony with the PHC refclock; both of these use the PTP_SYS_OFFSET_EXTENDED ioctl to get the time of the PHC.

Steps to reproduce the behaviour

Connect up the SYNC_OUT pin to a PPS source.

Use the testptp program (in linux/master/tools/testing/selftests/ptp/) to configure the SYNC_OUT pin to be an input pin:

sudo ./testptp  -d /dev/ptp0 -L 0,1

Then use testptp to read some PTP extts event

sudo ./testptp -e 10

You should see one event per second, e.g.:

external time stamp request okay
event index 0 at 1667216818.000468254
event index 0 at 1667216819.000468335
event index 0 at 1667216820.000468409
event index 0 at 1667216821.000468483
event index 0 at 1667216822.000468549
event index 0 at 1667216823.000468614
event index 0 at 1667216824.000468656
event index 0 at 1667216825.000468714
event index 0 at 1667216826.000468780
event index 0 at 1667216827.000468837

Now run chrony with a conf file including refclock line like this:

refclock PHC /dev/ptp0 dpoll -2 offset -37 precision 1e-7 pps

Now run testptp again (you may need more events):

sudo ./testptp -e 100

Instead of seeing one event per second, I see some events lost, e.g.

external time stamp request okay
event index 0 at 1667209592.000004850
event index 0 at 1667209597.000005139
event index 0 at 1667209598.000005181
event index 0 at 1667209599.000005230
event index 0 at 1667209606.000005523

In the above, we see we have lost the events for 1667209593-96 and 1667209600-05.

I believe this is incorrect behaviour and the occurrence of extts events should not be affected by getting the time from the PHC.

Device (s)

Raspberry Pi CM4

System

OS

Raspberry Pi reference 2022-09-22
Generated using pi-gen, https://github.com/RPi-Distro/pi-gen, 005a8c73b05a2cab394073150208bf4f069e861a, stage2

Firmware

Aug 26 2022 14:03:16
Copyright (c) 2012 Broadcom
version 102f1e848393c2112206fadffaaf86db04e98326 (clean) (release) (start)

Kernel

Linux roquefort 5.15.61-v8+ #1579 SMP PREEMPT Fri Aug 26 11:16:44 BST 2022 aarch64 GNU/Linux

Logs

I used the following bpftrace script to examine the behaviour with ts2phc and chrony running:

#include <linux/ptp_clock.h>
#include <linux/ptp_clock_kernel.h>


kprobe:ptp_clock_event
{
        $last_ts = @ts;
        @ts =  ((struct ptp_clock_event *)arg1)->timestamp;
        printf("ptp_clock_event sys=%lu, phc=%lu\n", nsecs, @ts);
        if ($last_ts != 0) {
                $expect = $last_ts + 1000000000;
                $diff = $expect > @ts ? $expect - @ts : @ts - $expect;
                if ($diff > 100000000) {
                        printf("%lu: timestamp off from expected by %lu ms\n", nsecs, $diff/1000000);
                }
        }
}

kprobe:ptp_ioctl
{

        if (arg1 == 0xc4c03d09) {
                printf("PTP_SYS_OFFSET_EXTENDED n_samples=%d, sys=%lu, pid=%d\n", ((struct ptp_sys_offset_extended *)arg2)->n_samples, nsecs, pid);
        }
        else {
                printf("PTP ioctl 0x%x, pid=%d\n", arg1, pid);
        }
}

It generated the following output:

Attaching 2 probes...
PTP_SYS_OFFSET_EXTENDED n_samples=10, sys=775358964899686, pid=42477
PTP_SYS_OFFSET_EXTENDED n_samples=10, sys=775359220482442, pid=42477
PTP_SYS_OFFSET_EXTENDED n_samples=10, sys=775359476262862, pid=42477
PTP_SYS_OFFSET_EXTENDED n_samples=10, sys=775359734913963, pid=42477
PTP_SYS_OFFSET_EXTENDED n_samples=10, sys=775359993825893, pid=42477
PTP_SYS_OFFSET_EXTENDED n_samples=10, sys=775360252666231, pid=42477
PTP_SYS_OFFSET_EXTENDED n_samples=10, sys=775360511563013, pid=42477
PTP_SYS_OFFSET_EXTENDED n_samples=10, sys=775360770475517, pid=42477
PTP_SYS_OFFSET_EXTENDED n_samples=10, sys=775361029279967, pid=42477
PTP_SYS_OFFSET_EXTENDED n_samples=10, sys=775361288115454, pid=42477
PTP_SYS_OFFSET_EXTENDED n_samples=10, sys=775361547008088, pid=42477
PTP_SYS_OFFSET_EXTENDED n_samples=10, sys=775361805888241, pid=42477
PTP_SYS_OFFSET_EXTENDED n_samples=10, sys=775362064612636, pid=42477
PTP_SYS_OFFSET_EXTENDED n_samples=10, sys=775362323417753, pid=42477
PTP_SYS_OFFSET_EXTENDED n_samples=10, sys=775362582262332, pid=42477
PTP_SYS_OFFSET_EXTENDED n_samples=10, sys=775362841110134, pid=42477
PTP_SYS_OFFSET_EXTENDED n_samples=10, sys=775363099983434, pid=42477
PTP_SYS_OFFSET_EXTENDED n_samples=10, sys=775363358858272, pid=42477
PTP_SYS_OFFSET_EXTENDED n_samples=10, sys=775363617879386, pid=42477
PTP_SYS_OFFSET_EXTENDED n_samples=10, sys=775363876745743, pid=42477
PTP_SYS_OFFSET_EXTENDED n_samples=10, sys=775364135575304, pid=42477
ptp_clock_event sys=775364368713367, phc=1667209381999999910
PTP_SYS_OFFSET_EXTENDED n_samples=10, sys=775364394640583, pid=42477
PTP_SYS_OFFSET_EXTENDED n_samples=10, sys=775364653579494, pid=42477
PTP_SYS_OFFSET_EXTENDED n_samples=10, sys=775364912429388, pid=42477
PTP_SYS_OFFSET_EXTENDED n_samples=10, sys=775365171301578, pid=42477
ptp_clock_event sys=775365376767024, phc=1667209382999999999
PTP_SYS_OFFSET_EXTENDED n_samples=10, sys=775365430213971, pid=42477
PTP_SYS_OFFSET_EXTENDED n_samples=10, sys=775365689093864, pid=42477
PTP_SYS_OFFSET_EXTENDED n_samples=10, sys=775365947923962, pid=42477
PTP_SYS_OFFSET_EXTENDED n_samples=10, sys=775366206801208, pid=42477
ptp_clock_event sys=775366384716294, phc=1667209384000000029
PTP_SYS_OFFSET_EXTENDED n_samples=10, sys=775366465621417, pid=42477
PTP_SYS_OFFSET_EXTENDED n_samples=10, sys=775366724501903, pid=42477
PTP_SYS_OFFSET_EXTENDED n_samples=10, sys=775366983352334, pid=42477
PTP_SYS_OFFSET_EXTENDED n_samples=10, sys=775367242210913, pid=42477
ptp_clock_event sys=775367392707952, phc=1667209385000000029
PTP_SYS_OFFSET_EXTENDED n_samples=10, sys=775367501030733, pid=42477
PTP_SYS_OFFSET_EXTENDED n_samples=10, sys=775367759908478, pid=42477
PTP_SYS_OFFSET_EXTENDED n_samples=10, sys=775368018789705, pid=42477
PTP_SYS_OFFSET_EXTENDED n_samples=10, sys=775368277586044, pid=42477
ptp_clock_event sys=775368400655407, phc=1667209386000000020
PTP_SYS_OFFSET_EXTENDED n_samples=10, sys=775368536405938, pid=42477
PTP_SYS_OFFSET_EXTENDED n_samples=10, sys=775368795293332, pid=42477
PTP_SYS_OFFSET_EXTENDED n_samples=10, sys=775369054102356, pid=42477
PTP_SYS_OFFSET_EXTENDED n_samples=10, sys=775369312891528, pid=42477
ptp_clock_event sys=775369408709583, phc=1667209387000000035
PTP_SYS_OFFSET_EXTENDED n_samples=10, sys=775369571698534, pid=42477
PTP_SYS_OFFSET_EXTENDED n_samples=10, sys=775369830626427, pid=42477
PTP_SYS_OFFSET_EXTENDED n_samples=10, sys=775370089704295, pid=42477
PTP_SYS_OFFSET_EXTENDED n_samples=10, sys=775370348500520, pid=42477
PTP_SYS_OFFSET_EXTENDED n_samples=10, sys=775370607365743, pid=42477
PTP_SYS_OFFSET_EXTENDED n_samples=10, sys=775370866244337, pid=42477
PTP_SYS_OFFSET_EXTENDED n_samples=10, sys=775371125093968, pid=42477
PTP_SYS_OFFSET_EXTENDED n_samples=10, sys=775371384036080, pid=42477
PTP_SYS_OFFSET_EXTENDED n_samples=10, sys=775371642913821, pid=42477
PTP_SYS_OFFSET_EXTENDED n_samples=10, sys=775371901786785, pid=42477
PTP_SYS_OFFSET_EXTENDED n_samples=10, sys=775372160643453, pid=42477
PTP_SYS_OFFSET_EXTENDED n_samples=10, sys=775372419445122, pid=42477
PTP_SYS_OFFSET_EXTENDED n_samples=10, sys=775372678284735, pid=42477
PTP_SYS_OFFSET_EXTENDED n_samples=10, sys=775372937282420, pid=42477
PTP_SYS_OFFSET_EXTENDED n_samples=10, sys=775373196151773, pid=42477
ptp_clock_event sys=775373440797610, phc=1667209390999999900
775373440809776: timestamp off from expected by 2999 ms
PTP_SYS_OFFSET_EXTENDED n_samples=10, sys=775373455039422, pid=42477
PTP_SYS_OFFSET_EXTENDED n_samples=10, sys=775373713912497, pid=42477
PTP_SYS_OFFSET_EXTENDED n_samples=10, sys=775373972762499, pid=42477
PTP_SYS_OFFSET_EXTENDED n_samples=10, sys=775374231600519, pid=42477
ptp_clock_event sys=775374448742293, phc=1667209391999999967
PTP_SYS_OFFSET_EXTENDED n_samples=10, sys=775374490478094, pid=42477
PTP_SYS_OFFSET_EXTENDED n_samples=10, sys=775374749479390, pid=42477
PTP_SYS_OFFSET_EXTENDED n_samples=10, sys=775375008327502, pid=42477
PTP_SYS_OFFSET_EXTENDED n_samples=10, sys=775375267171541, pid=42477
ptp_clock_event sys=775375456777807, phc=1667209393000000036
PTP_SYS_OFFSET_EXTENDED n_samples=10, sys=775375526022265, pid=42477
PTP_SYS_OFFSET_EXTENDED n_samples=10, sys=775375784881988, pid=42477
PTP_SYS_OFFSET_EXTENDED n_samples=10, sys=775376043691324, pid=42477
PTP_SYS_OFFSET_EXTENDED n_samples=10, sys=775376302530844, pid=42477
ptp_clock_event sys=775376464736360, phc=1667209394000000032
PTP_SYS_OFFSET_EXTENDED n_samples=10, sys=775376561398734, pid=42477
PTP_SYS_OFFSET_EXTENDED n_samples=10, sys=775376820283050, pid=42477
PTP_SYS_OFFSET_EXTENDED n_samples=10, sys=775377079173958, pid=42477
PTP_SYS_OFFSET_EXTENDED n_samples=10, sys=775377337984016, pid=42477
ptp_clock_event sys=775377472678838, phc=1667209395000000008
PTP_SYS_OFFSET_EXTENDED n_samples=10, sys=775377596850795, pid=42477
PTP_SYS_OFFSET_EXTENDED n_samples=10, sys=775377855718111, pid=42477
PTP_SYS_OFFSET_EXTENDED n_samples=10, sys=775378114689796, pid=42477
PTP_SYS_OFFSET_EXTENDED n_samples=10, sys=775378373520650, pid=42477
PTP_SYS_OFFSET_EXTENDED n_samples=10, sys=775378632377410, pid=42477
PTP_SYS_OFFSET_EXTENDED n_samples=10, sys=775378891257874, pid=42477
PTP_SYS_OFFSET_EXTENDED n_samples=10, sys=775379150060340, pid=42477
PTP_SYS_OFFSET_EXTENDED n_samples=10, sys=775379408875582, pid=42477
PTP_SYS_OFFSET_EXTENDED n_samples=10, sys=775379667762139, pid=42477
PTP_SYS_OFFSET_EXTENDED n_samples=10, sys=775379926720250, pid=42477
PTP_SYS_OFFSET_EXTENDED n_samples=10, sys=775380185490346, pid=42477
PTP_SYS_OFFSET_EXTENDED n_samples=10, sys=775380444353740, pid=42477
PTP_SYS_OFFSET_EXTENDED n_samples=10, sys=775380703224651, pid=42477
PTP_SYS_OFFSET_EXTENDED n_samples=10, sys=775380962109544, pid=42477
PTP_SYS_OFFSET_EXTENDED n_samples=10, sys=775381220919661, pid=42477
PTP_SYS_OFFSET_EXTENDED n_samples=10, sys=775381479790109, pid=42477
PTP_SYS_OFFSET_EXTENDED n_samples=10, sys=775381738820833, pid=42477
PTP_SYS_OFFSET_EXTENDED n_samples=10, sys=775381997694412, pid=42477
PTP_SYS_OFFSET_EXTENDED n_samples=10, sys=775382256557101, pid=42477
ptp_clock_event sys=775382512731348, phc=1667209399999999964
775382512745774: timestamp off from expected by 3999 ms
PTP_SYS_OFFSET_EXTENDED n_samples=10, sys=775382515606029, pid=42477
PTP_SYS_OFFSET_EXTENDED n_samples=10, sys=775382774594217, pid=42477
PTP_SYS_OFFSET_EXTENDED n_samples=10, sys=775383033368315, pid=42477
PTP_SYS_OFFSET_EXTENDED n_samples=10, sys=775383292192357, pid=42477
ptp_clock_event sys=775383520717894, phc=1667209400999999972
PTP_SYS_OFFSET_EXTENDED n_samples=10, sys=775383551075528, pid=42477
PTP_SYS_OFFSET_EXTENDED n_samples=10, sys=775383809976883, pid=42477
PTP_SYS_OFFSET_EXTENDED n_samples=10, sys=775384068918053, pid=42477
PTP_SYS_OFFSET_EXTENDED n_samples=10, sys=775384327794391, pid=42477
ptp_clock_event sys=775384528783290, phc=1667209401999999990
PTP_SYS_OFFSET_EXTENDED n_samples=10, sys=775384586679599, pid=42477
PTP_SYS_OFFSET_EXTENDED n_samples=10, sys=775384845545251, pid=42477
PTP_SYS_OFFSET_EXTENDED n_samples=10, sys=775385104444996, pid=42477
PTP_SYS_OFFSET_EXTENDED n_samples=10, sys=775385363291704, pid=42477
PTP_SYS_OFFSET_EXTENDED n_samples=10, sys=775385622092580, pid=42477
PTP_SYS_OFFSET_EXTENDED n_samples=10, sys=775385880923233, pid=42477
PTP_SYS_OFFSET_EXTENDED n_samples=10, sys=775386139780422, pid=42477
PTP_SYS_OFFSET_EXTENDED n_samples=10, sys=775386398687148, pid=42477
PTP_SYS_OFFSET_EXTENDED n_samples=10, sys=775386657732485, pid=42477
PTP_SYS_OFFSET_EXTENDED n_samples=10, sys=775386913863123, pid=42477
PTP_SYS_OFFSET_EXTENDED n_samples=10, sys=775387172766462, pid=42477
PTP_SYS_OFFSET_EXTENDED n_samples=10, sys=775387431591653, pid=42477
PTP_SYS_OFFSET_EXTENDED n_samples=10, sys=775387690512898, pid=42477
PTP_SYS_OFFSET_EXTENDED n_samples=10, sys=775387949412404, pid=42477
PTP_SYS_OFFSET_EXTENDED n_samples=10, sys=775388208248409, pid=42477
PTP_SYS_OFFSET_EXTENDED n_samples=10, sys=775388467065434, pid=42477
PTP_SYS_OFFSET_EXTENDED n_samples=10, sys=775388725994087, pid=42477
PTP_SYS_OFFSET_EXTENDED n_samples=10, sys=775388984868833, pid=42477
PTP_SYS_OFFSET_EXTENDED n_samples=10, sys=775389243730154, pid=42477
PTP_SYS_OFFSET_EXTENDED n_samples=10, sys=775389502548975, pid=42477
PTP_SYS_OFFSET_EXTENDED n_samples=10, sys=775389761711328, pid=42477
PTP_SYS_OFFSET_EXTENDED n_samples=10, sys=775390020554297, pid=42477
PTP_SYS_OFFSET_EXTENDED n_samples=10, sys=775390279397303, pid=42477
PTP_SYS_OFFSET_EXTENDED n_samples=10, sys=775390538255919, pid=42477
PTP_SYS_OFFSET_EXTENDED n_samples=10, sys=775390797176332, pid=42477
PTP_SYS_OFFSET_EXTENDED n_samples=10, sys=775391056059004, pid=42477
PTP_SYS_OFFSET_EXTENDED n_samples=10, sys=775391314857325, pid=42477
PTP_SYS_OFFSET_EXTENDED n_samples=10, sys=775391573663406, pid=42477
PTP_SYS_OFFSET_EXTENDED n_samples=10, sys=775391832518856, pid=42477
PTP_SYS_OFFSET_EXTENDED n_samples=10, sys=775392091625524, pid=42477
PTP_SYS_OFFSET_EXTENDED n_samples=10, sys=775392350423290, pid=42477
PTP_SYS_OFFSET_EXTENDED n_samples=10, sys=775392609301666, pid=42477
PTP_SYS_OFFSET_EXTENDED n_samples=10, sys=775392868325299, pid=42477
PTP_SYS_OFFSET_EXTENDED n_samples=10, sys=775393127203156, pid=42477
PTP_SYS_OFFSET_EXTENDED n_samples=10, sys=775393386028551, pid=42477
PTP_SYS_OFFSET_EXTENDED n_samples=10, sys=775393644836076, pid=42477
PTP_SYS_OFFSET_EXTENDED n_samples=10, sys=775393903732729, pid=42477
PTP_SYS_OFFSET_EXTENDED n_samples=10, sys=775394162663475, pid=42477
ptp_clock_event sys=775394356653129, phc=1667209412000000111
775394356661444: timestamp off from expected by 9000 ms
PTP_SYS_OFFSET_EXTENDED n_samples=10, sys=775394421495740, pid=42477
PTP_SYS_OFFSET_EXTENDED n_samples=10, sys=775394680478114, pid=42477
PTP_SYS_OFFSET_EXTENDED n_samples=10, sys=775394939303454, pid=42477
PTP_SYS_OFFSET_EXTENDED n_samples=10, sys=775395198153015, pid=42477
ptp_clock_event sys=775395364719014, phc=1667209412999999994
PTP_SYS_OFFSET_EXTENDED n_samples=10, sys=775395457001410, pid=42477
PTP_SYS_OFFSET_EXTENDED n_samples=10, sys=775395715986340, pid=42477
PTP_SYS_OFFSET_EXTENDED n_samples=10, sys=775395974848382, pid=42477
PTP_SYS_OFFSET_EXTENDED n_samples=10, sys=775396233687536, pid=42477
ptp_clock_event sys=775396372678863, phc=1667209413999999967
PTP_SYS_OFFSET_EXTENDED n_samples=10, sys=775396492544986, pid=42477
PTP_SYS_OFFSET_EXTENDED n_samples=10, sys=775396751350819, pid=42477
PTP_SYS_OFFSET_EXTENDED n_samples=10, sys=775397010162305, pid=42477
PTP_SYS_OFFSET_EXTENDED n_samples=10, sys=775397268966624, pid=42477
ptp_clock_event sys=775397380696984, phc=1667209414999999962
PTP_SYS_OFFSET_EXTENDED n_samples=10, sys=775397527975866, pid=42477
PTP_SYS_OFFSET_EXTENDED n_samples=10, sys=775397786856184, pid=42477
PTP_SYS_OFFSET_EXTENDED n_samples=10, sys=775398045666392, pid=42477
PTP_SYS_OFFSET_EXTENDED n_samples=10, sys=775398304528100, pid=42477
ptp_clock_event sys=775398388750785, phc=1667209415999999979
PTP_SYS_OFFSET_EXTENDED n_samples=10, sys=775398563355900, pid=42477
PTP_SYS_OFFSET_EXTENDED n_samples=10, sys=775398822208497, pid=42477
PTP_SYS_OFFSET_EXTENDED n_samples=10, sys=775399081034427, pid=42477
PTP_SYS_OFFSET_EXTENDED n_samples=10, sys=775399339952059, pid=42477
ptp_clock_event sys=775399397096434, phc=1667209416999999984
PTP_SYS_OFFSET_EXTENDED n_samples=10, sys=775399598816026, pid=42477
PTP_SYS_OFFSET_EXTENDED n_samples=10, sys=775399857677566, pid=42477
PTP_SYS_OFFSET_EXTENDED n_samples=10, sys=775400116607902, pid=42477
PTP_SYS_OFFSET_EXTENDED n_samples=10, sys=775400375386851, pid=42477
PTP_SYS_OFFSET_EXTENDED n_samples=10, sys=775400634254151, pid=42477

Additional context

The dpoll value in the chrony refclock line affects how often the problem occurs. With dpoll 4 (which does a PTP_SYS_OFFSET_EXTENDED ioctl every 16 seconds with 10 samples) it happens roughly every 10 to 15 minutes. When it does happen it "clusters": it will miss one timestamp and then another 16 or 32 seconds later; it will do this several times; then it will not miss one for 10 or 15 minutes. With both chrony and phc2sys, the interval between the ioctl is an integral number of seconds.

This is consistent with a hypothesis that an extts event will be missed if the edge happens while a call to bcm_ptp_gettimex is happening.

I noticed that the extts signal is enabled by setting the NSE_SYNC1_FRAMESYNC flag in bcm_ptp_extts_locked (https://github.com/raspberrypi/linux/blob/7f52d634c6e810fbc704d579e8e9614d3959c575/drivers/net/phy/bcm-phy-ptp.c#L677) but that flag appears to be cleared for the duration of bcm_ptp_framesync_ts (which is called by bcm_ptp_gettimex) by the call to bcm_ptp_framesync_disable at (https://github.com/raspberrypi/linux/blob/7f52d634c6e810fbc704d579e8e9614d3959c575/drivers/net/phy/bcm-phy-ptp.c#L225). I wonder if this might be relevant.