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 <amit(dot)kapila16(at)gmail(dot)com> 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