Compare commits

..

7 Commits

Author SHA1 Message Date
Joonas Koivunen 677f46301f try: enclose load operations to initial load span
this makes only sense if we would then have a "new span" start after
tenants and timelines have been activated, not doing that now.
2023-05-31 15:34:56 +03:00
Joonas Koivunen 2725f6197f tracing_flame: disable empty samples -- seem just like noise 2023-05-31 15:34:34 +03:00
Joonas Koivunen 2c55c5a0ea neon_local: exit early if process died 2023-05-31 14:13:12 +03:00
Joonas Koivunen 777bee85fa to be dropped: tracing-flame second attempt
with configuring it no post processing is needed. the time spent in
loading is very small so one needs to use:

cat .neon/tracing.folded | inferno-flamegraph --minwidth=0 >| flamegraph.svg

To find them, otherwise it will be just walreceiver and compaction.
Noticed also some trouble with the shutdown propagating from a signal
with single threaded runtime; it very likely is that all of the
compactions are already spawned, and as they are mostly blocking code,
they will block the shutdown procedure, which will be quite late
anyways.
2023-05-31 10:54:48 +03:00
Joonas Koivunen 5fc725031b rest of tracing changes 2023-05-30 18:38:44 +03:00
Joonas Koivunen 7963237c43 to be dropped: mandatory PAGESERVER_THREADS_PER_RUNTIME 2023-05-30 18:38:20 +03:00
Joonas Koivunen 2d9d679238 to be dropped: tracing-flame usage attempt
for our purposes the folded need post processing:

```
cat .neon/tracing.folded \
  | sed -Ee 's/^ThreadId\([0-9]+\)-//' \
  | inferno-flamegraph >| flamegraph.svg
```
2023-05-30 18:38:20 +03:00
24 changed files with 226 additions and 253 deletions
Generated
+12
View File
@@ -4590,6 +4590,17 @@ dependencies = [
"tracing-subscriber",
]
[[package]]
name = "tracing-flame"
version = "0.2.0"
source = "registry+https://github.com/rust-lang/crates.io-index"
checksum = "0bae117ee14789185e129aaee5d93750abe67fdc5a9a62650452bfe4e122a3a9"
dependencies = [
"lazy_static",
"tracing",
"tracing-subscriber",
]
[[package]]
name = "tracing-futures"
version = "0.2.5"
@@ -4843,6 +4854,7 @@ dependencies = [
"tokio",
"tracing",
"tracing-error",
"tracing-flame",
"tracing-subscriber",
"url",
"uuid",
+17 -1
View File
@@ -106,6 +106,17 @@ where
);
for retries in 0..RETRIES {
match spawned_process.try_wait() {
Ok(Some(exit)) => {
anyhow::bail!("process {process_name} already exited: {exit}")
}
Ok(None) => { /* not dead yet */ }
Err(e) => {
return Err(
anyhow::Error::new(e).context(format!("try_wait failed on process {pid}"))
)
}
}
match process_started(pid, Some(pid_file_to_check), &process_status_check) {
Ok(true) => {
println!("\n{process_name} started, pid: {pid}");
@@ -219,7 +230,12 @@ fn fill_rust_env_vars(cmd: &mut Command) -> &mut Command {
let mut filled_cmd = cmd.env_clear().env("RUST_BACKTRACE", backtrace_setting);
// Pass through these environment variables to the command
for var in ["LLVM_PROFILE_FILE", "FAILPOINTS", "RUST_LOG"] {
for var in [
"LLVM_PROFILE_FILE",
"FAILPOINTS",
"RUST_LOG",
"PAGESERVER_THREADS_PER_RUNTIME",
] {
if let Some(val) = std::env::var_os(var) {
filled_cmd = filled_cmd.env(var, val);
}
-10
View File
@@ -369,11 +369,6 @@ impl PageServerNode {
evictions_low_residence_duration_metric_threshold: settings
.remove("evictions_low_residence_duration_metric_threshold")
.map(|x| x.to_string()),
gc_feedback: settings
.remove("gc_feedback")
.map(|x| x.parse::<bool>())
.transpose()
.context("Failed to parse 'gc_feedback' as bool")?,
};
// If tenant ID was not specified, generate one
@@ -468,11 +463,6 @@ impl PageServerNode {
evictions_low_residence_duration_metric_threshold: settings
.remove("evictions_low_residence_duration_metric_threshold")
.map(|x| x.to_string()),
gc_feedback: settings
.remove("gc_feedback")
.map(|x| x.parse::<bool>())
.transpose()
.context("Failed to parse 'gc_feedback' as bool")?,
}
};
-2
View File
@@ -223,7 +223,6 @@ pub struct TenantConfig {
pub eviction_policy: Option<serde_json::Value>,
pub min_resident_size_override: Option<u64>,
pub evictions_low_residence_duration_metric_threshold: Option<String>,
pub gc_feedback: Option<bool>,
}
#[serde_as]
@@ -282,7 +281,6 @@ impl TenantConfigRequest {
eviction_policy: None,
min_resident_size_override: None,
evictions_low_residence_duration_metric_threshold: None,
gc_feedback: None,
};
TenantConfigRequest { tenant_id, config }
}
+1
View File
@@ -40,6 +40,7 @@ uuid.workspace = true
pq_proto.workspace = true
metrics.workspace = true
workspace_hack.workspace = true
tracing-flame = "0.2"
[dev-dependencies]
byteorder.workspace = true
+49
View File
@@ -104,6 +104,55 @@ pub fn init(
Ok(())
}
pub fn init_with_flame(
log_format: LogFormat,
tracing_error_layer_enablement: TracingErrorLayerEnablement,
) -> anyhow::Result<impl Drop> {
// We fall back to printing all spans at info-level or above if
// the RUST_LOG environment variable is not set.
let rust_log_env_filter = || {
tracing_subscriber::EnvFilter::try_from_default_env()
.unwrap_or_else(|_| tracing_subscriber::EnvFilter::new("info"))
};
// NB: the order of the with() calls does not matter.
// See https://docs.rs/tracing-subscriber/0.3.16/tracing_subscriber/layer/index.html#per-layer-filtering
use tracing_subscriber::prelude::*;
let r = tracing_subscriber::registry();
let r = r.with({
let log_layer = tracing_subscriber::fmt::layer()
.with_target(false)
.with_ansi(atty::is(atty::Stream::Stdout))
.with_writer(std::io::stdout);
let log_layer = match log_format {
LogFormat::Json => log_layer.json().boxed(),
LogFormat::Plain => log_layer.boxed(),
LogFormat::Test => log_layer.with_test_writer().boxed(),
};
log_layer.with_filter(rust_log_env_filter())
});
let r = r.with(TracingEventCountLayer(&TRACING_EVENT_COUNT).with_filter(rust_log_env_filter()));
let (flame_layer, guard) = {
let (l, guard) = tracing_flame::FlameLayer::with_file("./tracing.folded").unwrap();
let l = l
.with_empty_samples(false)
.with_module_path(false)
.with_file_and_line(false)
.with_threads_collapsed(true);
(l, guard)
};
let r = r.with(flame_layer);
match tracing_error_layer_enablement {
TracingErrorLayerEnablement::EnableWithRustLogFilter => {
r.with(tracing_error::ErrorLayer::default().with_filter(rust_log_env_filter()))
.init();
}
TracingErrorLayerEnablement::Disabled => r.init(),
}
Ok(guard)
}
/// Disable the default rust panic hook by using `set_hook`.
///
/// For neon binaries, the assumption is that tracing is configured before with [`init`], after
+21 -10
View File
@@ -98,7 +98,7 @@ fn main() -> anyhow::Result<()> {
} else {
TracingErrorLayerEnablement::Disabled
};
logging::init(conf.log_format, tracing_error_layer_enablement)?;
let _guard = logging::init_with_flame(conf.log_format, tracing_error_layer_enablement)?;
// mind the order required here: 1. logging, 2. panic_hook, 3. sentry.
// disarming this hook on pageserver, because we never tear down tracing.
@@ -127,7 +127,7 @@ fn main() -> anyhow::Result<()> {
virtual_file::init(conf.max_file_descriptors);
page_cache::init(conf.page_cache_size);
start_pageserver(launch_ts, conf).context("Failed to start pageserver")?;
start_pageserver(launch_ts, conf, _guard).context("Failed to start pageserver")?;
scenario.teardown();
Ok(())
@@ -225,6 +225,7 @@ fn initialize_config(
fn start_pageserver(
launch_ts: &'static LaunchTimestamp,
conf: &'static PageServerConf,
guard: impl Drop,
) -> anyhow::Result<()> {
// Print version and launch timestamp to the log,
// and expose them as prometheus metrics.
@@ -341,16 +342,24 @@ fn start_pageserver(
let (init_done_tx, init_done_rx) = utils::completion::channel();
// Scan the local 'tenants/' directory and start loading the tenants
let span = tracing::info_span!("initial load");
let init_started_at = std::time::Instant::now();
BACKGROUND_RUNTIME.block_on(mgr::init_tenant_mgr(
conf,
broker_client.clone(),
remote_storage.clone(),
(init_done_tx, init_done_rx.clone()),
))?;
// initial load started by initializing tenant manager but stopped when initialization is
// actually complete
BACKGROUND_RUNTIME.block_on(
mgr::init_tenant_mgr(
conf,
broker_client.clone(),
remote_storage.clone(),
(init_done_tx, init_done_rx.clone()),
)
.instrument(span.clone()),
)?;
BACKGROUND_RUNTIME.spawn({
let init_done_rx = init_done_rx.clone();
async move {
init_done_rx.wait().await;
@@ -361,6 +370,7 @@ fn start_pageserver(
"Initial load completed."
);
}
.instrument(span)
});
// shared state between the disk-usage backed eviction background task and the http endpoint
@@ -484,7 +494,8 @@ fn start_pageserver(
}
// All started up! Now just sit and wait for shutdown signal.
ShutdownSignals::handle(|signal| match signal {
let mut guard = Some(guard);
ShutdownSignals::handle(move |signal| match signal {
Signal::Quit => {
info!(
"Got {}. Terminating in immediate shutdown mode",
@@ -498,7 +509,7 @@ fn start_pageserver(
"Got {}. Terminating gracefully in fast shutdown mode",
signal.name()
);
BACKGROUND_RUNTIME.block_on(pageserver::shutdown_pageserver(0));
BACKGROUND_RUNTIME.block_on(pageserver::shutdown_pageserver(0, guard.take()));
unreachable!()
}
})
+1 -9
View File
@@ -108,7 +108,7 @@ pub mod defaults {
#min_resident_size_override = .. # in bytes
#evictions_low_residence_duration_metric_threshold = '{DEFAULT_EVICTIONS_LOW_RESIDENCE_DURATION_METRIC_THRESHOLD}'
#gc_feedback = false
# [remote_storage]
"###
@@ -828,14 +828,6 @@ impl PageServerConf {
)?);
}
if let Some(gc_feedback) = item.get("gc_feedback") {
t_conf.gc_feedback = Some(
gc_feedback
.as_bool()
.with_context(|| "configure option gc_feedback is not a bool".to_string())?,
);
}
Ok(t_conf)
}
+3 -3
View File
@@ -111,7 +111,7 @@ pub fn launch_disk_usage_global_eviction_task(
task_mgr::shutdown_token(),
)
.await;
info!("disk usage based eviction task finishing");
debug!("disk usage based eviction task finishing");
Ok(())
},
);
@@ -133,7 +133,7 @@ async fn disk_usage_eviction_task(
.await
.is_err()
{
info!("shutting down");
debug!("shutting down");
return;
}
}
@@ -168,7 +168,7 @@ async fn disk_usage_eviction_task(
tokio::select! {
_ = tokio::time::sleep_until(sleep_until) => {},
_ = cancel.cancelled() => {
info!("shutting down");
debug!("shutting down");
break
}
}
+5 -2
View File
@@ -45,8 +45,8 @@ static ZERO_PAGE: bytes::Bytes = bytes::Bytes::from_static(&[0u8; 8192]);
pub use crate::metrics::preinitialize_metrics;
#[tracing::instrument]
pub async fn shutdown_pageserver(exit_code: i32) {
#[tracing::instrument(skip(guard))]
pub async fn shutdown_pageserver(exit_code: i32, guard: Option<impl Drop>) {
// Shut down the libpq endpoint task. This prevents new connections from
// being accepted.
task_mgr::shutdown_tasks(Some(TaskKind::LibpqEndpointListener), None, None).await;
@@ -72,6 +72,9 @@ pub async fn shutdown_pageserver(exit_code: i32) {
// There should be nothing left, but let's be sure
task_mgr::shutdown_tasks(None, None, None).await;
info!("Shut down successfully completed");
drop(guard);
std::process::exit(exit_code);
}
+18 -1
View File
@@ -103,9 +103,23 @@ use crate::shutdown_pageserver;
// other operations, if the upload tasks e.g. get blocked on locks. It shouldn't
// happen, but still.
//
pub static THREADS_PER_RUNTIME: Lazy<std::num::NonZeroUsize> = Lazy::new(|| {
let num = std::env::var_os("PAGESERVER_THREADS_PER_RUNTIME")
.and_then(|var| var.to_str().map(|v| v.parse::<usize>()))
.expect("PAGESERVER_THREADS_PER_RUNTIME is unset")
.expect("PAGESERVER_THREADS_PER_RUNTIME is not an usize");
let num =
std::num::NonZeroUsize::new(num).expect("PAGESERVER_THREADS_PER_RUNTIME out of range");
num
});
pub static COMPUTE_REQUEST_RUNTIME: Lazy<Runtime> = Lazy::new(|| {
tokio::runtime::Builder::new_multi_thread()
.thread_name("compute request worker")
.worker_threads(THREADS_PER_RUNTIME.get())
.enable_all()
.build()
.expect("Failed to create compute request runtime")
@@ -114,6 +128,7 @@ pub static COMPUTE_REQUEST_RUNTIME: Lazy<Runtime> = Lazy::new(|| {
pub static MGMT_REQUEST_RUNTIME: Lazy<Runtime> = Lazy::new(|| {
tokio::runtime::Builder::new_multi_thread()
.thread_name("mgmt request worker")
.worker_threads(THREADS_PER_RUNTIME.get())
.enable_all()
.build()
.expect("Failed to create mgmt request runtime")
@@ -122,6 +137,7 @@ pub static MGMT_REQUEST_RUNTIME: Lazy<Runtime> = Lazy::new(|| {
pub static WALRECEIVER_RUNTIME: Lazy<Runtime> = Lazy::new(|| {
tokio::runtime::Builder::new_multi_thread()
.thread_name("walreceiver worker")
.worker_threads(THREADS_PER_RUNTIME.get())
.enable_all()
.build()
.expect("Failed to create walreceiver runtime")
@@ -130,6 +146,7 @@ pub static WALRECEIVER_RUNTIME: Lazy<Runtime> = Lazy::new(|| {
pub static BACKGROUND_RUNTIME: Lazy<Runtime> = Lazy::new(|| {
tokio::runtime::Builder::new_multi_thread()
.thread_name("background op worker")
.worker_threads(THREADS_PER_RUNTIME.get())
.enable_all()
.build()
.expect("Failed to create background op runtime")
@@ -433,7 +450,7 @@ async fn task_finish(
}
if shutdown_process {
shutdown_pageserver(1).await;
shutdown_pageserver(1, None::<Box<u32>>).await;
}
}
+8 -6
View File
@@ -955,8 +955,7 @@ impl Tenant {
Ok(())
}
.instrument({
let span = tracing::info_span!(parent: None, "load", tenant_id=%tenant_id);
span.follows_from(Span::current());
let span = tracing::info_span!("load", tenant_id=%tenant_id);
span
}),
);
@@ -1102,14 +1101,14 @@ impl Tenant {
/// Subroutine of `load_tenant`, to load an individual timeline
///
/// NB: The parent is assumed to be already loaded!
#[instrument(skip_all, fields(timeline_id))]
#[instrument(skip_all, fields(timeline_id=%timeline_id))]
async fn load_local_timeline(
&self,
timeline_id: TimelineId,
local_metadata: TimelineMetadata,
ctx: &RequestContext,
) -> anyhow::Result<()> {
debug_assert_current_span_has_tenant_id();
debug_assert_current_span_has_tenant_and_timeline_id();
let remote_client = self.remote_storage.as_ref().map(|remote_storage| {
RemoteTimelineClient::new(
@@ -1394,6 +1393,8 @@ impl Tenant {
pitr: Duration,
ctx: &RequestContext,
) -> anyhow::Result<GcResult> {
debug_assert_current_span_has_tenant_id();
anyhow::ensure!(
self.is_active(),
"Cannot run GC iteration on inactive tenant"
@@ -1408,6 +1409,8 @@ impl Tenant {
/// Also it can be explicitly requested per timeline through page server
/// api's 'compact' command.
pub async fn compaction_iteration(&self, ctx: &RequestContext) -> anyhow::Result<()> {
debug_assert_current_span_has_tenant_id();
anyhow::ensure!(
self.is_active(),
"Cannot run compaction iteration on inactive tenant"
@@ -2141,7 +2144,7 @@ impl Tenant {
let target_config_path = conf.tenant_config_path(tenant_id);
let target_config_display = target_config_path.display();
info!("loading tenantconf from {target_config_display}");
debug!("loading tenantconf from {target_config_display}");
// FIXME If the config file is not found, assume that we're attaching
// a detached tenant and config is passed via attach command.
@@ -3209,7 +3212,6 @@ pub mod harness {
evictions_low_residence_duration_metric_threshold: Some(
tenant_conf.evictions_low_residence_duration_metric_threshold,
),
gc_feedback: Some(tenant_conf.gc_feedback),
}
}
}
-8
View File
@@ -99,7 +99,6 @@ pub struct TenantConf {
// See the corresponding metric's help string.
#[serde(with = "humantime_serde")]
pub evictions_low_residence_duration_metric_threshold: Duration,
pub gc_feedback: bool,
}
/// Same as TenantConf, but this struct preserves the information about
@@ -176,10 +175,6 @@ pub struct TenantConfOpt {
#[serde(with = "humantime_serde")]
#[serde(default)]
pub evictions_low_residence_duration_metric_threshold: Option<Duration>,
#[serde(skip_serializing_if = "Option::is_none")]
#[serde(default)]
pub gc_feedback: Option<bool>,
}
#[derive(Debug, Clone, Copy, PartialEq, Eq, Serialize, Deserialize)]
@@ -247,7 +242,6 @@ impl TenantConfOpt {
evictions_low_residence_duration_metric_threshold: self
.evictions_low_residence_duration_metric_threshold
.unwrap_or(global_conf.evictions_low_residence_duration_metric_threshold),
gc_feedback: self.gc_feedback.unwrap_or(global_conf.gc_feedback),
}
}
}
@@ -284,7 +278,6 @@ impl Default for TenantConf {
DEFAULT_EVICTIONS_LOW_RESIDENCE_DURATION_METRIC_THRESHOLD,
)
.expect("cannot parse default evictions_low_residence_duration_metric_threshold"),
gc_feedback: false,
}
}
}
@@ -379,7 +372,6 @@ impl TryFrom<&'_ models::TenantConfig> for TenantConfOpt {
))?,
);
}
tenant_conf.gc_feedback = request_data.gc_feedback;
Ok(tenant_conf)
}
@@ -30,19 +30,13 @@ impl PartialOrd for LayerKey {
impl Ord for LayerKey {
fn cmp(&self, other: &Self) -> std::cmp::Ordering {
// NOTE we really care about comparing by lsn.start first, because
// the persistent data structure must be constructed in that order.
// NOTE we also care about comparing by (-lsn.end), then key.start, and
// then (-key.end) next to make sure that if one layer contains
// another, the outer one is inserted first and the inner one
// is detected as redundant. So if we ever find an L1 layer with
// many L0s in it, the L0s are redundant, not the L1.
// NOTE we really care about comparing by lsn.start first
self.lsn
.start
.cmp(&other.lsn.start)
.then(self.lsn.end.cmp(&other.lsn.end).reverse())
.then(self.lsn.end.cmp(&other.lsn.end))
.then(self.key.start.cmp(&other.key.start))
.then(self.key.end.cmp(&other.key.end).reverse())
.then(self.key.end.cmp(&other.key.end))
.then(self.is_image.cmp(&other.is_image))
}
}
@@ -86,14 +80,11 @@ impl<Value: Clone> HistoricLayerCoverage<Value> {
}
}
/// Add a layer, returning whether the insertion had any effect.
///
/// Returns false after inserting a layer whose Key-Lsn space is already
/// covered by a union of previously inserted layers.
/// Add a layer
///
/// Panics if new layer has older lsn.start than an existing layer.
/// See BufferedHistoricLayerCoverage for a more general insertion method.
pub fn insert(&mut self, layer_key: LayerKey, value: Value) -> bool {
pub fn insert(&mut self, layer_key: LayerKey, value: Value) {
// It's only a persistent map, not a retroactive one
if let Some(last_entry) = self.historic.iter().next_back() {
let last_lsn = last_entry.0;
@@ -109,12 +100,10 @@ impl<Value: Clone> HistoricLayerCoverage<Value> {
&mut self.head.delta_coverage
};
let changed = target.insert(layer_key.key, layer_key.lsn.clone(), value);
target.insert(layer_key.key, layer_key.lsn.clone(), value);
// Remember history. Clone is O(1)
self.historic.insert(layer_key.lsn.start, self.head.clone());
changed
}
/// Query at a particular LSN, inclusive
@@ -215,35 +204,6 @@ fn test_off_by_one() {
assert_eq!(version.image_coverage.query(5), None);
}
/// White-box regression test, checking for incorrect removal of node at key.end
#[test]
fn test_regression() {
let mut map = HistoricLayerCoverage::<String>::new();
map.insert(
LayerKey {
key: 0..5,
lsn: 0..5,
is_image: false,
},
"Layer 1".to_string(),
);
map.insert(
LayerKey {
key: 0..5,
lsn: 1..2,
is_image: false,
},
"Layer 2".to_string(),
);
// If an insertion operation improperly deletes the endpoint of a previous layer
// (which is more likely to happen with layers that collide on key.end), we will
// end up with an infinite layer, covering the entire keyspace. Here we assert
// that there's no layer at key 100 because we didn't insert any layer there.
let version = map.get_version(100).unwrap();
assert_eq!(version.delta_coverage.query(100), None);
}
/// Cover edge cases where layers begin or end on the same key
#[test]
fn test_key_collision() {
@@ -431,18 +391,6 @@ pub struct BufferedHistoricLayerCoverage<Value> {
/// All current layers. This is not used for search. Only to make rebuilds easier.
layers: BTreeMap<LayerKey, Value>,
/// Redundant layers are ones that are completely covered by a union of other layers.
/// If two layers are identical only one of them will be marked as redundant, such that
/// it is always safe to remove all redundant layers without seeing any difference in
/// results. If a layer is contained in another, the inner one will be marked as
/// redundant. This makes sure that if we have an L1 layer and a set of L0 layers
/// that completely cover it, the L0s are marked redundant, not the L1.
///
/// Redundant layers can show up if the pageserver dies during compaction, after
/// creating some L1 layers but before deleting the L0 layers. In this case we'd rather
/// notice the redundant L0 layers than recreate the L1 layer, or do something worse.
redundant_layers: BTreeMap<LayerKey, Value>,
}
impl<T: std::fmt::Debug> std::fmt::Debug for BufferedHistoricLayerCoverage<T> {
@@ -466,7 +414,6 @@ impl<Value: Clone> BufferedHistoricLayerCoverage<Value> {
historic_coverage: HistoricLayerCoverage::<Value>::new(),
buffer: BTreeMap::new(),
layers: BTreeMap::new(),
redundant_layers: BTreeMap::new(),
}
}
@@ -547,7 +494,6 @@ impl<Value: Clone> BufferedHistoricLayerCoverage<Value> {
}
None => {
self.layers.remove(layer_key);
self.redundant_layers.remove(layer_key);
}
};
false
@@ -558,20 +504,14 @@ impl<Value: Clone> BufferedHistoricLayerCoverage<Value> {
self.historic_coverage.trim(&rebuild_since);
for (layer_key, layer) in self.layers.range(
LayerKey {
lsn: rebuild_since..u64::MAX,
key: 0..i128::MAX,
lsn: rebuild_since..0,
key: 0..0,
is_image: false,
}..,
) {
let changed = self
.historic_coverage
self.historic_coverage
.insert(layer_key.clone(), layer.clone());
num_inserted += 1;
if !changed {
self.redundant_layers
.insert(layer_key.clone(), layer.clone());
}
}
// TODO maybe only warn if ratio is at least 10
@@ -592,16 +532,6 @@ impl<Value: Clone> BufferedHistoricLayerCoverage<Value> {
self.layers.values().cloned()
}
/// Returns whether the layer with the given key was already inserted as redundant
#[allow(dead_code)] // This function should be used on startup to clean up.
pub fn is_redundant(&self, key: &LayerKey) -> bool {
if !self.buffer.is_empty() {
panic!("rebuild pls")
}
self.redundant_layers.contains_key(key)
}
/// Return a reference to a queryable map, assuming all updates
/// have already been processed using self.rebuild()
pub fn get(&self) -> anyhow::Result<&HistoricLayerCoverage<Value>> {
@@ -741,32 +671,6 @@ fn test_retroactive_simple() {
}
}
#[test]
fn test_redundant_layers() {
for i in 0..10 {
for j in 0..10 {
let key1 = LayerKey {
key: i..(i + 2),
lsn: j..(j + 2),
is_image: false,
};
let key2 = LayerKey {
key: 3..6,
lsn: 3..6,
is_image: false,
};
let is_redundant = i >= 3 && i + 2 <= 6 && j >= 3 && j + 2 <= 6;
let mut map = BufferedHistoricLayerCoverage::new();
map.insert(key1.clone(), "Delta 1".to_string());
map.insert(key2.clone(), "Delta 2".to_string());
map.rebuild();
assert_eq!(map.is_redundant(&key1), is_redundant);
assert!(!map.is_redundant(&key2));
}
}
}
#[test]
fn test_retroactive_replacement() {
let mut map = BufferedHistoricLayerCoverage::new();
@@ -10,22 +10,19 @@ use rpds::RedBlackTreeMapSync;
/// - iterate the latest layers in a key range
/// - insert layers in non-decreasing lsn.start order
///
/// For a detailed explanation and justification of this approach, see:
/// https://neon.tech/blog/persistent-structures-in-neons-wal-indexing
///
/// NOTE The struct is parameterized over Value for easier
/// testing, but in practice it's some sort of layer.
/// The struct is parameterized over Value for easier
/// testing, but in practice it's some sort of layer.
pub struct LayerCoverage<Value> {
/// For every change in coverage (as we sweep the key space)
/// we store (lsn.end, value).
///
/// NOTE We use an immutable/persistent tree so that we can keep historic
/// versions of this coverage without cloning the whole thing and
/// incurring quadratic memory cost. See HistoricLayerCoverage.
/// We use an immutable/persistent tree so that we can keep historic
/// versions of this coverage without cloning the whole thing and
/// incurring quadratic memory cost. See HistoricLayerCoverage.
///
/// NOTE We use the Sync version of the map because we want Self to
/// be Sync. Using nonsync might be faster, if we can work with
/// that.
/// We use the Sync version of the map because we want Self to
/// be Sync. Using nonsync might be faster, if we can work with
/// that.
nodes: RedBlackTreeMapSync<i128, Option<(u64, Value)>>,
}
@@ -44,13 +41,6 @@ impl<Value: Clone> LayerCoverage<Value> {
/// Helper function to subdivide the key range without changing any values
///
/// This operation has no semantic effect by itself. It only helps us pin in
/// place the part of the coverage we don't want to change when inserting.
///
/// As an analogy, think of a polygon. If you add a vertex along one of the
/// segments, the polygon is still the same, but it behaves differently when
/// we move or delete one of the other points.
///
/// Complexity: O(log N)
fn add_node(&mut self, key: i128) {
let value = match self.nodes.range(..=key).last() {
@@ -61,13 +51,10 @@ impl<Value: Clone> LayerCoverage<Value> {
self.nodes.insert_mut(key, value);
}
/// Insert a layer, returning whether the insertion had any effect.
///
/// Returns false after inserting a layer whose Key-Lsn space is already
/// covered by a union of previously inserted layers.
/// Insert a layer.
///
/// Complexity: worst case O(N), in practice O(log N). See NOTE in implementation.
pub fn insert(&mut self, key: Range<i128>, lsn: Range<u64>, value: Value) -> bool {
pub fn insert(&mut self, key: Range<i128>, lsn: Range<u64>, value: Value) {
// Add nodes at endpoints
//
// NOTE The order of lines is important. We add nodes at the start
@@ -87,7 +74,7 @@ impl<Value: Clone> LayerCoverage<Value> {
let mut to_update = Vec::new();
let mut to_remove = Vec::new();
let mut prev_covered = false;
for (k, node) in self.nodes.range(key) {
for (k, node) in self.nodes.range(key.clone()) {
let needs_cover = match node {
None => true,
Some((h, _)) => h < &lsn.end,
@@ -100,16 +87,15 @@ impl<Value: Clone> LayerCoverage<Value> {
}
prev_covered = needs_cover;
}
// TODO check if the nodes inserted at key.start and key.end are safe
// to remove. It's fine to keep them but they could be redundant.
for k in &to_update {
self.nodes.insert_mut(*k, Some((lsn.end, value.clone())));
if !prev_covered {
to_remove.push(key.end);
}
for k in &to_remove {
self.nodes.remove_mut(k);
for k in to_update {
self.nodes.insert_mut(k, Some((lsn.end, value.clone())));
}
for k in to_remove {
self.nodes.remove_mut(&k);
}
!to_update.is_empty()
}
/// Get the latest (by lsn.end) layer at a given key
+1 -1
View File
@@ -212,7 +212,7 @@ pub fn schedule_local_tenant_processing(
)
}
} else {
info!("tenant {tenant_id} is assumed to be loadable, starting load operation");
trace!("tenant {tenant_id} is assumed to be loadable, starting load operation");
// Start loading the tenant into memory. It will initially be in Loading state.
Tenant::spawn_load(
conf,
+8 -8
View File
@@ -61,7 +61,7 @@ pub fn start_background_loops(tenant: &Arc<Tenant>, init_done: Option<&completio
///
async fn compaction_loop(tenant: Arc<Tenant>) {
let wait_duration = Duration::from_secs(2);
info!("starting");
debug!("starting");
TENANT_TASK_EVENTS.with_label_values(&["start"]).inc();
async {
let cancel = task_mgr::shutdown_token();
@@ -72,7 +72,7 @@ async fn compaction_loop(tenant: Arc<Tenant>) {
tokio::select! {
_ = cancel.cancelled() => {
info!("received cancellation request");
debug!("received cancellation request");
return;
},
tenant_wait_result = wait_for_active_tenant(&tenant) => match tenant_wait_result {
@@ -95,7 +95,7 @@ async fn compaction_loop(tenant: Arc<Tenant>) {
let started_at = Instant::now();
let sleep_duration = if period == Duration::ZERO {
info!("automatic compaction is disabled");
debug!("automatic compaction is disabled");
// check again in 10 seconds, in case it's been enabled again.
Duration::from_secs(10)
} else {
@@ -113,7 +113,7 @@ async fn compaction_loop(tenant: Arc<Tenant>) {
// Sleep
tokio::select! {
_ = cancel.cancelled() => {
info!("received cancellation request during idling");
debug!("received cancellation request during idling");
break;
},
_ = tokio::time::sleep(sleep_duration) => {},
@@ -131,7 +131,7 @@ async fn compaction_loop(tenant: Arc<Tenant>) {
///
async fn gc_loop(tenant: Arc<Tenant>) {
let wait_duration = Duration::from_secs(2);
info!("starting");
debug!("starting");
TENANT_TASK_EVENTS.with_label_values(&["start"]).inc();
async {
let cancel = task_mgr::shutdown_token();
@@ -145,7 +145,7 @@ async fn gc_loop(tenant: Arc<Tenant>) {
tokio::select! {
_ = cancel.cancelled() => {
info!("received cancellation request");
debug!("received cancellation request");
return;
},
tenant_wait_result = wait_for_active_tenant(&tenant) => match tenant_wait_result {
@@ -167,7 +167,7 @@ async fn gc_loop(tenant: Arc<Tenant>) {
let gc_horizon = tenant.get_gc_horizon();
let sleep_duration = if period == Duration::ZERO || gc_horizon == 0 {
info!("automatic GC is disabled");
debug!("automatic GC is disabled");
// check again in 10 seconds, in case it's been enabled again.
Duration::from_secs(10)
} else {
@@ -188,7 +188,7 @@ async fn gc_loop(tenant: Arc<Tenant>) {
// Sleep
tokio::select! {
_ = cancel.cancelled() => {
info!("received cancellation request during idling");
debug!("received cancellation request during idling");
break;
},
_ = tokio::time::sleep(sleep_duration) => {},
+31 -33
View File
@@ -674,7 +674,10 @@ impl Timeline {
}
/// Outermost timeline compaction operation; downloads needed layers.
#[instrument(skip_all)]
pub async fn compact(self: &Arc<Self>, ctx: &RequestContext) -> anyhow::Result<()> {
debug_assert_current_span_has_tenant_and_timeline_id();
const ROUNDS: usize = 2;
let last_record_lsn = self.get_last_record_lsn();
@@ -1291,13 +1294,6 @@ impl Timeline {
.unwrap_or(default_tenant_conf.evictions_low_residence_duration_metric_threshold)
}
fn get_gc_feedback(&self) -> bool {
let tenant_conf = self.tenant_conf.read().unwrap();
tenant_conf
.gc_feedback
.unwrap_or(self.conf.default_tenant_conf.gc_feedback)
}
pub(super) fn tenant_conf_updated(&self) {
// NB: Most tenant conf options are read by background loops, so,
// changes will automatically be picked up.
@@ -1441,7 +1437,7 @@ impl Timeline {
match *flush_loop_state {
FlushLoopState::NotStarted => (),
FlushLoopState::Running => {
info!(
debug!(
"skipping attempt to start flush_loop twice {}/{}",
self.tenant_id, self.timeline_id
);
@@ -1459,7 +1455,7 @@ impl Timeline {
let layer_flush_start_rx = self.layer_flush_start_tx.subscribe();
let self_clone = Arc::clone(self);
info!("spawning flush loop");
debug!("spawning flush loop");
task_mgr::spawn(
task_mgr::BACKGROUND_RUNTIME.handle(),
task_mgr::TaskKind::LayerFlushTask,
@@ -1475,7 +1471,11 @@ impl Timeline {
*flush_loop_state = FlushLoopState::Exited;
Ok(())
}
.instrument(info_span!(parent: None, "layer flush task", tenant = %self.tenant_id, timeline = %self.timeline_id))
.instrument({
let span = info_span!(parent: None, "layer flush task", tenant_id = %self.tenant_id, timeline_id = %self.timeline_id);
span.follows_from(Span::current());
span
})
);
*flush_loop_state = FlushLoopState::Running;
@@ -1490,7 +1490,7 @@ impl Timeline {
ctx: &RequestContext,
broker_client: BrokerClientChannel,
) {
info!(
debug!(
"launching WAL receiver for timeline {} of tenant {}",
self.timeline_id, self.tenant_id
);
@@ -1611,7 +1611,7 @@ impl Timeline {
} else if fname == METADATA_FILE_NAME || fname.ends_with(".old") {
// ignore these
} else if remote_timeline_client::is_temp_download_file(&direntry_path) {
info!(
debug!(
"skipping temp download file, reconcile_with_remote will resume / clean up: {}",
fname
);
@@ -1620,7 +1620,7 @@ impl Timeline {
trace!("deleting old ephemeral file in timeline dir: {}", fname);
fs::remove_file(&direntry_path)?;
} else if is_temporary(&direntry_path) {
info!("removing temp timeline file at {}", direntry_path.display());
debug!("removing temp timeline file at {}", direntry_path.display());
fs::remove_file(&direntry_path).with_context(|| {
format!(
"failed to remove temp download file at {}",
@@ -1717,7 +1717,7 @@ impl Timeline {
}
}
info!(
debug!(
"remote layer does not exist locally, creating remote layer: {}",
remote_layer_name.file_name()
);
@@ -1802,7 +1802,7 @@ impl Timeline {
up_to_date_metadata: &TimelineMetadata,
index_part: Option<&IndexPart>,
) -> anyhow::Result<()> {
info!("starting");
trace!("starting");
let remote_client = self
.remote_client
.as_ref()
@@ -1822,7 +1822,7 @@ impl Timeline {
let has_local_layers = !local_layers.is_empty();
let local_only_layers = match index_part {
Some(index_part) => {
info!(
debug!(
"initializing upload queue from remote index with {} layer files",
index_part.timeline_layers.len()
);
@@ -1831,7 +1831,7 @@ impl Timeline {
.await?
}
None => {
info!("initializing upload queue as empty");
debug!("initializing upload queue as empty");
remote_client.init_upload_queue_for_empty_remote(up_to_date_metadata)?;
local_layers
}
@@ -1849,7 +1849,7 @@ impl Timeline {
.metadata()
.with_context(|| format!("failed to get file {layer_path:?} metadata"))?
.len();
info!("scheduling {layer_path:?} for upload");
debug!("scheduling {layer_path:?} for upload");
remote_client
.schedule_layer_file_upload(layer_name, &LayerFileMetadata::new(layer_size))?;
}
@@ -1872,7 +1872,7 @@ impl Timeline {
// Local timeline has a metadata file, remote one too, both have no layers to sync.
}
info!("Done");
trace!("Done");
Ok(())
}
@@ -1894,7 +1894,7 @@ impl Timeline {
.get()
.is_none());
info!(
debug!(
"spawning logical size computation from context of task kind {:?}",
ctx.task_kind()
);
@@ -2088,6 +2088,7 @@ impl Timeline {
///
/// NOTE: counted incrementally, includes ancestors. This can be a slow operation,
/// especially if we need to download remote layers.
#[instrument(skip_all)]
pub async fn calculate_logical_size(
&self,
up_to_lsn: Lsn,
@@ -2095,7 +2096,7 @@ impl Timeline {
cancel: CancellationToken,
ctx: &RequestContext,
) -> Result<u64, CalculateLogicalSizeError> {
info!(
debug!(
"Calculating logical size for timeline {} at {}",
self.timeline_id, up_to_lsn
);
@@ -2137,8 +2138,8 @@ impl Timeline {
let logical_size = self
.get_current_logical_size_non_incremental(up_to_lsn, cancel, ctx)
.await?;
debug!("calculated logical size: {logical_size}");
timer.stop_and_record();
info!("calculated logical size: {logical_size}");
Ok(logical_size)
}
@@ -2650,11 +2651,11 @@ impl Timeline {
mut layer_flush_start_rx: tokio::sync::watch::Receiver<u64>,
ctx: &RequestContext,
) {
info!("started flush loop");
debug!("started flush loop");
loop {
tokio::select! {
_ = task_mgr::shutdown_watcher() => {
info!("shutting down layer flush task");
debug!("shutting down layer flush task");
break;
},
_ = layer_flush_start_rx.changed() => {}
@@ -2917,6 +2918,7 @@ impl Timeline {
Ok((new_delta_filename, LayerFileMetadata::new(sz)))
}
#[instrument(skip_all)]
async fn repartition(
&self,
lsn: Lsn,
@@ -3022,6 +3024,7 @@ impl Timeline {
Ok(false)
}
#[instrument(skip_all)]
async fn create_image_layers(
&self,
partitioning: &KeyPartitioning,
@@ -3131,7 +3134,6 @@ impl Timeline {
let mut layers = self.layers.write().unwrap();
let mut updates = layers.batch_update();
let timeline_path = self.conf.timeline_path(&self.timeline_id, &self.tenant_id);
for l in image_layers {
let path = l.filename();
let metadata = timeline_path
@@ -3246,7 +3248,7 @@ impl Timeline {
let remotes = deltas_to_compact
.iter()
.filter(|l| l.is_remote_layer())
.inspect(|l| info!("compact requires download of {}", l.filename().file_name()))
.inspect(|l| debug!("compact requires download of {}", l.filename().file_name()))
.map(|l| {
l.clone()
.downcast_remote_layer()
@@ -3270,7 +3272,7 @@ impl Timeline {
);
for l in deltas_to_compact.iter() {
info!("compact includes {}", l.filename().file_name());
debug!("compact includes {}", l.filename().file_name());
}
// We don't need the original list of layers anymore. Drop it so that
@@ -3517,10 +3519,6 @@ impl Timeline {
drop(all_keys_iter); // So that deltas_to_compact is no longer borrowed
fail_point!("compact-level0-phase1-finish", |_| {
Err(anyhow::anyhow!("failpoint compact-level0-phase1-finish").into())
});
Ok(CompactLevel0Phase1Result {
new_layers,
deltas_to_compact,
@@ -3802,7 +3800,7 @@ impl Timeline {
write_guard.store_and_unlock(new_gc_cutoff).wait();
}
info!("GC starting");
debug!("GC starting");
debug!("retain_lsns: {:?}", retain_lsns);
@@ -3908,7 +3906,7 @@ impl Timeline {
// delta layers. Image layers can form "stairs" preventing old image from been deleted.
// But image layers are in any case less sparse than delta layers. Also we need some
// protection from replacing recent image layers with new one after each GC iteration.
if self.get_gc_feedback() && l.is_incremental() && !LayerMap::is_l0(&*l) {
if l.is_incremental() && !LayerMap::is_l0(&*l) {
wanted_image_layers.add_range(l.get_key_range());
}
result.layers_not_updated += 1;
@@ -22,7 +22,7 @@ use std::{
use tokio::time::Instant;
use tokio_util::sync::CancellationToken;
use tracing::{debug, error, info, info_span, instrument, warn, Instrument};
use tracing::{debug, error, info, info_span, instrument, trace, warn, Instrument};
use crate::{
context::{DownloadBehavior, RequestContext},
@@ -58,7 +58,7 @@ impl Timeline {
false,
async move {
self_clone.eviction_task(task_mgr::shutdown_token()).await;
info!("eviction task finishing");
debug!("eviction task finishing");
Ok(())
},
);
@@ -74,7 +74,7 @@ impl Timeline {
EvictionPolicy::NoEviction => Duration::from_secs(10),
};
if random_init_delay(period, &cancel).await.is_err() {
info!("shutting down");
trace!("shutting down");
return;
}
}
@@ -89,7 +89,7 @@ impl Timeline {
ControlFlow::Continue(sleep_until) => {
tokio::select! {
_ = cancel.cancelled() => {
info!("shutting down");
trace!("shutting down");
break;
}
_ = tokio::time::sleep_until(sleep_until) => { }
@@ -348,7 +348,6 @@ impl Timeline {
cancel.clone(),
ctx,
)
.instrument(info_span!("calculate_logical_size"))
.await;
match &size {
@@ -85,7 +85,7 @@ impl WalReceiver {
&format!("walreceiver for timeline {tenant_id}/{timeline_id}"),
false,
async move {
info!("WAL receiver manager started, connecting to broker");
debug!("WAL receiver manager started, connecting to broker");
let mut connection_manager_state = ConnectionManagerState::new(
timeline,
conf,
@@ -93,7 +93,7 @@ impl WalReceiver {
loop {
select! {
_ = task_mgr::shutdown_watcher() => {
info!("WAL receiver shutdown requested, shutting down");
trace!("WAL receiver shutdown requested, shutting down");
break;
},
loop_step_result = connection_manager_loop_step(
@@ -104,7 +104,7 @@ impl WalReceiver {
) => match loop_step_result {
ControlFlow::Continue(()) => continue,
ControlFlow::Break(()) => {
info!("Connection manager loop ended, shutting down");
trace!("Connection manager loop ended, shutting down");
break;
}
},
@@ -115,7 +115,11 @@ impl WalReceiver {
*loop_status.write().unwrap() = None;
Ok(())
}
.instrument(info_span!(parent: None, "wal_connection_manager", tenant = %tenant_id, timeline = %timeline_id))
.instrument({
let span = info_span!(parent: None, "wal_connection_manager", tenant = %tenant_id, timeline = %timeline_id);
span.follows_from(Span::current());
span
})
);
Self {
@@ -214,7 +218,7 @@ impl<E: Clone> TaskHandle<E> {
// So, tone them down to info-level.
//
// XXX: rewrite this module to eliminate the race condition.
info!("sender is dropped while join handle is still alive");
debug!("sender is dropped while join handle is still alive");
}
let res = jh
@@ -56,7 +56,7 @@ pub(super) async fn connection_manager_loop_step(
{
Ok(()) => {}
Err(_) => {
info!("Timeline dropped state updates sender before becoming active, stopping wal connection manager loop");
debug!("Timeline dropped state updates sender before becoming active, stopping wal connection manager loop");
return ControlFlow::Break(());
}
}
@@ -79,7 +79,7 @@ pub(super) async fn connection_manager_loop_step(
// with other streams on this client (other connection managers). When
// object goes out of scope, stream finishes in drop() automatically.
let mut broker_subscription = subscribe_for_timeline_updates(broker_client, id).await;
info!("Subscribed for broker timeline updates");
debug!("Subscribed for broker timeline updates");
loop {
let time_until_next_retry = connection_manager_state.time_until_next_retry();
@@ -151,7 +151,7 @@ pub(super) async fn connection_manager_loop_step(
// we're already active as walreceiver, no need to reactivate
TimelineState::Active => continue,
TimelineState::Broken | TimelineState::Stopping => {
info!("timeline entered terminal state {new_state:?}, stopping wal connection manager loop");
debug!("timeline entered terminal state {new_state:?}, stopping wal connection manager loop");
return ControlFlow::Break(());
}
TimelineState::Loading => {
@@ -165,11 +165,11 @@ pub(super) async fn connection_manager_loop_step(
}
} => match new_event {
ControlFlow::Continue(new_state) => {
info!("observed timeline state change, new state is {new_state:?}");
debug!("observed timeline state change, new state is {new_state:?}");
return ControlFlow::Continue(());
}
ControlFlow::Break(()) => {
info!("Timeline dropped state updates sender, stopping wal connection manager loop");
debug!("Timeline dropped state updates sender, stopping wal connection manager loop");
return ControlFlow::Break(());
}
},
@@ -470,7 +470,7 @@ impl ConnectionManagerState {
if let Some(next) = &retry.next_retry_at {
if next > &now {
info!(
debug!(
"Next connection retry to {:?} is at {}",
wal_connection.sk_id, next
);
@@ -515,7 +515,7 @@ impl ConnectionManagerState {
);
if old_entry.is_none() {
info!("New SK node was added: {new_safekeeper_id}");
debug!("New SK node was added: {new_safekeeper_id}");
WALRECEIVER_CANDIDATES_ADDED.inc();
}
}
@@ -119,6 +119,7 @@ pub(super) async fn handle_walreceiver_connection(
ctx.download_behavior(),
);
let connection_cancellation = cancellation.clone();
use tracing::Instrument;
task_mgr::spawn(
WALRECEIVER_RUNTIME.handle(),
TaskKind::WalReceiverConnectionPoller,
@@ -140,7 +141,8 @@ pub(super) async fn handle_walreceiver_connection(
_ = connection_cancellation.cancelled() => info!("Connection cancelled"),
}
Ok(())
},
}
.instrument(tracing::info_span!("walreceiver")),
);
// Immediately increment the gauge, then create a job to decrement it on task exit.
@@ -153,7 +155,7 @@ pub(super) async fn handle_walreceiver_connection(
}
let identify = identify_system(&mut replication_client).await?;
info!("{identify:?}");
debug!("{identify:?}");
let end_of_wal = Lsn::from(u64::from(identify.xlogpos));
let mut caught_up = false;
-2
View File
@@ -1621,8 +1621,6 @@ class NeonPageserver(PgProtocol):
".*Compaction failed, retrying in [^:]+: Cannot run compaction iteration on inactive tenant",
# these can happen anytime we do compactions from background task and shutdown pageserver
r".*ERROR.*ancestor timeline \S+ is being stopped",
# this is expected given our collaborative shutdown approach for the UploadQueue
".*Compaction failed, retrying in .*: queue is in state Stopped.*",
]
def start(
@@ -158,7 +158,6 @@ def test_fully_custom_config(positive_env: NeonEnv):
"threshold": "23h",
},
"evictions_low_residence_duration_metric_threshold": "2days",
"gc_feedback": True,
"gc_horizon": 23 * (1024 * 1024),
"gc_period": "2h 13m",
"image_creation_threshold": 7,