Merge pull request #729 from aya-rs/logs-inline-always

log: annotate logging functions inlining

aya-log-common/src/lib.rs

@@ -1,6 +1,6 @@
 #![no_std]
 
-use core::{mem, num, ptr};
+use core::num;
 
 use num_enum::IntoPrimitive;
 
@@ -86,7 +86,7 @@ pub trait UpperMacFormatter {}
 impl UpperMacFormatter for [u8; 6] {}
 
 #[repr(u8)]
-#[derive(Copy, Clone, Debug)]
+#[derive(Copy, Clone, Debug, IntoPrimitive)]
 pub enum RecordField {
     Target = 1,
     Level,
@@ -99,7 +99,7 @@ pub enum RecordField {
 /// Types which are supported by aya-log and can be safely sent from eBPF
 /// programs to userspace.
 #[repr(u8)]
-#[derive(Copy, Clone, Debug)]
+#[derive(Copy, Clone, Debug, IntoPrimitive)]
 pub enum Argument {
     DisplayHint,
 
@@ -147,53 +147,28 @@ pub enum DisplayHint {
     UpperMac,
 }
 
-struct TagLenValue<T, V> {
+// Must be inlined, else the BPF backend emits:
-    pub tag: T,
+//
-    pub value: V,
+// llvm: <unknown>:0:0: in function _ZN14aya_log_common5write17hc9ed05433e23a663E { i64, i64 } (i8, ptr, i64, ptr, i64): only integer returns supported
-}
+#[inline(always)]
-
+pub(crate) fn write(tag: u8, value: &[u8], buf: &mut [u8]) -> Result<usize, ()> {
-impl<T, V> TagLenValue<T, V>
+    let wire_len: LogValueLength = value
-where
+        .len()
-    V: IntoIterator<Item = u8>,
+        .try_into()
-    <V as IntoIterator>::IntoIter: ExactSizeIterator,
+        .map_err(|num::TryFromIntError { .. }| ())?;
-{
+    let mut size = 0;
-    pub(crate) fn write(self, mut buf: &mut [u8]) -> Result<usize, ()> {
+    macro_rules! copy_from_slice {
-        // Break the abstraction to please the verifier.
+        ($value:expr) => {{
-        if buf.len() > LOG_BUF_CAPACITY {
+            let buf = buf.get_mut(size..).ok_or(())?;
-            buf = &mut buf[..LOG_BUF_CAPACITY];
+            let buf = buf.get_mut(..$value.len()).ok_or(())?;
-        }
+            buf.copy_from_slice($value);
-        let Self { tag, value } = self;
+            size += $value.len();
-        let value = value.into_iter();
+        }};
-        let len = value.len();
-        let wire_len: LogValueLength = value
-            .len()
-            .try_into()
-            .map_err(|num::TryFromIntError { .. }| ())?;
-        let size = mem::size_of_val(&tag) + mem::size_of_val(&wire_len) + len;
-        if size > buf.len() {
-            return Err(());
-        }
-
-        let tag_size = mem::size_of_val(&tag);
-        unsafe { ptr::write_unaligned(buf.as_mut_ptr() as *mut _, tag) };
-        buf = &mut buf[tag_size..];
-
-        unsafe { ptr::write_unaligned(buf.as_mut_ptr() as *mut _, wire_len) };
-        buf = &mut buf[mem::size_of_val(&wire_len)..];
-
-        buf.iter_mut().zip(value).for_each(|(dst, src)| {
-            *dst = src;
-        });
-
-        Ok(size)
-    }
-}
-
-impl<T, V> TagLenValue<T, V> {
-    #[inline(always)]
-    pub(crate) fn new(tag: T, value: V) -> TagLenValue<T, V> {
-        TagLenValue { tag, value }
     }
+    copy_from_slice!(&[tag]);
+    copy_from_slice!(&wire_len.to_ne_bytes());
+    copy_from_slice!(value);
+    Ok(size)
 }
 
 pub trait WriteToBuf {
@@ -204,8 +179,11 @@ pub trait WriteToBuf {
 macro_rules! impl_write_to_buf {
     ($type:ident, $arg_type:expr) => {
         impl WriteToBuf for $type {
+            // This need not be inlined because the return value is Result<N, ()> where N is
+            // mem::size_of<$type>, which is a compile-time constant.
+            #[inline(never)]
             fn write(self, buf: &mut [u8]) -> Result<usize, ()> {
-                TagLenValue::new($arg_type, self.to_ne_bytes()).write(buf)
+                write($arg_type.into(), &self.to_ne_bytes(), buf)
             }
         }
     };
@@ -227,46 +205,66 @@ impl_write_to_buf!(f32, Argument::F32);
 impl_write_to_buf!(f64, Argument::F64);
 
 impl WriteToBuf for [u8; 16] {
+    // This need not be inlined because the return value is Result<N, ()> where N is 16, which is a
+    // compile-time constant.
+    #[inline(never)]
     fn write(self, buf: &mut [u8]) -> Result<usize, ()> {
-        TagLenValue::new(Argument::ArrU8Len16, self).write(buf)
+        write(Argument::ArrU8Len16.into(), &self, buf)
     }
 }
 
 impl WriteToBuf for [u16; 8] {
+    // This need not be inlined because the return value is Result<N, ()> where N is 16, which is a
+    // compile-time constant.
+    #[inline(never)]
     fn write(self, buf: &mut [u8]) -> Result<usize, ()> {
         let bytes = unsafe { core::mem::transmute::<_, [u8; 16]>(self) };
-        TagLenValue::new(Argument::ArrU16Len8, bytes).write(buf)
+        write(Argument::ArrU16Len8.into(), &bytes, buf)
     }
 }
 
 impl WriteToBuf for [u8; 6] {
+    // This need not be inlined because the return value is Result<N, ()> where N is 6, which is a
+    // compile-time constant.
+    #[inline(never)]
     fn write(self, buf: &mut [u8]) -> Result<usize, ()> {
-        TagLenValue::new(Argument::ArrU8Len6, self).write(buf)
+        write(Argument::ArrU8Len6.into(), &self, buf)
     }
 }
 
 impl WriteToBuf for &[u8] {
+    // Must be inlined, else the BPF backend emits:
+    //
+    // llvm: <unknown>:0:0: in function _ZN63_$LT$$RF$$u5b$u8$u5d$$u20$as$u20$aya_log_common..WriteToBuf$GT$5write17h08f30a45f7b9f09dE { i64, i64 } (ptr, i64, ptr, i64): only integer returns supported
+    #[inline(always)]
     fn write(self, buf: &mut [u8]) -> Result<usize, ()> {
-        TagLenValue::new(Argument::Bytes, self.iter().copied()).write(buf)
+        write(Argument::Bytes.into(), self, buf)
     }
 }
 
 impl WriteToBuf for &str {
+    // Must be inlined, else the BPF backend emits:
+    //
+    // llvm: <unknown>:0:0: in function _ZN54_$LT$$RF$str$u20$as$u20$aya_log_common..WriteToBuf$GT$5write17h7e2d1ccaa758e2b5E { i64, i64 } (ptr, i64, ptr, i64): only integer returns supported
+    #[inline(always)]
     fn write(self, buf: &mut [u8]) -> Result<usize, ()> {
-        TagLenValue::new(Argument::Str, self.as_bytes().iter().copied()).write(buf)
+        write(Argument::Str.into(), self.as_bytes(), buf)
     }
 }
 
 impl WriteToBuf for DisplayHint {
+    // This need not be inlined because the return value is Result<N, ()> where N is 1, which is a
+    // compile-time constant.
+    #[inline(never)]
     fn write(self, buf: &mut [u8]) -> Result<usize, ()> {
         let v: u8 = self.into();
-        TagLenValue::new(Argument::DisplayHint, v.to_ne_bytes()).write(buf)
+        write(Argument::DisplayHint.into(), &v.to_ne_bytes(), buf)
     }
 }
 
 #[allow(clippy::result_unit_err)]
 #[doc(hidden)]
-#[inline(always)]
+#[inline(always)] // This function takes too many arguments to not be inlined.
 pub fn write_record_header(
     buf: &mut [u8],
     target: &str,
@@ -278,16 +276,18 @@ pub fn write_record_header(
 ) -> Result<usize, ()> {
     let level: u8 = level.into();
     let mut size = 0;
-    size += TagLenValue::new(RecordField::Target, target.as_bytes().iter().copied())
+    macro_rules! write {
-        .write(&mut buf[size..])?;
+        ($tag:expr, $value:expr) => {{
-    size += TagLenValue::new(RecordField::Level, level.to_ne_bytes()).write(&mut buf[size..])?;
+            let buf = buf.get_mut(size..).ok_or(())?;
-    size += TagLenValue::new(RecordField::Module, module.as_bytes().iter().copied())
+            size += write($tag.into(), $value, buf)?;
-        .write(&mut buf[size..])?;
+        }};
-    size += TagLenValue::new(RecordField::File, file.as_bytes().iter().copied())
+    }
-        .write(&mut buf[size..])?;
+    write!(RecordField::Target, target.as_bytes());
-    size += TagLenValue::new(RecordField::Line, line.to_ne_bytes()).write(&mut buf[size..])?;
+    write!(RecordField::Level, &level.to_ne_bytes());
-    size +=
+    write!(RecordField::Module, module.as_bytes());
-        TagLenValue::new(RecordField::NumArgs, num_args.to_ne_bytes()).write(&mut buf[size..])?;
+    write!(RecordField::File, file.as_bytes());
+    write!(RecordField::Line, &line.to_ne_bytes());
+    write!(RecordField::NumArgs, &num_args.to_ne_bytes());
     Ok(size)
 }
 

test/integration-ebpf/src/log.rs

@@ -7,7 +7,14 @@ use aya_log_ebpf::{debug, error, info, trace, warn};
 #[uprobe]
 pub fn test_log(ctx: ProbeContext) {
     debug!(&ctx, "Hello from eBPF!");
-    error!(&ctx, "{}, {}, {}", 69, 420i32, "wao");
+    error!(
+        &ctx,
+        "{}, {}, {}, {:x}",
+        69,
+        420i32,
+        "wao",
+        "wao".as_bytes()
+    );
     let ipv4 = 167772161u32; // 10.0.0.1
     let ipv6 = [
         32u8, 1u8, 13u8, 184u8, 0u8, 0u8, 0u8, 0u8, 0u8, 0u8, 0u8, 0u8, 0u8, 0u8, 0u8, 1u8,

test/integration-test/src/tests/log.rs

@@ -92,7 +92,7 @@ async fn log() {
     assert_eq!(
         records.next(),
         Some(&CapturedLog {
-            body: "69, 420, wao".into(),
+            body: "69, 420, wao, 77616f".into(),
             level: Level::Error,
             target: "log".into(),
         })

xtask/public-api/aya-log-common.txt

@@ -18,6 +18,8 @@ pub aya_log_common::Argument::U32
 pub aya_log_common::Argument::U64
 pub aya_log_common::Argument::U8
 pub aya_log_common::Argument::Usize
+impl core::convert::From<aya_log_common::Argument> for u8
+pub fn u8::from(enum_value: aya_log_common::Argument) -> Self
 impl core::clone::Clone for aya_log_common::Argument
 pub fn aya_log_common::Argument::clone(&self) -> aya_log_common::Argument
 impl core::fmt::Debug for aya_log_common::Argument
@@ -134,6 +136,8 @@ pub aya_log_common::RecordField::Line
 pub aya_log_common::RecordField::Module
 pub aya_log_common::RecordField::NumArgs
 pub aya_log_common::RecordField::Target = 1
+impl core::convert::From<aya_log_common::RecordField> for u8
+pub fn u8::from(enum_value: aya_log_common::RecordField) -> Self
 impl core::clone::Clone for aya_log_common::RecordField
 pub fn aya_log_common::RecordField::clone(&self) -> aya_log_common::RecordField
 impl core::fmt::Debug for aya_log_common::RecordField