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

[Francis Deslauriers]

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