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

[Awais Belal]

> 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 at lists.lttng.org>
> To: "Awais Belal" <awais_belal at mentor.com>, "lttng-dev" <lttng-dev at 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 at lists.lttng.org
>> https://lists.lttng.org/cgi-bin/mailman/listinfo/lttng-dev
> _______________________________________________
> lttng-dev mailing list
> lttng-dev at lists.lttng.org
> https://lists.lttng.org/cgi-bin/mailman/listinfo/lttng-dev