dsnoop/dshare/dmix: snd_pcm_htimestamp returns time past since last boot not clock time

[RonaldAJ]

While on a PC snd_pcm_htimestamp returns the clock time since the epoch, under Raspbian on an RPI it returns the time since the last boot. (A similar issue was described here: https://stackoverflow.com/questions/45841230/alsa-retrieving-audio-buffer-timestamps).

The problem shows if we run a slightly modified version of recordtest.py using the latest pyalsaaudio versions.

#!/usr/bin/env python3
# -*- mode: python; indent-tabs-mode: t; c-basic-offset: 4; tab-width: 4 -*-

## recordtest.py
##
## This is an example of a simple sound capture script.
##
## The script opens an ALSA pcm device for sound capture, sets
## various attributes of the capture, and reads in a loop,
## writing the data to standard out.
##
## To test it out do the following:
## python recordtest.py out.raw # talk to the microphone
## aplay -r 8000 -f S16_LE -c 1 out.raw

#!/usr/bin/env python

from __future__ import print_function

import sys
import time
import getopt
import alsaaudio

def usage():
    print('usage: recordtest.py [-d <device>] <file>', file=sys.stderr)
    sys.exit(2)

if __name__ == '__main__':

    device = 'default'

    opts, args = getopt.getopt(sys.argv[1:], 'd:')
    for o, a in opts:
        if o == '-d':
            device = a

    if not args:
        usage()

    f = open(args[0], 'wb')

    # Open the device in nonblocking capture mode in mono, with a sampling rate of 44100 Hz 
    # and 16 bit little endian samples
    # The period size controls the internal number of frames per period.
    # The significance of this parameter is documented in the ALSA api.
    # For our purposes, it is suficcient to know that reads from the device
    # will return this many frames. Each frame being 2 bytes long.
    # This means that the reads below will return either 320 bytes of data
    # or 0 bytes of data. The latter is possible because we are in nonblocking
    # mode.
    inp = alsaaudio.PCM(alsaaudio.PCM_CAPTURE, alsaaudio.PCM_NONBLOCK, 
        channels=1, rate=44100, format=alsaaudio.PCM_FORMAT_S16_LE, 
        periodsize=160, device=device)

    print(inp.info())
    # help(inp.htimestamp)

    loops = 100000
    while loops > 0:
        loops -= 1
        # Read data from device
        l, data = inp.read()
        if l:
            print(l, inp.htimestamp(), time.time())
            f.write(data)
            time.sleep(.001)

When executed on an RPi it yields:

{'name': 'plugsnoop:1,0', 'state': 'PREPARED', 'access_type': 'RW_INTERLEAVED', ' (call value) type': 1, ' (call value) type_name': 'CAPTURE', ' (call value) mode': 1, ' (call value) mode_name': 'PCM_NONBLOCK', 'format': 2, 'format_name': 'S16_LE', 'format_description': 'Signed 16 bit Little Endian', 'subformat_name': 'STD', 'subformat_description': 'Standard', 'channels': 1, 'rate': 44100, 'period_time': 21333, 'period_size': 940, 'buffer_time': 0, 'buffer_size': 4704, 'get_periods': 0, 'rate_numden': (44100, 1), 'significant_bits': 16, 'is_batch': True, 'is_block_transfer': True, 'is_double': False, 'is_half_duplex': False, 'is_joint_duplex': False, 'can_overrange': False, 'can_mmap_sample_resolution': False, 'can_pause': False, 'can_resume': False, 'can_sync_start': False}
940 (5596, 851796145, 0) 1617702646.0637105
940 (5596, 872796030, 0) 1617702646.084714
940 (5596, 893795916, 0) 1617702646.105702
940 (5596, 915796158, 0) 1617702646.1277127
940 (5596, 936795314, 0) 1617702646.1486921
940 (5596, 957795199, 0) 1617702646.1697078
940 (5596, 979795858, 0) 1617702646.191694
940 (5597, 795171, 0) 1617702646.212712
...

I read that for the timestamp function to work there should be hardware support. But here we have it half working.

This behavior is shown if I use the following in my .asoundrc

pcm.plugsnoop {
    type plug

    @args [ CARD DEV ]

    @args.CARD {
        type string
    }

    @args.DEV {
        type integer
    }

    slave { 
        pcm {
                @func concat
                strings [
                    "dsnoop:"
                    $CARD
                    ","
                    $DEV
                ]
            }
    }
}

and call it with: python recordtest.py -d plugsnoop:1,0 test.raw

Using plughw all timestamps become zero.

The attached microphone is an USB microphone: GoMic by SAMSON.

Is there a fix or workaround for this behavior which gives me clocktime instead of seconds since last boot?

[perexg]

What's the contents of /proc/asound/card0/pcm0c/sub0/sw_params when you're trying to capture something ? Replace card0 with the appropriate card (number).

[RonaldAJ]

(sa) pi@localhost:/proc/asound/card1/pcm0c/sub0 $ more sw_params closed

[perexg]

The PCM device must be active (you should try to capture / record something).

[RonaldAJ]

Ok. I'll set aup another ssh session then.

[RonaldAJ]

more sw_params

tstamp_mode: ENABLE
period_step: 1
avail_min: 1024
start_threshold: 1
stop_threshold: 1073741824
silence_threshold: 0
silence_size: 0
boundary: 1073741824

[RonaldAJ]

more hw_params

access: MMAP_INTERLEAVED
format: S16_LE
subformat: STD
channels: 1
rate: 48000 (48000/1)
period_size: 1024
buffer_size: 16384

[RonaldAJ]

more status

state: RUNNING
owner_pid   : 10252
trigger_time: 7656.727826313
tstamp      : 7658.540486440
delay       : 86784
avail       : 86784
avail_max   : 86784
-----
hw_ptr      : 86784
appl_ptr    : 0

[RonaldAJ]

The tstamp in the status file is close to the output of htimestamp. 940 (7656, 754484748, 0) 1617704705.9664147 ... 940 (7658, 695468285, 0) 1617704707.907379

[perexg]

I though that we print the type of timestamp in proc, but it seems that we don't. The timestamps are probably set to the monotonic (raw) type. You should ask the author of the alsaaudio python wrapper to add support for all ALSA timestamps (gettimeofday / realtime, monotonic, monotonic raw). See man 3 clock_getime for timestamp type explanation. Alsa-lib: snd_pcm_tstamp_type_t / snd_pcm_sw_params_set_tstamp_type() .

[RonaldAJ]

Well I wrote the htimestamp support in pyalsaaudio myself. If there is another function that returns the correct timestamp I can add it.

[perexg]

The mechanism to obtain the timestamp is one, but you should select the timestamp type - see hints in my last comment. The monotonic timestamps starts on boot (see the clock_gettime manpage).

[RonaldAJ]

I am studying. When you write monotonic do you mean monotic_raw? The documentation suggests that SND_PCM_TSTAMP_TYPE_MONOTONIC is updated through NTP whereas SND_PCM_TSTAMP_TYPE_MONOTONIC_RAW isn't.

[perexg]

Both. The monotonic time starts on boot. The NTP is used only for a correction (clock drift). You may use the realtime clock which is also affected by the NTP updates. I don't know what you expect to get. The sound card has own clock source, the system time is another clock source and the worldwide reference time is the third time source.

[RonaldAJ]

I want the seconds since the epoch.

On my VM this function can switch between the modes:

static PyObject *
alsapcm_enable_timestamp(alsapcm_t *self, PyObject *args)
{

        snd_pcm_sw_params_t* swParams;
        snd_pcm_sw_params_alloca( &swParams);

        snd_pcm_sw_params_current(self->handle, swParams);

        snd_pcm_sw_params_set_tstamp_mode(self->handle, swParams, SND_PCM_TSTAMP_ENABLE);
        snd_pcm_sw_params_set_tstamp_type(self->handle, swParams, SND_PCM_TSTAMP_TYPE_GETTIMEOFDAY);
        snd_pcm_sw_params(self->handle, swParams);

        return Py_None;
}

If I change SND_PCM_TSTAMP_TYPE_GETTIMEOFDAY to one of the monotonic types I see the expected change.

On the raspberry SND_PCM_TSTAMP_TYPE_GETTIMEOFDAY has no effect. Output resembles monotonic.

[perexg]

On the raspberry SND_PCM_TSTAMP_TYPE_GETTIMEOFDAY has no effect. Output resembles monotonic.

Does this python code work for you?

import time
print(time.time())

[RonaldAJ]

Yes, that is how the last part of 940 (7658, 695468285, 0) 1617704707.907379 samples, htimestamp, time.time() was obtained.

[RonaldAJ]

For my purposes the RPi can be assumed to be connected with an NTP server.

[RonaldAJ]

The Python function is on my pyalsaaudio fork on the phys_from_sound branch: https://github.com/soundappraisal/pyalsaaudio/tree/phys_from_sound

[RonaldAJ]

To add to the puzzle. On RPi:

(sa) pi@localhost:~/sa3am/pyalsaaudio $ python
Python 3.7.3 (default, Dec 20 2019, 18:57:59) 
[GCC 8.3.0] on linux
Type "help", "copyright", "credits" or "license" for more information.
>>> import time
>>> time.time()
1617715505.2663364
>>> time.clock_gettime(time.CLOCK_REALTIME)
1617715781.2435422
>>> time.clock_gettime(time.CLOCK_MONOTONIC_RAW)
18746.804572432
>>> time.clock_gettime(time.CLOCK_MONOTONIC)
18765.575212578

So it looks as if the realtime clock is available.

[perexg]

I want the seconds since the epoch.

On my VM this function can switch between the modes:

static PyObject *
alsapcm_enable_timestamp(alsapcm_t *self, PyObject *args)
{

        snd_pcm_sw_params_t* swParams;
        snd_pcm_sw_params_alloca( &swParams);

        snd_pcm_sw_params_current(self->handle, swParams);

        snd_pcm_sw_params_set_tstamp_mode(self->handle, swParams, SND_PCM_TSTAMP_ENABLE);
        snd_pcm_sw_params_set_tstamp_type(self->handle, swParams, SND_PCM_TSTAMP_TYPE_GETTIMEOFDAY);
        snd_pcm_sw_params(self->handle, swParams);

        return Py_None;
}

If I change SND_PCM_TSTAMP_TYPE_GETTIMEOFDAY to one of the monotonic types I see the expected change.

Do you really change the settings? I think that this snd_pcm_sw_params call returns an error code. I overlooked that you're using the dsnoop plugin where things are a bit different. By default the timestamp type is inherited from the hw plugin where the default is the monotonic timestamp type. Just add tstamp_type gettimeofday line to your dsnoop config: https://www.alsa-project.org/alsa-doc/alsa-lib/pcm_plugins.html .

[RonaldAJ]

 python recordtest.py -d plugsnoop:1,0 test.raw
ALSA lib pcm_plug.c:1286:(_snd_pcm_plug_open) Unknown field tstamp_type
Traceback (most recent call last):
  File "recordtest.py", line 54, in <module>
    periodsize=160, device=device)
alsaaudio.ALSAAudioError: Invalid argument [plugsnoop:1,0]

Maybe not for snoop devices? It is, however, entirely possible that I put it in the wrong place.

On the bright side: alsapcm_enable_timestamp does work with plughw on raspberry! I get correct timestamps with it and zeros without.

[perexg]

pcm.plugsnoop {
    type plug

    @args [ CARD DEV ]

    @args.CARD {
        type string
    }

    @args.DEV {
        type integer
    }

    slave.pcm {
           type dsnoop
           ipc_key 5678293
           ipc_gid audio
           ipc_perm 0660
           tstamp_type gettimeofday
           slave.pcm {
                 type hw
                 card $CARD
                 device $DEV
           }
    }
}

[perexg]

Or a simpler way (add this global config):

defaults.pcm.!tstamp_type gettimeofday

EDIT: Added ! to override the default config (but it seems that it's not necessary for the non-compound assignments).

[RonaldAJ]

defaults.pcm.tstamp_type gettimeofday is not picked up neither using the global setting or modifying the defnition in .asoundrc. The global setting also doesn't affect plughw. Both on Raspian and Ubuntu. And the alsapcm_enable_timestamp behavior seems to be consistent with this, except that that works for hwplug and hw.

So the distinction is indeed not between Raspbian and Ubuntu, but indeed between type dsnoop and type plug.

[perexg]

defaults.pcm.tstamp_type gettimeofday is not picked up neither using the global setting or modifying the defnition in .asoundrc.

Missed ! to override the variable. See above.

[RonaldAJ]

Alas, no effect. Also not after rebooting.

Should it be combined with a global enable flag?

[perexg]

The defaults.pcm.tstamp_type is used only for dsnoop/dshare/dmix plugins.

You may search the references in /usr/share/alsa config tree.

Raspian seems to have very old alsa-lib (1.1.8) where this settings is not supported:

Fedora:

$ grep tstamp_type /usr/share/alsa/alsa.conf
defaults.pcm.tstamp_type default

Raspbian (latest):

$ grep tstamp_type /usr/share/alsa/alsa.conf

So even my configuration proposal won't work there without the library upgrade.

[RonaldAJ]

Ah, then I'll have to move to another VM to test. That will be for a later moment.

For now I can manage with a working plughw and hw device. The snoop devices are actually from another usecase I like to pursue later again.

I'll add the following functions to my pyalsaaudio and create a pull request there: set_tstamp_mode set_tstamp_type asoundlib_version

and a set of constants:

/ PCM tstamp modes / PCM_TSTAMP_NONE PCM_TSTAMP_ENABLE

/ PCM tstamp types / PCM_TSTAMP_TYPE_GETTIMEOFDAY PCM_TSTAMP_TYPE_MONOTONIC PCM_TSTAMP_TYPE_MONOTONIC_RAW

I guess it would be good to have the getters for mode and type aswell.

Thanks sofar for considering my problems!

[RonaldAJ]

@perexg I wrote documentation with the new functions introduced with the pull request above. Could you glance at them to see if I haven't misinterpreted the information from the original functions? The changes can be found here: https://github.com/larsimmisch/pyalsaaudio/pull/100/commits/c8f3916337c3067f7ef2d909e6ef04b392007ac1

[perexg]

@perexg I wrote documentation with the new functions introduced with the pull request above. Could you glance at them to see if I haven't misinterpreted the information from the original functions? The changes can be found here: larsimmisch/pyalsaaudio@c8f3916

The text looks fine.

[RonaldAJ]

Thanks!