Skip to content

Commit

Permalink
Improve logging
Browse files Browse the repository at this point in the history 
Fix the log verbosity for the userspace program to let the user select
the level they want to filter by. This also replaces the previous description
which wasn't clear enough.

Add two other flags to set logging of the libbpf library which also
contains verifier errors, as well as for the BPF programs themselves. By
default they are turned off to reduce noise and performance overhead.

Test Plan
=========

Ensured the logging was off by default and could be enabled passing the
right flags.
  • Loading branch information
@javierhonduco
javierhonduco committed May 14, 2024
1 parent 8525177 commit cd5fa16
Show file tree
Hide file tree
Showing 2 changed files with 51 additions and 32 deletions.
60 changes: 34 additions & 26 deletions src/main.rs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -7,7 +7,6 @@ use std::panic;
use std::path::PathBuf;
use std::time::Duration;

use clap::ArgAction;
use clap::Parser;

use inferno::flamegraph;
Expand Down Expand Up @@ -74,6 +73,16 @@ fn primes_before_after(non_prime: usize) -> Result<(usize, usize), String> {
Ok((before, after))
}

#[derive(clap::ValueEnum, Debug, Clone, Default)]
enum LoggingLevel {
Trace,
Debug,
#[default]
Info,
Warn,
Error,
}

#[derive(Parser, Debug)]
struct Cli {
/// Specific PIDs to profile
Expand All @@ -84,23 +93,28 @@ struct Cli {
tids: Vec<i32>,
/// Show unwind info for given binary
#[arg(long, value_name = "PATH_TO_BINARY",
conflicts_with_all = ["pids", "tids", "show_info", "duration",
"filter_logs", "sample_freq", "flamegraph_file"]
conflicts_with_all = ["pids", "tids", "show_info", "duration", "sample_freq", "flamegraph_file"]
)]
show_unwind_info: Option<String>,
/// Show build ID for given binary
#[arg(long, value_name = "PATH_TO_BINARY",
conflicts_with_all = ["pids", "tids", "duration", "filter_logs",
conflicts_with_all = ["pids", "tids", "duration",
"sample_freq", "flamegraph_file"]
)]
show_info: Option<String>,
/// How long this agent will run in seconds
#[arg(short='D', long, default_value = Duration::MAX.as_secs().to_string(),
value_parser = parse_duration)]
duration: Duration,
/// Enable TRACE (max) level logging - defaults to INFO level otherwise
#[arg(long, action=ArgAction::SetFalse)]
filter_logs: bool,
/// Enable libbpf logs. This includes the BPF verifier output
#[arg(long)]
libbpf_logs: bool,
/// Enable BPF programs logging
#[arg(long)]
bpf_logging: bool,
/// Set lightswitch's logging level
#[arg(long, default_value_t, value_enum)]
logging: LoggingLevel,
// Verification for this option guarantees the only possible selections
// are prime numbers up to and including 1001
/// Per-CPU Sampling Frequency in Hz
Expand Down Expand Up @@ -148,10 +162,12 @@ fn main() -> Result<(), Box<dyn Error>> {
}

let subscriber = FmtSubscriber::builder()
.with_max_level(if args.filter_logs {
Level::TRACE
} else {
Level::INFO
.with_max_level(match args.logging {
LoggingLevel::Trace => Level::TRACE,
LoggingLevel::Debug => Level::DEBUG,
LoggingLevel::Info => Level::INFO,
LoggingLevel::Warn => Level::WARN,
LoggingLevel::Error => Level::ERROR,
})
.with_span_events(FmtSpan::ENTER | FmtSpan::CLOSE)
.with_ansi(std::io::stdout().is_terminal())
Expand All @@ -176,7 +192,12 @@ fn main() -> Result<(), Box<dyn Error>> {

let collector = Collector::new();

let mut p: Profiler<'_> = Profiler::new(true, args.duration, args.sample_freq);
let mut p: Profiler<'_> = Profiler::new(
args.libbpf_logs,
args.bpf_logging,
args.duration,
args.sample_freq,
);
p.profile_pids(args.pids);
p.run(collector.clone());

Expand Down Expand Up @@ -268,7 +289,7 @@ mod tests {
let actual = String::from_utf8(cmd.unwrap().stdout).unwrap();
insta::assert_yaml_snapshot!(actual, @r###"
---
"Usage: lightswitch [OPTIONS]\n\nOptions:\n --pids <PIDS>\n Specific PIDs to profile\n --tids <TIDS>\n Specific TIDs to profile (these can be outside the PIDs selected above)\n --show-unwind-info <PATH_TO_BINARY>\n Show unwind info for given binary\n --show-info <PATH_TO_BINARY>\n Show build ID for given binary\n -D, --duration <DURATION>\n How long this agent will run in seconds [default: 18446744073709551615]\n --filter-logs\n Enable TRACE (max) level logging - defaults to INFO level otherwise\n --sample-freq <SAMPLE_FREQ_IN_HZ>\n Per-CPU Sampling Frequency in Hz [default: 19]\n --flamegraph-file <FLAMEGRAPH_FILE>\n Output file for Flame Graph in SVG format [default: flame.svg]\n -h, --help\n Print help\n"
"Usage: lightswitch [OPTIONS]\n\nOptions:\n --pids <PIDS>\n Specific PIDs to profile\n --tids <TIDS>\n Specific TIDs to profile (these can be outside the PIDs selected above)\n --show-unwind-info <PATH_TO_BINARY>\n Show unwind info for given binary\n --show-info <PATH_TO_BINARY>\n Show build ID for given binary\n -D, --duration <DURATION>\n How long this agent will run in seconds [default: 18446744073709551615]\n --libbpf-logs\n Enable libbpf logs. This includes the BPF verifier output\n --bpf-logging\n Enable BPF programs logging\n --logging <LOGGING>\n Set lightswitch's logging level [default: info] [possible values: trace, debug, info, warn, error]\n --sample-freq <SAMPLE_FREQ_IN_HZ>\n Per-CPU Sampling Frequency in Hz [default: 19]\n --flamegraph-file <FLAMEGRAPH_FILE>\n Output file for Flame Graph in SVG format [default: flame.svg]\n -h, --help\n Print help\n"
"###);
}

Expand Down Expand Up @@ -340,17 +361,4 @@ mod tests {
}
}
}

// Only usable on the nightly toolchain for now...
// use test::{black_box, Bencher};

// #[bench]
// fn bench_primes_before_after(b: &mut Bencher) {
// b.iter(|| {
// // Inner closure, the actual test
// for i in 1..1009 {
// black_box(primes_before_after(i));
// }
// });
// }
}
23 changes: 17 additions & 6 deletions src/profiler.rs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -147,20 +147,27 @@ pub type SymbolizedAggregatedProfile = Vec<SymbolizedAggregatedSample>;

impl Default for Profiler<'_> {
fn default() -> Self {
Self::new(false, Duration::MAX, 19)
Self::new(false, false, Duration::MAX, 19)
}
}

impl Profiler<'_> {
pub fn new(bpf_debug: bool, duration: Duration, sample_freq: u16) -> Self {
pub fn new(
libbpf_debug: bool,
bpf_logging: bool,
duration: Duration,
sample_freq: u16,
) -> Self {
let mut skel_builder: ProfilerSkelBuilder = ProfilerSkelBuilder::default();
skel_builder.obj_builder.debug(bpf_debug);
let open_skel = skel_builder.open().expect("open skel");
skel_builder.obj_builder.debug(libbpf_debug);
let mut open_skel = skel_builder.open().expect("open skel");
open_skel.rodata_mut().lightswitch_config.verbose_logging = bpf_logging;
let bpf = open_skel.load().expect("load skel");
info!("native unwinder BPF program loaded");
let exec_mappings_fd = bpf.maps().exec_mappings().as_fd().as_raw_fd();

let mut tracers_builder = TracersSkelBuilder::default();
tracers_builder.obj_builder.debug(bpf_debug);
tracers_builder.obj_builder.debug(libbpf_debug);
let open_tracers = tracers_builder.open().expect("open skel");
open_tracers
.maps()
Expand All @@ -169,6 +176,7 @@ impl Profiler<'_> {
.expect("reuse exec_mappings");

let tracers = open_tracers.load().expect("load skel");
info!("munmap and process exit tracing BPF programs loaded");

let procs = Arc::new(Mutex::new(HashMap::new()));
let object_files = Arc::new(Mutex::new(HashMap::new()));
Expand Down Expand Up @@ -822,7 +830,10 @@ impl Profiler<'_> {
);

if available_space == 0 {
info!("no space in live shard, allocating a new one");
info!(
"live shard is full, allocating a new one [{}/{}]",
self.native_unwind_state.shard_index, MAX_SHARDS
);

if self.persist_unwind_info(&self.native_unwind_state.live_shard) {
self.native_unwind_state.dirty = false;
Expand Down

0 comments on commit cd5fa16

Please sign in to comment.