typed_store/
metrics.rs

1// Copyright (c) Mysten Labs, Inc.
2// Modifications Copyright (c) 2024 IOTA Stiftung
3// SPDX-License-Identifier: Apache-2.0
4
5use std::{
6    cell::RefCell,
7    sync::{
8        Arc,
9        atomic::{AtomicU64, Ordering},
10    },
11    time::Duration,
12};
13
14use once_cell::sync::OnceCell;
15use prometheus_filtered::{
16    HistogramVec, IntCounterVec, IntGaugeVec, MetricLevel, Registry,
17    register_histogram_vec_with_registry, register_int_counter_vec_with_registry,
18    register_int_gauge_vec_with_registry,
19};
20use rocksdb::{PerfContext, PerfMetric, PerfStatsLevel, perf::set_perf_stats};
21use tap::TapFallible;
22use tracing::warn;
23
24thread_local! {
25    static PER_THREAD_ROCKS_PERF_CONTEXT: std::cell::RefCell<rocksdb::PerfContext>  = RefCell::new(PerfContext::default());
26}
27
28const LATENCY_SEC_BUCKETS: &[f64] = &[
29    0.00001, 0.00005, // 10 mcs, 50 mcs
30    0.0001, 0.0002, 0.0003, 0.0004, 0.0005, // 100..500 mcs
31    0.001, 0.002, 0.003, 0.004, 0.005, // 1..5ms
32    0.01, 0.025, 0.05, 0.1, 0.25, 0.5, 1., 2.5, 5., 10.,
33];
34
35#[derive(Debug, Clone)]
36// A struct for sampling based on number of operations or duration.
37// Sampling happens if the duration expires and after number of operations
38pub struct SamplingInterval {
39    // Sample once every time duration
40    pub once_every_duration: Duration,
41    // Sample once every number of operations
42    pub after_num_ops: u64,
43    // Counter for keeping track of previous sample
44    pub counter: Arc<AtomicU64>,
45}
46
47impl Default for SamplingInterval {
48    fn default() -> Self {
49        // Enabled with 60 second interval
50        SamplingInterval::new(Duration::from_secs(60), 0)
51    }
52}
53
54impl SamplingInterval {
55    pub fn new(once_every_duration: Duration, after_num_ops: u64) -> Self {
56        let counter = Arc::new(AtomicU64::new(1));
57        if !once_every_duration.is_zero() {
58            let counter = Arc::downgrade(&counter);
59            tokio::task::spawn(async move {
60                while let Some(counter) = counter.upgrade() {
61                    if counter.load(Ordering::SeqCst) > after_num_ops {
62                        counter.store(0, Ordering::SeqCst);
63                    }
64                    drop(counter);
65                    tokio::time::sleep(once_every_duration).await;
66                }
67            });
68        }
69        SamplingInterval {
70            once_every_duration,
71            after_num_ops,
72            counter,
73        }
74    }
75    pub fn new_from_self(&self) -> SamplingInterval {
76        SamplingInterval::new(self.once_every_duration, self.after_num_ops)
77    }
78    pub fn sample(&self) -> bool {
79        if self.once_every_duration.is_zero() {
80            self.counter
81                .fetch_add(1, Ordering::Relaxed)
82                .is_multiple_of(self.after_num_ops + 1)
83        } else {
84            self.counter.fetch_add(1, Ordering::Relaxed) == 0
85        }
86    }
87}
88
89#[derive(Debug)]
90pub struct ColumnFamilyMetrics {
91    pub rocksdb_total_sst_files_size: IntGaugeVec,
92    pub rocksdb_total_blob_files_size: IntGaugeVec,
93    pub rocksdb_total_num_files: IntGaugeVec,
94    pub rocksdb_num_level0_files: IntGaugeVec,
95    pub rocksdb_current_size_active_mem_tables: IntGaugeVec,
96    pub rocksdb_size_all_mem_tables: IntGaugeVec,
97    pub rocksdb_num_snapshots: IntGaugeVec,
98    pub rocksdb_oldest_snapshot_time: IntGaugeVec,
99    pub rocksdb_actual_delayed_write_rate: IntGaugeVec,
100    pub rocksdb_is_write_stopped: IntGaugeVec,
101    pub rocksdb_block_cache_capacity: IntGaugeVec,
102    pub rocksdb_block_cache_usage: IntGaugeVec,
103    pub rocksdb_block_cache_pinned_usage: IntGaugeVec,
104    pub rocksdb_estimate_table_readers_mem: IntGaugeVec,
105    pub rocksdb_num_immutable_mem_tables: IntGaugeVec,
106    pub rocksdb_mem_table_flush_pending: IntGaugeVec,
107    pub rocksdb_compaction_pending: IntGaugeVec,
108    pub rocksdb_estimate_pending_compaction_bytes: IntGaugeVec,
109    pub rocksdb_num_running_compactions: IntGaugeVec,
110    pub rocksdb_num_running_flushes: IntGaugeVec,
111    pub rocksdb_estimate_oldest_key_time: IntGaugeVec,
112    pub rocksdb_background_errors: IntGaugeVec,
113    pub rocksdb_estimated_num_keys: IntGaugeVec,
114    pub rocksdb_base_level: IntGaugeVec,
115}
116
117impl ColumnFamilyMetrics {
118    pub(crate) fn new(registry: &Registry) -> Self {
119        ColumnFamilyMetrics {
120            rocksdb_total_sst_files_size: register_int_gauge_vec_with_registry!(
121                "rocksdb_total_sst_files_size",
122                "The storage size occupied by the sst files in the column family",
123                &["cf_name"],
124                registry;
125                MetricLevel::Trace,
126            )
127            .unwrap(),
128            rocksdb_total_blob_files_size: register_int_gauge_vec_with_registry!(
129                "rocksdb_total_blob_files_size",
130                "The storage size occupied by the blob files in the column family",
131                &["cf_name"],
132                registry;
133                MetricLevel::Trace,
134            )
135            .unwrap(),
136            rocksdb_total_num_files: register_int_gauge_vec_with_registry!(
137                "rocksdb_total_num_files",
138                "Total number of files used in the column family",
139                &["cf_name"],
140                registry;
141                MetricLevel::Trace,
142            )
143            .unwrap(),
144            rocksdb_num_level0_files: register_int_gauge_vec_with_registry!(
145                "rocksdb_num_level0_files",
146                "Number of level 0 files in the column family",
147                &["cf_name"],
148                registry;
149                MetricLevel::Trace,
150            )
151            .unwrap(),
152            rocksdb_current_size_active_mem_tables: register_int_gauge_vec_with_registry!(
153                "rocksdb_current_size_active_mem_tables",
154                "The current approximate size of active memtable (bytes).",
155                &["cf_name"],
156                registry;
157                MetricLevel::Trace,
158            )
159            .unwrap(),
160            rocksdb_size_all_mem_tables: register_int_gauge_vec_with_registry!(
161                "rocksdb_size_all_mem_tables",
162                "The memory size occupied by the column family's in-memory buffer",
163                &["cf_name"],
164                registry;
165                MetricLevel::Trace,
166            )
167            .unwrap(),
168            rocksdb_num_snapshots: register_int_gauge_vec_with_registry!(
169                "rocksdb_num_snapshots",
170                "Number of snapshots held for the column family",
171                &["cf_name"],
172                registry;
173                MetricLevel::Trace,
174            )
175            .unwrap(),
176            rocksdb_oldest_snapshot_time: register_int_gauge_vec_with_registry!(
177                "rocksdb_oldest_snapshot_time",
178                "Unit timestamp of the oldest unreleased snapshot",
179                &["cf_name"],
180                registry;
181                MetricLevel::Trace,
182            )
183            .unwrap(),
184            rocksdb_actual_delayed_write_rate: register_int_gauge_vec_with_registry!(
185                "rocksdb_actual_delayed_write_rate",
186                "The current actual delayed write rate. 0 means no delay",
187                &["cf_name"],
188                registry;
189                MetricLevel::Trace,
190            )
191            .unwrap(),
192            rocksdb_is_write_stopped: register_int_gauge_vec_with_registry!(
193                "rocksdb_is_write_stopped",
194                "A flag indicating whether writes are stopped on this column family. 1 indicates writes have been stopped.",
195                &["cf_name"],
196                registry;
197                MetricLevel::Trace,
198            )
199            .unwrap(),
200            rocksdb_block_cache_capacity: register_int_gauge_vec_with_registry!(
201                "rocksdb_block_cache_capacity",
202                "The block cache capacity of the column family.",
203                &["cf_name"],
204                registry;
205                MetricLevel::Trace,
206            )
207            .unwrap(),
208            rocksdb_block_cache_usage: register_int_gauge_vec_with_registry!(
209                "rocksdb_block_cache_usage",
210                "The memory size used by the column family in the block cache.",
211                &["cf_name"],
212                registry;
213                MetricLevel::Trace,
214            )
215            .unwrap(),
216            rocksdb_block_cache_pinned_usage: register_int_gauge_vec_with_registry!(
217                "rocksdb_block_cache_pinned_usage",
218                "The memory size used by the column family in the block cache where entries are pinned",
219                &["cf_name"],
220                registry;
221                MetricLevel::Trace,
222            )
223            .unwrap(),
224            rocksdb_estimate_table_readers_mem: register_int_gauge_vec_with_registry!(
225                "rocksdb_estimate_table_readers_mem",
226                "The estimated memory size used for reading SST tables in this column
227                family such as filters and index blocks. Note that this number does not
228                include the memory used in block cache.",
229                &["cf_name"],
230                registry;
231                MetricLevel::Trace,
232            )
233            .unwrap(),
234            rocksdb_num_immutable_mem_tables: register_int_gauge_vec_with_registry!(
235                "rocksdb_num_immutable_mem_tables",
236                "The number of immutable memtables that have not yet been flushed.",
237                &["cf_name"],
238                registry;
239                MetricLevel::Trace,
240            )
241            .unwrap(),
242            rocksdb_mem_table_flush_pending: register_int_gauge_vec_with_registry!(
243                "rocksdb_mem_table_flush_pending",
244                "A 1 or 0 flag indicating whether a memtable flush is pending.
245                If this number is 1, it means a memtable is waiting for being flushed,
246                but there might be too many L0 files that prevents it from being flushed.",
247                &["cf_name"],
248                registry;
249                MetricLevel::Trace,
250            )
251            .unwrap(),
252            rocksdb_compaction_pending: register_int_gauge_vec_with_registry!(
253                "rocksdb_compaction_pending",
254                "A 1 or 0 flag indicating whether a compaction job is pending.
255                If this number is 1, it means some part of the column family requires
256                compaction in order to maintain shape of LSM tree, but the compaction
257                is pending because the desired compaction job is either waiting for
258                other dependent compactions to be finished or waiting for an available
259                compaction thread.",
260                &["cf_name"],
261                registry;
262                MetricLevel::Trace,
263            )
264            .unwrap(),
265            rocksdb_estimate_pending_compaction_bytes: register_int_gauge_vec_with_registry!(
266                "rocksdb_estimate_pending_compaction_bytes",
267                "Estimated total number of bytes compaction needs to rewrite to get all levels down
268                to under target size. Not valid for other compactions than level-based.",
269                &["cf_name"],
270                registry;
271                MetricLevel::Trace,
272            )
273            .unwrap(),
274            rocksdb_num_running_compactions: register_int_gauge_vec_with_registry!(
275                "rocksdb_num_running_compactions",
276                "The number of compactions that are currently running for the column family.",
277                &["cf_name"],
278                registry;
279                MetricLevel::Trace,
280            )
281            .unwrap(),
282            rocksdb_num_running_flushes: register_int_gauge_vec_with_registry!(
283                "rocksdb_num_running_flushes",
284                "The number of flushes that are currently running for the column family.",
285                &["cf_name"],
286                registry;
287                MetricLevel::Trace,
288            )
289            .unwrap(),
290            rocksdb_estimate_oldest_key_time: register_int_gauge_vec_with_registry!(
291                "rocksdb_estimate_oldest_key_time",
292                "Estimation of the oldest key timestamp in the DB. Only available
293                for FIFO compaction with compaction_options_fifo.allow_compaction = false.",
294                &["cf_name"],
295                registry;
296                MetricLevel::Trace,
297            )
298            .unwrap(),
299            rocksdb_estimated_num_keys: register_int_gauge_vec_with_registry!(
300                "rocksdb_estimated_num_keys",
301                "The estimated number of keys in the table",
302                &["cf_name"],
303                registry;
304                MetricLevel::Trace,
305            )
306            .unwrap(),
307            rocksdb_background_errors: register_int_gauge_vec_with_registry!(
308                "rocksdb_background_errors",
309                "The accumulated number of RocksDB background errors.",
310                &["cf_name"],
311                registry;
312                MetricLevel::Trace,
313            )
314            .unwrap(),
315            rocksdb_base_level: register_int_gauge_vec_with_registry!(
316                "rocksdb_base_level",
317                "The number of level to which L0 data will be compacted.",
318                &["cf_name"],
319                registry;
320                MetricLevel::Trace,
321            )
322            .unwrap(),
323        }
324    }
325}
326
327#[derive(Debug)]
328pub struct OperationMetrics {
329    pub rocksdb_iter_latency_seconds: HistogramVec,
330    pub rocksdb_iter_bytes: HistogramVec,
331    pub rocksdb_iter_keys: HistogramVec,
332    pub rocksdb_get_latency_seconds: HistogramVec,
333    pub rocksdb_get_bytes: HistogramVec,
334    pub rocksdb_multiget_latency_seconds: HistogramVec,
335    pub rocksdb_multiget_bytes: HistogramVec,
336    pub rocksdb_put_latency_seconds: HistogramVec,
337    pub rocksdb_put_bytes: HistogramVec,
338    pub rocksdb_batch_put_bytes: HistogramVec,
339    pub rocksdb_delete_latency_seconds: HistogramVec,
340    pub rocksdb_deletes: IntCounterVec,
341    pub rocksdb_batch_commit_latency_seconds: HistogramVec,
342    pub rocksdb_batch_commit_bytes: HistogramVec,
343    pub rocksdb_num_active_db_handles: IntGaugeVec,
344    pub rocksdb_very_slow_batch_writes_count: IntCounterVec,
345    pub rocksdb_very_slow_batch_writes_duration_ms: IntCounterVec,
346    pub rocksdb_very_slow_puts_count: IntCounterVec,
347    pub rocksdb_very_slow_puts_duration_ms: IntCounterVec,
348}
349
350impl OperationMetrics {
351    pub(crate) fn new(registry: &Registry) -> Self {
352        OperationMetrics {
353            rocksdb_iter_latency_seconds: register_histogram_vec_with_registry!(
354                "rocksdb_iter_latency_seconds",
355                "Rocksdb iter latency in seconds",
356                &["cf_name"],
357                LATENCY_SEC_BUCKETS.to_vec(),
358                registry;
359                MetricLevel::Trace,
360            )
361            .unwrap(),
362            rocksdb_iter_bytes: register_histogram_vec_with_registry!(
363                "rocksdb_iter_bytes",
364                "Rocksdb iter size in bytes",
365                &["cf_name"],
366                prometheus_filtered::exponential_buckets(1.0, 4.0, 15)
367                    .unwrap()
368                    .to_vec(),
369                registry;
370                MetricLevel::Trace,
371            )
372            .unwrap(),
373            rocksdb_iter_keys: register_histogram_vec_with_registry!(
374                "rocksdb_iter_keys",
375                "Rocksdb iter num keys",
376                &["cf_name"],
377                registry;
378                MetricLevel::Trace,
379            )
380            .unwrap(),
381            rocksdb_get_latency_seconds: register_histogram_vec_with_registry!(
382                "rocksdb_get_latency_seconds",
383                "Rocksdb get latency in seconds",
384                &["cf_name"],
385                LATENCY_SEC_BUCKETS.to_vec(),
386                registry;
387                MetricLevel::Trace,
388            )
389            .unwrap(),
390            rocksdb_get_bytes: register_histogram_vec_with_registry!(
391                "rocksdb_get_bytes",
392                "Rocksdb get call returned data size in bytes",
393                &["cf_name"],
394                prometheus_filtered::exponential_buckets(1.0, 4.0, 15)
395                    .unwrap()
396                    .to_vec(),
397                registry;
398                MetricLevel::Trace,
399            )
400            .unwrap(),
401            rocksdb_multiget_latency_seconds: register_histogram_vec_with_registry!(
402                "rocksdb_multiget_latency_seconds",
403                "Rocksdb multiget latency in seconds",
404                &["cf_name"],
405                LATENCY_SEC_BUCKETS.to_vec(),
406                registry;
407                MetricLevel::Trace,
408            )
409            .unwrap(),
410            rocksdb_multiget_bytes: register_histogram_vec_with_registry!(
411                "rocksdb_multiget_bytes",
412                "Rocksdb multiget call returned data size in bytes",
413                &["cf_name"],
414                prometheus_filtered::exponential_buckets(1.0, 4.0, 15)
415                    .unwrap()
416                    .to_vec(),
417                registry;
418                MetricLevel::Trace,
419            )
420            .unwrap(),
421            rocksdb_put_latency_seconds: register_histogram_vec_with_registry!(
422                "rocksdb_put_latency_seconds",
423                "Rocksdb put latency in seconds",
424                &["cf_name"],
425                LATENCY_SEC_BUCKETS.to_vec(),
426                registry;
427                MetricLevel::Trace,
428            )
429            .unwrap(),
430            rocksdb_put_bytes: register_histogram_vec_with_registry!(
431                "rocksdb_put_bytes",
432                "Rocksdb put call puts data size in bytes",
433                &["cf_name"],
434                prometheus_filtered::exponential_buckets(1.0, 4.0, 15)
435                    .unwrap()
436                    .to_vec(),
437                registry;
438                MetricLevel::Trace,
439            )
440            .unwrap(),
441            rocksdb_batch_put_bytes: register_histogram_vec_with_registry!(
442                "rocksdb_batch_put_bytes",
443                "Rocksdb batch put call puts data size in bytes",
444                &["cf_name"],
445                prometheus_filtered::exponential_buckets(1.0, 4.0, 15)
446                    .unwrap()
447                    .to_vec(),
448                registry;
449                MetricLevel::Trace,
450            )
451            .unwrap(),
452            rocksdb_delete_latency_seconds: register_histogram_vec_with_registry!(
453                "rocksdb_delete_latency_seconds",
454                "Rocksdb delete latency in seconds",
455                &["cf_name"],
456                LATENCY_SEC_BUCKETS.to_vec(),
457                registry;
458                MetricLevel::Trace,
459            )
460            .unwrap(),
461            rocksdb_deletes: register_int_counter_vec_with_registry!(
462                "rocksdb_deletes",
463                "Rocksdb delete calls",
464                &["cf_name"],
465                registry;
466                MetricLevel::Trace,
467            )
468            .unwrap(),
469            rocksdb_batch_commit_latency_seconds: register_histogram_vec_with_registry!(
470                "rocksdb_write_batch_commit_latency_seconds",
471                "Rocksdb schema batch commit latency in seconds",
472                &["db_name"],
473                LATENCY_SEC_BUCKETS.to_vec(),
474                registry;
475                MetricLevel::Trace,
476            )
477            .unwrap(),
478            rocksdb_batch_commit_bytes: register_histogram_vec_with_registry!(
479                "rocksdb_batch_commit_bytes",
480                "Rocksdb schema batch commit size in bytes",
481                &["db_name"],
482                prometheus_filtered::exponential_buckets(1.0, 4.0, 15)
483                    .unwrap()
484                    .to_vec(),
485                registry;
486                MetricLevel::Trace,
487            )
488            .unwrap(),
489            rocksdb_num_active_db_handles: register_int_gauge_vec_with_registry!(
490                "rocksdb_num_active_db_handles",
491                "Number of active db handles",
492                &["db_name"],
493                registry;
494                MetricLevel::Trace,
495            )
496            .unwrap(),
497            rocksdb_very_slow_batch_writes_count: register_int_counter_vec_with_registry!(
498                "rocksdb_num_very_slow_batch_writes",
499                "Number of batch writes that took more than 1 second and were slower than 32 MiB/s",
500                &["db_name"],
501                registry;
502                MetricLevel::Trace,
503            )
504            .unwrap(),
505            rocksdb_very_slow_batch_writes_duration_ms: register_int_counter_vec_with_registry!(
506                "rocksdb_very_slow_batch_writes_duration",
507                "Total time in milliseconds spent on batch writes that took more than 1 second and were slower than 32 MiB/s",
508                &["db_name"],
509                registry;
510                MetricLevel::Trace,
511            )
512            .unwrap(),
513            rocksdb_very_slow_puts_count: register_int_counter_vec_with_registry!(
514                "rocksdb_num_very_slow_puts",
515                "Number of puts that took more than 1 second",
516                &["cf_name"],
517                registry;
518                MetricLevel::Trace,
519            )
520            .unwrap(),
521            rocksdb_very_slow_puts_duration_ms: register_int_counter_vec_with_registry!(
522                "rocksdb_very_slow_puts_duration",
523                "Total time in milliseconds spent on puts that took more than 1 second",
524                &["cf_name"],
525                registry;
526                MetricLevel::Trace,
527            )
528            .unwrap(),
529        }
530    }
531}
532
533pub struct RocksDBPerfContext;
534
535impl Default for RocksDBPerfContext {
536    fn default() -> Self {
537        set_perf_stats(PerfStatsLevel::EnableTime);
538        PER_THREAD_ROCKS_PERF_CONTEXT.with(|perf_context| {
539            perf_context.borrow_mut().reset();
540        });
541        RocksDBPerfContext {}
542    }
543}
544
545impl Drop for RocksDBPerfContext {
546    fn drop(&mut self) {
547        set_perf_stats(PerfStatsLevel::Disable);
548    }
549}
550
551#[derive(Debug)]
552pub struct ReadPerfContextMetrics {
553    pub user_key_comparison_count: IntCounterVec,
554    pub block_cache_hit_count: IntCounterVec,
555    pub block_read_count: IntCounterVec,
556    pub block_read_byte: IntCounterVec,
557    pub block_read_nanos: IntCounterVec,
558    pub block_checksum_nanos: IntCounterVec,
559    pub block_decompress_nanos: IntCounterVec,
560    pub get_read_bytes: IntCounterVec,
561    pub multiget_read_bytes: IntCounterVec,
562    pub get_snapshot_nanos: IntCounterVec,
563    pub get_from_memtable_nanos: IntCounterVec,
564    pub get_from_memtable_count: IntCounterVec,
565    pub get_post_process_nanos: IntCounterVec,
566    pub get_from_output_files_nanos: IntCounterVec,
567    pub db_mutex_lock_nanos: IntCounterVec,
568    pub db_condition_wait_nanos: IntCounterVec,
569    pub merge_operator_nanos: IntCounterVec,
570    pub read_index_block_nanos: IntCounterVec,
571    pub read_filter_block_nanos: IntCounterVec,
572    pub new_table_block_iter_nanos: IntCounterVec,
573    pub block_seek_nanos: IntCounterVec,
574    pub find_table_nanos: IntCounterVec,
575    pub bloom_memtable_hit_count: IntCounterVec,
576    pub bloom_memtable_miss_count: IntCounterVec,
577    pub bloom_sst_hit_count: IntCounterVec,
578    pub bloom_sst_miss_count: IntCounterVec,
579    pub key_lock_wait_time: IntCounterVec,
580    pub key_lock_wait_count: IntCounterVec,
581    pub internal_delete_skipped_count: IntCounterVec,
582    pub internal_skipped_count: IntCounterVec,
583}
584
585impl ReadPerfContextMetrics {
586    pub(crate) fn new(registry: &Registry) -> Self {
587        ReadPerfContextMetrics {
588            user_key_comparison_count: register_int_counter_vec_with_registry!(
589                "user_key_comparison_count",
590                "Helps us figure out whether too many comparisons in binary search can be a problem,
591                especially when a more expensive comparator is used. Moreover, since number of comparisons
592                is usually uniform based on the memtable size, the SST file size for Level 0 and size of other
593                levels, an significant increase of the counter can indicate unexpected LSM-tree shape.
594                You may want to check whether flush/compaction can keep up with the write speed",
595                &["cf_name"],
596                registry;
597                MetricLevel::Trace,
598            )
599            .unwrap(),
600            block_cache_hit_count: register_int_counter_vec_with_registry!(
601                "block_cache_hit_count",
602                "Tells us how many times we read data blocks from block cache, and block_read_count tells us how many
603                times we have to read blocks from the file system (either block cache is disabled or it is a cache miss).
604                We can evaluate the block cache efficiency by looking at the two counters over time.",
605                &["cf_name"],
606                registry;
607                MetricLevel::Trace,
608            )
609            .unwrap(),
610            block_read_count: register_int_counter_vec_with_registry!(
611                "block_read_count",
612                "Tells us how many times we have to read blocks from the file system (either block cache is disabled or it is a cache miss)",
613                &["cf_name"],
614                registry;
615                MetricLevel::Trace,
616            )
617            .unwrap(),
618            block_read_byte: register_int_counter_vec_with_registry!(
619                "block_read_byte",
620                "Tells us how many total bytes we read from the file system. It can tell us whether a slow query can be caused by reading
621                large blocks from the file system. Index and bloom filter blocks are usually large blocks. A large block can also be the result
622                of a very large key or value",
623                &["cf_name"],
624                registry;
625                MetricLevel::Trace,
626            )
627            .unwrap(),
628            block_read_nanos: register_int_counter_vec_with_registry!(
629                "block_read_nanos",
630                "Total nanos spent on block reads",
631                &["cf_name"],
632                registry;
633                MetricLevel::Trace,
634            )
635            .unwrap(),
636            block_checksum_nanos: register_int_counter_vec_with_registry!(
637                "block_checksum_nanos",
638                "Total nanos spent on verifying block checksum",
639                &["cf_name"],
640                registry;
641                MetricLevel::Trace,
642            )
643            .unwrap(),
644            block_decompress_nanos: register_int_counter_vec_with_registry!(
645                "block_decompress_nanos",
646                "Total nanos spent on decompressing a block",
647                &["cf_name"],
648                registry;
649                MetricLevel::Trace,
650            )
651            .unwrap(),
652            get_read_bytes: register_int_counter_vec_with_registry!(
653                "get_read_bytes",
654                "Total bytes for values returned by Get",
655                &["cf_name"],
656                registry;
657                MetricLevel::Trace,
658            )
659            .unwrap(),
660            multiget_read_bytes: register_int_counter_vec_with_registry!(
661                "multiget_read_bytes",
662                "Total bytes for values returned by MultiGet.",
663                &["cf_name"],
664                registry;
665                MetricLevel::Trace,
666            )
667            .unwrap(),
668            get_snapshot_nanos: register_int_counter_vec_with_registry!(
669                "get_snapshot_nanos",
670                "Time spent in getting snapshot.",
671                &["cf_name"],
672                registry;
673                MetricLevel::Trace,
674            )
675            .unwrap(),
676            get_from_memtable_nanos: register_int_counter_vec_with_registry!(
677                "get_from_memtable_nanos",
678                "Time spent on reading data from memtable.",
679                &["cf_name"],
680                registry;
681                MetricLevel::Trace,
682            )
683            .unwrap(),
684            get_from_memtable_count: register_int_counter_vec_with_registry!(
685                "get_from_memtable_count",
686                "Number of memtables queried",
687                &["cf_name"],
688                registry;
689                MetricLevel::Trace,
690            )
691            .unwrap(),
692            get_post_process_nanos: register_int_counter_vec_with_registry!(
693                "get_post_process_nanos",
694                "Total nanos spent after Get() finds a key",
695                &["cf_name"],
696                registry;
697                MetricLevel::Trace,
698            )
699            .unwrap(),
700            get_from_output_files_nanos: register_int_counter_vec_with_registry!(
701                "get_from_output_files_nanos",
702                "Total nanos reading from output files",
703                &["cf_name"],
704                registry;
705                MetricLevel::Trace,
706            )
707            .unwrap(),
708            db_mutex_lock_nanos: register_int_counter_vec_with_registry!(
709                "db_mutex_lock_nanos",
710                "Time spent on acquiring db mutex",
711                &["cf_name"],
712                registry;
713                MetricLevel::Trace,
714            )
715            .unwrap(),
716            db_condition_wait_nanos: register_int_counter_vec_with_registry!(
717                "db_condition_wait_nanos",
718                "Time spent waiting with a condition variable created with DB Mutex.",
719                &["cf_name"],
720                registry;
721                MetricLevel::Trace,
722            )
723            .unwrap(),
724            merge_operator_nanos: register_int_counter_vec_with_registry!(
725                "merge_operator_nanos",
726                "Time spent on merge operator.",
727                &["cf_name"],
728                registry;
729                MetricLevel::Trace,
730            )
731            .unwrap(),
732            read_index_block_nanos: register_int_counter_vec_with_registry!(
733                "read_index_block_nanos",
734                "Time spent on reading index block from block cache or SST file",
735                &["cf_name"],
736                registry;
737                MetricLevel::Trace,
738            )
739            .unwrap(),
740            read_filter_block_nanos: register_int_counter_vec_with_registry!(
741                "read_filter_block_nanos",
742                "Time spent on reading filter block from block cache or SST file",
743                &["cf_name"],
744                registry;
745                MetricLevel::Trace,
746            )
747            .unwrap(),
748            new_table_block_iter_nanos: register_int_counter_vec_with_registry!(
749                "new_table_block_iter_nanos",
750                "Time spent on creating data block iterator",
751                &["cf_name"],
752                registry;
753                MetricLevel::Trace,
754            )
755            .unwrap(),
756            block_seek_nanos: register_int_counter_vec_with_registry!(
757                "block_seek_nanos",
758                "Time spent on seeking a key in data/index blocks",
759                &["cf_name"],
760                registry;
761                MetricLevel::Trace,
762            )
763            .unwrap(),
764            find_table_nanos: register_int_counter_vec_with_registry!(
765                "find_table_nanos",
766                "Time spent on finding or creating a table reader",
767                &["cf_name"],
768                registry;
769                MetricLevel::Trace,
770            )
771            .unwrap(),
772            bloom_memtable_hit_count: register_int_counter_vec_with_registry!(
773                "bloom_memtable_hit_count",
774                "Total number of mem table bloom hits",
775                &["cf_name"],
776                registry;
777                MetricLevel::Trace,
778            )
779            .unwrap(),
780            bloom_memtable_miss_count: register_int_counter_vec_with_registry!(
781                "bloom_memtable_miss_count",
782                "Total number of mem table bloom misses",
783                &["cf_name"],
784                registry;
785                MetricLevel::Trace,
786            )
787            .unwrap(),
788            bloom_sst_hit_count: register_int_counter_vec_with_registry!(
789                "bloom_sst_hit_count",
790                "Total number of SST table bloom hits",
791                &["cf_name"],
792                registry;
793                MetricLevel::Trace,
794            )
795            .unwrap(),
796            bloom_sst_miss_count: register_int_counter_vec_with_registry!(
797                "bloom_sst_miss_count",
798                "Total number of SST table bloom misses",
799                &["cf_name"],
800                registry;
801                MetricLevel::Trace,
802            )
803            .unwrap(),
804            key_lock_wait_time: register_int_counter_vec_with_registry!(
805                "key_lock_wait_time",
806                "Time spent waiting on key locks in transaction lock manager",
807                &["cf_name"],
808                registry;
809                MetricLevel::Trace,
810            )
811            .unwrap(),
812            key_lock_wait_count: register_int_counter_vec_with_registry!(
813                "key_lock_wait_count",
814                "Number of times acquiring a lock was blocked by another transaction",
815                &["cf_name"],
816                registry;
817                MetricLevel::Trace,
818            )
819            .unwrap(),
820            internal_delete_skipped_count: register_int_counter_vec_with_registry!(
821                "internal_delete_skipped_count",
822                "Total number of deleted keys skipped during iteration",
823                &["cf_name"],
824                registry;
825                MetricLevel::Trace,
826            )
827                .unwrap(),
828            internal_skipped_count: register_int_counter_vec_with_registry!(
829                "internal_skipped_count",
830                "Totall number of internal keys skipped during iteration",
831                &["cf_name"],
832                registry;
833                MetricLevel::Trace,
834            )
835                .unwrap(),
836        }
837    }
838
839    pub fn report_metrics(&self, cf_name: &str) {
840        PER_THREAD_ROCKS_PERF_CONTEXT.with(|perf_context_cell| {
841            set_perf_stats(PerfStatsLevel::Disable);
842            let perf_context = perf_context_cell.borrow();
843            self.user_key_comparison_count
844                .with_label_values(&[cf_name])
845                .inc_by(perf_context.metric(PerfMetric::UserKeyComparisonCount));
846            self.block_cache_hit_count
847                .with_label_values(&[cf_name])
848                .inc_by(perf_context.metric(PerfMetric::BlockCacheHitCount));
849            self.block_read_count
850                .with_label_values(&[cf_name])
851                .inc_by(perf_context.metric(PerfMetric::BlockReadCount));
852            self.block_read_byte
853                .with_label_values(&[cf_name])
854                .inc_by(perf_context.metric(PerfMetric::BlockReadByte));
855            self.block_read_nanos
856                .with_label_values(&[cf_name])
857                .inc_by(perf_context.metric(PerfMetric::BlockReadTime));
858            self.block_read_count
859                .with_label_values(&[cf_name])
860                .inc_by(perf_context.metric(PerfMetric::BlockReadCount));
861            self.block_checksum_nanos
862                .with_label_values(&[cf_name])
863                .inc_by(perf_context.metric(PerfMetric::BlockChecksumTime));
864            self.block_decompress_nanos
865                .with_label_values(&[cf_name])
866                .inc_by(perf_context.metric(PerfMetric::BlockDecompressTime));
867            self.get_read_bytes
868                .with_label_values(&[cf_name])
869                .inc_by(perf_context.metric(PerfMetric::GetReadBytes));
870            self.multiget_read_bytes
871                .with_label_values(&[cf_name])
872                .inc_by(perf_context.metric(PerfMetric::MultigetReadBytes));
873            self.get_snapshot_nanos
874                .with_label_values(&[cf_name])
875                .inc_by(perf_context.metric(PerfMetric::GetSnapshotTime));
876            self.get_from_memtable_nanos
877                .with_label_values(&[cf_name])
878                .inc_by(perf_context.metric(PerfMetric::GetFromMemtableTime));
879            self.get_from_memtable_count
880                .with_label_values(&[cf_name])
881                .inc_by(perf_context.metric(PerfMetric::GetFromMemtableCount));
882            self.get_post_process_nanos
883                .with_label_values(&[cf_name])
884                .inc_by(perf_context.metric(PerfMetric::GetPostProcessTime));
885            self.get_from_output_files_nanos
886                .with_label_values(&[cf_name])
887                .inc_by(perf_context.metric(PerfMetric::GetFromOutputFilesTime));
888            self.db_mutex_lock_nanos
889                .with_label_values(&[cf_name])
890                .inc_by(perf_context.metric(PerfMetric::DbMutexLockNanos));
891            self.db_condition_wait_nanos
892                .with_label_values(&[cf_name])
893                .inc_by(perf_context.metric(PerfMetric::DbConditionWaitNanos));
894            self.merge_operator_nanos
895                .with_label_values(&[cf_name])
896                .inc_by(perf_context.metric(PerfMetric::MergeOperatorTimeNanos));
897            self.read_index_block_nanos
898                .with_label_values(&[cf_name])
899                .inc_by(perf_context.metric(PerfMetric::ReadIndexBlockNanos));
900            self.read_filter_block_nanos
901                .with_label_values(&[cf_name])
902                .inc_by(perf_context.metric(PerfMetric::ReadFilterBlockNanos));
903            self.new_table_block_iter_nanos
904                .with_label_values(&[cf_name])
905                .inc_by(perf_context.metric(PerfMetric::NewTableBlockIterNanos));
906            self.block_seek_nanos
907                .with_label_values(&[cf_name])
908                .inc_by(perf_context.metric(PerfMetric::BlockSeekNanos));
909            self.find_table_nanos
910                .with_label_values(&[cf_name])
911                .inc_by(perf_context.metric(PerfMetric::FindTableNanos));
912            self.bloom_memtable_hit_count
913                .with_label_values(&[cf_name])
914                .inc_by(perf_context.metric(PerfMetric::BloomMemtableHitCount));
915            self.bloom_memtable_miss_count
916                .with_label_values(&[cf_name])
917                .inc_by(perf_context.metric(PerfMetric::BloomMemtableMissCount));
918            self.bloom_sst_hit_count
919                .with_label_values(&[cf_name])
920                .inc_by(perf_context.metric(PerfMetric::BloomSstHitCount));
921            self.bloom_sst_miss_count
922                .with_label_values(&[cf_name])
923                .inc_by(perf_context.metric(PerfMetric::BloomSstMissCount));
924            self.key_lock_wait_time
925                .with_label_values(&[cf_name])
926                .inc_by(perf_context.metric(PerfMetric::KeyLockWaitTime));
927            self.key_lock_wait_count
928                .with_label_values(&[cf_name])
929                .inc_by(perf_context.metric(PerfMetric::KeyLockWaitCount));
930            self.internal_delete_skipped_count
931                .with_label_values(&[cf_name])
932                .inc_by(perf_context.metric(PerfMetric::InternalDeleteSkippedCount));
933            self.internal_skipped_count
934                .with_label_values(&[cf_name])
935                .inc_by(perf_context.metric(PerfMetric::InternalKeySkippedCount));
936        });
937    }
938}
939
940#[derive(Debug)]
941pub struct WritePerfContextMetrics {
942    pub write_wal_nanos: IntCounterVec,
943    pub write_memtable_nanos: IntCounterVec,
944    pub write_delay_nanos: IntCounterVec,
945    pub write_pre_and_post_process_nanos: IntCounterVec,
946    pub write_db_mutex_lock_nanos: IntCounterVec,
947    pub write_db_condition_wait_nanos: IntCounterVec,
948    pub write_key_lock_wait_nanos: IntCounterVec,
949    pub write_key_lock_wait_count: IntCounterVec,
950}
951
952impl WritePerfContextMetrics {
953    pub(crate) fn new(registry: &Registry) -> Self {
954        WritePerfContextMetrics {
955            write_wal_nanos: register_int_counter_vec_with_registry!(
956                "write_wal_nanos",
957                "Total nanos spent on writing to WAL",
958                &["cf_name"],
959                registry;
960                MetricLevel::Trace,
961            )
962            .unwrap(),
963            write_memtable_nanos: register_int_counter_vec_with_registry!(
964                "write_memtable_nanos",
965                "Total nanos spent on writing to memtable",
966                &["cf_name"],
967                registry;
968                MetricLevel::Trace,
969            )
970            .unwrap(),
971            write_delay_nanos: register_int_counter_vec_with_registry!(
972                "write_delay_nanos",
973                "Total nanos spent on delaying or throttling write",
974                &["cf_name"],
975                registry;
976                MetricLevel::Trace,
977            )
978            .unwrap(),
979            write_pre_and_post_process_nanos: register_int_counter_vec_with_registry!(
980                "write_pre_and_post_process_nanos",
981                "Total nanos spent on writing a record, excluding the above four things",
982                &["cf_name"],
983                registry;
984                MetricLevel::Trace,
985            )
986            .unwrap(),
987            write_db_mutex_lock_nanos: register_int_counter_vec_with_registry!(
988                "write_db_mutex_lock_nanos",
989                "Time spent on acquiring db mutex",
990                &["cf_name"],
991                registry;
992                MetricLevel::Trace,
993            )
994            .unwrap(),
995            write_db_condition_wait_nanos: register_int_counter_vec_with_registry!(
996                "write_db_condition_wait_nanos",
997                "Time spent waiting with a condition variable created with DB Mutex.",
998                &["cf_name"],
999                registry;
1000                MetricLevel::Trace,
1001            )
1002            .unwrap(),
1003            write_key_lock_wait_nanos: register_int_counter_vec_with_registry!(
1004                "write_key_lock_wait_time",
1005                "Time spent waiting on key locks in transaction lock manager",
1006                &["cf_name"],
1007                registry;
1008                MetricLevel::Trace,
1009            )
1010            .unwrap(),
1011            write_key_lock_wait_count: register_int_counter_vec_with_registry!(
1012                "write_key_lock_wait_count",
1013                "Number of times acquiring a lock was blocked by another transaction",
1014                &["cf_name"],
1015                registry;
1016                MetricLevel::Trace,
1017            )
1018            .unwrap(),
1019        }
1020    }
1021    pub fn report_metrics(&self, db_name: &str) {
1022        PER_THREAD_ROCKS_PERF_CONTEXT.with(|perf_context_cell| {
1023            set_perf_stats(PerfStatsLevel::Disable);
1024            let perf_context = perf_context_cell.borrow();
1025            self.write_wal_nanos
1026                .with_label_values(&[db_name])
1027                .inc_by(perf_context.metric(PerfMetric::WriteWalTime));
1028            self.write_memtable_nanos
1029                .with_label_values(&[db_name])
1030                .inc_by(perf_context.metric(PerfMetric::WriteMemtableTime));
1031            self.write_delay_nanos
1032                .with_label_values(&[db_name])
1033                .inc_by(perf_context.metric(PerfMetric::WriteDelayTime));
1034            self.write_pre_and_post_process_nanos
1035                .with_label_values(&[db_name])
1036                .inc_by(perf_context.metric(PerfMetric::WritePreAndPostProcessTime));
1037            self.write_db_mutex_lock_nanos
1038                .with_label_values(&[db_name])
1039                .inc_by(perf_context.metric(PerfMetric::DbMutexLockNanos));
1040            self.write_db_condition_wait_nanos
1041                .with_label_values(&[db_name])
1042                .inc_by(perf_context.metric(PerfMetric::DbConditionWaitNanos));
1043            self.write_key_lock_wait_nanos
1044                .with_label_values(&[db_name])
1045                .inc_by(perf_context.metric(PerfMetric::KeyLockWaitTime));
1046            self.write_key_lock_wait_count
1047                .with_label_values(&[db_name])
1048                .inc_by(perf_context.metric(PerfMetric::KeyLockWaitCount));
1049        });
1050    }
1051}
1052
1053#[derive(Debug)]
1054pub struct DBMetrics {
1055    pub op_metrics: OperationMetrics,
1056    pub cf_metrics: ColumnFamilyMetrics,
1057    pub read_perf_ctx_metrics: ReadPerfContextMetrics,
1058    pub write_perf_ctx_metrics: WritePerfContextMetrics,
1059}
1060
1061static ONCE: OnceCell<Arc<DBMetrics>> = OnceCell::new();
1062
1063impl DBMetrics {
1064    fn new(registry: &Registry) -> Self {
1065        DBMetrics {
1066            op_metrics: OperationMetrics::new(registry),
1067            cf_metrics: ColumnFamilyMetrics::new(registry),
1068            read_perf_ctx_metrics: ReadPerfContextMetrics::new(registry),
1069            write_perf_ctx_metrics: WritePerfContextMetrics::new(registry),
1070        }
1071    }
1072    pub fn init(registry: &Registry) -> &'static Arc<DBMetrics> {
1073        // Initialize this before creating any instance of DBMap
1074        // TODO: Remove static initialization because this basically means we can
1075        // only ever initialize db metrics once with a registry whereas
1076        // in the code we might want to initialize it with different
1077        // registries. The problem is underlying metrics cannot be re-initialized
1078        // or prometheus complains. We essentially need to pass in DBMetrics
1079        // everywhere we create DBMap as the right fix
1080        let _ = ONCE
1081            .set(Arc::new(DBMetrics::new(registry)))
1082            // this happens many times during tests
1083            .tap_err(|_| warn!("DBMetrics registry overwritten"));
1084        ONCE.get().unwrap()
1085    }
1086    pub fn increment_num_active_dbs(&self, db_name: &str) {
1087        self.op_metrics
1088            .rocksdb_num_active_db_handles
1089            .with_label_values(&[db_name])
1090            .inc();
1091    }
1092    pub fn decrement_num_active_dbs(&self, db_name: &str) {
1093        self.op_metrics
1094            .rocksdb_num_active_db_handles
1095            .with_label_values(&[db_name])
1096            .dec();
1097    }
1098    pub fn get() -> &'static Arc<DBMetrics> {
1099        // Lazily initialize against the global default registry when no explicit
1100        // `init` has run. `get_or_init` ensures the rocksdb metrics are
1101        // registered at most once even when first reached concurrently.
1102        ONCE.get_or_init(|| Arc::new(DBMetrics::new(prometheus_filtered::default_registry())))
1103    }
1104}
1105
1106#[cfg(test)]
1107mod tests {
1108    use std::time::Duration;
1109
1110    use crate::metrics::SamplingInterval;
1111
1112    // `RuntimeMetrics` is not provided by the deterministic simulator's tokio
1113    // fork. Under the simulator `#[tokio::test]` is turned into an ignored test
1114    // anyway, so this turns off nothing that would otherwise run.
1115    #[cfg(not(msim))]
1116    fn alive_tasks() -> usize {
1117        tokio::runtime::Handle::current()
1118            .metrics()
1119            .num_alive_tasks()
1120    }
1121
1122    /// A timed interval keeps a task resetting its counter, and that task stops
1123    /// once the last clone of the interval is dropped.
1124    #[cfg(not(msim))]
1125    #[tokio::test]
1126    async fn a_dropped_interval_stops_its_task() {
1127        let tasks_before = alive_tasks();
1128        let interval = SamplingInterval::new(Duration::from_millis(10), 0);
1129        let clone = interval.clone();
1130        assert_eq!(alive_tasks(), tasks_before + 1);
1131
1132        drop(interval);
1133        drop(clone);
1134        for _ in 0..100 {
1135            if alive_tasks() == tasks_before {
1136                return;
1137            }
1138            tokio::time::sleep(Duration::from_millis(10)).await;
1139        }
1140        assert_eq!(
1141            alive_tasks(),
1142            tasks_before,
1143            "the task outlived the interval"
1144        );
1145    }
1146}
typed_store/metrics.rs

typed_store/
metrics.rs
