From 91647eecb54557c8215504d8aa60cde3dda74194 Mon Sep 17 00:00:00 2001 From: stumpylog <797416+stumpylog@users.noreply.github.com> Date: Mon, 27 Jul 2026 15:08:23 -0700 Subject: [PATCH] chore(profiling): add throwaway-Postgres helper and typed profiling harness Adds standalone profiling tooling (never merged into dev/main): a persistent, self-healing Postgres 18 container helper (run_with_postgres.sh/stop_postgres.sh), a scale-profile dataset seeder (seed.py) whose document counts and guardian permission-row ratios mirror real bug reports (#13276, #13161), and a typed profiling harness (harness.py) for timing/query-count comparisons and EXPLAIN ANALYZE capture, gated by require_postgres() so it never silently runs on SQLite. seed.py samples distinct (subject, document) pairs up front rather than drawing with replacement, since guardian's assign_perm() dedupes on the (subject, object, permission) triple -- with-replacement sampling against a small group pool collides heavily (birthday paradox) and undercounts the target permission-row ratios otherwise. --- profiling/__init__.py | 0 profiling/harness.py | 67 ++++++++++ profiling/pyproject.toml | 18 +++ profiling/run_with_postgres.sh | 48 +++++++ profiling/seed.py | 184 +++++++++++++++++++++++++++ profiling/stop_postgres.sh | 24 ++++ profiling/test_harness_self_check.py | 46 +++++++ 7 files changed, 387 insertions(+) create mode 100644 profiling/__init__.py create mode 100644 profiling/harness.py create mode 100644 profiling/pyproject.toml create mode 100755 profiling/run_with_postgres.sh create mode 100644 profiling/seed.py create mode 100755 profiling/stop_postgres.sh create mode 100644 profiling/test_harness_self_check.py diff --git a/profiling/__init__.py b/profiling/__init__.py new file mode 100644 index 000000000..e69de29bb diff --git a/profiling/harness.py b/profiling/harness.py new file mode 100644 index 000000000..b469d20fe --- /dev/null +++ b/profiling/harness.py @@ -0,0 +1,67 @@ +# profiling/harness.py +from __future__ import annotations + +import time +from dataclasses import dataclass +from typing import TYPE_CHECKING +from typing import Any +from typing import Generic +from typing import TypeVar + +import pytest +from django.db import connection +from django.test.utils import CaptureQueriesContext + +if TYPE_CHECKING: + from collections.abc import Callable + + from django.db.models import QuerySet + +T = TypeVar("T") + + +def require_postgres() -> None: + if connection.vendor != "postgresql": + pytest.skip( + "Profiling requires PostgreSQL to reflect production query " + "planning; SQLite does not reproduce the varchar-cast planner " + "pathology this work fixes.", + ) + + +@dataclass(frozen=True, slots=True) +class ProfileResult(Generic[T]): + best_seconds: float + all_seconds: tuple[float, ...] + query_count: int + result: T + + +def run_profile(fn: Callable[[], T], *, repeat: int = 5) -> ProfileResult[T]: + require_postgres() + all_seconds: list[float] = [] + result: T | None = None + query_count = 0 + for i in range(repeat): + with CaptureQueriesContext(connection) as ctx: + start = time.perf_counter() + result = fn() + all_seconds.append(time.perf_counter() - start) + if i == repeat - 1: + query_count = len(ctx.captured_queries) + assert result is not None # repeat >= 1 guarantees at least one assignment + return ProfileResult( + best_seconds=min(all_seconds), + all_seconds=tuple(all_seconds), + query_count=query_count, + result=result, + ) + + +def capture_explain_analyze(queryset: QuerySet[Any]) -> str: + if connection.vendor != "postgresql": + raise RuntimeError("EXPLAIN ANALYZE capture is Postgres-only") + sql, params = queryset.query.sql_with_params() + with connection.cursor() as cur: + cur.execute(f"EXPLAIN ANALYZE {sql}", params) + return "\n".join(row[0] for row in cur.fetchall()) diff --git a/profiling/pyproject.toml b/profiling/pyproject.toml new file mode 100644 index 000000000..6568ab5d7 --- /dev/null +++ b/profiling/pyproject.toml @@ -0,0 +1,18 @@ +[tool.pytest] +ini_options.pythonpath = [ "../src", "..", "." ] +ini_options.markers = [ + """\ + profiling: Profiling scripts comparing old vs new query patterns; require a throwaway PostgreSQL container, not run \ + as part of the normal test suite\ + """, +] +ini_options.DJANGO_SETTINGS_MODULE = "paperless.settings" + +[tool.pytest_env] +# Standalone config: this directory must be independently runnable without +# the rest of the dev stack (Redis, etc) present -- only Postgres is required, +# via run_with_postgres.sh. +PAPERLESS_SECRET_KEY = "profiling-only-insecure-key" +PAPERLESS_DISABLE_DBHANDLER = "true" +PAPERLESS_CACHE_BACKEND = "django.core.cache.backends.locmem.LocMemCache" +PAPERLESS_CHANNELS_BACKEND = "channels.layers.InMemoryChannelLayer" diff --git a/profiling/run_with_postgres.sh b/profiling/run_with_postgres.sh new file mode 100755 index 000000000..1b787f067 --- /dev/null +++ b/profiling/run_with_postgres.sh @@ -0,0 +1,48 @@ +#!/usr/bin/env bash +# profiling/run_with_postgres.sh +# +# Starts a PostgreSQL 18 container (matching +# docker/compose/docker-compose.postgres.yml's image) if one isn't already +# running, waits for it to accept connections, force-terminates any +# leftover connections from a previous run that crashed or was killed, then +# runs the given command against it with the right PAPERLESS_DB* env vars +# set. The container is intentionally left running afterward -- see +# stop_postgres.sh to tear it down explicitly once you're done profiling +# for the session. +set -euo pipefail + +CONTAINER_NAME="pngx-profiling-pg" +HOST_PORT="55432" + +if ! docker inspect "$CONTAINER_NAME" >/dev/null 2>&1; then + docker run --rm -d \ + --name "$CONTAINER_NAME" \ + -e POSTGRES_DB=paperless \ + -e POSTGRES_USER=paperless \ + -e POSTGRES_PASSWORD=paperless \ + -p "${HOST_PORT}:5432" \ + docker.io/library/postgres:18 >/dev/null + echo "Started profiling Postgres container '$CONTAINER_NAME' on port $HOST_PORT (left running -- see profiling/stop_postgres.sh)." >&2 +fi + +until docker exec "$CONTAINER_NAME" pg_isready -U paperless >/dev/null 2>&1; do + sleep 1 +done + +# Reap any connections left over from a previous run that crashed, was +# killed, or timed out mid-query -- without this, a persistent container +# can accumulate stuck backends that block later test-database +# create/drop operations indefinitely. +docker exec "$CONTAINER_NAME" psql -U paperless -d paperless -v ON_ERROR_STOP=0 -c " + SELECT pg_terminate_backend(pid) + FROM pg_stat_activity + WHERE datname IN ('paperless', 'test_paperless') + AND pid <> pg_backend_pid(); +" >/dev/null 2>&1 || true + +PAPERLESS_DBHOST=localhost \ + PAPERLESS_DBNAME=paperless \ + PAPERLESS_DBUSER=paperless \ + PAPERLESS_DBPASS=paperless \ + PAPERLESS_DBPORT="${HOST_PORT}" \ + "$@" diff --git a/profiling/seed.py b/profiling/seed.py new file mode 100644 index 000000000..cf167fa38 --- /dev/null +++ b/profiling/seed.py @@ -0,0 +1,184 @@ +# profiling/seed.py +from __future__ import annotations + +import random +from dataclasses import dataclass +from typing import TYPE_CHECKING +from typing import Literal + +from django.contrib.auth.models import Group +from django.contrib.auth.models import User +from guardian.shortcuts import assign_perm + +from documents.tests.factories import CorrespondentFactory +from documents.tests.factories import DocumentFactory +from documents.tests.factories import DocumentTypeFactory +from documents.tests.factories import StoragePathFactory +from documents.tests.factories import TagFactory + +if TYPE_CHECKING: + from documents.models import Correspondent + from documents.models import Document + from documents.models import DocumentType + from documents.models import StoragePath + from documents.models import Tag + +ScaleProfile = Literal["medium", "large"] + + +class _ScaleCounts: + __slots__ = ( + "correspondents", + "document_types", + "documents", + "groups", + "storage_paths", + "tags", + "users", + ) + + def __init__( + self, + *, + documents: int, + tags: int, + correspondents: int, + document_types: int, + storage_paths: int, + users: int, + groups: int, + ) -> None: + self.documents = documents + self.tags = tags + self.correspondents = correspondents + self.document_types = document_types + self.storage_paths = storage_paths + self.users = users + self.groups = groups + + +_SCALE_PROFILES: dict[ScaleProfile, _ScaleCounts] = { + "medium": _ScaleCounts( + documents=20_000, + tags=100, + correspondents=300, + document_types=50, + storage_paths=20, + users=10, + groups=5, + ), + "large": _ScaleCounts( + documents=360_000, + tags=1_000, + correspondents=5_000, + document_types=300, + storage_paths=50, + users=25, + groups=10, + ), +} +# Ratios measured from a real install (discussion #13276): 1,414 user-perm +# rows / 27,232 group-perm rows over 12,000 documents. +_USER_PERM_ROWS_PER_DOC = 1_414 / 12_000 +_GROUP_PERM_ROWS_PER_DOC = 27_232 / 12_000 + + +def _sample_distinct_pairs( + rng: random.Random, + n_subjects: int, + n_objects: int, + count: int, +) -> set[tuple[int, int]]: + """ + Rejection-sample `count` distinct (subject_index, object_index) pairs. + `count` is always well under `n_subjects * n_objects` for every scale + profile, so this terminates quickly. + """ + if count > n_subjects * n_objects: + msg = ( + f"cannot sample {count} distinct pairs from only " + f"{n_subjects * n_objects} possible (subject, object) slots" + ) + raise ValueError(msg) + pairs: set[tuple[int, int]] = set() + while len(pairs) < count: + pairs.add((rng.randrange(n_subjects), rng.randrange(n_objects))) + return pairs + + +@dataclass(frozen=True, slots=True) +class SeededData: + users: tuple[User, ...] + groups: tuple[Group, ...] + documents: tuple[Document, ...] + tags: tuple[Tag, ...] + correspondents: tuple[Correspondent, ...] + document_types: tuple[DocumentType, ...] + storage_paths: tuple[StoragePath, ...] + + +def seed_permission_dataset( + scale: ScaleProfile = "medium", + *, + seed: int = 1337, +) -> SeededData: + """ + Build a dataset whose document count and guardian-permission-row ratios + mirror real bug reports, so profiling results are representative of + actual large installs rather than an arbitrary small fixture. + """ + counts = _SCALE_PROFILES[scale] + rng = random.Random(seed) + + users = tuple( + User.objects.create_user(username=f"profile_user_{i}") + for i in range(counts.users) + ) + groups = tuple( + Group.objects.create(name=f"profile_group_{i}") for i in range(counts.groups) + ) + for user in users: + user.groups.add(rng.choice(groups)) + + documents = tuple(DocumentFactory.create_batch(counts.documents)) + tags = tuple(TagFactory.create_batch(counts.tags)) + correspondents = tuple(CorrespondentFactory.create_batch(counts.correspondents)) + document_types = tuple(DocumentTypeFactory.create_batch(counts.document_types)) + storage_paths = tuple(StoragePathFactory.create_batch(counts.storage_paths)) + + n_user_perms = round(counts.documents * _USER_PERM_ROWS_PER_DOC) + n_group_perms = round(counts.documents * _GROUP_PERM_ROWS_PER_DOC) + + # guardian's assign_perm is a get_or_create on the (subject, object, + # permission) triple, so drawing (subject, document) pairs *with* + # replacement -- rng.choice/rng.choice in a loop -- collides far more + # than the raw draw count suggests once the subject pool is small + # relative to the number of draws (a birthday-paradox effect): e.g. at + # medium scale, 45,387 draws over only 5 groups x 20,000 documents = + # 100,000 slots yields ~36,500 *distinct* pairs, not ~45,387. Sampling + # distinct pairs up front guarantees the seeded row counts actually + # land on the real-install ratios the scale profiles are derived from. + for user_idx, doc_idx in _sample_distinct_pairs( + rng, + len(users), + len(documents), + n_user_perms, + ): + assign_perm("view_document", users[user_idx], documents[doc_idx]) + for group_idx, doc_idx in _sample_distinct_pairs( + rng, + len(groups), + len(documents), + n_group_perms, + ): + assign_perm("view_document", groups[group_idx], documents[doc_idx]) + + return SeededData( + users=users, + groups=groups, + documents=documents, + tags=tags, + correspondents=correspondents, + document_types=document_types, + storage_paths=storage_paths, + ) diff --git a/profiling/stop_postgres.sh b/profiling/stop_postgres.sh new file mode 100755 index 000000000..a35a12d82 --- /dev/null +++ b/profiling/stop_postgres.sh @@ -0,0 +1,24 @@ +#!/usr/bin/env bash +# profiling/stop_postgres.sh +# +# Explicit, manual teardown of the profiling Postgres container. Not called +# automatically by run_with_postgres.sh -- run this yourself once you're +# done with a profiling session, so a seeded `large`-scale dataset can be +# reused across several script runs first. Terminates any active backends +# before stopping, so a stuck query can't stall `docker stop` waiting for +# a graceful Postgres shutdown that never comes. +set -euo pipefail + +CONTAINER_NAME="pngx-profiling-pg" + +if docker inspect "$CONTAINER_NAME" >/dev/null 2>&1; then + docker exec "$CONTAINER_NAME" psql -U paperless -d paperless -v ON_ERROR_STOP=0 -c " + SELECT pg_terminate_backend(pid) + FROM pg_stat_activity + WHERE pid <> pg_backend_pid(); + " >/dev/null 2>&1 || true + docker stop "$CONTAINER_NAME" >/dev/null + echo "Stopped and removed profiling Postgres container." +else + echo "No profiling Postgres container was running." +fi diff --git a/profiling/test_harness_self_check.py b/profiling/test_harness_self_check.py new file mode 100644 index 000000000..81c314f77 --- /dev/null +++ b/profiling/test_harness_self_check.py @@ -0,0 +1,46 @@ +# profiling/test_harness_self_check.py +from __future__ import annotations + +import pytest + +from profiling.harness import require_postgres +from profiling.harness import run_profile +from profiling.seed import seed_permission_dataset + + +@pytest.mark.profiling +@pytest.mark.django_db +def test_seed_medium_scale_produces_expected_counts() -> None: + require_postgres() + data = seed_permission_dataset(scale="medium") + assert len(data.documents) == 20_000 + assert len(data.tags) == 100 + assert len(data.correspondents) == 300 + assert len(data.document_types) == 50 + assert len(data.storage_paths) == 20 + + from guardian.models import GroupObjectPermission + from guardian.models import UserObjectPermission + + user_perm_count = UserObjectPermission.objects.count() + group_perm_count = GroupObjectPermission.objects.count() + # within 5% of the ratio-derived target -- exact counts depend on random + # sampling without replacement, see seed.py + assert 2_242 <= user_perm_count <= 2_478 + assert 43_111 <= group_perm_count <= 47_649 + + +@pytest.mark.profiling +@pytest.mark.django_db +def test_run_profile_reports_query_count_and_timing() -> None: + require_postgres() + + def trivial() -> list[int]: + from documents.models import Document + + return list(Document.objects.values_list("id", flat=True)[:1]) + + result = run_profile(trivial, repeat=3) + assert result.best_seconds >= 0 + assert len(result.all_seconds) == 3 + assert result.query_count >= 1