From b3e0cf0e216fd3ca1a77a6c9752e912514ebeea8 Mon Sep 17 00:00:00 2001 From: stumpylog <797416+stumpylog@users.noreply.github.com> Date: Tue, 28 Jul 2026 16:36:44 -0700 Subject: [PATCH] chore(profiling): confirm Stage 2 loop-resolution reduces query count and wall time at scale --- profiling/results/history.jsonl | 2 + profiling/test_stage2_document_loops.py | 64 +++++++++++++++++++++++++ 2 files changed, 66 insertions(+) create mode 100644 profiling/test_stage2_document_loops.py diff --git a/profiling/results/history.jsonl b/profiling/results/history.jsonl index f35df5290..b78923969 100644 --- a/profiling/results/history.jsonl +++ b/profiling/results/history.jsonl @@ -4,3 +4,5 @@ {"timestamp": "2026-07-28T01:38:32.706519+00:00", "code_ref": "e80ede4cb", "stage": "stage1", "scenario": "get_objects_for_user_owner_aware_document_baseline", "scale": "medium", "best_seconds": 31.46481539506931, "query_count": 1} {"timestamp": "2026-07-28T03:53:46.770669+00:00", "code_ref": "d4fa85237", "stage": "stage1", "scenario": "get_objects_for_user_owner_aware_document_baseline", "scale": "medium", "best_seconds": 31.671881378046237, "query_count": 1} {"timestamp": "2026-07-28T04:02:41.942168+00:00", "code_ref": "d4fa85237", "stage": "stage1", "scenario": "permitted_document_ids_after_stage1", "scale": "medium", "best_seconds": 0.07956207206007093, "query_count": 1} +{"timestamp": "2026-07-28T23:30:28.602501+00:00", "code_ref": "86846255f", "stage": "stage2", "scenario": "per_row_checker_vs_resolved_set_old", "scale": "medium", "best_seconds": 3.4628250940004364, "query_count": 692} +{"timestamp": "2026-07-28T23:30:28.606987+00:00", "code_ref": "86846255f", "stage": "stage2", "scenario": "per_row_checker_vs_resolved_set_new", "scale": "medium", "best_seconds": 0.10436739504802972, "query_count": 1} diff --git a/profiling/test_stage2_document_loops.py b/profiling/test_stage2_document_loops.py new file mode 100644 index 000000000..9e38d5c18 --- /dev/null +++ b/profiling/test_stage2_document_loops.py @@ -0,0 +1,64 @@ +# profiling/test_stage2_document_loops.py +from __future__ import annotations + +import pytest + +from documents.permissions import has_perms_owner_aware +from documents.permissions import permitted_document_ids +from profiling.harness import append_profiling_history +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_profile_per_row_checker_vs_resolved_set_for_bulk_operation() -> None: + require_postgres() + data = seed_permission_dataset(scale="medium") + user = data.users[0] + # simulate a bulk operation over 500 documents the user can actually see + # (bulk-edit/share/trash all operate on a user's own selection) -- built + # from confirmed-visible documents so all() can't short-circuit unfairly + # in either old_style or new_style, see amendment note above + permitted_ids = set(permitted_document_ids(user)) + batch = [doc for doc in data.documents if doc.pk in permitted_ids][:500] + assert len(batch) == 500, ( + f"expected at least 500 visible documents to build a fair batch, " + f"got {len(batch)} -- scale profile or seed ratios may need adjusting" + ) + + def old_style(): + return all(has_perms_owner_aware(user, "view_document", doc) for doc in batch) + + def new_style(): + permitted = set(permitted_document_ids(user)) + return all(doc.pk in permitted for doc in batch) + + old_profile = run_profile(old_style, repeat=3) + new_profile = run_profile(new_style, repeat=3) + + append_profiling_history( + stage="stage2", + scenario="per_row_checker_vs_resolved_set_old", + best_seconds=old_profile.best_seconds, + query_count=old_profile.query_count, + scale="medium", + ) + append_profiling_history( + stage="stage2", + scenario="per_row_checker_vs_resolved_set_new", + best_seconds=new_profile.best_seconds, + query_count=new_profile.query_count, + scale="medium", + ) + + print( # noqa: T201 + f"\nOLD (per-row checker): best={old_profile.best_seconds:.4f}s queries={old_profile.query_count}", + ) + print( # noqa: T201 + f"NEW (resolved set): best={new_profile.best_seconds:.4f}s queries={new_profile.query_count}", + ) + + assert new_profile.query_count < old_profile.query_count + assert new_profile.best_seconds < old_profile.best_seconds