1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 65 66 67 68 69 70 71 72 73 74 75 76 77 78 79 80 81 82 83 84 85 86 87 88 89 90 91 92 93 94 95 96 97 98 99 100 101 102 103 104 105 106 107 108 109 110 111 112 113 114 115 116 117 118 119 120 121 122 123 124 125 126 127 128 129 130 131 132 133 134 135 136 137 138 139 140 141 142 143 144 145 146 147 148 149 150 151 152 153 154 155 156 157 158 159 160 161 162 163 164 165 166 167 168 169 170 171 172 173 174 175 176 177 178 179 180 181 182 183 184 185 186 187 188 189 190 191 192 193 194 195 196 197 198 199 200 201 202 203 204 205 206 207 208 209
// Copyright (C) Parity Technologies (UK) Ltd.
// This file is part of Polkadot.
// Polkadot is free software: you can redistribute it and/or modify
// it under the terms of the GNU General Public License as published by
// the Free Software Foundation, either version 3 of the License, or
// (at your option) any later version.
// Polkadot is distributed in the hope that it will be useful,
// but WITHOUT ANY WARRANTY; without even the implied warranty of
// MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the
// GNU General Public License for more details.
// You should have received a copy of the GNU General Public License
// along with Polkadot. If not, see <http://www.gnu.org/licenses/>.
#![deny(unused_crate_dependencies)]
#![deny(missing_docs)]
#![deny(clippy::dbg_macro)]
//! A wrapper around `tracing` macros, to provide semi automatic
//! `traceID` annotation without codebase turnover.
//!
//! # Usage
//!
//! The API follows the [`tracing`
//! API](https://docs.rs/tracing/latest/tracing/index.html), but the docs contain
//! more detail than you probably need to know, so here's the quick version.
//!
//! Most common usage is of the form:
//!
//! ```rs
//! gum::warn!(
//! target: LOG_TARGET,
//! worker_pid = %idle_worker.pid,
//! ?error,
//! "failed to send a handshake to the spawned worker",
//! );
//! ```
//!
//! ### Log levels
//!
//! All of the [`tracing` macros](https://docs.rs/tracing/latest/tracing/index.html#macros) are available.
//! In decreasing order of priority they are:
//!
//! - `error!`
//! - `warn!`
//! - `info!`
//! - `debug!`
//! - `trace!`
//!
//! ### `target`
//!
//! The `LOG_TARGET` should be defined once per crate, e.g.:
//!
//! ```rs
//! const LOG_TARGET: &str = "parachain::pvf";
//! ```
//!
//! This should be of the form `<target>::<subtarget>`, where the `::<subtarget>` is optional.
//!
//! The target and subtarget are used when debugging by specializing the Grafana Loki query to
//! filter specific subsystem logs. The more specific the query is the better when approaching the
//! query response limit.
//!
//! ### Fields
//!
//! Here's the rundown on how fields work:
//!
//! - Fields on spans and events are specified using the `syntax field_name = field_value`.
//! - Local variables may be used as field values without an assignment, similar to struct
//! initializers.
//! - The `?` sigil is shorthand that specifies a field should be recorded using its `fmt::Debug`
//! implementation.
//! - The `%` sigil operates similarly, but indicates that the value should be recorded using its
//! `fmt::Display` implementation.
//!
//! For full details, again see [the tracing
//! docs](https://docs.rs/tracing/latest/tracing/index.html#recording-fields).
//!
//! ### Viewing traces
//!
//! When testing,
//!
//! ```rs
//! sp_tracing::init_for_tests();
//! ```
//!
//! should enable all trace logs.
//!
//! Alternatively, you can do:
//!
//! ```rs
//! sp_tracing::try_init_simple();
//! ```
//!
//! On the command line you specify `RUST_LOG` with the desired target and trace level:
//!
//! ```sh
//! RUST_LOG=parachain::pvf=trace cargo test
//! ```
//!
//! On the other hand if you want all `parachain` logs, specify `parachain=trace`, which will also
//! include logs from `parachain::pvf` and other subtargets.
pub use tracing::{enabled, event, Level};
// jaeger dependency
/// Alias for the 16 byte unique identifier used with jaeger.
pub(crate) type TraceIdentifier = u128;
/// A helper to convert the hash to the fixed size representation
/// needed for jaeger.
#[inline]
pub fn hash_to_trace_identifier(hash: Hash) -> TraceIdentifier {
let mut buf = [0u8; 16];
buf.copy_from_slice(&hash.as_ref()[0..16]);
// The slice bytes are copied in reading order, so if interpreted
// in string form by a human, that means lower indices have higher
// values and hence corresponds to BIG endian ordering of the individual
// bytes.
u128::from_be_bytes(buf) as TraceIdentifier
}
#[doc(hidden)]
pub use polkadot_primitives::{CandidateHash, Hash};
pub use gum_proc_macro::{debug, error, info, trace, warn, warn_if_frequent};
#[cfg(test)]
mod tests;
const FREQ_SMOOTHING_FACTOR: f32 = 0.5;
/// Exponential moving average
#[derive(Debug, Default)]
struct EmaBucket {
current: f32,
count: u32,
}
impl EmaBucket {
fn update(&mut self, value: f32, alpha: f32) {
if self.count == 0 {
self.current = value;
} else {
self.current += alpha * (value - self.current);
}
self.count += 1;
}
}
/// Utility struct to compare the rate of its own calls.
pub struct Freq {
ema: EmaBucket,
last: u64,
}
impl Freq {
/// Initiates a new instance
pub fn new() -> Self {
Self { ema: Default::default(), last: Default::default() }
}
/// Compares the rate of its own calls with the passed one.
pub fn is_frequent(&mut self, max_rate: Times) -> bool {
self.record();
// Two attempts is not enough to call something as frequent.
if self.ema.count < 3 {
return false
}
let rate = 1000.0 / self.ema.current; // Current EMA represents interval in ms
rate > max_rate.into()
}
fn record(&mut self) {
let now = coarsetime::Clock::now_since_epoch().as_millis() as u64;
if self.last > 0 {
self.ema.update((now - self.last) as f32, FREQ_SMOOTHING_FACTOR);
}
self.last = now;
}
}
/// Represents frequency per second, minute, hour and day
pub enum Times {
/// Per second
PerSecond(u32),
/// Per minute
PerMinute(u32),
/// Per hour
PerHour(u32),
/// Per day
PerDay(u32),
}
impl From<Times> for f32 {
fn from(value: Times) -> Self {
match value {
Times::PerSecond(v) => v as f32,
Times::PerMinute(v) => v as f32 / 60.0,
Times::PerHour(v) => v as f32 / (60.0 * 60.0),
Times::PerDay(v) => v as f32 / (60.0 * 60.0 * 24.0),
}
}
}