[REGRESSION] ALSA: firewire-lib: heavy digital distortion with Fireface 800

[REGRESSION] ALSA: firewire-lib: heavy digital distortion with Fireface 800

[edmund.raile]

Between the kernel releases 6.9.9 and 6.10.0, something changed that causes
heavy digital distortion on playback from at least ALSA and PipeWire.
The rhythm of the music is discernable in the output, so it isn't just
random noise.
It sounds a bit like bitcrushing, but not quite.
The generated overtones appear to be dependet on the sample rate.

I am sorry I can not be more specific, there are no kernel messages this time.

As Mr. Sakamoto recently committed all these changes to firewire he might
be able to identify the issue easily, which is why I'd like to ask him to
look into it.

Kind regards,
Edmund Raile.

#regzbot introduced: v6.9.9..v6.10

Re: [REGRESSION] ALSA: firewire-lib: heavy digital distortion with Fireface 800

[Takashi Sakamoto]

On Thu, Jul 18, 2024 at 12:29:48PM +0000, edmund.raile wrote:
> Between the kernel releases 6.9.9 and 6.10.0, something changed that causes
> heavy digital distortion on playback from at least ALSA and PipeWire.
> The rhythm of the music is discernable in the output, so it isn't just
> random noise.
> It sounds a bit like bitcrushing, but not quite.
> The generated overtones appear to be dependet on the sample rate.
> 
> I am sorry I can not be more specific, there are no kernel messages this time.
> 
> As Mr. Sakamoto recently committed all these changes to firewire he might
> be able to identify the issue easily, which is why I'd like to ask him to
> look into it.
> 
> Kind regards,
> Edmund Raile.
> 
> #regzbot introduced: v6.9.9..v6.10

Fixes included in:
* 6.11-rc2
* 6.10.4
* 6.6.45
* 6.1.104
* 5.15.165


Thanks

Takashi Sakamoto

[REGRESSION] ALSA: firewire-lib: heavy digital distortion with Fireface 800

[edmund.raile]

Bisection revealed that the bitcrushing distortion with RME FireFace 800
was caused by 1d717123bb1a7555
("ALSA: firewire-lib: Avoid -Wflex-array-member-not-at-end warning").

Reverting this commit yields restoration of clear audio output.
I will send in a patch reverting this commit for now, soonTM.

#regzbot introduced: 1d717123bb1a7555

Re: [REGRESSION] ALSA: firewire-lib: heavy digital distortion with Fireface 800

[Takashi Iwai]

On Thu, 25 Jul 2024 00:24:29 +0200,
edmund.raile wrote:
> 
> Bisection revealed that the bitcrushing distortion with RME FireFace 800
> was caused by 1d717123bb1a7555
> ("ALSA: firewire-lib: Avoid -Wflex-array-member-not-at-end warning").
> 
> Reverting this commit yields restoration of clear audio output.
> I will send in a patch reverting this commit for now, soonTM.
> 
> #regzbot introduced: 1d717123bb1a7555

While it's OK to have a quick revert, it'd be worth to investigate
further what broke there; the change is rather trivial, so it might be
something in the macro expansion or a use of flex array stuff.


thanks,

Takashi

Re: [REGRESSION] ALSA: firewire-lib: heavy digital distortion with Fireface 800

[Gustavo A. R. Silva]

Hi!

On 25/07/24 07:07, Takashi Iwai wrote:
> On Thu, 25 Jul 2024 00:24:29 +0200,
> edmund.raile wrote:
>>
>> Bisection revealed that the bitcrushing distortion with RME FireFace 800
>> was caused by 1d717123bb1a7555
>> ("ALSA: firewire-lib: Avoid -Wflex-array-member-not-at-end warning").
>>
>> Reverting this commit yields restoration of clear audio output.
>> I will send in a patch reverting this commit for now, soonTM.
>>
>> #regzbot introduced: 1d717123bb1a7555
> 
> While it's OK to have a quick revert, it'd be worth to investigate
> further what broke there; the change is rather trivial, so it might be
> something in the macro expansion or a use of flex array stuff.
> 

I wonder is there is any log that I can take a look at. That'd be really
helpful.

Thanks!
--
Gustavo

Re: [REGRESSION] ALSA: firewire-lib: heavy digital distortion with Fireface 800

[Takashi Sakamoto]

On Thu, Jul 25, 2024 at 08:08:14AM -0600, Gustavo A. R. Silva wrote:
> Hi!
> 
> On 25/07/24 07:07, Takashi Iwai wrote:
> > On Thu, 25 Jul 2024 00:24:29 +0200,
> > edmund.raile wrote:
> > > 
> > > Bisection revealed that the bitcrushing distortion with RME FireFace 800
> > > was caused by 1d717123bb1a7555
> > > ("ALSA: firewire-lib: Avoid -Wflex-array-member-not-at-end warning").
> > > 
> > > Reverting this commit yields restoration of clear audio output.
> > > I will send in a patch reverting this commit for now, soonTM.
> > > 
> > > #regzbot introduced: 1d717123bb1a7555
> > 
> > While it's OK to have a quick revert, it'd be worth to investigate
> > further what broke there; the change is rather trivial, so it might be
> > something in the macro expansion or a use of flex array stuff.
> > 
> 
> I wonder is there is any log that I can take a look at. That'd be really
> helpful.

The original designated initializer fills all of fields with 0.

The new designated initializer assigns CIP_HEADER_QUADLETS (=2) to
struct fw_iso_packet.header_length. It is wrong value in the case of
CIP_NO_HEADER. Additionally it is wrong value in another case since the
value of the field should be byte unit.

I'll post a patch soon.


Regards

Takashi Sakamoto

Re: [REGRESSION] ALSA: firewire-lib: heavy digital distortion with Fireface 800

[Gustavo A. R. Silva]

On 25/07/24 08:08, Gustavo A. R. Silva wrote:
> Hi!
> 
> On 25/07/24 07:07, Takashi Iwai wrote:
>> On Thu, 25 Jul 2024 00:24:29 +0200,
>> edmund.raile wrote:
>>>
>>> Bisection revealed that the bitcrushing distortion with RME FireFace 800
>>> was caused by 1d717123bb1a7555
>>> ("ALSA: firewire-lib: Avoid -Wflex-array-member-not-at-end warning").
>>>
>>> Reverting this commit yields restoration of clear audio output.
>>> I will send in a patch reverting this commit for now, soonTM.
>>>
>>> #regzbot introduced: 1d717123bb1a7555
>>
>> While it's OK to have a quick revert, it'd be worth to investigate
>> further what broke there; the change is rather trivial, so it might be
>> something in the macro expansion or a use of flex array stuff.
>>
> 
> I wonder is there is any log that I can take a look at. That'd be really
> helpful.

OK, I found a discrepancy in how the `header_length` field in the flexible
structure (a struct that contains a flexible-array member) below is used:

include/linux/firewire.h:
458 struct fw_iso_packet {
...
465         u32 header_length:8;    /* Length of immediate header           */
466                                 /* tx: Top of 1394 isoch. data_block    */
467         u32 header[] __counted_by(header_length);
468 };

Take a look at the following piece of code:

sound/firewire/amdtp-stream.c:
1164         if (!(s->flags & CIP_NO_HEADER))
1165                 pkt_header_length = IT_PKT_HEADER_SIZE_CIP;

In the code above `pkt_header_length` is set to `IT_PKT_HEADER_SIZE_CIP`, which based
on the following macros is 8 _bytes_:

sound/firewire/amdtp-stream.c:37:#define CIP_HEADER_QUADLETS	2
sound/firewire/amdtp-stream.c:58:#define CIP_HEADER_SIZE		(sizeof(__be32) * CIP_HEADER_QUADLETS)
sound/firewire/amdtp-stream.c:72:#define IT_PKT_HEADER_SIZE_CIP		CIP_HEADER_SIZE

Then we use the DEFINE_FLEX() macro, which internally sets `template->header_length`
to `CIP_HEADER_QUADLETS`, which based on the macros above, takes the value
of 2 _elements_. We set `header_length` because such variable is the _counter_
used during the `__counted_by()` annotation in `struct fw_iso_packet`. The
_counter_ is the variable that holds the number of _elements_ in the flex-array
member at some point at run-time[1].

So, we set the counter to `CIP_HEADER_QUADLETS` because that's the total number
of _elements_ allocated for the flexible-array member `header[]` by the DEFINE_FLEX()
macro.

1183                 DEFINE_FLEX(struct fw_iso_packet, template, header,
1184                             header_length, CIP_HEADER_QUADLETS);
1185                 bool sched_irq = false;

Then we call function `build_it_pkt_header()` and pass as arguments a pointer
to `template`, and `pkt_header_length`, which at this point might hold the
value of 8 _bytes_.

1187                 build_it_pkt_header(s, desc->cycle, template, pkt_header_length,
1188                                     desc->data_blocks, desc->data_block_counter,
1189                                     desc->syt, i, curr_cycle_time);

Then inside function `build_it_pkt_header()`, the _counter_ is updated
`params->header_length = header_length;`:

  680 static void build_it_pkt_header(struct amdtp_stream *s, unsigned int cycle,
  681                                 struct fw_iso_packet *params, unsigned int header_length,
...
  692         if (header_length > 0) {
  693                 cip_header = (__be32 *)params->header;
  694                 generate_cip_header(s, cip_header, data_block_counter, syt);
  695                 params->header_length = header_length;
  696         } else {

This causes `params->header_length == 8`; however, only enough space for 2
_elements_ was allocated for the flex array (via DEFINE_FLEX()).

So, regardless of how `pkt_header_length` is intended to be used in the rest of
the code inside `build_it_pkt_header()`, this last update to `params->header_length`
seems to be incorrect.

So, my question here is whether this `header_length` struct member was originally
intended to be used as a counter for the elements in the flex array or as size
variable to hold the total number of bytes in the array?

Based on the comment "Length of immediate header", I suppose `header_length` would
hold _elements_ not _bytes_.

Thanks
--
Gustavo

[1] https://embeddedor.com/blog/2024/06/18/how-to-use-the-new-counted_by-attribute-in-c-and-linux/

Re: [REGRESSION] ALSA: firewire-lib: heavy digital distortion with Fireface 800

[Takashi Iwai]

On Thu, 25 Jul 2024 17:11:31 +0200,
Gustavo A. R. Silva wrote:
> 
> 
> 
> On 25/07/24 08:08, Gustavo A. R. Silva wrote:
> > Hi!
> > 
> > On 25/07/24 07:07, Takashi Iwai wrote:
> >> On Thu, 25 Jul 2024 00:24:29 +0200,
> >> edmund.raile wrote:
> >>> 
> >>> Bisection revealed that the bitcrushing distortion with RME FireFace 800
> >>> was caused by 1d717123bb1a7555
> >>> ("ALSA: firewire-lib: Avoid -Wflex-array-member-not-at-end warning").
> >>> 
> >>> Reverting this commit yields restoration of clear audio output.
> >>> I will send in a patch reverting this commit for now, soonTM.
> >>> 
> >>> #regzbot introduced: 1d717123bb1a7555
> >> 
> >> While it's OK to have a quick revert, it'd be worth to investigate
> >> further what broke there; the change is rather trivial, so it might be
> >> something in the macro expansion or a use of flex array stuff.
> >> 
> > 
> > I wonder is there is any log that I can take a look at. That'd be really
> > helpful.
> 
> OK, I found a discrepancy in how the `header_length` field in the flexible
> structure (a struct that contains a flexible-array member) below is used:
> 
> include/linux/firewire.h:
> 458 struct fw_iso_packet {
> ...
> 465         u32 header_length:8;    /* Length of immediate header           */
> 466                                 /* tx: Top of 1394 isoch. data_block    */
> 467         u32 header[] __counted_by(header_length);
> 468 };
> 
> Take a look at the following piece of code:
> 
> sound/firewire/amdtp-stream.c:
> 1164         if (!(s->flags & CIP_NO_HEADER))
> 1165                 pkt_header_length = IT_PKT_HEADER_SIZE_CIP;
> 
> In the code above `pkt_header_length` is set to `IT_PKT_HEADER_SIZE_CIP`, which based
> on the following macros is 8 _bytes_:
> 
> sound/firewire/amdtp-stream.c:37:#define CIP_HEADER_QUADLETS	2
> sound/firewire/amdtp-stream.c:58:#define CIP_HEADER_SIZE		(sizeof(__be32) * CIP_HEADER_QUADLETS)
> sound/firewire/amdtp-stream.c:72:#define IT_PKT_HEADER_SIZE_CIP		CIP_HEADER_SIZE
> 
> Then we use the DEFINE_FLEX() macro, which internally sets `template->header_length`
> to `CIP_HEADER_QUADLETS`, which based on the macros above, takes the value
> of 2 _elements_. We set `header_length` because such variable is the _counter_
> used during the `__counted_by()` annotation in `struct fw_iso_packet`. The
> _counter_ is the variable that holds the number of _elements_ in the flex-array
> member at some point at run-time[1].
> 
> So, we set the counter to `CIP_HEADER_QUADLETS` because that's the total number
> of _elements_ allocated for the flexible-array member `header[]` by the DEFINE_FLEX()
> macro.
> 
> 1183                 DEFINE_FLEX(struct fw_iso_packet, template, header,
> 1184                             header_length, CIP_HEADER_QUADLETS);
> 1185                 bool sched_irq = false;
> 
> Then we call function `build_it_pkt_header()` and pass as arguments a pointer
> to `template`, and `pkt_header_length`, which at this point might hold the
> value of 8 _bytes_.
> 
> 1187                 build_it_pkt_header(s, desc->cycle, template, pkt_header_length,
> 1188                                     desc->data_blocks, desc->data_block_counter,
> 1189                                     desc->syt, i, curr_cycle_time);
> 
> Then inside function `build_it_pkt_header()`, the _counter_ is updated
> `params->header_length = header_length;`:
> 
>  680 static void build_it_pkt_header(struct amdtp_stream *s, unsigned int cycle,
>  681                                 struct fw_iso_packet *params, unsigned int header_length,
> ...
>  692         if (header_length > 0) {
>  693                 cip_header = (__be32 *)params->header;
>  694                 generate_cip_header(s, cip_header, data_block_counter, syt);
>  695                 params->header_length = header_length;
>  696         } else {
> 
> This causes `params->header_length == 8`; however, only enough space for 2
> _elements_ was allocated for the flex array (via DEFINE_FLEX()).
> 
> So, regardless of how `pkt_header_length` is intended to be used in the rest of
> the code inside `build_it_pkt_header()`, this last update to `params->header_length`
> seems to be incorrect.
> 
> So, my question here is whether this `header_length` struct member was originally
> intended to be used as a counter for the elements in the flex array or as size
> variable to hold the total number of bytes in the array?
> 
> Based on the comment "Length of immediate header", I suppose `header_length` would
> hold _elements_ not _bytes_.

Thanks, now I took a look over the whole picture, and I guess there
are two problems:

- The header_length should be in bytes, as far as I read the code in
  drivers/firwire/*.  So the assumption in the commit d3155742db89
  ("firewire: Annotate struct fw_iso_packet with __counted_by()") was
  already wrong, and it couldn't be annotated like that -- unless we
  fix up all users of header_length field.

- By the use of DEFINE_FLEX() in amdtp-stream.c, process_rx_packets()
  sets the header_length field to CIP_HEADER_QUADLETS (= 2) as
  default.  Meanwhile, build_it_pkt_header() doesn't touch
  header_length unless non-zero pkt_header_length is passed, supposing
  it being zero.  So this may lead to a bogus header_length, which is
  processed by the firewire core code wrongly.

The actual effect we see is likely the latter.  A simple fix would be
to use DEFINE_RAW_FLEX() instead of DEFINE_FLEX() like below.


thanks,

Takashi

-- 8< --
--- a/sound/firewire/amdtp-stream.c
+++ b/sound/firewire/amdtp-stream.c
@@ -1180,8 +1180,8 @@ static void process_rx_packets(struct fw_iso_context *context, u32 tstamp, size_
 		(void)fw_card_read_cycle_time(fw_parent_device(s->unit)->card, &curr_cycle_time);
 
 	for (i = 0; i < packets; ++i) {
-		DEFINE_FLEX(struct fw_iso_packet, template, header,
-			    header_length, CIP_HEADER_QUADLETS);
+		DEFINE_RAW_FLEX(struct fw_iso_packet, template, header,
+				CIP_HEADER_QUADLETS);
 		bool sched_irq = false;
 
 		build_it_pkt_header(s, desc->cycle, template, pkt_header_length,

Re: [REGRESSION] ALSA: firewire-lib: heavy digital distortion with Fireface 800

[Gustavo A. R. Silva]

On 25/07/24 09:38, Takashi Iwai wrote:
> On Thu, 25 Jul 2024 17:11:31 +0200,
> Gustavo A. R. Silva wrote:
>>
>>
>>
>> On 25/07/24 08:08, Gustavo A. R. Silva wrote:
>>> Hi!
>>>
>>> On 25/07/24 07:07, Takashi Iwai wrote:
>>>> On Thu, 25 Jul 2024 00:24:29 +0200,
>>>> edmund.raile wrote:
>>>>>
>>>>> Bisection revealed that the bitcrushing distortion with RME FireFace 800
>>>>> was caused by 1d717123bb1a7555
>>>>> ("ALSA: firewire-lib: Avoid -Wflex-array-member-not-at-end warning").
>>>>>
>>>>> Reverting this commit yields restoration of clear audio output.
>>>>> I will send in a patch reverting this commit for now, soonTM.
>>>>>
>>>>> #regzbot introduced: 1d717123bb1a7555
>>>>
>>>> While it's OK to have a quick revert, it'd be worth to investigate
>>>> further what broke there; the change is rather trivial, so it might be
>>>> something in the macro expansion or a use of flex array stuff.
>>>>
>>>
>>> I wonder is there is any log that I can take a look at. That'd be really
>>> helpful.
>>
>> OK, I found a discrepancy in how the `header_length` field in the flexible
>> structure (a struct that contains a flexible-array member) below is used:
>>
>> include/linux/firewire.h:
>> 458 struct fw_iso_packet {
>> ...
>> 465         u32 header_length:8;    /* Length of immediate header           */
>> 466                                 /* tx: Top of 1394 isoch. data_block    */
>> 467         u32 header[] __counted_by(header_length);
>> 468 };
>>
>> Take a look at the following piece of code:
>>
>> sound/firewire/amdtp-stream.c:
>> 1164         if (!(s->flags & CIP_NO_HEADER))
>> 1165                 pkt_header_length = IT_PKT_HEADER_SIZE_CIP;
>>
>> In the code above `pkt_header_length` is set to `IT_PKT_HEADER_SIZE_CIP`, which based
>> on the following macros is 8 _bytes_:
>>
>> sound/firewire/amdtp-stream.c:37:#define CIP_HEADER_QUADLETS	2
>> sound/firewire/amdtp-stream.c:58:#define CIP_HEADER_SIZE		(sizeof(__be32) * CIP_HEADER_QUADLETS)
>> sound/firewire/amdtp-stream.c:72:#define IT_PKT_HEADER_SIZE_CIP		CIP_HEADER_SIZE
>>
>> Then we use the DEFINE_FLEX() macro, which internally sets `template->header_length`
>> to `CIP_HEADER_QUADLETS`, which based on the macros above, takes the value
>> of 2 _elements_. We set `header_length` because such variable is the _counter_
>> used during the `__counted_by()` annotation in `struct fw_iso_packet`. The
>> _counter_ is the variable that holds the number of _elements_ in the flex-array
>> member at some point at run-time[1].
>>
>> So, we set the counter to `CIP_HEADER_QUADLETS` because that's the total number
>> of _elements_ allocated for the flexible-array member `header[]` by the DEFINE_FLEX()
>> macro.
>>
>> 1183                 DEFINE_FLEX(struct fw_iso_packet, template, header,
>> 1184                             header_length, CIP_HEADER_QUADLETS);
>> 1185                 bool sched_irq = false;
>>
>> Then we call function `build_it_pkt_header()` and pass as arguments a pointer
>> to `template`, and `pkt_header_length`, which at this point might hold the
>> value of 8 _bytes_.
>>
>> 1187                 build_it_pkt_header(s, desc->cycle, template, pkt_header_length,
>> 1188                                     desc->data_blocks, desc->data_block_counter,
>> 1189                                     desc->syt, i, curr_cycle_time);
>>
>> Then inside function `build_it_pkt_header()`, the _counter_ is updated
>> `params->header_length = header_length;`:
>>
>>   680 static void build_it_pkt_header(struct amdtp_stream *s, unsigned int cycle,
>>   681                                 struct fw_iso_packet *params, unsigned int header_length,
>> ...
>>   692         if (header_length > 0) {
>>   693                 cip_header = (__be32 *)params->header;
>>   694                 generate_cip_header(s, cip_header, data_block_counter, syt);
>>   695                 params->header_length = header_length;
>>   696         } else {
>>
>> This causes `params->header_length == 8`; however, only enough space for 2
>> _elements_ was allocated for the flex array (via DEFINE_FLEX()).
>>
>> So, regardless of how `pkt_header_length` is intended to be used in the rest of
>> the code inside `build_it_pkt_header()`, this last update to `params->header_length`
>> seems to be incorrect.
>>
>> So, my question here is whether this `header_length` struct member was originally
>> intended to be used as a counter for the elements in the flex array or as size
>> variable to hold the total number of bytes in the array?
>>
>> Based on the comment "Length of immediate header", I suppose `header_length` would
>> hold _elements_ not _bytes_.
> 
> Thanks, now I took a look over the whole picture, and I guess there
> are two problems:
> 
> - The header_length should be in bytes, as far as I read the code in
>    drivers/firwire/*.  So the assumption in the commit d3155742db89
>    ("firewire: Annotate struct fw_iso_packet with __counted_by()") was
>    already wrong, and it couldn't be annotated like that -- unless we
>    fix up all users of header_length field.

I see. In this case, the code comment should also be changed:

s/Length/Size

to prevent any further confusion, as Size is clearly for bytes.

> - By the use of DEFINE_FLEX() in amdtp-stream.c, process_rx_packets()
>    sets the header_length field to CIP_HEADER_QUADLETS (= 2) as
>    default.  Meanwhile, build_it_pkt_header() doesn't touch
>    header_length unless non-zero pkt_header_length is passed, supposing
>    it being zero.  So this may lead to a bogus header_length, which is
>    processed by the firewire core code wrongly.
> 
> The actual effect we see is likely the latter.  A simple fix would be
> to use DEFINE_RAW_FLEX() instead of DEFINE_FLEX() like below.

Yes, `DEFINE_RAW_FLEX()` is the way to go in this case, as long as the
following patch is also applied:

--- a/include/linux/firewire.h
+++ b/include/linux/firewire.h
@@ -462,9 +462,9 @@ struct fw_iso_packet {
                                 /* rx: Sync bit, wait for matching sy   */
         u32 tag:2;              /* tx: Tag in packet header             */
         u32 sy:4;               /* tx: Sy in packet header              */
-       u32 header_length:8;    /* Length of immediate header           */
+       u32 header_length:8;    /* Size of immediate header             */
                                 /* tx: Top of 1394 isoch. data_block    */
-       u32 header[] __counted_by(header_length);
+       u32 header[];
  };

Thanks
- Gustavo

> 
> 
> thanks,
> 
> Takashi
> 
> -- 8< --
> --- a/sound/firewire/amdtp-stream.c
> +++ b/sound/firewire/amdtp-stream.c
> @@ -1180,8 +1180,8 @@ static void process_rx_packets(struct fw_iso_context *context, u32 tstamp, size_
>   		(void)fw_card_read_cycle_time(fw_parent_device(s->unit)->card, &curr_cycle_time);
>   
>   	for (i = 0; i < packets; ++i) {
> -		DEFINE_FLEX(struct fw_iso_packet, template, header,
> -			    header_length, CIP_HEADER_QUADLETS);
> +		DEFINE_RAW_FLEX(struct fw_iso_packet, template, header,
> +				CIP_HEADER_QUADLETS);
>   		bool sched_irq = false;
>   
>   		build_it_pkt_header(s, desc->cycle, template, pkt_header_length,