[lttng-dev] lttng-modules: block: invalid/unknown value for rwbs field

[lttng-dev] lttng-modules: block: invalid/unknown value for rwbs field

[Awais Belal via lttng-dev]

[-- Attachment #1.1: Type: text/plain, Size: 2393 bytes --]

Hi,

I am using lttng-modules 2.12.5 with a 5.4.93 kernel on an aarch64 
target. After creating a session I run

*lttng enable-event -k block**

to enable all the block_ kernel events but when I run babeltrace on the 
generated traces I get a handful of

*[warning] Unknown value 33 in enum.
...
...
*

with different values in place of 33. This does not happen with any 
other kernel event type

*BabelTrace Trace Viewer and Converter 1.5.8*

Also if I try to do a 'lttng view' on this session I can identify that 
this has something to do with the rwbs field as I get

*[14:03:42.649719750] (+0.000005750) imx8qxpmek block_bio_remap: { 
cpu_id = 3 }, { dev = 187695200, sector = 2460080, nr_sector = 8, rwbs = 
( <unknown> : container = 33 ), old_dev = 187695203, old_sector = 2105776 }
[14:03:42.649722125] (+0.000002375) imx8qxpmek block_bio_queue: { cpu_id 
= 3 }, { dev = 187695200, sector = 2460080, nr_sector = 8, rwbs = ( 
<unknown> : container = 33 ), tid = 428, comm = "jbd2/mmcblk1p3-" }
[14:03:42.649725000] (+0.000002875) imx8qxpmek block_bio_backmerge: { 
cpu_id = 3 }, { dev = 187695200, sector = 2460080, nr_sector = 8, rwbs = 
( <unknown> : container = 33 ), tid = 428, comm = "jbd2/mmcblk1p3-" }
...
...*

I believe <unknown> in the log points to a symptom? While for the 
events/container id that do not generate this warning I have in the same 
trace

*[14:03:44.697572375] (+2.036943500) imx8qxpmek block_bio_remap: { 
cpu_id = 0 }, { dev = 187695200, sector = 9382032, nr_sector = 8, rwbs = 
( "RWBS_FLAG_WRITE" : container = 1 ), old_dev = 187695206, old_sector = 
278672 }
[14:03:44.697584375] (+0.000012000) imx8qxpmek block_bio_queue: { cpu_id 
= 0 }, { dev = 187695200, sector = 9382032, nr_sector = 8, rwbs = ( 
"RWBS_FLAG_WRITE" : container = 1 ), tid = 1609, comm = "kworker/u8:0" }
[14:03:44.697604250] (+0.000019875) imx8qxpmek block_getrq: { cpu_id = 0 
}, { dev = 187695200, sector = 9382032, nr_sector = 8, rwbs = ( 
"RWBS_FLAG_WRITE" : container = 1 ), tid = 1609, comm = "kworker/u8:0" }*

The interesting thing to note with the working events is that all of 
them have "RWBS_FLAG_WRITE" and no other types from 
https://github.com/lttng/lttng-modules/blob/stable-2.12/instrumentation/events/lttng-module/block.h#L39 
which I would expect to see.

I am lost for hints as to what I need to look up... any help would be 
highly appreciated.

-- 
BR,
Awais


[-- Attachment #1.2: Type: text/html, Size: 3932 bytes --]

[-- Attachment #2: Type: text/plain, Size: 156 bytes --]

_______________________________________________
lttng-dev mailing list
lttng-dev@lists.lttng.org
https://lists.lttng.org/cgi-bin/mailman/listinfo/lttng-dev

Re: [lttng-dev] lttng-modules: block: invalid/unknown value for rwbs field

[Francis Deslauriers via lttng-dev]

Hi,

You see this "Unknown value 33" because there are no label with the 
value 33 in the "block_rq_type" enumeration.

More specifically, you see the value "33" because it's the result of two 
OR-ed bitflags (RWBS_FLAG_WRITE | RWBS_FLAG_SYNC).

The type of the "rwbs" field in the event was changed from integer to 
enum in that commit [0]. That change was made to allow trace readers to 
print OR-ed values more nicely have all they need to do it. In fact, 
babeltrace2 implements such feature and you can try it with the 
following command:

$ babeltrace2 -c sink.text.pretty -p print-enum-flags=true <path-to-trace>

And would print that field as such: ( "RWBS_FLAG_WRITE" | 
"RWBS_FLAG_SYNC" : container = 33 )

I believe this feature is turn off in Babeltrace2 by default to be 
backward compatible with Babeltrace 1.5.

It's important to note that before that change in the kernel tracer 
Babeltrace would have simply printed "rwbs = 33" so you're not losing 
any information here.

So, try it out with Babeltrace2, it should work as you expect.


Cheers,

Francis

[0] 
https://github.com/lttng/lttng-modules/commit/23634515e7271c8c8594ad87a6685232d4eff297


On 3/9/21 8:10 AM, Awais Belal via lttng-dev wrote:
>
> Hi,
>
> I am using lttng-modules 2.12.5 with a 5.4.93 kernel on an aarch64 
> target. After creating a session I run
>
> *lttng enable-event -k block**
>
> to enable all the block_ kernel events but when I run babeltrace on 
> the generated traces I get a handful of
>
> *[warning] Unknown value 33 in enum.
> ...
> ...
> *
>
> with different values in place of 33. This does not happen with any 
> other kernel event type
>
> *BabelTrace Trace Viewer and Converter 1.5.8*
>
> Also if I try to do a 'lttng view' on this session I can identify that 
> this has something to do with the rwbs field as I get
>
> *[14:03:42.649719750] (+0.000005750) imx8qxpmek block_bio_remap: { 
> cpu_id = 3 }, { dev = 187695200, sector = 2460080, nr_sector = 8, rwbs 
> = ( <unknown> : container = 33 ), old_dev = 187695203, old_sector = 
> 2105776 }
> [14:03:42.649722125] (+0.000002375) imx8qxpmek block_bio_queue: { 
> cpu_id = 3 }, { dev = 187695200, sector = 2460080, nr_sector = 8, rwbs 
> = ( <unknown> : container = 33 ), tid = 428, comm = "jbd2/mmcblk1p3-" }
> [14:03:42.649725000] (+0.000002875) imx8qxpmek block_bio_backmerge: { 
> cpu_id = 3 }, { dev = 187695200, sector = 2460080, nr_sector = 8, rwbs 
> = ( <unknown> : container = 33 ), tid = 428, comm = "jbd2/mmcblk1p3-" }
> ...
> ...*
>
> I believe <unknown> in the log points to a symptom? While for the 
> events/container id that do not generate this warning I have in the 
> same trace
>
> *[14:03:44.697572375] (+2.036943500) imx8qxpmek block_bio_remap: { 
> cpu_id = 0 }, { dev = 187695200, sector = 9382032, nr_sector = 8, rwbs 
> = ( "RWBS_FLAG_WRITE" : container = 1 ), old_dev = 187695206, 
> old_sector = 278672 }
> [14:03:44.697584375] (+0.000012000) imx8qxpmek block_bio_queue: { 
> cpu_id = 0 }, { dev = 187695200, sector = 9382032, nr_sector = 8, rwbs 
> = ( "RWBS_FLAG_WRITE" : container = 1 ), tid = 1609, comm = 
> "kworker/u8:0" }
> [14:03:44.697604250] (+0.000019875) imx8qxpmek block_getrq: { cpu_id = 
> 0 }, { dev = 187695200, sector = 9382032, nr_sector = 8, rwbs = ( 
> "RWBS_FLAG_WRITE" : container = 1 ), tid = 1609, comm = "kworker/u8:0" }*
>
> The interesting thing to note with the working events is that all of 
> them have "RWBS_FLAG_WRITE" and no other types from 
> https://github.com/lttng/lttng-modules/blob/stable-2.12/instrumentation/events/lttng-module/block.h#L39 
> which I would expect to see.
>
> I am lost for hints as to what I need to look up... any help would be 
> highly appreciated.
>
> -- 
> BR,
> Awais
>
> _______________________________________________
> lttng-dev mailing list
> lttng-dev@lists.lttng.org
> https://lists.lttng.org/cgi-bin/mailman/listinfo/lttng-dev
_______________________________________________
lttng-dev mailing list
lttng-dev@lists.lttng.org
https://lists.lttng.org/cgi-bin/mailman/listinfo/lttng-dev

Re: [lttng-dev] lttng-modules: block: invalid/unknown value for rwbs field

[Jérémie Galarneau via lttng-dev]

Just adding to Francis' explanation (and following up on Awais' questions on IRC):
the reason the `print-enum-flags` option is not the default is found here [1].

tl;dr: bitwise enumerations are not defined in CTF 1.8 and will likely be
part of CTF 2.0.

Also, this option is only available in master for the moment and will be part
of a future 2.1 release.

Thanks,
Jérémie

[1] https://review.lttng.org/c/babeltrace/+/3045/31#message-c7709b4431ad720962fe9b80880bc689f294c4a9

----- Original Message -----
From: "lttng-dev" <lttng-dev@lists.lttng.org>
To: "Awais Belal" <awais_belal@mentor.com>, "lttng-dev" <lttng-dev@lists.lttng.org>
Sent: Tuesday, March 9, 2021 9:34:09 AM
Subject: Re: [lttng-dev] lttng-modules: block: invalid/unknown value for rwbs field

Hi,

You see this "Unknown value 33" because there are no label with the 
value 33 in the "block_rq_type" enumeration.

More specifically, you see the value "33" because it's the result of two 
OR-ed bitflags (RWBS_FLAG_WRITE | RWBS_FLAG_SYNC).

The type of the "rwbs" field in the event was changed from integer to 
enum in that commit [0]. That change was made to allow trace readers to 
print OR-ed values more nicely have all they need to do it. In fact, 
babeltrace2 implements such feature and you can try it with the 
following command:

$ babeltrace2 -c sink.text.pretty -p print-enum-flags=true <path-to-trace>

And would print that field as such: ( "RWBS_FLAG_WRITE" | 
"RWBS_FLAG_SYNC" : container = 33 )

I believe this feature is turn off in Babeltrace2 by default to be 
backward compatible with Babeltrace 1.5.

It's important to note that before that change in the kernel tracer 
Babeltrace would have simply printed "rwbs = 33" so you're not losing 
any information here.

So, try it out with Babeltrace2, it should work as you expect.


Cheers,

Francis

[0] 
https://github.com/lttng/lttng-modules/commit/23634515e7271c8c8594ad87a6685232d4eff297


On 3/9/21 8:10 AM, Awais Belal via lttng-dev wrote:
>
> Hi,
>
> I am using lttng-modules 2.12.5 with a 5.4.93 kernel on an aarch64 
> target. After creating a session I run
>
> *lttng enable-event -k block**
>
> to enable all the block_ kernel events but when I run babeltrace on 
> the generated traces I get a handful of
>
> *[warning] Unknown value 33 in enum.
> ...
> ...
> *
>
> with different values in place of 33. This does not happen with any 
> other kernel event type
>
> *BabelTrace Trace Viewer and Converter 1.5.8*
>
> Also if I try to do a 'lttng view' on this session I can identify that 
> this has something to do with the rwbs field as I get
>
> *[14:03:42.649719750] (+0.000005750) imx8qxpmek block_bio_remap: { 
> cpu_id = 3 }, { dev = 187695200, sector = 2460080, nr_sector = 8, rwbs 
> = ( <unknown> : container = 33 ), old_dev = 187695203, old_sector = 
> 2105776 }
> [14:03:42.649722125] (+0.000002375) imx8qxpmek block_bio_queue: { 
> cpu_id = 3 }, { dev = 187695200, sector = 2460080, nr_sector = 8, rwbs 
> = ( <unknown> : container = 33 ), tid = 428, comm = "jbd2/mmcblk1p3-" }
> [14:03:42.649725000] (+0.000002875) imx8qxpmek block_bio_backmerge: { 
> cpu_id = 3 }, { dev = 187695200, sector = 2460080, nr_sector = 8, rwbs 
> = ( <unknown> : container = 33 ), tid = 428, comm = "jbd2/mmcblk1p3-" }
> ...
> ...*
>
> I believe <unknown> in the log points to a symptom? While for the 
> events/container id that do not generate this warning I have in the 
> same trace
>
> *[14:03:44.697572375] (+2.036943500) imx8qxpmek block_bio_remap: { 
> cpu_id = 0 }, { dev = 187695200, sector = 9382032, nr_sector = 8, rwbs 
> = ( "RWBS_FLAG_WRITE" : container = 1 ), old_dev = 187695206, 
> old_sector = 278672 }
> [14:03:44.697584375] (+0.000012000) imx8qxpmek block_bio_queue: { 
> cpu_id = 0 }, { dev = 187695200, sector = 9382032, nr_sector = 8, rwbs 
> = ( "RWBS_FLAG_WRITE" : container = 1 ), tid = 1609, comm = 
> "kworker/u8:0" }
> [14:03:44.697604250] (+0.000019875) imx8qxpmek block_getrq: { cpu_id = 
> 0 }, { dev = 187695200, sector = 9382032, nr_sector = 8, rwbs = ( 
> "RWBS_FLAG_WRITE" : container = 1 ), tid = 1609, comm = "kworker/u8:0" }*
>
> The interesting thing to note with the working events is that all of 
> them have "RWBS_FLAG_WRITE" and no other types from 
> https://github.com/lttng/lttng-modules/blob/stable-2.12/instrumentation/events/lttng-module/block.h#L39 
> which I would expect to see.
>
> I am lost for hints as to what I need to look up... any help would be 
> highly appreciated.
>
> -- 
> BR,
> Awais
>
> _______________________________________________
> lttng-dev mailing list
> lttng-dev@lists.lttng.org
> https://lists.lttng.org/cgi-bin/mailman/listinfo/lttng-dev
_______________________________________________
lttng-dev mailing list
lttng-dev@lists.lttng.org
https://lists.lttng.org/cgi-bin/mailman/listinfo/lttng-dev
_______________________________________________
lttng-dev mailing list
lttng-dev@lists.lttng.org
https://lists.lttng.org/cgi-bin/mailman/listinfo/lttng-dev

Re: [lttng-dev] lttng-modules: block: invalid/unknown value for rwbs field

[Awais Belal via lttng-dev]

> So, try it out with Babeltrace2, it should work as you expect.
Thanks a lot guys, bt2 works as expected.

BR,
Awais

On 09/03/2021 19:49, Jérémie Galarneau wrote:
> Just adding to Francis' explanation (and following up on Awais' questions on IRC):
> the reason the `print-enum-flags` option is not the default is found here [1].
>
> tl;dr: bitwise enumerations are not defined in CTF 1.8 and will likely be
> part of CTF 2.0.
>
> Also, this option is only available in master for the moment and will be part
> of a future 2.1 release.
>
> Thanks,
> Jérémie
>
> [1] https://review.lttng.org/c/babeltrace/+/3045/31#message-c7709b4431ad720962fe9b80880bc689f294c4a9
>
> ----- Original Message -----
> From: "lttng-dev" <lttng-dev@lists.lttng.org>
> To: "Awais Belal" <awais_belal@mentor.com>, "lttng-dev" <lttng-dev@lists.lttng.org>
> Sent: Tuesday, March 9, 2021 9:34:09 AM
> Subject: Re: [lttng-dev] lttng-modules: block: invalid/unknown value for rwbs field
>
> Hi,
>
> You see this "Unknown value 33" because there are no label with the
> value 33 in the "block_rq_type" enumeration.
>
> More specifically, you see the value "33" because it's the result of two
> OR-ed bitflags (RWBS_FLAG_WRITE | RWBS_FLAG_SYNC).
>
> The type of the "rwbs" field in the event was changed from integer to
> enum in that commit [0]. That change was made to allow trace readers to
> print OR-ed values more nicely have all they need to do it. In fact,
> babeltrace2 implements such feature and you can try it with the
> following command:
>
> $ babeltrace2 -c sink.text.pretty -p print-enum-flags=true <path-to-trace>
>
> And would print that field as such: ( "RWBS_FLAG_WRITE" |
> "RWBS_FLAG_SYNC" : container = 33 )
>
> I believe this feature is turn off in Babeltrace2 by default to be
> backward compatible with Babeltrace 1.5.
>
> It's important to note that before that change in the kernel tracer
> Babeltrace would have simply printed "rwbs = 33" so you're not losing
> any information here.
>
> So, try it out with Babeltrace2, it should work as you expect.
>
>
> Cheers,
>
> Francis
>
> [0]
> https://github.com/lttng/lttng-modules/commit/23634515e7271c8c8594ad87a6685232d4eff297
>
>
> On 3/9/21 8:10 AM, Awais Belal via lttng-dev wrote:
>> Hi,
>>
>> I am using lttng-modules 2.12.5 with a 5.4.93 kernel on an aarch64
>> target. After creating a session I run
>>
>> *lttng enable-event -k block**
>>
>> to enable all the block_ kernel events but when I run babeltrace on
>> the generated traces I get a handful of
>>
>> *[warning] Unknown value 33 in enum.
>> ...
>> ...
>> *
>>
>> with different values in place of 33. This does not happen with any
>> other kernel event type
>>
>> *BabelTrace Trace Viewer and Converter 1.5.8*
>>
>> Also if I try to do a 'lttng view' on this session I can identify that
>> this has something to do with the rwbs field as I get
>>
>> *[14:03:42.649719750] (+0.000005750) imx8qxpmek block_bio_remap: {
>> cpu_id = 3 }, { dev = 187695200, sector = 2460080, nr_sector = 8, rwbs
>> = ( <unknown> : container = 33 ), old_dev = 187695203, old_sector =
>> 2105776 }
>> [14:03:42.649722125] (+0.000002375) imx8qxpmek block_bio_queue: {
>> cpu_id = 3 }, { dev = 187695200, sector = 2460080, nr_sector = 8, rwbs
>> = ( <unknown> : container = 33 ), tid = 428, comm = "jbd2/mmcblk1p3-" }
>> [14:03:42.649725000] (+0.000002875) imx8qxpmek block_bio_backmerge: {
>> cpu_id = 3 }, { dev = 187695200, sector = 2460080, nr_sector = 8, rwbs
>> = ( <unknown> : container = 33 ), tid = 428, comm = "jbd2/mmcblk1p3-" }
>> ...
>> ...*
>>
>> I believe <unknown> in the log points to a symptom? While for the
>> events/container id that do not generate this warning I have in the
>> same trace
>>
>> *[14:03:44.697572375] (+2.036943500) imx8qxpmek block_bio_remap: {
>> cpu_id = 0 }, { dev = 187695200, sector = 9382032, nr_sector = 8, rwbs
>> = ( "RWBS_FLAG_WRITE" : container = 1 ), old_dev = 187695206,
>> old_sector = 278672 }
>> [14:03:44.697584375] (+0.000012000) imx8qxpmek block_bio_queue: {
>> cpu_id = 0 }, { dev = 187695200, sector = 9382032, nr_sector = 8, rwbs
>> = ( "RWBS_FLAG_WRITE" : container = 1 ), tid = 1609, comm =
>> "kworker/u8:0" }
>> [14:03:44.697604250] (+0.000019875) imx8qxpmek block_getrq: { cpu_id =
>> 0 }, { dev = 187695200, sector = 9382032, nr_sector = 8, rwbs = (
>> "RWBS_FLAG_WRITE" : container = 1 ), tid = 1609, comm = "kworker/u8:0" }*
>>
>> The interesting thing to note with the working events is that all of
>> them have "RWBS_FLAG_WRITE" and no other types from
>> https://github.com/lttng/lttng-modules/blob/stable-2.12/instrumentation/events/lttng-module/block.h#L39
>> which I would expect to see.
>>
>> I am lost for hints as to what I need to look up... any help would be
>> highly appreciated.
>>
>> -- 
>> BR,
>> Awais
>>
>> _______________________________________________
>> lttng-dev mailing list
>> lttng-dev@lists.lttng.org
>> https://lists.lttng.org/cgi-bin/mailman/listinfo/lttng-dev
> _______________________________________________
> lttng-dev mailing list
> lttng-dev@lists.lttng.org
> https://lists.lttng.org/cgi-bin/mailman/listinfo/lttng-dev
_______________________________________________
lttng-dev mailing list
lttng-dev@lists.lttng.org
https://lists.lttng.org/cgi-bin/mailman/listinfo/lttng-dev