Currently test_pcm_time() streams audio on each PCM with each
configuration for 4 seconds. This time can add up, and with the current
45 second kselftest timeout, some machines like mt8192-asurada-spherion
can't even run to completion. Lower the duration to 2 seconds to cut the
test duration in half, without reducing the test coverage.

Signed-off-by: Nícolas F. R. A. Prado <nfraprado@collabora.com>
---

 tools/testing/selftests/alsa/pcm-test.c | 2 +-
 1 file changed, 1 insertion(+), 1 deletion(-)

diff --git a/tools/testing/selftests/alsa/pcm-test.c b/tools/testing/selftests/alsa/pcm-test.c
index a2b6db33b513..de42fc7e9b53 100644
--- a/tools/testing/selftests/alsa/pcm-test.c
+++ b/tools/testing/selftests/alsa/pcm-test.c
@@ -258,7 +258,7 @@ static void test_pcm_time(struct pcm_data *data, enum test_class class,
 			  const char *test_name, snd_config_t *pcm_cfg)
 {
 	char name[64], key[128], msg[256];
-	const int duration_s = 4, margin_ms = 100;
+	const int duration_s = 2, margin_ms = 100;
 	const int duration_ms = duration_s * 1000;
 	const char *cs;
 	int i, err;
-- 
2.41.0

On Tue, Jun 20, 2023 at 06:08:26PM -0400, Nícolas F. R. A. Prado wrote:

> -	const int duration_s = 4, margin_ms = 100;
> +	const int duration_s = 2, margin_ms = 100;

This doesn't scale the margin with the duration which will affect the
sensitivity of the test to misclocking.  It should make it less
sensitive which is *probably* safer but at least worth noting.

We might also have issues with some of the lower sample rates, IIRC some
devices are constrained in ways that mean they want a minimum buffer
size which is harder to satisfy with very short playbacks and low sample
rates.

I don't know why Jaroslav picked the 4s number here.

On 21. 06. 23 15:08, Mark Brown wrote:
> On Tue, Jun 20, 2023 at 06:08:26PM -0400, Nícolas F. R. A. Prado wrote:
> 
>> -	const int duration_s = 4, margin_ms = 100;
>> +	const int duration_s = 2, margin_ms = 100;
> 
> This doesn't scale the margin with the duration which will affect the
> sensitivity of the test to misclocking.  It should make it less
> sensitive which is *probably* safer but at least worth noting.
> 
> We might also have issues with some of the lower sample rates, IIRC some
> devices are constrained in ways that mean they want a minimum buffer
> size which is harder to satisfy with very short playbacks and low sample
> rates.
> 
> I don't know why Jaroslav picked the 4s number here.

You basically replied yourself. The values (time + margin) were picked to do 
the DMA test for a reasonable time - based on my experience.

I think that the problem is somewhere else here. The overall test timeout 
should be calculated dynamically. All tests may be queried for the maximal 
expected interval based on the hardware/software capabilities. It's a bit 
pitfall to have a fixed time limit where the realtime tests depend on the 
number of devices.

					Jaroslav

-- 
Jaroslav Kysela <perex@perex.cz>
Linux Sound Maintainer; ALSA Project; Red Hat, Inc.

On Wed, Jun 21, 2023 at 04:08:47PM +0200, Jaroslav Kysela wrote:

> I think that the problem is somewhere else here. The overall test timeout
> should be calculated dynamically. All tests may be queried for the maximal
> expected interval based on the hardware/software capabilities. It's a bit
> pitfall to have a fixed time limit where the realtime tests depend on the
> number of devices.

I tend to agree here, unfortunately Shuah hasn't responded to queries
from Nícolas about this which I imagine is what inspired this patch.  We
also have problems with mixer-test on one of the Dialog CODECs with a
couple of 64k value controls and no cache only mode.

On Wed, Jun 21, 2023 at 03:39:12PM +0100, Mark Brown wrote:
> On Wed, Jun 21, 2023 at 04:08:47PM +0200, Jaroslav Kysela wrote:
> 
> > I think that the problem is somewhere else here. The overall test timeout
> > should be calculated dynamically. All tests may be queried for the maximal
> > expected interval based on the hardware/software capabilities. It's a bit
> > pitfall to have a fixed time limit where the realtime tests depend on the
> > number of devices.
> 
> I tend to agree here, unfortunately Shuah hasn't responded to queries
> from Nícolas about this which I imagine is what inspired this patch.  We
> also have problems with mixer-test on one of the Dialog CODECs with a
> couple of 64k value controls and no cache only mode.

Yes, exactly. I've tried increasing the timeout for this test to a larger fixed
value previously, and later asked for more information on how to deal with the
kselftest timeout. [1]

Since I didn't hear back, I thought this patch would be a way to at least
mitigate the issue for now, without limiting the test coverage, which was a
concern with having limited scopes for the test.

I've just noticed that in the mean time a way to override the timeout when
running kselftest has been introduced [2], so I suppose we could use that to
work around the timeout limitation in CI systems and be able to run through
completion on the different hardware at the lab. But I still believe, like you
do, that calculating the timeout at runtime based on the hardware would make
much more sense, though if there's such a desire to keep kselftests under the
45s mark, I'm not sure if it would be acceptable.

[1] https://lore.kernel.org/all/5302e70d-cb58-4e70-b44f-ff81b138a2e1@notapiano/
[2] https://git.kernel.org/pub/scm/linux/kernel/git/torvalds/linux.git/commit/?id=f6a01213e3f8

Thanks,
Nícolas

On Wed, 21 Jun 2023 18:03:22 +0200,
Nícolas F. R. A. Prado wrote:
> 
> On Wed, Jun 21, 2023 at 03:39:12PM +0100, Mark Brown wrote:
> > On Wed, Jun 21, 2023 at 04:08:47PM +0200, Jaroslav Kysela wrote:
> > 
> > > I think that the problem is somewhere else here. The overall test timeout
> > > should be calculated dynamically. All tests may be queried for the maximal
> > > expected interval based on the hardware/software capabilities. It's a bit
> > > pitfall to have a fixed time limit where the realtime tests depend on the
> > > number of devices.
> > 
> > I tend to agree here, unfortunately Shuah hasn't responded to queries
> > from Nícolas about this which I imagine is what inspired this patch.  We
> > also have problems with mixer-test on one of the Dialog CODECs with a
> > couple of 64k value controls and no cache only mode.
> 
> Yes, exactly. I've tried increasing the timeout for this test to a larger fixed
> value previously, and later asked for more information on how to deal with the
> kselftest timeout. [1]
> 
> Since I didn't hear back, I thought this patch would be a way to at least
> mitigate the issue for now, without limiting the test coverage, which was a
> concern with having limited scopes for the test.
> 
> I've just noticed that in the mean time a way to override the timeout when
> running kselftest has been introduced [2], so I suppose we could use that to
> work around the timeout limitation in CI systems and be able to run through
> completion on the different hardware at the lab. But I still believe, like you
> do, that calculating the timeout at runtime based on the hardware would make
> much more sense, though if there's such a desire to keep kselftests under the
> 45s mark, I'm not sure if it would be acceptable.
> 
> [1] https://lore.kernel.org/all/5302e70d-cb58-4e70-b44f-ff81b138a2e1@notapiano/
> [2] https://git.kernel.org/pub/scm/linux/kernel/git/torvalds/linux.git/commit/?id=f6a01213e3f8

So, we're back to square...  Unless anyone has a strong objection, I'm
inclined to take this as a workaround for 6.5 for now, as the merge
window deadline is coming.  We can improve things at the same time for
the future kernel, too.


thanks,

Takashi

On Wed, Jun 21, 2023 at 06:34:22PM +0200, Takashi Iwai wrote:

> So, we're back to square...  Unless anyone has a strong objection, I'm
> inclined to take this as a workaround for 6.5 for now, as the merge
> window deadline is coming.  We can improve things at the same time for
> the future kernel, too.

It feels like it might be good to let it cook for a bit longer before
going to Linus (eg, applying after the merge window) so we've more
chance to see what the impact is on other boards?

On Wed, 21 Jun 2023 19:08:27 +0200,
Mark Brown wrote:
> 
> On Wed, Jun 21, 2023 at 06:34:22PM +0200, Takashi Iwai wrote:
> 
> > So, we're back to square...  Unless anyone has a strong objection, I'm
> > inclined to take this as a workaround for 6.5 for now, as the merge
> > window deadline is coming.  We can improve things at the same time for
> > the future kernel, too.
> 
> It feels like it might be good to let it cook for a bit longer before
> going to Linus (eg, applying after the merge window) so we've more
> chance to see what the impact is on other boards?

I'm fine with that option, too.  Are most of selftests performed on
linux-next basis, or rather on Linus tree?


Takashi

On Wed, Jun 21, 2023 at 08:13:11PM +0200, Takashi Iwai wrote:
> Mark Brown wrote:

> > It feels like it might be good to let it cook for a bit longer before
> > going to Linus (eg, applying after the merge window) so we've more
> > chance to see what the impact is on other boards?

> I'm fine with that option, too.  Are most of selftests performed on
> linux-next basis, or rather on Linus tree?

For KernelCI we've got coverage on both.  I can also run stuff on the
boards I have in my lab on demand of course, but there's more coverage
in KernelCI.

On Wed, 21 Jun 2023 20:19:46 +0200,
Mark Brown wrote:
> 
> On Wed, Jun 21, 2023 at 08:13:11PM +0200, Takashi Iwai wrote:
> > Mark Brown wrote:
> 
> > > It feels like it might be good to let it cook for a bit longer before
> > > going to Linus (eg, applying after the merge window) so we've more
> > > chance to see what the impact is on other boards?
> 
> > I'm fine with that option, too.  Are most of selftests performed on
> > linux-next basis, or rather on Linus tree?
> 
> For KernelCI we've got coverage on both.  I can also run stuff on the
> boards I have in my lab on demand of course, but there's more coverage
> in KernelCI.

OK, now I applied those two patches to for-next branch (i.e. for 6.6
kernel).  Let's watch out.


thanks,

Takashi

On Mon, Jul 10, 2023 at 09:00:09AM +0200, Takashi Iwai wrote:
> Mark Brown wrote:

> > For KernelCI we've got coverage on both.  I can also run stuff on the
> > boards I have in my lab on demand of course, but there's more coverage
> > in KernelCI.

> OK, now I applied those two patches to for-next branch (i.e. for 6.6
> kernel).  Let's watch out.

I'm seeing failures on my i.MX6 boards, both the Q and DL have started
failing in the same way:

# default.time3.0.0.0.PLAYBACK - 44.1kHz stereo large periods
# default.time3.0.0.0.PLAYBACK hw_params.RW_INTERLEAVED.S16_LE.44100.2.16383.131064 sw_params.131064
not ok 10 default.time3.0.0.0.PLAYBACK
# time mismatch: expected 2000ms got 2229

reliably (the actual time drifts by a few ms).  The other boards I've
got coverage of seem fine, and I didn't check any broader CI yet.

On Thu, 13 Jul 2023 00:03:24 +0200,
Mark Brown wrote:
> 
> On Mon, Jul 10, 2023 at 09:00:09AM +0200, Takashi Iwai wrote:
> > Mark Brown wrote:
> 
> > > For KernelCI we've got coverage on both.  I can also run stuff on the
> > > boards I have in my lab on demand of course, but there's more coverage
> > > in KernelCI.
> 
> > OK, now I applied those two patches to for-next branch (i.e. for 6.6
> > kernel).  Let's watch out.
> 
> I'm seeing failures on my i.MX6 boards, both the Q and DL have started
> failing in the same way:
> 
> # default.time3.0.0.0.PLAYBACK - 44.1kHz stereo large periods
> # default.time3.0.0.0.PLAYBACK hw_params.RW_INTERLEAVED.S16_LE.44100.2.16383.131064 sw_params.131064
> not ok 10 default.time3.0.0.0.PLAYBACK
> # time mismatch: expected 2000ms got 2229
> 
> reliably (the actual time drifts by a few ms).  The other boards I've
> got coverage of seem fine, and I didn't check any broader CI yet.

Interesting.  With the current patch, we rather extended the margin in
proportion; formerly 4 sec +/- 0.1s, now 2 sec +/- 0.1s.  And it
exceeded out of sudden.

I guess this rather caught a problem of the driver itself.


thanks,

Takashi

On Thu, Jul 13, 2023 at 10:47:43AM +0200, Takashi Iwai wrote:
> Mark Brown wrote:

> > # default.time3.0.0.0.PLAYBACK - 44.1kHz stereo large periods
> > # default.time3.0.0.0.PLAYBACK hw_params.RW_INTERLEAVED.S16_LE.44100.2.16383.131064 sw_params.131064
> > not ok 10 default.time3.0.0.0.PLAYBACK
> > # time mismatch: expected 2000ms got 2229

> > reliably (the actual time drifts by a few ms).  The other boards I've
> > got coverage of seem fine, and I didn't check any broader CI yet.

> Interesting.  With the current patch, we rather extended the margin in
> proportion; formerly 4 sec +/- 0.1s, now 2 sec +/- 0.1s.  And it
> exceeded out of sudden.

Right.

> I guess this rather caught a problem of the driver itself.

Well, there's doubtless something driver/hardware related going on but
I'm not sure if it's a problem there or not.  The results from the 4s
runtime were:

# default.time3.0.0.0.PLAYBACK - 44.1kHz stereo large periods
# default.time3.0.0.0.PLAYBACK hw_params.RW_INTERLEAVED.S16_LE.44100.2.16383.131064 sw_params.131064
ok 10 default.time3.0.0.0.PLAYBACK

so the same buffer sizes and so on, and the period size is only 10ms
unless I miscalculated which should be quite a long way off from the
100ms of margin we give ourselves.  It does seem a little suspect that
it's the large periods test that's falling over though.