diff --git a/profiling/results/history.jsonl b/profiling/results/history.jsonl index d3bd22eb2..92276f470 100644 --- a/profiling/results/history.jsonl +++ b/profiling/results/history.jsonl @@ -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} diff --git a/profiling/results/stage1_baseline.json b/profiling/results/stage1_baseline.json index 541a36981..43230dced 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": 0.025123266968876123, + "best_seconds": 31.46481539506931, "query_count": 1 } } diff --git a/profiling/results/stage1_baseline_explain.txt b/profiling/results/stage1_baseline_explain.txt index ee7dc5d0f..56c60b5ac 100644 --- a/profiling/results/stage1_baseline_explain.txt +++ b/profiling/results/stage1_baseline_explain.txt @@ -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