From ffd146c3e519ace5f14b619ca63f00ca9dda4b56 Mon Sep 17 00:00:00 2001 From: Joonas Koivunen Date: Wed, 13 Sep 2023 22:05:30 +0300 Subject: [PATCH 01/22] refactor: globals in tests (#5298) Refactor tests to have less globals. This will allow to hopefully write more complex tests for our new metric collection requirements in #5297. Includes reverted work from #4761 related to test globals. Co-authored-by: Alexander Bayandin Co-authored-by: MMeent --- test_runner/conftest.py | 1 + test_runner/fixtures/httpserver.py | 45 ++++++ test_runner/fixtures/neon_fixtures.py | 6 - test_runner/regress/test_ddl_forwarding.py | 19 ++- test_runner/regress/test_gc_aggressive.py | 75 +++++----- test_runner/regress/test_metric_collection.py | 138 +++++++++--------- test_runner/regress/test_ondemand_download.py | 1 + test_runner/regress/test_tenant_detach.py | 115 +++++++-------- test_runner/regress/test_wal_acceptor.py | 4 +- 9 files changed, 228 insertions(+), 176 deletions(-) create mode 100644 test_runner/fixtures/httpserver.py diff --git a/test_runner/conftest.py b/test_runner/conftest.py index 1c36c1ed02..200c9c3740 100644 --- a/test_runner/conftest.py +++ b/test_runner/conftest.py @@ -1,6 +1,7 @@ pytest_plugins = ( "fixtures.pg_version", "fixtures.parametrize", + "fixtures.httpserver", "fixtures.neon_fixtures", "fixtures.benchmark_fixture", "fixtures.pg_stats", diff --git a/test_runner/fixtures/httpserver.py b/test_runner/fixtures/httpserver.py new file mode 100644 index 0000000000..a321d59266 --- /dev/null +++ b/test_runner/fixtures/httpserver.py @@ -0,0 +1,45 @@ +from typing import Tuple + +import pytest +from pytest_httpserver import HTTPServer + +# TODO: mypy fails with: +# Module "fixtures.neon_fixtures" does not explicitly export attribute "PortDistributor" [attr-defined] +# from fixtures.neon_fixtures import PortDistributor + +# compared to the fixtures from pytest_httpserver with same names, these are +# always function scoped, so you can check and stop the server in tests. + + +@pytest.fixture(scope="function") +def httpserver_ssl_context(): + return None + + +@pytest.fixture(scope="function") +def make_httpserver(httpserver_listen_address, httpserver_ssl_context): + host, port = httpserver_listen_address + if not host: + host = HTTPServer.DEFAULT_LISTEN_HOST + if not port: + port = HTTPServer.DEFAULT_LISTEN_PORT + + server = HTTPServer(host=host, port=port, ssl_context=httpserver_ssl_context) + server.start() + yield server + server.clear() + if server.is_running(): + server.stop() + + +@pytest.fixture(scope="function") +def httpserver(make_httpserver): + server = make_httpserver + yield server + server.clear() + + +@pytest.fixture(scope="function") +def httpserver_listen_address(port_distributor) -> Tuple[str, int]: + port = port_distributor.get_port() + return ("localhost", port) diff --git a/test_runner/fixtures/neon_fixtures.py b/test_runner/fixtures/neon_fixtures.py index 5a1acec9da..c7759d9b44 100644 --- a/test_runner/fixtures/neon_fixtures.py +++ b/test_runner/fixtures/neon_fixtures.py @@ -223,12 +223,6 @@ def port_distributor(worker_base_port: int, worker_port_num: int) -> PortDistrib return PortDistributor(base_port=worker_base_port, port_number=worker_port_num) -@pytest.fixture(scope="session") -def httpserver_listen_address(port_distributor: PortDistributor): - port = port_distributor.get_port() - return ("localhost", port) - - @pytest.fixture(scope="function") def default_broker( port_distributor: PortDistributor, diff --git a/test_runner/regress/test_ddl_forwarding.py b/test_runner/regress/test_ddl_forwarding.py index ebd836ecbc..740e489759 100644 --- a/test_runner/regress/test_ddl_forwarding.py +++ b/test_runner/regress/test_ddl_forwarding.py @@ -42,12 +42,11 @@ def handle_role(dbs, roles, operation): raise ValueError("Invalid op") -fail = False - - -def ddl_forward_handler(request: Request, dbs: Dict[str, str], roles: Dict[str, str]) -> Response: +def ddl_forward_handler( + request: Request, dbs: Dict[str, str], roles: Dict[str, str], ddl: "DdlForwardingContext" +) -> Response: log.info(f"Received request with data {request.get_data(as_text=True)}") - if fail: + if ddl.fail: log.info("FAILING") return Response(status=500, response="Failed just cuz") if request.json is None: @@ -72,6 +71,7 @@ class DdlForwardingContext: self.port = port self.dbs: Dict[str, str] = {} self.roles: Dict[str, str] = {} + self.fail = False endpoint = "/management/api/v2/roles_and_databases" ddl_url = f"http://{host}:{port}{endpoint}" self.pg.configure( @@ -82,7 +82,7 @@ class DdlForwardingContext: ) log.info(f"Listening on {ddl_url}") self.server.expect_request(endpoint, method="PATCH").respond_with_handler( - lambda request: ddl_forward_handler(request, self.dbs, self.roles) + lambda request: ddl_forward_handler(request, self.dbs, self.roles, self) ) def __enter__(self): @@ -103,6 +103,9 @@ class DdlForwardingContext: def wait(self, timeout=3): self.server.wait(timeout=timeout) + def failures(self, bool): + self.fail = bool + def send_and_wait(self, query: str, timeout=3) -> List[Tuple[Any, ...]]: res = self.send(query) self.wait(timeout=timeout) @@ -203,9 +206,9 @@ def test_ddl_forwarding(ddl: DdlForwardingContext): assert ddl.dbs == {"stork": "cork"} with pytest.raises(psycopg2.InternalError): - global fail - fail = True + ddl.failures(True) cur.execute("CREATE DATABASE failure WITH OWNER=cork") ddl.wait() + ddl.failures(False) conn.close() diff --git a/test_runner/regress/test_gc_aggressive.py b/test_runner/regress/test_gc_aggressive.py index db0020a8a4..017a38f85c 100644 --- a/test_runner/regress/test_gc_aggressive.py +++ b/test_runner/regress/test_gc_aggressive.py @@ -15,45 +15,45 @@ from fixtures.types import TimelineId # Test configuration # -# Create a table with {num_rows} rows, and perform {updates_to_perform} random -# UPDATEs on it, using {num_connections} separate connections. -num_connections = 10 -num_rows = 100000 -updates_to_perform = 10000 - -updates_performed = 0 - - -# Run random UPDATEs on test table -async def update_table(endpoint: Endpoint): - global updates_performed - pg_conn = await endpoint.connect_async() - - while updates_performed < updates_to_perform: - updates_performed += 1 - id = random.randrange(1, num_rows) - await pg_conn.fetchrow(f"UPDATE foo SET counter = counter + 1 WHERE id = {id}") - - -# Perform aggressive GC with 0 horizon -async def gc(env: NeonEnv, timeline: TimelineId): - pageserver_http = env.pageserver.http_client() - - loop = asyncio.get_running_loop() - - def do_gc(): - pageserver_http.timeline_checkpoint(env.initial_tenant, timeline) - pageserver_http.timeline_gc(env.initial_tenant, timeline, 0) - - with concurrent.futures.ThreadPoolExecutor() as pool: - while updates_performed < updates_to_perform: - await loop.run_in_executor(pool, do_gc) +# Create a table with {NUM_ROWS} rows, and perform {UPDATES_TO_PERFORM} random +# UPDATEs on it, using {NUM_CONNECTIONS} separate connections. +NUM_CONNECTIONS = 10 +NUM_ROWS = 100000 +UPDATES_TO_PERFORM = 10000 # At the same time, run UPDATEs and GC async def update_and_gc(env: NeonEnv, endpoint: Endpoint, timeline: TimelineId): workers = [] - for _ in range(num_connections): + updates_performed = 0 + + # Perform aggressive GC with 0 horizon + async def gc(env: NeonEnv, timeline: TimelineId): + pageserver_http = env.pageserver.http_client() + nonlocal updates_performed + global UPDATES_TO_PERFORM + + loop = asyncio.get_running_loop() + + def do_gc(): + pageserver_http.timeline_checkpoint(env.initial_tenant, timeline) + pageserver_http.timeline_gc(env.initial_tenant, timeline, 0) + + with concurrent.futures.ThreadPoolExecutor() as pool: + while updates_performed < UPDATES_TO_PERFORM: + await loop.run_in_executor(pool, do_gc) + + # Run random UPDATEs on test table + async def update_table(endpoint: Endpoint): + pg_conn = await endpoint.connect_async() + nonlocal updates_performed + + while updates_performed < UPDATES_TO_PERFORM: + updates_performed += 1 + id = random.randrange(1, NUM_ROWS) + await pg_conn.fetchrow(f"UPDATE foo SET counter = counter + 1 WHERE id = {id}") + + for _ in range(NUM_CONNECTIONS): workers.append(asyncio.create_task(update_table(endpoint))) workers.append(asyncio.create_task(gc(env, timeline))) @@ -81,7 +81,7 @@ def test_gc_aggressive(neon_env_builder: NeonEnvBuilder): f""" INSERT INTO foo SELECT g, 0, 'long string to consume some space' || g - FROM generate_series(1, {num_rows}) g + FROM generate_series(1, {NUM_ROWS}) g """ ) cur.execute("CREATE INDEX ON foo(id)") @@ -91,7 +91,7 @@ def test_gc_aggressive(neon_env_builder: NeonEnvBuilder): cur.execute("SELECT COUNT(*), SUM(counter) FROM foo") r = cur.fetchone() assert r is not None - assert r == (num_rows, updates_to_perform) + assert r == (NUM_ROWS, UPDATES_TO_PERFORM) # @@ -99,6 +99,7 @@ def test_gc_aggressive(neon_env_builder: NeonEnvBuilder): def test_gc_index_upload(neon_env_builder: NeonEnvBuilder, remote_storage_kind: RemoteStorageKind): # Disable time-based pitr, we will use LSN-based thresholds in the manual GC calls neon_env_builder.pageserver_config_override = "tenant_config={pitr_interval = '0 sec'}" + num_index_uploads = 0 neon_env_builder.enable_pageserver_remote_storage(remote_storage_kind) @@ -160,5 +161,5 @@ def test_gc_index_upload(neon_env_builder: NeonEnvBuilder, remote_storage_kind: log.info(f"{num_index_uploads} index uploads after GC iteration {i}") after = num_index_uploads - log.info(f"{after-before} new index uploads during test") + log.info(f"{after - before} new index uploads during test") assert after - before < 5 diff --git a/test_runner/regress/test_metric_collection.py b/test_runner/regress/test_metric_collection.py index 9ec649ee24..821c2ae683 100644 --- a/test_runner/regress/test_metric_collection.py +++ b/test_runner/regress/test_metric_collection.py @@ -3,9 +3,9 @@ # Use mock HTTP server to receive metrics and verify that they look sane. # -import time from pathlib import Path -from typing import Iterator +from queue import SimpleQueue +from typing import Any, Iterator, Set import pytest from fixtures.log_helper import log @@ -18,56 +18,10 @@ from fixtures.neon_fixtures import ( ) from fixtures.port_distributor import PortDistributor from fixtures.remote_storage import RemoteStorageKind -from fixtures.types import TenantId from pytest_httpserver import HTTPServer from werkzeug.wrappers.request import Request from werkzeug.wrappers.response import Response -# ============================================================================== -# Storage metrics tests -# ============================================================================== - -initial_tenant = TenantId.generate() -remote_uploaded = 0 -checks = { - "written_size": lambda value: value > 0, - "resident_size": lambda value: value >= 0, - # >= 0 check here is to avoid race condition when we receive metrics before - # remote_uploaded is updated - "remote_storage_size": lambda value: value > 0 if remote_uploaded > 0 else value >= 0, - # logical size may lag behind the actual size, so allow 0 here - "timeline_logical_size": lambda value: value >= 0, -} - -metric_kinds_checked = set([]) - - -# -# verify that metrics look minilally sane -# -def metrics_handler(request: Request) -> Response: - if request.json is None: - return Response(status=400) - - events = request.json["events"] - log.info("received events:") - log.info(events) - - for event in events: - assert event["tenant_id"] == str( - initial_tenant - ), "Expecting metrics only from the initial tenant" - metric_name = event["metric"] - - check = checks.get(metric_name) - # calm down mypy - if check is not None: - assert check(event["value"]), f"{metric_name} isn't valid" - global metric_kinds_checked - metric_kinds_checked.add(metric_name) - - return Response(status=200) - @pytest.mark.parametrize( "remote_storage_kind", [RemoteStorageKind.NOOP, RemoteStorageKind.LOCAL_FS] @@ -81,6 +35,18 @@ def test_metric_collection( (host, port) = httpserver_listen_address metric_collection_endpoint = f"http://{host}:{port}/billing/api/v1/usage_events" + metric_kinds_checked: Set[str] = set([]) + + uploads: SimpleQueue[Any] = SimpleQueue() + + def metrics_handler(request: Request) -> Response: + if request.json is None: + return Response(status=400) + + events = request.json["events"] + uploads.put(events) + return Response(status=200) + # Require collecting metrics frequently, since we change # the timeline and want something to be logged about it. # @@ -90,6 +56,7 @@ def test_metric_collection( f""" metric_collection_interval="1s" metric_collection_endpoint="{metric_collection_endpoint}" + cached_metric_collection_interval="0s" """ + "tenant_config={pitr_interval = '0 sec'}" ) @@ -98,9 +65,6 @@ def test_metric_collection( log.info(f"test_metric_collection endpoint is {metric_collection_endpoint}") - # Set initial tenant of the test, that we expect the logs from - global initial_tenant - initial_tenant = neon_env_builder.initial_tenant # mock http server that returns OK for the metrics httpserver.expect_request("/billing/api/v1/usage_events", method="POST").respond_with_handler( metrics_handler @@ -108,8 +72,7 @@ def test_metric_collection( # spin up neon, after http server is ready env = neon_env_builder.init_start() - # Order of fixtures shutdown is not specified, and if http server gets down - # before pageserver, pageserver log might contain such errors in the end. + # httpserver is shut down before pageserver during passing run env.pageserver.allowed_errors.append(".*metrics endpoint refused the sent metrics*") tenant_id = env.initial_tenant timeline_id = env.neon_cli.create_branch("test_metric_collection") @@ -141,29 +104,74 @@ def test_metric_collection( total += sample[2] return int(total) + remote_uploaded = 0 + # upload some data to remote storage if remote_storage_kind == RemoteStorageKind.LOCAL_FS: wait_for_last_flush_lsn(env, endpoint, tenant_id, timeline_id) pageserver_http = env.pageserver.http_client() pageserver_http.timeline_checkpoint(tenant_id, timeline_id) pageserver_http.timeline_gc(tenant_id, timeline_id, 10000) - global remote_uploaded + remote_uploaded = get_num_remote_ops("index", "upload") assert remote_uploaded > 0 - # wait longer than collecting interval and check that all requests are served - time.sleep(3) - httpserver.check() - global metric_kinds_checked, checks + # we expect uploads at 1Hz, on busy runners this could be too optimistic, + # so give 5s we only want to get the following upload after "ready" value. + # later tests will be added to ensure that the timeseries are sane. + timeout = 5 + uploads.put("ready") + + while True: + # discard earlier than "ready" + log.info("waiting for upload") + events = uploads.get(timeout=timeout) + import json + + if events == "ready": + events = uploads.get(timeout=timeout) + httpserver.check() + httpserver.stop() + # if anything comes after this, we'll just ignore it + stringified = json.dumps(events, indent=2) + log.info(f"inspecting: {stringified}") + break + else: + stringified = json.dumps(events, indent=2) + log.info(f"discarding: {stringified}") + + # verify that metrics look minimally sane + checks = { + "written_size": lambda value: value > 0, + "resident_size": lambda value: value >= 0, + "remote_storage_size": lambda value: value > 0 if remote_uploaded > 0 else value == 0, + # logical size may lag behind the actual size, so allow 0 here + "timeline_logical_size": lambda value: value >= 0, + # this can also be zero, depending on when we get the value + "written_data_bytes_delta": lambda value: value >= 0, + } + + metric_kinds_checked = set() + metric_kinds_seen = set() + + for event in events: + assert event["tenant_id"] == str(tenant_id) + metric_name = event["metric"] + metric_kinds_seen.add(metric_name) + + check = checks.get(metric_name) + # calm down mypy + if check is not None: + value = event["value"] + log.info(f"checking {metric_name} value {value}") + assert check(value), f"{metric_name} isn't valid" + metric_kinds_checked.add(metric_name) + expected_checks = set(checks.keys()) - assert len(metric_kinds_checked) == len( - checks + assert ( + metric_kinds_checked == checks.keys() ), f"Expected to receive and check all kind of metrics, but {expected_checks - metric_kinds_checked} got uncovered" - - -# ============================================================================== -# Proxy metrics tests -# ============================================================================== + assert metric_kinds_seen == metric_kinds_checked def proxy_metrics_handler(request: Request) -> Response: diff --git a/test_runner/regress/test_ondemand_download.py b/test_runner/regress/test_ondemand_download.py index fd9f9d631d..49439c5fab 100644 --- a/test_runner/regress/test_ondemand_download.py +++ b/test_runner/regress/test_ondemand_download.py @@ -301,6 +301,7 @@ def test_ondemand_download_timetravel( # they are present only in the remote storage, only locally, or both. # It should not change. assert filled_current_physical == get_api_current_physical_size() + endpoint_old.stop() # diff --git a/test_runner/regress/test_tenant_detach.py b/test_runner/regress/test_tenant_detach.py index cdf72edc4d..b34b2f95b5 100644 --- a/test_runner/regress/test_tenant_detach.py +++ b/test_runner/regress/test_tenant_detach.py @@ -119,65 +119,6 @@ def test_tenant_reattach( num_connections = 10 num_rows = 100000 -updates_to_perform = 0 - -updates_started = 0 -updates_finished = 0 - - -# Run random UPDATEs on test table. On failure, try again. -async def update_table(pg_conn: asyncpg.Connection): - global updates_started, updates_finished, updates_to_perform - - while updates_started < updates_to_perform or updates_to_perform == 0: - updates_started += 1 - id = random.randrange(1, num_rows) - - # Loop to retry until the UPDATE succeeds - while True: - try: - await pg_conn.fetchrow(f"UPDATE t SET counter = counter + 1 WHERE id = {id}") - updates_finished += 1 - if updates_finished % 1000 == 0: - log.info(f"update {updates_finished} / {updates_to_perform}") - break - except asyncpg.PostgresError as e: - # Received error from Postgres. Log it, sleep a little, and continue - log.info(f"UPDATE error: {e}") - await asyncio.sleep(0.1) - - -async def sleep_and_reattach(pageserver_http: PageserverHttpClient, tenant_id: TenantId): - global updates_started, updates_finished, updates_to_perform - - # Wait until we have performed some updates - wait_until(20, 0.5, lambda: updates_finished > 500) - - log.info("Detaching tenant") - pageserver_http.tenant_detach(tenant_id) - await asyncio.sleep(1) - log.info("Re-attaching tenant") - pageserver_http.tenant_attach(tenant_id) - log.info("Re-attach finished") - - # Continue with 5000 more updates - updates_to_perform = updates_started + 5000 - - -# async guts of test_tenant_reattach_while_bysy test -async def reattach_while_busy( - env: NeonEnv, endpoint: Endpoint, pageserver_http: PageserverHttpClient, tenant_id: TenantId -): - workers = [] - for _ in range(num_connections): - pg_conn = await endpoint.connect_async() - workers.append(asyncio.create_task(update_table(pg_conn))) - - workers.append(asyncio.create_task(sleep_and_reattach(pageserver_http, tenant_id))) - await asyncio.gather(*workers) - - assert updates_finished == updates_to_perform - # Detach and re-attach tenant, while compute is busy running queries. # @@ -226,6 +167,62 @@ def test_tenant_reattach_while_busy( neon_env_builder: NeonEnvBuilder, remote_storage_kind: RemoteStorageKind, ): + updates_started = 0 + updates_finished = 0 + updates_to_perform = 0 + + # Run random UPDATEs on test table. On failure, try again. + async def update_table(pg_conn: asyncpg.Connection): + nonlocal updates_started, updates_finished, updates_to_perform + + while updates_started < updates_to_perform or updates_to_perform == 0: + updates_started += 1 + id = random.randrange(1, num_rows) + + # Loop to retry until the UPDATE succeeds + while True: + try: + await pg_conn.fetchrow(f"UPDATE t SET counter = counter + 1 WHERE id = {id}") + updates_finished += 1 + if updates_finished % 1000 == 0: + log.info(f"update {updates_finished} / {updates_to_perform}") + break + except asyncpg.PostgresError as e: + # Received error from Postgres. Log it, sleep a little, and continue + log.info(f"UPDATE error: {e}") + await asyncio.sleep(0.1) + + async def sleep_and_reattach(pageserver_http: PageserverHttpClient, tenant_id: TenantId): + nonlocal updates_started, updates_finished, updates_to_perform + + # Wait until we have performed some updates + wait_until(20, 0.5, lambda: updates_finished > 500) + + log.info("Detaching tenant") + pageserver_http.tenant_detach(tenant_id) + await asyncio.sleep(1) + log.info("Re-attaching tenant") + pageserver_http.tenant_attach(tenant_id) + log.info("Re-attach finished") + + # Continue with 5000 more updates + updates_to_perform = updates_started + 5000 + + # async guts of test_tenant_reattach_while_bysy test + async def reattach_while_busy( + env: NeonEnv, endpoint: Endpoint, pageserver_http: PageserverHttpClient, tenant_id: TenantId + ): + nonlocal updates_to_perform, updates_finished + workers = [] + for _ in range(num_connections): + pg_conn = await endpoint.connect_async() + workers.append(asyncio.create_task(update_table(pg_conn))) + + workers.append(asyncio.create_task(sleep_and_reattach(pageserver_http, tenant_id))) + await asyncio.gather(*workers) + + assert updates_finished == updates_to_perform + neon_env_builder.enable_pageserver_remote_storage(remote_storage_kind) env = neon_env_builder.init_start() diff --git a/test_runner/regress/test_wal_acceptor.py b/test_runner/regress/test_wal_acceptor.py index b080caca33..8199f5777b 100644 --- a/test_runner/regress/test_wal_acceptor.py +++ b/test_runner/regress/test_wal_acceptor.py @@ -14,6 +14,8 @@ from pathlib import Path from typing import Any, List, Optional import psycopg2 +import psycopg2.errors +import psycopg2.extras import pytest from fixtures.broker import NeonBroker from fixtures.log_helper import log @@ -260,7 +262,7 @@ def test_restarts(neon_env_builder: NeonEnvBuilder): else: failed_node.start() failed_node = None - assert query_scalar(cur, "SELECT sum(key) FROM t") == 500500 + assert query_scalar(cur, "SELECT sum(key) FROM t") == (n_inserts * (n_inserts + 1)) // 2 # Test that safekeepers push their info to the broker and learn peer status from it From 3895829bda90635b162beef49718aa4ebffa9a37 Mon Sep 17 00:00:00 2001 From: Em Sharnoff Date: Thu, 14 Sep 2023 03:21:50 -0700 Subject: [PATCH 02/22] vm-monitor: Fix cgroup throttling (#5303) I believe this (not actual IO problems) is the cause of the "disk speed issue" that we've had for VMs recently. See e.g.: 1. https://neondb.slack.com/archives/C03H1K0PGKH/p1694287808046179?thread_ts=1694271790.580099&cid=C03H1K0PGKH 2. https://neondb.slack.com/archives/C03H1K0PGKH/p1694511932560659 The vm-informant (and now, the vm-monitor, its replacement) is supposed to gradually increase the `neon-postgres` cgroup's memory.high value, because otherwise the kernel will throttle all the processes in the cgroup. This PR fixes a bug with the vm-monitor's implementation of this behavior. --- Other references, for the vm-informant's implementation: - Original issue: neondatabase/autoscaling#44 - Original PR: neondatabase/autoscaling#223 --- libs/vm_monitor/src/cgroup.rs | 22 ++++++++++++---------- 1 file changed, 12 insertions(+), 10 deletions(-) diff --git a/libs/vm_monitor/src/cgroup.rs b/libs/vm_monitor/src/cgroup.rs index 4f529d16fd..fe1c514f76 100644 --- a/libs/vm_monitor/src/cgroup.rs +++ b/libs/vm_monitor/src/cgroup.rs @@ -315,12 +315,8 @@ impl CgroupWatcher { where E: Stream>, { - // There are several actions might do when receiving a `memory.high`, - // such as freezing the cgroup, or increasing its `memory.high`. We don't - // want to do these things too often (because postgres needs to run, and - // we only have so much memory). These timers serve as rate limits for this. let mut wait_to_freeze = pin!(tokio::time::sleep(Duration::ZERO)); - let mut wait_to_increase_memory_high = pin!(tokio::time::sleep(Duration::ZERO)); + let mut last_memory_high_increase_at: Option = None; let mut events = pin!(events); // Are we waiting to be upscaled? Could be true if we request upscale due @@ -332,6 +328,8 @@ impl CgroupWatcher { upscale = upscales.recv() => { let Sequenced { seqnum, data } = upscale .context("failed to listen on upscale notification channel")?; + waiting_on_upscale = false; + last_memory_high_increase_at = None; self.last_upscale_seqnum.store(seqnum, Ordering::Release); info!(cpu = data.cpu, mem_bytes = data.mem, "received upscale"); } @@ -396,12 +394,17 @@ impl CgroupWatcher { .send(()) .await .context("failed to request upscale")?; + waiting_on_upscale = true; continue; } // Shoot, we can't freeze or and we're still waiting on upscale, // increase memory.high to reduce throttling - if wait_to_increase_memory_high.is_elapsed() { + let can_increase_memory_high = match last_memory_high_increase_at { + None => true, + Some(t) => t.elapsed() > self.config.memory_high_increase_every, + }; + if can_increase_memory_high { info!( "received memory.high event, \ but too soon to refreeze and already requested upscale \ @@ -437,12 +440,11 @@ impl CgroupWatcher { ); self.set_high_bytes(new_high) .context("failed to set memory.high")?; - wait_to_increase_memory_high - .as_mut() - .reset(Instant::now() + self.config.memory_high_increase_every) + last_memory_high_increase_at = Some(Instant::now()); + continue; } - // we can't do anything + info!("received memory.high event, but can't do anything"); } }; } From 0501b74f551432f7267baf8fcb1a910a1e683e63 Mon Sep 17 00:00:00 2001 From: Alexander Bayandin Date: Thu, 14 Sep 2023 16:17:50 +0100 Subject: [PATCH 03/22] Update checksum for pg_hint_plan (#5309) ## Problem The checksum for `pg_hint_plan` doesn't match: ``` sha256sum: WARNING: 1 computed checksum did NOT match ``` Ref https://github.com/neondatabase/neon/actions/runs/6185715461/job/16793609251?pr=5307 It seems that the release was retagged yesterday: https://github.com/ossc-db/pg_hint_plan/releases/tag/REL16_1_6_0 I don't see any malicious changes from 15_1.5.1: https://github.com/ossc-db/pg_hint_plan/compare/REL15_1_5_1...REL16_1_6_0, so it should be ok to update. ## Summary of changes - Update checksum for `pg_hint_plan` 16_1.6.0 --- Dockerfile.compute-node | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/Dockerfile.compute-node b/Dockerfile.compute-node index ecf76f97c2..d724185d5d 100644 --- a/Dockerfile.compute-node +++ b/Dockerfile.compute-node @@ -416,7 +416,7 @@ RUN case "${PG_VERSION}" in \ ;; \ "v16") \ export PG_HINT_PLAN_VERSION=16_1_6_0 \ - export PG_HINT_PLAN_CHECKSUM=ce6a8040c78012000f5da7240caf6a971401412f41d33f930f09291e6c304b99 \ + export PG_HINT_PLAN_CHECKSUM=fc85a9212e7d2819d4ae4ac75817481101833c3cfa9f0fe1f980984e12347d00 \ ;; \ *) \ echo "Export the valid PG_HINT_PLAN_VERSION variable" && exit 1 \ From bd36d1c44a621537583411b15b8b671f62256b2d Mon Sep 17 00:00:00 2001 From: Alexander Bayandin Date: Thu, 14 Sep 2023 18:18:49 +0100 Subject: [PATCH 04/22] approved-for-ci-run.yml: fix variable name and permissions (#5307) ## Problem - `gh pr list` fails with `unknown argument "main"; please quote all values that have spaces due to using a variable with the wrong name - `permissions: write-all` are too wide for the job ## Summary of changes - For variable name `HEAD` -> `BRANCH` - Grant only required permissions for each job --------- Co-authored-by: Joonas Koivunen --- .github/workflows/approved-for-ci-run.yml | 29 ++++++++++++++++++----- 1 file changed, 23 insertions(+), 6 deletions(-) diff --git a/.github/workflows/approved-for-ci-run.yml b/.github/workflows/approved-for-ci-run.yml index 06e172d3e8..5b21011b83 100644 --- a/.github/workflows/approved-for-ci-run.yml +++ b/.github/workflows/approved-for-ci-run.yml @@ -16,21 +16,29 @@ on: # Actual magic happens here: - labeled +concurrency: + group: ${{ github.workflow }}-${{ github.event.pull_request.number }} + env: GH_TOKEN: ${{ secrets.GITHUB_TOKEN }} PR_NUMBER: ${{ github.event.pull_request.number }} BRANCH: "ci-run/pr-${{ github.event.pull_request.number }}" -permissions: write-all +# No permission for GITHUB_TOKEN by default; the **minimal required** set of permissions should be granted in each job. +permissions: {} -concurrency: - group: ${{ github.workflow }}-${{ github.event.pull_request.number }} +defaults: + run: + shell: bash -euo pipefail {0} jobs: remove-label: # Remove `approved-for-ci-run` label if the workflow is triggered by changes in a PR. # The PR should be reviewed and labelled manually again. + permissions: + pull-requests: write # For `gh pr edit` + if: | contains(fromJSON('["opened", "synchronize", "reopened", "closed"]'), github.event.action) && contains(github.event.pull_request.labels.*.name, 'approved-for-ci-run') @@ -43,6 +51,10 @@ jobs: create-or-update-pr-for-ci-run: # Create local PR for an `approved-for-ci-run` labelled PR to run CI pipeline in it. + permissions: + pull-requests: write # for `gh pr edit` + # For `git push` and `gh pr create` we use CI_ACCESS_TOKEN + if: | github.event.action == 'labeled' && contains(github.event.pull_request.labels.*.name, 'approved-for-ci-run') @@ -75,7 +87,7 @@ jobs: Feel free to review/comment/discuss the original PR #${PR_NUMBER}. EOF - ALREADY_CREATED="$(gh pr --repo ${GITHUB_REPOSITORY} list --head ${HEAD} --base main --json number --jq '.[].number')" + ALREADY_CREATED="$(gh pr --repo ${GITHUB_REPOSITORY} list --head ${BRANCH} --base main --json number --jq '.[].number')" if [ -z "${ALREADY_CREATED}" ]; then gh pr --repo "${GITHUB_REPOSITORY}" create --title "CI run for PR #${PR_NUMBER}" \ --body-file "body.md" \ @@ -87,6 +99,10 @@ jobs: cleanup: # Close PRs and delete branchs if the original PR is closed. + permissions: + contents: write # for `--delete-branch` flag in `gh pr close` + pull-requests: write # for `gh pr close` + if: | github.event.action == 'closed' && github.event.pull_request.head.repo.full_name != github.repository @@ -94,8 +110,9 @@ jobs: runs-on: ubuntu-latest steps: - - run: | - CLOSED="$(gh pr --repo ${GITHUB_REPOSITORY} list --head ${HEAD} --json 'closed' --jq '.[].closed')" + - name: Close PR and delete `ci-run/pr-${{ env.PR_NUMBER }}` branch + run: | + CLOSED="$(gh pr --repo ${GITHUB_REPOSITORY} list --head ${BRANCH} --json 'closed' --jq '.[].closed')" if [ "${CLOSED}" == "false" ]; then gh pr --repo "${GITHUB_REPOSITORY}" close "${BRANCH}" --delete-branch fi From e400a38fb9f250b8f90aeb7019bc9c6ad15c4993 Mon Sep 17 00:00:00 2001 From: Konstantin Knizhnik Date: Fri, 15 Sep 2023 10:32:25 +0300 Subject: [PATCH 05/22] References to old and new blocks were mixed in xlog_heap_update handler (#5312) ## Problem See https://neondb.slack.com/archives/C05L7D1JAUS/p1694614585955029 https://www.notion.so/neondatabase/Duplicate-key-issue-651627ce843c45188fbdcb2d30fd2178 ## Summary of changes Swap old/new block references ## Checklist before requesting a review - [ ] I have performed a self-review of my code. - [ ] If it is a core feature, I have added thorough tests. - [ ] Do we need to implement analytics? if so did you add the relevant metrics to the dashboard? - [ ] If this PR requires public announcement, mark it with /release-notes label and add several sentences in this section. ## Checklist before merging - [ ] Do not forget to reformat commit message to not include the above checklist --------- Co-authored-by: Konstantin Knizhnik Co-authored-by: Heikki Linnakangas --- pageserver/src/walingest.rs | 16 +++++----- test_runner/regress/test_vm_bits.py | 48 +++++++++++++++++++++++------ 2 files changed, 47 insertions(+), 17 deletions(-) diff --git a/pageserver/src/walingest.rs b/pageserver/src/walingest.rs index 9192af0ee8..d5ef1f2a24 100644 --- a/pageserver/src/walingest.rs +++ b/pageserver/src/walingest.rs @@ -470,14 +470,14 @@ impl<'a> WalIngest<'a> { // we can't validate the remaining number of bytes without parsing // the tuple data. if (xlrec.flags & pg_constants::XLH_UPDATE_OLD_ALL_VISIBLE_CLEARED) != 0 { - old_heap_blkno = Some(decoded.blocks[0].blkno); + old_heap_blkno = Some(decoded.blocks.last().unwrap().blkno); } if (xlrec.flags & pg_constants::XLH_UPDATE_NEW_ALL_VISIBLE_CLEARED) != 0 { // PostgreSQL only uses XLH_UPDATE_NEW_ALL_VISIBLE_CLEARED on a // non-HOT update where the new tuple goes to different page than // the old one. Otherwise, only XLH_UPDATE_OLD_ALL_VISIBLE_CLEARED is // set. - new_heap_blkno = Some(decoded.blocks[1].blkno); + new_heap_blkno = Some(decoded.blocks[0].blkno); } } } else if decoded.xl_rmid == pg_constants::RM_HEAP2_ID { @@ -526,14 +526,14 @@ impl<'a> WalIngest<'a> { // we can't validate the remaining number of bytes without parsing // the tuple data. if (xlrec.flags & pg_constants::XLH_UPDATE_OLD_ALL_VISIBLE_CLEARED) != 0 { - old_heap_blkno = Some(decoded.blocks[0].blkno); + old_heap_blkno = Some(decoded.blocks.last().unwrap().blkno); } if (xlrec.flags & pg_constants::XLH_UPDATE_NEW_ALL_VISIBLE_CLEARED) != 0 { // PostgreSQL only uses XLH_UPDATE_NEW_ALL_VISIBLE_CLEARED on a // non-HOT update where the new tuple goes to different page than // the old one. Otherwise, only XLH_UPDATE_OLD_ALL_VISIBLE_CLEARED is // set. - new_heap_blkno = Some(decoded.blocks[1].blkno); + new_heap_blkno = Some(decoded.blocks[0].blkno); } } } else if decoded.xl_rmid == pg_constants::RM_HEAP2_ID { @@ -582,14 +582,14 @@ impl<'a> WalIngest<'a> { // we can't validate the remaining number of bytes without parsing // the tuple data. if (xlrec.flags & pg_constants::XLH_UPDATE_OLD_ALL_VISIBLE_CLEARED) != 0 { - old_heap_blkno = Some(decoded.blocks[0].blkno); + old_heap_blkno = Some(decoded.blocks.last().unwrap().blkno); } if (xlrec.flags & pg_constants::XLH_UPDATE_NEW_ALL_VISIBLE_CLEARED) != 0 { // PostgreSQL only uses XLH_UPDATE_NEW_ALL_VISIBLE_CLEARED on a // non-HOT update where the new tuple goes to different page than // the old one. Otherwise, only XLH_UPDATE_OLD_ALL_VISIBLE_CLEARED is // set. - new_heap_blkno = Some(decoded.blocks[1].blkno); + new_heap_blkno = Some(decoded.blocks[0].blkno); } } } else if decoded.xl_rmid == pg_constants::RM_HEAP2_ID { @@ -745,14 +745,14 @@ impl<'a> WalIngest<'a> { // we can't validate the remaining number of bytes without parsing // the tuple data. if (xlrec.flags & pg_constants::XLH_UPDATE_OLD_ALL_VISIBLE_CLEARED) != 0 { - old_heap_blkno = Some(decoded.blocks[0].blkno); + old_heap_blkno = Some(decoded.blocks.last().unwrap().blkno); } if (xlrec.flags & pg_constants::XLH_UPDATE_NEW_ALL_VISIBLE_CLEARED) != 0 { // PostgreSQL only uses XLH_UPDATE_NEW_ALL_VISIBLE_CLEARED on a // non-HOT update where the new tuple goes to different page than // the old one. Otherwise, only XLH_UPDATE_OLD_ALL_VISIBLE_CLEARED is // set. - new_heap_blkno = Some(decoded.blocks[1].blkno); + new_heap_blkno = Some(decoded.blocks[0].blkno); } } pg_constants::XLOG_NEON_HEAP_MULTI_INSERT => { diff --git a/test_runner/regress/test_vm_bits.py b/test_runner/regress/test_vm_bits.py index d8034b31b0..8e20a44407 100644 --- a/test_runner/regress/test_vm_bits.py +++ b/test_runner/regress/test_vm_bits.py @@ -19,18 +19,40 @@ def test_vm_bit_clear(neon_simple_env: NeonEnv): # Install extension containing function needed for test cur.execute("CREATE EXTENSION neon_test_utils") - # Create a test table and freeze it to set the VM bit. + # Create a test table for a few different scenarios and freeze it to set the VM bits. cur.execute("CREATE TABLE vmtest_delete (id integer PRIMARY KEY)") cur.execute("INSERT INTO vmtest_delete VALUES (1)") cur.execute("VACUUM FREEZE vmtest_delete") - cur.execute("CREATE TABLE vmtest_update (id integer PRIMARY KEY)") - cur.execute("INSERT INTO vmtest_update SELECT g FROM generate_series(1, 1000) g") - cur.execute("VACUUM FREEZE vmtest_update") + cur.execute("CREATE TABLE vmtest_hot_update (id integer PRIMARY KEY, filler text)") + cur.execute("INSERT INTO vmtest_hot_update VALUES (1, 'x')") + cur.execute("VACUUM FREEZE vmtest_hot_update") + + cur.execute("CREATE TABLE vmtest_cold_update (id integer PRIMARY KEY)") + cur.execute("INSERT INTO vmtest_cold_update SELECT g FROM generate_series(1, 1000) g") + cur.execute("VACUUM FREEZE vmtest_cold_update") + + cur.execute( + "CREATE TABLE vmtest_cold_update2 (id integer PRIMARY KEY, filler text) WITH (fillfactor=100)" + ) + cur.execute("INSERT INTO vmtest_cold_update2 SELECT g, '' FROM generate_series(1, 1000) g") + cur.execute("VACUUM FREEZE vmtest_cold_update2") # DELETE and UPDATE the rows. cur.execute("DELETE FROM vmtest_delete WHERE id = 1") - cur.execute("UPDATE vmtest_update SET id = 5000 WHERE id = 1") + cur.execute("UPDATE vmtest_hot_update SET filler='x' WHERE id = 1") + cur.execute("UPDATE vmtest_cold_update SET id = 5000 WHERE id = 1") + + # Clear the VM bit on the last page with an INSERT. Then clear the VM bit on + # the page where row 1 is (block 0), by doing an UPDATE. The UPDATE is a + # cold update, and the new tuple goes to the last page, which already had + # its VM bit cleared. The point is that the UPDATE *only* clears the VM bit + # on the page containing the old tuple. We had a bug where we got the old + # and new pages mixed up, and that only shows up when one of the bits is + # cleared, but not the other one. + cur.execute("INSERT INTO vmtest_cold_update2 VALUES (9999, 'x')") + # Clears the VM bit on the old page + cur.execute("UPDATE vmtest_cold_update2 SET id = 5000, filler=repeat('x', 200) WHERE id = 1") # Branch at this point, to test that later fork_at_current_lsn(env, endpoint, "test_vm_bit_clear_new", "test_vm_bit_clear") @@ -50,9 +72,13 @@ def test_vm_bit_clear(neon_simple_env: NeonEnv): """ ) - cur.execute("SELECT * FROM vmtest_delete WHERE id = 1") + cur.execute("SELECT id FROM vmtest_delete WHERE id = 1") assert cur.fetchall() == [] - cur.execute("SELECT * FROM vmtest_update WHERE id = 1") + cur.execute("SELECT id FROM vmtest_hot_update WHERE id = 1") + assert cur.fetchall() == [(1,)] + cur.execute("SELECT id FROM vmtest_cold_update WHERE id = 1") + assert cur.fetchall() == [] + cur.execute("SELECT id FROM vmtest_cold_update2 WHERE id = 1") assert cur.fetchall() == [] cur.close() @@ -77,7 +103,11 @@ def test_vm_bit_clear(neon_simple_env: NeonEnv): """ ) - cur_new.execute("SELECT * FROM vmtest_delete WHERE id = 1") + cur_new.execute("SELECT id FROM vmtest_delete WHERE id = 1") assert cur_new.fetchall() == [] - cur_new.execute("SELECT * FROM vmtest_update WHERE id = 1") + cur_new.execute("SELECT id FROM vmtest_hot_update WHERE id = 1") + assert cur_new.fetchall() == [(1,)] + cur_new.execute("SELECT id FROM vmtest_cold_update WHERE id = 1") + assert cur_new.fetchall() == [] + cur_new.execute("SELECT id FROM vmtest_cold_update2 WHERE id = 1") assert cur_new.fetchall() == [] From e6985bd098621136042522398b12c614b279eb8e Mon Sep 17 00:00:00 2001 From: Rahul Modpur Date: Fri, 15 Sep 2023 15:47:18 +0530 Subject: [PATCH 06/22] Move tenant & timeline dir method to NeonPageserver and use them everywhere (#5262) ## Problem In many places in test code, paths are built manually from what NeonEnv.tenant_dir and NeonEnv.timeline_dir could do. ## Summary of changes 1. NeonEnv.tenant_dir and NeonEnv.timeline_dir moved under class NeonPageserver as the path they use is per-pageserver instance. 2. Used these everywhere to replace manual path building Closes #5258 --------- Signed-off-by: Rahul Modpur --- test_runner/fixtures/neon_fixtures.py | 27 ++++++++------- test_runner/performance/test_bulk_insert.py | 2 +- test_runner/regress/test_broken_timeline.py | 4 +-- .../regress/test_disk_usage_eviction.py | 2 +- test_runner/regress/test_import.py | 2 +- test_runner/regress/test_layer_eviction.py | 6 ++-- .../regress/test_layer_writers_fail.py | 4 +-- test_runner/regress/test_ondemand_download.py | 7 ++-- test_runner/regress/test_remote_storage.py | 13 ++++---- test_runner/regress/test_tenant_conf.py | 2 +- test_runner/regress/test_tenant_delete.py | 8 ++--- test_runner/regress/test_tenant_detach.py | 18 +++++----- test_runner/regress/test_tenant_relocation.py | 6 ++-- test_runner/regress/test_tenants.py | 14 ++------ .../test_tenants_with_remote_storage.py | 6 ++-- test_runner/regress/test_timeline_delete.py | 33 ++++--------------- test_runner/regress/test_timeline_size.py | 4 +-- .../test_walredo_not_left_behind_on_detach.py | 4 +-- 18 files changed, 68 insertions(+), 94 deletions(-) diff --git a/test_runner/fixtures/neon_fixtures.py b/test_runner/fixtures/neon_fixtures.py index c7759d9b44..0667403ba3 100644 --- a/test_runner/fixtures/neon_fixtures.py +++ b/test_runner/fixtures/neon_fixtures.py @@ -847,18 +847,6 @@ class NeonEnv: """Get list of safekeeper endpoints suitable for safekeepers GUC""" return ",".join(f"localhost:{wa.port.pg}" for wa in self.safekeepers) - def timeline_dir( - self, tenant_id: TenantId, timeline_id: TimelineId, pageserver_id: Optional[int] = None - ) -> Path: - """Get a timeline directory's path based on the repo directory of the test environment""" - return ( - self.tenant_dir(tenant_id, pageserver_id=pageserver_id) / "timelines" / str(timeline_id) - ) - - def tenant_dir(self, tenant_id: TenantId, pageserver_id: Optional[int] = None) -> Path: - """Get a tenant directory's path based on the repo directory of the test environment""" - return self.get_pageserver(pageserver_id).workdir / "tenants" / str(tenant_id) - def get_pageserver_version(self) -> str: bin_pageserver = str(self.neon_binpath / "pageserver") res = subprocess.run( @@ -1580,6 +1568,21 @@ class NeonPageserver(PgProtocol): '.*registered custom resource manager "neon".*', ] + def timeline_dir(self, tenant_id: TenantId, timeline_id: Optional[TimelineId] = None) -> Path: + """Get a timeline directory's path based on the repo directory of the test environment""" + if timeline_id is None: + return self.tenant_dir(tenant_id) / "timelines" + return self.tenant_dir(tenant_id) / "timelines" / str(timeline_id) + + def tenant_dir( + self, + tenant_id: Optional[TenantId] = None, + ) -> Path: + """Get a tenant directory's path based on the repo directory of the test environment""" + if tenant_id is None: + return self.workdir / "tenants" + return self.workdir / "tenants" / str(tenant_id) + def start( self, overrides: Tuple[str, ...] = (), diff --git a/test_runner/performance/test_bulk_insert.py b/test_runner/performance/test_bulk_insert.py index 92da2dae96..aafc315576 100644 --- a/test_runner/performance/test_bulk_insert.py +++ b/test_runner/performance/test_bulk_insert.py @@ -44,7 +44,7 @@ def measure_recovery_time(env: NeonCompare): # Stop pageserver and remove tenant data env.env.pageserver.stop() - timeline_dir = env.env.timeline_dir(env.tenant, env.timeline) + timeline_dir = env.env.pageserver.timeline_dir(env.tenant, env.timeline) shutil.rmtree(timeline_dir) # Start pageserver diff --git a/test_runner/regress/test_broken_timeline.py b/test_runner/regress/test_broken_timeline.py index c446f865cb..d0462844f0 100644 --- a/test_runner/regress/test_broken_timeline.py +++ b/test_runner/regress/test_broken_timeline.py @@ -135,7 +135,7 @@ def test_timeline_init_break_before_checkpoint(neon_env_builder: NeonEnvBuilder) tenant_id = env.initial_tenant - timelines_dir = env.pageserver.workdir / "tenants" / str(tenant_id) / "timelines" + timelines_dir = env.pageserver.timeline_dir(tenant_id) old_tenant_timelines = env.neon_cli.list_timelines(tenant_id) initial_timeline_dirs = [d for d in timelines_dir.iterdir()] @@ -166,7 +166,7 @@ def test_timeline_create_break_after_uninit_mark(neon_env_builder: NeonEnvBuilde tenant_id = env.initial_tenant - timelines_dir = env.pageserver.workdir / "tenants" / str(tenant_id) / "timelines" + timelines_dir = env.pageserver.timeline_dir(tenant_id) old_tenant_timelines = env.neon_cli.list_timelines(tenant_id) initial_timeline_dirs = [d for d in timelines_dir.iterdir()] diff --git a/test_runner/regress/test_disk_usage_eviction.py b/test_runner/regress/test_disk_usage_eviction.py index 32eb910188..ae62fdf4a4 100644 --- a/test_runner/regress/test_disk_usage_eviction.py +++ b/test_runner/regress/test_disk_usage_eviction.py @@ -417,7 +417,7 @@ def poor_mans_du( largest_layer = 0 smallest_layer = None for tenant_id, timeline_id in timelines: - timeline_dir = env.timeline_dir(tenant_id, timeline_id) + timeline_dir = env.pageserver.timeline_dir(tenant_id, timeline_id) assert timeline_dir.exists(), f"timeline dir does not exist: {timeline_dir}" total = 0 for file in timeline_dir.iterdir(): diff --git a/test_runner/regress/test_import.py b/test_runner/regress/test_import.py index 1722d6bfe7..d357bd0ee4 100644 --- a/test_runner/regress/test_import.py +++ b/test_runner/regress/test_import.py @@ -271,7 +271,7 @@ def _import( env.endpoints.stop_all() env.pageserver.stop() - dir_to_clear = Path(env.pageserver.workdir) / "tenants" + dir_to_clear = env.pageserver.tenant_dir() shutil.rmtree(dir_to_clear) os.mkdir(dir_to_clear) diff --git a/test_runner/regress/test_layer_eviction.py b/test_runner/regress/test_layer_eviction.py index 5bb953ffb0..3e23a8e165 100644 --- a/test_runner/regress/test_layer_eviction.py +++ b/test_runner/regress/test_layer_eviction.py @@ -55,7 +55,7 @@ def test_basic_eviction( for sk in env.safekeepers: sk.stop() - timeline_path = env.timeline_dir(tenant_id, timeline_id) + timeline_path = env.pageserver.timeline_dir(tenant_id, timeline_id) initial_local_layers = sorted( list(filter(lambda path: path.name != "metadata", timeline_path.glob("*"))) ) @@ -243,7 +243,7 @@ def test_gc_of_remote_layers(neon_env_builder: NeonEnvBuilder): assert by_kind["Image"] > 0 assert by_kind["Delta"] > 0 assert by_kind["InMemory"] == 0 - resident_layers = list(env.timeline_dir(tenant_id, timeline_id).glob("*-*_*")) + resident_layers = list(env.pageserver.timeline_dir(tenant_id, timeline_id).glob("*-*_*")) log.info("resident layers count before eviction: %s", len(resident_layers)) log.info("evict all layers") @@ -251,7 +251,7 @@ def test_gc_of_remote_layers(neon_env_builder: NeonEnvBuilder): def ensure_resident_and_remote_size_metrics(): log.info("ensure that all the layers are gone") - resident_layers = list(env.timeline_dir(tenant_id, timeline_id).glob("*-*_*")) + resident_layers = list(env.pageserver.timeline_dir(tenant_id, timeline_id).glob("*-*_*")) # we have disabled all background loops, so, this should hold assert len(resident_layers) == 0 diff --git a/test_runner/regress/test_layer_writers_fail.py b/test_runner/regress/test_layer_writers_fail.py index 5ffc12b5b3..7298635abe 100644 --- a/test_runner/regress/test_layer_writers_fail.py +++ b/test_runner/regress/test_layer_writers_fail.py @@ -38,7 +38,7 @@ def test_image_layer_writer_fail_before_finish(neon_simple_env: NeonEnv): new_temp_layer_files = list( filter( lambda file: str(file).endswith(NeonPageserver.TEMP_FILE_SUFFIX), - [path for path in env.timeline_dir(tenant_id, timeline_id).iterdir()], + [path for path in env.pageserver.timeline_dir(tenant_id, timeline_id).iterdir()], ) ) @@ -84,7 +84,7 @@ def test_delta_layer_writer_fail_before_finish(neon_simple_env: NeonEnv): new_temp_layer_files = list( filter( lambda file: str(file).endswith(NeonPageserver.TEMP_FILE_SUFFIX), - [path for path in env.timeline_dir(tenant_id, timeline_id).iterdir()], + [path for path in env.pageserver.timeline_dir(tenant_id, timeline_id).iterdir()], ) ) diff --git a/test_runner/regress/test_ondemand_download.py b/test_runner/regress/test_ondemand_download.py index 49439c5fab..4041b8aab7 100644 --- a/test_runner/regress/test_ondemand_download.py +++ b/test_runner/regress/test_ondemand_download.py @@ -3,7 +3,6 @@ import time from collections import defaultdict -from pathlib import Path from typing import Any, DefaultDict, Dict, Tuple import pytest @@ -115,7 +114,7 @@ def test_ondemand_download_large_rel( env.pageserver.stop() # remove all the layer files - for layer in (Path(env.pageserver.workdir) / "tenants").glob("*/timelines/*/*-*_*"): + for layer in env.pageserver.tenant_dir().glob("*/timelines/*/*-*_*"): log.info(f"unlinking layer {layer}") layer.unlink() @@ -237,7 +236,7 @@ def test_ondemand_download_timetravel( env.pageserver.stop() # remove all the layer files - for layer in (Path(env.pageserver.workdir) / "tenants").glob("*/timelines/*/*-*_*"): + for layer in env.pageserver.tenant_dir().glob("*/timelines/*/*-*_*"): log.info(f"unlinking layer {layer}") layer.unlink() @@ -368,7 +367,7 @@ def test_download_remote_layers_api( # remove all the layer files # XXX only delete some of the layer files, to show that it really just downloads all the layers - for layer in (Path(env.pageserver.workdir) / "tenants").glob("*/timelines/*/*-*_*"): + for layer in env.pageserver.tenant_dir().glob("*/timelines/*/*-*_*"): log.info(f"unlinking layer {layer.name}") layer.unlink() diff --git a/test_runner/regress/test_remote_storage.py b/test_runner/regress/test_remote_storage.py index d0bb52336d..f316b42d1c 100644 --- a/test_runner/regress/test_remote_storage.py +++ b/test_runner/regress/test_remote_storage.py @@ -6,7 +6,6 @@ import queue import shutil import threading import time -from pathlib import Path from typing import Dict, List, Optional, Tuple import pytest @@ -137,7 +136,7 @@ def test_remote_storage_backup_and_restore( env.endpoints.stop_all() env.pageserver.stop() - dir_to_clear = Path(env.pageserver.workdir) / "tenants" + dir_to_clear = env.pageserver.tenant_dir() shutil.rmtree(dir_to_clear) os.mkdir(dir_to_clear) @@ -353,7 +352,7 @@ def test_remote_storage_upload_queue_retries( env.pageserver.stop(immediate=True) env.endpoints.stop_all() - dir_to_clear = Path(env.pageserver.workdir) / "tenants" + dir_to_clear = env.pageserver.tenant_dir() shutil.rmtree(dir_to_clear) os.mkdir(dir_to_clear) @@ -488,7 +487,7 @@ def test_remote_timeline_client_calls_started_metric( env.pageserver.stop(immediate=True) env.endpoints.stop_all() - dir_to_clear = Path(env.pageserver.workdir) / "tenants" + dir_to_clear = env.pageserver.tenant_dir() shutil.rmtree(dir_to_clear) os.mkdir(dir_to_clear) @@ -533,7 +532,7 @@ def test_timeline_deletion_with_files_stuck_in_upload_queue( tenant_id = env.initial_tenant timeline_id = env.initial_timeline - timeline_path = env.timeline_dir(tenant_id, timeline_id) + timeline_path = env.pageserver.timeline_dir(tenant_id, timeline_id) client = env.pageserver.http_client() @@ -704,7 +703,9 @@ def test_empty_branch_remote_storage_upload_on_restart( # index upload is now hitting the failpoint, it should block the shutdown env.pageserver.stop(immediate=True) - local_metadata = env.timeline_dir(env.initial_tenant, new_branch_timeline_id) / "metadata" + local_metadata = ( + env.pageserver.timeline_dir(env.initial_tenant, new_branch_timeline_id) / "metadata" + ) assert local_metadata.is_file() assert isinstance(env.pageserver_remote_storage, LocalFsStorage) diff --git a/test_runner/regress/test_tenant_conf.py b/test_runner/regress/test_tenant_conf.py index d8a9e0390a..2fdcfca671 100644 --- a/test_runner/regress/test_tenant_conf.py +++ b/test_runner/regress/test_tenant_conf.py @@ -299,7 +299,7 @@ def test_creating_tenant_conf_after_attach(neon_env_builder: NeonEnvBuilder): # tenant is created with defaults, as in without config file (tenant_id, timeline_id) = env.neon_cli.create_tenant() - config_path = env.pageserver.workdir / "tenants" / str(tenant_id) / "config" + config_path = env.pageserver.tenant_dir(tenant_id) / "config" assert config_path.exists(), "config file is always initially created" http_client = env.pageserver.http_client() diff --git a/test_runner/regress/test_tenant_delete.py b/test_runner/regress/test_tenant_delete.py index e60b996a16..c6ddb54ee6 100644 --- a/test_runner/regress/test_tenant_delete.py +++ b/test_runner/regress/test_tenant_delete.py @@ -89,7 +89,7 @@ def test_tenant_delete_smoke( tenant_delete_wait_completed(ps_http, tenant_id, iterations) - tenant_path = env.tenant_dir(tenant_id=tenant_id) + tenant_path = env.pageserver.tenant_dir(tenant_id) assert not tenant_path.exists() if remote_storage_kind in available_s3_storages(): @@ -269,7 +269,7 @@ def test_delete_tenant_exercise_crash_safety_failpoints( tenant_delete_wait_completed(ps_http, tenant_id, iterations=iterations) - tenant_dir = env.tenant_dir(tenant_id) + tenant_dir = env.pageserver.tenant_dir(tenant_id) # Check local is empty assert not tenant_dir.exists() @@ -366,7 +366,7 @@ def test_tenant_delete_is_resumed_on_attach( env.endpoints.stop_all() env.pageserver.stop() - dir_to_clear = env.pageserver.workdir / "tenants" + dir_to_clear = env.pageserver.tenant_dir() shutil.rmtree(dir_to_clear) os.mkdir(dir_to_clear) @@ -379,7 +379,7 @@ def test_tenant_delete_is_resumed_on_attach( wait_tenant_status_404(ps_http, tenant_id, iterations) # we shouldn've created tenant dir on disk - tenant_path = env.tenant_dir(tenant_id=tenant_id) + tenant_path = env.pageserver.tenant_dir(tenant_id) assert not tenant_path.exists() if remote_storage_kind in available_s3_storages(): diff --git a/test_runner/regress/test_tenant_detach.py b/test_runner/regress/test_tenant_detach.py index b34b2f95b5..8ccbcf551d 100644 --- a/test_runner/regress/test_tenant_detach.py +++ b/test_runner/regress/test_tenant_detach.py @@ -286,7 +286,7 @@ def test_tenant_detach_smoke(neon_env_builder: NeonEnvBuilder): ) # assert tenant exists on disk - assert (env.pageserver.workdir / "tenants" / str(tenant_id)).exists() + assert env.pageserver.tenant_dir(tenant_id).exists() endpoint = env.endpoints.create_start("main", tenant_id=tenant_id) # we rely upon autocommit after each statement @@ -329,7 +329,7 @@ def test_tenant_detach_smoke(neon_env_builder: NeonEnvBuilder): log.info("gc thread returned") # check that nothing is left on disk for deleted tenant - assert not (env.pageserver.workdir / "tenants" / str(tenant_id)).exists() + assert not env.pageserver.tenant_dir(tenant_id).exists() with pytest.raises( expected_exception=PageserverApiException, match=f"NotFound: tenant {tenant_id}" @@ -354,7 +354,7 @@ def test_tenant_detach_ignored_tenant(neon_simple_env: NeonEnv): ) # assert tenant exists on disk - assert (env.pageserver.workdir / "tenants" / str(tenant_id)).exists() + assert env.pageserver.tenant_dir(tenant_id).exists() endpoint = env.endpoints.create_start("main", tenant_id=tenant_id) # we rely upon autocommit after each statement @@ -383,7 +383,7 @@ def test_tenant_detach_ignored_tenant(neon_simple_env: NeonEnv): log.info("ignored tenant detached without error") # check that nothing is left on disk for deleted tenant - assert not (env.pageserver.workdir / "tenants" / str(tenant_id)).exists() + assert not env.pageserver.tenant_dir(tenant_id).exists() # assert the tenant does not exists in the Pageserver tenants_after_detach = [tenant["id"] for tenant in client.tenant_list()] @@ -410,7 +410,7 @@ def test_tenant_detach_regular_tenant(neon_simple_env: NeonEnv): ) # assert tenant exists on disk - assert (env.pageserver.workdir / "tenants" / str(tenant_id)).exists() + assert env.pageserver.tenant_dir(tenant_id).exists() endpoint = env.endpoints.create_start("main", tenant_id=tenant_id) # we rely upon autocommit after each statement @@ -427,7 +427,7 @@ def test_tenant_detach_regular_tenant(neon_simple_env: NeonEnv): log.info("regular tenant detached without error") # check that nothing is left on disk for deleted tenant - assert not (env.pageserver.workdir / "tenants" / str(tenant_id)).exists() + assert not env.pageserver.tenant_dir(tenant_id).exists() # assert the tenant does not exists in the Pageserver tenants_after_detach = [tenant["id"] for tenant in client.tenant_list()] @@ -528,7 +528,7 @@ def test_ignored_tenant_reattach( pageserver_http = env.pageserver.http_client() ignored_tenant_id, _ = env.neon_cli.create_tenant() - tenant_dir = env.pageserver.workdir / "tenants" / str(ignored_tenant_id) + tenant_dir = env.pageserver.tenant_dir(ignored_tenant_id) tenants_before_ignore = [tenant["id"] for tenant in pageserver_http.tenant_list()] tenants_before_ignore.sort() timelines_before_ignore = [ @@ -619,7 +619,7 @@ def test_ignored_tenant_download_missing_layers( # ignore the tenant and remove its layers pageserver_http.tenant_ignore(tenant_id) - timeline_dir = env.timeline_dir(tenant_id, timeline_id) + timeline_dir = env.pageserver.timeline_dir(tenant_id, timeline_id) layers_removed = False for dir_entry in timeline_dir.iterdir(): if dir_entry.name.startswith("00000"): @@ -672,7 +672,7 @@ def test_ignored_tenant_stays_broken_without_metadata( # ignore the tenant and remove its metadata pageserver_http.tenant_ignore(tenant_id) - timeline_dir = env.timeline_dir(tenant_id, timeline_id) + timeline_dir = env.pageserver.timeline_dir(tenant_id, timeline_id) metadata_removed = False for dir_entry in timeline_dir.iterdir(): if dir_entry.name == "metadata": diff --git a/test_runner/regress/test_tenant_relocation.py b/test_runner/regress/test_tenant_relocation.py index a2b922bb84..8be0f0449b 100644 --- a/test_runner/regress/test_tenant_relocation.py +++ b/test_runner/regress/test_tenant_relocation.py @@ -216,7 +216,7 @@ def switch_pg_to_new_pageserver( endpoint.start() - timeline_to_detach_local_path = env.timeline_dir(tenant_id, timeline_id) + timeline_to_detach_local_path = env.pageserver.timeline_dir(tenant_id, timeline_id) files_before_detach = os.listdir(timeline_to_detach_local_path) assert ( "metadata" in files_before_detach @@ -561,7 +561,7 @@ def test_emergency_relocate_with_branches_slow_replay( # simpler than initializing a new one from scratch, but the effect on the single tenant # is the same. env.pageserver.stop(immediate=True) - shutil.rmtree(env.pageserver.workdir / "tenants" / str(tenant_id)) + shutil.rmtree(env.pageserver.tenant_dir(tenant_id)) env.pageserver.start() # This fail point will pause the WAL ingestion on the main branch, after the @@ -709,7 +709,7 @@ def test_emergency_relocate_with_branches_createdb( # Kill the pageserver, remove the tenant directory, and restart env.pageserver.stop(immediate=True) - shutil.rmtree(env.pageserver.workdir / "tenants" / str(tenant_id)) + shutil.rmtree(env.pageserver.tenant_dir(tenant_id)) env.pageserver.start() # Wait before ingesting the WAL for CREATE DATABASE on the main branch. The original diff --git a/test_runner/regress/test_tenants.py b/test_runner/regress/test_tenants.py index 28f0e658a1..677c0d18e8 100644 --- a/test_runner/regress/test_tenants.py +++ b/test_runner/regress/test_tenants.py @@ -27,7 +27,7 @@ from prometheus_client.samples import Sample def test_tenant_creation_fails(neon_simple_env: NeonEnv): - tenants_dir = Path(neon_simple_env.pageserver.workdir) / "tenants" + tenants_dir = neon_simple_env.pageserver.tenant_dir() initial_tenants = sorted( map(lambda t: t.split()[0], neon_simple_env.neon_cli.list_tenants().stdout.splitlines()) ) @@ -320,13 +320,7 @@ def test_pageserver_with_empty_tenants( ) files_in_timelines_dir = sum( - 1 - for _p in Path.iterdir( - Path(env.pageserver.workdir) - / "tenants" - / str(tenant_with_empty_timelines) - / "timelines" - ) + 1 for _p in Path.iterdir(env.pageserver.timeline_dir(tenant_with_empty_timelines)) ) assert ( files_in_timelines_dir == 0 @@ -337,9 +331,7 @@ def test_pageserver_with_empty_tenants( env.pageserver.stop() tenant_without_timelines_dir = env.initial_tenant - shutil.rmtree( - Path(env.pageserver.workdir) / "tenants" / str(tenant_without_timelines_dir) / "timelines" - ) + shutil.rmtree(env.pageserver.timeline_dir(tenant_without_timelines_dir)) env.pageserver.start() diff --git a/test_runner/regress/test_tenants_with_remote_storage.py b/test_runner/regress/test_tenants_with_remote_storage.py index 4aec4c6113..d42e566c36 100644 --- a/test_runner/regress/test_tenants_with_remote_storage.py +++ b/test_runner/regress/test_tenants_with_remote_storage.py @@ -179,9 +179,7 @@ def test_tenants_attached_after_download( env.pageserver.stop() - timeline_dir = ( - Path(env.pageserver.workdir) / "tenants" / str(tenant_id) / "timelines" / str(timeline_id) - ) + timeline_dir = env.pageserver.timeline_dir(tenant_id, timeline_id) local_layer_deleted = False for path in Path.iterdir(timeline_dir): if path.name.startswith("00000"): @@ -259,7 +257,7 @@ def test_tenant_redownloads_truncated_file_on_startup( env.endpoints.stop_all() env.pageserver.stop() - timeline_dir = env.timeline_dir(tenant_id, timeline_id) + timeline_dir = env.pageserver.timeline_dir(tenant_id, timeline_id) local_layer_truncated = None for path in Path.iterdir(timeline_dir): if path.name.startswith("00000"): diff --git a/test_runner/regress/test_timeline_delete.py b/test_runner/regress/test_timeline_delete.py index 0b79383442..0e4df21d83 100644 --- a/test_runner/regress/test_timeline_delete.py +++ b/test_runner/regress/test_timeline_delete.py @@ -3,7 +3,6 @@ import os import queue import shutil import threading -from pathlib import Path import pytest import requests @@ -72,13 +71,7 @@ def test_timeline_delete(neon_simple_env: NeonEnv): "test_ancestor_branch_delete_branch1", "test_ancestor_branch_delete_parent" ) - timeline_path = ( - env.pageserver.workdir - / "tenants" - / str(env.initial_tenant) - / "timelines" - / str(parent_timeline_id) - ) + timeline_path = env.pageserver.timeline_dir(env.initial_tenant, parent_timeline_id) with pytest.raises( PageserverApiException, match="Cannot delete timeline which has child timelines" @@ -89,13 +82,7 @@ def test_timeline_delete(neon_simple_env: NeonEnv): assert exc.value.status_code == 412 - timeline_path = ( - env.pageserver.workdir - / "tenants" - / str(env.initial_tenant) - / "timelines" - / str(leaf_timeline_id) - ) + timeline_path = env.pageserver.timeline_dir(env.initial_tenant, leaf_timeline_id) assert timeline_path.exists() # retry deletes when compaction or gc is running in pageserver @@ -336,7 +323,7 @@ def test_delete_timeline_exercise_crash_safety_failpoints( ), ) - timeline_dir = env.timeline_dir(env.initial_tenant, timeline_id) + timeline_dir = env.pageserver.timeline_dir(env.initial_tenant, timeline_id) # Check local is empty assert not timeline_dir.exists() # Check no delete mark present @@ -416,7 +403,7 @@ def test_timeline_resurrection_on_attach( env.endpoints.stop_all() env.pageserver.stop() - dir_to_clear = Path(env.pageserver.workdir) / "tenants" + dir_to_clear = env.pageserver.tenant_dir() shutil.rmtree(dir_to_clear) os.mkdir(dir_to_clear) @@ -467,13 +454,7 @@ def test_timeline_delete_fail_before_local_delete(neon_env_builder: NeonEnvBuild "test_timeline_delete_fail_before_local_delete", ) - leaf_timeline_path = ( - env.pageserver.workdir - / "tenants" - / str(env.initial_tenant) - / "timelines" - / str(leaf_timeline_id) - ) + leaf_timeline_path = env.pageserver.timeline_dir(env.initial_tenant, leaf_timeline_id) ps_http.timeline_delete(env.initial_tenant, leaf_timeline_id) timeline_info = wait_until_timeline_state( @@ -921,7 +902,7 @@ def test_timeline_delete_resumed_on_attach( env.endpoints.stop_all() env.pageserver.stop() - dir_to_clear = Path(env.pageserver.workdir) / "tenants" + dir_to_clear = env.pageserver.tenant_dir() shutil.rmtree(dir_to_clear) os.mkdir(dir_to_clear) @@ -933,7 +914,7 @@ def test_timeline_delete_resumed_on_attach( # delete should be resumed wait_timeline_detail_404(ps_http, env.initial_tenant, timeline_id, iterations=iterations) - tenant_path = env.timeline_dir(tenant_id=tenant_id, timeline_id=timeline_id) + tenant_path = env.pageserver.timeline_dir(tenant_id, timeline_id) assert not tenant_path.exists() if remote_storage_kind in available_s3_storages(): diff --git a/test_runner/regress/test_timeline_size.py b/test_runner/regress/test_timeline_size.py index 3f379a173c..f856b26c6e 100644 --- a/test_runner/regress/test_timeline_size.py +++ b/test_runner/regress/test_timeline_size.py @@ -518,7 +518,7 @@ def test_timeline_size_metrics( ).value # assert that the physical size metric matches the actual physical size on disk - timeline_path = env.timeline_dir(env.initial_tenant, new_timeline_id) + timeline_path = env.pageserver.timeline_dir(env.initial_tenant, new_timeline_id) assert tl_physical_size_metric == get_timeline_dir_size(timeline_path) # Check that the logical size metric is sane, and matches @@ -658,7 +658,7 @@ def get_physical_size_values( ) res.api_current_physical = detail["current_physical_size"] - timeline_path = env.timeline_dir(tenant_id, timeline_id) + timeline_path = env.pageserver.timeline_dir(tenant_id, timeline_id) res.python_timelinedir_layerfiles_physical = get_timeline_dir_size(timeline_path) return res diff --git a/test_runner/regress/test_walredo_not_left_behind_on_detach.py b/test_runner/regress/test_walredo_not_left_behind_on_detach.py index 155242ed15..13159efbe8 100644 --- a/test_runner/regress/test_walredo_not_left_behind_on_detach.py +++ b/test_runner/regress/test_walredo_not_left_behind_on_detach.py @@ -43,7 +43,7 @@ def test_walredo_not_left_behind_on_detach(neon_env_builder: NeonEnvBuilder): tenant_id, _ = env.neon_cli.create_tenant() # assert tenant exists on disk - assert (env.pageserver.workdir / "tenants" / str(tenant_id)).exists() + assert (env.pageserver.tenant_dir(tenant_id)).exists() endpoint = env.endpoints.create_start("main", tenant_id=tenant_id) @@ -101,7 +101,7 @@ def test_walredo_not_left_behind_on_detach(neon_env_builder: NeonEnvBuilder): pytest.fail(f"could not detach tenant: {last_error}") # check that nothing is left on disk for deleted tenant - assert not (env.pageserver.workdir / "tenants" / str(tenant_id)).exists() + assert not env.pageserver.tenant_dir(tenant_id).exists() # Pageserver schedules kill+wait of the WAL redo process to the background runtime, # asynchronously to tenant detach. Cut it some slack to complete kill+wait before From 9e6b5b686ced66ae28deb732f3c72db52298a608 Mon Sep 17 00:00:00 2001 From: Heikki Linnakangas Date: Fri, 15 Sep 2023 16:50:57 +0300 Subject: [PATCH 07/22] Add a test case for "CREATE DATABASE STRATEGY=file_copy". (#5301) It was utterly broken on v15 before commit 83e7e5dbbd, which fixed the incorrect definition of XLOG_DBASE_CREATE_WAL_LOG. We never noticed because we had no tests for it. --- test_runner/regress/test_createdropdb.py | 13 +++++++++++-- 1 file changed, 11 insertions(+), 2 deletions(-) diff --git a/test_runner/regress/test_createdropdb.py b/test_runner/regress/test_createdropdb.py index 68035b1b14..500d19cf31 100644 --- a/test_runner/regress/test_createdropdb.py +++ b/test_runner/regress/test_createdropdb.py @@ -1,16 +1,22 @@ import os import pathlib +import pytest from fixtures.log_helper import log from fixtures.neon_fixtures import NeonEnv, check_restored_datadir_content +from fixtures.pg_version import PgVersion from fixtures.utils import query_scalar # # Test CREATE DATABASE when there have been relmapper changes # -def test_createdb(neon_simple_env: NeonEnv): +@pytest.mark.parametrize("strategy", ["file_copy", "wal_log"]) +def test_createdb(neon_simple_env: NeonEnv, strategy: str): env = neon_simple_env + if env.pg_version == PgVersion.V14 and strategy == "wal_log": + pytest.skip("wal_log strategy not supported on PostgreSQL 14") + env.neon_cli.create_branch("test_createdb", "empty") endpoint = env.endpoints.create_start("test_createdb") @@ -20,7 +26,10 @@ def test_createdb(neon_simple_env: NeonEnv): # Cause a 'relmapper' change in the original branch cur.execute("VACUUM FULL pg_class") - cur.execute("CREATE DATABASE foodb") + if env.pg_version == PgVersion.V14: + cur.execute("CREATE DATABASE foodb") + else: + cur.execute(f"CREATE DATABASE foodb STRATEGY={strategy}") lsn = query_scalar(cur, "SELECT pg_current_wal_insert_lsn()") From 66fa176cc8ff78cfc1464d1affababaa604edecf Mon Sep 17 00:00:00 2001 From: Konstantin Knizhnik Date: Fri, 15 Sep 2023 17:47:29 +0300 Subject: [PATCH 08/22] Handle update of VM in XLOG_HEAP_LOCK/XLOG_HEAP2_LOCK_UPDATED WAL records (#4896) ## Problem VM should be updated if XLH_LOCK_ALL_FROZEN_CLEARED flags is set in XLOG_HEAP_LOCK,XLOG_HEAP_2_LOCK_UPDATED WAL records ## Summary of changes Add handling of this records in walingest.rs ## Checklist before requesting a review - [ ] I have performed a self-review of my code. - [ ] If it is a core feature, I have added thorough tests. - [ ] Do we need to implement analytics? if so did you add the relevant metrics to the dashboard? - [ ] If this PR requires public announcement, mark it with /release-notes label and add several sentences in this section. ## Checklist before merging - [ ] Do not forget to reformat commit message to not include the above checklist --------- Co-authored-by: Konstantin Knizhnik --- libs/postgres_ffi/src/pg_constants.rs | 3 + pageserver/src/walingest.rs | 60 +++++++++++++--- pageserver/src/walrecord.rs | 94 +++++++++++++++++++++++- test_runner/regress/test_vm_bits.py | 100 ++++++++++++++++++++++++++ 4 files changed, 244 insertions(+), 13 deletions(-) diff --git a/libs/postgres_ffi/src/pg_constants.rs b/libs/postgres_ffi/src/pg_constants.rs index 1d196c3fe7..9690dc0eb6 100644 --- a/libs/postgres_ffi/src/pg_constants.rs +++ b/libs/postgres_ffi/src/pg_constants.rs @@ -137,9 +137,12 @@ pub const XLOG_HEAP_INSERT: u8 = 0x00; pub const XLOG_HEAP_DELETE: u8 = 0x10; pub const XLOG_HEAP_UPDATE: u8 = 0x20; pub const XLOG_HEAP_HOT_UPDATE: u8 = 0x40; +pub const XLOG_HEAP_LOCK: u8 = 0x60; pub const XLOG_HEAP_INIT_PAGE: u8 = 0x80; pub const XLOG_HEAP2_VISIBLE: u8 = 0x40; pub const XLOG_HEAP2_MULTI_INSERT: u8 = 0x50; +pub const XLOG_HEAP2_LOCK_UPDATED: u8 = 0x60; +pub const XLH_LOCK_ALL_FROZEN_CLEARED: u8 = 0x01; pub const XLH_INSERT_ALL_FROZEN_SET: u8 = (1 << 5) as u8; pub const XLH_INSERT_ALL_VISIBLE_CLEARED: u8 = (1 << 0) as u8; pub const XLH_UPDATE_OLD_ALL_VISIBLE_CLEARED: u8 = (1 << 0) as u8; diff --git a/pageserver/src/walingest.rs b/pageserver/src/walingest.rs index d5ef1f2a24..e293fcc81b 100644 --- a/pageserver/src/walingest.rs +++ b/pageserver/src/walingest.rs @@ -444,6 +444,7 @@ impl<'a> WalIngest<'a> { // need to clear the corresponding bits in the visibility map. let mut new_heap_blkno: Option = None; let mut old_heap_blkno: Option = None; + let mut flags = pg_constants::VISIBILITYMAP_VALID_BITS; match self.timeline.pg_version { 14 => { @@ -479,6 +480,12 @@ impl<'a> WalIngest<'a> { // set. new_heap_blkno = Some(decoded.blocks[0].blkno); } + } else if info == pg_constants::XLOG_HEAP_LOCK { + let xlrec = v14::XlHeapLock::decode(buf); + if (xlrec.flags & pg_constants::XLH_LOCK_ALL_FROZEN_CLEARED) != 0 { + old_heap_blkno = Some(decoded.blocks[0].blkno); + flags = pg_constants::VISIBILITYMAP_ALL_FROZEN; + } } } else if decoded.xl_rmid == pg_constants::RM_HEAP2_ID { let info = decoded.xl_info & pg_constants::XLOG_HEAP_OPMASK; @@ -497,6 +504,12 @@ impl<'a> WalIngest<'a> { if (xlrec.flags & pg_constants::XLH_INSERT_ALL_VISIBLE_CLEARED) != 0 { new_heap_blkno = Some(decoded.blocks[0].blkno); } + } else if info == pg_constants::XLOG_HEAP2_LOCK_UPDATED { + let xlrec = v14::XlHeapLockUpdated::decode(buf); + if (xlrec.flags & pg_constants::XLH_LOCK_ALL_FROZEN_CLEARED) != 0 { + old_heap_blkno = Some(decoded.blocks[0].blkno); + flags = pg_constants::VISIBILITYMAP_ALL_FROZEN; + } } } else { bail!("Unknown RMGR {} for Heap decoding", decoded.xl_rmid); @@ -535,6 +548,12 @@ impl<'a> WalIngest<'a> { // set. new_heap_blkno = Some(decoded.blocks[0].blkno); } + } else if info == pg_constants::XLOG_HEAP_LOCK { + let xlrec = v15::XlHeapLock::decode(buf); + if (xlrec.flags & pg_constants::XLH_LOCK_ALL_FROZEN_CLEARED) != 0 { + old_heap_blkno = Some(decoded.blocks[0].blkno); + flags = pg_constants::VISIBILITYMAP_ALL_FROZEN; + } } } else if decoded.xl_rmid == pg_constants::RM_HEAP2_ID { let info = decoded.xl_info & pg_constants::XLOG_HEAP_OPMASK; @@ -553,6 +572,12 @@ impl<'a> WalIngest<'a> { if (xlrec.flags & pg_constants::XLH_INSERT_ALL_VISIBLE_CLEARED) != 0 { new_heap_blkno = Some(decoded.blocks[0].blkno); } + } else if info == pg_constants::XLOG_HEAP2_LOCK_UPDATED { + let xlrec = v15::XlHeapLockUpdated::decode(buf); + if (xlrec.flags & pg_constants::XLH_LOCK_ALL_FROZEN_CLEARED) != 0 { + old_heap_blkno = Some(decoded.blocks[0].blkno); + flags = pg_constants::VISIBILITYMAP_ALL_FROZEN; + } } } else { bail!("Unknown RMGR {} for Heap decoding", decoded.xl_rmid); @@ -591,6 +616,12 @@ impl<'a> WalIngest<'a> { // set. new_heap_blkno = Some(decoded.blocks[0].blkno); } + } else if info == pg_constants::XLOG_HEAP_LOCK { + let xlrec = v16::XlHeapLock::decode(buf); + if (xlrec.flags & pg_constants::XLH_LOCK_ALL_FROZEN_CLEARED) != 0 { + old_heap_blkno = Some(decoded.blocks[0].blkno); + flags = pg_constants::VISIBILITYMAP_ALL_FROZEN; + } } } else if decoded.xl_rmid == pg_constants::RM_HEAP2_ID { let info = decoded.xl_info & pg_constants::XLOG_HEAP_OPMASK; @@ -609,6 +640,12 @@ impl<'a> WalIngest<'a> { if (xlrec.flags & pg_constants::XLH_INSERT_ALL_VISIBLE_CLEARED) != 0 { new_heap_blkno = Some(decoded.blocks[0].blkno); } + } else if info == pg_constants::XLOG_HEAP2_LOCK_UPDATED { + let xlrec = v16::XlHeapLockUpdated::decode(buf); + if (xlrec.flags & pg_constants::XLH_LOCK_ALL_FROZEN_CLEARED) != 0 { + old_heap_blkno = Some(decoded.blocks[0].blkno); + flags = pg_constants::VISIBILITYMAP_ALL_FROZEN; + } } } else { bail!("Unknown RMGR {} for Heap decoding", decoded.xl_rmid); @@ -616,7 +653,6 @@ impl<'a> WalIngest<'a> { } _ => {} } - // FIXME: What about XLOG_HEAP_LOCK and XLOG_HEAP2_LOCK_UPDATED? // Clear the VM bits if required. if new_heap_blkno.is_some() || old_heap_blkno.is_some() { @@ -660,7 +696,7 @@ impl<'a> WalIngest<'a> { NeonWalRecord::ClearVisibilityMapFlags { new_heap_blkno, old_heap_blkno, - flags: pg_constants::VISIBILITYMAP_VALID_BITS, + flags, }, ctx, ) @@ -676,7 +712,7 @@ impl<'a> WalIngest<'a> { NeonWalRecord::ClearVisibilityMapFlags { new_heap_blkno, old_heap_blkno: None, - flags: pg_constants::VISIBILITYMAP_VALID_BITS, + flags, }, ctx, ) @@ -690,7 +726,7 @@ impl<'a> WalIngest<'a> { NeonWalRecord::ClearVisibilityMapFlags { new_heap_blkno: None, old_heap_blkno, - flags: pg_constants::VISIBILITYMAP_VALID_BITS, + flags, }, ctx, ) @@ -717,6 +753,8 @@ impl<'a> WalIngest<'a> { // need to clear the corresponding bits in the visibility map. let mut new_heap_blkno: Option = None; let mut old_heap_blkno: Option = None; + let mut flags = pg_constants::VISIBILITYMAP_VALID_BITS; + assert_eq!(decoded.xl_rmid, pg_constants::RM_NEON_ID); match self.timeline.pg_version { @@ -772,7 +810,11 @@ impl<'a> WalIngest<'a> { } } pg_constants::XLOG_NEON_HEAP_LOCK => { - /* XLOG_NEON_HEAP_LOCK doesn't need special care */ + let xlrec = v16::rm_neon::XlNeonHeapLock::decode(buf); + if (xlrec.flags & pg_constants::XLH_LOCK_ALL_FROZEN_CLEARED) != 0 { + old_heap_blkno = Some(decoded.blocks[0].blkno); + flags = pg_constants::VISIBILITYMAP_ALL_FROZEN; + } } info => bail!("Unknown WAL record type for Neon RMGR: {}", info), } @@ -783,8 +825,6 @@ impl<'a> WalIngest<'a> { ), } - // FIXME: What about XLOG_NEON_HEAP_LOCK? - // Clear the VM bits if required. if new_heap_blkno.is_some() || old_heap_blkno.is_some() { let vm_rel = RelTag { @@ -827,7 +867,7 @@ impl<'a> WalIngest<'a> { NeonWalRecord::ClearVisibilityMapFlags { new_heap_blkno, old_heap_blkno, - flags: pg_constants::VISIBILITYMAP_VALID_BITS, + flags, }, ctx, ) @@ -843,7 +883,7 @@ impl<'a> WalIngest<'a> { NeonWalRecord::ClearVisibilityMapFlags { new_heap_blkno, old_heap_blkno: None, - flags: pg_constants::VISIBILITYMAP_VALID_BITS, + flags, }, ctx, ) @@ -857,7 +897,7 @@ impl<'a> WalIngest<'a> { NeonWalRecord::ClearVisibilityMapFlags { new_heap_blkno: None, old_heap_blkno, - flags: pg_constants::VISIBILITYMAP_VALID_BITS, + flags, }, ctx, ) diff --git a/pageserver/src/walrecord.rs b/pageserver/src/walrecord.rs index 27d73fb46d..9c2e522f17 100644 --- a/pageserver/src/walrecord.rs +++ b/pageserver/src/walrecord.rs @@ -219,20 +219,66 @@ pub mod v14 { old_offnum: buf.get_u16_le(), old_infobits_set: buf.get_u8(), flags: buf.get_u8(), - t_cid: buf.get_u32(), + t_cid: buf.get_u32_le(), new_xmax: buf.get_u32_le(), new_offnum: buf.get_u16_le(), } } } + + #[repr(C)] + #[derive(Debug)] + pub struct XlHeapLock { + pub locking_xid: TransactionId, + pub offnum: OffsetNumber, + pub _padding: u16, + pub t_cid: u32, + pub infobits_set: u8, + pub flags: u8, + } + + impl XlHeapLock { + pub fn decode(buf: &mut Bytes) -> XlHeapLock { + XlHeapLock { + locking_xid: buf.get_u32_le(), + offnum: buf.get_u16_le(), + _padding: buf.get_u16_le(), + t_cid: buf.get_u32_le(), + infobits_set: buf.get_u8(), + flags: buf.get_u8(), + } + } + } + + #[repr(C)] + #[derive(Debug)] + pub struct XlHeapLockUpdated { + pub xmax: TransactionId, + pub offnum: OffsetNumber, + pub infobits_set: u8, + pub flags: u8, + } + + impl XlHeapLockUpdated { + pub fn decode(buf: &mut Bytes) -> XlHeapLockUpdated { + XlHeapLockUpdated { + xmax: buf.get_u32_le(), + offnum: buf.get_u16_le(), + infobits_set: buf.get_u8(), + flags: buf.get_u8(), + } + } + } } pub mod v15 { - pub use super::v14::{XlHeapDelete, XlHeapInsert, XlHeapMultiInsert, XlHeapUpdate}; + pub use super::v14::{ + XlHeapDelete, XlHeapInsert, XlHeapLock, XlHeapLockUpdated, XlHeapMultiInsert, XlHeapUpdate, + }; } pub mod v16 { - pub use super::v14::{XlHeapInsert, XlHeapMultiInsert}; + pub use super::v14::{XlHeapInsert, XlHeapLockUpdated, XlHeapMultiInsert}; use bytes::{Buf, Bytes}; use postgres_ffi::{OffsetNumber, TransactionId}; @@ -278,6 +324,26 @@ pub mod v16 { } } + #[repr(C)] + #[derive(Debug)] + pub struct XlHeapLock { + pub locking_xid: TransactionId, + pub offnum: OffsetNumber, + pub infobits_set: u8, + pub flags: u8, + } + + impl XlHeapLock { + pub fn decode(buf: &mut Bytes) -> XlHeapLock { + XlHeapLock { + locking_xid: buf.get_u32_le(), + offnum: buf.get_u16_le(), + infobits_set: buf.get_u8(), + flags: buf.get_u8(), + } + } + } + /* Since PG16, we have the Neon RMGR (RM_NEON_ID) to manage Neon-flavored WAL. */ pub mod rm_neon { use bytes::{Buf, Bytes}; @@ -366,6 +432,28 @@ pub mod v16 { } } } + + #[repr(C)] + #[derive(Debug)] + pub struct XlNeonHeapLock { + pub locking_xid: TransactionId, + pub t_cid: u32, + pub offnum: OffsetNumber, + pub infobits_set: u8, + pub flags: u8, + } + + impl XlNeonHeapLock { + pub fn decode(buf: &mut Bytes) -> XlNeonHeapLock { + XlNeonHeapLock { + locking_xid: buf.get_u32_le(), + t_cid: buf.get_u32_le(), + offnum: buf.get_u16_le(), + infobits_set: buf.get_u8(), + flags: buf.get_u8(), + } + } + } } } diff --git a/test_runner/regress/test_vm_bits.py b/test_runner/regress/test_vm_bits.py index 8e20a44407..bc810ceb09 100644 --- a/test_runner/regress/test_vm_bits.py +++ b/test_runner/regress/test_vm_bits.py @@ -111,3 +111,103 @@ def test_vm_bit_clear(neon_simple_env: NeonEnv): assert cur_new.fetchall() == [] cur_new.execute("SELECT id FROM vmtest_cold_update2 WHERE id = 1") assert cur_new.fetchall() == [] + + +# +# Test that the ALL_FROZEN VM bit is cleared correctly at a HEAP_LOCK +# record. +# +def test_vm_bit_clear_on_heap_lock(neon_simple_env: NeonEnv): + env = neon_simple_env + + env.neon_cli.create_branch("test_vm_bit_clear_on_heap_lock", "empty") + endpoint = env.endpoints.create_start( + "test_vm_bit_clear_on_heap_lock", + config_lines=[ + "log_autovacuum_min_duration = 0", + # Perform anti-wraparound vacuuming aggressively + "autovacuum_naptime='1 s'", + "autovacuum_freeze_max_age = 1000000", + ], + ) + + pg_conn = endpoint.connect() + cur = pg_conn.cursor() + + # Install extension containing function needed for test + cur.execute("CREATE EXTENSION neon_test_utils") + + cur.execute("SELECT pg_switch_wal()") + + # Create a test table and freeze it to set the all-frozen VM bit on all pages. + cur.execute("CREATE TABLE vmtest_lock (id integer PRIMARY KEY)") + cur.execute("INSERT INTO vmtest_lock SELECT g FROM generate_series(1, 50000) g") + cur.execute("VACUUM FREEZE vmtest_lock") + + # Lock a row. This clears the all-frozen VM bit for that page. + cur.execute("SELECT * FROM vmtest_lock WHERE id = 40000 FOR UPDATE") + + # Remember the XID. We will use it later to verify that we have consumed a lot of + # XIDs after this. + cur.execute("select pg_current_xact_id()") + locking_xid = cur.fetchall()[0][0] + + # Stop and restart postgres, to clear the buffer cache. + # + # NOTE: clear_buffer_cache() will not do, because it evicts the dirty pages + # in a "clean" way. Our neon extension will write a full-page image of the VM + # page, and we want to avoid that. + endpoint.stop() + endpoint.start() + pg_conn = endpoint.connect() + cur = pg_conn.cursor() + + cur.execute("select xmin, xmax, * from vmtest_lock where id = 40000 ") + tup = cur.fetchall() + xmax_before = tup[0][1] + + # Consume a lot of XIDs, so that anti-wraparound autovacuum kicks + # in and the clog gets truncated. We set autovacuum_freeze_max_age to a very + # low value, so it doesn't take all that many XIDs for autovacuum to kick in. + for i in range(1000): + cur.execute( + """ + CREATE TEMP TABLE othertable (i int) ON COMMIT DROP; + do $$ + begin + for i in 1..100000 loop + -- Use a begin-exception block to generate a new subtransaction on each iteration + begin + insert into othertable values (i); + exception when others then + raise 'not expected %', sqlerrm; + end; + end loop; + end; + $$; + """ + ) + cur.execute("select xmin, xmax, * from vmtest_lock where id = 40000 ") + tup = cur.fetchall() + log.info(f"tuple = {tup}") + xmax = tup[0][1] + assert xmax == xmax_before + + if i % 50 == 0: + cur.execute("select datfrozenxid from pg_database where datname='postgres'") + datfrozenxid = cur.fetchall()[0][0] + if datfrozenxid > locking_xid: + break + + cur.execute("select pg_current_xact_id()") + curr_xid = cur.fetchall()[0][0] + assert int(curr_xid) - int(locking_xid) >= 100000 + + # Now, if the VM all-frozen bit was not correctly cleared on + # replay, we will try to fetch the status of the XID that was + # already truncated away. + # + # ERROR: could not access status of transaction 1027 + cur.execute("select xmin, xmax, * from vmtest_lock where id = 40000 for update") + tup = cur.fetchall() + log.info(f"tuple = {tup}") From c5d226d9c77ffffaf80373d59b1d608abe609e50 Mon Sep 17 00:00:00 2001 From: Joonas Koivunen Date: Fri, 15 Sep 2023 19:44:14 +0300 Subject: [PATCH 09/22] refactor(consumption_metrics): prereq refactorings, tests (#5315) Split off from #5297. There should be no functional changes here: - refactor tenant metric "production" like previously timeline, allows unit testing, though not interesting enough yet to test - introduce type aliases for tuples - extra refactoring for `collect`, was initially thinking it was useful but will do a inline later - shorter binding names - support for future allocation reuse quests with IdempotencyKey - move code out of tokio::select to make it rustfmt-able - generification, allow later replacement of `&'static str` with enum - add tests that assert sent event contents exactly --- libs/consumption_metrics/src/lib.rs | 55 +++- pageserver/src/consumption_metrics.rs | 363 ++++++++++++++++++-------- proxy/src/metrics.rs | 2 +- 3 files changed, 299 insertions(+), 121 deletions(-) diff --git a/libs/consumption_metrics/src/lib.rs b/libs/consumption_metrics/src/lib.rs index 418885a1b0..9dd9b0a0ef 100644 --- a/libs/consumption_metrics/src/lib.rs +++ b/libs/consumption_metrics/src/lib.rs @@ -27,7 +27,8 @@ impl EventType { } pub fn incremental_timerange(&self) -> Option>> { - // these can most likely be thought of as Range or RangeFull + // these can most likely be thought of as Range or RangeFull, at least pageserver creates + // incremental ranges where the stop and next start are equal. use EventType::*; match self { Incremental { @@ -41,15 +42,25 @@ impl EventType { pub fn is_incremental(&self) -> bool { matches!(self, EventType::Incremental { .. }) } + + /// Returns the absolute time, or for incremental ranges, the stop time. + pub fn recorded_at(&self) -> &DateTime { + use EventType::*; + + match self { + Absolute { time } => time, + Incremental { stop_time, .. } => stop_time, + } + } } #[derive(Serialize, Debug, Clone, Eq, PartialEq, Ord, PartialOrd)] -pub struct Event { +pub struct Event { #[serde(flatten)] #[serde(rename = "type")] pub kind: EventType, - pub metric: &'static str, + pub metric: Metric, pub idempotency_key: String, pub value: u64, @@ -58,12 +69,38 @@ pub struct Event { } pub fn idempotency_key(node_id: &str) -> String { - format!( - "{}-{}-{:04}", - Utc::now(), - node_id, - rand::thread_rng().gen_range(0..=9999) - ) + IdempotencyKey::generate(node_id).to_string() +} + +/// Downstream users will use these to detect upload retries. +pub struct IdempotencyKey<'a> { + now: chrono::DateTime, + node_id: &'a str, + nonce: u16, +} + +impl std::fmt::Display for IdempotencyKey<'_> { + fn fmt(&self, f: &mut std::fmt::Formatter<'_>) -> std::fmt::Result { + write!(f, "{}-{}-{:04}", self.now, self.node_id, self.nonce) + } +} + +impl<'a> IdempotencyKey<'a> { + pub fn generate(node_id: &'a str) -> Self { + IdempotencyKey { + now: Utc::now(), + node_id, + nonce: rand::thread_rng().gen_range(0..=9999), + } + } + + pub fn for_tests(now: DateTime, node_id: &'a str, nonce: u16) -> Self { + IdempotencyKey { + now, + node_id, + nonce, + } + } } pub const CHUNK_SIZE: usize = 1000; diff --git a/pageserver/src/consumption_metrics.rs b/pageserver/src/consumption_metrics.rs index e4284b9e9c..b24038de4a 100644 --- a/pageserver/src/consumption_metrics.rs +++ b/pageserver/src/consumption_metrics.rs @@ -9,6 +9,7 @@ use crate::tenant::{mgr, LogicalSizeCalculationCause}; use anyhow; use chrono::{DateTime, Utc}; use consumption_metrics::{idempotency_key, Event, EventChunk, EventType, CHUNK_SIZE}; +use futures::stream::StreamExt; use pageserver_api::models::TenantState; use reqwest::Url; use serde::Serialize; @@ -32,7 +33,37 @@ struct Ids { timeline_id: Option, } -/// Key that uniquely identifies the object, this metric describes. +/// Name of the metric, used by `MetricsKey` factory methods and `deserialize_cached_events` +/// instead of static str. +// Do not rename any of these without first consulting with data team and partner +// management. +// FIXME: write those tests before refactoring to this! +#[derive(Debug, Clone, Copy, PartialEq, Eq, Hash, serde::Serialize, serde::Deserialize)] +enum Name { + /// Timeline last_record_lsn, absolute + #[serde(rename = "written_size")] + WrittenSize, + /// Timeline last_record_lsn, incremental + #[serde(rename = "written_data_bytes_delta")] + WrittenSizeDelta, + /// Timeline logical size + #[serde(rename = "timeline_logical_size")] + LogicalSize, + /// Tenant remote size + #[serde(rename = "remote_storage_size")] + RemoteSize, + /// Tenant resident size + #[serde(rename = "resident_size")] + ResidentSize, + /// Tenant synthetic size + #[serde(rename = "synthetic_storage_size")] + SyntheticSize, +} + +/// Key that uniquely identifies the object this metric describes. +/// +/// This is a denormalization done at the MetricsKey const methods; these should not be constructed +/// elsewhere. #[derive(Debug, Clone, PartialEq, Eq, Hash)] struct MetricsKey { tenant_id: TenantId, @@ -53,7 +84,7 @@ impl MetricsKey { struct AbsoluteValueFactory(MetricsKey); impl AbsoluteValueFactory { - fn at(self, time: DateTime, val: u64) -> (MetricsKey, (EventType, u64)) { + fn at(self, time: DateTime, val: u64) -> RawMetric { let key = self.0; (key, (EventType::Absolute { time }, val)) } @@ -69,7 +100,7 @@ impl IncrementalValueFactory { prev_end: DateTime, up_to: DateTime, val: u64, - ) -> (MetricsKey, (EventType, u64)) { + ) -> RawMetric { let key = self.0; // cannot assert prev_end < up_to because these are realtime clock based ( @@ -172,6 +203,20 @@ impl MetricsKey { } } +/// Basically a key-value pair, but usually in a Vec except for [`Cache`]. +/// +/// This is as opposed to `consumption_metrics::Event` which is the externally communicated form. +/// Difference is basically the missing idempotency key, which lives only for the duration of +/// upload attempts. +type RawMetric = (MetricsKey, (EventType, u64)); + +/// Caches the [`RawMetric`]s +/// +/// In practice, during startup, last sent values are stored here to be used in calculating new +/// ones. After successful uploading, the cached values are updated to cache. This used to be used +/// for deduplication, but that is no longer needed. +type Cache = HashMap; + /// Main thread that serves metrics collection pub async fn collect_metrics( metric_collection_endpoint: &Url, @@ -249,13 +294,12 @@ pub async fn collect_metrics( /// - refactor this function (chunking+sending part) to reuse it in proxy module; async fn collect_metrics_iteration( client: &reqwest::Client, - cached_metrics: &mut HashMap, + cached_metrics: &mut Cache, metric_collection_endpoint: &reqwest::Url, node_id: NodeId, ctx: &RequestContext, send_cached: bool, ) { - let mut current_metrics: Vec<(MetricsKey, (EventType, u64))> = Vec::new(); trace!( "starting collect_metrics_iteration. metric_collection_endpoint: {}", metric_collection_endpoint @@ -270,69 +314,18 @@ async fn collect_metrics_iteration( } }; - // iterate through list of Active tenants and collect metrics - for (tenant_id, tenant_state) in tenants { - if tenant_state != TenantState::Active { - continue; + let tenants = futures::stream::iter(tenants).filter_map(|(id, state)| async move { + if state != TenantState::Active { + None + } else { + mgr::get_tenant(id, true) + .await + .ok() + .map(|tenant| (id, tenant)) } + }); - let tenant = match mgr::get_tenant(tenant_id, true).await { - Ok(tenant) => tenant, - Err(err) => { - // It is possible that tenant was deleted between - // `list_tenants` and `get_tenant`, so just warn about it. - warn!("failed to get tenant {tenant_id:?}: {err:?}"); - continue; - } - }; - - let mut tenant_resident_size = 0; - - // iterate through list of timelines in tenant - for timeline in tenant.list_timelines() { - // collect per-timeline metrics only for active timelines - - let timeline_id = timeline.timeline_id; - - match TimelineSnapshot::collect(&timeline, ctx) { - Ok(Some(snap)) => { - snap.to_metrics( - tenant_id, - timeline_id, - Utc::now(), - &mut current_metrics, - cached_metrics, - ); - } - Ok(None) => {} - Err(e) => { - error!( - "failed to get metrics values for tenant {tenant_id} timeline {}: {e:#?}", - timeline.timeline_id - ); - continue; - } - } - - tenant_resident_size += timeline.resident_physical_size(); - } - - current_metrics - .push(MetricsKey::remote_storage_size(tenant_id).at(Utc::now(), tenant.remote_size())); - - current_metrics - .push(MetricsKey::resident_size(tenant_id).at(Utc::now(), tenant_resident_size)); - - // Note that this metric is calculated in a separate bgworker - // Here we only use cached value, which may lag behind the real latest one - let synthetic_size = tenant.cached_synthetic_size(); - - if synthetic_size != 0 { - // only send non-zeroes because otherwise these show up as errors in logs - current_metrics - .push(MetricsKey::synthetic_size(tenant_id).at(Utc::now(), synthetic_size)); - } - } + let mut current_metrics = collect(tenants, cached_metrics, ctx).await; // Filter metrics, unless we want to send all metrics, including cached ones. // See: https://github.com/neondatabase/neon/issues/3485 @@ -360,7 +353,7 @@ async fn collect_metrics_iteration( // Split into chunks of 1000 metrics to avoid exceeding the max request size let chunks = current_metrics.chunks(CHUNK_SIZE); - let mut chunk_to_send: Vec> = Vec::with_capacity(CHUNK_SIZE); + let mut chunk_to_send: Vec> = Vec::with_capacity(CHUNK_SIZE); let node_id = node_id.to_string(); @@ -422,6 +415,102 @@ async fn collect_metrics_iteration( } } +async fn collect( + tenants: S, + cache: &HashMap, + ctx: &RequestContext, +) -> Vec<(MetricsKey, (EventType, u64))> +where + S: futures::stream::Stream)>, +{ + let mut current_metrics: Vec<(MetricsKey, (EventType, u64))> = Vec::new(); + + let mut tenants = std::pin::pin!(tenants); + + while let Some((tenant_id, tenant)) = tenants.next().await { + let mut tenant_resident_size = 0; + + // iterate through list of timelines in tenant + for timeline in tenant.list_timelines() { + // collect per-timeline metrics only for active timelines + + let timeline_id = timeline.timeline_id; + + match TimelineSnapshot::collect(&timeline, ctx) { + Ok(Some(snap)) => { + snap.to_metrics( + tenant_id, + timeline_id, + Utc::now(), + &mut current_metrics, + cache, + ); + } + Ok(None) => {} + Err(e) => { + error!( + "failed to get metrics values for tenant {tenant_id} timeline {}: {e:#?}", + timeline.timeline_id + ); + continue; + } + } + + tenant_resident_size += timeline.resident_physical_size(); + } + + TenantSnapshot::collect(&tenant, tenant_resident_size).to_metrics( + tenant_id, + Utc::now(), + &mut current_metrics, + ); + } + + current_metrics +} + +/// Testing helping in-between abstraction allowing testing metrics without actual Tenants. +struct TenantSnapshot { + resident_size: u64, + remote_size: u64, + synthetic_size: u64, +} + +impl TenantSnapshot { + /// Collect tenant status to have metrics created out of it. + /// + /// `resident_size` is calculated of the timelines we had access to for other metrics, so we + /// cannot just list timelines here. + fn collect(t: &Arc, resident_size: u64) -> Self { + TenantSnapshot { + resident_size, + remote_size: t.remote_size(), + // Note that this metric is calculated in a separate bgworker + // Here we only use cached value, which may lag behind the real latest one + synthetic_size: t.cached_synthetic_size(), + } + } + + fn to_metrics(&self, tenant_id: TenantId, now: DateTime, metrics: &mut Vec) { + let remote_size = MetricsKey::remote_storage_size(tenant_id).at(now, self.remote_size); + + let resident_size = MetricsKey::resident_size(tenant_id).at(now, self.resident_size); + + let synthetic_size = if self.synthetic_size != 0 { + // only send non-zeroes because otherwise these show up as errors in logs + Some(MetricsKey::synthetic_size(tenant_id).at(now, self.synthetic_size)) + } else { + None + }; + + metrics.extend( + [Some(remote_size), Some(resident_size), synthetic_size] + .into_iter() + .flatten(), + ); + } +} + /// Internal type to make timeline metric production testable. /// /// As this value type contains all of the information needed from a timeline to produce the @@ -478,22 +567,13 @@ impl TimelineSnapshot { tenant_id: TenantId, timeline_id: TimelineId, now: DateTime, - metrics: &mut Vec<(MetricsKey, (EventType, u64))>, - cache: &HashMap, + metrics: &mut Vec, + cache: &Cache, ) { let timeline_written_size = u64::from(self.last_record_lsn); - let (key, written_size_now) = - MetricsKey::written_size(tenant_id, timeline_id).at(now, timeline_written_size); - - // last_record_lsn can only go up, right now at least, TODO: #2592 or related - // features might change this. - let written_size_delta_key = MetricsKey::written_size_delta(tenant_id, timeline_id); - // use this when available, because in a stream of incremental values, it will be - // accurate where as when last_record_lsn stops moving, we will only cache the last - // one of those. let last_stop_time = cache .get(written_size_delta_key.key()) .map(|(until, _val)| { @@ -503,6 +583,9 @@ impl TimelineSnapshot { .end }); + let (key, written_size_now) = + MetricsKey::written_size(tenant_id, timeline_id).at(now, timeline_written_size); + // by default, use the last sent written_size as the basis for // calculating the delta. if we don't yet have one, use the load time value. let prev = cache @@ -547,53 +630,47 @@ impl TimelineSnapshot { } /// Caclculate synthetic size for each active tenant -pub async fn calculate_synthetic_size_worker( +async fn calculate_synthetic_size_worker( synthetic_size_calculation_interval: Duration, ctx: &RequestContext, ) -> anyhow::Result<()> { info!("starting calculate_synthetic_size_worker"); + // reminder: this ticker is ready right away let mut ticker = tokio::time::interval(synthetic_size_calculation_interval); + let cause = LogicalSizeCalculationCause::ConsumptionMetricsSyntheticSize; loop { - tokio::select! { - _ = task_mgr::shutdown_watcher() => { - return Ok(()); - }, - tick_at = ticker.tick() => { + let tick_at = tokio::select! { + _ = task_mgr::shutdown_watcher() => return Ok(()), + tick_at = ticker.tick() => tick_at, + }; - let tenants = match mgr::list_tenants().await { - Ok(tenants) => tenants, - Err(e) => { - warn!("cannot get tenant list: {e:#}"); - continue; - } - }; - // iterate through list of Active tenants and collect metrics - for (tenant_id, tenant_state) in tenants { + let tenants = match mgr::list_tenants().await { + Ok(tenants) => tenants, + Err(e) => { + warn!("cannot get tenant list: {e:#}"); + continue; + } + }; - if tenant_state != TenantState::Active { - continue; - } - - if let Ok(tenant) = mgr::get_tenant(tenant_id, true).await - { - if let Err(e) = tenant.calculate_synthetic_size( - LogicalSizeCalculationCause::ConsumptionMetricsSyntheticSize, - ctx).await { - error!("failed to calculate synthetic size for tenant {}: {}", tenant_id, e); - } - } + for (tenant_id, tenant_state) in tenants { + if tenant_state != TenantState::Active { + continue; + } + if let Ok(tenant) = mgr::get_tenant(tenant_id, true).await { + if let Err(e) = tenant.calculate_synthetic_size(cause, ctx).await { + error!("failed to calculate synthetic size for tenant {tenant_id}: {e:#}"); } - - crate::tenant::tasks::warn_when_period_overrun( - tick_at.elapsed(), - synthetic_size_calculation_interval, - "consumption_metrics_synthetic_size_worker", - ); } } + + crate::tenant::tasks::warn_when_period_overrun( + tick_at.elapsed(), + synthetic_size_calculation_interval, + "consumption_metrics_synthetic_size_worker", + ); } } @@ -732,6 +809,70 @@ mod tests { ); } + #[test] + fn metric_image_stability() { + // it is important that these strings stay as they are + + let tenant_id = TenantId::from_array([0; 16]); + let timeline_id = TimelineId::from_array([0xff; 16]); + + let now = DateTime::parse_from_rfc3339("2023-09-15T00:00:00.123456789Z").unwrap(); + let before = DateTime::parse_from_rfc3339("2023-09-14T00:00:00.123456789Z").unwrap(); + + let [now, before] = [DateTime::::from(now), DateTime::from(before)]; + + let examples = [ + ( + line!(), + MetricsKey::written_size(tenant_id, timeline_id).at(now, 0), + r#"{"type":"absolute","time":"2023-09-15T00:00:00.123456789Z","metric":"written_size","idempotency_key":"2023-09-15 00:00:00.123456789 UTC-1-0000","value":0,"tenant_id":"00000000000000000000000000000000","timeline_id":"ffffffffffffffffffffffffffffffff"}"#, + ), + ( + line!(), + MetricsKey::written_size_delta(tenant_id, timeline_id) + .from_previous_up_to(before, now, 0), + r#"{"type":"incremental","start_time":"2023-09-14T00:00:00.123456789Z","stop_time":"2023-09-15T00:00:00.123456789Z","metric":"written_data_bytes_delta","idempotency_key":"2023-09-15 00:00:00.123456789 UTC-1-0000","value":0,"tenant_id":"00000000000000000000000000000000","timeline_id":"ffffffffffffffffffffffffffffffff"}"#, + ), + ( + line!(), + MetricsKey::timeline_logical_size(tenant_id, timeline_id).at(now, 0), + r#"{"type":"absolute","time":"2023-09-15T00:00:00.123456789Z","metric":"timeline_logical_size","idempotency_key":"2023-09-15 00:00:00.123456789 UTC-1-0000","value":0,"tenant_id":"00000000000000000000000000000000","timeline_id":"ffffffffffffffffffffffffffffffff"}"#, + ), + ( + line!(), + MetricsKey::remote_storage_size(tenant_id).at(now, 0), + r#"{"type":"absolute","time":"2023-09-15T00:00:00.123456789Z","metric":"remote_storage_size","idempotency_key":"2023-09-15 00:00:00.123456789 UTC-1-0000","value":0,"tenant_id":"00000000000000000000000000000000"}"#, + ), + ( + line!(), + MetricsKey::resident_size(tenant_id).at(now, 0), + r#"{"type":"absolute","time":"2023-09-15T00:00:00.123456789Z","metric":"resident_size","idempotency_key":"2023-09-15 00:00:00.123456789 UTC-1-0000","value":0,"tenant_id":"00000000000000000000000000000000"}"#, + ), + ( + line!(), + MetricsKey::synthetic_size(tenant_id).at(now, 1), + r#"{"type":"absolute","time":"2023-09-15T00:00:00.123456789Z","metric":"synthetic_storage_size","idempotency_key":"2023-09-15 00:00:00.123456789 UTC-1-0000","value":1,"tenant_id":"00000000000000000000000000000000"}"#, + ), + ]; + + let idempotency_key = consumption_metrics::IdempotencyKey::for_tests(now, "1", 0); + + for (line, (key, (kind, value)), expected) in examples { + let e = consumption_metrics::Event { + kind, + metric: key.metric, + idempotency_key: idempotency_key.to_string(), + value, + extra: super::Ids { + tenant_id: key.tenant_id, + timeline_id: key.timeline_id, + }, + }; + let actual = serde_json::to_string(&e).unwrap(); + assert_eq!(expected, actual, "example from line {line}"); + } + } + fn time_backwards() -> [std::time::SystemTime; N] { let mut times = [std::time::SystemTime::UNIX_EPOCH; N]; times[0] = std::time::SystemTime::now(); diff --git a/proxy/src/metrics.rs b/proxy/src/metrics.rs index d63f902ac1..9279002eb3 100644 --- a/proxy/src/metrics.rs +++ b/proxy/src/metrics.rs @@ -121,7 +121,7 @@ async fn collect_metrics_iteration( let current_metrics = gather_proxy_io_bytes_per_client(); - let metrics_to_send: Vec> = current_metrics + let metrics_to_send: Vec> = current_metrics .iter() .filter_map(|(curr_key, (curr_val, curr_time))| { let mut start_time = *curr_time; From 00c4c8e2e8e4c3bd00def7ae774032935a009937 Mon Sep 17 00:00:00 2001 From: Joonas Koivunen Date: Sat, 16 Sep 2023 00:06:19 +0300 Subject: [PATCH 10/22] feat(consumption_metrics): remove event deduplication support (#5316) We no longer use pageserver deduplication anywhere. Give out a warning instead. Split off from #5297. Cc: #5175 for dedup. --- pageserver/src/config.rs | 2 +- pageserver/src/consumption_metrics.rs | 37 ++++++--------------------- 2 files changed, 9 insertions(+), 30 deletions(-) diff --git a/pageserver/src/config.rs b/pageserver/src/config.rs index dbebde26bd..8ee7f28c11 100644 --- a/pageserver/src/config.rs +++ b/pageserver/src/config.rs @@ -64,7 +64,7 @@ pub mod defaults { super::ConfigurableSemaphore::DEFAULT_INITIAL.get(); pub const DEFAULT_METRIC_COLLECTION_INTERVAL: &str = "10 min"; - pub const DEFAULT_CACHED_METRIC_COLLECTION_INTERVAL: &str = "1 hour"; + pub const DEFAULT_CACHED_METRIC_COLLECTION_INTERVAL: &str = "0s"; pub const DEFAULT_METRIC_COLLECTION_ENDPOINT: Option = None; pub const DEFAULT_SYNTHETIC_SIZE_CALCULATION_INTERVAL: &str = "10 min"; pub const DEFAULT_BACKGROUND_TASK_MAXIMUM_DELAY: &str = "10s"; diff --git a/pageserver/src/consumption_metrics.rs b/pageserver/src/consumption_metrics.rs index b24038de4a..e74fe89cc8 100644 --- a/pageserver/src/consumption_metrics.rs +++ b/pageserver/src/consumption_metrics.rs @@ -221,11 +221,16 @@ type Cache = HashMap; pub async fn collect_metrics( metric_collection_endpoint: &Url, metric_collection_interval: Duration, - cached_metric_collection_interval: Duration, + _cached_metric_collection_interval: Duration, synthetic_size_calculation_interval: Duration, node_id: NodeId, ctx: RequestContext, ) -> anyhow::Result<()> { + if _cached_metric_collection_interval != Duration::ZERO { + tracing::warn!( + "cached_metric_collection_interval is no longer used, please set it to zero." + ) + } let mut ticker = tokio::time::interval(metric_collection_interval); info!("starting collect_metrics"); @@ -253,7 +258,6 @@ pub async fn collect_metrics( .build() .expect("Failed to create http client with timeout"); let mut cached_metrics = HashMap::new(); - let mut prev_iteration_time: std::time::Instant = std::time::Instant::now(); loop { tokio::select! { @@ -263,14 +267,7 @@ pub async fn collect_metrics( }, tick_at = ticker.tick() => { - // send cached metrics every cached_metric_collection_interval - let send_cached = prev_iteration_time.elapsed() >= cached_metric_collection_interval; - - if send_cached { - prev_iteration_time = std::time::Instant::now(); - } - - collect_metrics_iteration(&client, &mut cached_metrics, metric_collection_endpoint, node_id, &ctx, send_cached).await; + collect_metrics_iteration(&client, &mut cached_metrics, metric_collection_endpoint, node_id, &ctx).await; crate::tenant::tasks::warn_when_period_overrun( tick_at.elapsed(), @@ -298,7 +295,6 @@ async fn collect_metrics_iteration( metric_collection_endpoint: &reqwest::Url, node_id: NodeId, ctx: &RequestContext, - send_cached: bool, ) { trace!( "starting collect_metrics_iteration. metric_collection_endpoint: {}", @@ -325,24 +321,7 @@ async fn collect_metrics_iteration( } }); - let mut current_metrics = collect(tenants, cached_metrics, ctx).await; - - // Filter metrics, unless we want to send all metrics, including cached ones. - // See: https://github.com/neondatabase/neon/issues/3485 - if !send_cached { - current_metrics.retain(|(curr_key, (kind, curr_val))| { - if kind.is_incremental() { - // incremental values (currently only written_size_delta) should not get any cache - // deduplication because they will be used by upstream for "is still alive." - true - } else { - match cached_metrics.get(curr_key) { - Some((_, val)) => val != curr_val, - None => true, - } - } - }); - } + let current_metrics = collect(tenants, cached_metrics, ctx).await; if current_metrics.is_empty() { trace!("no new metrics to send"); From a7f4ee02a30a1835c6fb28e03da75baf593dc816 Mon Sep 17 00:00:00 2001 From: Joonas Koivunen Date: Sat, 16 Sep 2023 01:11:01 +0300 Subject: [PATCH 11/22] fix(consumption_metrics): exp backoff retry (#5317) Split off from #5297. Depends on #5315. Cc: #5175 for retry --- pageserver/src/consumption_metrics.rs | 149 +++++++++++++----- .../regress/test_threshold_based_eviction.py | 4 +- 2 files changed, 115 insertions(+), 38 deletions(-) diff --git a/pageserver/src/consumption_metrics.rs b/pageserver/src/consumption_metrics.rs index e74fe89cc8..a4a68581fa 100644 --- a/pageserver/src/consumption_metrics.rs +++ b/pageserver/src/consumption_metrics.rs @@ -6,7 +6,6 @@ use crate::context::{DownloadBehavior, RequestContext}; use crate::task_mgr::{self, TaskKind, BACKGROUND_RUNTIME}; use crate::tenant::{mgr, LogicalSizeCalculationCause}; -use anyhow; use chrono::{DateTime, Utc}; use consumption_metrics::{idempotency_key, Event, EventChunk, EventType, CHUNK_SIZE}; use futures::stream::StreamExt; @@ -17,6 +16,7 @@ use serde_with::{serde_as, DisplayFromStr}; use std::collections::HashMap; use std::sync::Arc; use std::time::{Duration, SystemTime}; +use tokio_util::sync::CancellationToken; use tracing::*; use utils::id::{NodeId, TenantId, TimelineId}; use utils::lsn::Lsn; @@ -328,6 +328,8 @@ async fn collect_metrics_iteration( return; } + let cancel = task_mgr::shutdown_token(); + // Send metrics. // Split into chunks of 1000 metrics to avoid exceeding the max request size let chunks = current_metrics.chunks(CHUNK_SIZE); @@ -336,6 +338,8 @@ async fn collect_metrics_iteration( let node_id = node_id.to_string(); + let mut buffer = bytes::BytesMut::new(); + for chunk in chunks { chunk_to_send.clear(); @@ -351,45 +355,28 @@ async fn collect_metrics_iteration( }, })); - const MAX_RETRIES: u32 = 3; + use bytes::BufMut; - for attempt in 0..MAX_RETRIES { - let res = client - .post(metric_collection_endpoint.clone()) - .json(&EventChunk { - events: (&chunk_to_send).into(), - }) - .send() - .await; + // FIXME: this is a new panic we did not have before. not really essential, but panics from + // this task currently restart pageserver. + serde_json::to_writer( + (&mut buffer).writer(), + &EventChunk { + events: (&chunk_to_send).into(), + }, + ) + .expect("serialization must not fail and bytesmut grows"); - match res { - Ok(res) => { - if res.status().is_success() { - // update cached metrics after they were sent successfully - for (curr_key, curr_val) in chunk.iter() { - cached_metrics.insert(curr_key.clone(), *curr_val); - } - } else { - error!("metrics endpoint refused the sent metrics: {:?}", res); - for metric in chunk_to_send - .iter() - .filter(|metric| metric.value > (1u64 << 40)) - { - // Report if the metric value is suspiciously large - error!("potentially abnormal metric value: {:?}", metric); - } - } - break; - } - Err(err) if err.is_timeout() => { - error!(attempt, "timeout sending metrics, retrying immediately"); - continue; - } - Err(err) => { - error!(attempt, ?err, "failed to send metrics"); - break; - } + let body = buffer.split().freeze(); + + let res = upload(client, metric_collection_endpoint, body, &cancel).await; + + if res.is_ok() { + for (curr_key, curr_val) in chunk.iter() { + cached_metrics.insert(curr_key.clone(), *curr_val); } + } else { + // no need to log, backoff::retry and upload have done it, just give up uploading. } } } @@ -448,6 +435,94 @@ where current_metrics } +enum UploadError { + Rejected(reqwest::StatusCode), + Reqwest(reqwest::Error), + Cancelled, +} + +impl std::fmt::Debug for UploadError { + fn fmt(&self, f: &mut std::fmt::Formatter<'_>) -> std::fmt::Result { + // use same impl because backoff::retry will log this using both + std::fmt::Display::fmt(self, f) + } +} + +impl std::fmt::Display for UploadError { + fn fmt(&self, f: &mut std::fmt::Formatter<'_>) -> std::fmt::Result { + use UploadError::*; + + match self { + Rejected(code) => write!(f, "server rejected the metrics with {code}"), + Reqwest(e) => write!(f, "request failed: {e}"), + Cancelled => write!(f, "cancelled"), + } + } +} + +impl UploadError { + fn is_reject(&self) -> bool { + matches!(self, UploadError::Rejected(_)) + } +} + +async fn upload( + client: &reqwest::Client, + metric_collection_endpoint: &reqwest::Url, + body: bytes::Bytes, + cancel: &CancellationToken, +) -> Result<(), UploadError> { + let warn_after = 3; + let max_attempts = 10; + let res = utils::backoff::retry( + move || { + let body = body.clone(); + async move { + let res = client + .post(metric_collection_endpoint.clone()) + .header(reqwest::header::CONTENT_TYPE, "application/json") + .body(body) + .send() + .await; + + let res = res.and_then(|res| res.error_for_status()); + + match res { + Ok(_response) => Ok(()), + Err(e) => { + let status = e.status().filter(|s| s.is_client_error()); + if let Some(status) = status { + Err(UploadError::Rejected(status)) + } else { + Err(UploadError::Reqwest(e)) + } + } + } + } + }, + UploadError::is_reject, + warn_after, + max_attempts, + "upload consumption_metrics", + utils::backoff::Cancel::new(cancel.clone(), || UploadError::Cancelled), + ) + .await; + + match &res { + Ok(_) => {} + Err(e) if e.is_reject() => { + // permanent errors currently do not get logged by backoff::retry + // display alternate has no effect, but keeping it here for easier pattern matching. + tracing::error!("failed to upload metrics: {e:#}"); + } + Err(_) => { + // these have been logged already + } + } + + res +} + /// Testing helping in-between abstraction allowing testing metrics without actual Tenants. struct TenantSnapshot { resident_size: u64, diff --git a/test_runner/regress/test_threshold_based_eviction.py b/test_runner/regress/test_threshold_based_eviction.py index 6f5e3e2518..12866accc7 100644 --- a/test_runner/regress/test_threshold_based_eviction.py +++ b/test_runner/regress/test_threshold_based_eviction.py @@ -32,7 +32,9 @@ def test_threshold_based_eviction( synthetic_size_calculation_interval="2s" metric_collection_endpoint="http://{host}:{port}/nonexistent" """ - metrics_refused_log_line = ".*metrics endpoint refused the sent metrics.*/nonexistent.*" + metrics_refused_log_line = ( + ".*metrics_collection:.* upload consumption_metrics (still failed|failed, will retry).*" + ) env = neon_env_builder.init_start() env.pageserver.allowed_errors.append(metrics_refused_log_line) From f902777202d77396f09fdbff57ec8fd56e62f588 Mon Sep 17 00:00:00 2001 From: Joonas Koivunen Date: Sat, 16 Sep 2023 11:24:42 +0300 Subject: [PATCH 12/22] fix: consumption metrics on restart (#5323) Write collected metrics to disk to recover previously sent metrics on restart. Recover the previously collected metrics during startup, send them over at right time - send cached synthetic size before actual is calculated - when `last_record_lsn` rolls back on startup - stay at last sent `written_size` metric - send `written_size_delta_bytes` metric as 0 Add test support: stateful verification of events in python tests. Fixes: #5206 Cc: #5175 (loggings, will be enhanced in follow-up) --- libs/consumption_metrics/src/lib.rs | 2 +- pageserver/Cargo.toml | 2 +- pageserver/src/bin/pageserver.rs | 4 + pageserver/src/consumption_metrics.rs | 681 ++++++++++++++---- test_runner/regress/test_metric_collection.py | 257 +++++-- 5 files changed, 757 insertions(+), 189 deletions(-) diff --git a/libs/consumption_metrics/src/lib.rs b/libs/consumption_metrics/src/lib.rs index 9dd9b0a0ef..040b047d6f 100644 --- a/libs/consumption_metrics/src/lib.rs +++ b/libs/consumption_metrics/src/lib.rs @@ -5,7 +5,7 @@ use chrono::{DateTime, Utc}; use rand::Rng; use serde::Serialize; -#[derive(Serialize, Debug, Clone, Copy, Eq, PartialEq, Ord, PartialOrd)] +#[derive(Serialize, serde::Deserialize, Debug, Clone, Copy, Eq, PartialEq, Ord, PartialOrd)] #[serde(tag = "type")] pub enum EventType { #[serde(rename = "absolute")] diff --git a/pageserver/Cargo.toml b/pageserver/Cargo.toml index bbdd8b1e99..9cb71dea09 100644 --- a/pageserver/Cargo.toml +++ b/pageserver/Cargo.toml @@ -80,11 +80,11 @@ enum-map.workspace = true enumset.workspace = true strum.workspace = true strum_macros.workspace = true +tempfile.workspace = true [dev-dependencies] criterion.workspace = true hex-literal.workspace = true -tempfile.workspace = true tokio = { workspace = true, features = ["process", "sync", "fs", "rt", "io-util", "time", "test-util"] } [[bench]] diff --git a/pageserver/src/bin/pageserver.rs b/pageserver/src/bin/pageserver.rs index 6103f4c885..b6a2117f9c 100644 --- a/pageserver/src/bin/pageserver.rs +++ b/pageserver/src/bin/pageserver.rs @@ -518,6 +518,9 @@ fn start_pageserver( // creates a child context with the right DownloadBehavior. DownloadBehavior::Error, ); + + let local_disk_storage = conf.workdir.join("last_consumption_metrics.json"); + task_mgr::spawn( crate::BACKGROUND_RUNTIME.handle(), TaskKind::MetricsCollection, @@ -544,6 +547,7 @@ fn start_pageserver( conf.cached_metric_collection_interval, conf.synthetic_size_calculation_interval, conf.id, + local_disk_storage, metrics_ctx, ) .instrument(info_span!("metrics_collection")) diff --git a/pageserver/src/consumption_metrics.rs b/pageserver/src/consumption_metrics.rs index a4a68581fa..065f74045a 100644 --- a/pageserver/src/consumption_metrics.rs +++ b/pageserver/src/consumption_metrics.rs @@ -14,6 +14,7 @@ use reqwest::Url; use serde::Serialize; use serde_with::{serde_as, DisplayFromStr}; use std::collections::HashMap; +use std::path::PathBuf; use std::sync::Arc; use std::time::{Duration, SystemTime}; use tokio_util::sync::CancellationToken; @@ -21,10 +22,12 @@ use tracing::*; use utils::id::{NodeId, TenantId, TimelineId}; use utils::lsn::Lsn; +use anyhow::Context; + const DEFAULT_HTTP_REPORTING_TIMEOUT: Duration = Duration::from_secs(60); #[serde_as] -#[derive(Serialize, Debug, Clone, Copy)] +#[derive(Serialize, serde::Deserialize, Debug, Clone, Copy)] struct Ids { #[serde_as(as = "DisplayFromStr")] tenant_id: TenantId, @@ -64,11 +67,17 @@ enum Name { /// /// This is a denormalization done at the MetricsKey const methods; these should not be constructed /// elsewhere. -#[derive(Debug, Clone, PartialEq, Eq, Hash)] +#[serde_with::serde_as] +#[derive(Debug, Clone, Copy, PartialEq, Eq, Hash, serde::Serialize, serde::Deserialize)] struct MetricsKey { + #[serde_as(as = "serde_with::DisplayFromStr")] tenant_id: TenantId, + + #[serde_as(as = "Option")] + #[serde(skip_serializing_if = "Option::is_none")] timeline_id: Option, - metric: &'static str, + + metric: Name, } impl MetricsKey { @@ -88,6 +97,10 @@ impl AbsoluteValueFactory { let key = self.0; (key, (EventType::Absolute { time }, val)) } + + fn key(&self) -> &MetricsKey { + &self.0 + } } /// Helper type which each individual metric kind can return to produce only incremental values. @@ -129,7 +142,7 @@ impl MetricsKey { MetricsKey { tenant_id, timeline_id: Some(timeline_id), - metric: "written_size", + metric: Name::WrittenSize, } .absolute_values() } @@ -144,9 +157,7 @@ impl MetricsKey { MetricsKey { tenant_id, timeline_id: Some(timeline_id), - // the name here is correctly about data not size, because that is what is wanted by - // downstream pipeline - metric: "written_data_bytes_delta", + metric: Name::WrittenSizeDelta, } .incremental_values() } @@ -161,7 +172,7 @@ impl MetricsKey { MetricsKey { tenant_id, timeline_id: Some(timeline_id), - metric: "timeline_logical_size", + metric: Name::LogicalSize, } .absolute_values() } @@ -173,7 +184,7 @@ impl MetricsKey { MetricsKey { tenant_id, timeline_id: None, - metric: "remote_storage_size", + metric: Name::RemoteSize, } .absolute_values() } @@ -185,7 +196,7 @@ impl MetricsKey { MetricsKey { tenant_id, timeline_id: None, - metric: "resident_size", + metric: Name::ResidentSize, } .absolute_values() } @@ -197,7 +208,7 @@ impl MetricsKey { MetricsKey { tenant_id, timeline_id: None, - metric: "synthetic_storage_size", + metric: Name::SyntheticSize, } .absolute_values() } @@ -224,6 +235,7 @@ pub async fn collect_metrics( _cached_metric_collection_interval: Duration, synthetic_size_calculation_interval: Duration, node_id: NodeId, + local_disk_storage: PathBuf, ctx: RequestContext, ) -> anyhow::Result<()> { if _cached_metric_collection_interval != Duration::ZERO { @@ -231,8 +243,6 @@ pub async fn collect_metrics( "cached_metric_collection_interval is no longer used, please set it to zero." ) } - let mut ticker = tokio::time::interval(metric_collection_interval); - info!("starting collect_metrics"); // spin up background worker that caclulates tenant sizes let worker_ctx = @@ -252,61 +262,183 @@ pub async fn collect_metrics( }, ); + let final_path: Arc = Arc::new(local_disk_storage); + // define client here to reuse it for all requests let client = reqwest::ClientBuilder::new() .timeout(DEFAULT_HTTP_REPORTING_TIMEOUT) .build() .expect("Failed to create http client with timeout"); - let mut cached_metrics = HashMap::new(); - loop { - tokio::select! { - _ = task_mgr::shutdown_watcher() => { - info!("collect_metrics received cancellation request"); - return Ok(()); - }, - tick_at = ticker.tick() => { + let node_id = node_id.to_string(); + let cancel = task_mgr::shutdown_token(); - collect_metrics_iteration(&client, &mut cached_metrics, metric_collection_endpoint, node_id, &ctx).await; + let (mut cached_metrics, oldest_metric_captured_at) = + match read_metrics_from_disk(final_path.clone()).await { + Ok(found_some) => { + // there is no min needed because we write these sequentially in + // collect_all_metrics + let oldest_metric_captured_at = found_some + .iter() + .map(|(_, (et, _))| et.recorded_at()) + .copied() + .next(); - crate::tenant::tasks::warn_when_period_overrun( - tick_at.elapsed(), - metric_collection_interval, - "consumption_metrics_collect_metrics", + let cached = found_some + .into_iter() + .collect::>(); + + (cached, oldest_metric_captured_at) + } + Err(e) => { + let root = e.root_cause(); + + let maybe_ioerr = root.downcast_ref::(); + let is_not_found = + maybe_ioerr.is_some_and(|e| e.kind() == std::io::ErrorKind::NotFound); + + if !is_not_found { + tracing::info!( + "failed to read any previous metrics from {final_path:?}: {e:#}" + ); + } + + (HashMap::new(), None) + } + }; + + if let Some(oldest_metric_captured_at) = oldest_metric_captured_at { + // FIXME: chrono methods panic + let oldest_metric_captured_at: SystemTime = oldest_metric_captured_at.into(); + let now = SystemTime::now(); + let error = match now.duration_since(oldest_metric_captured_at) { + Ok(from_last_send) if from_last_send < metric_collection_interval => { + let sleep_for = metric_collection_interval - from_last_send; + + let deadline = std::time::Instant::now() + sleep_for; + + tokio::select! { + _ = cancel.cancelled() => { return Ok(()); }, + _ = tokio::time::sleep_until(deadline.into()) => {}, + } + + let now = std::time::Instant::now(); + + // executor threads might be busy, add extra measurements + Some(if now < deadline { + deadline - now + } else { + now - deadline + }) + } + Ok(from_last_send) => Some(from_last_send.saturating_sub(metric_collection_interval)), + Err(_) => { + tracing::warn!( + ?now, + ?oldest_metric_captured_at, + "oldest recorded metric is in future; first values will come out with inconsistent timestamps" ); + oldest_metric_captured_at.duration_since(now).ok() + } + }; + + if let Some(error) = error { + if error.as_secs() >= 60 { + tracing::info!( + error_ms = error.as_millis(), + "startup scheduling error due to restart" + ) } } } + + // reminder: ticker is ready immediatedly + let mut ticker = tokio::time::interval(metric_collection_interval); + + loop { + let tick_at = tokio::select! { + _ = cancel.cancelled() => return Ok(()), + tick_at = ticker.tick() => tick_at, + }; + + iteration( + &client, + metric_collection_endpoint, + &cancel, + &mut cached_metrics, + &node_id, + &final_path, + &ctx, + ) + .await; + + crate::tenant::tasks::warn_when_period_overrun( + tick_at.elapsed(), + metric_collection_interval, + "consumption_metrics_collect_metrics", + ); + } } -/// One iteration of metrics collection -/// -/// Gather per-tenant and per-timeline metrics and send them to the `metric_collection_endpoint`. -/// Cache metrics to avoid sending the same metrics multiple times. -/// -/// This function handles all errors internally -/// and doesn't break iteration if just one tenant fails. -/// -/// TODO -/// - refactor this function (chunking+sending part) to reuse it in proxy module; -async fn collect_metrics_iteration( +async fn iteration( client: &reqwest::Client, - cached_metrics: &mut Cache, metric_collection_endpoint: &reqwest::Url, - node_id: NodeId, + cancel: &CancellationToken, + cached_metrics: &mut Cache, + node_id: &str, + final_path: &Arc, ctx: &RequestContext, ) { - trace!( - "starting collect_metrics_iteration. metric_collection_endpoint: {}", - metric_collection_endpoint - ); + // these are point in time, with variable "now" + let metrics = collect_all_metrics(cached_metrics, ctx).await; + + if metrics.is_empty() { + return; + } + + let metrics = Arc::new(metrics); + + let flush = async { + match flush_metrics_to_disk(&metrics, final_path).await { + Ok(()) => { + tracing::debug!("flushed metrics to disk"); + } + Err(e) => { + // idea here is that if someone creates a directory as our final_path, then they + // might notice it from the logs before shutdown and remove it + tracing::error!("failed to persist metrics to {final_path:?}: {e:#}"); + } + } + }; + + let upload = async { + let res = upload_metrics( + client, + metric_collection_endpoint, + cancel, + node_id, + &metrics, + cached_metrics, + ) + .await; + if let Err(e) = res { + // serialization error which should never happen + tracing::error!("failed to upload due to {e:#}"); + } + }; + + // let these run concurrently + let (_, _) = tokio::join!(flush, upload); +} + +async fn collect_all_metrics(cached_metrics: &Cache, ctx: &RequestContext) -> Vec { + let started_at = std::time::Instant::now(); - // get list of tenants let tenants = match mgr::list_tenants().await { Ok(tenants) => tenants, Err(err) => { error!("failed to list tenants: {:?}", err); - return; + return vec![]; } }; @@ -321,85 +453,29 @@ async fn collect_metrics_iteration( } }); - let current_metrics = collect(tenants, cached_metrics, ctx).await; + let res = collect(tenants, cached_metrics, ctx).await; - if current_metrics.is_empty() { - trace!("no new metrics to send"); - return; - } + tracing::info!( + elapsed_ms = started_at.elapsed().as_millis(), + total = res.len(), + "collected metrics" + ); - let cancel = task_mgr::shutdown_token(); - - // Send metrics. - // Split into chunks of 1000 metrics to avoid exceeding the max request size - let chunks = current_metrics.chunks(CHUNK_SIZE); - - let mut chunk_to_send: Vec> = Vec::with_capacity(CHUNK_SIZE); - - let node_id = node_id.to_string(); - - let mut buffer = bytes::BytesMut::new(); - - for chunk in chunks { - chunk_to_send.clear(); - - // enrich metrics with type,timestamp and idempotency key before sending - chunk_to_send.extend(chunk.iter().map(|(curr_key, (when, curr_val))| Event { - kind: *when, - metric: curr_key.metric, - idempotency_key: idempotency_key(&node_id), - value: *curr_val, - extra: Ids { - tenant_id: curr_key.tenant_id, - timeline_id: curr_key.timeline_id, - }, - })); - - use bytes::BufMut; - - // FIXME: this is a new panic we did not have before. not really essential, but panics from - // this task currently restart pageserver. - serde_json::to_writer( - (&mut buffer).writer(), - &EventChunk { - events: (&chunk_to_send).into(), - }, - ) - .expect("serialization must not fail and bytesmut grows"); - - let body = buffer.split().freeze(); - - let res = upload(client, metric_collection_endpoint, body, &cancel).await; - - if res.is_ok() { - for (curr_key, curr_val) in chunk.iter() { - cached_metrics.insert(curr_key.clone(), *curr_val); - } - } else { - // no need to log, backoff::retry and upload have done it, just give up uploading. - } - } + res } -async fn collect( - tenants: S, - cache: &HashMap, - ctx: &RequestContext, -) -> Vec<(MetricsKey, (EventType, u64))> +async fn collect(tenants: S, cache: &Cache, ctx: &RequestContext) -> Vec where S: futures::stream::Stream)>, { - let mut current_metrics: Vec<(MetricsKey, (EventType, u64))> = Vec::new(); + let mut current_metrics: Vec = Vec::new(); let mut tenants = std::pin::pin!(tenants); while let Some((tenant_id, tenant)) = tenants.next().await { let mut tenant_resident_size = 0; - // iterate through list of timelines in tenant for timeline in tenant.list_timelines() { - // collect per-timeline metrics only for active timelines - let timeline_id = timeline.timeline_id; match TimelineSnapshot::collect(&timeline, ctx) { @@ -425,16 +501,158 @@ where tenant_resident_size += timeline.resident_physical_size(); } - TenantSnapshot::collect(&tenant, tenant_resident_size).to_metrics( - tenant_id, - Utc::now(), - &mut current_metrics, - ); + let snap = TenantSnapshot::collect(&tenant, tenant_resident_size); + snap.to_metrics(tenant_id, Utc::now(), cache, &mut current_metrics); } current_metrics } +async fn flush_metrics_to_disk( + current_metrics: &Arc>, + final_path: &Arc, +) -> anyhow::Result<()> { + use std::io::Write; + + anyhow::ensure!( + final_path.parent().is_some(), + "path must have parent: {final_path:?}" + ); + + let span = tracing::Span::current(); + tokio::task::spawn_blocking({ + let current_metrics = current_metrics.clone(); + let final_path = final_path.clone(); + move || { + let _e = span.entered(); + + let mut tempfile = + tempfile::NamedTempFile::new_in(final_path.parent().expect("existence checked"))?; + + // write out all of the raw metrics, to be read out later on restart as cached values + { + let mut writer = std::io::BufWriter::new(&mut tempfile); + serde_json::to_writer(&mut writer, &*current_metrics) + .context("serialize metrics")?; + writer + .into_inner() + .map_err(|_| anyhow::anyhow!("flushing metrics failed"))?; + } + + tempfile.flush()?; + tempfile.as_file().sync_all()?; + + drop(tempfile.persist(&*final_path)?); + + let f = std::fs::File::open(final_path.parent().unwrap())?; + f.sync_all()?; + + anyhow::Ok(()) + } + }) + .await + .with_context(|| format!("write metrics to {final_path:?} join error")) + .and_then(|x| x.with_context(|| format!("write metrics to {final_path:?}"))) +} + +async fn read_metrics_from_disk(path: Arc) -> anyhow::Result> { + // do not add context to each error, callsite will log with full path + let span = tracing::Span::current(); + tokio::task::spawn_blocking(move || { + let _e = span.entered(); + let mut file = std::fs::File::open(&*path)?; + let reader = std::io::BufReader::new(&mut file); + anyhow::Ok(serde_json::from_reader::<_, Vec>(reader)?) + }) + .await + .context("read metrics join error") + .and_then(|x| x) +} + +#[tracing::instrument(skip_all, fields(metrics_total = %metrics.len()))] +async fn upload_metrics( + client: &reqwest::Client, + metric_collection_endpoint: &reqwest::Url, + cancel: &CancellationToken, + node_id: &str, + metrics: &[RawMetric], + cached_metrics: &mut Cache, +) -> anyhow::Result<()> { + use bytes::BufMut; + + let mut uploaded = 0; + let mut failed = 0; + + let started_at = std::time::Instant::now(); + + // write to a BytesMut so that we can cheaply clone the frozen Bytes for retries + let mut buffer = bytes::BytesMut::new(); + let mut chunk_to_send = Vec::new(); + + for chunk in metrics.chunks(CHUNK_SIZE) { + chunk_to_send.clear(); + + // FIXME: this should always overwrite and truncate to chunk.len() + chunk_to_send.extend(chunk.iter().map(|(curr_key, (when, curr_val))| Event { + kind: *when, + metric: curr_key.metric, + // FIXME: finally write! this to the prev allocation + idempotency_key: idempotency_key(node_id), + value: *curr_val, + extra: Ids { + tenant_id: curr_key.tenant_id, + timeline_id: curr_key.timeline_id, + }, + })); + + serde_json::to_writer( + (&mut buffer).writer(), + &EventChunk { + events: (&chunk_to_send).into(), + }, + )?; + + let body = buffer.split().freeze(); + let event_bytes = body.len(); + + let res = upload(client, metric_collection_endpoint, body, cancel) + .instrument(tracing::info_span!( + "upload", + %event_bytes, + uploaded, + total = metrics.len(), + )) + .await; + + match res { + Ok(()) => { + for (curr_key, curr_val) in chunk { + cached_metrics.insert(*curr_key, *curr_val); + } + uploaded += chunk.len(); + } + Err(_) => { + // failure(s) have already been logged + // + // however this is an inconsistency: if we crash here, we will start with the + // values as uploaded. in practice, the rejections no longer happen. + failed += chunk.len(); + } + } + } + + let elapsed = started_at.elapsed(); + + tracing::info!( + uploaded, + failed, + elapsed_ms = elapsed.as_millis(), + "done sending metrics" + ); + + Ok(()) +} + enum UploadError { Rejected(reqwest::StatusCode), Reqwest(reqwest::Error), @@ -545,16 +763,34 @@ impl TenantSnapshot { } } - fn to_metrics(&self, tenant_id: TenantId, now: DateTime, metrics: &mut Vec) { + fn to_metrics( + &self, + tenant_id: TenantId, + now: DateTime, + cached: &Cache, + metrics: &mut Vec, + ) { let remote_size = MetricsKey::remote_storage_size(tenant_id).at(now, self.remote_size); let resident_size = MetricsKey::resident_size(tenant_id).at(now, self.resident_size); - let synthetic_size = if self.synthetic_size != 0 { - // only send non-zeroes because otherwise these show up as errors in logs - Some(MetricsKey::synthetic_size(tenant_id).at(now, self.synthetic_size)) - } else { - None + let synthetic_size = { + let factory = MetricsKey::synthetic_size(tenant_id); + let mut synthetic_size = self.synthetic_size; + + if synthetic_size == 0 { + if let Some((_, value)) = cached.get(factory.key()) { + // use the latest value from previous session + synthetic_size = *value; + } + } + + if synthetic_size != 0 { + // only send non-zeroes because otherwise these show up as errors in logs + Some(factory.at(now, synthetic_size)) + } else { + None + } }; metrics.extend( @@ -585,8 +821,6 @@ impl TimelineSnapshot { t: &Arc, ctx: &RequestContext, ) -> anyhow::Result> { - use anyhow::Context; - if !t.is_active() { // no collection for broken or stopping needed, we will still keep the cached values // though at the caller. @@ -660,25 +894,30 @@ impl TimelineSnapshot { (DateTime::from(*loaded_at), disk_consistent_lsn.0) }); - // written_size_bytes_delta - metrics.extend( - if let Some(delta) = written_size_now.1.checked_sub(prev.1) { - let up_to = written_size_now - .0 - .absolute_time() - .expect("never create EventType::Incremental for written_size"); - let key_value = written_size_delta_key.from_previous_up_to(prev.0, *up_to, delta); - Some(key_value) - } else { - None - }, - ); + let up_to = now; - // written_size - metrics.push((key, written_size_now)); + if let Some(delta) = written_size_now.1.checked_sub(prev.1) { + let key_value = written_size_delta_key.from_previous_up_to(prev.0, up_to, delta); + // written_size_delta + metrics.push(key_value); + // written_size + metrics.push((key, written_size_now)); + } else { + // the cached value was ahead of us, report zero until we've caught up + metrics.push(written_size_delta_key.from_previous_up_to(prev.0, up_to, 0)); + // the cached value was ahead of us, report the same until we've caught up + metrics.push((key, (written_size_now.0, prev.1))); + } - if let Some(size) = self.current_exact_logical_size { - metrics.push(MetricsKey::timeline_logical_size(tenant_id, timeline_id).at(now, size)); + { + let factory = MetricsKey::timeline_logical_size(tenant_id, timeline_id); + let current_or_previous = self + .current_exact_logical_size + .or_else(|| cache.get(factory.key()).map(|(_, val)| *val)); + + if let Some(size) = current_or_previous { + metrics.push(factory.at(now, size)); + } } } } @@ -738,9 +977,7 @@ mod tests { lsn::Lsn, }; - use crate::consumption_metrics::MetricsKey; - - use super::TimelineSnapshot; + use super::*; use chrono::{DateTime, Utc}; #[test] @@ -927,6 +1164,164 @@ mod tests { } } + #[test] + fn post_restart_written_sizes_with_rolled_back_last_record_lsn() { + // it can happen that we lose the inmemorylayer but have previously sent metrics and we + // should never go backwards + + let tenant_id = TenantId::generate(); + let timeline_id = TimelineId::generate(); + + let [later, now, at_restart] = time_backwards(); + + // FIXME: tests would be so much easier if we did not need to juggle back and forth + // SystemTime and DateTime:: ... Could do the conversion only at upload time? + let now = DateTime::::from(now); + let later = DateTime::::from(later); + let before_restart = at_restart - std::time::Duration::from_secs(5 * 60); + let way_before = before_restart - std::time::Duration::from_secs(10 * 60); + let before_restart = DateTime::::from(before_restart); + let way_before = DateTime::::from(way_before); + + let snap = TimelineSnapshot { + loaded_at: (Lsn(50), at_restart), + last_record_lsn: Lsn(50), + current_exact_logical_size: None, + }; + + let mut cache = HashMap::from([ + MetricsKey::written_size(tenant_id, timeline_id).at(before_restart, 100), + MetricsKey::written_size_delta(tenant_id, timeline_id).from_previous_up_to( + way_before, + before_restart, + // not taken into account, but the timestamps are important + 999_999_999, + ), + ]); + + let mut metrics = Vec::new(); + snap.to_metrics(tenant_id, timeline_id, now, &mut metrics, &cache); + + assert_eq!( + metrics, + &[ + MetricsKey::written_size_delta(tenant_id, timeline_id).from_previous_up_to( + before_restart, + now, + 0 + ), + MetricsKey::written_size(tenant_id, timeline_id).at(now, 100), + ] + ); + + // now if we cache these metrics, and re-run while "still in recovery" + cache.extend(metrics.drain(..)); + + // "still in recovery", because our snapshot did not change + snap.to_metrics(tenant_id, timeline_id, later, &mut metrics, &cache); + + assert_eq!( + metrics, + &[ + MetricsKey::written_size_delta(tenant_id, timeline_id) + .from_previous_up_to(now, later, 0), + MetricsKey::written_size(tenant_id, timeline_id).at(later, 100), + ] + ); + } + + #[test] + fn post_restart_current_exact_logical_size_uses_cached() { + let tenant_id = TenantId::generate(); + let timeline_id = TimelineId::generate(); + + let [now, at_restart] = time_backwards(); + + let now = DateTime::::from(now); + let before_restart = at_restart - std::time::Duration::from_secs(5 * 60); + let before_restart = DateTime::::from(before_restart); + + let snap = TimelineSnapshot { + loaded_at: (Lsn(50), at_restart), + last_record_lsn: Lsn(50), + current_exact_logical_size: None, + }; + + let cache = HashMap::from([ + MetricsKey::timeline_logical_size(tenant_id, timeline_id).at(before_restart, 100) + ]); + + let mut metrics = Vec::new(); + snap.to_metrics(tenant_id, timeline_id, now, &mut metrics, &cache); + + metrics.retain(|(key, _)| key.metric == Name::LogicalSize); + + assert_eq!( + metrics, + &[MetricsKey::timeline_logical_size(tenant_id, timeline_id).at(now, 100)] + ); + } + + #[test] + fn post_restart_synthetic_size_uses_cached_if_available() { + let tenant_id = TenantId::generate(); + + let ts = TenantSnapshot { + resident_size: 1000, + remote_size: 1000, + // not yet calculated + synthetic_size: 0, + }; + + let now = SystemTime::now(); + let before_restart = DateTime::::from(now - std::time::Duration::from_secs(5 * 60)); + let now = DateTime::::from(now); + + let cached = + HashMap::from([MetricsKey::synthetic_size(tenant_id).at(before_restart, 1000)]); + + let mut metrics = Vec::new(); + ts.to_metrics(tenant_id, now, &cached, &mut metrics); + + assert_eq!( + metrics, + &[ + MetricsKey::remote_storage_size(tenant_id).at(now, 1000), + MetricsKey::resident_size(tenant_id).at(now, 1000), + MetricsKey::synthetic_size(tenant_id).at(now, 1000), + ] + ); + } + + #[test] + fn post_restart_synthetic_size_is_not_sent_when_not_cached() { + let tenant_id = TenantId::generate(); + + let ts = TenantSnapshot { + resident_size: 1000, + remote_size: 1000, + // not yet calculated + synthetic_size: 0, + }; + + let now = SystemTime::now(); + let now = DateTime::::from(now); + + let cached = HashMap::new(); + + let mut metrics = Vec::new(); + ts.to_metrics(tenant_id, now, &cached, &mut metrics); + + assert_eq!( + metrics, + &[ + MetricsKey::remote_storage_size(tenant_id).at(now, 1000), + MetricsKey::resident_size(tenant_id).at(now, 1000), + // no synthetic size here + ] + ); + } + fn time_backwards() -> [std::time::SystemTime; N] { let mut times = [std::time::SystemTime::UNIX_EPOCH; N]; times[0] = std::time::SystemTime::now(); diff --git a/test_runner/regress/test_metric_collection.py b/test_runner/regress/test_metric_collection.py index 821c2ae683..4c4c7b96fe 100644 --- a/test_runner/regress/test_metric_collection.py +++ b/test_runner/regress/test_metric_collection.py @@ -3,9 +3,11 @@ # Use mock HTTP server to receive metrics and verify that they look sane. # +import json +import time from pathlib import Path from queue import SimpleQueue -from typing import Any, Iterator, Set +from typing import Any, Dict, Iterator, Set import pytest from fixtures.log_helper import log @@ -18,6 +20,7 @@ from fixtures.neon_fixtures import ( ) from fixtures.port_distributor import PortDistributor from fixtures.remote_storage import RemoteStorageKind +from fixtures.types import TenantId, TimelineId from pytest_httpserver import HTTPServer from werkzeug.wrappers.request import Request from werkzeug.wrappers.response import Response @@ -35,8 +38,6 @@ def test_metric_collection( (host, port) = httpserver_listen_address metric_collection_endpoint = f"http://{host}:{port}/billing/api/v1/usage_events" - metric_kinds_checked: Set[str] = set([]) - uploads: SimpleQueue[Any] = SimpleQueue() def metrics_handler(request: Request) -> Response: @@ -57,6 +58,7 @@ def test_metric_collection( metric_collection_interval="1s" metric_collection_endpoint="{metric_collection_endpoint}" cached_metric_collection_interval="0s" + synthetic_size_calculation_interval="3s" """ + "tenant_config={pitr_interval = '0 sec'}" ) @@ -75,8 +77,8 @@ def test_metric_collection( # httpserver is shut down before pageserver during passing run env.pageserver.allowed_errors.append(".*metrics endpoint refused the sent metrics*") tenant_id = env.initial_tenant - timeline_id = env.neon_cli.create_branch("test_metric_collection") - endpoint = env.endpoints.create_start("test_metric_collection") + timeline_id = env.initial_timeline + endpoint = env.endpoints.create_start("main", tenant_id=tenant_id) pg_conn = endpoint.connect() cur = pg_conn.cursor() @@ -118,60 +120,227 @@ def test_metric_collection( # we expect uploads at 1Hz, on busy runners this could be too optimistic, # so give 5s we only want to get the following upload after "ready" value. - # later tests will be added to ensure that the timeseries are sane. timeout = 5 + + # these strings in the upload queue allow synchronizing with the uploads + # and the main test execution uploads.put("ready") + # note that this verifier graph should live across restarts as long as the + # cache file lives + v = MetricsVerifier() + while True: - # discard earlier than "ready" - log.info("waiting for upload") events = uploads.get(timeout=timeout) - import json if events == "ready": events = uploads.get(timeout=timeout) - httpserver.check() - httpserver.stop() - # if anything comes after this, we'll just ignore it - stringified = json.dumps(events, indent=2) - log.info(f"inspecting: {stringified}") + v.ingest(events) break else: - stringified = json.dumps(events, indent=2) - log.info(f"discarding: {stringified}") + v.ingest(events) - # verify that metrics look minimally sane - checks = { - "written_size": lambda value: value > 0, - "resident_size": lambda value: value >= 0, - "remote_storage_size": lambda value: value > 0 if remote_uploaded > 0 else value == 0, - # logical size may lag behind the actual size, so allow 0 here - "timeline_logical_size": lambda value: value >= 0, - # this can also be zero, depending on when we get the value - "written_data_bytes_delta": lambda value: value >= 0, - } + if "synthetic_storage_size" not in v.accepted_event_names(): + log.info("waiting for synthetic storage size to be calculated and uploaded...") - metric_kinds_checked = set() - metric_kinds_seen = set() + rounds = 0 + while "synthetic_storage_size" not in v.accepted_event_names(): + events = uploads.get(timeout=timeout) + v.ingest(events) + rounds += 1 + assert rounds < 10, "did not get synthetic_storage_size in 10 uploads" + # once we have it in verifiers, it will assert that future batches will contain it - for event in events: - assert event["tenant_id"] == str(tenant_id) - metric_name = event["metric"] - metric_kinds_seen.add(metric_name) + env.pageserver.stop() + time.sleep(1) + uploads.put("ready") + env.pageserver.start() - check = checks.get(metric_name) - # calm down mypy - if check is not None: - value = event["value"] - log.info(f"checking {metric_name} value {value}") - assert check(value), f"{metric_name} isn't valid" - metric_kinds_checked.add(metric_name) + while True: + events = uploads.get(timeout=timeout) - expected_checks = set(checks.keys()) - assert ( - metric_kinds_checked == checks.keys() - ), f"Expected to receive and check all kind of metrics, but {expected_checks - metric_kinds_checked} got uncovered" - assert metric_kinds_seen == metric_kinds_checked + if events == "ready": + events = uploads.get(timeout=timeout * 3) + v.ingest(events) + events = uploads.get(timeout=timeout) + v.ingest(events) + break + else: + v.ingest(events) + + httpserver.check() + + +class MetricsVerifier: + """ + A graph of per tenant per timeline verifiers, allowing one for each + metric + """ + + def __init__(self): + self.tenants: Dict[TenantId, TenantMetricsVerifier] = {} + pass + + def ingest(self, events): + stringified = json.dumps(events, indent=2) + log.info(f"ingesting: {stringified}") + for event in events: + id = TenantId(event["tenant_id"]) + if id not in self.tenants: + self.tenants[id] = TenantMetricsVerifier(id) + + self.tenants[id].ingest(event) + + for t in self.tenants.values(): + t.post_batch() + + def accepted_event_names(self) -> Set[str]: + names: Set[str] = set() + for t in self.tenants.values(): + names = names.union(t.accepted_event_names()) + return names + + +class TenantMetricsVerifier: + def __init__(self, id: TenantId): + self.id = id + self.timelines: Dict[TimelineId, TimelineMetricsVerifier] = {} + self.state: Dict[str, Any] = {} + + def ingest(self, event): + assert TenantId(event["tenant_id"]) == self.id + + if "timeline_id" in event: + id = TimelineId(event["timeline_id"]) + if id not in self.timelines: + self.timelines[id] = TimelineMetricsVerifier(self.id, id) + + self.timelines[id].ingest(event) + else: + name = event["metric"] + if name not in self.state: + self.state[name] = PER_METRIC_VERIFIERS[name]() + self.state[name].ingest(event, self) + + def post_batch(self): + for v in self.state.values(): + v.post_batch(self) + + for tl in self.timelines.values(): + tl.post_batch(self) + + def accepted_event_names(self) -> Set[str]: + names = set(self.state.keys()) + for t in self.timelines.values(): + names = names.union(t.accepted_event_names()) + return names + + +class TimelineMetricsVerifier: + def __init__(self, tenant_id: TenantId, timeline_id: TimelineId): + self.id = timeline_id + self.state: Dict[str, Any] = {} + + def ingest(self, event): + name = event["metric"] + if name not in self.state: + self.state[name] = PER_METRIC_VERIFIERS[name]() + self.state[name].ingest(event, self) + + def post_batch(self, parent): + for v in self.state.values(): + v.post_batch(self) + + def accepted_event_names(self) -> Set[str]: + return set(self.state.keys()) + + +class CannotVerifyAnything: + """We can only assert types, but rust already has types, so no need.""" + + def __init__(self): + pass + + def ingest(self, event, parent): + pass + + def post_batch(self, parent): + pass + + +class WrittenDataVerifier: + def __init__(self): + self.values = [] + pass + + def ingest(self, event, parent): + self.values.append(event["value"]) + + def post_batch(self, parent): + pass + + +class WrittenDataDeltaVerifier: + def __init__(self): + self.value = None + self.sum = 0 + self.timerange = None + pass + + def ingest(self, event, parent): + assert event["type"] == "incremental" + self.value = event["value"] + self.sum += event["value"] + start = event["start_time"] + stop = event["stop_time"] + timerange = (start, stop) + if self.timerange is not None: + # this holds across restarts + assert self.timerange[1] == timerange[0], "time ranges should be continious" + self.timerange = timerange + + def post_batch(self, parent): + absolute = parent.state["written_size"] + if len(absolute.values) == 1: + # in tests this comes up as initdb execution, so we can have 0 or + # about 30MB on the first event. it is not consistent. + assert self.value is not None + else: + assert self.value == absolute.values[-1] - absolute.values[-2] + # sounds like this should hold, but it will not for branches -- probably related to timing + # assert self.sum == absolute.latest + + +class SyntheticSizeVerifier: + def __init__(self): + self.prev = None + self.value = None + pass + + def ingest(self, event, parent): + assert isinstance(parent, TenantMetricsVerifier) + assert event["type"] == "absolute" + value = event["value"] + self.value = value + + def post_batch(self, parent): + if self.prev is not None: + # this is assuming no one goes and deletes the cache file + assert ( + self.value is not None + ), "after calculating first synthetic size, cached or more recent should be sent" + self.prev = self.value + self.value = None + + +PER_METRIC_VERIFIERS = { + "remote_storage_size": CannotVerifyAnything, + "resident_size": CannotVerifyAnything, + "written_size": WrittenDataVerifier, + "written_data_bytes_delta": WrittenDataDeltaVerifier, + "timeline_logical_size": CannotVerifyAnything, + "synthetic_storage_size": SyntheticSizeVerifier, +} def proxy_metrics_handler(request: Request) -> Response: From 74d99b5883f690b827b139b3d0b11edaa1e43774 Mon Sep 17 00:00:00 2001 From: Joonas Koivunen Date: Sat, 16 Sep 2023 18:05:35 +0300 Subject: [PATCH 13/22] refactor(test_consumption_metrics): split for pageserver and proxy (#5324) With the addition of the "stateful event verification" the test_consumption_metrics.py is now too crowded. Split it up for pageserver and proxy. Split from #5297. --- ...y => test_pageserver_metric_collection.py} | 111 +---------------- .../regress/test_proxy_metric_collection.py | 113 ++++++++++++++++++ 2 files changed, 114 insertions(+), 110 deletions(-) rename test_runner/regress/{test_metric_collection.py => test_pageserver_metric_collection.py} (73%) create mode 100644 test_runner/regress/test_proxy_metric_collection.py diff --git a/test_runner/regress/test_metric_collection.py b/test_runner/regress/test_pageserver_metric_collection.py similarity index 73% rename from test_runner/regress/test_metric_collection.py rename to test_runner/regress/test_pageserver_metric_collection.py index 4c4c7b96fe..eb9b295479 100644 --- a/test_runner/regress/test_metric_collection.py +++ b/test_runner/regress/test_pageserver_metric_collection.py @@ -1,24 +1,14 @@ -# -# Test for collecting metrics from pageserver and proxy. -# Use mock HTTP server to receive metrics and verify that they look sane. -# - import json import time -from pathlib import Path from queue import SimpleQueue -from typing import Any, Dict, Iterator, Set +from typing import Any, Dict, Set import pytest from fixtures.log_helper import log from fixtures.neon_fixtures import ( - PSQL, NeonEnvBuilder, - NeonProxy, - VanillaPostgres, wait_for_last_flush_lsn, ) -from fixtures.port_distributor import PortDistributor from fixtures.remote_storage import RemoteStorageKind from fixtures.types import TenantId, TimelineId from pytest_httpserver import HTTPServer @@ -341,102 +331,3 @@ PER_METRIC_VERIFIERS = { "timeline_logical_size": CannotVerifyAnything, "synthetic_storage_size": SyntheticSizeVerifier, } - - -def proxy_metrics_handler(request: Request) -> Response: - if request.json is None: - return Response(status=400) - - events = request.json["events"] - log.info("received events:") - log.info(events) - - # perform basic sanity checks - for event in events: - assert event["metric"] == "proxy_io_bytes_per_client" - assert event["endpoint_id"] == "test_endpoint_id" - assert event["value"] >= 0 - assert event["stop_time"] >= event["start_time"] - - return Response(status=200) - - -@pytest.fixture(scope="function") -def proxy_with_metric_collector( - port_distributor: PortDistributor, - neon_binpath: Path, - httpserver_listen_address, - test_output_dir: Path, -) -> Iterator[NeonProxy]: - """Neon proxy that routes through link auth and has metric collection enabled.""" - - http_port = port_distributor.get_port() - proxy_port = port_distributor.get_port() - mgmt_port = port_distributor.get_port() - external_http_port = port_distributor.get_port() - - (host, port) = httpserver_listen_address - metric_collection_endpoint = f"http://{host}:{port}/billing/api/v1/usage_events" - metric_collection_interval = "5s" - - with NeonProxy( - neon_binpath=neon_binpath, - test_output_dir=test_output_dir, - proxy_port=proxy_port, - http_port=http_port, - mgmt_port=mgmt_port, - external_http_port=external_http_port, - metric_collection_endpoint=metric_collection_endpoint, - metric_collection_interval=metric_collection_interval, - auth_backend=NeonProxy.Link(), - ) as proxy: - proxy.start() - yield proxy - - -@pytest.mark.asyncio -async def test_proxy_metric_collection( - httpserver: HTTPServer, - proxy_with_metric_collector: NeonProxy, - vanilla_pg: VanillaPostgres, -): - # mock http server that returns OK for the metrics - httpserver.expect_request("/billing/api/v1/usage_events", method="POST").respond_with_handler( - proxy_metrics_handler - ) - - # do something to generate load to generate metrics - # sleep for 5 seconds to give metric collector time to collect metrics - psql = await PSQL( - host=proxy_with_metric_collector.host, port=proxy_with_metric_collector.proxy_port - ).run( - "create table tbl as select * from generate_series(0,1000); select pg_sleep(5); select 42" - ) - - base_uri = proxy_with_metric_collector.link_auth_uri - link = await NeonProxy.find_auth_link(base_uri, psql) - - psql_session_id = NeonProxy.get_session_id(base_uri, link) - await NeonProxy.activate_link_auth(vanilla_pg, proxy_with_metric_collector, psql_session_id) - - assert psql.stdout is not None - out = (await psql.stdout.read()).decode("utf-8").strip() - assert out == "42" - - # do something to generate load to generate metrics - # sleep for 5 seconds to give metric collector time to collect metrics - psql = await PSQL( - host=proxy_with_metric_collector.host, port=proxy_with_metric_collector.proxy_port - ).run("insert into tbl select * from generate_series(0,1000); select pg_sleep(5); select 42") - - link = await NeonProxy.find_auth_link(base_uri, psql) - psql_session_id = NeonProxy.get_session_id(base_uri, link) - await NeonProxy.activate_link_auth( - vanilla_pg, proxy_with_metric_collector, psql_session_id, create_user=False - ) - - assert psql.stdout is not None - out = (await psql.stdout.read()).decode("utf-8").strip() - assert out == "42" - - httpserver.check() diff --git a/test_runner/regress/test_proxy_metric_collection.py b/test_runner/regress/test_proxy_metric_collection.py new file mode 100644 index 0000000000..f57b47f4da --- /dev/null +++ b/test_runner/regress/test_proxy_metric_collection.py @@ -0,0 +1,113 @@ +from pathlib import Path +from typing import Iterator + +import pytest +from fixtures.log_helper import log +from fixtures.neon_fixtures import ( + PSQL, + NeonProxy, + VanillaPostgres, +) +from fixtures.port_distributor import PortDistributor +from pytest_httpserver import HTTPServer +from werkzeug.wrappers.request import Request +from werkzeug.wrappers.response import Response + + +def proxy_metrics_handler(request: Request) -> Response: + if request.json is None: + return Response(status=400) + + events = request.json["events"] + log.info("received events:") + log.info(events) + + # perform basic sanity checks + for event in events: + assert event["metric"] == "proxy_io_bytes_per_client" + assert event["endpoint_id"] == "test_endpoint_id" + assert event["value"] >= 0 + assert event["stop_time"] >= event["start_time"] + + return Response(status=200) + + +@pytest.fixture(scope="function") +def proxy_with_metric_collector( + port_distributor: PortDistributor, + neon_binpath: Path, + httpserver_listen_address, + test_output_dir: Path, +) -> Iterator[NeonProxy]: + """Neon proxy that routes through link auth and has metric collection enabled.""" + + http_port = port_distributor.get_port() + proxy_port = port_distributor.get_port() + mgmt_port = port_distributor.get_port() + external_http_port = port_distributor.get_port() + + (host, port) = httpserver_listen_address + metric_collection_endpoint = f"http://{host}:{port}/billing/api/v1/usage_events" + metric_collection_interval = "5s" + + with NeonProxy( + neon_binpath=neon_binpath, + test_output_dir=test_output_dir, + proxy_port=proxy_port, + http_port=http_port, + mgmt_port=mgmt_port, + external_http_port=external_http_port, + metric_collection_endpoint=metric_collection_endpoint, + metric_collection_interval=metric_collection_interval, + auth_backend=NeonProxy.Link(), + ) as proxy: + proxy.start() + yield proxy + + +@pytest.mark.asyncio +async def test_proxy_metric_collection( + httpserver: HTTPServer, + proxy_with_metric_collector: NeonProxy, + vanilla_pg: VanillaPostgres, +): + # mock http server that returns OK for the metrics + httpserver.expect_request("/billing/api/v1/usage_events", method="POST").respond_with_handler( + proxy_metrics_handler + ) + + # do something to generate load to generate metrics + # sleep for 5 seconds to give metric collector time to collect metrics + psql = await PSQL( + host=proxy_with_metric_collector.host, port=proxy_with_metric_collector.proxy_port + ).run( + "create table tbl as select * from generate_series(0,1000); select pg_sleep(5); select 42" + ) + + base_uri = proxy_with_metric_collector.link_auth_uri + link = await NeonProxy.find_auth_link(base_uri, psql) + + psql_session_id = NeonProxy.get_session_id(base_uri, link) + await NeonProxy.activate_link_auth(vanilla_pg, proxy_with_metric_collector, psql_session_id) + + assert psql.stdout is not None + out = (await psql.stdout.read()).decode("utf-8").strip() + assert out == "42" + + # do something to generate load to generate metrics + # sleep for 5 seconds to give metric collector time to collect metrics + psql = await PSQL( + host=proxy_with_metric_collector.host, port=proxy_with_metric_collector.proxy_port + ).run("insert into tbl select * from generate_series(0,1000); select pg_sleep(5); select 42") + + link = await NeonProxy.find_auth_link(base_uri, psql) + psql_session_id = NeonProxy.get_session_id(base_uri, link) + await NeonProxy.activate_link_auth( + vanilla_pg, proxy_with_metric_collector, psql_session_id, create_user=False + ) + + assert psql.stdout is not None + out = (await psql.stdout.read()).decode("utf-8").strip() + assert out == "42" + + httpserver.check() From 9cf4ae86ff23da718c5bcc56a4ca14095d3c3048 Mon Sep 17 00:00:00 2001 From: Joonas Koivunen Date: Sat, 16 Sep 2023 18:08:33 +0300 Subject: [PATCH 14/22] refactor(consumption_metrics): pre-split cleanup (#5325) Cleanups in preparation to splitting the consumption_metrics.rs in #5326. Split off from #5297. --- pageserver/src/consumption_metrics.rs | 269 +++++++++++++------------- 1 file changed, 133 insertions(+), 136 deletions(-) diff --git a/pageserver/src/consumption_metrics.rs b/pageserver/src/consumption_metrics.rs index 065f74045a..3e7b8f62c7 100644 --- a/pageserver/src/consumption_metrics.rs +++ b/pageserver/src/consumption_metrics.rs @@ -1,8 +1,5 @@ -//! //! Periodically collect consumption metrics for all active tenants //! and push them to a HTTP endpoint. -//! Cache metrics to send only the updated ones. -//! use crate::context::{DownloadBehavior, RequestContext}; use crate::task_mgr::{self, TaskKind, BACKGROUND_RUNTIME}; use crate::tenant::{mgr, LogicalSizeCalculationCause}; @@ -264,6 +261,14 @@ pub async fn collect_metrics( let final_path: Arc = Arc::new(local_disk_storage); + let cancel = task_mgr::shutdown_token(); + let restore_and_reschedule = restore_and_reschedule(&final_path, metric_collection_interval); + + let mut cached_metrics = tokio::select! { + _ = cancel.cancelled() => return Ok(()), + ret = restore_and_reschedule => ret, + }; + // define client here to reuse it for all requests let client = reqwest::ClientBuilder::new() .timeout(DEFAULT_HTTP_REPORTING_TIMEOUT) @@ -271,77 +276,111 @@ pub async fn collect_metrics( .expect("Failed to create http client with timeout"); let node_id = node_id.to_string(); - let cancel = task_mgr::shutdown_token(); - let (mut cached_metrics, oldest_metric_captured_at) = - match read_metrics_from_disk(final_path.clone()).await { - Ok(found_some) => { - // there is no min needed because we write these sequentially in - // collect_all_metrics - let oldest_metric_captured_at = found_some - .iter() - .map(|(_, (et, _))| et.recorded_at()) - .copied() - .next(); + // reminder: ticker is ready immediatedly + let mut ticker = tokio::time::interval(metric_collection_interval); - let cached = found_some - .into_iter() - .collect::>(); + loop { + let tick_at = tokio::select! { + _ = cancel.cancelled() => return Ok(()), + tick_at = ticker.tick() => tick_at, + }; - (cached, oldest_metric_captured_at) - } - Err(e) => { - let root = e.root_cause(); + // these are point in time, with variable "now" + let metrics = collect_all_metrics(&cached_metrics, &ctx).await; - let maybe_ioerr = root.downcast_ref::(); - let is_not_found = - maybe_ioerr.is_some_and(|e| e.kind() == std::io::ErrorKind::NotFound); + if metrics.is_empty() { + continue; + } - if !is_not_found { - tracing::info!( - "failed to read any previous metrics from {final_path:?}: {e:#}" - ); + let metrics = Arc::new(metrics); + + // why not race cancellation here? because we are one of the last tasks, and if we are + // already here, better to try to flush the new values. + + let flush = async { + match flush_metrics_to_disk(&metrics, &final_path).await { + Ok(()) => { + tracing::debug!("flushed metrics to disk"); + } + Err(e) => { + // idea here is that if someone creates a directory as our final_path, then they + // might notice it from the logs before shutdown and remove it + tracing::error!("failed to persist metrics to {final_path:?}: {e:#}"); } - - (HashMap::new(), None) } }; - if let Some(oldest_metric_captured_at) = oldest_metric_captured_at { - // FIXME: chrono methods panic - let oldest_metric_captured_at: SystemTime = oldest_metric_captured_at.into(); - let now = SystemTime::now(); - let error = match now.duration_since(oldest_metric_captured_at) { - Ok(from_last_send) if from_last_send < metric_collection_interval => { - let sleep_for = metric_collection_interval - from_last_send; - - let deadline = std::time::Instant::now() + sleep_for; - - tokio::select! { - _ = cancel.cancelled() => { return Ok(()); }, - _ = tokio::time::sleep_until(deadline.into()) => {}, - } - - let now = std::time::Instant::now(); - - // executor threads might be busy, add extra measurements - Some(if now < deadline { - deadline - now - } else { - now - deadline - }) - } - Ok(from_last_send) => Some(from_last_send.saturating_sub(metric_collection_interval)), - Err(_) => { - tracing::warn!( - ?now, - ?oldest_metric_captured_at, - "oldest recorded metric is in future; first values will come out with inconsistent timestamps" - ); - oldest_metric_captured_at.duration_since(now).ok() + let upload = async { + let res = upload_metrics( + &client, + metric_collection_endpoint, + &cancel, + &node_id, + &metrics, + &mut cached_metrics, + ) + .await; + if let Err(e) = res { + // serialization error which should never happen + tracing::error!("failed to upload due to {e:#}"); } }; + // let these run concurrently + let (_, _) = tokio::join!(flush, upload); + + crate::tenant::tasks::warn_when_period_overrun( + tick_at.elapsed(), + metric_collection_interval, + "consumption_metrics_collect_metrics", + ); + } +} + +/// Called on the first iteration in an attempt to join the metric uploading schedule from previous +/// pageserver session. Pageserver is supposed to upload at intervals regardless of restarts. +/// +/// Cancellation safe. +async fn restore_and_reschedule( + final_path: &Arc, + metric_collection_interval: Duration, +) -> Cache { + let (cached, earlier_metric_at) = match read_metrics_from_disk(final_path.clone()).await { + Ok(found_some) => { + // there is no min needed because we write these sequentially in + // collect_all_metrics + let earlier_metric_at = found_some + .iter() + .map(|(_, (et, _))| et.recorded_at()) + .copied() + .next(); + + let cached = found_some.into_iter().collect::(); + + (cached, earlier_metric_at) + } + Err(e) => { + use std::io::{Error, ErrorKind}; + + let root = e.root_cause(); + + let maybe_ioerr = root.downcast_ref::(); + let is_not_found = maybe_ioerr.is_some_and(|e| e.kind() == ErrorKind::NotFound); + + if !is_not_found { + tracing::info!("failed to read any previous metrics from {final_path:?}: {e:#}"); + } + + (HashMap::new(), None) + } + }; + + if let Some(earlier_metric_at) = earlier_metric_at { + let earlier_metric_at: SystemTime = earlier_metric_at.into(); + + let error = reschedule(earlier_metric_at, metric_collection_interval).await; + if let Some(error) = error { if error.as_secs() >= 60 { tracing::info!( @@ -352,83 +391,41 @@ pub async fn collect_metrics( } } - // reminder: ticker is ready immediatedly - let mut ticker = tokio::time::interval(metric_collection_interval); - - loop { - let tick_at = tokio::select! { - _ = cancel.cancelled() => return Ok(()), - tick_at = ticker.tick() => tick_at, - }; - - iteration( - &client, - metric_collection_endpoint, - &cancel, - &mut cached_metrics, - &node_id, - &final_path, - &ctx, - ) - .await; - - crate::tenant::tasks::warn_when_period_overrun( - tick_at.elapsed(), - metric_collection_interval, - "consumption_metrics_collect_metrics", - ); - } + cached } -async fn iteration( - client: &reqwest::Client, - metric_collection_endpoint: &reqwest::Url, - cancel: &CancellationToken, - cached_metrics: &mut Cache, - node_id: &str, - final_path: &Arc, - ctx: &RequestContext, -) { - // these are point in time, with variable "now" - let metrics = collect_all_metrics(cached_metrics, ctx).await; +async fn reschedule( + earlier_metric_at: SystemTime, + metric_collection_interval: Duration, +) -> Option { + let now = SystemTime::now(); + match now.duration_since(earlier_metric_at) { + Ok(from_last_send) if from_last_send < metric_collection_interval => { + let sleep_for = metric_collection_interval - from_last_send; - if metrics.is_empty() { - return; + let deadline = std::time::Instant::now() + sleep_for; + + tokio::time::sleep_until(deadline.into()).await; + + let now = std::time::Instant::now(); + + // executor threads might be busy, add extra measurements + Some(if now < deadline { + deadline - now + } else { + now - deadline + }) + } + Ok(from_last_send) => Some(from_last_send.saturating_sub(metric_collection_interval)), + Err(_) => { + tracing::warn!( + ?now, + ?earlier_metric_at, + "oldest recorded metric is in future; first values will come out with inconsistent timestamps" + ); + earlier_metric_at.duration_since(now).ok() + } } - - let metrics = Arc::new(metrics); - - let flush = async { - match flush_metrics_to_disk(&metrics, final_path).await { - Ok(()) => { - tracing::debug!("flushed metrics to disk"); - } - Err(e) => { - // idea here is that if someone creates a directory as our final_path, then they - // might notice it from the logs before shutdown and remove it - tracing::error!("failed to persist metrics to {final_path:?}: {e:#}"); - } - } - }; - - let upload = async { - let res = upload_metrics( - client, - metric_collection_endpoint, - cancel, - node_id, - &metrics, - cached_metrics, - ) - .await; - if let Err(e) = res { - // serialization error which should never happen - tracing::error!("failed to upload due to {e:#}"); - } - }; - - // let these run concurrently - let (_, _) = tokio::join!(flush, upload); } async fn collect_all_metrics(cached_metrics: &Cache, ctx: &RequestContext) -> Vec { @@ -929,7 +926,7 @@ async fn calculate_synthetic_size_worker( ) -> anyhow::Result<()> { info!("starting calculate_synthetic_size_worker"); - // reminder: this ticker is ready right away + // reminder: ticker is ready immediatedly let mut ticker = tokio::time::interval(synthetic_size_calculation_interval); let cause = LogicalSizeCalculationCause::ConsumptionMetricsSyntheticSize; From a221ecb0da7aedfdf5a9bb659add500024d29b22 Mon Sep 17 00:00:00 2001 From: Joonas Koivunen Date: Sat, 16 Sep 2023 18:27:19 +0300 Subject: [PATCH 15/22] test: test_download_remote_layers_api again (#5322) The test is still flaky, perhaps more after #5233, see #3831. Do one more `timeline_checkpoint` *after* shutting down safekeepers *before* shutting down pageserver. Put more effort into not compacting or creating image layers. --- test_runner/regress/test_ondemand_download.py | 46 ++++++++----------- 1 file changed, 19 insertions(+), 27 deletions(-) diff --git a/test_runner/regress/test_ondemand_download.py b/test_runner/regress/test_ondemand_download.py index 4041b8aab7..a38a517100 100644 --- a/test_runner/regress/test_ondemand_download.py +++ b/test_runner/regress/test_ondemand_download.py @@ -323,8 +323,8 @@ def test_download_remote_layers_api( "compaction_period": "0s", # small checkpoint distance to create more delta layer files "checkpoint_distance": f"{1 * 1024 ** 2}", # 1 MB - "compaction_threshold": "1", - "image_creation_threshold": "1", + "compaction_threshold": "999999", + "image_creation_threshold": "999999", "compaction_target_size": f"{1 * 1024 ** 2}", # 1 MB } ) @@ -357,8 +357,20 @@ def test_download_remote_layers_api( tenant_id, timeline_id, "pageserver_resident_physical_size" ) + # Shut down safekeepers before starting the pageserver. + # If we don't, they might stream us more WAL. + for sk in env.safekeepers: + sk.stop() + + # it is sad we cannot do a flush inmem layer without compaction, but + # working around with very high layer0 count and image layer creation + # threshold + client.timeline_checkpoint(tenant_id, timeline_id) + + wait_for_upload_queue_empty(client, tenant_id, timeline_id) + filled_current_physical = get_api_current_physical_size() - log.info(filled_current_physical) + log.info(f"filled_current_physical: {filled_current_physical}") filled_size = get_resident_physical_size() log.info(f"filled_size: {filled_size}") assert filled_current_physical == filled_size, "we don't yet do layer eviction" @@ -366,18 +378,10 @@ def test_download_remote_layers_api( env.pageserver.stop() # remove all the layer files - # XXX only delete some of the layer files, to show that it really just downloads all the layers for layer in env.pageserver.tenant_dir().glob("*/timelines/*/*-*_*"): log.info(f"unlinking layer {layer.name}") layer.unlink() - # Shut down safekeepers before starting the pageserver. - # If we don't, the tenant's walreceiver handler will trigger the - # the logical size computation task, and that downloads layes, - # which makes our assertions on size fail. - for sk in env.safekeepers: - sk.stop(immediate=True) - ##### Second start, restore the data and ensure it's the same env.pageserver.start(extra_env_vars={"FAILPOINTS": "remote-storage-download-pre-rename=return"}) env.pageserver.allowed_errors.extend( @@ -391,32 +395,21 @@ def test_download_remote_layers_api( ###### Phase 1: exercise download error code path - # comparison here is requiring the size to be at least the previous size, because it's possible received WAL after last_flush_lsn_upload - # witnessed for example difference of 29827072 (filled_current_physical) to 29868032 (here) is no good reason to fail a test. this_time = get_api_current_physical_size() assert ( - filled_current_physical <= this_time + filled_current_physical == this_time ), "current_physical_size is sum of loaded layer sizes, independent of whether local or remote" - if filled_current_physical != this_time: - log.info( - f"fixing up filled_current_physical from {filled_current_physical} to {this_time} ({this_time - filled_current_physical})" - ) - filled_current_physical = this_time post_unlink_size = get_resident_physical_size() log.info(f"post_unlink_size: {post_unlink_size}") assert ( post_unlink_size < filled_size ), "we just deleted layers and didn't cause anything to re-download them yet" - assert filled_size - post_unlink_size > 5 * ( - 1024**2 - ), "we may be downloading some layers as part of tenant activation" # issue downloads that we know will fail info = client.timeline_download_remote_layers( tenant_id, timeline_id, - # allow some concurrency to unveil potential concurrency bugs max_concurrent_downloads=10, errors_ok=True, at_least_one_download=False, @@ -425,9 +418,9 @@ def test_download_remote_layers_api( assert info["state"] == "Completed" assert info["total_layer_count"] > 0 assert info["successful_download_count"] == 0 - assert ( - info["failed_download_count"] > 0 - ) # can't assert == total_layer_count because attach + tenant status downloads some layers + # can't assert == total_layer_count because timeline_detail also tries to + # download layers for logical size, but this might not always hold. + assert info["failed_download_count"] > 0 assert ( info["total_layer_count"] == info["successful_download_count"] + info["failed_download_count"] @@ -436,7 +429,6 @@ def test_download_remote_layers_api( assert ( get_resident_physical_size() == post_unlink_size ), "didn't download anything new due to failpoint" - # would be nice to assert that the layers in the layer map are still RemoteLayer ##### Retry, this time without failpoints client.configure_failpoints(("remote-storage-download-pre-rename", "off")) From e62ab176b808375b5c0c77de29c2a44ed1a37cf8 Mon Sep 17 00:00:00 2001 From: Joonas Koivunen Date: Sat, 16 Sep 2023 18:45:08 +0300 Subject: [PATCH 16/22] refactor(consumption_metrics): split (#5326) Split off from #5297. Builds upon #5325, should contain only the splitting. Next up: #5327. --- pageserver/src/consumption_metrics.rs | 1070 +---------------- .../src/consumption_metrics/disk_cache.rs | 66 + pageserver/src/consumption_metrics/metrics.rs | 470 ++++++++ .../src/consumption_metrics/metrics/tests.rs | 361 ++++++ pageserver/src/consumption_metrics/upload.rs | 177 +++ 5 files changed, 1086 insertions(+), 1058 deletions(-) create mode 100644 pageserver/src/consumption_metrics/disk_cache.rs create mode 100644 pageserver/src/consumption_metrics/metrics.rs create mode 100644 pageserver/src/consumption_metrics/metrics/tests.rs create mode 100644 pageserver/src/consumption_metrics/upload.rs diff --git a/pageserver/src/consumption_metrics.rs b/pageserver/src/consumption_metrics.rs index 3e7b8f62c7..42af40d02a 100644 --- a/pageserver/src/consumption_metrics.rs +++ b/pageserver/src/consumption_metrics.rs @@ -3,214 +3,23 @@ use crate::context::{DownloadBehavior, RequestContext}; use crate::task_mgr::{self, TaskKind, BACKGROUND_RUNTIME}; use crate::tenant::{mgr, LogicalSizeCalculationCause}; -use chrono::{DateTime, Utc}; -use consumption_metrics::{idempotency_key, Event, EventChunk, EventType, CHUNK_SIZE}; -use futures::stream::StreamExt; +use consumption_metrics::EventType; use pageserver_api::models::TenantState; use reqwest::Url; -use serde::Serialize; -use serde_with::{serde_as, DisplayFromStr}; use std::collections::HashMap; use std::path::PathBuf; use std::sync::Arc; use std::time::{Duration, SystemTime}; -use tokio_util::sync::CancellationToken; use tracing::*; -use utils::id::{NodeId, TenantId, TimelineId}; -use utils::lsn::Lsn; +use utils::id::NodeId; -use anyhow::Context; +mod metrics; +use metrics::{Ids, MetricsKey}; +mod disk_cache; +mod upload; const DEFAULT_HTTP_REPORTING_TIMEOUT: Duration = Duration::from_secs(60); -#[serde_as] -#[derive(Serialize, serde::Deserialize, Debug, Clone, Copy)] -struct Ids { - #[serde_as(as = "DisplayFromStr")] - tenant_id: TenantId, - #[serde_as(as = "Option")] - #[serde(skip_serializing_if = "Option::is_none")] - timeline_id: Option, -} - -/// Name of the metric, used by `MetricsKey` factory methods and `deserialize_cached_events` -/// instead of static str. -// Do not rename any of these without first consulting with data team and partner -// management. -// FIXME: write those tests before refactoring to this! -#[derive(Debug, Clone, Copy, PartialEq, Eq, Hash, serde::Serialize, serde::Deserialize)] -enum Name { - /// Timeline last_record_lsn, absolute - #[serde(rename = "written_size")] - WrittenSize, - /// Timeline last_record_lsn, incremental - #[serde(rename = "written_data_bytes_delta")] - WrittenSizeDelta, - /// Timeline logical size - #[serde(rename = "timeline_logical_size")] - LogicalSize, - /// Tenant remote size - #[serde(rename = "remote_storage_size")] - RemoteSize, - /// Tenant resident size - #[serde(rename = "resident_size")] - ResidentSize, - /// Tenant synthetic size - #[serde(rename = "synthetic_storage_size")] - SyntheticSize, -} - -/// Key that uniquely identifies the object this metric describes. -/// -/// This is a denormalization done at the MetricsKey const methods; these should not be constructed -/// elsewhere. -#[serde_with::serde_as] -#[derive(Debug, Clone, Copy, PartialEq, Eq, Hash, serde::Serialize, serde::Deserialize)] -struct MetricsKey { - #[serde_as(as = "serde_with::DisplayFromStr")] - tenant_id: TenantId, - - #[serde_as(as = "Option")] - #[serde(skip_serializing_if = "Option::is_none")] - timeline_id: Option, - - metric: Name, -} - -impl MetricsKey { - const fn absolute_values(self) -> AbsoluteValueFactory { - AbsoluteValueFactory(self) - } - const fn incremental_values(self) -> IncrementalValueFactory { - IncrementalValueFactory(self) - } -} - -/// Helper type which each individual metric kind can return to produce only absolute values. -struct AbsoluteValueFactory(MetricsKey); - -impl AbsoluteValueFactory { - fn at(self, time: DateTime, val: u64) -> RawMetric { - let key = self.0; - (key, (EventType::Absolute { time }, val)) - } - - fn key(&self) -> &MetricsKey { - &self.0 - } -} - -/// Helper type which each individual metric kind can return to produce only incremental values. -struct IncrementalValueFactory(MetricsKey); - -impl IncrementalValueFactory { - #[allow(clippy::wrong_self_convention)] - fn from_previous_up_to( - self, - prev_end: DateTime, - up_to: DateTime, - val: u64, - ) -> RawMetric { - let key = self.0; - // cannot assert prev_end < up_to because these are realtime clock based - ( - key, - ( - EventType::Incremental { - start_time: prev_end, - stop_time: up_to, - }, - val, - ), - ) - } - - fn key(&self) -> &MetricsKey { - &self.0 - } -} - -// the static part of a MetricsKey -impl MetricsKey { - /// Absolute value of [`Timeline::get_last_record_lsn`]. - /// - /// [`Timeline::get_last_record_lsn`]: crate::tenant::Timeline::get_last_record_lsn - const fn written_size(tenant_id: TenantId, timeline_id: TimelineId) -> AbsoluteValueFactory { - MetricsKey { - tenant_id, - timeline_id: Some(timeline_id), - metric: Name::WrittenSize, - } - .absolute_values() - } - - /// Values will be the difference of the latest [`MetricsKey::written_size`] to what we - /// previously sent, starting from the previously sent incremental time range ending at the - /// latest absolute measurement. - const fn written_size_delta( - tenant_id: TenantId, - timeline_id: TimelineId, - ) -> IncrementalValueFactory { - MetricsKey { - tenant_id, - timeline_id: Some(timeline_id), - metric: Name::WrittenSizeDelta, - } - .incremental_values() - } - - /// Exact [`Timeline::get_current_logical_size`]. - /// - /// [`Timeline::get_current_logical_size`]: crate::tenant::Timeline::get_current_logical_size - const fn timeline_logical_size( - tenant_id: TenantId, - timeline_id: TimelineId, - ) -> AbsoluteValueFactory { - MetricsKey { - tenant_id, - timeline_id: Some(timeline_id), - metric: Name::LogicalSize, - } - .absolute_values() - } - - /// [`Tenant::remote_size`] - /// - /// [`Tenant::remote_size`]: crate::tenant::Tenant::remote_size - const fn remote_storage_size(tenant_id: TenantId) -> AbsoluteValueFactory { - MetricsKey { - tenant_id, - timeline_id: None, - metric: Name::RemoteSize, - } - .absolute_values() - } - - /// Sum of [`Timeline::resident_physical_size`] for each `Tenant`. - /// - /// [`Timeline::resident_physical_size`]: crate::tenant::Timeline::resident_physical_size - const fn resident_size(tenant_id: TenantId) -> AbsoluteValueFactory { - MetricsKey { - tenant_id, - timeline_id: None, - metric: Name::ResidentSize, - } - .absolute_values() - } - - /// [`Tenant::cached_synthetic_size`] as refreshed by [`calculate_synthetic_size_worker`]. - /// - /// [`Tenant::cached_synthetic_size`]: crate::tenant::Tenant::cached_synthetic_size - const fn synthetic_size(tenant_id: TenantId) -> AbsoluteValueFactory { - MetricsKey { - tenant_id, - timeline_id: None, - metric: Name::SyntheticSize, - } - .absolute_values() - } -} - /// Basically a key-value pair, but usually in a Vec except for [`Cache`]. /// /// This is as opposed to `consumption_metrics::Event` which is the externally communicated form. @@ -287,7 +96,7 @@ pub async fn collect_metrics( }; // these are point in time, with variable "now" - let metrics = collect_all_metrics(&cached_metrics, &ctx).await; + let metrics = metrics::collect_all_metrics(&cached_metrics, &ctx).await; if metrics.is_empty() { continue; @@ -299,7 +108,7 @@ pub async fn collect_metrics( // already here, better to try to flush the new values. let flush = async { - match flush_metrics_to_disk(&metrics, &final_path).await { + match disk_cache::flush_metrics_to_disk(&metrics, &final_path).await { Ok(()) => { tracing::debug!("flushed metrics to disk"); } @@ -312,7 +121,7 @@ pub async fn collect_metrics( }; let upload = async { - let res = upload_metrics( + let res = upload::upload_metrics( &client, metric_collection_endpoint, &cancel, @@ -346,7 +155,9 @@ async fn restore_and_reschedule( final_path: &Arc, metric_collection_interval: Duration, ) -> Cache { - let (cached, earlier_metric_at) = match read_metrics_from_disk(final_path.clone()).await { + let (cached, earlier_metric_at) = match disk_cache::read_metrics_from_disk(final_path.clone()) + .await + { Ok(found_some) => { // there is no min needed because we write these sequentially in // collect_all_metrics @@ -428,497 +239,6 @@ async fn reschedule( } } -async fn collect_all_metrics(cached_metrics: &Cache, ctx: &RequestContext) -> Vec { - let started_at = std::time::Instant::now(); - - let tenants = match mgr::list_tenants().await { - Ok(tenants) => tenants, - Err(err) => { - error!("failed to list tenants: {:?}", err); - return vec![]; - } - }; - - let tenants = futures::stream::iter(tenants).filter_map(|(id, state)| async move { - if state != TenantState::Active { - None - } else { - mgr::get_tenant(id, true) - .await - .ok() - .map(|tenant| (id, tenant)) - } - }); - - let res = collect(tenants, cached_metrics, ctx).await; - - tracing::info!( - elapsed_ms = started_at.elapsed().as_millis(), - total = res.len(), - "collected metrics" - ); - - res -} - -async fn collect(tenants: S, cache: &Cache, ctx: &RequestContext) -> Vec -where - S: futures::stream::Stream)>, -{ - let mut current_metrics: Vec = Vec::new(); - - let mut tenants = std::pin::pin!(tenants); - - while let Some((tenant_id, tenant)) = tenants.next().await { - let mut tenant_resident_size = 0; - - for timeline in tenant.list_timelines() { - let timeline_id = timeline.timeline_id; - - match TimelineSnapshot::collect(&timeline, ctx) { - Ok(Some(snap)) => { - snap.to_metrics( - tenant_id, - timeline_id, - Utc::now(), - &mut current_metrics, - cache, - ); - } - Ok(None) => {} - Err(e) => { - error!( - "failed to get metrics values for tenant {tenant_id} timeline {}: {e:#?}", - timeline.timeline_id - ); - continue; - } - } - - tenant_resident_size += timeline.resident_physical_size(); - } - - let snap = TenantSnapshot::collect(&tenant, tenant_resident_size); - snap.to_metrics(tenant_id, Utc::now(), cache, &mut current_metrics); - } - - current_metrics -} - -async fn flush_metrics_to_disk( - current_metrics: &Arc>, - final_path: &Arc, -) -> anyhow::Result<()> { - use std::io::Write; - - anyhow::ensure!( - final_path.parent().is_some(), - "path must have parent: {final_path:?}" - ); - - let span = tracing::Span::current(); - tokio::task::spawn_blocking({ - let current_metrics = current_metrics.clone(); - let final_path = final_path.clone(); - move || { - let _e = span.entered(); - - let mut tempfile = - tempfile::NamedTempFile::new_in(final_path.parent().expect("existence checked"))?; - - // write out all of the raw metrics, to be read out later on restart as cached values - { - let mut writer = std::io::BufWriter::new(&mut tempfile); - serde_json::to_writer(&mut writer, &*current_metrics) - .context("serialize metrics")?; - writer - .into_inner() - .map_err(|_| anyhow::anyhow!("flushing metrics failed"))?; - } - - tempfile.flush()?; - tempfile.as_file().sync_all()?; - - drop(tempfile.persist(&*final_path)?); - - let f = std::fs::File::open(final_path.parent().unwrap())?; - f.sync_all()?; - - anyhow::Ok(()) - } - }) - .await - .with_context(|| format!("write metrics to {final_path:?} join error")) - .and_then(|x| x.with_context(|| format!("write metrics to {final_path:?}"))) -} - -async fn read_metrics_from_disk(path: Arc) -> anyhow::Result> { - // do not add context to each error, callsite will log with full path - let span = tracing::Span::current(); - tokio::task::spawn_blocking(move || { - let _e = span.entered(); - let mut file = std::fs::File::open(&*path)?; - let reader = std::io::BufReader::new(&mut file); - anyhow::Ok(serde_json::from_reader::<_, Vec>(reader)?) - }) - .await - .context("read metrics join error") - .and_then(|x| x) -} - -#[tracing::instrument(skip_all, fields(metrics_total = %metrics.len()))] -async fn upload_metrics( - client: &reqwest::Client, - metric_collection_endpoint: &reqwest::Url, - cancel: &CancellationToken, - node_id: &str, - metrics: &[RawMetric], - cached_metrics: &mut Cache, -) -> anyhow::Result<()> { - use bytes::BufMut; - - let mut uploaded = 0; - let mut failed = 0; - - let started_at = std::time::Instant::now(); - - // write to a BytesMut so that we can cheaply clone the frozen Bytes for retries - let mut buffer = bytes::BytesMut::new(); - let mut chunk_to_send = Vec::new(); - - for chunk in metrics.chunks(CHUNK_SIZE) { - chunk_to_send.clear(); - - // FIXME: this should always overwrite and truncate to chunk.len() - chunk_to_send.extend(chunk.iter().map(|(curr_key, (when, curr_val))| Event { - kind: *when, - metric: curr_key.metric, - // FIXME: finally write! this to the prev allocation - idempotency_key: idempotency_key(node_id), - value: *curr_val, - extra: Ids { - tenant_id: curr_key.tenant_id, - timeline_id: curr_key.timeline_id, - }, - })); - - serde_json::to_writer( - (&mut buffer).writer(), - &EventChunk { - events: (&chunk_to_send).into(), - }, - )?; - - let body = buffer.split().freeze(); - let event_bytes = body.len(); - - let res = upload(client, metric_collection_endpoint, body, cancel) - .instrument(tracing::info_span!( - "upload", - %event_bytes, - uploaded, - total = metrics.len(), - )) - .await; - - match res { - Ok(()) => { - for (curr_key, curr_val) in chunk { - cached_metrics.insert(*curr_key, *curr_val); - } - uploaded += chunk.len(); - } - Err(_) => { - // failure(s) have already been logged - // - // however this is an inconsistency: if we crash here, we will start with the - // values as uploaded. in practice, the rejections no longer happen. - failed += chunk.len(); - } - } - } - - let elapsed = started_at.elapsed(); - - tracing::info!( - uploaded, - failed, - elapsed_ms = elapsed.as_millis(), - "done sending metrics" - ); - - Ok(()) -} - -enum UploadError { - Rejected(reqwest::StatusCode), - Reqwest(reqwest::Error), - Cancelled, -} - -impl std::fmt::Debug for UploadError { - fn fmt(&self, f: &mut std::fmt::Formatter<'_>) -> std::fmt::Result { - // use same impl because backoff::retry will log this using both - std::fmt::Display::fmt(self, f) - } -} - -impl std::fmt::Display for UploadError { - fn fmt(&self, f: &mut std::fmt::Formatter<'_>) -> std::fmt::Result { - use UploadError::*; - - match self { - Rejected(code) => write!(f, "server rejected the metrics with {code}"), - Reqwest(e) => write!(f, "request failed: {e}"), - Cancelled => write!(f, "cancelled"), - } - } -} - -impl UploadError { - fn is_reject(&self) -> bool { - matches!(self, UploadError::Rejected(_)) - } -} - -async fn upload( - client: &reqwest::Client, - metric_collection_endpoint: &reqwest::Url, - body: bytes::Bytes, - cancel: &CancellationToken, -) -> Result<(), UploadError> { - let warn_after = 3; - let max_attempts = 10; - let res = utils::backoff::retry( - move || { - let body = body.clone(); - async move { - let res = client - .post(metric_collection_endpoint.clone()) - .header(reqwest::header::CONTENT_TYPE, "application/json") - .body(body) - .send() - .await; - - let res = res.and_then(|res| res.error_for_status()); - - match res { - Ok(_response) => Ok(()), - Err(e) => { - let status = e.status().filter(|s| s.is_client_error()); - if let Some(status) = status { - Err(UploadError::Rejected(status)) - } else { - Err(UploadError::Reqwest(e)) - } - } - } - } - }, - UploadError::is_reject, - warn_after, - max_attempts, - "upload consumption_metrics", - utils::backoff::Cancel::new(cancel.clone(), || UploadError::Cancelled), - ) - .await; - - match &res { - Ok(_) => {} - Err(e) if e.is_reject() => { - // permanent errors currently do not get logged by backoff::retry - // display alternate has no effect, but keeping it here for easier pattern matching. - tracing::error!("failed to upload metrics: {e:#}"); - } - Err(_) => { - // these have been logged already - } - } - - res -} - -/// Testing helping in-between abstraction allowing testing metrics without actual Tenants. -struct TenantSnapshot { - resident_size: u64, - remote_size: u64, - synthetic_size: u64, -} - -impl TenantSnapshot { - /// Collect tenant status to have metrics created out of it. - /// - /// `resident_size` is calculated of the timelines we had access to for other metrics, so we - /// cannot just list timelines here. - fn collect(t: &Arc, resident_size: u64) -> Self { - TenantSnapshot { - resident_size, - remote_size: t.remote_size(), - // Note that this metric is calculated in a separate bgworker - // Here we only use cached value, which may lag behind the real latest one - synthetic_size: t.cached_synthetic_size(), - } - } - - fn to_metrics( - &self, - tenant_id: TenantId, - now: DateTime, - cached: &Cache, - metrics: &mut Vec, - ) { - let remote_size = MetricsKey::remote_storage_size(tenant_id).at(now, self.remote_size); - - let resident_size = MetricsKey::resident_size(tenant_id).at(now, self.resident_size); - - let synthetic_size = { - let factory = MetricsKey::synthetic_size(tenant_id); - let mut synthetic_size = self.synthetic_size; - - if synthetic_size == 0 { - if let Some((_, value)) = cached.get(factory.key()) { - // use the latest value from previous session - synthetic_size = *value; - } - } - - if synthetic_size != 0 { - // only send non-zeroes because otherwise these show up as errors in logs - Some(factory.at(now, synthetic_size)) - } else { - None - } - }; - - metrics.extend( - [Some(remote_size), Some(resident_size), synthetic_size] - .into_iter() - .flatten(), - ); - } -} - -/// Internal type to make timeline metric production testable. -/// -/// As this value type contains all of the information needed from a timeline to produce the -/// metrics, it can easily be created with different values in test. -struct TimelineSnapshot { - loaded_at: (Lsn, SystemTime), - last_record_lsn: Lsn, - current_exact_logical_size: Option, -} - -impl TimelineSnapshot { - /// Collect the metrics from an actual timeline. - /// - /// Fails currently only when [`Timeline::get_current_logical_size`] fails. - /// - /// [`Timeline::get_current_logical_size`]: crate::tenant::Timeline::get_current_logical_size - fn collect( - t: &Arc, - ctx: &RequestContext, - ) -> anyhow::Result> { - if !t.is_active() { - // no collection for broken or stopping needed, we will still keep the cached values - // though at the caller. - Ok(None) - } else { - let loaded_at = t.loaded_at; - let last_record_lsn = t.get_last_record_lsn(); - - let current_exact_logical_size = { - let span = info_span!("collect_metrics_iteration", tenant_id = %t.tenant_id, timeline_id = %t.timeline_id); - let res = span - .in_scope(|| t.get_current_logical_size(ctx)) - .context("get_current_logical_size"); - match res? { - // Only send timeline logical size when it is fully calculated. - (size, is_exact) if is_exact => Some(size), - (_, _) => None, - } - }; - - Ok(Some(TimelineSnapshot { - loaded_at, - last_record_lsn, - current_exact_logical_size, - })) - } - } - - /// Produce the timeline consumption metrics into the `metrics` argument. - fn to_metrics( - &self, - tenant_id: TenantId, - timeline_id: TimelineId, - now: DateTime, - metrics: &mut Vec, - cache: &Cache, - ) { - let timeline_written_size = u64::from(self.last_record_lsn); - - let written_size_delta_key = MetricsKey::written_size_delta(tenant_id, timeline_id); - - let last_stop_time = cache - .get(written_size_delta_key.key()) - .map(|(until, _val)| { - until - .incremental_timerange() - .expect("never create EventType::Absolute for written_size_delta") - .end - }); - - let (key, written_size_now) = - MetricsKey::written_size(tenant_id, timeline_id).at(now, timeline_written_size); - - // by default, use the last sent written_size as the basis for - // calculating the delta. if we don't yet have one, use the load time value. - let prev = cache - .get(&key) - .map(|(prev_at, prev)| { - // use the prev time from our last incremental update, or default to latest - // absolute update on the first round. - let prev_at = prev_at - .absolute_time() - .expect("never create EventType::Incremental for written_size"); - let prev_at = last_stop_time.unwrap_or(prev_at); - (*prev_at, *prev) - }) - .unwrap_or_else(|| { - // if we don't have a previous point of comparison, compare to the load time - // lsn. - let (disk_consistent_lsn, loaded_at) = &self.loaded_at; - (DateTime::from(*loaded_at), disk_consistent_lsn.0) - }); - - let up_to = now; - - if let Some(delta) = written_size_now.1.checked_sub(prev.1) { - let key_value = written_size_delta_key.from_previous_up_to(prev.0, up_to, delta); - // written_size_delta - metrics.push(key_value); - // written_size - metrics.push((key, written_size_now)); - } else { - // the cached value was ahead of us, report zero until we've caught up - metrics.push(written_size_delta_key.from_previous_up_to(prev.0, up_to, 0)); - // the cached value was ahead of us, report the same until we've caught up - metrics.push((key, (written_size_now.0, prev.1))); - } - - { - let factory = MetricsKey::timeline_logical_size(tenant_id, timeline_id); - let current_or_previous = self - .current_exact_logical_size - .or_else(|| cache.get(factory.key()).map(|(_, val)| *val)); - - if let Some(size) = current_or_previous { - metrics.push(factory.at(now, size)); - } - } - } -} - /// Caclculate synthetic size for each active tenant async fn calculate_synthetic_size_worker( synthetic_size_calculation_interval: Duration, @@ -963,369 +283,3 @@ async fn calculate_synthetic_size_worker( ); } } - -#[cfg(test)] -mod tests { - use std::collections::HashMap; - - use std::time::SystemTime; - use utils::{ - id::{TenantId, TimelineId}, - lsn::Lsn, - }; - - use super::*; - use chrono::{DateTime, Utc}; - - #[test] - fn startup_collected_timeline_metrics_before_advancing() { - let tenant_id = TenantId::generate(); - let timeline_id = TimelineId::generate(); - - let mut metrics = Vec::new(); - let cache = HashMap::new(); - - let initdb_lsn = Lsn(0x10000); - let disk_consistent_lsn = Lsn(initdb_lsn.0 * 2); - - let snap = TimelineSnapshot { - loaded_at: (disk_consistent_lsn, SystemTime::now()), - last_record_lsn: disk_consistent_lsn, - current_exact_logical_size: Some(0x42000), - }; - - let now = DateTime::::from(SystemTime::now()); - - snap.to_metrics(tenant_id, timeline_id, now, &mut metrics, &cache); - - assert_eq!( - metrics, - &[ - MetricsKey::written_size_delta(tenant_id, timeline_id).from_previous_up_to( - snap.loaded_at.1.into(), - now, - 0 - ), - MetricsKey::written_size(tenant_id, timeline_id).at(now, disk_consistent_lsn.0), - MetricsKey::timeline_logical_size(tenant_id, timeline_id).at(now, 0x42000) - ] - ); - } - - #[test] - fn startup_collected_timeline_metrics_second_round() { - let tenant_id = TenantId::generate(); - let timeline_id = TimelineId::generate(); - - let [now, before, init] = time_backwards(); - - let now = DateTime::::from(now); - let before = DateTime::::from(before); - - let initdb_lsn = Lsn(0x10000); - let disk_consistent_lsn = Lsn(initdb_lsn.0 * 2); - - let mut metrics = Vec::new(); - let cache = HashMap::from([ - MetricsKey::written_size(tenant_id, timeline_id).at(before, disk_consistent_lsn.0) - ]); - - let snap = TimelineSnapshot { - loaded_at: (disk_consistent_lsn, init), - last_record_lsn: disk_consistent_lsn, - current_exact_logical_size: Some(0x42000), - }; - - snap.to_metrics(tenant_id, timeline_id, now, &mut metrics, &cache); - - assert_eq!( - metrics, - &[ - MetricsKey::written_size_delta(tenant_id, timeline_id) - .from_previous_up_to(before, now, 0), - MetricsKey::written_size(tenant_id, timeline_id).at(now, disk_consistent_lsn.0), - MetricsKey::timeline_logical_size(tenant_id, timeline_id).at(now, 0x42000) - ] - ); - } - - #[test] - fn startup_collected_timeline_metrics_nth_round_at_same_lsn() { - let tenant_id = TenantId::generate(); - let timeline_id = TimelineId::generate(); - - let [now, just_before, before, init] = time_backwards(); - - let now = DateTime::::from(now); - let just_before = DateTime::::from(just_before); - let before = DateTime::::from(before); - - let initdb_lsn = Lsn(0x10000); - let disk_consistent_lsn = Lsn(initdb_lsn.0 * 2); - - let mut metrics = Vec::new(); - let cache = HashMap::from([ - // at t=before was the last time the last_record_lsn changed - MetricsKey::written_size(tenant_id, timeline_id).at(before, disk_consistent_lsn.0), - // end time of this event is used for the next ones - MetricsKey::written_size_delta(tenant_id, timeline_id).from_previous_up_to( - before, - just_before, - 0, - ), - ]); - - let snap = TimelineSnapshot { - loaded_at: (disk_consistent_lsn, init), - last_record_lsn: disk_consistent_lsn, - current_exact_logical_size: Some(0x42000), - }; - - snap.to_metrics(tenant_id, timeline_id, now, &mut metrics, &cache); - - assert_eq!( - metrics, - &[ - MetricsKey::written_size_delta(tenant_id, timeline_id).from_previous_up_to( - just_before, - now, - 0 - ), - MetricsKey::written_size(tenant_id, timeline_id).at(now, disk_consistent_lsn.0), - MetricsKey::timeline_logical_size(tenant_id, timeline_id).at(now, 0x42000) - ] - ); - } - - #[test] - fn metric_image_stability() { - // it is important that these strings stay as they are - - let tenant_id = TenantId::from_array([0; 16]); - let timeline_id = TimelineId::from_array([0xff; 16]); - - let now = DateTime::parse_from_rfc3339("2023-09-15T00:00:00.123456789Z").unwrap(); - let before = DateTime::parse_from_rfc3339("2023-09-14T00:00:00.123456789Z").unwrap(); - - let [now, before] = [DateTime::::from(now), DateTime::from(before)]; - - let examples = [ - ( - line!(), - MetricsKey::written_size(tenant_id, timeline_id).at(now, 0), - r#"{"type":"absolute","time":"2023-09-15T00:00:00.123456789Z","metric":"written_size","idempotency_key":"2023-09-15 00:00:00.123456789 UTC-1-0000","value":0,"tenant_id":"00000000000000000000000000000000","timeline_id":"ffffffffffffffffffffffffffffffff"}"#, - ), - ( - line!(), - MetricsKey::written_size_delta(tenant_id, timeline_id) - .from_previous_up_to(before, now, 0), - r#"{"type":"incremental","start_time":"2023-09-14T00:00:00.123456789Z","stop_time":"2023-09-15T00:00:00.123456789Z","metric":"written_data_bytes_delta","idempotency_key":"2023-09-15 00:00:00.123456789 UTC-1-0000","value":0,"tenant_id":"00000000000000000000000000000000","timeline_id":"ffffffffffffffffffffffffffffffff"}"#, - ), - ( - line!(), - MetricsKey::timeline_logical_size(tenant_id, timeline_id).at(now, 0), - r#"{"type":"absolute","time":"2023-09-15T00:00:00.123456789Z","metric":"timeline_logical_size","idempotency_key":"2023-09-15 00:00:00.123456789 UTC-1-0000","value":0,"tenant_id":"00000000000000000000000000000000","timeline_id":"ffffffffffffffffffffffffffffffff"}"#, - ), - ( - line!(), - MetricsKey::remote_storage_size(tenant_id).at(now, 0), - r#"{"type":"absolute","time":"2023-09-15T00:00:00.123456789Z","metric":"remote_storage_size","idempotency_key":"2023-09-15 00:00:00.123456789 UTC-1-0000","value":0,"tenant_id":"00000000000000000000000000000000"}"#, - ), - ( - line!(), - MetricsKey::resident_size(tenant_id).at(now, 0), - r#"{"type":"absolute","time":"2023-09-15T00:00:00.123456789Z","metric":"resident_size","idempotency_key":"2023-09-15 00:00:00.123456789 UTC-1-0000","value":0,"tenant_id":"00000000000000000000000000000000"}"#, - ), - ( - line!(), - MetricsKey::synthetic_size(tenant_id).at(now, 1), - r#"{"type":"absolute","time":"2023-09-15T00:00:00.123456789Z","metric":"synthetic_storage_size","idempotency_key":"2023-09-15 00:00:00.123456789 UTC-1-0000","value":1,"tenant_id":"00000000000000000000000000000000"}"#, - ), - ]; - - let idempotency_key = consumption_metrics::IdempotencyKey::for_tests(now, "1", 0); - - for (line, (key, (kind, value)), expected) in examples { - let e = consumption_metrics::Event { - kind, - metric: key.metric, - idempotency_key: idempotency_key.to_string(), - value, - extra: super::Ids { - tenant_id: key.tenant_id, - timeline_id: key.timeline_id, - }, - }; - let actual = serde_json::to_string(&e).unwrap(); - assert_eq!(expected, actual, "example from line {line}"); - } - } - - #[test] - fn post_restart_written_sizes_with_rolled_back_last_record_lsn() { - // it can happen that we lose the inmemorylayer but have previously sent metrics and we - // should never go backwards - - let tenant_id = TenantId::generate(); - let timeline_id = TimelineId::generate(); - - let [later, now, at_restart] = time_backwards(); - - // FIXME: tests would be so much easier if we did not need to juggle back and forth - // SystemTime and DateTime:: ... Could do the conversion only at upload time? - let now = DateTime::::from(now); - let later = DateTime::::from(later); - let before_restart = at_restart - std::time::Duration::from_secs(5 * 60); - let way_before = before_restart - std::time::Duration::from_secs(10 * 60); - let before_restart = DateTime::::from(before_restart); - let way_before = DateTime::::from(way_before); - - let snap = TimelineSnapshot { - loaded_at: (Lsn(50), at_restart), - last_record_lsn: Lsn(50), - current_exact_logical_size: None, - }; - - let mut cache = HashMap::from([ - MetricsKey::written_size(tenant_id, timeline_id).at(before_restart, 100), - MetricsKey::written_size_delta(tenant_id, timeline_id).from_previous_up_to( - way_before, - before_restart, - // not taken into account, but the timestamps are important - 999_999_999, - ), - ]); - - let mut metrics = Vec::new(); - snap.to_metrics(tenant_id, timeline_id, now, &mut metrics, &cache); - - assert_eq!( - metrics, - &[ - MetricsKey::written_size_delta(tenant_id, timeline_id).from_previous_up_to( - before_restart, - now, - 0 - ), - MetricsKey::written_size(tenant_id, timeline_id).at(now, 100), - ] - ); - - // now if we cache these metrics, and re-run while "still in recovery" - cache.extend(metrics.drain(..)); - - // "still in recovery", because our snapshot did not change - snap.to_metrics(tenant_id, timeline_id, later, &mut metrics, &cache); - - assert_eq!( - metrics, - &[ - MetricsKey::written_size_delta(tenant_id, timeline_id) - .from_previous_up_to(now, later, 0), - MetricsKey::written_size(tenant_id, timeline_id).at(later, 100), - ] - ); - } - - #[test] - fn post_restart_current_exact_logical_size_uses_cached() { - let tenant_id = TenantId::generate(); - let timeline_id = TimelineId::generate(); - - let [now, at_restart] = time_backwards(); - - let now = DateTime::::from(now); - let before_restart = at_restart - std::time::Duration::from_secs(5 * 60); - let before_restart = DateTime::::from(before_restart); - - let snap = TimelineSnapshot { - loaded_at: (Lsn(50), at_restart), - last_record_lsn: Lsn(50), - current_exact_logical_size: None, - }; - - let cache = HashMap::from([ - MetricsKey::timeline_logical_size(tenant_id, timeline_id).at(before_restart, 100) - ]); - - let mut metrics = Vec::new(); - snap.to_metrics(tenant_id, timeline_id, now, &mut metrics, &cache); - - metrics.retain(|(key, _)| key.metric == Name::LogicalSize); - - assert_eq!( - metrics, - &[MetricsKey::timeline_logical_size(tenant_id, timeline_id).at(now, 100)] - ); - } - - #[test] - fn post_restart_synthetic_size_uses_cached_if_available() { - let tenant_id = TenantId::generate(); - - let ts = TenantSnapshot { - resident_size: 1000, - remote_size: 1000, - // not yet calculated - synthetic_size: 0, - }; - - let now = SystemTime::now(); - let before_restart = DateTime::::from(now - std::time::Duration::from_secs(5 * 60)); - let now = DateTime::::from(now); - - let cached = - HashMap::from([MetricsKey::synthetic_size(tenant_id).at(before_restart, 1000)]); - - let mut metrics = Vec::new(); - ts.to_metrics(tenant_id, now, &cached, &mut metrics); - - assert_eq!( - metrics, - &[ - MetricsKey::remote_storage_size(tenant_id).at(now, 1000), - MetricsKey::resident_size(tenant_id).at(now, 1000), - MetricsKey::synthetic_size(tenant_id).at(now, 1000), - ] - ); - } - - #[test] - fn post_restart_synthetic_size_is_not_sent_when_not_cached() { - let tenant_id = TenantId::generate(); - - let ts = TenantSnapshot { - resident_size: 1000, - remote_size: 1000, - // not yet calculated - synthetic_size: 0, - }; - - let now = SystemTime::now(); - let now = DateTime::::from(now); - - let cached = HashMap::new(); - - let mut metrics = Vec::new(); - ts.to_metrics(tenant_id, now, &cached, &mut metrics); - - assert_eq!( - metrics, - &[ - MetricsKey::remote_storage_size(tenant_id).at(now, 1000), - MetricsKey::resident_size(tenant_id).at(now, 1000), - // no synthetic size here - ] - ); - } - - fn time_backwards() -> [std::time::SystemTime; N] { - let mut times = [std::time::SystemTime::UNIX_EPOCH; N]; - times[0] = std::time::SystemTime::now(); - for behind in 1..N { - times[behind] = times[0] - std::time::Duration::from_secs(behind as u64); - } - - times - } -} diff --git a/pageserver/src/consumption_metrics/disk_cache.rs b/pageserver/src/consumption_metrics/disk_cache.rs new file mode 100644 index 0000000000..1fd1338c95 --- /dev/null +++ b/pageserver/src/consumption_metrics/disk_cache.rs @@ -0,0 +1,66 @@ +use anyhow::Context; +use std::path::PathBuf; +use std::sync::Arc; + +use super::RawMetric; + +pub(super) async fn read_metrics_from_disk(path: Arc) -> anyhow::Result> { + // do not add context to each error, callsite will log with full path + let span = tracing::Span::current(); + tokio::task::spawn_blocking(move || { + let _e = span.entered(); + let mut file = std::fs::File::open(&*path)?; + let reader = std::io::BufReader::new(&mut file); + anyhow::Ok(serde_json::from_reader::<_, Vec>(reader)?) + }) + .await + .context("read metrics join error") + .and_then(|x| x) +} + +pub(super) async fn flush_metrics_to_disk( + current_metrics: &Arc>, + final_path: &Arc, +) -> anyhow::Result<()> { + use std::io::Write; + + anyhow::ensure!( + final_path.parent().is_some(), + "path must have parent: {final_path:?}" + ); + + let span = tracing::Span::current(); + tokio::task::spawn_blocking({ + let current_metrics = current_metrics.clone(); + let final_path = final_path.clone(); + move || { + let _e = span.entered(); + + let mut tempfile = + tempfile::NamedTempFile::new_in(final_path.parent().expect("existence checked"))?; + + // write out all of the raw metrics, to be read out later on restart as cached values + { + let mut writer = std::io::BufWriter::new(&mut tempfile); + serde_json::to_writer(&mut writer, &*current_metrics) + .context("serialize metrics")?; + writer + .into_inner() + .map_err(|_| anyhow::anyhow!("flushing metrics failed"))?; + } + + tempfile.flush()?; + tempfile.as_file().sync_all()?; + + drop(tempfile.persist(&*final_path)?); + + let f = std::fs::File::open(final_path.parent().unwrap())?; + f.sync_all()?; + + anyhow::Ok(()) + } + }) + .await + .with_context(|| format!("write metrics to {final_path:?} join error")) + .and_then(|x| x.with_context(|| format!("write metrics to {final_path:?}"))) +} diff --git a/pageserver/src/consumption_metrics/metrics.rs b/pageserver/src/consumption_metrics/metrics.rs new file mode 100644 index 0000000000..e03d2dc34f --- /dev/null +++ b/pageserver/src/consumption_metrics/metrics.rs @@ -0,0 +1,470 @@ +use crate::context::RequestContext; +use crate::tenant::mgr; +use chrono::{DateTime, Utc}; +use consumption_metrics::EventType; +use futures::stream::StreamExt; +use pageserver_api::models::TenantState; +use serde::Serialize; +use serde_with::{serde_as, DisplayFromStr}; +use std::sync::Arc; +use std::time::SystemTime; +use utils::id::{TenantId, TimelineId}; +use utils::lsn::Lsn; + +use anyhow::Context; + +use super::{Cache, RawMetric}; + +// FIXME: all other consumption_metrics::Event stuff is over at uploading, maybe move? +#[serde_as] +#[derive(Serialize, serde::Deserialize, Debug, Clone, Copy)] +pub(super) struct Ids { + #[serde_as(as = "DisplayFromStr")] + pub(super) tenant_id: TenantId, + #[serde_as(as = "Option")] + #[serde(skip_serializing_if = "Option::is_none")] + pub(super) timeline_id: Option, +} + +/// Name of the metric, used by `MetricsKey` factory methods and `deserialize_cached_events` +/// instead of static str. +// Do not rename any of these without first consulting with data team and partner +// management. +// FIXME: write those tests before refactoring to this! +#[derive(Debug, Clone, Copy, PartialEq, Eq, Hash, serde::Serialize, serde::Deserialize)] +pub(super) enum Name { + /// Timeline last_record_lsn, absolute + #[serde(rename = "written_size")] + WrittenSize, + /// Timeline last_record_lsn, incremental + #[serde(rename = "written_data_bytes_delta")] + WrittenSizeDelta, + /// Timeline logical size + #[serde(rename = "timeline_logical_size")] + LogicalSize, + /// Tenant remote size + #[serde(rename = "remote_storage_size")] + RemoteSize, + /// Tenant resident size + #[serde(rename = "resident_size")] + ResidentSize, + /// Tenant synthetic size + #[serde(rename = "synthetic_storage_size")] + SyntheticSize, +} + +/// Key that uniquely identifies the object this metric describes. +/// +/// This is a denormalization done at the MetricsKey const methods; these should not be constructed +/// elsewhere. +#[serde_with::serde_as] +#[derive(Debug, Clone, Copy, PartialEq, Eq, Hash, serde::Serialize, serde::Deserialize)] +pub(super) struct MetricsKey { + #[serde_as(as = "serde_with::DisplayFromStr")] + pub(super) tenant_id: TenantId, + + #[serde_as(as = "Option")] + #[serde(skip_serializing_if = "Option::is_none")] + pub(super) timeline_id: Option, + + pub(super) metric: Name, +} + +impl MetricsKey { + const fn absolute_values(self) -> AbsoluteValueFactory { + AbsoluteValueFactory(self) + } + const fn incremental_values(self) -> IncrementalValueFactory { + IncrementalValueFactory(self) + } +} + +/// Helper type which each individual metric kind can return to produce only absolute values. +struct AbsoluteValueFactory(MetricsKey); + +impl AbsoluteValueFactory { + fn at(self, time: DateTime, val: u64) -> RawMetric { + let key = self.0; + (key, (EventType::Absolute { time }, val)) + } + + fn key(&self) -> &MetricsKey { + &self.0 + } +} + +/// Helper type which each individual metric kind can return to produce only incremental values. +struct IncrementalValueFactory(MetricsKey); + +impl IncrementalValueFactory { + #[allow(clippy::wrong_self_convention)] + fn from_previous_up_to( + self, + prev_end: DateTime, + up_to: DateTime, + val: u64, + ) -> RawMetric { + let key = self.0; + // cannot assert prev_end < up_to because these are realtime clock based + ( + key, + ( + EventType::Incremental { + start_time: prev_end, + stop_time: up_to, + }, + val, + ), + ) + } + + fn key(&self) -> &MetricsKey { + &self.0 + } +} + +// the static part of a MetricsKey +impl MetricsKey { + /// Absolute value of [`Timeline::get_last_record_lsn`]. + /// + /// [`Timeline::get_last_record_lsn`]: crate::tenant::Timeline::get_last_record_lsn + const fn written_size(tenant_id: TenantId, timeline_id: TimelineId) -> AbsoluteValueFactory { + MetricsKey { + tenant_id, + timeline_id: Some(timeline_id), + metric: Name::WrittenSize, + } + .absolute_values() + } + + /// Values will be the difference of the latest [`MetricsKey::written_size`] to what we + /// previously sent, starting from the previously sent incremental time range ending at the + /// latest absolute measurement. + const fn written_size_delta( + tenant_id: TenantId, + timeline_id: TimelineId, + ) -> IncrementalValueFactory { + MetricsKey { + tenant_id, + timeline_id: Some(timeline_id), + metric: Name::WrittenSizeDelta, + } + .incremental_values() + } + + /// Exact [`Timeline::get_current_logical_size`]. + /// + /// [`Timeline::get_current_logical_size`]: crate::tenant::Timeline::get_current_logical_size + const fn timeline_logical_size( + tenant_id: TenantId, + timeline_id: TimelineId, + ) -> AbsoluteValueFactory { + MetricsKey { + tenant_id, + timeline_id: Some(timeline_id), + metric: Name::LogicalSize, + } + .absolute_values() + } + + /// [`Tenant::remote_size`] + /// + /// [`Tenant::remote_size`]: crate::tenant::Tenant::remote_size + const fn remote_storage_size(tenant_id: TenantId) -> AbsoluteValueFactory { + MetricsKey { + tenant_id, + timeline_id: None, + metric: Name::RemoteSize, + } + .absolute_values() + } + + /// Sum of [`Timeline::resident_physical_size`] for each `Tenant`. + /// + /// [`Timeline::resident_physical_size`]: crate::tenant::Timeline::resident_physical_size + const fn resident_size(tenant_id: TenantId) -> AbsoluteValueFactory { + MetricsKey { + tenant_id, + timeline_id: None, + metric: Name::ResidentSize, + } + .absolute_values() + } + + /// [`Tenant::cached_synthetic_size`] as refreshed by [`calculate_synthetic_size_worker`]. + /// + /// [`Tenant::cached_synthetic_size`]: crate::tenant::Tenant::cached_synthetic_size + /// [`calculate_synthetic_size_worker`]: super::calculate_synthetic_size_worker + const fn synthetic_size(tenant_id: TenantId) -> AbsoluteValueFactory { + MetricsKey { + tenant_id, + timeline_id: None, + metric: Name::SyntheticSize, + } + .absolute_values() + } +} + +pub(super) async fn collect_all_metrics( + cached_metrics: &Cache, + ctx: &RequestContext, +) -> Vec { + let started_at = std::time::Instant::now(); + + let tenants = match mgr::list_tenants().await { + Ok(tenants) => tenants, + Err(err) => { + tracing::error!("failed to list tenants: {:?}", err); + return vec![]; + } + }; + + let tenants = futures::stream::iter(tenants).filter_map(|(id, state)| async move { + if state != TenantState::Active { + None + } else { + mgr::get_tenant(id, true) + .await + .ok() + .map(|tenant| (id, tenant)) + } + }); + + let res = collect(tenants, cached_metrics, ctx).await; + + tracing::info!( + elapsed_ms = started_at.elapsed().as_millis(), + total = res.len(), + "collected metrics" + ); + + res +} + +async fn collect(tenants: S, cache: &Cache, ctx: &RequestContext) -> Vec +where + S: futures::stream::Stream)>, +{ + let mut current_metrics: Vec = Vec::new(); + + let mut tenants = std::pin::pin!(tenants); + + while let Some((tenant_id, tenant)) = tenants.next().await { + let mut tenant_resident_size = 0; + + for timeline in tenant.list_timelines() { + let timeline_id = timeline.timeline_id; + + match TimelineSnapshot::collect(&timeline, ctx) { + Ok(Some(snap)) => { + snap.to_metrics( + tenant_id, + timeline_id, + Utc::now(), + &mut current_metrics, + cache, + ); + } + Ok(None) => {} + Err(e) => { + tracing::error!( + "failed to get metrics values for tenant {tenant_id} timeline {}: {e:#?}", + timeline.timeline_id + ); + continue; + } + } + + tenant_resident_size += timeline.resident_physical_size(); + } + + let snap = TenantSnapshot::collect(&tenant, tenant_resident_size); + snap.to_metrics(tenant_id, Utc::now(), cache, &mut current_metrics); + } + + current_metrics +} + +/// Testing helping in-between abstraction allowing testing metrics without actual Tenants. +struct TenantSnapshot { + resident_size: u64, + remote_size: u64, + synthetic_size: u64, +} + +impl TenantSnapshot { + /// Collect tenant status to have metrics created out of it. + /// + /// `resident_size` is calculated of the timelines we had access to for other metrics, so we + /// cannot just list timelines here. + fn collect(t: &Arc, resident_size: u64) -> Self { + TenantSnapshot { + resident_size, + remote_size: t.remote_size(), + // Note that this metric is calculated in a separate bgworker + // Here we only use cached value, which may lag behind the real latest one + synthetic_size: t.cached_synthetic_size(), + } + } + + fn to_metrics( + &self, + tenant_id: TenantId, + now: DateTime, + cached: &Cache, + metrics: &mut Vec, + ) { + let remote_size = MetricsKey::remote_storage_size(tenant_id).at(now, self.remote_size); + + let resident_size = MetricsKey::resident_size(tenant_id).at(now, self.resident_size); + + let synthetic_size = { + let factory = MetricsKey::synthetic_size(tenant_id); + let mut synthetic_size = self.synthetic_size; + + if synthetic_size == 0 { + if let Some((_, value)) = cached.get(factory.key()) { + // use the latest value from previous session + synthetic_size = *value; + } + } + + if synthetic_size != 0 { + // only send non-zeroes because otherwise these show up as errors in logs + Some(factory.at(now, synthetic_size)) + } else { + None + } + }; + + metrics.extend( + [Some(remote_size), Some(resident_size), synthetic_size] + .into_iter() + .flatten(), + ); + } +} + +/// Internal type to make timeline metric production testable. +/// +/// As this value type contains all of the information needed from a timeline to produce the +/// metrics, it can easily be created with different values in test. +struct TimelineSnapshot { + loaded_at: (Lsn, SystemTime), + last_record_lsn: Lsn, + current_exact_logical_size: Option, +} + +impl TimelineSnapshot { + /// Collect the metrics from an actual timeline. + /// + /// Fails currently only when [`Timeline::get_current_logical_size`] fails. + /// + /// [`Timeline::get_current_logical_size`]: crate::tenant::Timeline::get_current_logical_size + fn collect( + t: &Arc, + ctx: &RequestContext, + ) -> anyhow::Result> { + if !t.is_active() { + // no collection for broken or stopping needed, we will still keep the cached values + // though at the caller. + Ok(None) + } else { + let loaded_at = t.loaded_at; + let last_record_lsn = t.get_last_record_lsn(); + + let current_exact_logical_size = { + let span = tracing::info_span!("collect_metrics_iteration", tenant_id = %t.tenant_id, timeline_id = %t.timeline_id); + let res = span + .in_scope(|| t.get_current_logical_size(ctx)) + .context("get_current_logical_size"); + match res? { + // Only send timeline logical size when it is fully calculated. + (size, is_exact) if is_exact => Some(size), + (_, _) => None, + } + }; + + Ok(Some(TimelineSnapshot { + loaded_at, + last_record_lsn, + current_exact_logical_size, + })) + } + } + + /// Produce the timeline consumption metrics into the `metrics` argument. + fn to_metrics( + &self, + tenant_id: TenantId, + timeline_id: TimelineId, + now: DateTime, + metrics: &mut Vec, + cache: &Cache, + ) { + let timeline_written_size = u64::from(self.last_record_lsn); + + let written_size_delta_key = MetricsKey::written_size_delta(tenant_id, timeline_id); + + let last_stop_time = cache + .get(written_size_delta_key.key()) + .map(|(until, _val)| { + until + .incremental_timerange() + .expect("never create EventType::Absolute for written_size_delta") + .end + }); + + let (key, written_size_now) = + MetricsKey::written_size(tenant_id, timeline_id).at(now, timeline_written_size); + + // by default, use the last sent written_size as the basis for + // calculating the delta. if we don't yet have one, use the load time value. + let prev = cache + .get(&key) + .map(|(prev_at, prev)| { + // use the prev time from our last incremental update, or default to latest + // absolute update on the first round. + let prev_at = prev_at + .absolute_time() + .expect("never create EventType::Incremental for written_size"); + let prev_at = last_stop_time.unwrap_or(prev_at); + (*prev_at, *prev) + }) + .unwrap_or_else(|| { + // if we don't have a previous point of comparison, compare to the load time + // lsn. + let (disk_consistent_lsn, loaded_at) = &self.loaded_at; + (DateTime::from(*loaded_at), disk_consistent_lsn.0) + }); + + let up_to = now; + + if let Some(delta) = written_size_now.1.checked_sub(prev.1) { + let key_value = written_size_delta_key.from_previous_up_to(prev.0, up_to, delta); + // written_size_delta + metrics.push(key_value); + // written_size + metrics.push((key, written_size_now)); + } else { + // the cached value was ahead of us, report zero until we've caught up + metrics.push(written_size_delta_key.from_previous_up_to(prev.0, up_to, 0)); + // the cached value was ahead of us, report the same until we've caught up + metrics.push((key, (written_size_now.0, prev.1))); + } + + { + let factory = MetricsKey::timeline_logical_size(tenant_id, timeline_id); + let current_or_previous = self + .current_exact_logical_size + .or_else(|| cache.get(factory.key()).map(|(_, val)| *val)); + + if let Some(size) = current_or_previous { + metrics.push(factory.at(now, size)); + } + } + } +} + +#[cfg(test)] +mod tests; diff --git a/pageserver/src/consumption_metrics/metrics/tests.rs b/pageserver/src/consumption_metrics/metrics/tests.rs new file mode 100644 index 0000000000..f47bccce54 --- /dev/null +++ b/pageserver/src/consumption_metrics/metrics/tests.rs @@ -0,0 +1,361 @@ +use std::collections::HashMap; + +use std::time::SystemTime; +use utils::{ + id::{TenantId, TimelineId}, + lsn::Lsn, +}; + +use super::*; +use chrono::{DateTime, Utc}; + +#[test] +fn startup_collected_timeline_metrics_before_advancing() { + let tenant_id = TenantId::generate(); + let timeline_id = TimelineId::generate(); + + let mut metrics = Vec::new(); + let cache = HashMap::new(); + + let initdb_lsn = Lsn(0x10000); + let disk_consistent_lsn = Lsn(initdb_lsn.0 * 2); + + let snap = TimelineSnapshot { + loaded_at: (disk_consistent_lsn, SystemTime::now()), + last_record_lsn: disk_consistent_lsn, + current_exact_logical_size: Some(0x42000), + }; + + let now = DateTime::::from(SystemTime::now()); + + snap.to_metrics(tenant_id, timeline_id, now, &mut metrics, &cache); + + assert_eq!( + metrics, + &[ + MetricsKey::written_size_delta(tenant_id, timeline_id).from_previous_up_to( + snap.loaded_at.1.into(), + now, + 0 + ), + MetricsKey::written_size(tenant_id, timeline_id).at(now, disk_consistent_lsn.0), + MetricsKey::timeline_logical_size(tenant_id, timeline_id).at(now, 0x42000) + ] + ); +} + +#[test] +fn startup_collected_timeline_metrics_second_round() { + let tenant_id = TenantId::generate(); + let timeline_id = TimelineId::generate(); + + let [now, before, init] = time_backwards(); + + let now = DateTime::::from(now); + let before = DateTime::::from(before); + + let initdb_lsn = Lsn(0x10000); + let disk_consistent_lsn = Lsn(initdb_lsn.0 * 2); + + let mut metrics = Vec::new(); + let cache = HashMap::from([ + MetricsKey::written_size(tenant_id, timeline_id).at(before, disk_consistent_lsn.0) + ]); + + let snap = TimelineSnapshot { + loaded_at: (disk_consistent_lsn, init), + last_record_lsn: disk_consistent_lsn, + current_exact_logical_size: Some(0x42000), + }; + + snap.to_metrics(tenant_id, timeline_id, now, &mut metrics, &cache); + + assert_eq!( + metrics, + &[ + MetricsKey::written_size_delta(tenant_id, timeline_id) + .from_previous_up_to(before, now, 0), + MetricsKey::written_size(tenant_id, timeline_id).at(now, disk_consistent_lsn.0), + MetricsKey::timeline_logical_size(tenant_id, timeline_id).at(now, 0x42000) + ] + ); +} + +#[test] +fn startup_collected_timeline_metrics_nth_round_at_same_lsn() { + let tenant_id = TenantId::generate(); + let timeline_id = TimelineId::generate(); + + let [now, just_before, before, init] = time_backwards(); + + let now = DateTime::::from(now); + let just_before = DateTime::::from(just_before); + let before = DateTime::::from(before); + + let initdb_lsn = Lsn(0x10000); + let disk_consistent_lsn = Lsn(initdb_lsn.0 * 2); + + let mut metrics = Vec::new(); + let cache = HashMap::from([ + // at t=before was the last time the last_record_lsn changed + MetricsKey::written_size(tenant_id, timeline_id).at(before, disk_consistent_lsn.0), + // end time of this event is used for the next ones + MetricsKey::written_size_delta(tenant_id, timeline_id).from_previous_up_to( + before, + just_before, + 0, + ), + ]); + + let snap = TimelineSnapshot { + loaded_at: (disk_consistent_lsn, init), + last_record_lsn: disk_consistent_lsn, + current_exact_logical_size: Some(0x42000), + }; + + snap.to_metrics(tenant_id, timeline_id, now, &mut metrics, &cache); + + assert_eq!( + metrics, + &[ + MetricsKey::written_size_delta(tenant_id, timeline_id).from_previous_up_to( + just_before, + now, + 0 + ), + MetricsKey::written_size(tenant_id, timeline_id).at(now, disk_consistent_lsn.0), + MetricsKey::timeline_logical_size(tenant_id, timeline_id).at(now, 0x42000) + ] + ); +} + +#[test] +fn metric_image_stability() { + // it is important that these strings stay as they are + + let tenant_id = TenantId::from_array([0; 16]); + let timeline_id = TimelineId::from_array([0xff; 16]); + + let now = DateTime::parse_from_rfc3339("2023-09-15T00:00:00.123456789Z").unwrap(); + let before = DateTime::parse_from_rfc3339("2023-09-14T00:00:00.123456789Z").unwrap(); + + let [now, before] = [DateTime::::from(now), DateTime::from(before)]; + + let examples = [ + ( + line!(), + MetricsKey::written_size(tenant_id, timeline_id).at(now, 0), + r#"{"type":"absolute","time":"2023-09-15T00:00:00.123456789Z","metric":"written_size","idempotency_key":"2023-09-15 00:00:00.123456789 UTC-1-0000","value":0,"tenant_id":"00000000000000000000000000000000","timeline_id":"ffffffffffffffffffffffffffffffff"}"#, + ), + ( + line!(), + MetricsKey::written_size_delta(tenant_id, timeline_id) + .from_previous_up_to(before, now, 0), + r#"{"type":"incremental","start_time":"2023-09-14T00:00:00.123456789Z","stop_time":"2023-09-15T00:00:00.123456789Z","metric":"written_data_bytes_delta","idempotency_key":"2023-09-15 00:00:00.123456789 UTC-1-0000","value":0,"tenant_id":"00000000000000000000000000000000","timeline_id":"ffffffffffffffffffffffffffffffff"}"#, + ), + ( + line!(), + MetricsKey::timeline_logical_size(tenant_id, timeline_id).at(now, 0), + r#"{"type":"absolute","time":"2023-09-15T00:00:00.123456789Z","metric":"timeline_logical_size","idempotency_key":"2023-09-15 00:00:00.123456789 UTC-1-0000","value":0,"tenant_id":"00000000000000000000000000000000","timeline_id":"ffffffffffffffffffffffffffffffff"}"#, + ), + ( + line!(), + MetricsKey::remote_storage_size(tenant_id).at(now, 0), + r#"{"type":"absolute","time":"2023-09-15T00:00:00.123456789Z","metric":"remote_storage_size","idempotency_key":"2023-09-15 00:00:00.123456789 UTC-1-0000","value":0,"tenant_id":"00000000000000000000000000000000"}"#, + ), + ( + line!(), + MetricsKey::resident_size(tenant_id).at(now, 0), + r#"{"type":"absolute","time":"2023-09-15T00:00:00.123456789Z","metric":"resident_size","idempotency_key":"2023-09-15 00:00:00.123456789 UTC-1-0000","value":0,"tenant_id":"00000000000000000000000000000000"}"#, + ), + ( + line!(), + MetricsKey::synthetic_size(tenant_id).at(now, 1), + r#"{"type":"absolute","time":"2023-09-15T00:00:00.123456789Z","metric":"synthetic_storage_size","idempotency_key":"2023-09-15 00:00:00.123456789 UTC-1-0000","value":1,"tenant_id":"00000000000000000000000000000000"}"#, + ), + ]; + + let idempotency_key = consumption_metrics::IdempotencyKey::for_tests(now, "1", 0); + + for (line, (key, (kind, value)), expected) in examples { + let e = consumption_metrics::Event { + kind, + metric: key.metric, + idempotency_key: idempotency_key.to_string(), + value, + extra: Ids { + tenant_id: key.tenant_id, + timeline_id: key.timeline_id, + }, + }; + let actual = serde_json::to_string(&e).unwrap(); + assert_eq!(expected, actual, "example from line {line}"); + } +} + +#[test] +fn post_restart_written_sizes_with_rolled_back_last_record_lsn() { + // it can happen that we lose the inmemorylayer but have previously sent metrics and we + // should never go backwards + + let tenant_id = TenantId::generate(); + let timeline_id = TimelineId::generate(); + + let [later, now, at_restart] = time_backwards(); + + // FIXME: tests would be so much easier if we did not need to juggle back and forth + // SystemTime and DateTime:: ... Could do the conversion only at upload time? + let now = DateTime::::from(now); + let later = DateTime::::from(later); + let before_restart = at_restart - std::time::Duration::from_secs(5 * 60); + let way_before = before_restart - std::time::Duration::from_secs(10 * 60); + let before_restart = DateTime::::from(before_restart); + let way_before = DateTime::::from(way_before); + + let snap = TimelineSnapshot { + loaded_at: (Lsn(50), at_restart), + last_record_lsn: Lsn(50), + current_exact_logical_size: None, + }; + + let mut cache = HashMap::from([ + MetricsKey::written_size(tenant_id, timeline_id).at(before_restart, 100), + MetricsKey::written_size_delta(tenant_id, timeline_id).from_previous_up_to( + way_before, + before_restart, + // not taken into account, but the timestamps are important + 999_999_999, + ), + ]); + + let mut metrics = Vec::new(); + snap.to_metrics(tenant_id, timeline_id, now, &mut metrics, &cache); + + assert_eq!( + metrics, + &[ + MetricsKey::written_size_delta(tenant_id, timeline_id).from_previous_up_to( + before_restart, + now, + 0 + ), + MetricsKey::written_size(tenant_id, timeline_id).at(now, 100), + ] + ); + + // now if we cache these metrics, and re-run while "still in recovery" + cache.extend(metrics.drain(..)); + + // "still in recovery", because our snapshot did not change + snap.to_metrics(tenant_id, timeline_id, later, &mut metrics, &cache); + + assert_eq!( + metrics, + &[ + MetricsKey::written_size_delta(tenant_id, timeline_id) + .from_previous_up_to(now, later, 0), + MetricsKey::written_size(tenant_id, timeline_id).at(later, 100), + ] + ); +} + +#[test] +fn post_restart_current_exact_logical_size_uses_cached() { + let tenant_id = TenantId::generate(); + let timeline_id = TimelineId::generate(); + + let [now, at_restart] = time_backwards(); + + let now = DateTime::::from(now); + let before_restart = at_restart - std::time::Duration::from_secs(5 * 60); + let before_restart = DateTime::::from(before_restart); + + let snap = TimelineSnapshot { + loaded_at: (Lsn(50), at_restart), + last_record_lsn: Lsn(50), + current_exact_logical_size: None, + }; + + let cache = HashMap::from([ + MetricsKey::timeline_logical_size(tenant_id, timeline_id).at(before_restart, 100) + ]); + + let mut metrics = Vec::new(); + snap.to_metrics(tenant_id, timeline_id, now, &mut metrics, &cache); + + metrics.retain(|(key, _)| key.metric == Name::LogicalSize); + + assert_eq!( + metrics, + &[MetricsKey::timeline_logical_size(tenant_id, timeline_id).at(now, 100)] + ); +} + +#[test] +fn post_restart_synthetic_size_uses_cached_if_available() { + let tenant_id = TenantId::generate(); + + let ts = TenantSnapshot { + resident_size: 1000, + remote_size: 1000, + // not yet calculated + synthetic_size: 0, + }; + + let now = SystemTime::now(); + let before_restart = DateTime::::from(now - std::time::Duration::from_secs(5 * 60)); + let now = DateTime::::from(now); + + let cached = HashMap::from([MetricsKey::synthetic_size(tenant_id).at(before_restart, 1000)]); + + let mut metrics = Vec::new(); + ts.to_metrics(tenant_id, now, &cached, &mut metrics); + + assert_eq!( + metrics, + &[ + MetricsKey::remote_storage_size(tenant_id).at(now, 1000), + MetricsKey::resident_size(tenant_id).at(now, 1000), + MetricsKey::synthetic_size(tenant_id).at(now, 1000), + ] + ); +} + +#[test] +fn post_restart_synthetic_size_is_not_sent_when_not_cached() { + let tenant_id = TenantId::generate(); + + let ts = TenantSnapshot { + resident_size: 1000, + remote_size: 1000, + // not yet calculated + synthetic_size: 0, + }; + + let now = SystemTime::now(); + let now = DateTime::::from(now); + + let cached = HashMap::new(); + + let mut metrics = Vec::new(); + ts.to_metrics(tenant_id, now, &cached, &mut metrics); + + assert_eq!( + metrics, + &[ + MetricsKey::remote_storage_size(tenant_id).at(now, 1000), + MetricsKey::resident_size(tenant_id).at(now, 1000), + // no synthetic size here + ] + ); +} + +fn time_backwards() -> [std::time::SystemTime; N] { + let mut times = [std::time::SystemTime::UNIX_EPOCH; N]; + times[0] = std::time::SystemTime::now(); + for behind in 1..N { + times[behind] = times[0] - std::time::Duration::from_secs(behind as u64); + } + + times +} diff --git a/pageserver/src/consumption_metrics/upload.rs b/pageserver/src/consumption_metrics/upload.rs new file mode 100644 index 0000000000..6f6b263884 --- /dev/null +++ b/pageserver/src/consumption_metrics/upload.rs @@ -0,0 +1,177 @@ +use consumption_metrics::{idempotency_key, Event, EventChunk, CHUNK_SIZE}; +use tokio_util::sync::CancellationToken; +use tracing::*; + +use super::{Cache, Ids, RawMetric}; + +#[tracing::instrument(skip_all, fields(metrics_total = %metrics.len()))] +pub(super) async fn upload_metrics( + client: &reqwest::Client, + metric_collection_endpoint: &reqwest::Url, + cancel: &CancellationToken, + node_id: &str, + metrics: &[RawMetric], + cached_metrics: &mut Cache, +) -> anyhow::Result<()> { + use bytes::BufMut; + + let mut uploaded = 0; + let mut failed = 0; + + let started_at = std::time::Instant::now(); + + // write to a BytesMut so that we can cheaply clone the frozen Bytes for retries + let mut buffer = bytes::BytesMut::new(); + let mut chunk_to_send = Vec::new(); + + for chunk in metrics.chunks(CHUNK_SIZE) { + chunk_to_send.clear(); + + // FIXME: this should always overwrite and truncate to chunk.len() + chunk_to_send.extend(chunk.iter().map(|(curr_key, (when, curr_val))| Event { + kind: *when, + metric: curr_key.metric, + // FIXME: finally write! this to the prev allocation + idempotency_key: idempotency_key(node_id), + value: *curr_val, + extra: Ids { + tenant_id: curr_key.tenant_id, + timeline_id: curr_key.timeline_id, + }, + })); + + serde_json::to_writer( + (&mut buffer).writer(), + &EventChunk { + events: (&chunk_to_send).into(), + }, + )?; + + let body = buffer.split().freeze(); + let event_bytes = body.len(); + + let res = upload(client, metric_collection_endpoint, body, cancel) + .instrument(tracing::info_span!( + "upload", + %event_bytes, + uploaded, + total = metrics.len(), + )) + .await; + + match res { + Ok(()) => { + for (curr_key, curr_val) in chunk { + cached_metrics.insert(*curr_key, *curr_val); + } + uploaded += chunk.len(); + } + Err(_) => { + // failure(s) have already been logged + // + // however this is an inconsistency: if we crash here, we will start with the + // values as uploaded. in practice, the rejections no longer happen. + failed += chunk.len(); + } + } + } + + let elapsed = started_at.elapsed(); + + tracing::info!( + uploaded, + failed, + elapsed_ms = elapsed.as_millis(), + "done sending metrics" + ); + + Ok(()) +} + +enum UploadError { + Rejected(reqwest::StatusCode), + Reqwest(reqwest::Error), + Cancelled, +} + +impl std::fmt::Debug for UploadError { + fn fmt(&self, f: &mut std::fmt::Formatter<'_>) -> std::fmt::Result { + // use same impl because backoff::retry will log this using both + std::fmt::Display::fmt(self, f) + } +} + +impl std::fmt::Display for UploadError { + fn fmt(&self, f: &mut std::fmt::Formatter<'_>) -> std::fmt::Result { + use UploadError::*; + + match self { + Rejected(code) => write!(f, "server rejected the metrics with {code}"), + Reqwest(e) => write!(f, "request failed: {e}"), + Cancelled => write!(f, "cancelled"), + } + } +} + +impl UploadError { + fn is_reject(&self) -> bool { + matches!(self, UploadError::Rejected(_)) + } +} + +async fn upload( + client: &reqwest::Client, + metric_collection_endpoint: &reqwest::Url, + body: bytes::Bytes, + cancel: &CancellationToken, +) -> Result<(), UploadError> { + let warn_after = 3; + let max_attempts = 10; + let res = utils::backoff::retry( + move || { + let body = body.clone(); + async move { + let res = client + .post(metric_collection_endpoint.clone()) + .header(reqwest::header::CONTENT_TYPE, "application/json") + .body(body) + .send() + .await; + + let res = res.and_then(|res| res.error_for_status()); + + match res { + Ok(_response) => Ok(()), + Err(e) => { + let status = e.status().filter(|s| s.is_client_error()); + if let Some(status) = status { + Err(UploadError::Rejected(status)) + } else { + Err(UploadError::Reqwest(e)) + } + } + } + } + }, + UploadError::is_reject, + warn_after, + max_attempts, + "upload consumption_metrics", + utils::backoff::Cancel::new(cancel.clone(), || UploadError::Cancelled), + ) + .await; + + match &res { + Ok(_) => {} + Err(e) if e.is_reject() => { + // permanent errors currently do not get logged by backoff::retry + // display alternate has no effect, but keeping it here for easier pattern matching. + tracing::error!("failed to upload metrics: {e:#}"); + } + Err(_) => { + // these have been logged already + } + } + + res +} From 55371af71106b3b8a6ddb3231ed6d73bf18a8848 Mon Sep 17 00:00:00 2001 From: Joonas Koivunen Date: Mon, 18 Sep 2023 10:24:53 +0300 Subject: [PATCH 17/22] test: workaround known bad mock_s3 ListObjectsV2 response (#5330) this should allow test test_delete_tenant_exercise_crash_safety_failpoints with debug-pg16-Check.RETRY_WITH_RESTART-mock_s3-tenant-delete-before-remove-timelines-dir-True to pass more reliably. --- test_runner/fixtures/pageserver/utils.py | 28 +++++++++++++++++------- test_runner/fixtures/remote_storage.py | 4 ++++ 2 files changed, 24 insertions(+), 8 deletions(-) diff --git a/test_runner/fixtures/pageserver/utils.py b/test_runner/fixtures/pageserver/utils.py index 3197017bd1..2e5d75a0fc 100644 --- a/test_runner/fixtures/pageserver/utils.py +++ b/test_runner/fixtures/pageserver/utils.py @@ -236,15 +236,27 @@ def assert_prefix_empty(neon_env_builder: "NeonEnvBuilder", prefix: Optional[str response = list_prefix(neon_env_builder, prefix) keys = response["KeyCount"] objects = response.get("Contents", []) + common_prefixes = response.get("CommonPrefixes", []) - if keys != 0 and len(objects) == 0: - # this has been seen in one case with mock_s3: - # https://neon-github-public-dev.s3.amazonaws.com/reports/pr-4938/6000769714/index.html#suites/3556ed71f2d69272a7014df6dcb02317/ca01e4f4d8d9a11f - # looking at moto impl, it might be there's a race with common prefix (sub directory) not going away with deletes - common_prefixes = response.get("CommonPrefixes", []) - log.warn( - f"contradicting ListObjectsV2 response with KeyCount={keys} and Contents={objects}, CommonPrefixes={common_prefixes}" - ) + remote_storage = neon_env_builder.pageserver_remote_storage + is_mock_s3 = isinstance(remote_storage, S3Storage) and not remote_storage.cleanup + + if is_mock_s3: + if keys == 1 and len(objects) == 0 and len(common_prefixes) == 1: + # this has been seen in the wild by tests with the below contradicting logging + # https://neon-github-public-dev.s3.amazonaws.com/reports/pr-5322/6207777020/index.html#suites/3556ed71f2d69272a7014df6dcb02317/53b5c368b5a68865 + # this seems like a mock_s3 issue + log.warn( + f"contrading ListObjectsV2 response with KeyCount={keys} and Contents={objects}, CommonPrefixes={common_prefixes}, assuming this means KeyCount=0" + ) + keys = 0 + elif keys != 0 and len(objects) == 0: + # this has been seen in one case with mock_s3: + # https://neon-github-public-dev.s3.amazonaws.com/reports/pr-4938/6000769714/index.html#suites/3556ed71f2d69272a7014df6dcb02317/ca01e4f4d8d9a11f + # looking at moto impl, it might be there's a race with common prefix (sub directory) not going away with deletes + log.warn( + f"contradicting ListObjectsV2 response with KeyCount={keys} and Contents={objects}, CommonPrefixes={common_prefixes}" + ) assert keys == 0, f"remote dir with prefix {prefix} is not empty after deletion: {objects}" diff --git a/test_runner/fixtures/remote_storage.py b/test_runner/fixtures/remote_storage.py index ca7ad93f83..f7cddbc821 100644 --- a/test_runner/fixtures/remote_storage.py +++ b/test_runner/fixtures/remote_storage.py @@ -115,6 +115,8 @@ class S3Storage: prefix_in_bucket: str client: S3Client cleanup: bool + """Is this MOCK_S3 (false) or REAL_S3 (true)""" + real: bool endpoint: Optional[str] = None def access_env_vars(self) -> Dict[str, str]: @@ -265,6 +267,7 @@ class RemoteStorageKind(str, enum.Enum): prefix_in_bucket="", client=client, cleanup=False, + real=False, ) assert self == RemoteStorageKind.REAL_S3 @@ -300,6 +303,7 @@ class RemoteStorageKind(str, enum.Enum): prefix_in_bucket=prefix_in_bucket, client=client, cleanup=True, + real=True, ) From 0904d8cf4a5841ed9999fd36fa2b5442d19f90dd Mon Sep 17 00:00:00 2001 From: Alexander Bayandin Date: Mon, 18 Sep 2023 12:55:49 +0100 Subject: [PATCH 18/22] Downgrade plv8 for Postgres 14/15 (#5320) Backport https://github.com/neondatabase/neon/pull/5318 from release into main --- Dockerfile.compute-node | 17 +++++++++++++++-- 1 file changed, 15 insertions(+), 2 deletions(-) diff --git a/Dockerfile.compute-node b/Dockerfile.compute-node index d724185d5d..892c5e93f3 100644 --- a/Dockerfile.compute-node +++ b/Dockerfile.compute-node @@ -124,8 +124,21 @@ COPY --from=pg-build /usr/local/pgsql/ /usr/local/pgsql/ RUN apt update && \ apt install -y ninja-build python3-dev libncurses5 binutils clang -RUN wget https://github.com/plv8/plv8/archive/refs/tags/v3.1.8.tar.gz -O plv8.tar.gz && \ - echo "92b10c7db39afdae97ff748c9ec54713826af222c459084ad002571b79eb3f49 plv8.tar.gz" | sha256sum --check && \ +RUN case "${PG_VERSION}" in \ + "v14" | "v15") \ + export PLV8_VERSION=3.1.5 \ + export PLV8_CHECKSUM=1e108d5df639e4c189e1c5bdfa2432a521c126ca89e7e5a969d46899ca7bf106 \ + ;; \ + "v16") \ + export PLV8_VERSION=3.1.8 \ + export PLV8_CHECKSUM=92b10c7db39afdae97ff748c9ec54713826af222c459084ad002571b79eb3f49 \ + ;; \ + *) \ + echo "Export the valid PG_VERSION variable" && exit 1 \ + ;; \ + esac && \ + wget https://github.com/plv8/plv8/archive/refs/tags/v${PLV8_VERSION}.tar.gz -O plv8.tar.gz && \ + echo "${PLV8_CHECKSUM} plv8.tar.gz" | sha256sum --check && \ mkdir plv8-src && cd plv8-src && tar xvzf ../plv8.tar.gz --strip-components=1 -C . && \ export PATH="/usr/local/pgsql/bin:$PATH" && \ make DOCKER=1 -j $(getconf _NPROCESSORS_ONLN) install && \ From 70b17981a770510de19cba6ed1e6f54afba77047 Mon Sep 17 00:00:00 2001 From: Alexander Bayandin Date: Mon, 18 Sep 2023 12:58:34 +0100 Subject: [PATCH 19/22] Enable compatibility tests on Postgres 16 (#5314) ## Problem We didn't have a Postgres 16 snapshot of data to run compatibility tests on, but now we have it (since the release). ## Summary of changes - remove `@skip_on_postgres(PgVersion.V16, ...)` from compatibility tests --- test_runner/regress/test_compatibility.py | 4 +--- 1 file changed, 1 insertion(+), 3 deletions(-) diff --git a/test_runner/regress/test_compatibility.py b/test_runner/regress/test_compatibility.py index 480caf6bf6..161662bc99 100644 --- a/test_runner/regress/test_compatibility.py +++ b/test_runner/regress/test_compatibility.py @@ -20,7 +20,7 @@ from fixtures.pageserver.utils import ( wait_for_last_record_lsn, wait_for_upload, ) -from fixtures.pg_version import PgVersion, skip_on_postgres +from fixtures.pg_version import PgVersion from fixtures.port_distributor import PortDistributor from fixtures.remote_storage import LocalFsStorage, RemoteStorageKind, RemoteStorageUser from fixtures.types import Lsn @@ -151,7 +151,6 @@ def test_create_snapshot( shutil.copytree(test_output_dir, compatibility_snapshot_dir) -@skip_on_postgres(PgVersion.V16, reason="TODO: Enable after the first Postgres 16 release") @check_ondisk_data_compatibility_if_enabled @pytest.mark.xdist_group("compatibility") @pytest.mark.order(after="test_create_snapshot") @@ -209,7 +208,6 @@ def test_backward_compatibility( ), "Breaking changes are allowed by ALLOW_BACKWARD_COMPATIBILITY_BREAKAGE, but the test has passed without any breakage" -@skip_on_postgres(PgVersion.V16, reason="TODO: Enable after the first Postgres 16 release") @check_ondisk_data_compatibility_if_enabled @pytest.mark.xdist_group("compatibility") @pytest.mark.order(after="test_create_snapshot") From 18f3a706daef21805a2e331992fba27abda4d255 Mon Sep 17 00:00:00 2001 From: Em Sharnoff Date: Mon, 18 Sep 2023 10:30:34 -0700 Subject: [PATCH 20/22] Bump vm-builder v0.17.5 -> v0.17.10 (#5334) Only notable change is including neondatabase/autoscaling#523, which we hope will help with making sure that TCP connections are properly terminated before shutdown (which hopefully fixes a leak in the pageserver). --- .github/workflows/build_and_test.yml | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/.github/workflows/build_and_test.yml b/.github/workflows/build_and_test.yml index a2376f6d15..d31c8ad66e 100644 --- a/.github/workflows/build_and_test.yml +++ b/.github/workflows/build_and_test.yml @@ -834,7 +834,7 @@ jobs: run: shell: sh -eu {0} env: - VM_BUILDER_VERSION: v0.17.5 + VM_BUILDER_VERSION: v0.17.10 steps: - name: Checkout From 722e5260bf51e063b7f9b8d8664fb56dea91b896 Mon Sep 17 00:00:00 2001 From: Em Sharnoff Date: Mon, 18 Sep 2023 10:47:48 -0700 Subject: [PATCH 21/22] vm-monitor: Don't set cgroup memory.max (#5333) All it does is make postgres OOM more often (which, tbf, means we're less likely to have e.g. compute_ctl get OOM-killed, but that tradeoff isn't worth it). Internally, this means removing all references to `memory.max` and the places where we calculate or store the intended value. As discussed in the sync earlier. ref: - https://neondb.slack.com/archives/C03H1K0PGKH/p1694698949252439?thread_ts=1694505575.693449&cid=C03H1K0PGKH - https://neondb.slack.com/archives/C03H1K0PGKH/p1695049198622759 --- libs/vm_monitor/src/cgroup.rs | 20 ++++---------------- libs/vm_monitor/src/runner.rs | 11 ++++++----- 2 files changed, 10 insertions(+), 21 deletions(-) diff --git a/libs/vm_monitor/src/cgroup.rs b/libs/vm_monitor/src/cgroup.rs index fe1c514f76..3254fa4501 100644 --- a/libs/vm_monitor/src/cgroup.rs +++ b/libs/vm_monitor/src/cgroup.rs @@ -561,14 +561,7 @@ impl CgroupWatcher { /// Setting these values also affects the thresholds for receiving usage alerts. #[derive(Debug)] pub struct MemoryLimits { - high: u64, - max: u64, -} - -impl MemoryLimits { - pub fn new(high: u64, max: u64) -> Self { - Self { max, high } - } + pub high: u64, } // Methods for manipulating the actual cgroup @@ -645,12 +638,7 @@ impl CgroupWatcher { /// Set cgroup memory.high and memory.max. pub fn set_limits(&self, limits: &MemoryLimits) -> anyhow::Result<()> { - info!( - limits.high, - limits.max, - path = self.path(), - "writing new memory limits", - ); + info!(limits.high, path = self.path(), "writing new memory limits",); self.memory() .context("failed to get memory subsystem while setting memory limits")? .set_mem(cgroups_rs::memory::SetMemory { @@ -659,7 +647,7 @@ impl CgroupWatcher { high: Some(MaxValue::Value( u64::min(limits.high, i64::MAX as u64) as i64 )), - max: Some(MaxValue::Value(u64::min(limits.max, i64::MAX as u64) as i64)), + max: None, }) .context("failed to set memory limits") } @@ -667,7 +655,7 @@ impl CgroupWatcher { /// Given some amount of available memory, set the desired cgroup memory limits pub fn set_memory_limits(&mut self, available_memory: u64) -> anyhow::Result<()> { let new_high = self.config.calculate_memory_high_value(available_memory); - let limits = MemoryLimits::new(new_high, available_memory); + let limits = MemoryLimits { high: new_high }; info!( path = self.path(), memory = ?limits, diff --git a/libs/vm_monitor/src/runner.rs b/libs/vm_monitor/src/runner.rs index 8f904b879d..376017d784 100644 --- a/libs/vm_monitor/src/runner.rs +++ b/libs/vm_monitor/src/runner.rs @@ -257,12 +257,11 @@ impl Runner { new_cgroup_mem_high = cgroup.config.calculate_memory_high_value(available_memory); } - let limits = MemoryLimits::new( + let limits = MemoryLimits { // new_cgroup_mem_high is initialized to 0 but it is guarancontextd to not be here // since it is properly initialized in the previous cgroup if let block - new_cgroup_mem_high, - available_memory, - ); + high: new_cgroup_mem_high, + }; cgroup .set_limits(&limits) .context("failed to set cgroup memory limits")?; @@ -328,7 +327,9 @@ impl Runner { name = cgroup.path(), "updating cgroup memory.high", ); - let limits = MemoryLimits::new(new_cgroup_mem_high, available_memory); + let limits = MemoryLimits { + high: new_cgroup_mem_high, + }; cgroup .set_limits(&limits) .context("failed to set file cache size")?; From 5d8597c2f0d19440eb4a5f744b0559263a35487f Mon Sep 17 00:00:00 2001 From: Joonas Koivunen Date: Mon, 18 Sep 2023 23:30:01 +0300 Subject: [PATCH 22/22] refactor(consumption_metrics): post-split cleanup (#5327) MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit Split off from #5297. Builds upon #5326. Handles original review comments which I did not move to earlier split PRs. Completes test support for verifying events by notifying of the last batch of events. Adds cleaning up of tempfiles left because of an unlucky shutdown or SIGKILL. Finally closes #5175. Co-authored-by: Arpad Müller --- libs/consumption_metrics/src/lib.rs | 6 +- pageserver/src/consumption_metrics.rs | 22 +- .../src/consumption_metrics/disk_cache.rs | 71 +++- pageserver/src/consumption_metrics/metrics.rs | 65 ++-- .../src/consumption_metrics/metrics/tests.rs | 116 ++---- pageserver/src/consumption_metrics/upload.rs | 330 ++++++++++++++++-- .../test_pageserver_metric_collection.py | 188 ++++++++-- 7 files changed, 591 insertions(+), 207 deletions(-) diff --git a/libs/consumption_metrics/src/lib.rs b/libs/consumption_metrics/src/lib.rs index 040b047d6f..7b133c61af 100644 --- a/libs/consumption_metrics/src/lib.rs +++ b/libs/consumption_metrics/src/lib.rs @@ -3,7 +3,7 @@ //! use chrono::{DateTime, Utc}; use rand::Rng; -use serde::Serialize; +use serde::{Deserialize, Serialize}; #[derive(Serialize, serde::Deserialize, Debug, Clone, Copy, Eq, PartialEq, Ord, PartialOrd)] #[serde(tag = "type")] @@ -54,8 +54,8 @@ impl EventType { } } -#[derive(Serialize, Debug, Clone, Eq, PartialEq, Ord, PartialOrd)] -pub struct Event { +#[derive(Serialize, Deserialize, Debug, Clone, Eq, PartialEq, Ord, PartialOrd)] +pub struct Event { #[serde(flatten)] #[serde(rename = "type")] pub kind: EventType, diff --git a/pageserver/src/consumption_metrics.rs b/pageserver/src/consumption_metrics.rs index 42af40d02a..5f64bb2b3b 100644 --- a/pageserver/src/consumption_metrics.rs +++ b/pageserver/src/consumption_metrics.rs @@ -14,7 +14,7 @@ use tracing::*; use utils::id::NodeId; mod metrics; -use metrics::{Ids, MetricsKey}; +use metrics::MetricsKey; mod disk_cache; mod upload; @@ -68,10 +68,11 @@ pub async fn collect_metrics( }, ); - let final_path: Arc = Arc::new(local_disk_storage); + let path: Arc = Arc::new(local_disk_storage); let cancel = task_mgr::shutdown_token(); - let restore_and_reschedule = restore_and_reschedule(&final_path, metric_collection_interval); + + let restore_and_reschedule = restore_and_reschedule(&path, metric_collection_interval); let mut cached_metrics = tokio::select! { _ = cancel.cancelled() => return Ok(()), @@ -108,14 +109,14 @@ pub async fn collect_metrics( // already here, better to try to flush the new values. let flush = async { - match disk_cache::flush_metrics_to_disk(&metrics, &final_path).await { + match disk_cache::flush_metrics_to_disk(&metrics, &path).await { Ok(()) => { tracing::debug!("flushed metrics to disk"); } Err(e) => { - // idea here is that if someone creates a directory as our final_path, then they + // idea here is that if someone creates a directory as our path, then they // might notice it from the logs before shutdown and remove it - tracing::error!("failed to persist metrics to {final_path:?}: {e:#}"); + tracing::error!("failed to persist metrics to {path:?}: {e:#}"); } } }; @@ -152,12 +153,10 @@ pub async fn collect_metrics( /// /// Cancellation safe. async fn restore_and_reschedule( - final_path: &Arc, + path: &Arc, metric_collection_interval: Duration, ) -> Cache { - let (cached, earlier_metric_at) = match disk_cache::read_metrics_from_disk(final_path.clone()) - .await - { + let (cached, earlier_metric_at) = match disk_cache::read_metrics_from_disk(path.clone()).await { Ok(found_some) => { // there is no min needed because we write these sequentially in // collect_all_metrics @@ -175,12 +174,11 @@ async fn restore_and_reschedule( use std::io::{Error, ErrorKind}; let root = e.root_cause(); - let maybe_ioerr = root.downcast_ref::(); let is_not_found = maybe_ioerr.is_some_and(|e| e.kind() == ErrorKind::NotFound); if !is_not_found { - tracing::info!("failed to read any previous metrics from {final_path:?}: {e:#}"); + tracing::info!("failed to read any previous metrics from {path:?}: {e:#}"); } (HashMap::new(), None) diff --git a/pageserver/src/consumption_metrics/disk_cache.rs b/pageserver/src/consumption_metrics/disk_cache.rs index 1fd1338c95..4b1cd79c6d 100644 --- a/pageserver/src/consumption_metrics/disk_cache.rs +++ b/pageserver/src/consumption_metrics/disk_cache.rs @@ -9,6 +9,13 @@ pub(super) async fn read_metrics_from_disk(path: Arc) -> anyhow::Result let span = tracing::Span::current(); tokio::task::spawn_blocking(move || { let _e = span.entered(); + + if let Some(parent) = path.parent() { + if let Err(e) = scan_and_delete_with_same_prefix(&path) { + tracing::info!("failed to cleanup temporary files in {parent:?}: {e:#}"); + } + } + let mut file = std::fs::File::open(&*path)?; let reader = std::io::BufReader::new(&mut file); anyhow::Ok(serde_json::from_reader::<_, Vec>(reader)?) @@ -18,26 +25,68 @@ pub(super) async fn read_metrics_from_disk(path: Arc) -> anyhow::Result .and_then(|x| x) } +fn scan_and_delete_with_same_prefix(path: &std::path::Path) -> std::io::Result<()> { + let it = std::fs::read_dir(path.parent().expect("caller checked"))?; + + let prefix = path.file_name().expect("caller checked").to_string_lossy(); + + for entry in it { + let entry = entry?; + if !entry.metadata()?.is_file() { + continue; + } + let file_name = entry.file_name(); + + if path.file_name().unwrap() == file_name { + // do not remove our actual file + continue; + } + + let file_name = file_name.to_string_lossy(); + + if !file_name.starts_with(&*prefix) { + continue; + } + + let path = entry.path(); + + if let Err(e) = std::fs::remove_file(&path) { + tracing::warn!("cleaning up old tempfile {file_name:?} failed: {e:#}"); + } else { + tracing::info!("cleaned up old tempfile {file_name:?}"); + } + } + + Ok(()) +} + pub(super) async fn flush_metrics_to_disk( current_metrics: &Arc>, - final_path: &Arc, + path: &Arc, ) -> anyhow::Result<()> { use std::io::Write; + anyhow::ensure!(path.parent().is_some(), "path must have parent: {path:?}"); anyhow::ensure!( - final_path.parent().is_some(), - "path must have parent: {final_path:?}" + path.file_name().is_some(), + "path must have filename: {path:?}" ); let span = tracing::Span::current(); tokio::task::spawn_blocking({ let current_metrics = current_metrics.clone(); - let final_path = final_path.clone(); + let path = path.clone(); move || { let _e = span.entered(); - let mut tempfile = - tempfile::NamedTempFile::new_in(final_path.parent().expect("existence checked"))?; + let parent = path.parent().expect("existence checked"); + let file_name = path.file_name().expect("existence checked"); + let mut tempfile = tempfile::Builder::new() + .prefix(file_name) + .suffix(".tmp") + .tempfile_in(parent)?; + + tracing::debug!("using tempfile {:?}", tempfile.path()); // write out all of the raw metrics, to be read out later on restart as cached values { @@ -52,15 +101,17 @@ pub(super) async fn flush_metrics_to_disk( tempfile.flush()?; tempfile.as_file().sync_all()?; - drop(tempfile.persist(&*final_path)?); + fail::fail_point!("before-persist-last-metrics-collected"); - let f = std::fs::File::open(final_path.parent().unwrap())?; + drop(tempfile.persist(&*path).map_err(|e| e.error)?); + + let f = std::fs::File::open(path.parent().unwrap())?; f.sync_all()?; anyhow::Ok(()) } }) .await - .with_context(|| format!("write metrics to {final_path:?} join error")) - .and_then(|x| x.with_context(|| format!("write metrics to {final_path:?}"))) + .with_context(|| format!("write metrics to {path:?} join error")) + .and_then(|x| x.with_context(|| format!("write metrics to {path:?}"))) } diff --git a/pageserver/src/consumption_metrics/metrics.rs b/pageserver/src/consumption_metrics/metrics.rs index e03d2dc34f..652dd98683 100644 --- a/pageserver/src/consumption_metrics/metrics.rs +++ b/pageserver/src/consumption_metrics/metrics.rs @@ -1,36 +1,21 @@ use crate::context::RequestContext; -use crate::tenant::mgr; +use anyhow::Context; use chrono::{DateTime, Utc}; use consumption_metrics::EventType; use futures::stream::StreamExt; -use pageserver_api::models::TenantState; -use serde::Serialize; -use serde_with::{serde_as, DisplayFromStr}; -use std::sync::Arc; -use std::time::SystemTime; -use utils::id::{TenantId, TimelineId}; -use utils::lsn::Lsn; - -use anyhow::Context; +use serde_with::serde_as; +use std::{sync::Arc, time::SystemTime}; +use utils::{ + id::{TenantId, TimelineId}, + lsn::Lsn, +}; use super::{Cache, RawMetric}; -// FIXME: all other consumption_metrics::Event stuff is over at uploading, maybe move? -#[serde_as] -#[derive(Serialize, serde::Deserialize, Debug, Clone, Copy)] -pub(super) struct Ids { - #[serde_as(as = "DisplayFromStr")] - pub(super) tenant_id: TenantId, - #[serde_as(as = "Option")] - #[serde(skip_serializing_if = "Option::is_none")] - pub(super) timeline_id: Option, -} - /// Name of the metric, used by `MetricsKey` factory methods and `deserialize_cached_events` /// instead of static str. // Do not rename any of these without first consulting with data team and partner // management. -// FIXME: write those tests before refactoring to this! #[derive(Debug, Clone, Copy, PartialEq, Eq, Hash, serde::Serialize, serde::Deserialize)] pub(super) enum Name { /// Timeline last_record_lsn, absolute @@ -59,7 +44,7 @@ pub(super) enum Name { /// elsewhere. #[serde_with::serde_as] #[derive(Debug, Clone, Copy, PartialEq, Eq, Hash, serde::Serialize, serde::Deserialize)] -pub(super) struct MetricsKey { +pub(crate) struct MetricsKey { #[serde_as(as = "serde_with::DisplayFromStr")] pub(super) tenant_id: TenantId, @@ -83,7 +68,7 @@ impl MetricsKey { struct AbsoluteValueFactory(MetricsKey); impl AbsoluteValueFactory { - fn at(self, time: DateTime, val: u64) -> RawMetric { + const fn at(self, time: DateTime, val: u64) -> RawMetric { let key = self.0; (key, (EventType::Absolute { time }, val)) } @@ -98,7 +83,7 @@ struct IncrementalValueFactory(MetricsKey); impl IncrementalValueFactory { #[allow(clippy::wrong_self_convention)] - fn from_previous_up_to( + const fn from_until( self, prev_end: DateTime, up_to: DateTime, @@ -106,16 +91,11 @@ impl IncrementalValueFactory { ) -> RawMetric { let key = self.0; // cannot assert prev_end < up_to because these are realtime clock based - ( - key, - ( - EventType::Incremental { - start_time: prev_end, - stop_time: up_to, - }, - val, - ), - ) + let when = EventType::Incremental { + start_time: prev_end, + stop_time: up_to, + }; + (key, (when, val)) } fn key(&self) -> &MetricsKey { @@ -209,9 +189,11 @@ pub(super) async fn collect_all_metrics( cached_metrics: &Cache, ctx: &RequestContext, ) -> Vec { + use pageserver_api::models::TenantState; + let started_at = std::time::Instant::now(); - let tenants = match mgr::list_tenants().await { + let tenants = match crate::tenant::mgr::list_tenants().await { Ok(tenants) => tenants, Err(err) => { tracing::error!("failed to list tenants: {:?}", err); @@ -223,7 +205,7 @@ pub(super) async fn collect_all_metrics( if state != TenantState::Active { None } else { - mgr::get_tenant(id, true) + crate::tenant::mgr::get_tenant(id, true) .await .ok() .map(|tenant| (id, tenant)) @@ -285,7 +267,7 @@ where current_metrics } -/// Testing helping in-between abstraction allowing testing metrics without actual Tenants. +/// In-between abstraction to allow testing metrics without actual Tenants. struct TenantSnapshot { resident_size: u64, remote_size: u64, @@ -441,14 +423,14 @@ impl TimelineSnapshot { let up_to = now; if let Some(delta) = written_size_now.1.checked_sub(prev.1) { - let key_value = written_size_delta_key.from_previous_up_to(prev.0, up_to, delta); + let key_value = written_size_delta_key.from_until(prev.0, up_to, delta); // written_size_delta metrics.push(key_value); // written_size metrics.push((key, written_size_now)); } else { // the cached value was ahead of us, report zero until we've caught up - metrics.push(written_size_delta_key.from_previous_up_to(prev.0, up_to, 0)); + metrics.push(written_size_delta_key.from_until(prev.0, up_to, 0)); // the cached value was ahead of us, report the same until we've caught up metrics.push((key, (written_size_now.0, prev.1))); } @@ -468,3 +450,6 @@ impl TimelineSnapshot { #[cfg(test)] mod tests; + +#[cfg(test)] +pub(crate) use tests::metric_examples; diff --git a/pageserver/src/consumption_metrics/metrics/tests.rs b/pageserver/src/consumption_metrics/metrics/tests.rs index f47bccce54..38a4c9eb5d 100644 --- a/pageserver/src/consumption_metrics/metrics/tests.rs +++ b/pageserver/src/consumption_metrics/metrics/tests.rs @@ -1,13 +1,7 @@ -use std::collections::HashMap; - -use std::time::SystemTime; -use utils::{ - id::{TenantId, TimelineId}, - lsn::Lsn, -}; - use super::*; -use chrono::{DateTime, Utc}; +use std::collections::HashMap; +use std::time::SystemTime; +use utils::lsn::Lsn; #[test] fn startup_collected_timeline_metrics_before_advancing() { @@ -33,7 +27,7 @@ fn startup_collected_timeline_metrics_before_advancing() { assert_eq!( metrics, &[ - MetricsKey::written_size_delta(tenant_id, timeline_id).from_previous_up_to( + MetricsKey::written_size_delta(tenant_id, timeline_id).from_until( snap.loaded_at.1.into(), now, 0 @@ -73,8 +67,7 @@ fn startup_collected_timeline_metrics_second_round() { assert_eq!( metrics, &[ - MetricsKey::written_size_delta(tenant_id, timeline_id) - .from_previous_up_to(before, now, 0), + MetricsKey::written_size_delta(tenant_id, timeline_id).from_until(before, now, 0), MetricsKey::written_size(tenant_id, timeline_id).at(now, disk_consistent_lsn.0), MetricsKey::timeline_logical_size(tenant_id, timeline_id).at(now, 0x42000) ] @@ -100,11 +93,7 @@ fn startup_collected_timeline_metrics_nth_round_at_same_lsn() { // at t=before was the last time the last_record_lsn changed MetricsKey::written_size(tenant_id, timeline_id).at(before, disk_consistent_lsn.0), // end time of this event is used for the next ones - MetricsKey::written_size_delta(tenant_id, timeline_id).from_previous_up_to( - before, - just_before, - 0, - ), + MetricsKey::written_size_delta(tenant_id, timeline_id).from_until(before, just_before, 0), ]); let snap = TimelineSnapshot { @@ -118,81 +107,13 @@ fn startup_collected_timeline_metrics_nth_round_at_same_lsn() { assert_eq!( metrics, &[ - MetricsKey::written_size_delta(tenant_id, timeline_id).from_previous_up_to( - just_before, - now, - 0 - ), + MetricsKey::written_size_delta(tenant_id, timeline_id).from_until(just_before, now, 0), MetricsKey::written_size(tenant_id, timeline_id).at(now, disk_consistent_lsn.0), MetricsKey::timeline_logical_size(tenant_id, timeline_id).at(now, 0x42000) ] ); } -#[test] -fn metric_image_stability() { - // it is important that these strings stay as they are - - let tenant_id = TenantId::from_array([0; 16]); - let timeline_id = TimelineId::from_array([0xff; 16]); - - let now = DateTime::parse_from_rfc3339("2023-09-15T00:00:00.123456789Z").unwrap(); - let before = DateTime::parse_from_rfc3339("2023-09-14T00:00:00.123456789Z").unwrap(); - - let [now, before] = [DateTime::::from(now), DateTime::from(before)]; - - let examples = [ - ( - line!(), - MetricsKey::written_size(tenant_id, timeline_id).at(now, 0), - r#"{"type":"absolute","time":"2023-09-15T00:00:00.123456789Z","metric":"written_size","idempotency_key":"2023-09-15 00:00:00.123456789 UTC-1-0000","value":0,"tenant_id":"00000000000000000000000000000000","timeline_id":"ffffffffffffffffffffffffffffffff"}"#, - ), - ( - line!(), - MetricsKey::written_size_delta(tenant_id, timeline_id) - .from_previous_up_to(before, now, 0), - r#"{"type":"incremental","start_time":"2023-09-14T00:00:00.123456789Z","stop_time":"2023-09-15T00:00:00.123456789Z","metric":"written_data_bytes_delta","idempotency_key":"2023-09-15 00:00:00.123456789 UTC-1-0000","value":0,"tenant_id":"00000000000000000000000000000000","timeline_id":"ffffffffffffffffffffffffffffffff"}"#, - ), - ( - line!(), - MetricsKey::timeline_logical_size(tenant_id, timeline_id).at(now, 0), - r#"{"type":"absolute","time":"2023-09-15T00:00:00.123456789Z","metric":"timeline_logical_size","idempotency_key":"2023-09-15 00:00:00.123456789 UTC-1-0000","value":0,"tenant_id":"00000000000000000000000000000000","timeline_id":"ffffffffffffffffffffffffffffffff"}"#, - ), - ( - line!(), - MetricsKey::remote_storage_size(tenant_id).at(now, 0), - r#"{"type":"absolute","time":"2023-09-15T00:00:00.123456789Z","metric":"remote_storage_size","idempotency_key":"2023-09-15 00:00:00.123456789 UTC-1-0000","value":0,"tenant_id":"00000000000000000000000000000000"}"#, - ), - ( - line!(), - MetricsKey::resident_size(tenant_id).at(now, 0), - r#"{"type":"absolute","time":"2023-09-15T00:00:00.123456789Z","metric":"resident_size","idempotency_key":"2023-09-15 00:00:00.123456789 UTC-1-0000","value":0,"tenant_id":"00000000000000000000000000000000"}"#, - ), - ( - line!(), - MetricsKey::synthetic_size(tenant_id).at(now, 1), - r#"{"type":"absolute","time":"2023-09-15T00:00:00.123456789Z","metric":"synthetic_storage_size","idempotency_key":"2023-09-15 00:00:00.123456789 UTC-1-0000","value":1,"tenant_id":"00000000000000000000000000000000"}"#, - ), - ]; - - let idempotency_key = consumption_metrics::IdempotencyKey::for_tests(now, "1", 0); - - for (line, (key, (kind, value)), expected) in examples { - let e = consumption_metrics::Event { - kind, - metric: key.metric, - idempotency_key: idempotency_key.to_string(), - value, - extra: Ids { - tenant_id: key.tenant_id, - timeline_id: key.timeline_id, - }, - }; - let actual = serde_json::to_string(&e).unwrap(); - assert_eq!(expected, actual, "example from line {line}"); - } -} - #[test] fn post_restart_written_sizes_with_rolled_back_last_record_lsn() { // it can happen that we lose the inmemorylayer but have previously sent metrics and we @@ -220,7 +141,7 @@ fn post_restart_written_sizes_with_rolled_back_last_record_lsn() { let mut cache = HashMap::from([ MetricsKey::written_size(tenant_id, timeline_id).at(before_restart, 100), - MetricsKey::written_size_delta(tenant_id, timeline_id).from_previous_up_to( + MetricsKey::written_size_delta(tenant_id, timeline_id).from_until( way_before, before_restart, // not taken into account, but the timestamps are important @@ -234,7 +155,7 @@ fn post_restart_written_sizes_with_rolled_back_last_record_lsn() { assert_eq!( metrics, &[ - MetricsKey::written_size_delta(tenant_id, timeline_id).from_previous_up_to( + MetricsKey::written_size_delta(tenant_id, timeline_id).from_until( before_restart, now, 0 @@ -252,8 +173,7 @@ fn post_restart_written_sizes_with_rolled_back_last_record_lsn() { assert_eq!( metrics, &[ - MetricsKey::written_size_delta(tenant_id, timeline_id) - .from_previous_up_to(now, later, 0), + MetricsKey::written_size_delta(tenant_id, timeline_id).from_until(now, later, 0), MetricsKey::written_size(tenant_id, timeline_id).at(later, 100), ] ); @@ -359,3 +279,19 @@ fn time_backwards() -> [std::time::SystemTime; N] { times } + +pub(crate) const fn metric_examples( + tenant_id: TenantId, + timeline_id: TimelineId, + now: DateTime, + before: DateTime, +) -> [RawMetric; 6] { + [ + MetricsKey::written_size(tenant_id, timeline_id).at(now, 0), + MetricsKey::written_size_delta(tenant_id, timeline_id).from_until(before, now, 0), + MetricsKey::timeline_logical_size(tenant_id, timeline_id).at(now, 0), + MetricsKey::remote_storage_size(tenant_id).at(now, 0), + MetricsKey::resident_size(tenant_id).at(now, 0), + MetricsKey::synthetic_size(tenant_id).at(now, 1), + ] +} diff --git a/pageserver/src/consumption_metrics/upload.rs b/pageserver/src/consumption_metrics/upload.rs index 6f6b263884..d69d43a2a8 100644 --- a/pageserver/src/consumption_metrics/upload.rs +++ b/pageserver/src/consumption_metrics/upload.rs @@ -1,8 +1,21 @@ -use consumption_metrics::{idempotency_key, Event, EventChunk, CHUNK_SIZE}; +use consumption_metrics::{Event, EventChunk, IdempotencyKey, CHUNK_SIZE}; +use serde_with::serde_as; use tokio_util::sync::CancellationToken; -use tracing::*; +use tracing::Instrument; -use super::{Cache, Ids, RawMetric}; +use super::{metrics::Name, Cache, MetricsKey, RawMetric}; +use utils::id::{TenantId, TimelineId}; + +/// How the metrics from pageserver are identified. +#[serde_with::serde_as] +#[derive(serde::Serialize, serde::Deserialize, Debug, Clone, Copy, PartialEq)] +struct Ids { + #[serde_as(as = "serde_with::DisplayFromStr")] + pub(super) tenant_id: TenantId, + #[serde_as(as = "Option")] + #[serde(skip_serializing_if = "Option::is_none")] + pub(super) timeline_id: Option, +} #[tracing::instrument(skip_all, fields(metrics_total = %metrics.len()))] pub(super) async fn upload_metrics( @@ -13,44 +26,21 @@ pub(super) async fn upload_metrics( metrics: &[RawMetric], cached_metrics: &mut Cache, ) -> anyhow::Result<()> { - use bytes::BufMut; - let mut uploaded = 0; let mut failed = 0; let started_at = std::time::Instant::now(); - // write to a BytesMut so that we can cheaply clone the frozen Bytes for retries - let mut buffer = bytes::BytesMut::new(); - let mut chunk_to_send = Vec::new(); + let mut iter = serialize_in_chunks(CHUNK_SIZE, metrics, node_id); - for chunk in metrics.chunks(CHUNK_SIZE) { - chunk_to_send.clear(); + while let Some(res) = iter.next() { + let (chunk, body) = res?; - // FIXME: this should always overwrite and truncate to chunk.len() - chunk_to_send.extend(chunk.iter().map(|(curr_key, (when, curr_val))| Event { - kind: *when, - metric: curr_key.metric, - // FIXME: finally write! this to the prev allocation - idempotency_key: idempotency_key(node_id), - value: *curr_val, - extra: Ids { - tenant_id: curr_key.tenant_id, - timeline_id: curr_key.timeline_id, - }, - })); - - serde_json::to_writer( - (&mut buffer).writer(), - &EventChunk { - events: (&chunk_to_send).into(), - }, - )?; - - let body = buffer.split().freeze(); let event_bytes = body.len(); - let res = upload(client, metric_collection_endpoint, body, cancel) + let is_last = iter.len() == 0; + + let res = upload(client, metric_collection_endpoint, body, cancel, is_last) .instrument(tracing::info_span!( "upload", %event_bytes, @@ -88,6 +78,150 @@ pub(super) async fn upload_metrics( Ok(()) } +// The return type is quite ugly, but we gain testability in isolation +fn serialize_in_chunks<'a, F>( + chunk_size: usize, + input: &'a [RawMetric], + factory: F, +) -> impl ExactSizeIterator> + 'a +where + F: KeyGen<'a> + 'a, +{ + use bytes::BufMut; + + struct Iter<'a, F> { + inner: std::slice::Chunks<'a, RawMetric>, + chunk_size: usize, + + // write to a BytesMut so that we can cheaply clone the frozen Bytes for retries + buffer: bytes::BytesMut, + // chunk amount of events are reused to produce the serialized document + scratch: Vec>, + factory: F, + } + + impl<'a, F: KeyGen<'a>> Iterator for Iter<'a, F> { + type Item = Result<(&'a [RawMetric], bytes::Bytes), serde_json::Error>; + + fn next(&mut self) -> Option { + let chunk = self.inner.next()?; + + if self.scratch.is_empty() { + // first round: create events with N strings + self.scratch.extend( + chunk + .iter() + .map(|raw_metric| raw_metric.as_event(&self.factory.generate())), + ); + } else { + // next rounds: update_in_place to reuse allocations + assert_eq!(self.scratch.len(), self.chunk_size); + self.scratch + .iter_mut() + .zip(chunk.iter()) + .for_each(|(slot, raw_metric)| { + raw_metric.update_in_place(slot, &self.factory.generate()) + }); + } + + let res = serde_json::to_writer( + (&mut self.buffer).writer(), + &EventChunk { + events: (&self.scratch[..chunk.len()]).into(), + }, + ); + + match res { + Ok(()) => Some(Ok((chunk, self.buffer.split().freeze()))), + Err(e) => Some(Err(e)), + } + } + + fn size_hint(&self) -> (usize, Option) { + self.inner.size_hint() + } + } + + impl<'a, F: KeyGen<'a>> ExactSizeIterator for Iter<'a, F> {} + + let buffer = bytes::BytesMut::new(); + let inner = input.chunks(chunk_size); + let scratch = Vec::new(); + + Iter { + inner, + chunk_size, + buffer, + scratch, + factory, + } +} + +trait RawMetricExt { + fn as_event(&self, key: &IdempotencyKey<'_>) -> Event; + fn update_in_place(&self, event: &mut Event, key: &IdempotencyKey<'_>); +} + +impl RawMetricExt for RawMetric { + fn as_event(&self, key: &IdempotencyKey<'_>) -> Event { + let MetricsKey { + metric, + tenant_id, + timeline_id, + } = self.0; + + let (kind, value) = self.1; + + Event { + kind, + metric, + idempotency_key: key.to_string(), + value, + extra: Ids { + tenant_id, + timeline_id, + }, + } + } + + fn update_in_place(&self, event: &mut Event, key: &IdempotencyKey<'_>) { + use std::fmt::Write; + + let MetricsKey { + metric, + tenant_id, + timeline_id, + } = self.0; + + let (kind, value) = self.1; + + *event = Event { + kind, + metric, + idempotency_key: { + event.idempotency_key.clear(); + write!(event.idempotency_key, "{key}").unwrap(); + std::mem::take(&mut event.idempotency_key) + }, + value, + extra: Ids { + tenant_id, + timeline_id, + }, + }; + } +} + +trait KeyGen<'a>: Copy { + fn generate(&self) -> IdempotencyKey<'a>; +} + +impl<'a> KeyGen<'a> for &'a str { + fn generate(&self) -> IdempotencyKey<'a> { + IdempotencyKey::generate(self) + } +} + enum UploadError { Rejected(reqwest::StatusCode), Reqwest(reqwest::Error), @@ -119,11 +253,16 @@ impl UploadError { } } +// this is consumed by the test verifiers +static LAST_IN_BATCH: reqwest::header::HeaderName = + reqwest::header::HeaderName::from_static("pageserver-metrics-last-upload-in-batch"); + async fn upload( client: &reqwest::Client, metric_collection_endpoint: &reqwest::Url, body: bytes::Bytes, cancel: &CancellationToken, + is_last: bool, ) -> Result<(), UploadError> { let warn_after = 3; let max_attempts = 10; @@ -134,17 +273,24 @@ async fn upload( let res = client .post(metric_collection_endpoint.clone()) .header(reqwest::header::CONTENT_TYPE, "application/json") + .header( + LAST_IN_BATCH.clone(), + if is_last { "true" } else { "false" }, + ) .body(body) .send() .await; let res = res.and_then(|res| res.error_for_status()); + // 10 redirects are normally allowed, so we don't need worry about 3xx match res { Ok(_response) => Ok(()), Err(e) => { let status = e.status().filter(|s| s.is_client_error()); if let Some(status) = status { + // rejection used to be a thing when the server could reject a + // whole batch of metrics if one metric was bad. Err(UploadError::Rejected(status)) } else { Err(UploadError::Reqwest(e)) @@ -175,3 +321,123 @@ async fn upload( res } + +#[cfg(test)] +mod tests { + use super::*; + use chrono::{DateTime, Utc}; + use once_cell::sync::Lazy; + + #[test] + fn chunked_serialization() { + let examples = metric_samples(); + assert!(examples.len() > 1); + + let factory = FixedGen::new(Utc::now(), "1", 42); + + // need to use Event here because serde_json::Value uses default hashmap, not linked + // hashmap + #[derive(serde::Deserialize)] + struct EventChunk { + events: Vec>, + } + + let correct = serialize_in_chunks(examples.len(), &examples, factory) + .map(|res| res.unwrap().1) + .flat_map(|body| serde_json::from_slice::(&body).unwrap().events) + .collect::>(); + + for chunk_size in 1..examples.len() { + let actual = serialize_in_chunks(chunk_size, &examples, factory) + .map(|res| res.unwrap().1) + .flat_map(|body| serde_json::from_slice::(&body).unwrap().events) + .collect::>(); + + // if these are equal, it means that multi-chunking version works as well + assert_eq!(correct, actual); + } + } + + #[derive(Clone, Copy)] + struct FixedGen<'a>(chrono::DateTime, &'a str, u16); + + impl<'a> FixedGen<'a> { + fn new(now: chrono::DateTime, node_id: &'a str, nonce: u16) -> Self { + FixedGen(now, node_id, nonce) + } + } + + impl<'a> KeyGen<'a> for FixedGen<'a> { + fn generate(&self) -> IdempotencyKey<'a> { + IdempotencyKey::for_tests(self.0, self.1, self.2) + } + } + + static SAMPLES_NOW: Lazy> = Lazy::new(|| { + DateTime::parse_from_rfc3339("2023-09-15T00:00:00.123456789Z") + .unwrap() + .into() + }); + + #[test] + fn metric_image_stability() { + // it is important that these strings stay as they are + + let examples = [ + ( + line!(), + r#"{"type":"absolute","time":"2023-09-15T00:00:00.123456789Z","metric":"written_size","idempotency_key":"2023-09-15 00:00:00.123456789 UTC-1-0000","value":0,"tenant_id":"00000000000000000000000000000000","timeline_id":"ffffffffffffffffffffffffffffffff"}"#, + ), + ( + line!(), + r#"{"type":"incremental","start_time":"2023-09-14T00:00:00.123456789Z","stop_time":"2023-09-15T00:00:00.123456789Z","metric":"written_data_bytes_delta","idempotency_key":"2023-09-15 00:00:00.123456789 UTC-1-0000","value":0,"tenant_id":"00000000000000000000000000000000","timeline_id":"ffffffffffffffffffffffffffffffff"}"#, + ), + ( + line!(), + r#"{"type":"absolute","time":"2023-09-15T00:00:00.123456789Z","metric":"timeline_logical_size","idempotency_key":"2023-09-15 00:00:00.123456789 UTC-1-0000","value":0,"tenant_id":"00000000000000000000000000000000","timeline_id":"ffffffffffffffffffffffffffffffff"}"#, + ), + ( + line!(), + r#"{"type":"absolute","time":"2023-09-15T00:00:00.123456789Z","metric":"remote_storage_size","idempotency_key":"2023-09-15 00:00:00.123456789 UTC-1-0000","value":0,"tenant_id":"00000000000000000000000000000000"}"#, + ), + ( + line!(), + r#"{"type":"absolute","time":"2023-09-15T00:00:00.123456789Z","metric":"resident_size","idempotency_key":"2023-09-15 00:00:00.123456789 UTC-1-0000","value":0,"tenant_id":"00000000000000000000000000000000"}"#, + ), + ( + line!(), + r#"{"type":"absolute","time":"2023-09-15T00:00:00.123456789Z","metric":"synthetic_storage_size","idempotency_key":"2023-09-15 00:00:00.123456789 UTC-1-0000","value":1,"tenant_id":"00000000000000000000000000000000"}"#, + ), + ]; + + let idempotency_key = consumption_metrics::IdempotencyKey::for_tests(*SAMPLES_NOW, "1", 0); + let examples = examples.into_iter().zip(metric_samples()); + + for ((line, expected), (key, (kind, value))) in examples { + let e = consumption_metrics::Event { + kind, + metric: key.metric, + idempotency_key: idempotency_key.to_string(), + value, + extra: Ids { + tenant_id: key.tenant_id, + timeline_id: key.timeline_id, + }, + }; + let actual = serde_json::to_string(&e).unwrap(); + assert_eq!(expected, actual, "example for {kind:?} from line {line}"); + } + } + + fn metric_samples() -> [RawMetric; 6] { + let tenant_id = TenantId::from_array([0; 16]); + let timeline_id = TimelineId::from_array([0xff; 16]); + + let before = DateTime::parse_from_rfc3339("2023-09-14T00:00:00.123456789Z") + .unwrap() + .into(); + let [now, before] = [*SAMPLES_NOW, before]; + + super::super::metrics::metric_examples(tenant_id, timeline_id, now, before) + } +} diff --git a/test_runner/regress/test_pageserver_metric_collection.py b/test_runner/regress/test_pageserver_metric_collection.py index eb9b295479..dae39d2752 100644 --- a/test_runner/regress/test_pageserver_metric_collection.py +++ b/test_runner/regress/test_pageserver_metric_collection.py @@ -1,5 +1,7 @@ import json import time +from dataclasses import dataclass +from pathlib import Path from queue import SimpleQueue from typing import Any, Dict, Set @@ -28,6 +30,7 @@ def test_metric_collection( (host, port) = httpserver_listen_address metric_collection_endpoint = f"http://{host}:{port}/billing/api/v1/usage_events" + # this should be Union[str, Tuple[List[Any], bool]], but it will make unpacking much more verbose uploads: SimpleQueue[Any] = SimpleQueue() def metrics_handler(request: Request) -> Response: @@ -35,7 +38,9 @@ def test_metric_collection( return Response(status=400) events = request.json["events"] - uploads.put(events) + is_last = request.headers["pageserver-metrics-last-upload-in-batch"] + assert is_last in ["true", "false"] + uploads.put((events, is_last == "true")) return Response(status=200) # Require collecting metrics frequently, since we change @@ -43,15 +48,12 @@ def test_metric_collection( # # Disable time-based pitr, we will use the manual GC calls # to trigger remote storage operations in a controlled way - neon_env_builder.pageserver_config_override = ( - f""" + neon_env_builder.pageserver_config_override = f""" metric_collection_interval="1s" metric_collection_endpoint="{metric_collection_endpoint}" cached_metric_collection_interval="0s" synthetic_size_calculation_interval="3s" - """ - + "tenant_config={pitr_interval = '0 sec'}" - ) + """ neon_env_builder.enable_pageserver_remote_storage(remote_storage_kind) @@ -63,7 +65,7 @@ def test_metric_collection( ) # spin up neon, after http server is ready - env = neon_env_builder.init_start() + env = neon_env_builder.init_start(initial_tenant_conf={"pitr_interval": "0 sec"}) # httpserver is shut down before pageserver during passing run env.pageserver.allowed_errors.append(".*metrics endpoint refused the sent metrics*") tenant_id = env.initial_tenant @@ -124,19 +126,20 @@ def test_metric_collection( events = uploads.get(timeout=timeout) if events == "ready": - events = uploads.get(timeout=timeout) - v.ingest(events) + (events, is_last) = uploads.get(timeout=timeout) + v.ingest(events, is_last) break else: - v.ingest(events) + (events, is_last) = events + v.ingest(events, is_last) if "synthetic_storage_size" not in v.accepted_event_names(): log.info("waiting for synthetic storage size to be calculated and uploaded...") rounds = 0 while "synthetic_storage_size" not in v.accepted_event_names(): - events = uploads.get(timeout=timeout) - v.ingest(events) + (events, is_last) = uploads.get(timeout=timeout) + v.ingest(events, is_last) rounds += 1 assert rounds < 10, "did not get synthetic_storage_size in 10 uploads" # once we have it in verifiers, it will assert that future batches will contain it @@ -150,17 +153,161 @@ def test_metric_collection( events = uploads.get(timeout=timeout) if events == "ready": - events = uploads.get(timeout=timeout * 3) - v.ingest(events) - events = uploads.get(timeout=timeout) - v.ingest(events) + (events, is_last) = uploads.get(timeout=timeout * 3) + v.ingest(events, is_last) + (events, is_last) = uploads.get(timeout=timeout) + v.ingest(events, is_last) break else: - v.ingest(events) + (events, is_last) = events + v.ingest(events, is_last) httpserver.check() +def test_metric_collection_cleans_up_tempfile( + httpserver: HTTPServer, + neon_env_builder: NeonEnvBuilder, + httpserver_listen_address, +): + (host, port) = httpserver_listen_address + metric_collection_endpoint = f"http://{host}:{port}/billing/api/v1/usage_events" + + # this should be Union[str, Tuple[List[Any], bool]], but it will make unpacking much more verbose + uploads: SimpleQueue[Any] = SimpleQueue() + + def metrics_handler(request: Request) -> Response: + if request.json is None: + return Response(status=400) + + events = request.json["events"] + is_last = request.headers["pageserver-metrics-last-upload-in-batch"] + assert is_last in ["true", "false"] + uploads.put((events, is_last == "true")) + return Response(status=200) + + # Require collecting metrics frequently, since we change + # the timeline and want something to be logged about it. + # + # Disable time-based pitr, we will use the manual GC calls + # to trigger remote storage operations in a controlled way + neon_env_builder.pageserver_config_override = f""" + metric_collection_interval="1s" + metric_collection_endpoint="{metric_collection_endpoint}" + cached_metric_collection_interval="0s" + synthetic_size_calculation_interval="3s" + """ + + neon_env_builder.enable_pageserver_remote_storage(RemoteStorageKind.LOCAL_FS) + + # mock http server that returns OK for the metrics + httpserver.expect_request("/billing/api/v1/usage_events", method="POST").respond_with_handler( + metrics_handler + ) + + # spin up neon, after http server is ready + env = neon_env_builder.init_start(initial_tenant_conf={"pitr_interval": "0 sec"}) + pageserver_http = env.pageserver.http_client() + + # httpserver is shut down before pageserver during passing run + env.pageserver.allowed_errors.append(".*metrics endpoint refused the sent metrics*") + tenant_id = env.initial_tenant + timeline_id = env.initial_timeline + endpoint = env.endpoints.create_start("main", tenant_id=tenant_id) + + pg_conn = endpoint.connect() + cur = pg_conn.cursor() + + cur.execute("CREATE TABLE foo (id int, counter int, t text)") + cur.execute( + """ + INSERT INTO foo + SELECT g, 0, 'long string to consume some space' || g + FROM generate_series(1, 100000) g + """ + ) + + wait_for_last_flush_lsn(env, endpoint, tenant_id, timeline_id) + pageserver_http.timeline_checkpoint(tenant_id, timeline_id) + + # we expect uploads at 1Hz, on busy runners this could be too optimistic, + # so give 5s we only want to get the following upload after "ready" value. + timeout = 5 + + # these strings in the upload queue allow synchronizing with the uploads + # and the main test execution + uploads.put("ready") + + while True: + events = uploads.get(timeout=timeout) + + if events == "ready": + (events, _) = uploads.get(timeout=timeout) + break + + # should really configure an env? + pageserver_http.configure_failpoints(("before-persist-last-metrics-collected", "exit")) + + time.sleep(3) + + env.pageserver.stop() + + initially = iterate_pageserver_workdir(env.pageserver.workdir, "last_consumption_metrics.json") + + assert ( + len(initially.matching) == 2 + ), f"expecting actual file and tempfile, but not found: {initially.matching}" + + uploads.put("ready") + env.pageserver.start() + + while True: + events = uploads.get(timeout=timeout * 3) + + if events == "ready": + (events, _) = uploads.get(timeout=timeout) + break + + env.pageserver.stop() + + later = iterate_pageserver_workdir(env.pageserver.workdir, "last_consumption_metrics.json") + + # it is possible we shutdown the pageserver right at the correct time, so the old tempfile + # is gone, but we also have a new one. + only = set(["last_consumption_metrics.json"]) + assert ( + initially.matching.intersection(later.matching) == only + ), "only initial tempfile should had been removed" + assert initially.other.issuperset(later.other), "no other files should had been removed" + + +@dataclass +class PrefixPartitionedFiles: + matching: Set[str] + other: Set[str] + + +def iterate_pageserver_workdir(path: Path, prefix: str) -> PrefixPartitionedFiles: + """ + Iterates the files in the workdir, returns two sets: + - files with the prefix + - files without the prefix + """ + + matching = set() + other = set() + for entry in path.iterdir(): + if not entry.is_file(): + continue + + if not entry.name.startswith(prefix): + other.add(entry.name) + else: + matching.add(entry.name) + + return PrefixPartitionedFiles(matching, other) + + class MetricsVerifier: """ A graph of per tenant per timeline verifiers, allowing one for each @@ -171,7 +318,7 @@ class MetricsVerifier: self.tenants: Dict[TenantId, TenantMetricsVerifier] = {} pass - def ingest(self, events): + def ingest(self, events, is_last): stringified = json.dumps(events, indent=2) log.info(f"ingesting: {stringified}") for event in events: @@ -181,8 +328,9 @@ class MetricsVerifier: self.tenants[id].ingest(event) - for t in self.tenants.values(): - t.post_batch() + if is_last: + for t in self.tenants.values(): + t.post_batch() def accepted_event_names(self) -> Set[str]: names: Set[str] = set()