[BUGS] BUG #14575: Standby recovery process call close() very slow,when drop (many small files) database on Primary.

The following bug has been logged on the website:

Bug reference:      14575
Logged by:          Zhou Digoal
Email address:      digoal@126.com
PostgreSQL version: 9.6.2
Operating system:   CentOS 6.x x64
Description:

HI,
  I have a user case, which will create many table (and index) in
PostgreSQL, about 3000*150 tables, and 2.25 million small file in
database.
  I also use stream replication create a physical standby.
  And in this case, user will create and drop database/schema daily, so
postgresql must create and drop about 3000*150 tables, and 2.25 million
small file in database every day.
  in this case, i found postgresql standby will delay, when checkpoint, when
drop database, when drop schema.
  I use perf, pstack see standby's startup, checkpoint process, it do
close() syscall very slow.
  but why checkpoint and drop database|schema so fast in primary?
  
Best regards, digoal.

test case:

1\.  
  
```  
create database tmp1 with template template0;  
```  
  
2\. 
  
```  
\c tmp1  
  
create table public.test(  
c0 serial  unique  check(c0>0),   
c1 serial  unique  check(c1>0),   
c2 serial  unique  check(c2>0),  
c3 serial  unique  check(c3>0),   
c4 serial  ,  
c5 serial  ,   
c6 serial  ,  
c7 serial  ,   
c8 serial  ,  
c9 serial  ,   
c10 serial  ,   
c11 serial  ,   
c12 serial  ,  
c13 serial  ,   
c14 serial  ,  
c15 serial  ,   
c16 serial  ,  
c17 serial  ,   
c18 serial  ,  
c19 serial  ,   
c20 serial  ,   
c21 serial  ,   
c22 serial  ,  
c23 serial  ,   
c24 serial  ,  
c25 serial  ,   
c26 serial  ,  
c27 serial  ,   
c28 serial  ,  
c29 serial  ,   
c30 serial  ,   
c31 serial  ,   
c32 serial  ,  
c33 serial  ,   
c34 serial  ,  
c35 serial  ,   
c36 serial  ,  
c37 serial  ,   
c38 serial  ,  
c39 serial    
);  
```  

3\. 
  
```  
for ((i=1;i<=3000;i++)) ; do psql tmp1 -c "create schema s$i" ; done  
```  
  
this step , standby no delay.
  
```  
select
pg_size_pretty(pg_xlog_location_diff(pg_current_xlog_insert_location(),sent_location)),

pg_size_pretty(pg_xlog_location_diff(pg_current_xlog_insert_location(),replay_location))
from pg_stat_replication ;  
  
\watch 1  
```  
  
4\. create table now
  
```  
vi test.sh  
  
for ((x=1;x<=150;x++)) ; do (for ((i=1;i<=3000;i++)) ; do psql tmp1 -c
"create table if not exists s$i.test$x (like public.test including all)" ;
done) & done  
  
chmod 500 test.sh  
  
nohup ./test.sh >/dev/null 2>&1 &  
```  
  
this step, standby also no delay.
  
```  
select count(*) from pg_class;  
  
2.25 million record.  
```  
  

  
```  
\l+  
52 GB   
```  
  
5\. now checkpoint in primary
  
```  
checkpoint; 

very quick end;
```  
  
on standby :   

checkpoint process CPU 100%，run about 7 hours.
  
strace -p checkpoint, many close() syscall, and very slow.  
  
perf 
  
```
perf record -avg -p checkpoint PID

perf report --stdio

    99.74%  postgres  postgres           [.] remove_from_unowned_list
            |
            --- remove_from_unowned_list
                smgrclose
                smgrcloseall
                CheckpointerMain
                AuxiliaryProcessMain
                StartChildProcess
                sigusr1_handler
                __restore_rt
                PostmasterMain
                startup_hacks
                __libc_start_main
```
  
and bgwriter perf
  
```
    99.78%  postgres  postgres           [.] remove_from_unowned_list
            |
            --- remove_from_unowned_list
                smgrclose
                smgrcloseall
                BackgroundWriterMain
                AuxiliaryProcessMain
                StartChildProcess
                sigusr1_handler
                __restore_rt
                PostmasterMain
                startup_hacks
                __libc_start_main
```
  
but checkpoint don't conflict with startup, so postgresql standby don't
delay now.

```
close(149466)                           = 0
close(137674)                           = 0
close(895987)                           = 0
--- SIGINT (Interrupt) @ 0 (0) ---
rt_sigreturn(0x7facea633e3c)            = 217400424
close(438148)                           = 0
close(541088)                           = 0
```
  
this step , i found when i use very large
max_files_per_process=1024000，checkpointer process in standby can quick stop
( restart standby ). 
  
6\. create another big database (many small files)
  
```  
create database test with template tmp1;  
```  
  
this time, standby also no delay . 

this is standby's startup process strace result.
  
```  
  
lstat("base/16384/12976402", {st_mode=S_IFREG|0600, st_size=0, ...}) = 0  
open("base/16384/12976402", O_RDONLY)   = 12  
open("base/24795111/12976402", O_RDWR|O_CREAT|O_EXCL, 0600) = 13  
read(12, "", 65536)                     = 0  
close(13)                               = 0  
close(12)                               = 0  
lstat("base/16384/305700", {st_mode=S_IFREG|0600, st_size=8192, ...}) = 0

open("base/16384/305700", O_RDONLY)     = 12  
open("base/24795111/305700", O_RDWR|O_CREAT|O_EXCL, 0600) = 13  
read(12, "\0\0\0\0\30p\234+\0\0\0\0000\0\360\37\360\37\4
\0\0\0\0b1\5\0\2\0\0\0"..., 65536) = 8192  
write(13, "\0\0\0\0\30p\234+\0\0\0\0000\0\360\37\360\37\4
\0\0\0\0b1\5\0\2\0\0\0"..., 8192) = 8192  
sync_file_range(0xd, 0, 0x2000, 0x2)    = 0  
read(12, "", 65536)                     = 0  
close(13)                               = 0  
close(12)                               = 0  
lstat("base/16384/639437", {st_mode=S_IFREG|0600, st_size=8192, ...}) = 0

```  
  
7\. drop one schema  
  
```  
\c test  
  
drop schema s1 cascade;  
```  
  
standby's startup process very slow, delay .
  
8\. drop one database
  
```  
create database test1 with template tmp1;
drop database  test;  
drop database test1;

quick on primary
```  
  
standby will delay now, startup process very slow, and CPU  100%,

```
    99.76%  postgres  postgres           [.] remove_from_unowned_list
            |
            --- remove_from_unowned_list
                smgrclose
                smgrcloseall
                XLogDropDatabase
                dbase_redo
                StartupXLOG
                StartupProcessMain
                AuxiliaryProcessMain
                StartChildProcess
                PostmasterMain
                startup_hacks
                __libc_start_main
```




--
Sent via pgsql-bugs mailing list (pgsql-bugs@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-bugs