Re: sidewinder has one failure

On 2020-01-03 15:48, Amit Kapila wrote:
> On Fri, Jan 3, 2020 at 7:03 PM Amit Kapila <[email protected]> wrote:

> I debugged on HEAD and found that we are closing all the files (like
> postgresql.conf, postgresql.auto.conf, etc.) that got opened before
> set_max_safe_fds.  I think on HEAD the 3 already opened files are
> basically stdin, stdout, stderr.   It is still not clear why on some
> other versions it shows different number of already opened files.

I think Tom Lane found the "problem".  It has to do with the semaphores 
taking up FD's.


>>>>   We can easily see the
>>>> number of already opened files by changing the error level from DEBUG2
>>>> to LOG for elog message in set_max_safe_fds.  It is not very clear to
>>>> me how many files we can expect to be kept open during startup?  Can
>>>> the number vary on different setups?
>>>
>>> Hm, where does it get the limit from?  Is it something we set?
>>>
>>> Why is this machine different from everybody else when it comes to this
>>> limit?
>>>
> 
> Mikael, is it possible for you to set log_min_messages to DEBUG2 on
> your machine and start the server.  You must see a line like:
> "max_safe_fds = 984, usable_fds = 1000, already_open = 6".  Is it
> possible to share that information?  This is just to confirm if the
> already_open number is 7 on your machine.

Sure.  I compiled pgsql 12 and this is the complete logfile after 
starting up the server the first time with log_min_messages=debug2:


2020-01-04 01:03:14.484 CET [14906] DEBUG:  registering background 
worker "logical replication launcher"
2020-01-04 01:03:14.484 CET [14906] LOG:  starting PostgreSQL 12.1 on 
x86_64-unknown-netbsd7.0, compiled by gcc (nb2 20150115) 4.8.4, 64-bit
2020-01-04 01:03:14.484 CET [14906] LOG:  listening on IPv6 address 
"::1", port 5432
2020-01-04 01:03:14.484 CET [14906] LOG:  listening on IPv4 address 
"127.0.0.1", port 5432
2020-01-04 01:03:14.485 CET [14906] LOG:  listening on Unix socket 
"/tmp/.s.PGSQL.5432"
2020-01-04 01:03:14.491 CET [14906] DEBUG:  SlruScanDirectory invoking 
callback on pg_notify/0000
2020-01-04 01:03:14.491 CET [14906] DEBUG:  removing file "pg_notify/0000"
2020-01-04 01:03:14.491 CET [14906] DEBUG:  dynamic shared memory system 
will support 308 segments
2020-01-04 01:03:14.491 CET [14906] DEBUG:  created dynamic shared 
memory control segment 2134641633 (7408 bytes)
2020-01-04 01:03:14.492 CET [14906] DEBUG:  max_safe_fds = 984, 
usable_fds = 1000, already_open = 6
2020-01-04 01:03:14.493 CET [426] LOG:  database system was shut down at 
2020-01-04 01:00:15 CET
2020-01-04 01:03:14.493 CET [426] DEBUG:  checkpoint record is at 0/15F15B8
2020-01-04 01:03:14.493 CET [426] DEBUG:  redo record is at 0/15F15B8; 
shutdown true
2020-01-04 01:03:14.493 CET [426] DEBUG:  next transaction ID: 486; next 
OID: 12974
2020-01-04 01:03:14.493 CET [426] DEBUG:  next MultiXactId: 1; next 
MultiXactOffset: 0
2020-01-04 01:03:14.493 CET [426] DEBUG:  oldest unfrozen transaction 
ID: 479, in database 1
2020-01-04 01:03:14.493 CET [426] DEBUG:  oldest MultiXactId: 1, in 
database 1
2020-01-04 01:03:14.493 CET [426] DEBUG:  commit timestamp Xid 
oldest/newest: 0/0
2020-01-04 01:03:14.493 CET [426] DEBUG:  transaction ID wrap limit is 
2147484126, limited by database with OID 1
2020-01-04 01:03:14.493 CET [426] DEBUG:  MultiXactId wrap limit is 
2147483648, limited by database with OID 1
2020-01-04 01:03:14.493 CET [426] DEBUG:  starting up replication slots
2020-01-04 01:03:14.493 CET [426] DEBUG:  starting up replication origin 
progress state
2020-01-04 01:03:14.493 CET [426] DEBUG:  MultiXactId wrap limit is 
2147483648, limited by database with OID 1
2020-01-04 01:03:14.493 CET [426] DEBUG:  MultiXact member stop limit is 
now 4294914944 based on MultiXact 1
2020-01-04 01:03:14.494 CET [14906] DEBUG:  starting background worker 
process "logical replication launcher"
2020-01-04 01:03:14.494 CET [14906] LOG:  database system is ready to 
accept connections
2020-01-04 01:03:14.495 CET [9809] DEBUG:  autovacuum launcher started
2020-01-04 01:03:14.496 CET [11463] DEBUG:  received inquiry for database 0
2020-01-04 01:03:14.496 CET [11463] DEBUG:  writing stats file 
"pg_stat_tmp/global.stat"
2020-01-04 01:03:14.497 CET [7890] DEBUG:  logical replication launcher 
started
2020-01-04 01:03:14.498 CET [28096] DEBUG:  checkpointer updated shared 
memory configuration values

/Mikael