[Bug]: cardwired spends ~0.4 ms CPU per process launch in Integrated mode decoding eBPF debug logs

[MaxWolf-01]

Disclaimer: AI-drafted, verified by me before filing. I answer follow-ups.

Distribution

NixOS in a VM built from cardwire's nix/vm-configuration.nix, with the QEMU GPU options from nix/ci-2gpu.nix and nixpkgs as locked in v0.12.3

Kernel Version

6.18.46

Cardwire Version

cardwire-cli 0.12.3

Cardwire GPU list

Two virtio GPUs, as in the CI VM

{
  "0": {
    "id": 0,
    "name": "Virtio 1.0 GPU",
    "pci": "0000:00:07.0",
    "render": 128,
    "card": 0,
    "default": true,
    "discrete": false,
    "virtual_gpu": true,
    "available": true,
    "vendor": "Unknown Vendor",
    "driver": "virtio-pci",
    "blocked": false,
    "launchable": true,
    "nvidia": false,
    "nvidia_minor": "none"
  },
  "1": {
    "id": 1,
    "name": "Virtio 1.0 GPU",
    "pci": "0000:00:08.0",
    "render": 129,
    "card": 1,
    "default": false,
    "discrete": true,
    "virtual_gpu": true,
    "available": true,
    "vendor": "Unknown Vendor",
    "driver": "virtio-pci",
    "blocked": false,
    "launchable": true,
    "nvidia": false,
    "nvidia_minor": "none"
  }
}

Describe the bug

In Integrated and Smart mode, cardwired uses about 0.4 ms of CPU for every process the system launches, against about 1 µs in Hybrid. The CPU goes to decoding eBPF debug! records, which reach the daemon whatever its log level.

Expected vs Actual Behavior

Expected: a process launch costs cardwired the same CPU in Integrated mode as in Hybrid. In Integrated mode the exec tracepoint sends nothing to userspace, so the daemon has no work per launch.

Actual: cardwired CPU per process launch, measured as the CPUUsageNSec delta over 1000 launches of true:

mode	v0.12.3	v0.12.3 with the eBPF log level set to Info at load
Hybrid	1 µs	1 µs
Integrated	433 µs	1 µs
Smart	543 µs	95 µs

With battery_auto_switch enabled, cardwire runs in Integrated mode on battery.

Cardwire Daemon Logs

With RUST_LOG=debug, 20 launches in Integrated mode log the lines below, and the same launches in Hybrid log nothing. At the default log level the daemon's filter drops these records, so the journal shows nothing.

  25000 [DEBUG] EBPF inode_key() found an unnamed inode in inode_permission, skipping
      1 Suppressed 19252 messages from cardwired.service

LLM Output

try_inode_permission logs a debug! for every inode without a name:

cardwire/crates/cardwire-ebpf/src/main.rs

Lines 212 to 217 in 92c3e96

	KeyBuild::Unnamed => {
	debug!(
	&ctx,
	"EBPF inode_key() found an unnamed inode in inode_permission, skipping"
	);
	return ReturnCode::SUCCESS;

aya-log filters records inside the kernel only when the loader lowers AYA_LOG_LEVEL. It defaults to 0xff, every level, and a loader can lower it only at load time, with EbpfLoader::override_global(aya_log::LEVEL, ...) (aya-log 0.3.0 README, "Disabling log levels at load-time"). EbpfBlocker::new loads with aya::Ebpf::load and never sets it:

cardwire/crates/cardwire-ebpf-userspace/src/lib.rs

Lines 78 to 82 in 92c3e96

	let mut ebpf = aya::Ebpf::load(aya::include_bytes_aligned!(concat!(
	env!("OUT_DIR"),
	"/cardwire-ebpf"
	)))
	.map_err(|err| CardwireEbpfError::EbpfLoadError(err.to_string()))?;

Every record therefore crosses the AYA_LOGS ring buffer to cardwired, which parses and formats it before its info filter drops it. In Hybrid mode the hook returns before any log statement.

The table's right-hand column comes from v0.12.3 with only that load call changed, in aya-log-level.patch below. The eBPF code and its loader are the same on main at 2584ff6. All numbers come from cardwire's 2-GPU test VM; I have not measured on bare metal.

repro.sh, run as root

#!/usr/bin/env bash
# Run as root on a laptop-type system (Integrated and Smart available) with cardwired running.
set -euo pipefail

true_bin=$(type -P true)
cpu_ns() { systemctl show cardwired -p CPUUsageNSec --value; }

echo "# cardwired CPU per process launch (1000 launches of $true_bin)"
for mode in hybrid integrated smart; do
    cardwire set "$mode" > /dev/null
    sleep 2
    before=$(cpu_ns)
    for _ in $(seq 1000); do "$true_bin"; done
    sleep 1
    after=$(cpu_ns)
    echo "$mode: $(( (after - before) / 1000 / 1000 )) us"
done

echo
echo "# cardwired log lines per 20 launches, with RUST_LOG=debug"
mkdir -p /run/systemd/system/cardwired.service.d
printf '[Service]\nEnvironment=RUST_LOG=debug\n' > /run/systemd/system/cardwired.service.d/debug.conf
systemctl daemon-reload
systemctl restart cardwired
sleep 2
for mode in hybrid integrated; do
    cardwire set "$mode" > /dev/null
    sleep 2
    since=$(date +%s)
    sleep 1
    for _ in $(seq 20); do "$true_bin"; done
    sleep 2
    echo "== $mode"
    journalctl -u cardwired -o cat --since "@$since" | sort | uniq -c | sort -rn | head -3
done
rm -r /run/systemd/system/cardwired.service.d
systemctl daemon-reload
systemctl restart cardwired

Output on v0.12.3

# cardwired CPU per process launch (1000 launches of /run/current-system/sw/bin/true)
hybrid: 1 us
integrated: 433 us
smart: 543 us

# cardwired log lines per 20 launches, with RUST_LOG=debug
== hybrid
== integrated
  25000 [DEBUG] EBPF inode_key() found an unnamed inode in inode_permission, skipping
      1 Suppressed 19252 messages from cardwired.service

Output on v0.12.3 with the log level set to Info at load

# cardwired CPU per process launch (1000 launches of /run/current-system/sw/bin/true)
hybrid: 1 us
integrated: 1 us
smart: 95 us

# cardwired log lines per 20 launches, with RUST_LOG=debug
== hybrid
== integrated

aya-log-level.patch, the load change used for that run

diff --git a/crates/cardwire-ebpf-userspace/src/lib.rs b/crates/cardwire-ebpf-userspace/src/lib.rs
index 0c8591b..9d104b5 100644
--- a/crates/cardwire-ebpf-userspace/src/lib.rs
+++ b/crates/cardwire-ebpf-userspace/src/lib.rs
@@ -75,11 +75,14 @@ impl EbpfBlocker {
             return Err(CardwireEbpfError::LSMNotEnabled);
         }
         // load the program from the .o
-        let mut ebpf = aya::Ebpf::load(aya::include_bytes_aligned!(concat!(
-            env!("OUT_DIR"),
-            "/cardwire-ebpf"
-        )))
-        .map_err(|err| CardwireEbpfError::EbpfLoadError(err.to_string()))?;
+        let level = aya_log::Level::Info as u8;
+        let mut ebpf = aya::EbpfLoader::new()
+            .override_global(aya_log::LEVEL, &level, false)
+            .load(aya::include_bytes_aligned!(concat!(
+                env!("OUT_DIR"),
+                "/cardwire-ebpf"
+            )))
+            .map_err(|err| CardwireEbpfError::EbpfLoadError(err.to_string()))?;
 
         let btf = Btf::from_sys_fs().map_err(CardwireEbpfError::aya)?;
 

flake.nix that runs both VMs with nix build .#default.driver and ./result/bin/nixos-test-driver

{
  description = "Run repro.sh in cardwire's 2-GPU test VM, against v0.12.3 and v0.12.3 with the aya-log level set to Info";
  inputs.cardwire.url = "github:OpenGamingCollective/cardwire/v0.12.3";
  outputs =
    { cardwire, ... }:
    let
      system = "x86_64-linux";
      pkgs = cardwire.inputs.nixpkgs.legacyPackages.${system};
      stock = cardwire.packages.${system}.default;
      patched = stock.overrideAttrs (old: {
        patches = (old.patches or [ ]) ++ [ ./aya-log-level.patch ];
      });
      node =
        daemon:
        { lib, ... }:
        {
          imports = [
            cardwire.nixosModules.default
            "${cardwire}/nix/vm-configuration.nix"
          ];
          services.cardwire.settings.battery_auto_switch = lib.mkForce false;
          systemd.services.cardwired.serviceConfig.ExecStart = lib.mkForce "${daemon}/bin/cardwired";
          # The debug log flood would otherwise go to the serial console the test driver reads
          services.journald.extraConfig = lib.mkForce "";
          environment.etc."repro.sh".source = ./repro.sh;
          virtualisation = {
            memorySize = 2048;
            cores = 2;
            graphics = false;
            diskImage = null;
            qemu.options = [
              "-machine q35,accel=kvm,kernel-irqchip=split"
              "-device intel-iommu,intremap=on,device-iotlb=on"
              "-vga none"
              "-device virtio-gpu-pci,id=igpu,max_outputs=2"
              "-device virtio-gpu-pci,id=dgpu,max_outputs=1"
            ];
          };
          networking.useDHCP = false;
          networking.interfaces = lib.mkForce { };
        };
    in
    {
      packages.${system}.default = pkgs.testers.runNixOSTest {
        name = "cardwire-log-level-repro";
        nodes.stock = node stock;
        nodes.patched = node patched;
        testScript = ''
          import os
          out = os.environ.get("out", "/tmp")
          for m in [stock, patched]:
              m.start()
              m.wait_for_unit("cardwired.service")
              m.wait_until_succeeds("cardwire get")
              env = m.succeed("uname -r; cardwire -V; cardwire list --json")
              report = m.succeed("bash /etc/repro.sh 2>&1")
              journal = m.succeed("journalctl -u cardwired --no-pager -o short-monotonic | tail -40")
              with open(os.path.join(out, f"{m.name}.txt"), "w") as f:
                  f.write(f"## environment\n{env}\n## repro.sh\n{report}\n## journalctl -u cardwired (tail)\n{journal}")
              print(f"==== {m.name}\n{report}")
              m.shutdown()
        '';
      };
    };
}