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

solana_metrics/
counter.rs
