一起 pg_pathman 的有趣案例
xiongcc约 26 分钟前言
昨天上午同事转了封邮件过来，说有个查询生成执行计划耗时特别久，需要几分钟，而实际执行时间只需要几毫秒。话不多说，一起看看这个奇怪的案例！
公众号所有文章，未经作者同意，请勿转载。
分析
先看下SQL
postgres=# explain select * from hbs_cm_xxx task join hbs_type_xxx t1 on (t1.type_code = task.type_code) where task.designee_um = 'hello' limit 1;
QUERY PLAN
-----------------------------------------------------------------------------------------------------------------------------
Limit (cost=165.73..171.67 rows=1 width=2206)
-> Nested Loop (cost=165.73..48914.19 rows=8201 width=2206)
-> Append (cost=165.58..18250.64 rows=8406 width=259)
-> Bitmap Heap Scan on hbs_cm_xxx_24 task (cost=165.58..18250.64 rows=8406 width=259)
Recheck Cond: ((designee_um)::text = 'hello'::text)
-> Bitmap Index Scan on hbs_cm_xxx_24_designee_um_idx (cost=0.00..163.48 rows=8406 width=0)
Index Cond: ((designee_um)::text = 'hello'::text)
-> Index Scan using idx_hbs_type_xxx_type_code on hbs_type_xxx t1 (cost=0.15..3.64 rows=1 width=1962)
Index Cond: ((type_code)::text = (task.type_code)::text)
(9 rows)Time: 214973.317 ms (03:34.973)
可以看到👆🏻生成一个执行计划居然花费了三分钟，见鬼了！
根据往常经验，执行计划生成耗时长的情形多出现于分区子表特别多的情况，但耗时这么久的还是第一次看到。瞅瞅对应的表结构，hbs_cm_xxx 确实是个分区表，由于数据库版本版本较低（10的版本），因此使用 pg_pathman （1.4的版本）创建的分区表，总共 128 个子表
postgres=# \d+ hbs_cm_common_task
Table "public.hbs_cm_common_task"
Column | Type | Collation | Nullable | Default | Storage | Stats target | Description --------------------------+-----------------------------+-----------+----------+--------------------------------------------+----------+--------------+--------------------------------------------------------------------------------------
---
id_hbs_xx_ | character varying(36) | | not null | | extended | | 主键
type_code | character varying(100) | | | | extended | | 类型编码 详见公共类型表
biz_id | character varying(100) | | | | extended | | 业务id（相关业务的ID）
...
Indexes:
"pk_id_hbs_xxx" PRIMARY KEY, btree (xxx)
...
"idx_hbs_cm_common_task_type_code" btree (type_code)
Child tables: hbs_cm_common_task_0,
hbs_cm_common_task_1,
hbs_cm_common_task_10,
hbs_cm_common_task_100,
hbs_cm_common_task_101,
hbs_cm_common_task_102,
hbs_cm_common_task_103,
hbs_cm_common_task_104,
hbs_cm_common_task_105,
hbs_cm_common_task_106,
hbs_cm_common_task_107,
hbs_cm_common_task_108,
hbs_cm_common_task_109,
...
但是即便是分区表，也不过 128 个子表，1000 多个子表的案例都见过，生成执行计划耗时也不该慢到如此量级。假如上面的SQL改造一下，只指定子表的话，立马就可以生成执行计划。看样子和父表有关，父表哪里出了幺蛾子。
抓一下 strace，满满一屏幕，持续在打印...
...
...
read(66, "\235)\1\0\0R\301\365\0\0\0\0$\0\300\37\360\37\4 \0\0\0\0\340\237 \0\320\237!\0"..., 8192) = 8192
lseek(66, 6269476864, SEEK_SET) = 6269476864
read(66, "\235)\1\0\300R\301\365\0\0\0\0<\0`\37\360\37\4 \0\0\0\0\340\237 \0`\237!\0"..., 8192) = 8192
read(66, "\235)\1\0PS\301\365\0\0\0\0(\0\260\37\360\37\4 \0\0\0\0\340\237 \0\320\237!\0"..., 8192) = 8192
lseek(66, 6269501440, SEEK_SET) = 6269501440
read(66, "\235)\1\0\330S\301\365\0\0\0\0 \0\320\37\360\37\4 \0\0\0\0\340\237 \0\320\237!\0"..., 8192) = 8192
read(66, "\235)\1\0xT\301\365\0\0\0\0,\0\240\37\360\37\4 \0\0\0\0\340\237 \0\240\237!\0"..., 8192) = 8192
read(66, "\235)\1\0\360x\301\365\0\0\0\0004\0\200\37\360\37\4 \0\0\0\0\340\237 \0\320\237!\0"..., 8192) = 8192
read(66, "\235)\1\0P8\302\365\0\0\0\0@\0P\37\360\37\4 \0\0\0\0\340\237 \0\320\237!\0"..., 8192) = 8192
read(66, "\235)\1\0\3308\302\365\0\0\0\0 \0\320\37\360\37\4 \0\0\0\0\340\237 \0\320\237!\0"..., 8192) = 8192
lseek(66, 6269575168, SEEK_SET) = 6269575168
read(66, "\235)\1\0@x\302\365\0\0\0\0(\0\260\37\360\37\4 \0\0\0\0\340\237 \0\260\237!\0"..., 8192) = 8192
read(66, "\235)\1\0\320x\302\365\0\0\0\0(\0\260\37\360\37\4 \0\0\0\0\340\237 \0\320\237!\0"..., 8192) = 8192
read(66, "\235)\1\0`y\302\365\0\0\0\0(\0\260\37\360\37\4 \0\0\0\0\340\237 \0\320\237!\0"..., 8192) = 8192
read(66, "\235)\1\0\350y\302\365\0\0\0\0 \0\320\37\360\37\4 \0\0\0\0\340\237 \0\320\237!\0"..., 8192) = 8192
futex(0x2aeb61c4bd38, FUTEX_WAIT, 0, NULL) = -1 EAGAIN (Resource temporarily unavailable)
futex(0x2aeb61c4a5b8, FUTEX_WAKE, 1) = 1
lseek(66, 6269616128, SEEK_SET) = 6269616128
read(66, "\235)\1\0h|\302\365\0\0\0\0000\0\220\37\360\37\4 \0\0\0\0\340\237 \0\220\237!\0"..., 8192) = 8192
futex(0x2aeb61c534b8, FUTEX_WAKE, 1) = 0
read(66, "\235)\1\0@}\302\365\0\0\0\0$\0\300\37\360\37\4 \0\0\0\0\340\237 \0\320\237!\0"..., 8192) = 8192
read(66, "\235)\1\0\330~\302\365\0\0\0\0@\0P\37\360\37\4 \0\0\0\0\340\237 \0P\237!\0"..., 8192) = 8192
read(66, "\235)\1\0p\177\302\365\0\0\0\0$\0\300\37\360\37\4 \0\0\0\0\340\237 \0\300\237!\0"..., 8192) = 8192
read(66, "\235)\1\0 \200\302\365\0\0\0\0$\0\300\37\360\37\4 \0\0\0\0\340\237 \0\320\237!\0"..., 8192) = 8192
read(66, "\235)\1\0\260\200\302\365\0\0\0\0(\0\260\37\360\37\4 \0\0\0\0\340\237 \0\320\237!\0"..., 8192) = 8192
lseek(66, 6269673472, SEEK_SET) = 6269673472
read(66, "\235)\1\0H\201\302\365\0\0\0\0$\0\300\37\360\37\4 \0\0\0\0\340\237 \0\320\237!\0"..., 8192) = 8192
read(66, "\235)\1\0\200\365\302\365\0\0\0\0<\0`\37\360\37\4 \0\0\0\0\340\237 \0`\237!\0"..., 8192) = 8192
...
...
根据 strace，表明在生成执行计划的过程中，数据库在不断地调整文件偏移量、不断地读某个文件，pidstat 也可以看到该进程的 sys 高，在忙于读写中。
[postgres@xiongcc ~]$ pidstat -p 96045 1
Linux 3.10.0-693.11.6.el7.x86_64 (cnsz082763) 10/31/2022 _x86_64_ (80 CPU)02:09:51 PM UID PID %usr %system %guest %CPU CPU Command
02:09:52 PM 6001 96045 59.41 39.60 0.00 99.01 75 postgres
02:09:53 PM 6001 96045 59.00 40.00 0.00 99.00 6 postgres
02:09:54 PM 6001 96045 48.00 52.00 0.00 100.00 6 postgres
02:09:55 PM 6001 96045 48.00 52.00 0.00 100.00 18 postgres
02:09:56 PM 6001 96045 52.00 47.00 0.00 99.00 18 postgres
02:09:57 PM 6001 96045 51.00 49.00 0.00 100.00 12 postgres
02:09:58 PM 6001 96045 51.00 49.00 0.00 100.00 12 postgres
02:09:59 PM 6001 96045 50.00 50.00 0.00 100.00 13 postgres
02:10:00 PM 6001 96045 48.00 42.00 0.00 90.00 75 postgres
02:10:01 PM 6001 96045 50.00 45.00 0.00 95.00 63 postgres
02:10:02 PM 6001 96045 57.00 43.00 0.00 100.00 72 postgres
02:10:03 PM 6001 96045 52.00 45.00 0.00 97.00 77 postgres
02:10:04 PM 6001 96045 52.00 45.00 0.00 97.00 20 postgres
看下这个 66 句柄对应的是什么文件
[postgres@xiongcc ~]$ ll /proc/96045/fd/66
lrwx------ 1 postgres postgres 64 Oct 31 15:46 /proc/96045/fd/66 -> /xxx/17042/941301.1[postgres@xiongcc ~]$ oid2name -o 941301 -d ptxx
From database "ptxx":
Filenode Table Name
--------------------------------------------
941301 idx_hbs_cm_common_task_type_code
原来是个索引，是父表 type_code 字段上的一个索引。那问题来了，为什么在生成执行计划的时候会去反复读这个索引呢？而且执行计划和这个索引也没有关系。
根据我之前几次的踩坑经验，莫非又双叒叕是索引坏了？赶忙使用 amcheck 验证一下
SELECT
bt_index_check (c.oid),
c.relname,
c.relpages
FROM
pg_index i
JOIN pg_opclass op ON i.indclass[0] = op.oid
JOIN pg_am am ON op.opcmethod = am.oid
JOIN pg_class c ON i.indexrelid = c.oid
JOIN pg_namespace n ON c.relnamespace = n.oid
WHERE
am.amname = 'btree'
AND n.nspname = 'pg_catalog'
-- Don't check temp tables, which may be from another session:
AND c.relpersistence != 't'
AND c.relname = 'idx_hbs_cm_common_task_type_code'
-- Function may throw an error when this is omitted:
AND i.indisready
AND i.indisvalid
ORDER BY
c.relpages DESC
LIMIT 10;
可惜索引也是完好的。不过索引的碎片率倒是极其严重，也很臃肿
postgres=# select * from pgstatindex('idx_hbs_cm_xxx_type_code'::regclass);
-[ RECORD 1 ]------+------------
version | 2
tree_level | 3
index_size | 47330353152
root_block_no | 88640
internal_pages | 26915
leaf_pages | 3649397
empty_pages | 1
deleted_pages | 2101317
avg_leaf_density | 53.18
leaf_fragmentation | 93.16postgres=# \di+ idx_hbs_cm_common_task_type_code
List of relations
Schema | Name | Type | Owner | Table | Size | Description
--------+----------------------------------+-------+----------+--------------------+-------+-------------
public | idx_hbs_cm_common_task_type_code | index | xxx | hbs_cm_xxx | 44 GB |
(1 row)
丢失了救命稻草，只能试着从源码出发瞅瞅可能的问题了，跑的时候抓一下堆栈
可以看到，确实在读取索引，在下面的堆栈流程，可以看到走了 mergejoin，try_mergejoin_path -> cached_scansel -> mergejoinscansel -> scalarineqsel -> ... -> index_getnext，优化器在生成执行计划的时候，会去评估可能的执行方式，在之前的优化器篇章中提到过
“不同的组合顺序将会产生不同的代价，想要获得最佳的组合顺序，如果枚举所有组合顺序，那么将会有N! 的排列组合，计算量对于优化器来说难以承受。数据库路径的搜索方法通常有3种类型：自底向上方法、自顶向下方法、随机方法，而PostgreSQL采用了其中的两种方法：自底向上和随机方法，其中自底向上的方法是采用动态规划方法，而随机方法采用的是遗传算法，对于连接比较少的情况使用动态规划，否则使用遗传算法。
/*
* try_mergejoin_path
* Consider a merge join path; if it appears useful, push it into
* the joinrel's pathlist via add_path().
*/
static void
try_mergejoin_path(PlannerInfo *root,
RelOptInfo *joinrel,
Path *outer_path,
...
此处优化器尝试使用 mergejoin，而 mergejoin 的前提是数据是有序的，如果两表已经被排过序或者有索引，在执行排序合并连接时不需要再排序了，那是mergejoin 的时候需要去扫描索引？
为了进一步验证我们的想法，简单构造一个例子并让查询走 mergejoin：
postgres=# create table t1(id int);
CREATE TABLE
postgres=# create table t2(id int,info text);
CREATE TABLE
postgres=# insert into t1 values(generate_series(1,10000));
INSERT 0 10000
postgres=# create index on t1(id);
CREATE INDEX
postgres=# insert into t2 select n,md5(random()::text) from generate_series(1,10000) as n;
INSERT 0 10000
postgres=# create index on t2(id);
CREATE INDEX
postgres=# select pg_relation_filepath('t1_id_idx');
pg_relation_filepath
----------------------
base/13580/30669
(1 row)postgres=# select pg_relation_filepath('t2_id_idx');
pg_relation_filepath
----------------------
base/13580/30671
(1 row)
postgres=# select pg_relation_size('t1_id_idx'); --索引大小
pg_relation_size
------------------
245760
(1 row)
postgres=# select pg_relation_size('t2_id_idx'); --索引大小
pg_relation_size
------------------
245760
(1 row)
再抓下 strace
postgres=# explain select t2.info from t1 join t2 on t1.id = t2.id;
QUERY PLAN
-------------------------------------------------------------------------------------
Merge Join (cost=0.57..777.57 rows=10000 width=33)
Merge Cond: (t1.id = t2.id)
-> Index Only Scan using t1_id_idx on t1 (cost=0.29..270.29 rows=10000 width=4)
-> Index Scan using t2_id_idx on t2 (cost=0.29..357.29 rows=10000 width=37)
(4 rows)
可以看到👇🏻，确实有 lseek 的操作，每个打开的文件都有一个关联的"当前偏移量"，用于记录从文件到当前当前位置的偏移字节数，lseek 函数是设置这个当前偏移量的函数，off_t lseek(int filedes, off_t offset, int whence);
[root@xiongcc ~]# strace -p 29937
strace: Process 29937 attached
epoll_wait(4, [{EPOLLIN, {u32=27601976, u64=27601976}}], 1, -1) = 1
recvfrom(9, "Q\0\0\0=explain select t2.info from"..., 8192, 0, NULL, NULL) = 62
lseek(13, 0, SEEK_END) = 368640
lseek(18, 0, SEEK_END) = 245760
lseek(34, 0, SEEK_END) = 688128
lseek(33, 0, SEEK_END) = 245760
sendto(8, "\2\0\0\0\350\1\0\0\f5\0\0\4\0\0\0\1\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 488, 0, NULL, 0) = 488
sendto(9, "T\0\0\0#\0\1QUERY PLAN\0\0\0\0\0\0\0\0\0\0\31\377\377\377\377"..., 341, 0, NULL, 0) = 341
recvfrom(9, 0xf000c0, 8192, 0, NULL, NULL) = -1 EAGAIN (Resource temporarily unavailable)
epoll_wait(4, ^Cstrace: Process 29937 detached
<detached ...>
[root@xiongcc ~]# ll /proc/29937/fd | grep 30671
lrwx------ 1 postgres postgres 64 Nov 1 15:37 33 -> /home/postgres/13data/base/13580/30671 ---t2_id_idx索引
[root@xiongcc ~]# ll /proc/29937/fd | grep 30669
lrwx------ 1 postgres postgres 64 Nov 1 15:37 18 -> /home/postgres/13data/base/13580/30669 ---t1_id_idx索引
lseek 成功则返回新的文件偏移量，失败则返回 -1
如果whence是SEEK_SET，则文件的偏移量设置为文件开始加上offset个字节。 如果whence是SEEK_CUR，则文件的偏移量设置为当前偏移量开始加上offset个字节，offset可正可负。 如果whence是SEEK_END，则文件的偏移量设置为文件长度加上offset个字节，offset可正可负。
那回到我这个例子，
lseek(18, 0, SEEK_END) = 245760 --t1_id_idx索引 lseek(33, 0, SEEK_END) = 245760 --t2_id_idx索引
可以看到设置的偏移量就是索引的大小，准备读取这个索引。让我们加上 analyze 真正跑一下（此处换了个进程号 ）：
epoll_wait(4, [{EPOLLIN, {u32=49265736, u64=49265736}}], 1, -1) = 1
recvfrom(9, "Q\0\0\0Eexplain analyze select t2.i"..., 8192, 0, NULL, NULL) = 70
lseek(45, 0, SEEK_END) = 368640
lseek(47, 0, SEEK_END) = 245760
lseek(49, 0, SEEK_END) = 688128
lseek(50, 0, SEEK_END) = 245760
kill(31261, SIGUSR1) = 0
pread64(50, "\0\0\0\0 \353/\231\0\0\0\0\324\5\0\t\360\37\4 \0\0\0\0\0\211 \0\340\237 \0"..., 8192, 16384) = 8192
pread64(47, "\0\0\0\0\330\303\5\231\0\0\0\0\324\5\0\t\360\37\4 \0\0\0\0\0\211 \0\340\237 \0"..., 8192, 16384) = 8192
pread64(50, "\0\0\0\0@\0100\231\0\0\0\0\324\5\0\t\360\37\4 \0\0\0\0\0\211 \0\340\237 \0"..., 8192, 32768) = 8192
pread64(47, "\0\0\0\0\370\340\5\231\0\0\0\0\324\5\0\t\360\37\4 \0\0\0\0\0\211 \0\340\237 \0"..., 8192, 32768) = 8192
pread64(50, "\0\0\0\0`%0\231\0\0\0\0\324\5\0\t\360\37\4 \0\0\0\0\0\211 \0\340\237 \0"..., 8192, 40960) = 8192
pread64(47, "\0\0\0\0\0\376\5\231\0\0\0\0\324\5\0\t\360\37\4 \0\0\0\0\0\211 \0\340\237 \0"..., 8192, 40960) = 8192
pread64(50, "\0\0\0\0\200B0\231\0\0\0\0\324\5\0\t\360\37\4 \0\0\0\0\0\211 \0\340\237 \0"..., 8192, 49152) = 8192
pread64(47, "\0\0\0\0 \33\6\231\0\0\0\0\324\5\0\t\360\37\4 \0\0\0\0\0\211 \0\340\237 \0"..., 8192, 49152) = 8192
pread64(50, "\0\0\0\0\210_0\231\0\0\0\0\324\5\0\t\360\37\4 \0\0\0\0\0\211 \0\340\237 \0"..., 8192, 57344) = 8192
pread64(47, "\0\0\0\0@8\6\231\0\0\0\0\324\5\0\t\360\37\4 \0\0\0\0\0\211 \0\340\237 \0"..., 8192, 57344) = 8192
pread64(50, "\0\0\0\0\250|0\231\0\0\0\0\324\5\0\t\360\37\4 \0\0\0\0\0\211 \0\340\237 \0"..., 8192, 65536) = 8192
pread64(47, "\0\0\0\0`U\6\231\0\0\0\0\324\5\0\t\360\37\4 \0\0\0\0\0\211 \0\340\237 \0"..., 8192, 65536) = 8192
pread64(50, "\0\0\0\0\310\2310\231\0\0\0\0\324\5\0\t\360\37\4 \0\0\0\0\0\211 \0\340\237 \0"..., 8192, 73728) = 8192
pread64(47, "\0\0\0\0\200r\6\231\0\0\0\0\324\5\0\t\360\37\4 \0\0\0\0\0\211 \0\340\237 \0"..., 8192, 73728) = 8192
pread64(50, "\0\0\0\0\350\2660\231\0\0\0\0\324\5\0\t\360\37\4 \0\0\0\0\0\211 \0\340\237 \0"..., 8192, 81920) = 8192
pread64(47, "\0\0\0\0\240\217\6\231\0\0\0\0\324\5\0\t\360\37\4 \0\0\0\0\0\211 \0\340\237 \0"..., 8192, 81920) = 8192
pread64(50, "\0\0\0\0\10\3240\231\0\0\0\0\324\5\0\t\360\37\4 \0\0\0\0\0\211 \0\340\237 \0"..., 8192, 90112) = 8192
pread64(47, "\0\0\0\0\300\254\6\231\0\0\0\0\324\5\0\t\360\37\4 \0\0\0\0\0\211 \0\340\237 \0"..., 8192, 90112) = 8192
pread64(50, "\0\0\0\0(\3610\231\0\0\0\0\324\5\0\t\360\37\4 \0\0\0\0\0\211 \0\340\237 \0"..., 8192, 98304) = 8192
pread64(47, "\0\0\0\0\340\311\6\231\0\0\0\0\324\5\0\t\360\37\4 \0\0\0\0\0\211 \0\340\237 \0"..., 8192, 98304) = 8192
pread64(50, "\0\0\0\0H\0161\231\0\0\0\0\324\5\0\t\360\37\4 \0\0\0\0\0\211 \0\340\237 \0"..., 8192, 106496) = 8192
pread64(47, "\0\0\0\0\0\347\6\231\0\0\0\0\324\5\0\t\360\37\4 \0\0\0\0\0\211 \0\340\237 \0"..., 8192, 106496) = 8192
pread64(50, "\0\0\0\0h+1\231\0\0\0\0\324\5\0\t\360\37\4 \0\0\0\0\0\211 \0\340\237 \0"..., 8192, 114688) = 8192
pread64(47, "\0\0\0\0 \4\7\231\0\0\0\0\324\5\0\t\360\37\4 \0\0\0\0\0\211 \0\340\237 \0"..., 8192, 114688) = 8192
pread64(50, "\0\0\0\0\210H1\231\0\0\0\0\324\5\0\t\360\37\4 \0\0\0\0\0\211 \0\340\237 \0"..., 8192, 122880) = 8192
pread64(47, "\0\0\0\0@!\7\231\0\0\0\0\324\5\0\t\360\37\4 \0\0\0\0\0\211 \0\340\237 \0"..., 8192, 122880) = 8192
pread64(50, "\0\0\0\0\250e1\231\0\0\0\0\324\5\0\t\360\37\4 \0\0\0\0\0\211 \0\340\237 \0"..., 8192, 131072) = 8192
pread64(47, "\0\0\0\0H>\7\231\0\0\0\0\324\5\0\t\360\37\4 \0\0\0\0\0\211 \0\340\237 \0"..., 8192, 131072) = 8192
pread64(50, "\0\0\0\0\310\2021\231\0\0\0\0\324\5\0\t\360\37\4 \0\0\0\0\0\211 \0\340\237 \0"..., 8192, 139264) = 8192
pread64(47, "\0\0\0\0h[\7\231\0\0\0\0\324\5\0\t\360\37\4 \0\0\0\0\0\211 \0\340\237 \0"..., 8192, 139264) = 8192
pread64(50, "\0\0\0\0\320\2371\231\0\0\0\0\324\5\0\t\360\37\4 \0\0\0\0\0\211 \0\340\237 \0"..., 8192, 147456) = 8192
pread64(47, "\0\0\0\0\210x\7\231\0\0\0\0\324\5\0\t\360\37\4 \0\0\0\0\0\211 \0\340\237 \0"..., 8192, 147456) = 8192
pread64(50, "\0\0\0\0\360\2741\231\0\0\0\0\324\5\0\t\360\37\4 \0\0\0\0\0\211 \0\340\237 \0"..., 8192, 155648) = 8192
pread64(47, "\0\0\0\0\250\225\7\231\0\0\0\0\324\5\0\t\360\37\4 \0\0\0\0\0\211 \0\340\237 \0"..., 8192, 155648) = 8192
pread64(50, "\0\0\0\0\20\3321\231\0\0\0\0\324\5\0\t\360\37\4 \0\0\0\0\0\211 \0\340\237 \0"..., 8192, 163840) = 8192
pread64(47, "\0\0\0\0\310\262\7\231\0\0\0\0\324\5\0\t\360\37\4 \0\0\0\0\0\211 \0\340\237 \0"..., 8192, 163840) = 8192
pread64(50, "\0\0\0\0000\3671\231\0\0\0\0\324\5\0\t\360\37\4 \0\0\0\0\0\211 \0\340\237 \0"..., 8192, 172032) = 8192
pread64(47, "\0\0\0\0\350\317\7\231\0\0\0\0\324\5\0\t\360\37\4 \0\0\0\0\0\211 \0\340\237 \0"..., 8192, 172032) = 8192
pread64(50, "\0\0\0\0P\0242\231\0\0\0\0\324\5\0\t\360\37\4 \0\0\0\0\0\211 \0\340\237 \0"..., 8192, 180224) = 8192
pread64(47, "\0\0\0\0\10\355\7\231\0\0\0\0\324\5\0\t\360\37\4 \0\0\0\0\0\211 \0\340\237 \0"..., 8192, 180224) = 8192
pread64(50, "\0\0\0\0p12\231\0\0\0\0\324\5\0\t\360\37\4 \0\0\0\0\0\211 \0\340\237 \0"..., 8192, 188416) = 8192
pread64(47, "\0\0\0\0(\n\10\231\0\0\0\0\324\5\0\t\360\37\4 \0\0\0\0\0\211 \0\340\237 \0"..., 8192, 188416) = 8192
pread64(50, "\0\0\0\0\220N2\231\0\0\0\0\324\5\0\t\360\37\4 \0\0\0\0\0\211 \0\340\237 \0"..., 8192, 196608) = 8192
pread64(47, "\0\0\0\0H'\10\231\0\0\0\0\324\5\0\t\360\37\4 \0\0\0\0\0\211 \0\340\237 \0"..., 8192, 196608) = 8192
pread64(50, "\0\0\0\0\260k2\231\0\0\0\0\324\5\0\t\360\37\4 \0\0\0\0\0\211 \0\340\237 \0"..., 8192, 204800) = 8192
pread64(47, "\0\0\0\0hD\10\231\0\0\0\0\324\5\0\t\360\37\4 \0\0\0\0\0\211 \0\340\237 \0"..., 8192, 204800) = 8192
pread64(50, "\0\0\0\0\320\2102\231\0\0\0\0\324\5\0\t\360\37\4 \0\0\0\0\0\211 \0\340\237 \0"..., 8192, 212992) = 8192
pread64(47, "\0\0\0\0\210a\10\231\0\0\0\0\324\5\0\t\360\37\4 \0\0\0\0\0\211 \0\340\237 \0"..., 8192, 212992) = 8192
pread64(50, "\0\0\0\0\360\2452\231\0\0\0\0\324\5\0\t\360\37\4 \0\0\0\0\0\211 \0\340\237 \0"..., 8192, 221184) = 8192
pread64(47, "\0\0\0\0\220~\10\231\0\0\0\0\324\5\0\t\360\37\4 \0\0\0\0\0\211 \0\340\237 \0"..., 8192, 221184) = 8192
pread64(50, "\0\0\0\0\20\3032\231\0\0\0\0\324\5\0\t\360\37\4 \0\0\0\0\0\211 \0\340\237 \0"..., 8192, 229376) = 8192
pread64(47, "\0\0\0\0\260\233\10\231\0\0\0\0\324\5\0\t\360\37\4 \0\0\0\0\0\211 \0\340\237 \0"..., 8192, 229376) = 8192
sendto(8, "\2\0\0\0\250\3\0\0\f5\0\0\10\0\0\0\1\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 936, 0, NULL, 0) = 936
sendto(9, "T\0\0\0#\0\1QUERY PLAN\0\0\0\0\0\0\0\0\0\0\31\377\377\377\377"..., 584, 0, NULL, 0) = 584
recvfrom(9, 0xf000c0, 8192, 0, NULL, NULL) = -1 EAGAIN (Resource temporarily unavailable)
这次就不一样了，不仅有 lseek ，也可以看到在不断地读索引，最后发给 socket。那么至此，进过我们的实验，我们可以得知：
explain 生成执行计划期间并不会发生真正的读，只是会调用 lseek 去设置文件偏移量 explain analyze 真正执行 SQL 的时候才会去读取文件
不过确实也符合我们的认知，假如生成执行计划就要去访问索引了，索引越多越大，执行计划生成时间越长，那还得了。
那为什么这个例子会这样？让我们关闭一下 mergejoin 试试
postgres=# set enable_mergejoin to off;
SET
Time: 0.183 ms
postgres=# explain select * from hbs_cm_xxx task join hbs_type_xxx t1 on (t1.type_code = task.type_code) where task.designee_um = 'hello' limit 1;
QUERY PLAN
-----------------------------------------------------------------------------------------------------------------------------
Limit (cost=165.73..171.68 rows=1 width=2206)
-> Nested Loop (cost=165.73..48916.46 rows=8201 width=2206)
-> Append (cost=165.59..18252.74 rows=8407 width=259)
-> Bitmap Heap Scan on hbs_cm_xxx_24 task (cost=165.59..18252.74 rows=8407 width=259)
Recheck Cond: ((designee_um)::text = 'hello'::text)
-> Bitmap Index Scan on hbs_cm_xxx_24_designee_um_idx (cost=0.00..163.49 rows=8407 width=0)
Index Cond: ((designee_um)::text = 'hello'::text)
-> Index Scan using idx_hbs_type_xxx_type_code on hbs_type_xxx t1 (cost=0.15..3.64 rows=1 width=1962)
Index Cond: ((type_code)::text = (task.type_code)::text)
(9 rows)Time: 1.421 ms
postgres=# set enable_mergejoin to on;
SET
Time: 0.164 ms
postgres=# explain select * from hbs_cm_xxx task join hbs_type_xxx t1 on (t1.type_code = task.type_code) where task.designee_um = 'hello' limit 1;
^CCancel request sent
ERROR: canceling statement due to user request
Time: 64126.239 ms (01:04.126)
postgres=# set enable_mergejoin to off;
SET
Time: 0.192 ms
postgres=# explain select * from hbs_cm_xxx task join hbs_type_xxx t1 on (t1.type_code = task.type_code) where task.designee_um = 'hello' limit 1;
QUERY PLAN
-----------------------------------------------------------------------------------------------------------------------------
Limit (cost=165.73..171.68 rows=1 width=2206)
-> Nested Loop (cost=165.73..48916.46 rows=8201 width=2206)
-> Append (cost=165.59..18252.74 rows=8407 width=259)
-> Bitmap Heap Scan on hbs_cm_xxx_24 task (cost=165.59..18252.74 rows=8407 width=259)
Recheck Cond: ((designee_um)::text = 'hello'::text)
-> Bitmap Index Scan on hbs_cm_xxx_24_designee_um_idx (cost=0.00..163.49 rows=8407 width=0)
Index Cond: ((designee_um)::text = 'hello'::text)
-> Index Scan using idx_hbs_type_xxx_type_code on hbs_type_xxx t1 (cost=0.15..3.64 rows=1 width=1962)
Index Cond: ((type_code)::text = (task.type_code)::text)
(9 rows)
Time: 1.310 ms
果然！关闭了 mergejoin 之后瞬间通透了，打开 mergejoin 就跑不出来。在底层堆栈中，代码进入到了 pathman 的 HOOK 中
看样子是 pathman 自己的BUG了，在 explain 生成执行计划的时候就在不断地读取索引，经过我们的实际验证，explain 期间是不会去读取索引的，随着PostgreSQL自身原生分区功能的不断增强，pathman后续也不再进行更新了，仅仅维护 BUG ，官方也推荐切换到原生分区。
由于此次案例数据库版本太低，还是10的，只能使用 pathman ，后续我们新上的版本都不会再使用 pathman，使用原生分区即可，另外我们也做了增强，比如 interval 分区，因此我也没有继续去追 pathman 1.4 的代码了，没有太大必要，我们知晓了原因，对症下药即可。
值得一提的是， pathman 还有个值得注意的问题是，使用 partition_table_concurrently() 搬迁完数据之后，父表里的数据确实都没了，但是大小还没有被释放，需要在下次 vacuum 的时候，收缩大小（vacuum 会截断所有的页面，因为全部都被 delete 了），但是索引不会！索引还在那里
postgres=# select pg_size_pretty(pg_indexes_size('hbs_cm_xxx'));
pg_size_pretty
----------------
593 GB
(1 row)Time: 0.816 ms
postgres=# select pg_size_pretty(pg_total_relation_size('hbs_cm_xxx'));
pg_size_pretty
----------------
923 GB
(1 row)
Time: 0.864 ms
postgres=# select pg_size_pretty(pg_relation_size('hbs_cm_xxx'));
pg_size_pretty
----------------
330 GB
(1 row)
Time: 0.408 ms
因此一个可行的方式是使用 truncate table only 的方式，截断父表，索引也会被清空，注意一定要加 only 关键字，否则提桶跑路吧。
前天搬迁完之后，DBA并没有做这个操作，因此假如做了这个操作的话，这个奇怪的 SQL 应该也不至于这么慢了，因为索引经过截断就8KB了，即使去读取也就读8KB。
小结
知晓了原因，那就对症下药。昨天晚上开发发版，删除了这个索引，这个奇怪的SQL也瞬间恢复正常了。我在 pathman 1.5的版本未能复现这个问题，感兴趣的小伙伴可以去试下 pathman 1.4 + PostgreSQL 10 ，这个和此例的环境是一样的，也可以去看下 pathman 1.4 的代码，不过应该也是类似的，生成执行计划期间不会去扫描索引。
另外预告一下，PostgreSQL Architecture 大图正式绘制完成啦 ~