Re: [PATCH v3] Bluetooth: ISO: Support SCM_TIMESTAMPING for ISO TS

[Pauli Virtanen <pav@iki.fi>]

Hi,

ma, 2025-07-07 kello 09:48 +0800, Yang Li kirjoitti:
> Hi,
> > [ EXTERNAL EMAIL ]
> > 
> > Hi,
> > 
> > pe, 2025-07-04 kello 13:36 +0800, Yang Li via B4 Relay kirjoitti:
> > > From: Yang Li <yang.li@amlogic.com>
> > > 
> > > User-space applications (e.g., PipeWire) depend on
> > > ISO-formatted timestamps for precise audio sync.
> > > 
> > > Signed-off-by: Yang Li <yang.li@amlogic.com>
> > > ---
> > > Changes in v3:
> > > - Change to use hwtimestamp
> > > - Link to v2: https://lore.kernel.org/r/20250702-iso_ts-v2-1-723d199c8068@amlogic.com
> > > 
> > > Changes in v2:
> > > - Support SOCK_RCVTSTAMPNS via CMSG for ISO sockets
> > > - Link to v1: https://lore.kernel.org/r/20250429-iso_ts-v1-1-e586f30de6cb@amlogic.com
> > > ---
> > >   net/bluetooth/iso.c | 10 +++++++++-
> > >   1 file changed, 9 insertions(+), 1 deletion(-)
> > > 
> > > diff --git a/net/bluetooth/iso.c b/net/bluetooth/iso.c
> > > index fc22782cbeeb..67ff355167d8 100644
> > > --- a/net/bluetooth/iso.c
> > > +++ b/net/bluetooth/iso.c
> > > @@ -2301,13 +2301,21 @@ void iso_recv(struct hci_conn *hcon, struct sk_buff *skb, u16 flags)
> > >                if (ts) {
> > >                        struct hci_iso_ts_data_hdr *hdr;
> > > 
> > > -                     /* TODO: add timestamp to the packet? */
> > >                        hdr = skb_pull_data(skb, HCI_ISO_TS_DATA_HDR_SIZE);
> > >                        if (!hdr) {
> > >                                BT_ERR("Frame is too short (len %d)", skb->len);
> > >                                goto drop;
> > >                        }
> > > 
> > > +                     /* The ISO ts is based on the controller’s clock domain,
> > > +                      * so hardware timestamping (hwtimestamp) must be used.
> > > +                      * Ref: Documentation/networking/timestamping.rst,
> > > +                      * chapter 3.1 Hardware Timestamping.
> > > +                      */
> > > +                     struct skb_shared_hwtstamps *hwts = skb_hwtstamps(skb);
> > > +                     if (hwts)
> > In addition to the moving variable on top, the null check is spurious
> > as skb_hwtstamps is never NULL (driver/net/* do not check it either).
> > 
> > Did you test this with SOF_TIMESTAMPING_RX_HARDWARE in userspace?
> > Pipewire does not try to get HW timestamps right now.
> > 
> > Would be good to also add some tests in bluez/tools/iso-tester.c
> > although this needs some extension to the emulator/* to support
> > timestamps properly.
> 
> 
> Yes, here is the patch and log based on testing with Pipewire:
> 
> diff --git a/spa/plugins/bluez5/media-source.c 
> b/spa/plugins/bluez5/media-source.c
> index 2fe08b8..10e9378 100644
> --- a/spa/plugins/bluez5/media-source.c
> +++ b/spa/plugins/bluez5/media-source.c
> @@ -407,7 +413,7 @@ static int32_t read_data(struct impl *this) {
>          struct msghdr msg = {0};
>          struct iovec iov;
>          char control[128];
> -       struct timespec *ts = NULL;
> +       struct scm_timestamping *ts = NULL;
> 
>          iov.iov_base = this->buffer_read;
>          iov.iov_len = b_size;
> @@ -439,12 +445,14 @@ again:
>          struct cmsghdr *cmsg;
>          for (cmsg = CMSG_FIRSTHDR(&msg); cmsg != NULL; cmsg = 
> CMSG_NXTHDR(&msg, cmsg)) {
>   #ifdef SCM_TIMESTAMPING
>                  /* Check for timestamp */
> +               if (cmsg->cmsg_level == SOL_SOCKET && cmsg->cmsg_type == 
> SCM_TIMESTAMPING) {
> +                       ts = (struct scm_timestamping *)CMSG_DATA(cmsg);
> +                       spa_log_error(this->log, "%p: received timestamp 
> %ld.%09ld",
> +                                       this, ts->ts[2].tv_sec, 
> ts->ts[2].tv_nsec);
>                          break;
>                  }
>   #endif
> 
>   @@ -726,9 +734,9 @@ static int transport_start(struct impl *this)
>          if (setsockopt(this->fd, SOL_SOCKET, SO_PRIORITY, &val, 
> sizeof(val)) < 0)
>                  spa_log_warn(this->log, "SO_PRIORITY failed: %m");
> 
> +       val = SOF_TIMESTAMPING_RX_HARDWARE | SOF_TIMESTAMPING_RAW_HARDWARE;
> +       if (setsockopt(this->fd, SOL_SOCKET, SO_TIMESTAMPING, &val, 
> sizeof(val)) < 0) {
> +               spa_log_warn(this->log, "SO_TIMESTAMPING failed: %m");
>                  /* don't fail if timestamping is not supported */
>          }
> 
> trace log：
> 
> read_data: 0x1e78d68: received timestamp 7681.972000000
> read_data: 0x1e95000: received timestamp 7681.972000000
> read_data: 0x1e78d68: received timestamp 7691.972000000
> read_data: 0x1e95000: received timestamp 7691.972000000

The counter increases by 10 *seconds* on each step. Is there some
scaling problem here, or is the hardware producing bogus values?

Isn't it supposed to increase by ISO interval (10 *milliseconds*)?

> read_data: 0x1e78d68: received timestamp 7701.972000000
> read_data: 0x1e95000: received timestamp 7701.972000000
> read_data: 0x1e78d68: received timestamp 7711.972000000
> read_data: 0x1e95000: received timestamp 7711.972000000
> read_data: 0x1e78d68: received timestamp 7721.972000000
> read_data: 0x1e95000: received timestamp 7721.972000000
> read_data: 0x1e78d68: received timestamp 7731.972000000
> 
> > 
> > > +                             hwts->hwtstamp = us_to_ktime(le32_to_cpu(hdr->ts));
> > > +
> > >                        len = __le16_to_cpu(hdr->slen);
> > >                } else {
> > >                        struct hci_iso_data_hdr *hdr;
> > > 
> > > ---
> > > base-commit: 3bc46213b81278f3a9df0324768e152de71eb9fe
> > > change-id: 20250421-iso_ts-c82a300ae784
> > > 
> > > Best regards,
> > --
> > Pauli Virtanen

-- 
Pauli Virtanen