solana_metrics/
counter.rs

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

solana_metrics/
counter.rs
