diff --git a/profiling/results/history.jsonl b/profiling/results/history.jsonl index 92276f470..f35df5290 100644 --- a/profiling/results/history.jsonl +++ b/profiling/results/history.jsonl @@ -2,3 +2,5 @@ {"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} {"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} diff --git a/profiling/results/stage1_after.json b/profiling/results/stage1_after.json new file mode 100644 index 000000000..ba4333717 --- /dev/null +++ b/profiling/results/stage1_after.json @@ -0,0 +1,9 @@ +{ + "permitted_document_ids": { + "best_seconds": 0.07956207206007093, + "query_count": 1 + }, + "baseline_best_seconds": 31.671881378046237, + "baseline_query_count": 1, + "speedup_x": 398.07763370131113 +} diff --git a/profiling/results/stage1_after_explain.txt b/profiling/results/stage1_after_explain.txt new file mode 100644 index 000000000..5fec1c0e2 --- /dev/null +++ b/profiling/results/stage1_after_explain.txt @@ -0,0 +1,58 @@ +Index Scan Backward using documents_document_created_bedd0818 on documents_document v0 (cost=91.31..99.33 rows=1 width=2900) (actual time=68.340..77.517 rows=12024.00 loops=1) + Filter: ((deleted_at IS NULL) AND ((owner_id = 12) OR (owner_id IS NULL) OR (ANY (id = (hashed SubPlan 1).col1)))) + Rows Removed by Filter: 7976 + Index Searches: 1 + Buffers: shared hit=74978 + SubPlan 1 + -> Unique (cost=91.04..91.05 rows=2 width=4) (actual time=64.698..66.622 rows=9136.00 loops=1) + Buffers: shared hit=73487 + -> Sort (cost=91.04..91.05 rows=2 width=4) (actual time=64.697..65.202 rows=9262.00 loops=1) + Sort Key: ((u0.object_pk)::integer) + Sort Method: quicksort Memory: 385kB + Buffers: shared hit=73487 + -> Append (cost=0.27..91.03 rows=2 width=4) (actual time=0.026..63.201 rows=9262.00 loops=1) + Buffers: shared hit=73487 + -> Nested Loop (cost=0.27..12.79 rows=1 width=4) (actual time=0.026..1.834 rows=237.00 loops=1) + Join Filter: (u0.permission_id = u1.id) + Buffers: shared hit=696 + -> Index Only Scan using guardian_userobjectpermi_user_id_permission_id_ob_b0b3d2fc_uniq on guardian_userobjectpermission u0 (cost=0.27..8.29 rows=1 width=520) (actual time=0.012..0.131 rows=237.00 loops=1) + Index Cond: (user_id = 12) + Heap Fetches: 237 + Index Searches: 1 + Buffers: shared hit=222 + -> Seq Scan on auth_permission u1 (cost=0.00..4.49 rows=1 width=4) (actual time=0.006..0.006 rows=1.00 loops=237) + Filter: (((codename)::text = 'view_document'::text) AND (content_type_id = 17)) + Rows Removed by Filter: 67 + Buffers: shared hit=474 + -> Nested Loop (cost=4.73..78.23 rows=1 width=4) (actual time=1.119..60.528 rows=9025.00 loops=1) + Buffers: shared hit=72791 + -> Nested Loop (cost=4.59..78.05 rows=1 width=524) (actual time=1.115..50.521 rows=9025.00 loops=1) + Buffers: shared hit=54741 + -> Nested Loop (cost=4.44..73.62 rows=24 width=520) (actual time=1.109..13.226 rows=45387.00 loops=1) + Buffers: shared hit=329 + -> Seq Scan on auth_permission u4 (cost=0.00..4.49 rows=1 width=4) (actual time=0.008..0.017 rows=1.00 loops=1) + Filter: (((codename)::text = 'view_document'::text) AND (content_type_id = 17)) + Rows Removed by Filter: 165 + Buffers: shared hit=2 + -> Bitmap Heap Scan on guardian_groupobjectpermission u0_1 (cost=4.44..68.93 rows=20 width=524) (actual time=1.100..8.095 rows=45387.00 loops=1) + Recheck Cond: (permission_id = u4.id) + Heap Blocks: exact=290 + Buffers: shared hit=327 + -> Bitmap Index Scan on guardian_groupobjectpermission_permission_id_36572738 (cost=0.00..4.43 rows=20 width=0) (actual time=1.052..1.053 rows=45387.00 loops=1) + Index Cond: (permission_id = u4.id) + Index Searches: 1 + Buffers: shared hit=37 + -> Index Only Scan using auth_user_groups_user_id_group_id_94350c0c_uniq on auth_user_groups u2 (cost=0.15..0.18 rows=1 width=4) (actual time=0.001..0.001 rows=0.20 loops=45387) + Index Cond: ((user_id = 12) AND (group_id = u0_1.group_id)) + Heap Fetches: 9025 + Index Searches: 45387 + Buffers: shared hit=54412 + -> Index Only Scan using auth_group_pkey on auth_group u1_1 (cost=0.14..0.17 rows=1 width=4) (actual time=0.001..0.001 rows=1.00 loops=9025) + Index Cond: (id = u0_1.group_id) + Heap Fetches: 9025 + Index Searches: 9025 + Buffers: shared hit=18050 +Planning: + Buffers: shared hit=2 +Planning Time: 1.089 ms +Execution Time: 78.020 ms diff --git a/profiling/results/stage1_baseline.json b/profiling/results/stage1_baseline.json index 43230dced..5d404bc68 100644 --- a/profiling/results/stage1_baseline.json +++ b/profiling/results/stage1_baseline.json @@ -1,6 +1,6 @@ { "get_objects_for_user_owner_aware_document": { - "best_seconds": 31.46481539506931, + "best_seconds": 31.671881378046237, "query_count": 1 } } diff --git a/profiling/results/stage1_baseline_explain.txt b/profiling/results/stage1_baseline_explain.txt index 56c60b5ac..8bcf7aaf7 100644 --- a/profiling/results/stage1_baseline_explain.txt +++ b/profiling/results/stage1_baseline_explain.txt @@ -1,48 +1,48 @@ -Sort (cost=3796.95..3796.97 rows=9 width=2900) (actual time=39283.751..39284.442 rows=12024.00 loops=1) +Sort (cost=3790.80..3790.82 rows=9 width=2900) (actual time=39120.166..39120.831 rows=12024.00 loops=1) Sort Key: documents_document.created DESC - Sort Method: quicksort Memory: 3233kB - Buffers: shared hit=8613512 - -> Seq Scan on documents_document (cost=2554.80..3796.80 rows=9 width=2900) (actual time=0.009..39277.965 rows=12024.00 loops=1) + Sort Method: quicksort Memory: 3230kB + Buffers: shared hit=8598270 + -> Seq Scan on documents_document (cost=2550.72..3790.65 rows=9 width=2900) (actual time=0.009..39114.720 rows=12024.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)))) Rows Removed by Filter: 7976 - Buffers: shared hit=8613512 + Buffers: shared hit=8598270 SubPlan 1 - -> Nested Loop Semi Join (cost=0.00..1247.67 rows=1 width=8) (actual time=4.060..1017.730 rows=237.00 loops=1) + -> Nested Loop Semi Join (cost=0.00..1245.63 rows=1 width=8) (actual time=4.254..969.033 rows=237.00 loops=1) Join Filter: ((((v0.object_pk)::bigint)::character varying)::text = (((u0.id)::bigint)::character varying)::text) - Rows Removed by Join Filter: 2543701 - Buffers: shared hit=215598 - -> Nested Loop (cost=0.00..23.30 rows=1 width=516) (actual time=0.031..2.505 rows=237.00 loops=1) + Rows Removed by Join Filter: 2539276 + Buffers: shared hit=214835 + -> Nested Loop (cost=0.00..23.30 rows=1 width=516) (actual time=0.031..2.425 rows=237.00 loops=1) Join Filter: (v0.permission_id = v2.id) Buffers: shared hit=490 - -> Seq Scan on guardian_userobjectpermission v0 (cost=0.00..18.80 rows=1 width=520) (actual time=0.020..0.445 rows=237.00 loops=1) + -> Seq Scan on guardian_userobjectpermission v0 (cost=0.00..18.80 rows=1 width=520) (actual time=0.021..0.424 rows=237.00 loops=1) Filter: (user_id = 2) Rows Removed by Filter: 2120 Buffers: shared hit=16 - -> Seq Scan on auth_permission v2 (cost=0.00..4.49 rows=1 width=4) (actual time=0.007..0.007 rows=1.00 loops=237) + -> Seq Scan on auth_permission v2 (cost=0.00..4.49 rows=1 width=4) (actual time=0.006..0.006 rows=1.00 loops=237) Filter: ((content_type_id = 17) AND ((codename)::text = 'view_document'::text)) Rows Removed by Filter: 67 Buffers: shared hit=474 - -> Seq Scan on documents_document u0 (cost=0.00..1224.00 rows=12 width=4) (actual time=0.002..2.013 rows=10733.92 loops=237) + -> Seq Scan on documents_document u0 (cost=0.00..1221.96 rows=12 width=4) (actual time=0.002..1.917 rows=10715.24 loops=237) Filter: (deleted_at IS NULL) - Buffers: shared hit=215108 + Buffers: shared hit=214345 SubPlan 2 - -> Nested Loop Semi Join (cost=4.73..1307.13 rows=1 width=8) (actual time=6.923..38241.920 rows=9025.00 loops=1) + -> Nested Loop Semi Join (cost=4.73..1305.09 rows=1 width=8) (actual time=6.729..38127.912 rows=9025.00 loops=1) Join Filter: ((((v0_1.object_pk)::bigint)::character varying)::text = (((u0_2.id)::bigint)::character varying)::text) - Rows Removed by Join Filter: 99040000 - Buffers: shared hit=8396714 - -> Nested Loop Semi Join (cost=4.73..82.77 rows=1 width=516) (actual time=1.140..139.944 rows=9025.00 loops=1) + Rows Removed by Join Filter: 98955406 + Buffers: shared hit=8382237 + -> Nested Loop Semi Join (cost=4.73..82.77 rows=1 width=516) (actual time=1.109..137.661 rows=9025.00 loops=1) Buffers: shared hit=145515 - -> Nested Loop (cost=4.44..73.62 rows=24 width=520) (actual time=1.120..18.745 rows=45387.00 loops=1) + -> Nested Loop (cost=4.44..73.62 rows=24 width=520) (actual time=1.090..18.002 rows=45387.00 loops=1) Buffers: shared hit=329 - -> Seq Scan on auth_permission v2_1 (cost=0.00..4.49 rows=1 width=4) (actual time=0.011..0.022 rows=1.00 loops=1) + -> Seq Scan on auth_permission v2_1 (cost=0.00..4.49 rows=1 width=4) (actual time=0.011..0.023 rows=1.00 loops=1) Filter: (((codename)::text = 'view_document'::text) AND (content_type_id = 17)) Rows Removed by Filter: 165 Buffers: shared hit=2 - -> Bitmap Heap Scan on guardian_groupobjectpermission v0_1 (cost=4.44..68.93 rows=20 width=524) (actual time=1.107..11.189 rows=45387.00 loops=1) + -> Bitmap Heap Scan on guardian_groupobjectpermission v0_1 (cost=4.44..68.93 rows=20 width=524) (actual time=1.077..10.777 rows=45387.00 loops=1) Recheck Cond: (permission_id = v2_1.id) Heap Blocks: exact=290 Buffers: shared hit=327 - -> Bitmap Index Scan on guardian_groupobjectpermission_permission_id_36572738 (cost=0.00..4.43 rows=20 width=0) (actual time=1.053..1.053 rows=45387.00 loops=1) + -> Bitmap Index Scan on guardian_groupobjectpermission_permission_id_36572738 (cost=0.00..4.43 rows=20 width=0) (actual time=1.026..1.026 rows=45387.00 loops=1) Index Cond: (permission_id = v2_1.id) Index Searches: 1 Buffers: shared hit=37 @@ -59,10 +59,10 @@ Sort (cost=3796.95..3796.97 rows=9 width=2900) (actual time=39283.751..39284.44 Heap Fetches: 9025 Index Searches: 45387 Buffers: shared hit=54412 - -> Seq Scan on documents_document u0_2 (cost=0.00..1224.00 rows=12 width=4) (actual time=0.002..1.979 rows=10974.96 loops=9025) + -> Seq Scan on documents_document u0_2 (cost=0.00..1221.96 rows=12 width=4) (actual time=0.002..1.956 rows=10965.59 loops=9025) Filter: (deleted_at IS NULL) - Buffers: shared hit=8251199 + Buffers: shared hit=8236722 Planning: Buffers: shared hit=3 -Planning Time: 1.153 ms -Execution Time: 39284.929 ms +Planning Time: 1.119 ms +Execution Time: 39121.312 ms diff --git a/profiling/test_stage1_document_calls.py b/profiling/test_stage1_document_calls.py index ddcd29802..7659d3d4c 100644 --- a/profiling/test_stage1_document_calls.py +++ b/profiling/test_stage1_document_calls.py @@ -7,6 +7,7 @@ import pytest from documents.models import Document from documents.permissions import get_objects_for_user_owner_aware +from documents.permissions import permitted_document_ids from profiling.harness import append_profiling_history from profiling.harness import capture_explain_analyze from profiling.harness import require_postgres @@ -60,3 +61,65 @@ def test_profile_get_objects_for_user_owner_aware_document_baseline() -> None: print(f"\nBASELINE best={profile.best_seconds:.4f}s queries={profile.query_count}") # noqa: T201 print(plan) # noqa: T201 + + +@pytest.mark.profiling +@pytest.mark.django_db +def test_profile_permitted_document_ids_after_stage1() -> None: + require_postgres() + data = seed_permission_dataset(scale="medium") + user = data.users[0] + + def call(): + return list( + Document.objects.filter(id__in=permitted_document_ids(user)).values_list( + "id", + flat=True, + ), + ) + + profile = run_profile(call, repeat=3) + plan = capture_explain_analyze( + Document.objects.filter(id__in=permitted_document_ids(user)), + ) + + baseline = json.loads((RESULTS_DIR / "stage1_baseline.json").read_text()) + baseline_seconds = baseline["get_objects_for_user_owner_aware_document"][ + "best_seconds" + ] + baseline_queries = baseline["get_objects_for_user_owner_aware_document"][ + "query_count" + ] + + (RESULTS_DIR / "stage1_after.json").write_text( + json.dumps( + { + "permitted_document_ids": { + "best_seconds": profile.best_seconds, + "query_count": profile.query_count, + }, + "baseline_best_seconds": baseline_seconds, + "baseline_query_count": baseline_queries, + "speedup_x": baseline_seconds / profile.best_seconds + if profile.best_seconds + else None, + }, + indent=2, + ), + ) + (RESULTS_DIR / "stage1_after_explain.txt").write_text(plan) + append_profiling_history( + stage="stage1", + scenario="permitted_document_ids_after_stage1", + best_seconds=profile.best_seconds, + query_count=profile.query_count, + scale="medium", + ) + + print(f"\nBEFORE best={baseline_seconds:.4f}s queries={baseline_queries}") # noqa: T201 + print(f"AFTER best={profile.best_seconds:.4f}s queries={profile.query_count}") # noqa: T201 + + # Hard gate: must not be a regression, and should be meaningfully faster + # at this scale (the whole point of this stage). + assert profile.best_seconds < baseline_seconds + assert profile.query_count <= baseline_queries