amorfo77/paperless-ngx
1
0
Fork 0
mirror of https://github.com/paperless-ngx/paperless-ngx.git synced 2026-08-02 09:02:18 +00:00
Code Issues Projects Releases Wiki Activity

chore(profiling): record Stage 1 after-profile, confirm speedup and no query-count regression

Browse Source
This commit is contained in:
stumpylog
2026-07-27 21:20:55 -07:00
parent fb99b3defb
commit 5b63a7bc41
6 changed files with 158 additions and 26 deletions
Download Patch File Download Diff File Expand all files Collapse all files
profiling/results/history.jsonl
+2
View File
@@ -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}
profiling/results/stage1_after.json
+9
View File
@@ -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
}
profiling/results/stage1_after_explain.txt
+58
View File
@@ -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
profiling/results/stage1_baseline.json
+1 -1
View File
@@ -1,6 +1,6 @@
{
"get_objects_for_user_owner_aware_document": {
"best_seconds": 31.46481539506931,
"best_seconds": 31.671881378046237,
"query_count": 1
}
}
profiling/results/stage1_baseline_explain.txt
+25 -25
View File
@@ -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
profiling/test_stage1_document_calls.py
+63
View File
@@ -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