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

[Yang Li <yang.li@amlogic.com>]

Hi Pauli,
> [ EXTERNAL EMAIL ]
>
> 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*)?


Yes, you are right. The interval should be the ISO interval (10 ms).
The 10 s interval in the log happened because the kernel version I 
tested (6.6) doesn’t have us_to_ktime(), so I wrote a custom version, 
but the conversion factor was wrong.
kernel patch as below:

diff --git a/net/bluetooth/iso.c b/net/bluetooth/iso.c
index 070de5588c74..de05587393fa 100644
--- a/net/bluetooth/iso.c
+++ b/net/bluetooth/iso.c
@@ -2251,6 +2251,10 @@ static void iso_disconn_cfm(struct hci_conn 
*hcon, __u8 reason)

         iso_conn_del(hcon, bt_to_errno(reason));
  }
+static  ktime_t us_to_ktime(u64 us)
+{
+       return us * 1000000L;
+}

  void iso_recv(struct hci_conn *hcon, struct sk_buff *skb, u16 flags)
  {
@@ -2285,6 +2289,11 @@ void iso_recv(struct hci_conn *hcon, struct 
sk_buff *skb, u16 flags)
                                 goto drop;
                         }

+                       /* Record the timestamp to skb*/
+                       struct skb_shared_hwtstamps *hwts = 
skb_hwtstamps(skb);
+                       if (hwts)
+                               hwts->hwtstamp = 
us_to_ktime(le32_to_cpu(hdr->ts));
+

>
>> 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