Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Improve event formatting #411

Merged
merged 6 commits into from
Sep 26, 2024
Merged

Improve event formatting #411

merged 6 commits into from
Sep 26, 2024

Conversation

atenart
Copy link
Contributor

@atenart atenart commented Jul 3, 2024

Based on #385.

This introduces our own Formatter instead of directly using fmt::Formatter when constructing the event display result. The main advantage is an improved flexibility where formatting is not done at post-processing but directly while constructing the output. Event sub-sections and types can now decide to output multi-line data.

Copy link
Contributor

@amorenoz amorenoz left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

A couple of nits but otherwise, lgtm.

retis-events/src/display.rs Outdated Show resolved Hide resolved
retis-events/src/display.rs Show resolved Hide resolved
@amorenoz
Copy link
Contributor

amorenoz commented Sep 24, 2024

I found a possible corner case. I don't think it's related to this series but when I was testing it I happened to capture some drops on my wifi interface. These packets are probably some low level 802.11 frames so the skb fails to parse any metadata, everything is None except for packet.

Current main branch prints is as:
(replacing whitespaces with "·")


22465108813415·(0)·[irq/181-iwlwifi]·1675·[tp]·skb:kfree_skb·#146e90d4a667ffff8e8efdbff700·(skb·ffff8e8ee8afe200)
··

With this series, this event is printed as:

22465108813415·(0)·[irq/181-iwlwifi]·1675·[tp]·skb:kfree_skb·#146e90d4a667ffff8e8efdbff700·(skb·ffff8e8ee8afe200)
··


So, there are two extra lines at the end, not sure why but it seems related to this PR.

Also, the two spaces that are also present in main branch. I guess the issue is here:

          .try_for_each(|section| {
                write!(f, "{sep}")?;
                section.event_fmt(f, format)
            })?;

if a section writes 0 bytes we should not write "{sep}".

@atenart
Copy link
Contributor Author

atenart commented Sep 25, 2024

Thanks for the report and analysis. I however see a different root cause: sections are all expected to print an output (so far at least) but this is not true for the skb section if the protocol used is not supported. In such case the skb event is empty (except for the raw data) and nothing gets printed. This hides a bigger issue: the user has no idea what those packets are.

One option would be to display a warning if nothing was printed, eg "protocol not supported", but that leaves the user to wonder what this packet might be. Alternatively I think we can parse the eth header and at least provide this information (even if it was not requested) for packets we don't know how to handle. That will give a pointer to users about what this packet is.

diff --git a/retis/src/module/skb/bpf.rs b/retis/src/module/skb/bpf.rs
index 2978fbe0beb6..f1c23838335d 100644
--- a/retis/src/module/skb/bpf.rs
+++ b/retis/src/module/skb/bpf.rs
@@ -305,7 +305,9 @@ pub(super) fn unmarshal_packet(
                 unmarshal_l4(event, ip.get_next_header(), ip.payload())?;
             };
         }
-        _ => (),
+        // If we did not generate any data in the skb section, this means we do
+        // not support yet the protocol used. At least provide the ethertype.
+        _ => if event.eth.is_none() {
+            event.eth = Some(unmarshal_eth(&eth)?);
+        }
     }
 
     Ok(())

Which gives (for packets we don't know how to handle):

124073691061994 (0) [irq/178-iwlwifi] 1323 [tp] skb:kfree_skb #70d8283ef3f6ffff8c8f078dd680 (skb ffff8c91b1fda800) drop (reason NOT_SPECIFIED)
  if 4 (wlp82s0) 00:00:00:00:00:00 > 00:00:00:00:00:00 ethertype EAPOL (0x888e)

124075821479497 (0) [irq/188-iwlwifi] 1333 [tp] skb:kfree_skb #70d8a743b649ffff8c8f06082a80 (skb ffff8c916f8f3600) drop (reason mac80211_unusable/RX_DROP_U_REPLAY)
  67:00:00:a4:65:20 > 86:e4:00:e1:34:02 (0xc2c5)

An event better thing would be to only print the etype in such cases, but that makes things way more complex for not much value IMO.

I'll include the above by adding a commit (once #385 is merged as I'll have to rebase anyway).

There's no reason to enable verbose build while running the benchmarking
scripts: if there's a build issue one can run `make bench` manually.
Also make the build use more than a single CPU to speed up things.

Signed-off-by: Antoine Tenart <[email protected]>
Using `display()` is meant for external users. The event and its
sub-sections (& types) can directly access the internal `event_fmt`
helper.

Signed-off-by: Antoine Tenart <[email protected]>
Add our own formatter and an associated configuration struct. The
scope of a configuration object is expected to be within a single
`display()` call.

Using our own formatter provides better flexibility over how we print
our events and better performances.

Flexibility improvements:

- Indentation is handled at the formatter level. Thanks to this
  sub-sections and event types can now print multi-line events.

- Delimiter can be used while printing parts of an event.

Performances improvements:

- An internal buffer is used which helps reducing write calls as events
  usually have many write!() call in sequences.

- This buffer is also used to only apply the formatting logic (eg.
  indentation) once in a while, reducing the costs.

Before the series,

1M_time_single_single: 988812µs
1M_time_single_multi: 995100µs
1M_time_series_single: 1043459µs
1M_time_series_multi: 1039526µs

After the series,

1M_time_single_single: 842520µs
1M_time_single_multi: 877022µs
1M_time_series_single: 971998µs
1M_time_series_multi: 997519µs

Also the benchmark does not use stdout() which has a lock, so benefits
should be slightly better.

Signed-off-by: Antoine Tenart <[email protected]>
@atenart
Copy link
Contributor Author

atenart commented Sep 25, 2024

Added a commit for generating an skb.eth section on unknown packets, reworked very slightly the prefix generation in the formatter (to support utf8 chars) and rebased on top of main. But really, not a lot of changes since v n-1.

@amorenoz
Copy link
Contributor

As discussed offline, the issue I've raised is actually more complicated as for some reason a non-Ethernet packet is getting sent to retis (in particular it was a 802.11 frame). Let's tackle that in a different issue: #428.

@atenart atenart merged commit 2836f7e into main Sep 26, 2024
4 of 9 checks passed
@atenart atenart deleted the at/event-formatter branch September 26, 2024 15:33
@atenart atenart added this to the v1.5 milestone Oct 2, 2024
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

2 participants