[SKIP SOF-TEST] capture-test: Add buffer size control & verbose logging

[andyross]

Recent SOF drivers have started populating the buffer size of ALSA hw_params structs with values that produce an -EINVAL if you try to set them (unclear to me if this is a bug or not).

Regardless, the capture test wants control over that, so add it. Also hook the ALSA hw_params dump code (for debugging issues like this) and hide it under a "--verbose" flag.

[marc-hb]

No problem with the code but could you please fix some of the pylint warnings and silence the others with the corresponding meta-comment?

https://github.com/thesofproject/sof-test/actions/runs/9572893341/job/26393223942?pr=1207

[andyross]

Adjusted, but FWIW: I just had this fight in Zephyr and lost there too. Pylint as it exists today is too dumb to be trying to enforce the recommendations it's giving (c.f. demanding the "with" be used with open() always, even in expressions that don't save the resulting filehandle) and relying on it is basically demanding we write in some kind of weird subset language that (1) isn't actually python, (2) isn't defined anywhere and (3) isn't stable over time as we continue chasing new warnings in perpetuity.

Language definition is for language standards writers[1], not ad-hoc "checker" tool developers.

[1] Who I don't particularly trust either, FWIW (c.f. Rust's habit of introducing and then deprecating novel and non-trivial idioms, and its generally horrifying march into complexity). Though I trust them a lot more.

[marc-hb]

You missed one sorry:

tools/capture-test.py:121:14: W1309: Using an f-string that does not have any interpolated variables (f-string-without-interpolation)

I think this one is less debatable.

[marc-hb]

Adjusted, but FWIW: I just had this fight in Zephyr and lost there too.

Yes, and you also mentioned it in:

• tools: Add a new script for firmware boot stress testing #1180 (comment)

Care to share a link to the Zephyr discussion? So we don't repeat it too much.

This is a bit off-topic here but since this PR is otherwise a no-brainer, I have no problem "hi-jacking" it for a more generic discussion about with. I hope you don't either - hey, you started it :-)

Pylint as it exists today is too dumb to be trying to enforce the recommendations it's giving (c.f. demanding the "with" be used with open() always, even in expressions that don't save the resulting filehandle)

I googled this for 2 minutes and this is what I found, please correct me:

• Explicit closure with with avoids any buffering issue
• Python will garbage-collect the filehandle and close the file at a random point in the future! Closing files at a random point in time: is this really what people want? Maybe it's OK in this particular case[*], but in general?

[*] which is why pylint warnings can easily be silenced.

relying on it is basically demanding we write in some kind of weird subset language that (1) isn't actually python, (2) isn't defined anywhere

Are you still referring to pylint? I found it pretty well documented. Just like any good linter, it saves reviewers a MASSIVE amount of time because it avoids turning every PR into a personalized training session. Instead, submitters can just google the error message.

(3) isn't stable over time as we continue chasing new warnings in perpetuity.

I agree this is a problem sometimes and I have run into it but there is a relatively simple workaround: selectively turn off some warnings. pylint is very flexible there (per-file, per-project or only in one spot) and I specifically offered that option above.

Just like any other linter, pylint isn't always right and selectively turning off some warnings is also the solution there.

At the end of the day, using a linter is an engineering trade-off like many others. From a reviewer perspective, pylint is a very good trade-off because it saves a LOT more time than it costs. We all know reviewers are much more of a bottleneck than submitters in every single project. Probably because everyone wants quality but no one wants to pay for it. OK, too much of a digression now.

[andyross]

Fixed. Also note I snuck in an extra patch with another new feature.

[marc-hb]

I don't care in this particular case but I'd really like to get nearer to the bottom of this with discussion some day.

[marc-hb]

  assert len(opts.capmap) == opts.capchan

(never silently discard user input)

[andyross]

That's intentional. The specific device that needs this has a 4-channel PDM DMIC device with only two connected microphones (on different inputs on different boards, even) and needs to be compared against 2-channel PCM stream. The default handling is two channels for all streams, which seems reasonable.

[marc-hb]

I think you missed my point, which was only about "input validation". What happens if the user screws up and opt.capchan and opt.capmap are inconsistent with each other? More specifically, what happens to spurious/extra digits in opts.capmap? Whatever happens, it should never silently discard (part of) the user input. At the very least a [log.]warning. It's also a useful statement for the code reader (it would have helped at least me for sure).

[marc-hb]

Please don't re-use i again inside for i, that really threw me off! How about c or even better: chan?

[marc-hb]

Re-using the same name frame over and over does not help. The comments save the day but a little bit more imagination would not hurt... At least a plural?

Suggested change

	frame = struct.unpack(capfmt, buf[i:i+capsz]) # Decode
	frames = struct.unpack(capfmt, buf[idx:idx+sample_bytes]) # Decode

It would help for capsz and i's names to reflect that they are byte numbers.

[marc-hb]

Recent SOF drivers have started populating the buffer size of ALSA
hw_params structs with values that produce an -EINVAL if you try to
set them (unclear to me if this is a bug or not).

Please file a new issue either way so this can be discussed somewhere.

[andyross]

Updated. FWIW, about with, I had to do some research:

It turns out that I'm right about the ref counted allocation, if you strace this test script under python3, you'll see that every time the opened file handle gets dereferenced it's closed synchronously, before the next one is opened:

#!/usr/bin/env python3
import re

def readfile(f):
    return open(f, "rb").read()

pid = None

while True:
    stat = re.split(b' +', readfile("/proc/self/stat"))
    if pid:
        assert stat[0] == pid
    pid = stat[0]

But not under pypy! PyPy uses a true GC (it's just Boehm I think), and that won't clean up synchronously. You'll see the script run through its 1024 (or whatever the sysctl limit is) file descriptors and then fail on the next open.

Neither behavior is really specified, but since there's an interpreter out there that behaves the way the warning assumes, you're right and I'm wrong and I've updated the code.

(FWIW: that's probably one of the big reasons why PyPy has seem so little uptake in practice: tha'ts just not compatible! It's VERY easy to write code to trip over this kind of allocation assumption, and while you can blame user code if you want, no one is going to use your interpreter if it doesn't actually work in practice.)

[marc-hb]

Thanks for actually testing with! Very interesting and much appreciated.

One of the reasons of Python's success is IMHO the official documentation regularly hitting the sweet spot between user-friendliness and rigour/formality.

So, if the official documentation does not promise something then not relying on it is wiser more often than not. Especially when it does not cost much.

[marc-hb]

I know you will likely reply "overkill!" but this really smells like a missed import logging opportunity. People often overstate the complexity of Python's built-in logging, for a counter example see how little code logging required in recent commit 5419b42

Also, something resistant to change something :-D

[andyross]

Logging puts ugly prefix nonsense on the output lines, which IMHO is exactly what you don't want for human readable --verbose output. For a running system with multiple levels and the expectation of an engineer pouring through logs to intuit state? Sure. Here, for a --verbose flag? That's just not the way unix tools are expected to work.

[marc-hb]

Logging puts ugly prefix nonsense on the output lines

No, it does not. As seen in 5419b42

ipython3

import logging
logging.basicConfig(level=logging.INFO, format="%(message)s")
logging.info("foo")

foo # no prefix!

And that's all it takes.

Here, for a --verbose flag?

Python is a high level language. This means complicated things are possible, but simple things are easy: it's not because logging has 5 levels that you have to use them. You can just use two: verbose and not. Same for prefixes, multiple loggers and what not: they can be completely ignored.

What logging gives even when not using any complex/fancy feature:

• the code is not littered with if opt.verbose conditionals and indentation
• best flexibility to change or add extra levels temporarily for debugging purposes with single-line changes and no wrangling with if opt.verbose conditionals and indentation.

Don't get me wrong: I do NOT think this PR should be blocked on switching to logging. I only want to thank you for confirming that logging's complexity is generally overstated and misunderstood :-)

Maybe its documentation is missing the example above...

[marc-hb]

I think you missed my point, which was only about "input validation". What happens if the user screws up and opt.capchan and opt.capmap are inconsistent with each other? More specifically, what happens to spurious/extra digits in opts.capmap? Whatever happens, it should never silently discard (part of) the user input. At the very least a [log.]warning. It's also a useful statement for the code reader (it would have helped at least me for sure).

[andyross]

What happens if the user screws up and opt.capchan and opt.capmap are inconsistent with each other?

They're not required to be consistent. Normal operation on the MTL board in front of me has "--capchan 4 --capmap 23"

[marc-hb]

They're not required to be consistent. Normal operation on the MTL board in front of me has "--capchan 4 --capmap 23"

Thanks to this example I think I finally understood this new feature. It really confused me at first, even after reading the code I was still not making sense of it sorry.

Would the following --help changes make sense? If correct, they would have saved me a huge amount of time.

    ap.add_argument("--capchan", type=int,
                      help="Total number of capture channels available in the hardware (if different from output)")
    ap.add_argument("--capbits", type=int, default=16, help="Capture sample bits (16 or 32)")
    ap.add_argument("--capmap", type=str, default="01",
                    help="Map of capture channels in actual use (as string, e.g. '23' to select 3rd/4th elems)")

My key misunderstanding was about capchan: I assumed it was user input. I didn't understand the purpose is to fix the script's inability to discover the hardware.

[andyross]

My key misunderstanding was about capchan: I assumed it was user input. I didn't understand the purpose is to fix the script's inability to discover the hardware.

It's actually just the way ALSA works; arecord has exactly the same behavior. You have to specify the stream metadata correctly for the underlying driver or you get a -EINVAL back from the set_hw_params() ioctl with no other feedback. In theory the hw_params are supposed to be populated with working values/ranges, but in practice it seems like there's no code (at least none I can find) in the SOF kernel driver to do that, and all the ALSA code I can find in the wild just sets it all by fiat (or just assumes stereo s16le @ 48kHz) and puts the details in a configuration file somewhere.

[marc-hb]

It's actually just the way ALSA works; arecord has exactly the same behavior.

Good but not a reason to hold back on a slightly more explicit and barely longer --help?