system: add logs

config.toml

@@ -1,3 +1,111 @@
+# Watt Default Configuration
+
+# Rules are evaluated by priority (higher number => higher priority).
+# Each rule can specify conditions and actions for CPU and power management.
+
+# Emergency thermal protection (highest priority).
+[[rule]]
+priority = 100
+if = { value = "$cpu-temperature", is-more-than = 85.0 }
+cpu.governor = "powersave"
+cpu.energy-performance-preference = "power"
+cpu.frequency-mhz-maximum = 2000
+cpu.turbo = false
+
+# Critical battery preservation.
+[[rule]]
+priority = 90
+if.all = [
+  "?discharging",
+  { value = "%power-supply-charge", is-less-than = 0.3 },
+]
+cpu.governor = "powersave"
+cpu.energy-performance-preference = "power"
+cpu.frequency-mhz-maximum = 800 # More aggressive below critical threshold.
+cpu.turbo = false
+power.platform-profile = "low-power"
+
+# High performance mode for sustained high load.
+[[rule]]
+priority = 80
+if.all = [
+  { value = "%cpu-usage", is-more-than = 0.8 },
+  { value = "$cpu-idle-seconds", is-less-than = 30.0 },
+  { value = "$cpu-temperature", is-less-than = 75.0 },
+]
+cpu.governor = "performance"
+cpu.energy-performance-preference = "performance"
+cpu.turbo = true
+
+# Performance mode when not discharging.
+[[rule]]
+priority = 70
+if.all = [
+  { not = "?discharging" },
+  { value = "%cpu-usage", is-more-than = 0.1 },
+  { value = "$cpu-temperature", is-less-than = 80.0 },
+]
+cpu.governor = "performance"
+cpu.energy-performance-preference = "performance"
+cpu.energy-performance-bias = "balance_performance"
+cpu.turbo = true
+
+# Moderate performance for medium load.
+[[rule]]
+priority = 60
+if.all = [
+  { value = "%cpu-usage", is-more-than = 0.4 },
+  { value = "%cpu-usage", is-less-than = 0.8 },
+]
+cpu.governor = "schedutil"
+cpu.energy-performance-preference = "balance_performance"
+
+# Power saving during low activity.
+[[rule]]
+priority = 50
+if.all = [
+  { value = "%cpu-usage", is-less-than = 0.2 },
+  { value = "$cpu-idle-seconds", is-more-than = 60.0 },
+]
+cpu.governor = "powersave"
+cpu.energy-performance-preference = "power"
+cpu.turbo = false
+
+# Extended idle power optimization.
+[[rule]]
+priority = 40
+if = { value = "$cpu-idle-seconds", is-more-than = 300.0 }
+cpu.governor = "powersave"
+cpu.energy-performance-preference = "power"
+cpu.frequency-mhz-maximum = 1600
+cpu.turbo = false
+
+# Battery conservation when discharging.
+[[rule]]
+priority = 30
+if.all = [
+  "?discharging",
+  { value = "%power-supply-charge", is-less-than = 0.5 },
+]
+cpu.governor = "powersave"
+cpu.energy-performance-preference = "power"
+cpu.frequency-mhz-maximum = 2000
+cpu.turbo = false
+power.platform-profile = "low-power"
+
+# General battery mode.
+[[rule]]
+priority = 20
+if = "?discharging"
+cpu.governor = "powersave"
+cpu.energy-performance-preference = "power"
+cpu.energy-performance-bias = "balance_power"
+cpu.frequency-mhz-maximum = 1800
+cpu.frequency-mhz-minimum = 200
+cpu.turbo = false
+
+# Balanced performance for general use. Default fallback rule.
 [[rule]]
 priority = 0
-if = { value = "%cpu-usage", is-more-than = 0.7 }
+cpu.governor = "schedutil"
+cpu.energy-performance-preference = "balance_performance"

src/config.rs

@@ -471,13 +471,30 @@ pub struct DaemonConfig {
 }
 
 impl DaemonConfig {
-    pub fn load_from(path: &Path) -> anyhow::Result<Self> {
-        let contents = fs::read_to_string(path).with_context(|| {
-            format!("failed to read config from '{path}'", path = path.display())
-        })?;
+    const DEFAULT: &str = include_str!("../config.toml");
 
-        let mut config: Self = toml::from_str(&contents)
-            .with_context(|| format!("failed to parse file at '{path}'", path = path.display(),))?;
+    pub fn load_from(path: Option<&Path>) -> anyhow::Result<Self> {
+        let contents = if let Some(path) = path {
+            log::debug!("loading config from '{path}'", path = path.display());
+
+            &fs::read_to_string(path).with_context(|| {
+                format!("failed to read config from '{path}'", path = path.display())
+            })?
+        } else {
+            log::debug!(
+                "loading default config from embedded toml:\n{config}",
+                config = Self::DEFAULT,
+            );
+
+            Self::DEFAULT
+        };
+
+        let mut config: Self = toml::from_str(contents).with_context(|| {
+            path.map_or(
+                "failed to parse builtin default config, this is a bug".to_owned(),
+                |p| format!("failed to parse file at '{path}'", path = p.display()),
+            )
+        })?;
 
         {
             let mut priorities = Vec::with_capacity(config.rules.len());
@@ -491,6 +508,15 @@ impl DaemonConfig {
             }
         }
 
+        // This is just for debug traces.
+        if log::max_level() >= log::LevelFilter::Debug {
+            if config.rules.is_sorted_by_key(|rule| rule.priority) {
+                log::debug!("config rules are sorted by increasing priority, not doing anything");
+            } else {
+                log::debug!("config rules aren't sorted by priority, sorting");
+            }
+        }
+
         config.rules.sort_by_key(|rule| rule.priority);
 
         log::debug!("loaded config: {config:#?}");

src/daemon.rs

@@ -1,7 +1,6 @@
 use std::{
     cell::LazyCell,
     collections::{HashMap, VecDeque},
-    ops::Deref,
     sync::{
         Arc,
         atomic::{AtomicBool, Ordering},
@@ -33,16 +32,17 @@ fn idle_multiplier(idle_for: Duration) -> f64 {
         }
     };
 
-    // Clamp the multiplier to avoid excessive intervals.
+    // Clamp the multiplier to avoid excessive delays.
     (1.0 + factor).clamp(1.0, 5.0)
 }
 
+#[derive(Debug)]
 struct Daemon {
     /// Last time when there was user activity.
     last_user_activity: Instant,
 
-    /// The last computed polling interval.
-    last_polling_interval: Option<Duration>,
+    /// The last computed polling delay.
+    last_polling_delay: Option<Duration>,
 
     /// The system state.
     system: system::System,
@@ -58,12 +58,17 @@ impl Daemon {
     fn rescan(&mut self) -> anyhow::Result<()> {
         self.system.rescan()?;
 
-        while self.cpu_log.len() > 99 {
+        log::debug!("appending daemon logs...");
+
+        let at = Instant::now();
+
+        while self.cpu_log.len() > 100 {
+            log::debug!("daemon CPU log was too long, popping element");
             self.cpu_log.pop_front();
         }
 
-        self.cpu_log.push_back(CpuLog {
-            at: Instant::now(),
+        let cpu_log = CpuLog {
+            at,
 
             usage: self
                 .system
@@ -75,35 +80,40 @@ impl Daemon {
 
             temperature: self.system.cpu_temperatures.values().sum::<f64>()
                 / self.system.cpu_temperatures.len() as f64,
-        });
+        };
+        log::debug!("appending CPU log item: {cpu_log:?}");
+        self.cpu_log.push_back(cpu_log);
 
-        let at = Instant::now();
-
-        let (charge_sum, charge_nr) =
-            self.system
-                .power_supplies
-                .iter()
-                .fold((0.0, 0u32), |(sum, count), power_supply| {
-                    if let Some(charge_percent) = power_supply.charge_percent {
-                        (sum + charge_percent, count + 1)
-                    } else {
-                        (sum, count)
-                    }
-                });
-
-        while self.power_supply_log.len() > 99 {
+        while self.power_supply_log.len() > 100 {
+            log::debug!("daemon power supply log was too long, popping element");
             self.power_supply_log.pop_front();
         }
 
-        self.power_supply_log.push_back(PowerSupplyLog {
+        let power_supply_log = PowerSupplyLog {
             at,
-            charge: charge_sum / charge_nr as f64,
-        });
+            charge: {
+                let (charge_sum, charge_nr) = self.system.power_supplies.iter().fold(
+                    (0.0, 0u32),
+                    |(sum, count), power_supply| {
+                        if let Some(charge_percent) = power_supply.charge_percent {
+                            (sum + charge_percent, count + 1)
+                        } else {
+                            (sum, count)
+                        }
+                    },
+                );
+
+                charge_sum / charge_nr as f64
+            },
+        };
+        log::debug!("appending power supply log item: {power_supply_log:?}");
+        self.power_supply_log.push_back(power_supply_log);
 
         Ok(())
     }
 }
 
+#[derive(Debug)]
 struct CpuLog {
     at: Instant,
 
@@ -114,6 +124,7 @@ struct CpuLog {
     temperature: f64,
 }
 
+#[derive(Debug)]
 struct CpuVolatility {
     usage: f64,
 
@@ -185,6 +196,7 @@ impl Daemon {
     }
 }
 
+#[derive(Debug)]
 struct PowerSupplyLog {
     at: Instant,
 
@@ -243,28 +255,28 @@ impl Daemon {
 }
 
 impl Daemon {
-    fn polling_interval(&mut self) -> Duration {
-        let mut interval = Duration::from_secs(5);
+    fn polling_delay(&mut self) -> Duration {
+        let mut delay = Duration::from_secs(5);
 
         // We are on battery, so we must be more conservative with our polling.
         if self.discharging() {
             match self.power_supply_discharge_rate() {
                 Some(discharge_rate) => {
                     if discharge_rate > 0.2 {
-                        interval *= 3;
+                        delay *= 3;
                     } else if discharge_rate > 0.1 {
-                        interval *= 2;
+                        delay *= 2;
                     } else {
                         // *= 1.5;
-                        interval /= 2;
-                        interval *= 3;
+                        delay /= 2;
+                        delay *= 3;
                     }
                 }
 
                 // If we can't determine the discharge rate, that means that
                 // we were very recently started. Which is user activity.
                 None => {
-                    interval *= 2;
+                    delay *= 2;
                 }
             }
         }
@@ -281,30 +293,30 @@ impl Daemon {
                     minutes = idle_for.as_secs() / 60,
                 );
 
-                interval = Duration::from_secs_f64(interval.as_secs_f64() * factor);
+                delay = Duration::from_secs_f64(delay.as_secs_f64() * factor);
             }
         }
 
         if let Some(volatility) = self.cpu_volatility() {
             if volatility.usage > 0.1 || volatility.temperature > 0.02 {
-                interval = (interval / 2).max(Duration::from_secs(1));
+                delay = (delay / 2).max(Duration::from_secs(1));
             }
         }
 
-        let interval = match self.last_polling_interval {
-            Some(last_interval) => Duration::from_secs_f64(
-                // 30% of current computed interval, 70% of last interval.
-                interval.as_secs_f64() * 0.3 + last_interval.as_secs_f64() * 0.7,
+        let delay = match self.last_polling_delay {
+            Some(last_delay) => Duration::from_secs_f64(
+                // 30% of current computed delay, 70% of last delay.
+                delay.as_secs_f64() * 0.3 + last_delay.as_secs_f64() * 0.7,
             ),
 
-            None => interval,
+            None => delay,
         };
 
-        let interval = Duration::from_secs_f64(interval.as_secs_f64().clamp(1.0, 30.0));
+        let delay = Duration::from_secs_f64(delay.as_secs_f64().clamp(1.0, 30.0));
 
-        self.last_polling_interval = Some(interval);
+        self.last_polling_delay = Some(delay);
 
-        interval
+        delay
     }
 }
 
@@ -315,17 +327,18 @@ pub fn run(config: config::DaemonConfig) -> anyhow::Result<()> {
 
     let cancelled = Arc::new(AtomicBool::new(false));
 
+    log::debug!("setting ctrl-c handler...");
     let cancelled_ = Arc::clone(&cancelled);
     ctrlc::set_handler(move || {
         log::info!("received shutdown signal");
         cancelled_.store(true, Ordering::SeqCst);
     })
-    .context("failed to set Ctrl-C handler")?;
+    .context("failed to set ctrl-c handler")?;
 
     let mut daemon = Daemon {
         last_user_activity: Instant::now(),
 
-        last_polling_interval: None,
+        last_polling_delay: None,
 
         system: system::System::new()?,
 
@@ -336,7 +349,16 @@ pub fn run(config: config::DaemonConfig) -> anyhow::Result<()> {
     while !cancelled.load(Ordering::SeqCst) {
         daemon.rescan()?;
 
-        let sleep_until = Instant::now() + daemon.polling_interval();
+        let delay = daemon.polling_delay();
+        log::info!(
+            "next poll will be in {seconds} seconds or {minutes} minutes, possibly delayed if application of rules takes more than the polling delay",
+            seconds = delay.as_secs_f64(),
+            minutes = delay.as_secs_f64() / 60.0,
+        );
+
+        log::debug!("filtering rules and applying them...");
+
+        let start = Instant::now();
 
         let state = config::EvalState {
             cpu_usage: daemon.cpu_log.back().unwrap().usage,
@@ -399,12 +421,17 @@ pub fn run(config: config::DaemonConfig) -> anyhow::Result<()> {
             delta.apply()?;
         }
 
-        if let Some(delay) = sleep_until.checked_duration_since(Instant::now()) {
-            thread::sleep(delay);
-        }
+        let elapsed = start.elapsed();
+        log::info!(
+            "filtered and applied rules in {seconds} seconds or {minutes} minutes",
+            seconds = elapsed.as_secs_f64(),
+            minutes = elapsed.as_secs_f64() / 60.0,
+        );
+
+        thread::sleep(delay.saturating_sub(elapsed));
     }
 
-    log::info!("exiting...");
+    log::info!("stopping polling loop and thus daemon...");
 
     Ok(())
 }

src/main.rs

@@ -35,7 +35,7 @@ enum Command {
 
         /// The daemon config path.
         #[arg(long, env = "WATT_CONFIG")]
-        config: PathBuf,
+        config: Option<PathBuf>,
     },
 
     /// CPU metadata and modification utility.
@@ -86,8 +86,8 @@ fn real_main() -> anyhow::Result<()> {
 
     match cli.command {
         Command::Watt { config, .. } => {
-            let config =
-                config::DaemonConfig::load_from(&config).context("failed to load daemon config")?;
+            let config = config::DaemonConfig::load_from(config.as_deref())
+                .context("failed to load daemon config")?;
 
             daemon::run(config)
         }

src/system.rs

@@ -1,9 +1,10 @@
-use std::{collections::HashMap, path::Path};
+use std::{collections::HashMap, path::Path, time::Instant};
 
 use anyhow::{Context, bail};
 
 use crate::{cpu, fs, power_supply};
 
+#[derive(Debug)]
 pub struct System {
     pub is_ac: bool,
 
@@ -38,19 +39,72 @@ impl System {
     }
 
     pub fn rescan(&mut self) -> anyhow::Result<()> {
-        self.cpus = cpu::Cpu::all().context("failed to scan CPUs")?;
+        log::debug!("rescanning view of system hardware...");
 
-        self.power_supplies =
-            power_supply::PowerSupply::all().context("failed to scan power supplies")?;
+        {
+            let start = Instant::now();
+            self.cpus = cpu::Cpu::all().context("failed to scan CPUs")?;
+            log::debug!(
+                "rescanned all CPUs in {millis}ms",
+                millis = start.elapsed().as_millis(),
+            );
+        }
+
+        {
+            let start = Instant::now();
+            self.power_supplies =
+                power_supply::PowerSupply::all().context("failed to scan power supplies")?;
+            log::debug!(
+                "rescanned all power supplies in {millis}ms",
+                millis = start.elapsed().as_millis(),
+            );
+        }
 
         self.is_ac = self
             .power_supplies
             .iter()
             .any(|power_supply| power_supply.is_ac())
-            || self.is_desktop()?;
+            || {
+                log::debug!(
+                    "checking whether if this device is a desktop to determine if it is AC as no power supplies are"
+                );
 
-        self.rescan_load_average()?;
-        self.rescan_temperatures()?;
+                let start = Instant::now();
+                let is_desktop = self.is_desktop()?;
+                log::debug!(
+                    "checked if is a desktop in {millis}ms",
+                    millis = start.elapsed().as_millis(),
+                );
+
+                log::debug!(
+                    "scan result: {elaborate}",
+                    elaborate = if is_desktop {
+                        "is a desktop, therefore is AC"
+                    } else {
+                        "not a desktop, and not AC"
+                    },
+                );
+
+                is_desktop
+            };
+
+        {
+            let start = Instant::now();
+            self.rescan_load_average()?;
+            log::debug!(
+                "rescanned load average in {millis}ms",
+                millis = start.elapsed().as_millis(),
+            );
+        }
+
+        {
+            let start = Instant::now();
+            self.rescan_temperatures()?;
+            log::debug!(
+                "rescanned temperatures in {millis}ms",
+                millis = start.elapsed().as_millis(),
+            );
+        }
 
         Ok(())
     }
@@ -108,9 +162,20 @@ impl System {
             let input_path = device_path.join(format!("temp{i}_input"));
 
             if !label_path.exists() || !input_path.exists() {
+                log::debug!(
+                    "{label_path} or {input_path} doesn't exist, skipping temp label",
+                    label_path = label_path.display(),
+                    input_path = input_path.display(),
+                );
                 continue;
             }
 
+            log::debug!(
+                "{label_path} or {input_path} exists, scanning temp label...",
+                label_path = label_path.display(),
+                input_path = input_path.display(),
+            );
+
             let Some(label) = fs::read(&label_path).with_context(|| {
                 format!(
                     "failed to read hardware hardware device label from '{path}'",
@@ -120,6 +185,7 @@ impl System {
             else {
                 continue;
             };
+            log::debug!("label content: {number}");
 
             // Match various common label formats:
             // "Core X", "core X", "Core-X", "CPU Core X", etc.
@@ -138,9 +204,16 @@ impl System {
                 .trim_start_matches("-")
                 .trim();
 
+            log::debug!("stripped 'Core' or similar identifier prefix of label content: {number}");
+
             let Ok(number) = number.parse::<u32>() else {
+                log::debug!("stripped content not a valid number, skipping");
                 continue;
             };
+            log::debug!("stripped content is a valid number, taking it as the core number");
+            log::debug!(
+                "it is fine if this number doesn't seem accurate due to CPU binning, see a more detailed explanation at: https://rgbcu.be/blog/why-cores"
+            );
 
             let Some(temperature_mc) = fs::read_n::<i64>(&input_path).with_context(|| {
                 format!(
@@ -151,6 +224,10 @@ impl System {
             else {
                 continue;
             };
+            log::debug!(
+                "temperature content: {celcius} celcius",
+                celcius = temperature_mc as f64 / 1000.0
+            );
 
             temperatures.insert(number, temperature_mc as f64 / 1000.0);
         }
@@ -159,6 +236,7 @@ impl System {
     }
 
     fn is_desktop(&mut self) -> anyhow::Result<bool> {
+        log::debug!("checking chassis type to determine if we are a desktop");
         if let Some(chassis_type) =
             fs::read("/sys/class/dmi/id/chassis_type").context("failed to read chassis type")?
         {
@@ -169,16 +247,18 @@ impl System {
             match chassis_type.trim() {
                 // Desktop form factors.
                 "3" | "4" | "5" | "6" | "7" | "15" | "16" | "17" => {
+                    log::debug!("chassis is a desktop form factor, short circuting true");
                     return Ok(true);
                 }
 
                 // Laptop form factors.
                 "9" | "10" | "14" | "31" => {
+                    log::debug!("chassis is a laptop form factor, short circuting false");
                     return Ok(false);
                 }
 
                 // Unknown, continue with other checks
-                _ => {}
+                _ => log::debug!("unknown chassis type"),
             }
         }
 
@@ -189,21 +269,26 @@ impl System {
             "/proc/acpi/battery",
         ];
 
+        log::debug!("checking existence of ACPI paths");
         for path in laptop_acpi_paths {
             if fs::exists(path) {
+                log::debug!("path '{path}' exists, short circuting false");
                 return Ok(false); // Likely a laptop.
             }
         }
 
+        log::debug!("checking if power saving paths exists");
         // Check CPU power policies, desktops often don't have these
         let power_saving_exists = fs::exists("/sys/module/intel_pstate/parameters/no_hwp")
             || fs::exists("/sys/devices/system/cpu/cpufreq/conservative");
 
         if !power_saving_exists {
+            log::debug!("power saving paths do not exist, short circuting true");
             return Ok(true); // Likely a desktop.
         }
 
         // Default to assuming desktop if we can't determine.
+        log::debug!("cannot determine whether if we are a desktop, defaulting to true");
         Ok(true)
     }