2017年12月 – Oracle and Linux

一问题现象

接开发同事反馈，某个日志表原来有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来回收空间+更新统计信息之后，统计信息保持正确且不再变动？

Archive 2017年12月13日

PostgreSQL删除表中的大量数据之后，统计信息不准的一则案例

一问题现象

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

三分析其执行计划

四收集统计信息

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

六小结与疑问

Archive 2017年12月13日

一 问题现象

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

三 分析其执行计划

四 收集统计信息

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

六 小结与疑问

一问题现象

三分析其执行计划

四收集统计信息

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

六小结与疑问