mirror of
https://github.com/paperless-ngx/paperless-ngx.git
synced 2026-07-29 07:14:56 +00:00
profiling(stage1): re-capture baseline with realistic document ownership
Guardian permission subplans now actually execute (previously 'never executed' due to unowned seed documents short-circuiting the owner_id IS NULL branch). best_seconds rose from 0.0251s to 31.4648s, confirming the varchar-cast nested-loop-semi-join pathology is real and now measured under realistic conditions.
This commit is contained in:
stumpylog
@@ -1,3 +1,4 @@
|
||||
{"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}
|
||||
{"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}
|
||||
|
||||
@@ -1,6 +1,6 @@
|
||||
{
|
||||
"get_objects_for_user_owner_aware_document": {
|
||||
"best_seconds": 0.025123266968876123,
|
||||
"best_seconds": 31.46481539506931,
|
||||
"query_count": 1
|
||||
}
|
||||
}
|
||||
|
||||
@@ -1,49 +1,68 @@
|
||||
Sort (cost=2035.14..2035.15 rows=5 width=2900) (actual time=34.879..39.900 rows=20000.00 loops=1)
|
||||
Sort (cost=3796.95..3796.97 rows=9 width=2900) (actual time=39283.751..39284.442 rows=12024.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)
|
||||
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)
|
||||
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
|
||||
Rows Removed by Filter: 7976
|
||||
Buffers: shared hit=8613512
|
||||
SubPlan 1
|
||||
-> Nested Loop Semi Join (cost=0.27..657.61 rows=1 width=8) (never executed)
|
||||
-> Nested Loop Semi Join (cost=0.00..1247.67 rows=1 width=8) (actual time=4.060..1017.730 rows=237.00 loops=1)
|
||||
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)
|
||||
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)
|
||||
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)
|
||||
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)
|
||||
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)
|
||||
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)
|
||||
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)
|
||||
Filter: (deleted_at IS NULL)
|
||||
Buffers: shared hit=215108
|
||||
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)
|
||||
-> Nested Loop Semi Join (cost=4.73..1307.13 rows=1 width=8) (actual time=6.923..38241.920 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)
|
||||
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)
|
||||
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)
|
||||
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)
|
||||
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)
|
||||
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)
|
||||
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)
|
||||
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
|
||||
Index Searches: 1
|
||||
Buffers: shared hit=37
|
||||
-> Nested Loop (cost=0.30..0.37 rows=1 width=8) (actual time=0.002..0.002 rows=0.20 loops=45387)
|
||||
Join Filter: (u0_1.id = u1.group_id)
|
||||
Buffers: shared hit=145186
|
||||
-> Index Only Scan using auth_group_pkey on auth_group u0_1 (cost=0.14..0.17 rows=1 width=4) (actual time=0.001..0.001 rows=1.00 loops=45387)
|
||||
Index Cond: (id = v0_1.group_id)
|
||||
Heap Fetches: 45387
|
||||
Index Searches: 45387
|
||||
Buffers: shared hit=90774
|
||||
-> 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) (actual time=0.001..0.001 rows=0.20 loops=45387)
|
||||
Index Cond: ((user_id = 2) AND (group_id = v0_1.group_id))
|
||||
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)
|
||||
Filter: (deleted_at IS NULL)
|
||||
Buffers: shared hit=8251199
|
||||
Planning:
|
||||
Buffers: shared hit=3
|
||||
Planning Time: 1.721 ms
|
||||
Execution Time: 42.131 ms
|
||||
Planning Time: 1.153 ms
|
||||
Execution Time: 39284.929 ms
|
||||
|
||||
Reference in New Issue
Block a user