admin/ 十二月 13, 2017/ PostgreSQL/ 0 comments

一 问题现象

接开发同事反馈,某个日志表原来有100多万条记录,删除到只剩下200多条记录,在删除大量数据之后,执行查询,还是非常缓慢。

 postgres=# \c superp2b_test superp2b_test
You are now connected to database "superp2b_test" as user "superp2b_test".
superp2b_test=> select count(*) from t_sys_exception_log;
count
-------
267
(1 row)
 
Time: 101702.768 ms
superp2b_test=> create table t_sys_exception_log_bak as select * from t_sys_exception_log;
SELECT 267
Time: 160531.138 ms
superp2b_test=> select count(*) from t_sys_exception_log_bak ;
count
-------
267
(1 row)
 
Time: 87.180 ms
superp2b_test=>

通过执行CTAS复制该表为t_sys_exception_log_bak之后,查询该复制表却不慢。

二查看表结构和表及相关索引统计信息

superp2b_test=> \d t_sys_exception_log
              Table "public.t_sys_exception_log"
      Column      |              Type              | Modifiers
------------------+--------------------------------+-----------
 id               | character(32)                  | not null
 class_name       | character varying(512)         |
 create_time      | timestamp(6) without time zone |
 remark           | character varying(1024)        |
 type             | character varying(4)           |
 exception_type   | character varying(1024)        |
 exception_detail | text                           |
 method_name      | character varying(255)         |
 source           | character varying(1024)        |
 target           | character varying(1024)        |
 operator_id      | character(32)                  |
 operator_name    | character varying(255)         |
Indexes:
    "t_sys_exception_log_pkey" PRIMARY KEY, btree (id)
    "t_sys_exception_log_class_name_idx" btree (class_name)
    "t_sys_exception_log_create_time_idx" btree (create_time)
    "t_sys_exception_log_exception_type_idx" btree (exception_type)
    "t_sys_exception_log_method_name_idx" btree (method_name)
    "t_sys_exception_log_operator_id_idx" btree (operator_id)
    "t_sys_exception_log_operator_name_idx" btree (operator_name)
         
superp2b_test=> select relname,relpages,to_char(reltuples,'999999999') from pg_class where relname like 't_sys_exception_log%';
                relname                 | relpages |  to_char  
----------------------------------------+----------+------------
 t_sys_exception_log                    |   293660 |    1515498
 t_sys_exception_log_class_name_idx     |    14813 |    1515502
 t_sys_exception_log_pkey               |    20655 |    1515502
 t_sys_exception_log_create_time_idx    |     4162 |    1515502
 t_sys_exception_log_exception_type_idx |    12626 |    1515502
 t_sys_exception_log_method_name_idx    |     8555 |    1515502
 t_sys_exception_log_operator_id_idx    |     5302 |    1515502
 t_sys_exception_log_operator_name_idx  |     5267 |    1515502
 t_sys_exception_log_bak                |       38 |        267
(9 rows)
Time: 12.494 ms
superp2b_test=>

从上,看到,虽然表里当前只有267条记录,但是由于删除大量数据之后,数据库没有及时更新该表的统计信息,导致数据库依然认为该表有1515498条记录,占用了293660个磁盘页。

三 分析其执行计划

superp2b_test=> explain analyze select count(*) from t_sys_exception_log;
QUERY PLAN
-------------------------------------------------------------------------------------------------------------------------------------
Aggregate (cost=312603.72..312603.73 rows=1 width=0) (actual time=25771.014..25771.014 rows=1 loops=1)
-> Seq Scan on t_sys_exception_log (cost=0.00..308814.98 rows=1515498 width=0) (actual time=14.402..25770.915 rows=267 loops=1)
Total runtime: 25771.087 ms
(3 rows)
 
Time: 25779.274 ms
superp2b_test=>

的确,发现优化器对于该select count(*) from t_sys_exception_log语句,执行的全表扫描,且,优化器认为该表仍然有rows=1515498。实际上,该表只有267条记录。

四 收集统计信息

 superp2b_test=> analyze verbose t_sys_exception_log;
信息:  正在分析 "public.t_sys_exception_log"
信息:  "t_sys_exception_log": 已经扫描了293660页的30000, 包含28可用的记录和154878不能用的记录; 在示例中有28条记录,估算所有记录为1360704 .
ANALYZE
Time: 14294.586 ms
superp2b_test=> select relname,relpages,to_char(reltuples,'999999999') from pg_class where relname like 't_sys_exception_log%';
                relname                 | relpages |  to_char  
----------------------------------------+----------+------------
 t_sys_exception_log                    |   293660 |    1360704
 t_sys_exception_log_class_name_idx     |    14818 |    1360704
 t_sys_exception_log_pkey               |    20659 |    1360704
 t_sys_exception_log_create_time_idx    |     4163 |    1360704
 t_sys_exception_log_exception_type_idx |    12629 |    1360704
 t_sys_exception_log_method_name_idx    |     8559 |    1360704
 t_sys_exception_log_operator_id_idx    |     5304 |    1360704
 t_sys_exception_log_operator_name_idx  |     5268 |    1360704
 t_sys_exception_log_bak                |       38 |        267
(9 rows)
Time: 18.558 ms
superp2b_test=> explain analyze select count(*) from t_sys_exception_log;                                                     
                                                             QUERY PLAN                                                             
-------------------------------------------------------------------------------------------------------------------------------------
 Aggregate  (cost=310668.80..310668.81 rows=1 width=0) (actual time=24315.485..24315.485 rows=1 loops=1)
   ->  Seq Scan on t_sys_exception_log  (cost=0.00..307267.04 rows=1360704 width=0) (actual time=19.217..24315.358 rows=267 loops=1)
 Total runtime: 24315.574 ms
(3 rows)
Time: 24346.502 ms
superp2b_test=>

通过analyze来收集统计信息时,数据库扫描了该表所占有的磁盘页的293660页中的30000页。同时,数据库认为该表仍然有1360704条记录。此时,数据库收集的统计信息依然是不准确的,或者说是错误的。且,数据库还把这个错误的统计信息更新到字典表pg_statistic中。

接下来,再执行一次统计信息收集,并查看其select count(*) from t_sys_exception_log语句的执行计划:

superp2b_test=> analyze verbose t_sys_exception_log;                                                                          
信息:  正在分析 "public.t_sys_exception_log"
信息:  "t_sys_exception_log": 已经扫描了293660页的30000, 包含26可用的记录和105480不能用的记录; 在示例中有26条记录,估算所有记录为1221722 .
ANALYZE
Time: 15645.520 ms
superp2b_test=> select relname,relpages,to_char(reltuples,'999999999') from pg_class where relname like 't_sys_exception_log%';
                relname                 | relpages |  to_char  
----------------------------------------+----------+------------
 t_sys_exception_log                    |   293660 |    1221722
 t_sys_exception_log_class_name_idx     |    14818 |    1221722
 t_sys_exception_log_pkey               |    20659 |    1221722
 t_sys_exception_log_create_time_idx    |     4163 |    1221722
 t_sys_exception_log_exception_type_idx |    12629 |    1221722
 t_sys_exception_log_method_name_idx    |     8559 |    1221722
 t_sys_exception_log_operator_id_idx    |     5304 |    1221722
 t_sys_exception_log_operator_name_idx  |     5268 |    1221722
 t_sys_exception_log_bak                |       38 |        267
(9 rows)
Time: 11.437 ms
superp2b_test=> explain analyze select count(*) from t_sys_exception_log;
                                                             QUERY PLAN                                                            
------------------------------------------------------------------------------------------------------------------------------------
 Aggregate  (cost=308931.52..308931.53 rows=1 width=0) (actual time=21058.435..21058.435 rows=1 loops=1)
   ->  Seq Scan on t_sys_exception_log  (cost=0.00..305877.22 rows=1221722 width=0) (actual time=0.146..21058.327 rows=268 loops=1)
 Total runtime: 21058.525 ms
(3 rows)
Time: 21161.205 ms
superp2b_test=>

数据库依然认为,t_sys_exception_log占用293660个磁盘页,有1221722条记录。同时,这个统计信息也是错误的。

五 数据库自动收集统计信息

由于手头上有事儿,暂时停止了上述手工收集该表统计信息的工作。忙完其它事情之后,再回过头来继续的时候,发现了“惊喜”。

 superp2b_test=> explain analyze select count(*) from t_sys_exception_log;                                                      
                                                                                   QUERY PLAN                                                                                   
--------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
 Aggregate  (cost=21547.18..21547.19 rows=1 width=0) (actual time=27.386..27.386 rows=1 loops=1)
   ->  Index Only Scan using t_sys_exception_log_create_time_idx on t_sys_exception_log  (cost=0.30..20562.24 rows=393976 width=0) (actual time=9.056..27.337 rows=268 loops=1)
         Heap Fetches: 23
 Total runtime: 27.450 ms
(4 rows)

Time: 127.384 ms
superp2b_test=> select relname,relpages,to_char(reltuples,'999999999') from pg_class where relname like 't_sys_exception_log%';
                relname                 | relpages |  to_char   
----------------------------------------+----------+------------
 t_sys_exception_log                    |   293660 |     393976
 t_sys_exception_log_class_name_idx     |    14818 |        268
 t_sys_exception_log_pkey               |    20659 |        268
 t_sys_exception_log_create_time_idx    |     4163 |        268
 t_sys_exception_log_exception_type_idx |    12629 |        268
 t_sys_exception_log_method_name_idx    |     8559 |        268
 t_sys_exception_log_operator_id_idx    |     5304 |        268
 t_sys_exception_log_operator_name_idx  |     5268 |        268
 t_sys_exception_log_bak                |       38 |        267
(9 rows)

Time: 18.922 ms
superp2b_test=> analyze verbose t_sys_exception_log;                                                                           
信息:  正在分析 "public.t_sys_exception_log"
信息:  "t_sys_exception_log": 已经扫描了293660页的30000, 包含32可用的记录和20不能用的记录; 在示例中有32条记录,估算所有记录为353760 .
ANALYZE
Time: 22083.290 ms
superp2b_test=> select relname,relpages,to_char(reltuples,'999999999') from pg_class where relname like 't_sys_exception_log%';
                relname                 | relpages |  to_char   
----------------------------------------+----------+------------
 t_sys_exception_log                    |   293660 |     353760
 t_sys_exception_log_class_name_idx     |    14818 |     353760
 t_sys_exception_log_pkey               |    20659 |     353760
 t_sys_exception_log_create_time_idx    |     4163 |     353760
 t_sys_exception_log_exception_type_idx |    12629 |     353760
 t_sys_exception_log_method_name_idx    |     8559 |     353760
 t_sys_exception_log_operator_id_idx    |     5304 |     353760
 t_sys_exception_log_operator_name_idx  |     5268 |     353760
 t_sys_exception_log_bak                |       38 |        267
(9 rows)

Time: 13.805 ms
superp2b_test=> explain analyze select count(*) from t_sys_exception_log;                                                      
                                                                                  QUERY PLAN                                                                                   
-------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
 Aggregate  (cost=20885.77..20885.78 rows=1 width=0) (actual time=0.193..0.194 rows=1 loops=1)
   ->  Index Only Scan using t_sys_exception_log_create_time_idx on t_sys_exception_log  (cost=0.30..20001.37 rows=353760 width=0) (actual time=0.052..0.159 rows=268 loops=1)
         Heap Fetches: 23
 Total runtime: 0.230 ms
(4 rows)

Time: 1.753 ms
superp2b_test=> select relname,relpages,to_char(reltuples,'999999999') from pg_class where relname like 't_sys_exception_log%';
                relname                 | relpages |  to_char   
----------------------------------------+----------+------------
 t_sys_exception_log                    |   293660 |     353760
 t_sys_exception_log_class_name_idx     |    14818 |     353760
 t_sys_exception_log_pkey               |    20659 |     353760
 t_sys_exception_log_create_time_idx    |     4163 |     353760
 t_sys_exception_log_exception_type_idx |    12629 |     353760
 t_sys_exception_log_method_name_idx    |     8559 |     353760
 t_sys_exception_log_operator_id_idx    |     5304 |     353760
 t_sys_exception_log_operator_name_idx  |     5268 |     353760
 t_sys_exception_log_bak                |       38 |        267
(9 rows)

Time: 1.458 ms
superp2b_test=> vacuum(verbose,full,freeze,analyze) t_sys_exception_log;
信息:  正在清理 (vacuum)  "public.t_sys_exception_log"
信息:  "t_sys_exception_log": 在293660个页中找到0个可删除行版本,268不可删除的行版本.
DETAIL:  0 死行版本号仍不能移除.
CPU 3.04s/1.11u sec elapsed 29.73 sec.
信息:  正在分析 "public.t_sys_exception_log"
信息:  "t_sys_exception_log": 已经扫描了38页的38, 包含268可用的记录和0不能用的记录; 在示例中有268条记录,估算所有记录为268 .
VACUUM
Time: 32353.681 ms
superp2b_test=> select relname,relpages,to_char(reltuples,'999999999') from pg_class where relname like 't_sys_exception_log%';
                relname                 | relpages |  to_char   
----------------------------------------+----------+------------
 t_sys_exception_log                    |       38 |        268
 t_sys_exception_log_class_name_idx     |        5 |        268
 t_sys_exception_log_bak                |       38 |        267
 t_sys_exception_log_pkey               |        4 |        268
 t_sys_exception_log_create_time_idx    |        2 |        268
 t_sys_exception_log_exception_type_idx |        5 |        268
 t_sys_exception_log_method_name_idx    |        4 |        268
 t_sys_exception_log_operator_id_idx    |        4 |        268
 t_sys_exception_log_operator_name_idx  |        2 |        268
(9 rows)

Time: 6.762 ms
superp2b_test=> explain analyze select count(*) from t_sys_exception_log;
                                                       QUERY PLAN                                                       
------------------------------------------------------------------------------------------------------------------------
 Aggregate  (cost=41.35..41.36 rows=1 width=0) (actual time=0.103..0.103 rows=1 loops=1)
   ->  Seq Scan on t_sys_exception_log  (cost=0.00..40.68 rows=268 width=0) (actual time=0.005..0.074 rows=268 loops=1)
 Total runtime: 0.133 ms
(3 rows)

Time: 0.535 ms
superp2b_test=> select count(*) from t_sys_exception_log;                
 count 
-------
   268
(1 row)

Time: 1.007 ms
superp2b_test=>

说明:
1 第一次执行查看执行计划时,发现执行计划有所改变,变的“更快更好”了,从之前的全表扫描变为索引扫描,执行效率变好了。但是,这个离真实情况下的执行计划,应该还是有误差,因为表里才268条记录,此时不应该走index的;
2 接下来,查看统计信息,发现t_sys_exception_log表上的统计信息依然显示有393976条记录,而该表上的index却显示的有268条记录,与真实情况向吻合;
3 再手工收集一次统计信息看看,再次发生偏差,结果显示有353760条记录,连之前索引上的统计信息也从正确的268条记录,变为了353760条记录;
4 干脆执行vacuum(verbose,full,freeze,analyze) t_sys_exception_log来回收空间+更新统计信息。这里,不论是从vacuum的verbose信息来看,还是从pg_class里的信息查询来看,统计信息终于正确了;
5 最后,再次查看执行计划,发现回归正常了。统计一个只有268条记录的表数据量,其选择的全表扫描的执行计划,比较合理。且,该条语句本身,执行起来,也回归正常了,不再像前面那么慢,让人费解了。

六 小结与疑问

1 对于PostgreSQL数据库而言,如果有频繁的DML操作,或者批量DML操作的情形,要及时更新统计信息;
2 为什么手工执行analyze收集统计信息时,得到的统计信息结果,与实际情况偏差那么大?
3 多次执行analyze之后,依然得不到准确的统计信息?
4 间隔一段时间之后,发现统计信息比较接近真实情况(此时,猜测应该是数据库autovacuum自动更新了统计信息)?
5 如果是autovacuum更新统计信息之后,为什么优化器选择的执行计划不够好,只有268条记录的表执行count操作,还是选择index scan?
6 为什么,最后通过执行vacuum来回收空间+更新统计信息之后,统计信息保持正确且不再变动?

顶一下
(1)
100%
踩一下
(0)
0%
Share this Post

Leave a Comment

电子邮件地址不会被公开。 必填项已用*标注

You may use these HTML tags and attributes: <a href="" title=""> <abbr title=""> <acronym title=""> <b> <blockquote cite=""> <cite> <code> <del datetime=""> <em> <i> <q cite=""> <s> <strike> <strong>
*
*