diff --git a/profiling/results/history.jsonl b/profiling/results/history.jsonl new file mode 100644 index 000000000..d3bd22eb2 --- /dev/null +++ b/profiling/results/history.jsonl @@ -0,0 +1,3 @@ +{"timestamp": "2026-07-27T22:47:46.677504+00:00", "code_ref": "test-run", "stage": "self-check", "scenario": "test_append_profiling_history_writes_a_valid_json_line", "scale": "medium", "best_seconds": 0.001, "query_count": 0} +{"timestamp": "2026-07-27T22:49:03.762638+00:00", "code_ref": "test-run", "stage": "self-check", "scenario": "test_append_profiling_history_writes_a_valid_json_line", "scale": "medium", "best_seconds": 0.001, "query_count": 0} +{"timestamp": "2026-07-27T23:01:49.777269+00:00", "code_ref": "0506dcad0", "stage": "stage1", "scenario": "get_objects_for_user_owner_aware_document_baseline", "scale": "medium", "best_seconds": 0.025123266968876123, "query_count": 1} diff --git a/profiling/results/stage1_baseline.json b/profiling/results/stage1_baseline.json new file mode 100644 index 000000000..541a36981 --- /dev/null +++ b/profiling/results/stage1_baseline.json @@ -0,0 +1,6 @@ +{ + "get_objects_for_user_owner_aware_document": { + "best_seconds": 0.025123266968876123, + "query_count": 1 + } +} diff --git a/profiling/results/stage1_baseline_explain.txt b/profiling/results/stage1_baseline_explain.txt new file mode 100644 index 000000000..ee7dc5d0f --- /dev/null +++ b/profiling/results/stage1_baseline_explain.txt @@ -0,0 +1,49 @@ +Sort (cost=2035.14..2035.15 rows=5 width=2900) (actual time=34.879..39.900 rows=20000.00 loops=1) + Sort Key: documents_document.created DESC + Sort Method: external merge Disk: 4608kB + Buffers: shared hit=632, temp read=576 written=577 + -> Seq Scan on documents_document (cost=1380.96..2035.08 rows=5 width=2900) (actual time=0.013..9.365 rows=20000.00 loops=1) + Filter: ((deleted_at IS NULL) AND ((owner_id = 2) OR (owner_id IS NULL) OR (ANY (id = (hashed SubPlan 1).col1)) OR (ANY (id = (hashed SubPlan 2).col1)))) + Buffers: shared hit=632 + SubPlan 1 + -> Nested Loop Semi Join (cost=0.27..657.61 rows=1 width=8) (never executed) + Join Filter: ((((v0.object_pk)::bigint)::character varying)::text = (((u0.id)::bigint)::character varying)::text) + -> Nested Loop (cost=0.27..12.79 rows=1 width=516) (never executed) + Join Filter: (v0.permission_id = v2.id) + -> Index Only Scan using guardian_userobjectpermi_user_id_permission_id_ob_b0b3d2fc_uniq on guardian_userobjectpermission v0 (cost=0.27..8.29 rows=1 width=520) (never executed) + Index Cond: (user_id = 2) + Heap Fetches: 0 + Index Searches: 0 + -> Seq Scan on auth_permission v2 (cost=0.00..4.49 rows=1 width=4) (never executed) + Filter: ((content_type_id = 17) AND ((codename)::text = 'view_document'::text)) + -> Seq Scan on documents_document u0 (cost=0.00..644.64 rows=6 width=4) (never executed) + Filter: (deleted_at IS NULL) + SubPlan 2 + -> Nested Loop Semi Join (cost=4.73..723.34 rows=1 width=8) (never executed) + -> Nested Loop Semi Join (cost=4.44..722.95 rows=1 width=520) (never executed) + Join Filter: ((((v0_1.object_pk)::bigint)::character varying)::text = (((u0_2.id)::bigint)::character varying)::text) + -> Nested Loop (cost=4.44..73.62 rows=24 width=520) (never executed) + -> Seq Scan on auth_permission v2_1 (cost=0.00..4.49 rows=1 width=4) (never executed) + Filter: (((codename)::text = 'view_document'::text) AND (content_type_id = 17)) + -> Bitmap Heap Scan on guardian_groupobjectpermission v0_1 (cost=4.44..68.93 rows=20 width=524) (never executed) + Recheck Cond: (permission_id = v2_1.id) + -> Bitmap Index Scan on guardian_groupobjectpermission_permission_id_36572738 (cost=0.00..4.43 rows=20 width=0) (never executed) + Index Cond: (permission_id = v2_1.id) + Index Searches: 0 + -> Materialize (cost=0.00..644.67 rows=6 width=4) (never executed) + -> Seq Scan on documents_document u0_2 (cost=0.00..644.64 rows=6 width=4) (never executed) + Filter: (deleted_at IS NULL) + -> Nested Loop (cost=0.30..0.37 rows=1 width=8) (never executed) + Join Filter: (u0_1.id = u1.group_id) + -> Index Only Scan using auth_group_pkey on auth_group u0_1 (cost=0.14..0.17 rows=1 width=4) (never executed) + Index Cond: (id = v0_1.group_id) + Heap Fetches: 0 + Index Searches: 0 + -> Index Only Scan using auth_user_groups_user_id_group_id_94350c0c_uniq on auth_user_groups u1 (cost=0.15..0.18 rows=1 width=4) (never executed) + Index Cond: ((user_id = 2) AND (group_id = v0_1.group_id)) + Heap Fetches: 0 + Index Searches: 0 +Planning: + Buffers: shared hit=3 +Planning Time: 1.721 ms +Execution Time: 42.131 ms diff --git a/profiling/test_stage1_document_calls.py b/profiling/test_stage1_document_calls.py new file mode 100644 index 000000000..ddcd29802 --- /dev/null +++ b/profiling/test_stage1_document_calls.py @@ -0,0 +1,62 @@ +from __future__ import annotations + +import json +from pathlib import Path + +import pytest + +from documents.models import Document +from documents.permissions import get_objects_for_user_owner_aware +from profiling.harness import append_profiling_history +from profiling.harness import capture_explain_analyze +from profiling.harness import require_postgres +from profiling.harness import run_profile +from profiling.seed import seed_permission_dataset + +RESULTS_DIR = Path(__file__).parent / "results" + + +@pytest.mark.profiling +@pytest.mark.django_db +def test_profile_get_objects_for_user_owner_aware_document_baseline() -> None: + require_postgres() + data = seed_permission_dataset(scale="medium") + user = data.users[0] + + def call() -> list[int]: + return list( + get_objects_for_user_owner_aware( + user, + "documents.view_document", + Document, + ).values_list("id", flat=True), + ) + + profile = run_profile(call, repeat=3) + plan = capture_explain_analyze( + get_objects_for_user_owner_aware(user, "documents.view_document", Document), + ) + + RESULTS_DIR.mkdir(exist_ok=True) + (RESULTS_DIR / "stage1_baseline.json").write_text( + json.dumps( + { + "get_objects_for_user_owner_aware_document": { + "best_seconds": profile.best_seconds, + "query_count": profile.query_count, + }, + }, + indent=2, + ), + ) + (RESULTS_DIR / "stage1_baseline_explain.txt").write_text(plan) + append_profiling_history( + stage="stage1", + scenario="get_objects_for_user_owner_aware_document_baseline", + best_seconds=profile.best_seconds, + query_count=profile.query_count, + scale="medium", + ) + + print(f"\nBASELINE best={profile.best_seconds:.4f}s queries={profile.query_count}") # noqa: T201 + print(plan) # noqa: T201