2018-11-16 08:45:59 -08:00
|
|
|
use solana_metrics::{influxdb, submit};
|
|
|
|
use solana_sdk::timing;
|
2018-07-17 15:26:10 -07:00
|
|
|
use std::env;
|
2018-05-30 21:24:21 -07:00
|
|
|
use std::sync::atomic::{AtomicUsize, Ordering};
|
|
|
|
|
2018-11-15 22:27:16 -08:00
|
|
|
const DEFAULT_LOG_RATE: usize = 1000;
|
2018-07-10 12:37:39 -07:00
|
|
|
|
2018-05-30 21:24:21 -07:00
|
|
|
pub struct Counter {
|
|
|
|
pub name: &'static str,
|
2018-07-10 15:14:59 -07:00
|
|
|
/// total accumulated value
|
2018-05-30 21:24:21 -07:00
|
|
|
pub counts: AtomicUsize,
|
|
|
|
pub times: AtomicUsize,
|
2018-07-10 15:14:59 -07:00
|
|
|
/// last accumulated value logged
|
|
|
|
pub lastlog: AtomicUsize,
|
2018-07-17 15:26:10 -07:00
|
|
|
pub lograte: AtomicUsize,
|
2018-05-30 21:24:21 -07:00
|
|
|
}
|
|
|
|
|
|
|
|
macro_rules! create_counter {
|
|
|
|
($name:expr, $lograte:expr) => {
|
|
|
|
Counter {
|
|
|
|
name: $name,
|
|
|
|
counts: AtomicUsize::new(0),
|
|
|
|
times: AtomicUsize::new(0),
|
2018-07-10 15:14:59 -07:00
|
|
|
lastlog: AtomicUsize::new(0),
|
2018-07-17 15:26:10 -07:00
|
|
|
lograte: AtomicUsize::new($lograte),
|
2018-05-30 21:24:21 -07:00
|
|
|
}
|
|
|
|
};
|
|
|
|
}
|
|
|
|
|
|
|
|
macro_rules! inc_counter {
|
2018-11-13 16:55:14 -08:00
|
|
|
($name:expr, $level:expr, $count:expr) => {
|
|
|
|
unsafe { $name.inc($level, $count) };
|
2018-05-30 21:24:21 -07:00
|
|
|
};
|
|
|
|
}
|
|
|
|
|
2018-08-06 11:35:45 -07:00
|
|
|
macro_rules! inc_new_counter_info {
|
2018-07-16 18:33:50 -07:00
|
|
|
($name:expr, $count:expr) => {{
|
2018-08-06 11:35:45 -07:00
|
|
|
inc_new_counter!($name, $count, Level::Info, 0);
|
2018-07-16 18:33:50 -07:00
|
|
|
}};
|
|
|
|
($name:expr, $count:expr, $lograte:expr) => {{
|
2018-08-06 11:35:45 -07:00
|
|
|
inc_new_counter!($name, $count, Level::Info, $lograte);
|
|
|
|
}};
|
|
|
|
}
|
|
|
|
|
|
|
|
macro_rules! inc_new_counter {
|
|
|
|
($name:expr, $count:expr, $level:expr, $lograte:expr) => {{
|
2018-11-13 16:55:14 -08:00
|
|
|
static mut INC_NEW_COUNTER: Counter = create_counter!($name, $lograte);
|
|
|
|
inc_counter!(INC_NEW_COUNTER, $level, $count);
|
2018-07-16 18:33:50 -07:00
|
|
|
}};
|
|
|
|
}
|
|
|
|
|
2018-05-30 21:24:21 -07:00
|
|
|
impl Counter {
|
2018-07-17 15:26:10 -07:00
|
|
|
fn default_log_rate() -> usize {
|
2018-11-15 22:27:16 -08:00
|
|
|
let v = env::var("SOLANA_DEFAULT_LOG_RATE")
|
|
|
|
.map(|x| x.parse().unwrap_or(DEFAULT_LOG_RATE))
|
|
|
|
.unwrap_or(DEFAULT_LOG_RATE);
|
2018-07-17 15:26:10 -07:00
|
|
|
if v == 0 {
|
2018-11-15 22:27:16 -08:00
|
|
|
DEFAULT_LOG_RATE
|
2018-07-17 15:26:10 -07:00
|
|
|
} else {
|
|
|
|
v
|
|
|
|
}
|
|
|
|
}
|
2018-11-13 16:55:14 -08:00
|
|
|
pub fn inc(&mut self, level: log::Level, events: usize) {
|
2018-05-30 21:24:21 -07:00
|
|
|
let counts = self.counts.fetch_add(events, Ordering::Relaxed);
|
|
|
|
let times = self.times.fetch_add(1, Ordering::Relaxed);
|
2018-07-17 15:26:10 -07:00
|
|
|
let mut lograte = self.lograte.load(Ordering::Relaxed);
|
|
|
|
if lograte == 0 {
|
|
|
|
lograte = Counter::default_log_rate();
|
|
|
|
self.lograte.store(lograte, Ordering::Relaxed);
|
|
|
|
}
|
2018-11-15 22:27:16 -08:00
|
|
|
if times % lograte == 0 && times > 0 && log_enabled!(level) {
|
|
|
|
info!(
|
|
|
|
"COUNTER:{{\"name\": \"{}\", \"counts\": {}, \"samples\": {}, \"now\": {}, \"events\": {}}}",
|
|
|
|
self.name,
|
|
|
|
counts + events,
|
|
|
|
times,
|
|
|
|
timing::timestamp(),
|
|
|
|
events,
|
|
|
|
);
|
|
|
|
}
|
|
|
|
let lastlog = self.lastlog.load(Ordering::Relaxed);
|
|
|
|
let prev = self
|
|
|
|
.lastlog
|
|
|
|
.compare_and_swap(lastlog, counts, Ordering::Relaxed);
|
|
|
|
if prev == lastlog {
|
2018-11-16 08:45:59 -08:00
|
|
|
submit(
|
2018-11-15 22:27:16 -08:00
|
|
|
influxdb::Point::new(&format!("counter-{}", self.name))
|
|
|
|
.add_field(
|
|
|
|
"count",
|
|
|
|
influxdb::Value::Integer(counts as i64 - lastlog as i64),
|
2018-12-07 19:01:28 -08:00
|
|
|
)
|
|
|
|
.to_owned(),
|
2018-11-15 22:27:16 -08:00
|
|
|
);
|
2018-05-30 21:24:21 -07:00
|
|
|
}
|
|
|
|
}
|
|
|
|
}
|
|
|
|
#[cfg(test)]
|
|
|
|
mod tests {
|
2018-11-15 22:27:16 -08:00
|
|
|
use counter::{Counter, DEFAULT_LOG_RATE};
|
2018-08-06 11:35:45 -07:00
|
|
|
use log::Level;
|
2018-07-17 15:26:10 -07:00
|
|
|
use std::env;
|
2018-05-30 21:24:21 -07:00
|
|
|
use std::sync::atomic::{AtomicUsize, Ordering};
|
2018-07-31 12:37:39 -07:00
|
|
|
use std::sync::{Once, RwLock, ONCE_INIT};
|
|
|
|
|
|
|
|
fn get_env_lock() -> &'static RwLock<()> {
|
|
|
|
static mut ENV_LOCK: Option<RwLock<()>> = None;
|
|
|
|
static INIT_HOOK: Once = ONCE_INIT;
|
|
|
|
|
|
|
|
unsafe {
|
|
|
|
INIT_HOOK.call_once(|| {
|
|
|
|
ENV_LOCK = Some(RwLock::new(()));
|
|
|
|
});
|
|
|
|
&ENV_LOCK.as_ref().unwrap()
|
|
|
|
}
|
|
|
|
}
|
|
|
|
|
2018-05-30 21:24:21 -07:00
|
|
|
#[test]
|
|
|
|
fn test_counter() {
|
2018-07-31 12:37:39 -07:00
|
|
|
let _readlock = get_env_lock().read();
|
2018-11-15 22:27:16 -08:00
|
|
|
static mut COUNTER: Counter = create_counter!("test", 1000);
|
2018-05-30 21:24:21 -07:00
|
|
|
let count = 1;
|
2018-11-13 16:55:14 -08:00
|
|
|
inc_counter!(COUNTER, Level::Info, count);
|
2018-05-30 21:24:21 -07:00
|
|
|
unsafe {
|
|
|
|
assert_eq!(COUNTER.counts.load(Ordering::Relaxed), 1);
|
|
|
|
assert_eq!(COUNTER.times.load(Ordering::Relaxed), 1);
|
2018-11-15 22:27:16 -08:00
|
|
|
assert_eq!(COUNTER.lograte.load(Ordering::Relaxed), 1000);
|
2018-07-10 15:14:59 -07:00
|
|
|
assert_eq!(COUNTER.lastlog.load(Ordering::Relaxed), 0);
|
2018-05-30 21:24:21 -07:00
|
|
|
assert_eq!(COUNTER.name, "test");
|
|
|
|
}
|
2018-07-10 15:14:59 -07:00
|
|
|
for _ in 0..199 {
|
2018-11-13 16:55:14 -08:00
|
|
|
inc_counter!(COUNTER, Level::Info, 2);
|
2018-07-10 15:14:59 -07:00
|
|
|
}
|
|
|
|
unsafe {
|
2018-11-15 22:27:16 -08:00
|
|
|
assert_eq!(COUNTER.lastlog.load(Ordering::Relaxed), 397);
|
2018-07-10 15:14:59 -07:00
|
|
|
}
|
2018-11-13 16:55:14 -08:00
|
|
|
inc_counter!(COUNTER, Level::Info, 2);
|
2018-07-10 15:14:59 -07:00
|
|
|
unsafe {
|
|
|
|
assert_eq!(COUNTER.lastlog.load(Ordering::Relaxed), 399);
|
|
|
|
}
|
2018-05-30 21:24:21 -07:00
|
|
|
}
|
2018-07-16 18:33:50 -07:00
|
|
|
#[test]
|
|
|
|
fn test_inc_new_counter() {
|
2018-07-31 12:37:39 -07:00
|
|
|
let _readlock = get_env_lock().read();
|
2018-07-16 18:33:50 -07:00
|
|
|
//make sure that macros are syntactically correct
|
|
|
|
//the variable is internal to the macro scope so there is no way to introspect it
|
2018-08-06 11:35:45 -07:00
|
|
|
inc_new_counter_info!("counter-1", 1);
|
|
|
|
inc_new_counter_info!("counter-2", 1, 2);
|
2018-07-16 18:33:50 -07:00
|
|
|
}
|
2018-07-17 15:26:10 -07:00
|
|
|
#[test]
|
|
|
|
fn test_lograte() {
|
2018-07-31 12:37:39 -07:00
|
|
|
let _readlock = get_env_lock().read();
|
|
|
|
assert_eq!(
|
|
|
|
Counter::default_log_rate(),
|
2018-11-15 22:27:16 -08:00
|
|
|
DEFAULT_LOG_RATE,
|
|
|
|
"default_log_rate() is {}, expected {}, SOLANA_DEFAULT_LOG_RATE environment variable set?",
|
2018-07-31 12:37:39 -07:00
|
|
|
Counter::default_log_rate(),
|
2018-11-15 22:27:16 -08:00
|
|
|
DEFAULT_LOG_RATE,
|
2018-07-31 12:37:39 -07:00
|
|
|
);
|
2018-07-17 15:26:10 -07:00
|
|
|
static mut COUNTER: Counter = create_counter!("test_lograte", 0);
|
2018-11-13 16:55:14 -08:00
|
|
|
inc_counter!(COUNTER, Level::Info, 2);
|
2018-07-17 15:26:10 -07:00
|
|
|
unsafe {
|
2018-11-15 22:27:16 -08:00
|
|
|
assert_eq!(COUNTER.lograte.load(Ordering::Relaxed), DEFAULT_LOG_RATE);
|
2018-07-17 15:26:10 -07:00
|
|
|
}
|
|
|
|
}
|
2018-07-31 12:37:39 -07:00
|
|
|
|
2018-07-17 15:26:10 -07:00
|
|
|
#[test]
|
|
|
|
fn test_lograte_env() {
|
2018-11-15 22:27:16 -08:00
|
|
|
assert_ne!(DEFAULT_LOG_RATE, 0);
|
2018-07-31 12:37:39 -07:00
|
|
|
let _writelock = get_env_lock().write();
|
2018-07-17 15:26:10 -07:00
|
|
|
static mut COUNTER: Counter = create_counter!("test_lograte_env", 0);
|
2018-11-15 22:27:16 -08:00
|
|
|
env::set_var("SOLANA_DEFAULT_LOG_RATE", "50");
|
2018-11-13 16:55:14 -08:00
|
|
|
inc_counter!(COUNTER, Level::Info, 2);
|
2018-07-17 15:26:10 -07:00
|
|
|
unsafe {
|
|
|
|
assert_eq!(COUNTER.lograte.load(Ordering::Relaxed), 50);
|
|
|
|
}
|
|
|
|
|
|
|
|
static mut COUNTER2: Counter = create_counter!("test_lograte_env", 0);
|
2018-11-15 22:27:16 -08:00
|
|
|
env::set_var("SOLANA_DEFAULT_LOG_RATE", "0");
|
2018-11-13 16:55:14 -08:00
|
|
|
inc_counter!(COUNTER2, Level::Info, 2);
|
2018-07-17 15:26:10 -07:00
|
|
|
unsafe {
|
2018-11-15 22:27:16 -08:00
|
|
|
assert_eq!(COUNTER2.lograte.load(Ordering::Relaxed), DEFAULT_LOG_RATE);
|
2018-07-17 15:26:10 -07:00
|
|
|
}
|
|
|
|
}
|
2018-05-30 21:24:21 -07:00
|
|
|
}
|