solana_metrics/
counter.rs

1use {
2    crate::metrics::submit_counter,
3    log::*,
4    solana_sdk::timing,
5    std::{
6        env,
7        sync::atomic::{AtomicU64, AtomicUsize, Ordering},
8        time::SystemTime,
9    },
10};
11
12const DEFAULT_LOG_RATE: usize = 1000;
13// Submit a datapoint every second by default
14const DEFAULT_METRICS_RATE: u64 = 1000;
15
16pub struct Counter {
17    pub name: &'static str,
18    /// total accumulated value
19    pub counts: AtomicUsize,
20    pub times: AtomicUsize,
21    /// last accumulated value logged
22    pub lastlog: AtomicUsize,
23    pub lograte: AtomicUsize,
24    pub metricsrate: AtomicU64,
25}
26
27#[derive(Clone, Debug)]
28pub struct CounterPoint {
29    pub name: &'static str,
30    pub count: i64,
31    pub timestamp: SystemTime,
32}
33
34impl CounterPoint {
35    pub fn new(name: &'static str) -> Self {
36        CounterPoint {
37            name,
38            count: 0,
39            timestamp: std::time::UNIX_EPOCH,
40        }
41    }
42}
43
44#[macro_export]
45macro_rules! create_counter {
46    ($name:expr, $lograte:expr, $metricsrate:expr) => {
47        $crate::counter::Counter {
48            name: $name,
49            counts: std::sync::atomic::AtomicUsize::new(0),
50            times: std::sync::atomic::AtomicUsize::new(0),
51            lastlog: std::sync::atomic::AtomicUsize::new(0),
52            lograte: std::sync::atomic::AtomicUsize::new($lograte),
53            metricsrate: std::sync::atomic::AtomicU64::new($metricsrate),
54        }
55    };
56}
57
58#[macro_export]
59macro_rules! inc_counter {
60    ($name:expr, $level:expr, $count:expr) => {
61        #[allow(clippy::macro_metavars_in_unsafe)]
62        unsafe {
63            $name.inc($level, $count)
64        };
65    };
66}
67
68#[macro_export]
69macro_rules! inc_counter_info {
70    ($name:expr, $count:expr) => {
71        unsafe {
72            if log_enabled!(log::Level::Info) {
73                $name.inc(log::Level::Info, $count)
74            }
75        };
76    };
77}
78
79#[macro_export]
80macro_rules! inc_new_counter {
81    ($name:expr, $count:expr, $level:expr, $lograte:expr, $metricsrate:expr) => {{
82        if log_enabled!($level) {
83            static mut INC_NEW_COUNTER: $crate::counter::Counter =
84                create_counter!($name, $lograte, $metricsrate);
85            static INIT_HOOK: std::sync::Once = std::sync::Once::new();
86            unsafe {
87                INIT_HOOK.call_once(|| {
88                    INC_NEW_COUNTER.init();
89                });
90            }
91            inc_counter!(INC_NEW_COUNTER, $level, $count);
92        }
93    }};
94}
95
96#[macro_export]
97macro_rules! inc_new_counter_error {
98    ($name:expr, $count:expr) => {{
99        inc_new_counter!($name, $count, log::Level::Error, 0, 0);
100    }};
101    ($name:expr, $count:expr, $lograte:expr) => {{
102        inc_new_counter!($name, $count, log::Level::Error, $lograte, 0);
103    }};
104    ($name:expr, $count:expr, $lograte:expr, $metricsrate:expr) => {{
105        inc_new_counter!($name, $count, log::Level::Error, $lograte, $metricsrate);
106    }};
107}
108
109#[macro_export]
110macro_rules! inc_new_counter_warn {
111    ($name:expr, $count:expr) => {{
112        inc_new_counter!($name, $count, log::Level::Warn, 0, 0);
113    }};
114    ($name:expr, $count:expr, $lograte:expr) => {{
115        inc_new_counter!($name, $count, log::Level::Warn, $lograte, 0);
116    }};
117    ($name:expr, $count:expr, $lograte:expr, $metricsrate:expr) => {{
118        inc_new_counter!($name, $count, log::Level::Warn, $lograte, $metricsrate);
119    }};
120}
121
122#[macro_export]
123macro_rules! inc_new_counter_info {
124    ($name:expr, $count:expr) => {{
125        inc_new_counter!($name, $count, log::Level::Info, 0, 0);
126    }};
127    ($name:expr, $count:expr, $lograte:expr) => {{
128        inc_new_counter!($name, $count, log::Level::Info, $lograte, 0);
129    }};
130    ($name:expr, $count:expr, $lograte:expr, $metricsrate:expr) => {{
131        inc_new_counter!($name, $count, log::Level::Info, $lograte, $metricsrate);
132    }};
133}
134
135#[macro_export]
136macro_rules! inc_new_counter_debug {
137    ($name:expr, $count:expr) => {{
138        inc_new_counter!($name, $count, log::Level::Debug, 0, 0);
139    }};
140    ($name:expr, $count:expr, $lograte:expr) => {{
141        inc_new_counter!($name, $count, log::Level::Debug, $lograte, 0);
142    }};
143    ($name:expr, $count:expr, $lograte:expr, $metricsrate:expr) => {{
144        inc_new_counter!($name, $count, log::Level::Debug, $lograte, $metricsrate);
145    }};
146}
147
148impl Counter {
149    fn default_metrics_rate() -> u64 {
150        let v = env::var("SOLANA_DEFAULT_METRICS_RATE")
151            .map(|x| x.parse().unwrap_or(0))
152            .unwrap_or(0);
153        if v == 0 {
154            DEFAULT_METRICS_RATE
155        } else {
156            v
157        }
158    }
159    fn default_log_rate() -> usize {
160        let v = env::var("SOLANA_DEFAULT_LOG_RATE")
161            .map(|x| x.parse().unwrap_or(DEFAULT_LOG_RATE))
162            .unwrap_or(DEFAULT_LOG_RATE);
163        if v == 0 {
164            DEFAULT_LOG_RATE
165        } else {
166            v
167        }
168    }
169    pub fn init(&mut self) {
170        #![allow(deprecated)]
171        self.lograte
172            .compare_and_swap(0, Self::default_log_rate(), Ordering::Relaxed);
173        self.metricsrate
174            .compare_and_swap(0, Self::default_metrics_rate(), Ordering::Relaxed);
175    }
176    pub fn inc(&mut self, level: log::Level, events: usize) {
177        let now = timing::timestamp();
178        let counts = self.counts.fetch_add(events, Ordering::Relaxed);
179        let times = self.times.fetch_add(1, Ordering::Relaxed);
180        let lograte = self.lograte.load(Ordering::Relaxed);
181        let metricsrate = self.metricsrate.load(Ordering::Relaxed);
182
183        if times % lograte == 0 && times > 0 && log_enabled!(level) {
184            log!(level,
185                "COUNTER:{{\"name\": \"{}\", \"counts\": {}, \"samples\": {},  \"now\": {}, \"events\": {}}}",
186                self.name,
187                counts + events,
188                times,
189                now,
190                events,
191            );
192        }
193
194        let lastlog = self.lastlog.load(Ordering::Relaxed);
195        #[allow(deprecated)]
196        let prev = self
197            .lastlog
198            .compare_and_swap(lastlog, counts, Ordering::Relaxed);
199        if prev == lastlog {
200            let bucket = now / metricsrate;
201            let counter = CounterPoint {
202                name: self.name,
203                count: counts as i64 - lastlog as i64,
204                timestamp: SystemTime::now(),
205            };
206            submit_counter(counter, level, bucket);
207        }
208    }
209}
210#[cfg(test)]
211mod tests {
212    use {
213        crate::counter::{Counter, DEFAULT_LOG_RATE, DEFAULT_METRICS_RATE},
214        log::{Level, *},
215        serial_test::serial,
216        std::{
217            env,
218            sync::{atomic::Ordering, Once, RwLock},
219        },
220    };
221
222    fn get_env_lock() -> &'static RwLock<()> {
223        static mut ENV_LOCK: Option<RwLock<()>> = None;
224        static INIT_HOOK: Once = Once::new();
225
226        unsafe {
227            INIT_HOOK.call_once(|| {
228                ENV_LOCK = Some(RwLock::new(()));
229            });
230            ENV_LOCK.as_ref().unwrap()
231        }
232    }
233
234    /// Try to initialize the logger with a filter level of INFO.
235    ///
236    /// Incrementing a counter only happens if the logger is configured for the
237    /// given log level, so the tests need an INFO logger to pass.
238    fn try_init_logger_at_level_info() -> Result<(), log::SetLoggerError> {
239        // Use ::new() to configure the logger manually, instead of using the
240        // default of reading the RUST_LOG environment variable. Set is_test to
241        // print to stdout captured by the test runner, instead of polluting the
242        // test runner output.
243        let module_limit = None;
244        env_logger::Builder::new()
245            .filter(module_limit, log::LevelFilter::Info)
246            .is_test(true)
247            .try_init()
248    }
249
250    #[test]
251    #[serial]
252    fn test_counter() {
253        try_init_logger_at_level_info().ok();
254        let _readlock = get_env_lock().read();
255        static mut COUNTER: Counter = create_counter!("test", 1000, 1);
256        unsafe {
257            COUNTER.init();
258        }
259        let count = 1;
260        inc_counter!(COUNTER, Level::Info, count);
261        unsafe {
262            assert_eq!(COUNTER.counts.load(Ordering::Relaxed), 1);
263            assert_eq!(COUNTER.times.load(Ordering::Relaxed), 1);
264            assert_eq!(COUNTER.lograte.load(Ordering::Relaxed), 1000);
265            assert_eq!(COUNTER.lastlog.load(Ordering::Relaxed), 0);
266            assert_eq!(COUNTER.name, "test");
267        }
268        for _ in 0..199 {
269            inc_counter!(COUNTER, Level::Info, 2);
270        }
271        unsafe {
272            assert_eq!(COUNTER.lastlog.load(Ordering::Relaxed), 397);
273        }
274        inc_counter!(COUNTER, Level::Info, 2);
275        unsafe {
276            assert_eq!(COUNTER.lastlog.load(Ordering::Relaxed), 399);
277        }
278    }
279
280    #[test]
281    #[serial]
282    fn test_metricsrate() {
283        try_init_logger_at_level_info().ok();
284        let _readlock = get_env_lock().read();
285        env::remove_var("SOLANA_DEFAULT_METRICS_RATE");
286        static mut COUNTER: Counter = create_counter!("test", 1000, 0);
287        unsafe {
288            COUNTER.init();
289            assert_eq!(
290                COUNTER.metricsrate.load(Ordering::Relaxed),
291                DEFAULT_METRICS_RATE
292            );
293        }
294    }
295
296    #[test]
297    #[serial]
298    fn test_metricsrate_env() {
299        try_init_logger_at_level_info().ok();
300        let _writelock = get_env_lock().write();
301        env::set_var("SOLANA_DEFAULT_METRICS_RATE", "50");
302        static mut COUNTER: Counter = create_counter!("test", 1000, 0);
303        unsafe {
304            COUNTER.init();
305            assert_eq!(COUNTER.metricsrate.load(Ordering::Relaxed), 50);
306        }
307    }
308
309    #[test]
310    #[serial]
311    fn test_inc_new_counter() {
312        let _readlock = get_env_lock().read();
313        //make sure that macros are syntactically correct
314        //the variable is internal to the macro scope so there is no way to introspect it
315        inc_new_counter_info!("1", 1);
316        inc_new_counter_info!("2", 1, 3);
317        inc_new_counter_info!("3", 1, 2, 1);
318    }
319
320    #[test]
321    #[serial]
322    fn test_lograte() {
323        try_init_logger_at_level_info().ok();
324        let _readlock = get_env_lock().read();
325        assert_eq!(
326            Counter::default_log_rate(),
327            DEFAULT_LOG_RATE,
328            "default_log_rate() is {}, expected {}, SOLANA_DEFAULT_LOG_RATE environment variable set?",
329            Counter::default_log_rate(),
330            DEFAULT_LOG_RATE,
331        );
332        static mut COUNTER: Counter = create_counter!("test_lograte", 0, 1);
333        unsafe {
334            COUNTER.init();
335            assert_eq!(COUNTER.lograte.load(Ordering::Relaxed), DEFAULT_LOG_RATE);
336        }
337    }
338
339    #[test]
340    #[serial]
341    fn test_lograte_env() {
342        try_init_logger_at_level_info().ok();
343        assert_ne!(DEFAULT_LOG_RATE, 0);
344        let _writelock = get_env_lock().write();
345        static mut COUNTER: Counter = create_counter!("test_lograte_env", 0, 1);
346        env::set_var("SOLANA_DEFAULT_LOG_RATE", "50");
347        unsafe {
348            COUNTER.init();
349            assert_eq!(COUNTER.lograte.load(Ordering::Relaxed), 50);
350        }
351
352        static mut COUNTER2: Counter = create_counter!("test_lograte_env", 0, 1);
353        env::set_var("SOLANA_DEFAULT_LOG_RATE", "0");
354        unsafe {
355            COUNTER2.init();
356            assert_eq!(COUNTER2.lograte.load(Ordering::Relaxed), DEFAULT_LOG_RATE);
357        }
358    }
359}
solana_metrics/counter.rs

solana_metrics/
counter.rs
