Allow metrics rate to differ from log rate (#3993)

And reduce metrics rate for exchange contract counters.
Since we can go 10s-100s thousands of contracts per second,
some metrics would be dropped if submitting every time.
This commit is contained in:
sakridge 2019-04-25 16:58:49 -07:00 committed by GitHub
parent aa0b67c93c
commit fd60ef8a8d
No known key found for this signature in database
GPG Key ID: 4AEE18F83AFDEB23
2 changed files with 43 additions and 26 deletions

View File

@ -5,6 +5,7 @@ use std::env;
use std::sync::atomic::{AtomicUsize, Ordering}; use std::sync::atomic::{AtomicUsize, Ordering};
const DEFAULT_LOG_RATE: usize = 1000; const DEFAULT_LOG_RATE: usize = 1000;
const DEFAULT_METRICS_RATE: usize = 1;
pub struct Counter { pub struct Counter {
pub name: &'static str, pub name: &'static str,
@ -14,18 +15,20 @@ pub struct Counter {
/// last accumulated value logged /// last accumulated value logged
pub lastlog: AtomicUsize, pub lastlog: AtomicUsize,
pub lograte: AtomicUsize, pub lograte: AtomicUsize,
pub metricsrate: AtomicUsize,
pub point: Option<influxdb::Point>, pub point: Option<influxdb::Point>,
} }
#[macro_export] #[macro_export]
macro_rules! create_counter { macro_rules! create_counter {
($name:expr, $lograte:expr) => { ($name:expr, $lograte:expr, $metricsrate:expr) => {
Counter { Counter {
name: $name, name: $name,
counts: std::sync::atomic::AtomicUsize::new(0), counts: std::sync::atomic::AtomicUsize::new(0),
times: std::sync::atomic::AtomicUsize::new(0), times: std::sync::atomic::AtomicUsize::new(0),
lastlog: std::sync::atomic::AtomicUsize::new(0), lastlog: std::sync::atomic::AtomicUsize::new(0),
lograte: std::sync::atomic::AtomicUsize::new($lograte), lograte: std::sync::atomic::AtomicUsize::new($lograte),
metricsrate: std::sync::atomic::AtomicUsize::new($metricsrate),
point: None, point: None,
} }
}; };
@ -47,8 +50,8 @@ macro_rules! inc_counter_info {
#[macro_export] #[macro_export]
macro_rules! inc_new_counter { macro_rules! inc_new_counter {
($name:expr, $count:expr, $level:expr, $lograte:expr) => {{ ($name:expr, $count:expr, $level:expr, $lograte:expr, $metricsrate:expr) => {{
static mut INC_NEW_COUNTER: Counter = create_counter!($name, $lograte); static mut INC_NEW_COUNTER: Counter = create_counter!($name, $lograte, $metricsrate);
static INIT_HOOK: std::sync::Once = std::sync::ONCE_INIT; static INIT_HOOK: std::sync::Once = std::sync::ONCE_INIT;
unsafe { unsafe {
INIT_HOOK.call_once(|| { INIT_HOOK.call_once(|| {
@ -62,10 +65,13 @@ macro_rules! inc_new_counter {
#[macro_export] #[macro_export]
macro_rules! inc_new_counter_info { macro_rules! inc_new_counter_info {
($name:expr, $count:expr) => {{ ($name:expr, $count:expr) => {{
inc_new_counter!($name, $count, log::Level::Info, 0); inc_new_counter!($name, $count, log::Level::Info, 0, 0);
}}; }};
($name:expr, $count:expr, $lograte:expr) => {{ ($name:expr, $count:expr, $lograte:expr) => {{
inc_new_counter!($name, $count, log::Level::Info, $lograte); inc_new_counter!($name, $count, log::Level::Info, $lograte, 0);
}};
($name:expr, $count:expr, $lograte:expr, $metricsrate:expr) => {{
inc_new_counter!($name, $count, log::Level::Info, $lograte, $metricsrate);
}}; }};
} }
@ -95,6 +101,11 @@ impl Counter {
lograte = Counter::default_log_rate(); lograte = Counter::default_log_rate();
self.lograte.store(lograte, Ordering::Relaxed); self.lograte.store(lograte, Ordering::Relaxed);
} }
let mut metricsrate = self.metricsrate.load(Ordering::Relaxed);
if metricsrate == 0 {
metricsrate = DEFAULT_METRICS_RATE;
self.metricsrate.store(metricsrate, Ordering::Relaxed);
}
if times % lograte == 0 && times > 0 && log_enabled!(level) { if times % lograte == 0 && times > 0 && log_enabled!(level) {
log!(level, log!(level,
"COUNTER:{{\"name\": \"{}\", \"counts\": {}, \"samples\": {}, \"now\": {}, \"events\": {}}}", "COUNTER:{{\"name\": \"{}\", \"counts\": {}, \"samples\": {}, \"now\": {}, \"events\": {}}}",
@ -105,20 +116,25 @@ impl Counter {
events, events,
); );
} }
let lastlog = self.lastlog.load(Ordering::Relaxed);
let prev = self if times % metricsrate == 0 && times > 0 {
.lastlog let lastlog = self.lastlog.load(Ordering::Relaxed);
.compare_and_swap(lastlog, counts, Ordering::Relaxed); let prev = self
if prev == lastlog { .lastlog
if let Some(ref mut point) = self.point { .compare_and_swap(lastlog, counts, Ordering::Relaxed);
point if prev == lastlog {
.fields if let Some(ref mut point) = self.point {
.entry("count".to_string()) point
.and_modify(|v| *v = influxdb::Value::Integer(counts as i64 - lastlog as i64)) .fields
.or_insert(influxdb::Value::Integer(0)); .entry("count".to_string())
} .and_modify(|v| {
if let Some(ref mut point) = self.point { *v = influxdb::Value::Integer(counts as i64 - lastlog as i64)
submit(point.to_owned()); })
.or_insert(influxdb::Value::Integer(0));
}
if let Some(ref mut point) = self.point {
submit(point.to_owned());
}
} }
} }
} }
@ -146,7 +162,7 @@ mod tests {
#[test] #[test]
fn test_counter() { fn test_counter() {
let _readlock = get_env_lock().read(); let _readlock = get_env_lock().read();
static mut COUNTER: Counter = create_counter!("test", 1000); static mut COUNTER: Counter = create_counter!("test", 1000, 1);
let count = 1; let count = 1;
inc_counter!(COUNTER, Level::Info, count); inc_counter!(COUNTER, Level::Info, count);
unsafe { unsafe {
@ -173,7 +189,8 @@ mod tests {
//make sure that macros are syntactically correct //make sure that macros are syntactically correct
//the variable is internal to the macro scope so there is no way to introspect it //the variable is internal to the macro scope so there is no way to introspect it
inc_new_counter_info!("counter-1", 1); inc_new_counter_info!("counter-1", 1);
inc_new_counter_info!("counter-2", 1, 2); inc_new_counter_info!("counter-2", 1, 3);
inc_new_counter_info!("counter-3", 1, 2, 1);
} }
#[test] #[test]
fn test_lograte() { fn test_lograte() {
@ -185,7 +202,7 @@ mod tests {
Counter::default_log_rate(), Counter::default_log_rate(),
DEFAULT_LOG_RATE, DEFAULT_LOG_RATE,
); );
static mut COUNTER: Counter = create_counter!("test_lograte", 0); static mut COUNTER: Counter = create_counter!("test_lograte", 0, 1);
inc_counter!(COUNTER, Level::Info, 2); inc_counter!(COUNTER, Level::Info, 2);
unsafe { unsafe {
assert_eq!(COUNTER.lograte.load(Ordering::Relaxed), DEFAULT_LOG_RATE); assert_eq!(COUNTER.lograte.load(Ordering::Relaxed), DEFAULT_LOG_RATE);
@ -196,14 +213,14 @@ mod tests {
fn test_lograte_env() { fn test_lograte_env() {
assert_ne!(DEFAULT_LOG_RATE, 0); assert_ne!(DEFAULT_LOG_RATE, 0);
let _writelock = get_env_lock().write(); let _writelock = get_env_lock().write();
static mut COUNTER: Counter = create_counter!("test_lograte_env", 0); static mut COUNTER: Counter = create_counter!("test_lograte_env", 0, 1);
env::set_var("SOLANA_DEFAULT_LOG_RATE", "50"); env::set_var("SOLANA_DEFAULT_LOG_RATE", "50");
inc_counter!(COUNTER, Level::Info, 2); inc_counter!(COUNTER, Level::Info, 2);
unsafe { unsafe {
assert_eq!(COUNTER.lograte.load(Ordering::Relaxed), 50); assert_eq!(COUNTER.lograte.load(Ordering::Relaxed), 50);
} }
static mut COUNTER2: Counter = create_counter!("test_lograte_env", 0); static mut COUNTER2: Counter = create_counter!("test_lograte_env", 0, 1);
env::set_var("SOLANA_DEFAULT_LOG_RATE", "0"); env::set_var("SOLANA_DEFAULT_LOG_RATE", "0");
inc_counter!(COUNTER2, Level::Info, 2); inc_counter!(COUNTER2, Level::Info, 2);
unsafe { unsafe {

View File

@ -296,7 +296,7 @@ impl ExchangeProcessor {
// Trade holds the tokens in escrow // Trade holds the tokens in escrow
account.tokens[from_token] -= info.tokens; account.tokens[from_token] -= info.tokens;
inc_new_counter_info!("exchange_processor-trades", 1); inc_new_counter_info!("exchange_processor-trades", 1, 1000, 1000);
Self::serialize( Self::serialize(
&ExchangeState::Trade(TradeOrderInfo { &ExchangeState::Trade(TradeOrderInfo {
@ -390,7 +390,7 @@ impl ExchangeProcessor {
Err(e)? Err(e)?
} }
inc_new_counter_info!("exchange_processor-swap", 1); inc_new_counter_info!("exchange_processor-swap", 1, 1000, 1000);
if to_trade.tokens == 0 { if to_trade.tokens == 0 {
// Turn into token account // Turn into token account