Thread: 9.6rc1 Background worker starting multiple times
Running into an issue with pg_partman's (version 2.6.0) background worker process with 9.6rc1.
https://github.com/keithf4/pg_partman/tree/master/test/test_bgw
Noticed the issue when a user ran the pgtap tests against it and I'm seeing the same thing as well. It's working fine with 9.4 and 9.5. Looking in the postgresql logs it seems to be trying to start the initial background worker process multiple times and then one of them fails to start properly which then causes issues when maintenance tries to run. I've attached the postgresql log file from when 9.5 starts up (95_postgresql-2016-09-15_180306.log) and things are working normally and another log file from 9.6 (96_postgresql-2016-09-15_180131.log) that shows the odd startup behavior
https://github.com/keithf4/pg_partman/tree/master/test/test_bgw
Noticed the issue when a user ran the pgtap tests against it and I'm seeing the same thing as well. It's working fine with 9.4 and 9.5. Looking in the postgresql logs it seems to be trying to start the initial background worker process multiple times and then one of them fails to start properly which then causes issues when maintenance tries to run. I've attached the postgresql log file from when 9.5 starts up (95_postgresql-2016-09-15_180306.log) and things are working normally and another log file from 9.6 (96_postgresql-2016-09-15_180131.log) that shows the odd startup behavior
Attachment
On Thu, Sep 15, 2016 at 6:17 PM, Keith Fiske <keith@omniti.com> wrote: > Running into an issue with pg_partman's (version 2.6.0) background worker > process with 9.6rc1. > > https://github.com/keithf4/pg_partman/tree/master/test/test_bgw > > Noticed the issue when a user ran the pgtap tests against it and I'm seeing > the same thing as well. It's working fine with 9.4 and 9.5. Looking in the > postgresql logs it seems to be trying to start the initial background worker > process multiple times and then one of them fails to start properly which > then causes issues when maintenance tries to run. I've attached the > postgresql log file from when 9.5 starts up > (95_postgresql-2016-09-15_180306.log) and things are working normally and > another log file from 9.6 (96_postgresql-2016-09-15_180131.log) that shows > the odd startup behavior I don't know what's happening here exactly, but I think your statement that it is trying to start the same background worker multiple times is not accurate. There are a series of log entries like this: 2016-09-15 18:03:06 EDT [] [7688]: [8-1] user=,db=,e=00000 DEBUG: registering background worker "pg_partman dynamic background worker (dbname=keith)" 2016-09-15 18:03:06 EDT [] [7688]: [9-1] user=,db=,e=00000 DEBUG: starting background worker process "pg_partman dynamic background worker (dbname=keith)" 2016-09-15 18:03:06 EDT [] [7694]: [1-1] user=,db=,e=00000 LOG: autovacuum launcher started 2016-09-15 18:03:06 EDT [] [7697]: [1-1] user=,db=,e=00000 DEBUG: Before parsing dbname GUC in dynamic main func: keith 2016-09-15 18:03:06 EDT [] [7697]: [2-1] user=,db=,e=00000 DEBUG: GUC rawstring copy: keith 2016-09-15 18:03:06 EDT [] [7697]: [3-1] user=,db=,e=00000 DEBUG: Entered foreach loop: name (keith), db_main_counter (0), dbcounter (0) 2016-09-15 18:03:06 EDT [] [7697]: [4-1] user=,db=,e=00000 DEBUG: Parsing list: keith (0) 2016-09-15 18:03:06 EDT [] [7697]: [5-1] user=,db=,e=00000 DEBUG: Before run_maint initialize connection for db keith 2016-09-15 18:03:06 EDT [] [7697]: [6-1] user=,db=,e=00000 DEBUG: After run_maint initialize connection for db keith 2016-09-15 18:03:06 EDT [] [7697]: [7-1] user=,db=,e=00000 DEBUG: Checking if pg_partman extension is installed in database: keith 2016-09-15 18:03:06 EDT [] [7697]: [8-1] user=,db=,e=00000 LOG: pg_partman dynamic background worker (dbname=keith) dynamic background worker initialized with role keith on database keith 2016-09-15 18:03:06 EDT [] [7697]: [9-1] user=,db=,e=00000 LOG: pg_partman dynamic background worker (dbname=keith): SELECT partman.run_maintenance(p_analyze := true, p_jobmon := true) called by role keith on database keith 2016-09-15 18:03:06 EDT [] [7697]: [10-1] user=,db=,e=00000 DEBUG: pg_partman dynamic BGW shutting down gracefully for database keith. 2016-09-15 18:03:06 EDT [] [7688]: [10-1] user=,db=,e=00000 DEBUG: worker process: pg_partman dynamic background worker (dbname=keith) (PID 7697) exited with exit code 0 2016-09-15 18:03:06 EDT [] [7688]: [11-1] user=,db=,e=00000 DEBUG: unregistering background worker "pg_partman dynamic background worker (dbname=keith)" Note that the worker is registered (by something) at the beginning of that sequence and then unregistered (because it exited with code 0) at the end of that sequence. So the trouble isn't that the bgworker system itself is restarting the worker, but that your code keeps reregistering it. I can't guess why your code behaves differently on 9.6 than on 9.5 and prior off the top of my head, but you might want to try to figure that out. I don't rule out the possibility that there's some bug in 9.6 that is tickling your code to behave differently, but I don't think I want to try to go analyze your code and figure out what the issue is either... -- Robert Haas EnterpriseDB: http://www.enterprisedb.com The Enterprise PostgreSQL Company
On Thu, Sep 22, 2016 at 4:54 PM, Robert Haas <robertmhaas@gmail.com> wrote: > On Thu, Sep 15, 2016 at 6:17 PM, Keith Fiske <keith@omniti.com> wrote: > > Running into an issue with pg_partman's (version 2.6.0) background worker > > process with 9.6rc1. > > > > https://github.com/keithf4/pg_partman/tree/master/test/test_bgw > > > > Noticed the issue when a user ran the pgtap tests against it and I'm > seeing > > the same thing as well. It's working fine with 9.4 and 9.5. Looking in > the > > postgresql logs it seems to be trying to start the initial background > worker > > process multiple times and then one of them fails to start properly which > > then causes issues when maintenance tries to run. I've attached the > > postgresql log file from when 9.5 starts up > > (95_postgresql-2016-09-15_180306.log) and things are working normally > and > > another log file from 9.6 (96_postgresql-2016-09-15_180131.log) that > shows > > the odd startup behavior > > I don't know what's happening here exactly, but I think your statement > that it is trying to start the same background worker multiple times > is not accurate. There are a series of log entries like this: > > 2016-09-15 18:03:06 EDT [] [7688]: [8-1] user=,db=,e=00000 DEBUG: > registering background worker "pg_partman dynamic background worker > (dbname=keith)" > 2016-09-15 18:03:06 EDT [] [7688]: [9-1] user=,db=,e=00000 DEBUG: > starting background worker process "pg_partman dynamic background > worker (dbname=keith)" > 2016-09-15 18:03:06 EDT [] [7694]: [1-1] user=,db=,e=00000 LOG: > autovacuum launcher started > 2016-09-15 18:03:06 EDT [] [7697]: [1-1] user=,db=,e=00000 DEBUG: > Before parsing dbname GUC in dynamic main func: keith > 2016-09-15 18:03:06 EDT [] [7697]: [2-1] user=,db=,e=00000 DEBUG: GUC > rawstring copy: keith > 2016-09-15 18:03:06 EDT [] [7697]: [3-1] user=,db=,e=00000 DEBUG: > Entered foreach loop: name (keith), db_main_counter (0), dbcounter (0) > 2016-09-15 18:03:06 EDT [] [7697]: [4-1] user=,db=,e=00000 DEBUG: > Parsing list: keith (0) > 2016-09-15 18:03:06 EDT [] [7697]: [5-1] user=,db=,e=00000 DEBUG: > Before run_maint initialize connection for db keith > 2016-09-15 18:03:06 EDT [] [7697]: [6-1] user=,db=,e=00000 DEBUG: > After run_maint initialize connection for db keith > 2016-09-15 18:03:06 EDT [] [7697]: [7-1] user=,db=,e=00000 DEBUG: > Checking if pg_partman extension is installed in database: keith > 2016-09-15 18:03:06 EDT [] [7697]: [8-1] user=,db=,e=00000 LOG: > pg_partman dynamic background worker (dbname=keith) dynamic background > worker initialized with role keith on database keith > 2016-09-15 18:03:06 EDT [] [7697]: [9-1] user=,db=,e=00000 LOG: > pg_partman dynamic background worker (dbname=keith): SELECT > partman.run_maintenance(p_analyze := true, p_jobmon := true) called by > role keith on database keith > 2016-09-15 18:03:06 EDT [] [7697]: [10-1] user=,db=,e=00000 DEBUG: > pg_partman dynamic BGW shutting down gracefully for database keith. > 2016-09-15 18:03:06 EDT [] [7688]: [10-1] user=,db=,e=00000 DEBUG: > worker process: pg_partman dynamic background worker (dbname=keith) > (PID 7697) exited with exit code 0 > 2016-09-15 18:03:06 EDT [] [7688]: [11-1] user=,db=,e=00000 DEBUG: > unregistering background worker "pg_partman dynamic background worker > (dbname=keith)" > > Note that the worker is registered (by something) at the beginning of > that sequence and then unregistered (because it exited with code 0) at > the end of that sequence. So the trouble isn't that the bgworker > system itself is restarting the worker, but that your code keeps > reregistering it. I can't guess why your code behaves differently on > 9.6 than on 9.5 and prior off the top of my head, but you might want > to try to figure that out. I don't rule out the possibility that > there's some bug in 9.6 that is tickling your code to behave > differently, but I don't think I want to try to go analyze your code > and figure out what the issue is either... > > -- > Robert Haas > EnterpriseDB: http://www.enterprisedb.com > The Enterprise PostgreSQL Company > I was mistaken about it starting multiple times being the actual problem. I thought the master process was trying to start more than once, but that's working normally. It's the dynamic portion that's starting multiple times, and that's normal, along with the unregistering of it. The master background worker process starts up a new dynamic background worker for each database configured to run pg_partman. So, someone forked pg_partman and submitted a patch that I thought may be relevant here. Didn't fix things, but may have made the issue clearer. https://github.com/keithf4/pg_partman/pull/140/ The unclosed if statement was causing a "continue" to always be run which seemed to be causing the eventual conflict of advisory locks at some point. Removing the "continue" caused the conflict to no longer occur, but what now happens is that background worker loop executes extremely fast with no "sleep" state. It seems the latch process to cause the main background worker to wait the given number of seconds between creating the dynamic one(s) is not working. I didn't write this latch wait process myself but took it from the worker_spi example that comes with the pg source. I tested the 9.4 worker_spi I based it on in 9.6, though, and it seems to work fine. The worker_spi has changed a small bit of code in 9.5, but the change it incorporates doesn't seem to have been backpatched to 9.4, which I'm trying to stay compatible with. Right now, it seems the latch wait is no longer working. I'll continue looking myself and I've also asked the person that submitted that patch if he may be able to look as well. Appreciate your time! Keith
On Tue, Sep 27, 2016 at 11:31 AM, Keith Fiske <keith@omniti.com> wrote:
On Thu, Sep 22, 2016 at 4:54 PM, Robert Haas <robertmhaas@gmail.com> wrote:On Thu, Sep 15, 2016 at 6:17 PM, Keith Fiske <keith@omniti.com> wrote:
> Running into an issue with pg_partman's (version 2.6.0) background worker
> process with 9.6rc1.
>
> https://github.com/keithf4/pg_partman/tree/master/test/test_ bgw
>
> Noticed the issue when a user ran the pgtap tests against it and I'm seeing
> the same thing as well. It's working fine with 9.4 and 9.5. Looking in the
> postgresql logs it seems to be trying to start the initial background worker
> process multiple times and then one of them fails to start properly which
> then causes issues when maintenance tries to run. I've attached the
> postgresql log file from when 9.5 starts up
> (95_postgresql-2016-09-15_180306.log) and things are working normally and
> another log file from 9.6 (96_postgresql-2016-09-15_180131.log) that shows
> the odd startup behavior
I don't know what's happening here exactly, but I think your statement
that it is trying to start the same background worker multiple times
is not accurate. There are a series of log entries like this:
2016-09-15 18:03:06 EDT [] [7688]: [8-1] user=,db=,e=00000 DEBUG:
registering background worker "pg_partman dynamic background worker
(dbname=keith)"
2016-09-15 18:03:06 EDT [] [7688]: [9-1] user=,db=,e=00000 DEBUG:
starting background worker process "pg_partman dynamic background
worker (dbname=keith)"
2016-09-15 18:03:06 EDT [] [7694]: [1-1] user=,db=,e=00000 LOG:
autovacuum launcher started
2016-09-15 18:03:06 EDT [] [7697]: [1-1] user=,db=,e=00000 DEBUG:
Before parsing dbname GUC in dynamic main func: keith
2016-09-15 18:03:06 EDT [] [7697]: [2-1] user=,db=,e=00000 DEBUG: GUC
rawstring copy: keith
2016-09-15 18:03:06 EDT [] [7697]: [3-1] user=,db=,e=00000 DEBUG:
Entered foreach loop: name (keith), db_main_counter (0), dbcounter (0)
2016-09-15 18:03:06 EDT [] [7697]: [4-1] user=,db=,e=00000 DEBUG:
Parsing list: keith (0)
2016-09-15 18:03:06 EDT [] [7697]: [5-1] user=,db=,e=00000 DEBUG:
Before run_maint initialize connection for db keith
2016-09-15 18:03:06 EDT [] [7697]: [6-1] user=,db=,e=00000 DEBUG:
After run_maint initialize connection for db keith
2016-09-15 18:03:06 EDT [] [7697]: [7-1] user=,db=,e=00000 DEBUG:
Checking if pg_partman extension is installed in database: keith
2016-09-15 18:03:06 EDT [] [7697]: [8-1] user=,db=,e=00000 LOG:
pg_partman dynamic background worker (dbname=keith) dynamic background
worker initialized with role keith on database keith
2016-09-15 18:03:06 EDT [] [7697]: [9-1] user=,db=,e=00000 LOG:
pg_partman dynamic background worker (dbname=keith): SELECT
partman.run_maintenance(p_analyze := true, p_jobmon := true) called by
role keith on database keith
2016-09-15 18:03:06 EDT [] [7697]: [10-1] user=,db=,e=00000 DEBUG:
pg_partman dynamic BGW shutting down gracefully for database keith.
2016-09-15 18:03:06 EDT [] [7688]: [10-1] user=,db=,e=00000 DEBUG:
worker process: pg_partman dynamic background worker (dbname=keith)
(PID 7697) exited with exit code 0
2016-09-15 18:03:06 EDT [] [7688]: [11-1] user=,db=,e=00000 DEBUG:
unregistering background worker "pg_partman dynamic background worker
(dbname=keith)"
Note that the worker is registered (by something) at the beginning of
that sequence and then unregistered (because it exited with code 0) at
the end of that sequence. So the trouble isn't that the bgworker
system itself is restarting the worker, but that your code keeps
reregistering it. I can't guess why your code behaves differently on
9.6 than on 9.5 and prior off the top of my head, but you might want
to try to figure that out. I don't rule out the possibility that
there's some bug in 9.6 that is tickling your code to behave
differently, but I don't think I want to try to go analyze your code
and figure out what the issue is either...
--
Robert Haas
EnterpriseDB: http://www.enterprisedb.com
The Enterprise PostgreSQL CompanyI was mistaken about it starting multiple times being the actual problem. I thought the master process was trying to start more than once, but that's working normally. It's the dynamic portion that's starting multiple times, and that's normal, along with the unregistering of it. The master background worker process starts up a new dynamic background worker for each database configured to run pg_partman.
So, someone forked pg_partman and submitted a patch that I thought may be relevant here. Didn't fix things, but may have made the issue clearer.
https://github.com/keithf4/pg_partman/pull/140/ The unclosed if statement was causing a "continue" to always be run which seemed to be causing the eventual conflict of advisory locks at some point. Removing the "continue" caused the conflict to no longer occur, but what now happens is that background worker loop executes extremely fast with no "sleep" state. It seems the latch process to cause the main background worker to wait the given number of seconds between creating the dynamic one(s) is not working. I didn't write this latch wait process myself but took it from the worker_spi example that comes with the pg source. I tested the 9.4 worker_spi I based it on in 9.6, though, and it seems to work fine. The worker_spi has changed a small bit of code in 9.5, but the change it incorporates doesn't seem to have been backpatched to 9.4, which I'm trying to stay compatible with.Right now, it seems the latch wait is no longer working. I'll continue looking myself and I've also asked the person that submitted that patch if he may be able to look as well. Appreciate your time!Keith
So trying to dig into this more myself, I added some debugging lines in the attached copy of the bgw file to check the status of whether the latch is getting set/reset properly. You don't even have to configure any partition sets to see this happen, just load the library in postgresql.conf and set a time, database & user with the partman GUCs. Below is from the log file when running 9.6. You can see that something is setting the Latch when the Wait is called causing it to immediately continue to the next loop with no timeout.
2016-12-13 16:16:31 EST [] [6750]: [2-1] user=,db=,e=00000 DEBUG: Latch status just before for loop: 1
2016-12-13 16:16:31 EST [] [6750]: [3-1] user=,db=,e=00000 DEBUG: Latch status inside for loop before reset: 1
2016-12-13 16:16:31 EST [] [6750]: [4-1] user=,db=,e=00000 DEBUG: Latch status just after reset before interupt check: 0
2016-12-13 16:16:31 EST [] [6750]: [5-1] user=,db=,e=00000 DEBUG: Latch status just after reset after interupt check: 0
2016-12-13 16:16:31 EST [] [6750]: [6-1] user=,db=,e=00000 DEBUG: Dynamic bgw launch begun for keith (0)
2016-12-13 16:16:31 EST [] [6741]: [8-1] user=,db=,e=00000 DEBUG: registering background worker "pg_partman dynamic background worker (dbname=keith)"
2016-12-13 16:16:31 EST [] [6741]: [9-1] user=,db=,e=00000 DEBUG: starting background worker process "pg_partman dynamic background worker (dbname=keith)"
2016-12-13 16:16:31 EST [] [6750]: [7-1] user=,db=,e=00000 DEBUG: Latch status just before wait call: 0
2016-12-13 16:16:31 EST [] [6747]: [1-1] user=,db=,e=00000 LOG: autovacuum launcher started
2016-12-13 16:16:31 EST [] [6751]: [1-1] user=,db=,e=00000 DEBUG: Before parsing dbname GUC in dynamic main func: keith
2016-12-13 16:16:31 EST [] [6751]: [2-1] user=,db=,e=00000 DEBUG: GUC rawstring copy: keith
2016-12-13 16:16:31 EST [] [6751]: [3-1] user=,db=,e=00000 DEBUG: Entered foreach loop: name (keith), db_main_counter (0), dbcounter (0)
2016-12-13 16:16:31 EST [] [6751]: [4-1] user=,db=,e=00000 DEBUG: Parsing list: keith (0)
2016-12-13 16:16:31 EST [] [6751]: [5-1] user=,db=,e=00000 DEBUG: Before run_maint initialize connection for db keith
2016-12-13 16:16:31 EST [] [6751]: [6-1] user=,db=,e=00000 DEBUG: After run_maint initialize connection for db keith
2016-12-13 16:16:31 EST [] [6751]: [7-1] user=,db=,e=00000 DEBUG: Checking if pg_partman extension is installed in database: keith
2016-12-13 16:16:31 EST [] [6751]: [8-1] user=,db=,e=00000 LOG: pg_partman dynamic background worker (dbname=keith) dynamic background worker initialized with role keith on database keith
2016-12-13 16:16:31 EST [] [6751]: [9-1] user=,db=,e=00000 LOG: pg_partman dynamic background worker (dbname=keith): SELECT "partman".run_maintenance(p_an alyze := true, p_jobmon := true) called by role keith on database keith
2016-12-13 16:16:31 EST [] [6751]: [10-1] user=,db=,e=00000 DEBUG: pg_partman dynamic BGW shutting down gracefully for database keith.
2016-12-13 16:16:31 EST [] [6741]: [10-1] user=,db=,e=00000 DEBUG: worker process: pg_partman dynamic background worker (dbname=keith) (PID 6751) exited with exit code 0
2016-12-13 16:16:31 EST [] [6741]: [11-1] user=,db=,e=00000 DEBUG: unregistering background worker "pg_partman dynamic background worker (dbname=keith)"
2016-12-13 16:16:31 EST [] [6750]: [8-1] user=,db=,e=00000 DEBUG: Latch status after wait call: 1
2016-12-13 16:16:31 EST [] [6750]: [9-1] user=,db=,e=00000 DEBUG: Latch status inside for loop before reset: 1
2016-12-13 16:16:31 EST [] [6750]: [10-1] user=,db=,e=00000 DEBUG: Latch status just after reset before interupt check: 0
2016-12-13 16:16:31 EST [] [6750]: [11-1] user=,db=,e=00000 DEBUG: Latch status just after reset after interupt check: 0
2016-12-13 16:16:31 EST [] [6750]: [12-1] user=,db=,e=00000 DEBUG: Dynamic bgw launch begun for keith (0)
2016-12-13 16:16:31 EST [] [6741]: [12-1] user=,db=,e=00000 DEBUG: registering background worker "pg_partman dynamic background worker (dbname=keith)"
2016-12-13 16:16:31 EST [] [6741]: [13-1] user=,db=,e=00000 DEBUG: starting background worker process "pg_partman dynamic background worker (dbname=keith)"
2016-12-13 16:16:31 EST [] [6752]: [1-1] user=,db=,e=00000 DEBUG: Before parsing dbname GUC in dynamic main func: keith
2016-12-13 16:16:31 EST [] [6752]: [2-1] user=,db=,e=00000 DEBUG: GUC rawstring copy: keith
2016-12-13 16:16:31 EST [] [6752]: [3-1] user=,db=,e=00000 DEBUG: Entered foreach loop: name (keith), db_main_counter (0), dbcounter (0)
2016-12-13 16:16:31 EST [] [6752]: [4-1] user=,db=,e=00000 DEBUG: Parsing list: keith (0)
2016-12-13 16:16:31 EST [] [6752]: [5-1] user=,db=,e=00000 DEBUG: Before run_maint initialize connection for db keith
2016-12-13 16:16:31 EST [] [6752]: [6-1] user=,db=,e=00000 DEBUG: After run_maint initialize connection for db keith
2016-12-13 16:16:31 EST [] [6752]: [7-1] user=,db=,e=00000 DEBUG: Checking if pg_partman extension is installed in database: keith
2016-12-13 16:16:31 EST [] [6752]: [8-1] user=,db=,e=00000 LOG: pg_partman dynamic background worker (dbname=keith) dynamic background worker initialized with role keith on database keith
2016-12-13 16:16:31 EST [] [6750]: [13-1] user=,db=,e=00000 DEBUG: Latch status just before wait call: 0
2016-12-13 16:16:31 EST [] [6752]: [9-1] user=,db=,e=00000 LOG: pg_partman dynamic background worker (dbname=keith): SELECT "partman".run_maintenance(p_an alyze := true, p_jobmon := true) called by role keith on database keith
2016-12-13 16:16:31 EST [] [6752]: [10-1] user=,db=,e=00000 DEBUG: pg_partman dynamic BGW shutting down gracefully for database keith.
2016-12-13 16:16:31 EST [] [6741]: [14-1] user=,db=,e=00000 DEBUG: worker process: pg_partman dynamic background worker (dbname=keith) (PID 6752) exited with exit code 0
2016-12-13 16:16:31 EST [] [6741]: [15-1] user=,db=,e=00000 DEBUG: unregistering background worker "pg_partman dynamic background worker (dbname=keith)"
2016-12-13 16:16:31 EST [] [6750]: [14-1] user=,db=,e=00000 DEBUG: Latch status after wait call: 1
2016-12-13 16:16:31 EST [] [6750]: [15-1] user=,db=,e=00000 DEBUG: Latch status inside for loop before reset: 1
2016-12-13 16:16:31 EST [] [6750]: [2-1] user=,db=,e=00000 DEBUG: Latch status just before for loop: 1
2016-12-13 16:16:31 EST [] [6750]: [3-1] user=,db=,e=00000 DEBUG: Latch status inside for loop before reset: 1
2016-12-13 16:16:31 EST [] [6750]: [4-1] user=,db=,e=00000 DEBUG: Latch status just after reset before interupt check: 0
2016-12-13 16:16:31 EST [] [6750]: [5-1] user=,db=,e=00000 DEBUG: Latch status just after reset after interupt check: 0
2016-12-13 16:16:31 EST [] [6750]: [6-1] user=,db=,e=00000 DEBUG: Dynamic bgw launch begun for keith (0)
2016-12-13 16:16:31 EST [] [6741]: [8-1] user=,db=,e=00000 DEBUG: registering background worker "pg_partman dynamic background worker (dbname=keith)"
2016-12-13 16:16:31 EST [] [6741]: [9-1] user=,db=,e=00000 DEBUG: starting background worker process "pg_partman dynamic background worker (dbname=keith)"
2016-12-13 16:16:31 EST [] [6750]: [7-1] user=,db=,e=00000 DEBUG: Latch status just before wait call: 0
2016-12-13 16:16:31 EST [] [6747]: [1-1] user=,db=,e=00000 LOG: autovacuum launcher started
2016-12-13 16:16:31 EST [] [6751]: [1-1] user=,db=,e=00000 DEBUG: Before parsing dbname GUC in dynamic main func: keith
2016-12-13 16:16:31 EST [] [6751]: [2-1] user=,db=,e=00000 DEBUG: GUC rawstring copy: keith
2016-12-13 16:16:31 EST [] [6751]: [3-1] user=,db=,e=00000 DEBUG: Entered foreach loop: name (keith), db_main_counter (0), dbcounter (0)
2016-12-13 16:16:31 EST [] [6751]: [4-1] user=,db=,e=00000 DEBUG: Parsing list: keith (0)
2016-12-13 16:16:31 EST [] [6751]: [5-1] user=,db=,e=00000 DEBUG: Before run_maint initialize connection for db keith
2016-12-13 16:16:31 EST [] [6751]: [6-1] user=,db=,e=00000 DEBUG: After run_maint initialize connection for db keith
2016-12-13 16:16:31 EST [] [6751]: [7-1] user=,db=,e=00000 DEBUG: Checking if pg_partman extension is installed in database: keith
2016-12-13 16:16:31 EST [] [6751]: [8-1] user=,db=,e=00000 LOG: pg_partman dynamic background worker (dbname=keith) dynamic background worker initialized with role keith on database keith
2016-12-13 16:16:31 EST [] [6751]: [9-1] user=,db=,e=00000 LOG: pg_partman dynamic background worker (dbname=keith): SELECT "partman".run_maintenance(p_an
2016-12-13 16:16:31 EST [] [6751]: [10-1] user=,db=,e=00000 DEBUG: pg_partman dynamic BGW shutting down gracefully for database keith.
2016-12-13 16:16:31 EST [] [6741]: [10-1] user=,db=,e=00000 DEBUG: worker process: pg_partman dynamic background worker (dbname=keith) (PID 6751) exited with exit code 0
2016-12-13 16:16:31 EST [] [6741]: [11-1] user=,db=,e=00000 DEBUG: unregistering background worker "pg_partman dynamic background worker (dbname=keith)"
2016-12-13 16:16:31 EST [] [6750]: [8-1] user=,db=,e=00000 DEBUG: Latch status after wait call: 1
2016-12-13 16:16:31 EST [] [6750]: [9-1] user=,db=,e=00000 DEBUG: Latch status inside for loop before reset: 1
2016-12-13 16:16:31 EST [] [6750]: [10-1] user=,db=,e=00000 DEBUG: Latch status just after reset before interupt check: 0
2016-12-13 16:16:31 EST [] [6750]: [11-1] user=,db=,e=00000 DEBUG: Latch status just after reset after interupt check: 0
2016-12-13 16:16:31 EST [] [6750]: [12-1] user=,db=,e=00000 DEBUG: Dynamic bgw launch begun for keith (0)
2016-12-13 16:16:31 EST [] [6741]: [12-1] user=,db=,e=00000 DEBUG: registering background worker "pg_partman dynamic background worker (dbname=keith)"
2016-12-13 16:16:31 EST [] [6741]: [13-1] user=,db=,e=00000 DEBUG: starting background worker process "pg_partman dynamic background worker (dbname=keith)"
2016-12-13 16:16:31 EST [] [6752]: [1-1] user=,db=,e=00000 DEBUG: Before parsing dbname GUC in dynamic main func: keith
2016-12-13 16:16:31 EST [] [6752]: [2-1] user=,db=,e=00000 DEBUG: GUC rawstring copy: keith
2016-12-13 16:16:31 EST [] [6752]: [3-1] user=,db=,e=00000 DEBUG: Entered foreach loop: name (keith), db_main_counter (0), dbcounter (0)
2016-12-13 16:16:31 EST [] [6752]: [4-1] user=,db=,e=00000 DEBUG: Parsing list: keith (0)
2016-12-13 16:16:31 EST [] [6752]: [5-1] user=,db=,e=00000 DEBUG: Before run_maint initialize connection for db keith
2016-12-13 16:16:31 EST [] [6752]: [6-1] user=,db=,e=00000 DEBUG: After run_maint initialize connection for db keith
2016-12-13 16:16:31 EST [] [6752]: [7-1] user=,db=,e=00000 DEBUG: Checking if pg_partman extension is installed in database: keith
2016-12-13 16:16:31 EST [] [6752]: [8-1] user=,db=,e=00000 LOG: pg_partman dynamic background worker (dbname=keith) dynamic background worker initialized with role keith on database keith
2016-12-13 16:16:31 EST [] [6750]: [13-1] user=,db=,e=00000 DEBUG: Latch status just before wait call: 0
2016-12-13 16:16:31 EST [] [6752]: [9-1] user=,db=,e=00000 LOG: pg_partman dynamic background worker (dbname=keith): SELECT "partman".run_maintenance(p_an
2016-12-13 16:16:31 EST [] [6752]: [10-1] user=,db=,e=00000 DEBUG: pg_partman dynamic BGW shutting down gracefully for database keith.
2016-12-13 16:16:31 EST [] [6741]: [14-1] user=,db=,e=00000 DEBUG: worker process: pg_partman dynamic background worker (dbname=keith) (PID 6752) exited with exit code 0
2016-12-13 16:16:31 EST [] [6741]: [15-1] user=,db=,e=00000 DEBUG: unregistering background worker "pg_partman dynamic background worker (dbname=keith)"
2016-12-13 16:16:31 EST [] [6750]: [14-1] user=,db=,e=00000 DEBUG: Latch status after wait call: 1
2016-12-13 16:16:31 EST [] [6750]: [15-1] user=,db=,e=00000 DEBUG: Latch status inside for loop before reset: 1
However, when running this in 9.5, you can see the latch is never set during the Wait (except when the bgw is first started) and the WaitLatch() is able to use the timeout properly (currently set for 10 seconds)
2016-12-13 16:22:58 EST [] [7743]: [2-1] user=,db=,e=00000 DEBUG: Latch status just before for loop: 1
2016-12-13 16:22:58 EST [] [7743]: [3-1] user=,db=,e=00000 DEBUG: Latch status inside for loop before reset: 1
2016-12-13 16:22:58 EST [] [7743]: [4-1] user=,db=,e=00000 DEBUG: Latch status just after reset before interupt check: 0
2016-12-13 16:22:58 EST [] [7743]: [5-1] user=,db=,e=00000 DEBUG: Latch status just after reset after interupt check: 0
2016-12-13 16:22:58 EST [] [7743]: [6-1] user=,db=,e=00000 DEBUG: Dynamic bgw launch begun for keith (0)
2016-12-13 16:22:58 EST [] [7735]: [8-1] user=,db=,e=00000 DEBUG: registering background worker "pg_partman dynamic background worker (dbname=keith)"
2016-12-13 16:22:58 EST [] [7735]: [9-1] user=,db=,e=00000 DEBUG: starting background worker process "pg_partman dynamic background worker (dbname=keith)"
2016-12-13 16:22:58 EST [] [7743]: [7-1] user=,db=,e=00000 DEBUG: Latch status just before wait call: 0
2016-12-13 16:22:58 EST [] [7741]: [1-1] user=,db=,e=00000 LOG: autovacuum launcher started
2016-12-13 16:22:58 EST [] [7744]: [1-1] user=,db=,e=00000 DEBUG: Before parsing dbname GUC in dynamic main func: keith
2016-12-13 16:22:58 EST [] [7744]: [2-1] user=,db=,e=00000 DEBUG: GUC rawstring copy: keith
2016-12-13 16:22:58 EST [] [7744]: [3-1] user=,db=,e=00000 DEBUG: Entered foreach loop: name (keith), db_main_counter (0), dbcounter (0)
2016-12-13 16:22:58 EST [] [7744]: [4-1] user=,db=,e=00000 DEBUG: Parsing list: keith (0)
2016-12-13 16:22:58 EST [] [7744]: [5-1] user=,db=,e=00000 DEBUG: Before run_maint initialize connection for db keith
2016-12-13 16:22:58 EST [] [7744]: [6-1] user=,db=,e=00000 DEBUG: After run_maint initialize connection for db keith
2016-12-13 16:22:58 EST [] [7744]: [7-1] user=,db=,e=00000 DEBUG: Checking if pg_partman extension is installed in database: keith
2016-12-13 16:22:58 EST [] [7744]: [8-1] user=,db=,e=00000 LOG: pg_partman dynamic background worker (dbname=keith) dynamic background worker initialized with role keith on database keith
2016-12-13 16:22:58 EST [] [7744]: [9-1] user=,db=,e=00000 LOG: pg_partman dynamic background worker (dbname=keith): SELECT "partman".run_maintenance(p_an
2016-12-13 16:22:58 EST [] [7744]: [10-1] user=,db=,e=00000 DEBUG: pg_partman dynamic BGW shutting down gracefully for database keith.
2016-12-13 16:22:58 EST [] [7735]: [10-1] user=,db=,e=00000 DEBUG: worker process: pg_partman dynamic background worker (dbname=keith) (PID 7744) exited with exit code 0
2016-12-13 16:22:58 EST [] [7735]: [11-1] user=,db=,e=00000 DEBUG: unregistering background worker "pg_partman dynamic background worker (dbname=keith)"
2016-12-13 16:23:08 EST [] [7743]: [8-1] user=,db=,e=00000 DEBUG: Latch status after wait call: 0
2016-12-13 16:23:08 EST [] [7743]: [9-1] user=,db=,e=00000 DEBUG: Latch status inside for loop before reset: 0
2016-12-13 16:23:08 EST [] [7743]: [10-1] user=,db=,e=00000 DEBUG: Latch status just after reset before interupt check: 0
2016-12-13 16:23:08 EST [] [7743]: [11-1] user=,db=,e=00000 DEBUG: Latch status just after reset after interupt check: 0
2016-12-13 16:23:08 EST [] [7743]: [12-1] user=,db=,e=00000 DEBUG: Dynamic bgw launch begun for keith (0)
2016-12-13 16:23:08 EST [] [7735]: [12-1] user=,db=,e=00000 DEBUG: registering background worker "pg_partman dynamic background worker (dbname=keith)"
2016-12-13 16:23:08 EST [] [7735]: [13-1] user=,db=,e=00000 DEBUG: starting background worker process "pg_partman dynamic background worker (dbname=keith)"
2016-12-13 16:23:08 EST [] [7754]: [1-1] user=,db=,e=00000 DEBUG: Before parsing dbname GUC in dynamic main func: keith
2016-12-13 16:23:08 EST [] [7754]: [2-1] user=,db=,e=00000 DEBUG: GUC rawstring copy: keith
2016-12-13 16:23:08 EST [] [7754]: [3-1] user=,db=,e=00000 DEBUG: Entered foreach loop: name (keith), db_main_counter (0), dbcounter (0)
2016-12-13 16:23:08 EST [] [7754]: [4-1] user=,db=,e=00000 DEBUG: Parsing list: keith (0)
2016-12-13 16:23:08 EST [] [7754]: [5-1] user=,db=,e=00000 DEBUG: Before run_maint initialize connection for db keith
2016-12-13 16:23:08 EST [] [7754]: [6-1] user=,db=,e=00000 DEBUG: After run_maint initialize connection for db keith
2016-12-13 16:23:08 EST [] [7754]: [7-1] user=,db=,e=00000 DEBUG: Checking if pg_partman extension is installed in database: keith
2016-12-13 16:23:08 EST [] [7743]: [13-1] user=,db=,e=00000 DEBUG: Latch status just before wait call: 0
2016-12-13 16:23:08 EST [] [7754]: [8-1] user=,db=,e=00000 LOG: pg_partman dynamic background worker (dbname=keith) dynamic background worker initialized with role keith on database keith
2016-12-13 16:23:08 EST [] [7754]: [9-1] user=,db=,e=00000 LOG: pg_partman dynamic background worker (dbname=keith): SELECT "partman".run_maintenance(p_an
2016-12-13 16:23:08 EST [] [7754]: [10-1] user=,db=,e=00000 DEBUG: pg_partman dynamic BGW shutting down gracefully for database keith.
2016-12-13 16:23:08 EST [] [7735]: [14-1] user=,db=,e=00000 DEBUG: worker process: pg_partman dynamic background worker (dbname=keith) (PID 7754) exited with exit code 0
2016-12-13 16:23:08 EST [] [7735]: [15-1] user=,db=,e=00000 DEBUG: unregistering background worker "pg_partman dynamic background worker (dbname=keith)"
2016-12-13 16:23:18 EST [] [7743]: [14-1] user=,db=,e=00000 DEBUG: Latch status after wait call: 0
2016-12-13 16:23:18 EST [] [7743]: [15-1] user=,db=,e=00000 DEBUG: Latch status inside for loop before reset: 0
I'm not quite sure exactly how to debug this further to see what is actually setting the latch in 9.6.
Attachment
On Tue, Dec 20, 2016 at 6:47 AM, Keith Fiske <keith@omniti.com> wrote: > I'm not quite sure exactly how to debug this further to see what is actually > setting the latch in 9.6. The commit you are complaining about here is likely this one: commit: db0f6cad4884bd4c835156d3a720d9a79dbd63a9 author: Robert Haas <rhaas@postgresql.org> date: Fri, 9 Oct 2015 14:31:04 -0400 Remove set_latch_on_sigusr1 flag. This flag has proven to be a recipe for bugs, and it doesn't seem like it can really buy anything in terms of performance. So let's just *always* set the process latch when we receive SIGUSR1 instead of trying to do it only when needed. So your process gets a SIGUSR1 and its latch is set, causing the loop to repeat... I would discard that as a backend bug, because the removal of set_latch_on_sigusr1 was a good move. -- Michael -- Sent via pgsql-bugs mailing list (pgsql-bugs@postgresql.org) To make changes to your subscription: http://www.postgresql.org/mailpref/pgsql-bugs
On Tue, Dec 20, 2016 at 1:42 AM, Michael Paquier <michael.paquier@gmail.com> wrote:
On Tue, Dec 20, 2016 at 6:47 AM, Keith Fiske <keith@omniti.com> wrote:
> I'm not quite sure exactly how to debug this further to see what is actually
> setting the latch in 9.6.
The commit you are complaining about here is likely this one:
commit: db0f6cad4884bd4c835156d3a720d9a79dbd63a9
author: Robert Haas <rhaas@postgresql.org>
date: Fri, 9 Oct 2015 14:31:04 -0400
Remove set_latch_on_sigusr1 flag.
This flag has proven to be a recipe for bugs, and it doesn't seem like
it can really buy anything in terms of performance. So let's just
*always* set the process latch when we receive SIGUSR1 instead of
trying to do it only when needed.
So your process gets a SIGUSR1 and its latch is set, causing the loop
to repeat... I would discard that as a backend bug, because the
removal of set_latch_on_sigusr1 was a good move.
--
Michael
Anything I can do in the mean time to fix this, or have to wait for a bugfix patch?
Keith
-On Tue, Dec 20, 2016 at 10:26 AM, Keith Fiske <keith@omniti.com> wrote:
On Tue, Dec 20, 2016 at 1:42 AM, Michael Paquier <michael.paquier@gmail.com> wrote:On Tue, Dec 20, 2016 at 6:47 AM, Keith Fiske <keith@omniti.com> wrote:
> I'm not quite sure exactly how to debug this further to see what is actually
> setting the latch in 9.6.
The commit you are complaining about here is likely this one:
commit: db0f6cad4884bd4c835156d3a720d9a79dbd63a9
author: Robert Haas <rhaas@postgresql.org>
date: Fri, 9 Oct 2015 14:31:04 -0400
Remove set_latch_on_sigusr1 flag.
This flag has proven to be a recipe for bugs, and it doesn't seem like
it can really buy anything in terms of performance. So let's just
*always* set the process latch when we receive SIGUSR1 instead of
trying to do it only when needed.
So your process gets a SIGUSR1 and its latch is set, causing the loop
to repeat... I would discard that as a backend bug, because the
removal of set_latch_on_sigusr1 was a good move.
--
MichaelAnything I can do in the mean time to fix this, or have to wait for a bugfix patch?Keith
So, attached is my naive attempt to try and handle SIGUSR1. Can at least confirm this is the source of the problem, but I'm unable to figure out how to work around it. Handling it does in fact stop the background worker from going nuts anymore. But it also completely stops the maintenance loop from working properly. It runs once, then never again. It seems to get stuck after the call to WaitForBackgroundWorkerStartup() and never even gets to my WaitLatch() call. There is logging that it successfully unregisters the dynamic BGW, but never seems to go further than that. I tried adding latch_sigusr1_handler() similar to how the handler in procsignal.c does, but didn't seem to fix it. With some additional debugging I added, it doesn't even appear to be calling my custom signal handler function at all. got_sigusr1 is never set to true.
The simple act of registering to listen for the SIGUSR1 seems to stop the original bug. If I comment out just this line in pg_partman_bgw_main() (the one in pg_partman_bgw_run_maint() seems to make no difference):
pqsignal(SIGUSR1, pg_partman_bgw_sigusr1);
it goes back to doing what it was doing before.
The simple act of registering to listen for the SIGUSR1 seems to stop the original bug. If I comment out just this line in pg_partman_bgw_main() (the one in pg_partman_bgw_run_maint() seems to make no difference):
pqsignal(SIGUSR1, pg_partman_bgw_sigusr1);
Guessing there's a lot more to SIGUSR1 than I can see right now. But figured I'd at least try to provide some additional investigation. I noticed in the BGW code, it mentions using SIGUSR1 on start/stop.
https://doxygen.postgresql.org/bgworker_8h_source.html#l00099
Perhaps that's part of the issue when I try and handle it instead?
https://doxygen.postgresql.org/bgworker_8h_source.html#l00099
Perhaps that's part of the issue when I try and handle it instead?
partman maintenance timer is set for 10 seconds so the timestamp on the log entries shows it's not running on time.
2016-12-20 11:56:46 EST [] [14486]: [7-1] user=,db=,e=00000 LOG: database system is ready to accept connections
2016-12-20 11:56:46 EST [] [14495]: [1-1] user=,db=,e=00000 LOG: pg_partman master background worker master process initialized with role keith
2016-12-20 11:56:46 EST [] [14495]: [2-1] user=,db=,e=00000 DEBUG: Latch status just before for loop: 1
2016-12-20 11:56:46 EST [] [14495]: [3-1] user=,db=,e=00000 DEBUG: Latch status inside for loop before reset: 1
2016-12-20 11:56:46 EST [] [14495]: [4-1] user=,db=,e=00000 DEBUG: Latch status just after reset before interupt check: 0
2016-12-20 11:56:46 EST [] [14495]: [5-1] user=,db=,e=00000 DEBUG: Latch status just after reset after interupt check: 0
2016-12-20 11:56:46 EST [] [14495]: [6-1] user=,db=,e=00000 DEBUG: After sighup check: 0
2016-12-20 11:56:46 EST [] [14495]: [7-1] user=,db=,e=00000 DEBUG: After sigterm check: 0
2016-12-20 11:56:46 EST [] [14495]: [8-1] user=,db=,e=00000 DEBUG: Before sigusr1 check: 0
2016-12-20 11:56:46 EST [] [14495]: [9-1] user=,db=,e=00000 DEBUG: After sigusr1 check: 0
2016-12-20 11:56:46 EST [] [14495]: [10-1] user=,db=,e=00000 DEBUG: Dynamic bgw launch begun for keith (0)
2016-12-20 11:56:46 EST [] [14495]: [11-1] user=,db=,e=00000 DEBUG: Registering dynamic background worker...
2016-12-20 11:56:46 EST [] [14495]: [12-1] user=,db=,e=00000 DEBUG: Waiting for BGW startup...
2016-12-20 11:56:46 EST [] [14486]: [8-1] user=,db=,e=00000 DEBUG: registering background worker "pg_partman dynamic background worker (dbname=keith)"
2016-12-20 11:56:46 EST [] [14486]: [9-1] user=,db=,e=00000 DEBUG: starting background worker process "pg_partman dynamic background worker (dbname=keith)"
2016-12-20 11:56:46 EST [] [14493]: [1-1] user=,db=,e=00000 LOG: autovacuum launcher started
2016-12-20 11:56:46 EST [] [14496]: [1-1] user=,db=,e=00000 DEBUG: Before parsing dbname GUC in dynamic main func: keith
2016-12-20 11:56:46 EST [] [14496]: [2-1] user=,db=,e=00000 DEBUG: GUC rawstring copy: keith
2016-12-20 11:56:46 EST [] [14496]: [3-1] user=,db=,e=00000 DEBUG: Entered foreach loop: name (keith), db_main_counter (0), dbcounter (0)
2016-12-20 11:56:46 EST [] [14496]: [4-1] user=,db=,e=00000 DEBUG: Parsing list: keith (0)
2016-12-20 11:56:46 EST [] [14496]: [5-1] user=,db=,e=00000 DEBUG: Before run_maint initialize connection for db keith
2016-12-20 11:56:46 EST [] [14496]: [6-1] user=,db=,e=00000 DEBUG: After run_maint initialize connection for db keith
2016-12-20 11:56:46 EST [] [14496]: [7-1] user=,db=,e=00000 DEBUG: Checking if pg_partman extension is installed in database: keith
2016-12-20 11:56:46 EST [] [14496]: [8-1] user=,db=,e=00000 LOG: pg_partman dynamic background worker (dbname=keith) dynamic background worker initialized with role keith on database keith
2016-12-20 11:56:46 EST [] [14496]: [9-1] user=,db=,e=00000 LOG: pg_partman dynamic background worker (dbname=keith): SELECT "partman".run_maintenance(p_analyze := true, p_jobmon := true) called by role keith on database keith
2016-12-20 11:56:46 EST [] [14496]: [10-1] user=,db=,e=00000 DEBUG: pg_partman dynamic BGW shutting down gracefully for database keith.
2016-12-20 11:56:46 EST [] [14486]: [10-1] user=,db=,e=00000 DEBUG: worker process: pg_partman dynamic background worker (dbname=keith) (PID 14496) exited with exit code 0
2016-12-20 11:56:46 EST [] [14486]: [11-1] user=,db=,e=00000 DEBUG: unregistering background worker "pg_partman dynamic background worker (dbname=keith)"
2016-12-20 11:57:16 EST [] [14506]: [1-1] user=,db=,e=00000 DEBUG: autovacuum: processing database "keith"
2016-12-20 11:57:46 EST [] [14515]: [1-1] user=,db=,e=00000 DEBUG: autovacuum: processing database "postgres"
2
2016-12-20 11:56:46 EST [] [14486]: [7-1] user=,db=,e=00000 LOG: database system is ready to accept connections
2016-12-20 11:56:46 EST [] [14495]: [1-1] user=,db=,e=00000 LOG: pg_partman master background worker master process initialized with role keith
2016-12-20 11:56:46 EST [] [14495]: [2-1] user=,db=,e=00000 DEBUG: Latch status just before for loop: 1
2016-12-20 11:56:46 EST [] [14495]: [3-1] user=,db=,e=00000 DEBUG: Latch status inside for loop before reset: 1
2016-12-20 11:56:46 EST [] [14495]: [4-1] user=,db=,e=00000 DEBUG: Latch status just after reset before interupt check: 0
2016-12-20 11:56:46 EST [] [14495]: [5-1] user=,db=,e=00000 DEBUG: Latch status just after reset after interupt check: 0
2016-12-20 11:56:46 EST [] [14495]: [6-1] user=,db=,e=00000 DEBUG: After sighup check: 0
2016-12-20 11:56:46 EST [] [14495]: [7-1] user=,db=,e=00000 DEBUG: After sigterm check: 0
2016-12-20 11:56:46 EST [] [14495]: [8-1] user=,db=,e=00000 DEBUG: Before sigusr1 check: 0
2016-12-20 11:56:46 EST [] [14495]: [9-1] user=,db=,e=00000 DEBUG: After sigusr1 check: 0
2016-12-20 11:56:46 EST [] [14495]: [10-1] user=,db=,e=00000 DEBUG: Dynamic bgw launch begun for keith (0)
2016-12-20 11:56:46 EST [] [14495]: [11-1] user=,db=,e=00000 DEBUG: Registering dynamic background worker...
2016-12-20 11:56:46 EST [] [14495]: [12-1] user=,db=,e=00000 DEBUG: Waiting for BGW startup...
2016-12-20 11:56:46 EST [] [14486]: [8-1] user=,db=,e=00000 DEBUG: registering background worker "pg_partman dynamic background worker (dbname=keith)"
2016-12-20 11:56:46 EST [] [14486]: [9-1] user=,db=,e=00000 DEBUG: starting background worker process "pg_partman dynamic background worker (dbname=keith)"
2016-12-20 11:56:46 EST [] [14493]: [1-1] user=,db=,e=00000 LOG: autovacuum launcher started
2016-12-20 11:56:46 EST [] [14496]: [1-1] user=,db=,e=00000 DEBUG: Before parsing dbname GUC in dynamic main func: keith
2016-12-20 11:56:46 EST [] [14496]: [2-1] user=,db=,e=00000 DEBUG: GUC rawstring copy: keith
2016-12-20 11:56:46 EST [] [14496]: [3-1] user=,db=,e=00000 DEBUG: Entered foreach loop: name (keith), db_main_counter (0), dbcounter (0)
2016-12-20 11:56:46 EST [] [14496]: [4-1] user=,db=,e=00000 DEBUG: Parsing list: keith (0)
2016-12-20 11:56:46 EST [] [14496]: [5-1] user=,db=,e=00000 DEBUG: Before run_maint initialize connection for db keith
2016-12-20 11:56:46 EST [] [14496]: [6-1] user=,db=,e=00000 DEBUG: After run_maint initialize connection for db keith
2016-12-20 11:56:46 EST [] [14496]: [7-1] user=,db=,e=00000 DEBUG: Checking if pg_partman extension is installed in database: keith
2016-12-20 11:56:46 EST [] [14496]: [8-1] user=,db=,e=00000 LOG: pg_partman dynamic background worker (dbname=keith) dynamic background worker initialized with role keith on database keith
2016-12-20 11:56:46 EST [] [14496]: [9-1] user=,db=,e=00000 LOG: pg_partman dynamic background worker (dbname=keith): SELECT "partman".run_maintenance(p_analyze := true, p_jobmon := true) called by role keith on database keith
2016-12-20 11:56:46 EST [] [14496]: [10-1] user=,db=,e=00000 DEBUG: pg_partman dynamic BGW shutting down gracefully for database keith.
2016-12-20 11:56:46 EST [] [14486]: [10-1] user=,db=,e=00000 DEBUG: worker process: pg_partman dynamic background worker (dbname=keith) (PID 14496) exited with exit code 0
2016-12-20 11:56:46 EST [] [14486]: [11-1] user=,db=,e=00000 DEBUG: unregistering background worker "pg_partman dynamic background worker (dbname=keith)"
2016-12-20 11:57:16 EST [] [14506]: [1-1] user=,db=,e=00000 DEBUG: autovacuum: processing database "keith"
2016-12-20 11:57:46 EST [] [14515]: [1-1] user=,db=,e=00000 DEBUG: autovacuum: processing database "postgres"
2
Attachment
On Tue, Dec 20, 2016 at 12:04 PM, Keith Fiske <keith@omniti.com> wrote:
-On Tue, Dec 20, 2016 at 10:26 AM, Keith Fiske <keith@omniti.com> wrote:On Tue, Dec 20, 2016 at 1:42 AM, Michael Paquier <michael.paquier@gmail.com> wrote:On Tue, Dec 20, 2016 at 6:47 AM, Keith Fiske <keith@omniti.com> wrote:
> I'm not quite sure exactly how to debug this further to see what is actually
> setting the latch in 9.6.
The commit you are complaining about here is likely this one:
commit: db0f6cad4884bd4c835156d3a720d9a79dbd63a9
author: Robert Haas <rhaas@postgresql.org>
date: Fri, 9 Oct 2015 14:31:04 -0400
Remove set_latch_on_sigusr1 flag.
This flag has proven to be a recipe for bugs, and it doesn't seem like
it can really buy anything in terms of performance. So let's just
*always* set the process latch when we receive SIGUSR1 instead of
trying to do it only when needed.
So your process gets a SIGUSR1 and its latch is set, causing the loop
to repeat... I would discard that as a backend bug, because the
removal of set_latch_on_sigusr1 was a good move.
--
MichaelAnything I can do in the mean time to fix this, or have to wait for a bugfix patch?KeithSo, attached is my naive attempt to try and handle SIGUSR1. Can at least confirm this is the source of the problem, but I'm unable to figure out how to work around it. Handling it does in fact stop the background worker from going nuts anymore. But it also completely stops the maintenance loop from working properly. It runs once, then never again. It seems to get stuck after the call to WaitForBackgroundWorkerStartup() and never even gets to my WaitLatch() call. There is logging that it successfully unregisters the dynamic BGW, but never seems to go further than that. I tried adding latch_sigusr1_handler() similar to how the handler in procsignal.c does, but didn't seem to fix it. With some additional debugging I added, it doesn't even appear to be calling my custom signal handler function at all. got_sigusr1 is never set to true. it goes back to doing what it was doing before.
The simple act of registering to listen for the SIGUSR1 seems to stop the original bug. If I comment out just this line in pg_partman_bgw_main() (the one in pg_partman_bgw_run_maint() seems to make no difference):
pqsignal(SIGUSR1, pg_partman_bgw_sigusr1);Guessing there's a lot more to SIGUSR1 than I can see right now. But figured I'd at least try to provide some additional investigation. I noticed in the BGW code, it mentions using SIGUSR1 on start/stop.
https://doxygen.postgresql.org/bgworker_8h_source.html#l0009 9
Perhaps that's part of the issue when I try and handle it instead?partman maintenance timer is set for 10 seconds so the timestamp on the log entries shows it's not running on time.
2016-12-20 11:56:46 EST [] [14486]: [7-1] user=,db=,e=00000 LOG: database system is ready to accept connections
2016-12-20 11:56:46 EST [] [14495]: [1-1] user=,db=,e=00000 LOG: pg_partman master background worker master process initialized with role keith
2016-12-20 11:56:46 EST [] [14495]: [2-1] user=,db=,e=00000 DEBUG: Latch status just before for loop: 1
2016-12-20 11:56:46 EST [] [14495]: [3-1] user=,db=,e=00000 DEBUG: Latch status inside for loop before reset: 1
2016-12-20 11:56:46 EST [] [14495]: [4-1] user=,db=,e=00000 DEBUG: Latch status just after reset before interupt check: 0
2016-12-20 11:56:46 EST [] [14495]: [5-1] user=,db=,e=00000 DEBUG: Latch status just after reset after interupt check: 0
2016-12-20 11:56:46 EST [] [14495]: [6-1] user=,db=,e=00000 DEBUG: After sighup check: 0
2016-12-20 11:56:46 EST [] [14495]: [7-1] user=,db=,e=00000 DEBUG: After sigterm check: 0
2016-12-20 11:56:46 EST [] [14495]: [8-1] user=,db=,e=00000 DEBUG: Before sigusr1 check: 0
2016-12-20 11:56:46 EST [] [14495]: [9-1] user=,db=,e=00000 DEBUG: After sigusr1 check: 0
2016-12-20 11:56:46 EST [] [14495]: [10-1] user=,db=,e=00000 DEBUG: Dynamic bgw launch begun for keith (0)
2016-12-20 11:56:46 EST [] [14495]: [11-1] user=,db=,e=00000 DEBUG: Registering dynamic background worker...
2016-12-20 11:56:46 EST [] [14495]: [12-1] user=,db=,e=00000 DEBUG: Waiting for BGW startup...
2016-12-20 11:56:46 EST [] [14486]: [8-1] user=,db=,e=00000 DEBUG: registering background worker "pg_partman dynamic background worker (dbname=keith)"
2016-12-20 11:56:46 EST [] [14486]: [9-1] user=,db=,e=00000 DEBUG: starting background worker process "pg_partman dynamic background worker (dbname=keith)"
2016-12-20 11:56:46 EST [] [14493]: [1-1] user=,db=,e=00000 LOG: autovacuum launcher started
2016-12-20 11:56:46 EST [] [14496]: [1-1] user=,db=,e=00000 DEBUG: Before parsing dbname GUC in dynamic main func: keith
2016-12-20 11:56:46 EST [] [14496]: [2-1] user=,db=,e=00000 DEBUG: GUC rawstring copy: keith
2016-12-20 11:56:46 EST [] [14496]: [3-1] user=,db=,e=00000 DEBUG: Entered foreach loop: name (keith), db_main_counter (0), dbcounter (0)
2016-12-20 11:56:46 EST [] [14496]: [4-1] user=,db=,e=00000 DEBUG: Parsing list: keith (0)
2016-12-20 11:56:46 EST [] [14496]: [5-1] user=,db=,e=00000 DEBUG: Before run_maint initialize connection for db keith
2016-12-20 11:56:46 EST [] [14496]: [6-1] user=,db=,e=00000 DEBUG: After run_maint initialize connection for db keith
2016-12-20 11:56:46 EST [] [14496]: [7-1] user=,db=,e=00000 DEBUG: Checking if pg_partman extension is installed in database: keith
2016-12-20 11:56:46 EST [] [14496]: [8-1] user=,db=,e=00000 LOG: pg_partman dynamic background worker (dbname=keith) dynamic background worker initialized with role keith on database keith
2016-12-20 11:56:46 EST [] [14496]: [9-1] user=,db=,e=00000 LOG: pg_partman dynamic background worker (dbname=keith): SELECT "partman".run_maintenance(p_analyze := true, p_jobmon := true) called by role keith on database keith
2016-12-20 11:56:46 EST [] [14496]: [10-1] user=,db=,e=00000 DEBUG: pg_partman dynamic BGW shutting down gracefully for database keith.
2016-12-20 11:56:46 EST [] [14486]: [10-1] user=,db=,e=00000 DEBUG: worker process: pg_partman dynamic background worker (dbname=keith) (PID 14496) exited with exit code 0
2016-12-20 11:56:46 EST [] [14486]: [11-1] user=,db=,e=00000 DEBUG: unregistering background worker "pg_partman dynamic background worker (dbname=keith)"
2016-12-20 11:57:16 EST [] [14506]: [1-1] user=,db=,e=00000 DEBUG: autovacuum: processing database "keith"
2016-12-20 11:57:46 EST [] [14515]: [1-1] user=,db=,e=00000 DEBUG: autovacuum: processing database "postgres"
2
Found this pull request in pg_cron where they suggested using WaitLatch similar to what I was doing in pg_partman.
https://github.com/citusdata/ pg_cron/pull/15
Decided to apply that patch and see if it worked. After fixing the missing WL_TIMEOUT flag, everything was working fine and this extension didn't seem to have the same problem pg_partman was. So, went back to adding some more debugging flags and my suspicion about the use of SIGUSR1 on background worker startup/stop seems justified (thanks to whoever added that comment).
I noticed the timing of things in the log (see below). The dynamic background worker is unregistered just before the WaitLatch() is called. So perhaps it's the unregistering of the dynamic BGW worker that the main BGW process had called that's setting the latch...
https://github.com/citusdata/
Decided to apply that patch and see if it worked. After fixing the missing WL_TIMEOUT flag, everything was working fine and this extension didn't seem to have the same problem pg_partman was. So, went back to adding some more debugging flags and my suspicion about the use of SIGUSR1 on background worker startup/stop seems justified (thanks to whoever added that comment).
I noticed the timing of things in the log (see below). The dynamic background worker is unregistered just before the WaitLatch() is called. So perhaps it's the unregistering of the dynamic BGW worker that the main BGW process had called that's setting the latch...
Looking through bgworker.c, I found this comment
https://github.com/postgres/ postgres/blob/REL9_6_STABLE/ src/backend/postmaster/ bgworker.c#L257
https://github.com/postgres/
Sure enough, I use bgw_notify_pid so my main BGW process can know when my dynamic worker finishes running. And it seems it sends SIGUSR1 to do this notification if I'm reading this right
https://github.com/postgres/ postgres/blob/REL9_6_STABLE/ src/backend/postmaster/ bgworker.c#L276
https://github.com/postgres/
So, now because the SIGUSR1 signal always sets the latch in 9.6, this WaitLatch process doesn't seem like it can be used when a BGW itself starts other dynamic background workers and has to rely on them informing it when they're done running.
Can anyone confirm/deny what I think I've found here? If this is true, any idea how this can be handled now in 9.6 or is this a bug that needs to be fixed?
2016-12-23 15:31:36 EST [] [30766]: [1-1] user=,db=,e=00000 LOG: pg_partman master background worker master process initialized with role keith
2016-12-23 15:31:36 EST [] [30766]: [3-1] user=,db=,e=00000 DEBUG: Latch status inside for loop before reset: 1
2016-12-23 15:31:36 EST [] [30766]: [4-1] user=,db=,e=00000 DEBUG: Latch status just after reset before interupt check: 0
[..]
2016-12-23 15:31:36 EST [] [30766]: [14-1] user=,db=,e=00000 DEBUG: Latch status just after BGW status check: 0
2016-12-23 15:31:36 EST [] [30766]: [15-1] user=,db=,e=00000 DEBUG: Latch status just before wait call: 0
[...]
2016-12-23 15:31:36 EST [] [30758]: [11-1] user=,db=,e=00000 DEBUG: unregistering background worker "pg_partman dynamic background worker (dbname=keith)"
2016-12-23 15:31:36 EST [] [30766]: [16-1] user=,db=,e=00000 DEBUG: Latch status after wait call: 1
2016-12-23 15:31:36 EST [] [30766]: [18-1] user=,db=,e=00000 DEBUG: Latch status inside for loop before reset: 1
2016-12-23 15:31:36 EST [] [30766]: [19-1] user=,db=,e=00000 DEBUG: Latch status just after reset before interupt check: 0
[...]
2016-12-23 15:31:36 EST [] [30766]: [29-1] user=,db=,e=00000 DEBUG: Latch status just after BGW status check: 0
2016-12-23 15:31:36 EST [] [30766]: [30-1] user=,db=,e=00000 DEBUG: Latch status just before wait call: 0
[...]
2016-12-23 15:31:36 EST [] [30758]: [15-1] user=,db=,e=00000 DEBUG: unregistering background worker "pg_partman dynamic background worker (dbname=keith)"
2016-12-23 15:31:36 EST [] [30766]: [31-1] user=,db=,e=00000 DEBUG: Latch status after wait call: 1
2016-12-23 15:31:36 EST [] [30766]: [33-1] user=,db=,e=00000 DEBUG: Latch status inside for loop before reset: 1
2016-12-23 15:31:36 EST [] [30766]: [34-1] user=,db=,e=00000 DEBUG: Latch status just after reset before interupt check: 0
On Fri, Dec 23, 2016 at 4:18 PM, Keith Fiske <keith@omniti.com> wrote:
On Tue, Dec 20, 2016 at 12:04 PM, Keith Fiske <keith@omniti.com> wrote:-On Tue, Dec 20, 2016 at 10:26 AM, Keith Fiske <keith@omniti.com> wrote:On Tue, Dec 20, 2016 at 1:42 AM, Michael Paquier <michael.paquier@gmail.com> wrote:On Tue, Dec 20, 2016 at 6:47 AM, Keith Fiske <keith@omniti.com> wrote:
> I'm not quite sure exactly how to debug this further to see what is actually
> setting the latch in 9.6.
The commit you are complaining about here is likely this one:
commit: db0f6cad4884bd4c835156d3a720d9a79dbd63a9
author: Robert Haas <rhaas@postgresql.org>
date: Fri, 9 Oct 2015 14:31:04 -0400
Remove set_latch_on_sigusr1 flag.
This flag has proven to be a recipe for bugs, and it doesn't seem like
it can really buy anything in terms of performance. So let's just
*always* set the process latch when we receive SIGUSR1 instead of
trying to do it only when needed.
So your process gets a SIGUSR1 and its latch is set, causing the loop
to repeat... I would discard that as a backend bug, because the
removal of set_latch_on_sigusr1 was a good move.
--
MichaelAnything I can do in the mean time to fix this, or have to wait for a bugfix patch?KeithSo, attached is my naive attempt to try and handle SIGUSR1. Can at least confirm this is the source of the problem, but I'm unable to figure out how to work around it. Handling it does in fact stop the background worker from going nuts anymore. But it also completely stops the maintenance loop from working properly. It runs once, then never again. It seems to get stuck after the call to WaitForBackgroundWorkerStartup() and never even gets to my WaitLatch() call. There is logging that it successfully unregisters the dynamic BGW, but never seems to go further than that. I tried adding latch_sigusr1_handler() similar to how the handler in procsignal.c does, but didn't seem to fix it. With some additional debugging I added, it doesn't even appear to be calling my custom signal handler function at all. got_sigusr1 is never set to true. it goes back to doing what it was doing before.
The simple act of registering to listen for the SIGUSR1 seems to stop the original bug. If I comment out just this line in pg_partman_bgw_main() (the one in pg_partman_bgw_run_maint() seems to make no difference):
pqsignal(SIGUSR1, pg_partman_bgw_sigusr1);Guessing there's a lot more to SIGUSR1 than I can see right now. But figured I'd at least try to provide some additional investigation. I noticed in the BGW code, it mentions using SIGUSR1 on start/stop.
https://doxygen.postgresql.org/bgworker_8h_source.html#l0009 9
Perhaps that's part of the issue when I try and handle it instead?partman maintenance timer is set for 10 seconds so the timestamp on the log entries shows it's not running on time.
2016-12-20 11:56:46 EST [] [14486]: [7-1] user=,db=,e=00000 LOG: database system is ready to accept connections
2016-12-20 11:56:46 EST [] [14495]: [1-1] user=,db=,e=00000 LOG: pg_partman master background worker master process initialized with role keith
2016-12-20 11:56:46 EST [] [14495]: [2-1] user=,db=,e=00000 DEBUG: Latch status just before for loop: 1
2016-12-20 11:56:46 EST [] [14495]: [3-1] user=,db=,e=00000 DEBUG: Latch status inside for loop before reset: 1
2016-12-20 11:56:46 EST [] [14495]: [4-1] user=,db=,e=00000 DEBUG: Latch status just after reset before interupt check: 0
2016-12-20 11:56:46 EST [] [14495]: [5-1] user=,db=,e=00000 DEBUG: Latch status just after reset after interupt check: 0
2016-12-20 11:56:46 EST [] [14495]: [6-1] user=,db=,e=00000 DEBUG: After sighup check: 0
2016-12-20 11:56:46 EST [] [14495]: [7-1] user=,db=,e=00000 DEBUG: After sigterm check: 0
2016-12-20 11:56:46 EST [] [14495]: [8-1] user=,db=,e=00000 DEBUG: Before sigusr1 check: 0
2016-12-20 11:56:46 EST [] [14495]: [9-1] user=,db=,e=00000 DEBUG: After sigusr1 check: 0
2016-12-20 11:56:46 EST [] [14495]: [10-1] user=,db=,e=00000 DEBUG: Dynamic bgw launch begun for keith (0)
2016-12-20 11:56:46 EST [] [14495]: [11-1] user=,db=,e=00000 DEBUG: Registering dynamic background worker...
2016-12-20 11:56:46 EST [] [14495]: [12-1] user=,db=,e=00000 DEBUG: Waiting for BGW startup...
2016-12-20 11:56:46 EST [] [14486]: [8-1] user=,db=,e=00000 DEBUG: registering background worker "pg_partman dynamic background worker (dbname=keith)"
2016-12-20 11:56:46 EST [] [14486]: [9-1] user=,db=,e=00000 DEBUG: starting background worker process "pg_partman dynamic background worker (dbname=keith)"
2016-12-20 11:56:46 EST [] [14493]: [1-1] user=,db=,e=00000 LOG: autovacuum launcher started
2016-12-20 11:56:46 EST [] [14496]: [1-1] user=,db=,e=00000 DEBUG: Before parsing dbname GUC in dynamic main func: keith
2016-12-20 11:56:46 EST [] [14496]: [2-1] user=,db=,e=00000 DEBUG: GUC rawstring copy: keith
2016-12-20 11:56:46 EST [] [14496]: [3-1] user=,db=,e=00000 DEBUG: Entered foreach loop: name (keith), db_main_counter (0), dbcounter (0)
2016-12-20 11:56:46 EST [] [14496]: [4-1] user=,db=,e=00000 DEBUG: Parsing list: keith (0)
2016-12-20 11:56:46 EST [] [14496]: [5-1] user=,db=,e=00000 DEBUG: Before run_maint initialize connection for db keith
2016-12-20 11:56:46 EST [] [14496]: [6-1] user=,db=,e=00000 DEBUG: After run_maint initialize connection for db keith
2016-12-20 11:56:46 EST [] [14496]: [7-1] user=,db=,e=00000 DEBUG: Checking if pg_partman extension is installed in database: keith
2016-12-20 11:56:46 EST [] [14496]: [8-1] user=,db=,e=00000 LOG: pg_partman dynamic background worker (dbname=keith) dynamic background worker initialized with role keith on database keith
2016-12-20 11:56:46 EST [] [14496]: [9-1] user=,db=,e=00000 LOG: pg_partman dynamic background worker (dbname=keith): SELECT "partman".run_maintenance(p_analyze := true, p_jobmon := true) called by role keith on database keith
2016-12-20 11:56:46 EST [] [14496]: [10-1] user=,db=,e=00000 DEBUG: pg_partman dynamic BGW shutting down gracefully for database keith.
2016-12-20 11:56:46 EST [] [14486]: [10-1] user=,db=,e=00000 DEBUG: worker process: pg_partman dynamic background worker (dbname=keith) (PID 14496) exited with exit code 0
2016-12-20 11:56:46 EST [] [14486]: [11-1] user=,db=,e=00000 DEBUG: unregistering background worker "pg_partman dynamic background worker (dbname=keith)"
2016-12-20 11:57:16 EST [] [14506]: [1-1] user=,db=,e=00000 DEBUG: autovacuum: processing database "keith"
2016-12-20 11:57:46 EST [] [14515]: [1-1] user=,db=,e=00000 DEBUG: autovacuum: processing database "postgres"
2Found this pull request in pg_cron where they suggested using WaitLatch similar to what I was doing in pg_partman.
https://github.com/citusdata/pg_cron/pull/15
Decided to apply that patch and see if it worked. After fixing the missing WL_TIMEOUT flag, everything was working fine and this extension didn't seem to have the same problem pg_partman was. So, went back to adding some more debugging flags and my suspicion about the use of SIGUSR1 on background worker startup/stop seems justified (thanks to whoever added that comment).
I noticed the timing of things in the log (see below). The dynamic background worker is unregistered just before the WaitLatch() is called. So perhaps it's the unregistering of the dynamic BGW worker that the main BGW process had called that's setting the latch...Looking through bgworker.c, I found this comment
https://github.com/postgres/postgres/blob/REL9_6_STABLE/src/ backend/postmaster/bgworker.c# L257 Sure enough, I use bgw_notify_pid so my main BGW process can know when my dynamic worker finishes running. And it seems it sends SIGUSR1 to do this notification if I'm reading this right
https://github.com/postgres/postgres/blob/REL9_6_STABLE/src/ backend/postmaster/bgworker.c# L276 So, now because the SIGUSR1 signal always sets the latch in 9.6, this WaitLatch process doesn't seem like it can be used when a BGW itself starts other dynamic background workers and has to rely on them informing it when they're done running.Can anyone confirm/deny what I think I've found here? If this is true, any idea how this can be handled now in 9.6 or is this a bug that needs to be fixed?
2016-12-23 15:31:36 EST [] [30766]: [1-1] user=,db=,e=00000 LOG: pg_partman master background worker master process initialized with role keith
2016-12-23 15:31:36 EST [] [30766]: [3-1] user=,db=,e=00000 DEBUG: Latch status inside for loop before reset: 1
2016-12-23 15:31:36 EST [] [30766]: [4-1] user=,db=,e=00000 DEBUG: Latch status just after reset before interupt check: 0
[..]
2016-12-23 15:31:36 EST [] [30766]: [14-1] user=,db=,e=00000 DEBUG: Latch status just after BGW status check: 0
2016-12-23 15:31:36 EST [] [30766]: [15-1] user=,db=,e=00000 DEBUG: Latch status just before wait call: 0
[...]
2016-12-23 15:31:36 EST [] [30758]: [11-1] user=,db=,e=00000 DEBUG: unregistering background worker "pg_partman dynamic background worker (dbname=keith)"
2016-12-23 15:31:36 EST [] [30766]: [16-1] user=,db=,e=00000 DEBUG: Latch status after wait call: 1
2016-12-23 15:31:36 EST [] [30766]: [18-1] user=,db=,e=00000 DEBUG: Latch status inside for loop before reset: 1
2016-12-23 15:31:36 EST [] [30766]: [19-1] user=,db=,e=00000 DEBUG: Latch status just after reset before interupt check: 0
[...]
2016-12-23 15:31:36 EST [] [30766]: [29-1] user=,db=,e=00000 DEBUG: Latch status just after BGW status check: 0
2016-12-23 15:31:36 EST [] [30766]: [30-1] user=,db=,e=00000 DEBUG: Latch status just before wait call: 0
[...]
2016-12-23 15:31:36 EST [] [30758]: [15-1] user=,db=,e=00000 DEBUG: unregistering background worker "pg_partman dynamic background worker (dbname=keith)"
2016-12-23 15:31:36 EST [] [30766]: [31-1] user=,db=,e=00000 DEBUG: Latch status after wait call: 1
2016-12-23 15:31:36 EST [] [30766]: [33-1] user=,db=,e=00000 DEBUG: Latch status inside for loop before reset: 1
2016-12-23 15:31:36 EST [] [30766]: [34-1] user=,db=,e=00000 DEBUG: Latch status just after reset before interupt check: 0
Just to help confirm my above assumption, commenting out this single line of code in my main background worker allowed the WaitLatch timeout to work again
worker.bgw_notify_pid = MyProcPid;
Thankfully the only thing my background worker does is call another plpgsql function on an interval, and that function has an advisory lock to prevent concurrent runs. Don't think this bgw_notify_pid was actually preventing concurrent runs before, but if someone actually needed that feedback and used a WaitLatch, this could cause it to break. Only reason I had this in there was because I used the worker_spi code as my initial example on how to create a dynamic background worker.worker.bgw_notify_pid = MyProcPid;
Keith
On Fri, Dec 23, 2016 at 5:47 PM, Keith Fiske <keith@omniti.com> wrote:
On Fri, Dec 23, 2016 at 4:18 PM, Keith Fiske <keith@omniti.com> wrote:On Tue, Dec 20, 2016 at 12:04 PM, Keith Fiske <keith@omniti.com> wrote:-On Tue, Dec 20, 2016 at 10:26 AM, Keith Fiske <keith@omniti.com> wrote:On Tue, Dec 20, 2016 at 1:42 AM, Michael Paquier <michael.paquier@gmail.com> wrote:On Tue, Dec 20, 2016 at 6:47 AM, Keith Fiske <keith@omniti.com> wrote:
> I'm not quite sure exactly how to debug this further to see what is actually
> setting the latch in 9.6.
The commit you are complaining about here is likely this one:
commit: db0f6cad4884bd4c835156d3a720d9a79dbd63a9
author: Robert Haas <rhaas@postgresql.org>
date: Fri, 9 Oct 2015 14:31:04 -0400
Remove set_latch_on_sigusr1 flag.
This flag has proven to be a recipe for bugs, and it doesn't seem like
it can really buy anything in terms of performance. So let's just
*always* set the process latch when we receive SIGUSR1 instead of
trying to do it only when needed.
So your process gets a SIGUSR1 and its latch is set, causing the loop
to repeat... I would discard that as a backend bug, because the
removal of set_latch_on_sigusr1 was a good move.
--
MichaelAnything I can do in the mean time to fix this, or have to wait for a bugfix patch?KeithSo, attached is my naive attempt to try and handle SIGUSR1. Can at least confirm this is the source of the problem, but I'm unable to figure out how to work around it. Handling it does in fact stop the background worker from going nuts anymore. But it also completely stops the maintenance loop from working properly. It runs once, then never again. It seems to get stuck after the call to WaitForBackgroundWorkerStartup() and never even gets to my WaitLatch() call. There is logging that it successfully unregisters the dynamic BGW, but never seems to go further than that. I tried adding latch_sigusr1_handler() similar to how the handler in procsignal.c does, but didn't seem to fix it. With some additional debugging I added, it doesn't even appear to be calling my custom signal handler function at all. got_sigusr1 is never set to true. it goes back to doing what it was doing before.
The simple act of registering to listen for the SIGUSR1 seems to stop the original bug. If I comment out just this line in pg_partman_bgw_main() (the one in pg_partman_bgw_run_maint() seems to make no difference):
pqsignal(SIGUSR1, pg_partman_bgw_sigusr1);Guessing there's a lot more to SIGUSR1 than I can see right now. But figured I'd at least try to provide some additional investigation. I noticed in the BGW code, it mentions using SIGUSR1 on start/stop.
https://doxygen.postgresql.org/bgworker_8h_source.html#l0009 9
Perhaps that's part of the issue when I try and handle it instead?partman maintenance timer is set for 10 seconds so the timestamp on the log entries shows it's not running on time.
2016-12-20 11:56:46 EST [] [14486]: [7-1] user=,db=,e=00000 LOG: database system is ready to accept connections
2016-12-20 11:56:46 EST [] [14495]: [1-1] user=,db=,e=00000 LOG: pg_partman master background worker master process initialized with role keith
2016-12-20 11:56:46 EST [] [14495]: [2-1] user=,db=,e=00000 DEBUG: Latch status just before for loop: 1
2016-12-20 11:56:46 EST [] [14495]: [3-1] user=,db=,e=00000 DEBUG: Latch status inside for loop before reset: 1
2016-12-20 11:56:46 EST [] [14495]: [4-1] user=,db=,e=00000 DEBUG: Latch status just after reset before interupt check: 0
2016-12-20 11:56:46 EST [] [14495]: [5-1] user=,db=,e=00000 DEBUG: Latch status just after reset after interupt check: 0
2016-12-20 11:56:46 EST [] [14495]: [6-1] user=,db=,e=00000 DEBUG: After sighup check: 0
2016-12-20 11:56:46 EST [] [14495]: [7-1] user=,db=,e=00000 DEBUG: After sigterm check: 0
2016-12-20 11:56:46 EST [] [14495]: [8-1] user=,db=,e=00000 DEBUG: Before sigusr1 check: 0
2016-12-20 11:56:46 EST [] [14495]: [9-1] user=,db=,e=00000 DEBUG: After sigusr1 check: 0
2016-12-20 11:56:46 EST [] [14495]: [10-1] user=,db=,e=00000 DEBUG: Dynamic bgw launch begun for keith (0)
2016-12-20 11:56:46 EST [] [14495]: [11-1] user=,db=,e=00000 DEBUG: Registering dynamic background worker...
2016-12-20 11:56:46 EST [] [14495]: [12-1] user=,db=,e=00000 DEBUG: Waiting for BGW startup...
2016-12-20 11:56:46 EST [] [14486]: [8-1] user=,db=,e=00000 DEBUG: registering background worker "pg_partman dynamic background worker (dbname=keith)"
2016-12-20 11:56:46 EST [] [14486]: [9-1] user=,db=,e=00000 DEBUG: starting background worker process "pg_partman dynamic background worker (dbname=keith)"
2016-12-20 11:56:46 EST [] [14493]: [1-1] user=,db=,e=00000 LOG: autovacuum launcher started
2016-12-20 11:56:46 EST [] [14496]: [1-1] user=,db=,e=00000 DEBUG: Before parsing dbname GUC in dynamic main func: keith
2016-12-20 11:56:46 EST [] [14496]: [2-1] user=,db=,e=00000 DEBUG: GUC rawstring copy: keith
2016-12-20 11:56:46 EST [] [14496]: [3-1] user=,db=,e=00000 DEBUG: Entered foreach loop: name (keith), db_main_counter (0), dbcounter (0)
2016-12-20 11:56:46 EST [] [14496]: [4-1] user=,db=,e=00000 DEBUG: Parsing list: keith (0)
2016-12-20 11:56:46 EST [] [14496]: [5-1] user=,db=,e=00000 DEBUG: Before run_maint initialize connection for db keith
2016-12-20 11:56:46 EST [] [14496]: [6-1] user=,db=,e=00000 DEBUG: After run_maint initialize connection for db keith
2016-12-20 11:56:46 EST [] [14496]: [7-1] user=,db=,e=00000 DEBUG: Checking if pg_partman extension is installed in database: keith
2016-12-20 11:56:46 EST [] [14496]: [8-1] user=,db=,e=00000 LOG: pg_partman dynamic background worker (dbname=keith) dynamic background worker initialized with role keith on database keith
2016-12-20 11:56:46 EST [] [14496]: [9-1] user=,db=,e=00000 LOG: pg_partman dynamic background worker (dbname=keith): SELECT "partman".run_maintenance(p_analyze := true, p_jobmon := true) called by role keith on database keith
2016-12-20 11:56:46 EST [] [14496]: [10-1] user=,db=,e=00000 DEBUG: pg_partman dynamic BGW shutting down gracefully for database keith.
2016-12-20 11:56:46 EST [] [14486]: [10-1] user=,db=,e=00000 DEBUG: worker process: pg_partman dynamic background worker (dbname=keith) (PID 14496) exited with exit code 0
2016-12-20 11:56:46 EST [] [14486]: [11-1] user=,db=,e=00000 DEBUG: unregistering background worker "pg_partman dynamic background worker (dbname=keith)"
2016-12-20 11:57:16 EST [] [14506]: [1-1] user=,db=,e=00000 DEBUG: autovacuum: processing database "keith"
2016-12-20 11:57:46 EST [] [14515]: [1-1] user=,db=,e=00000 DEBUG: autovacuum: processing database "postgres"
2Found this pull request in pg_cron where they suggested using WaitLatch similar to what I was doing in pg_partman.
https://github.com/citusdata/pg_cron/pull/15
Decided to apply that patch and see if it worked. After fixing the missing WL_TIMEOUT flag, everything was working fine and this extension didn't seem to have the same problem pg_partman was. So, went back to adding some more debugging flags and my suspicion about the use of SIGUSR1 on background worker startup/stop seems justified (thanks to whoever added that comment).
I noticed the timing of things in the log (see below). The dynamic background worker is unregistered just before the WaitLatch() is called. So perhaps it's the unregistering of the dynamic BGW worker that the main BGW process had called that's setting the latch...Looking through bgworker.c, I found this comment
https://github.com/postgres/postgres/blob/REL9_6_STABLE/src/ backend/postmaster/bgworker.c# L257 Sure enough, I use bgw_notify_pid so my main BGW process can know when my dynamic worker finishes running. And it seems it sends SIGUSR1 to do this notification if I'm reading this right
https://github.com/postgres/postgres/blob/REL9_6_STABLE/src/ backend/postmaster/bgworker.c# L276 So, now because the SIGUSR1 signal always sets the latch in 9.6, this WaitLatch process doesn't seem like it can be used when a BGW itself starts other dynamic background workers and has to rely on them informing it when they're done running.Can anyone confirm/deny what I think I've found here? If this is true, any idea how this can be handled now in 9.6 or is this a bug that needs to be fixed?
2016-12-23 15:31:36 EST [] [30766]: [1-1] user=,db=,e=00000 LOG: pg_partman master background worker master process initialized with role keith
2016-12-23 15:31:36 EST [] [30766]: [3-1] user=,db=,e=00000 DEBUG: Latch status inside for loop before reset: 1
2016-12-23 15:31:36 EST [] [30766]: [4-1] user=,db=,e=00000 DEBUG: Latch status just after reset before interupt check: 0
[..]
2016-12-23 15:31:36 EST [] [30766]: [14-1] user=,db=,e=00000 DEBUG: Latch status just after BGW status check: 0
2016-12-23 15:31:36 EST [] [30766]: [15-1] user=,db=,e=00000 DEBUG: Latch status just before wait call: 0
[...]
2016-12-23 15:31:36 EST [] [30758]: [11-1] user=,db=,e=00000 DEBUG: unregistering background worker "pg_partman dynamic background worker (dbname=keith)"
2016-12-23 15:31:36 EST [] [30766]: [16-1] user=,db=,e=00000 DEBUG: Latch status after wait call: 1
2016-12-23 15:31:36 EST [] [30766]: [18-1] user=,db=,e=00000 DEBUG: Latch status inside for loop before reset: 1
2016-12-23 15:31:36 EST [] [30766]: [19-1] user=,db=,e=00000 DEBUG: Latch status just after reset before interupt check: 0
[...]
2016-12-23 15:31:36 EST [] [30766]: [29-1] user=,db=,e=00000 DEBUG: Latch status just after BGW status check: 0
2016-12-23 15:31:36 EST [] [30766]: [30-1] user=,db=,e=00000 DEBUG: Latch status just before wait call: 0
[...]
2016-12-23 15:31:36 EST [] [30758]: [15-1] user=,db=,e=00000 DEBUG: unregistering background worker "pg_partman dynamic background worker (dbname=keith)"
2016-12-23 15:31:36 EST [] [30766]: [31-1] user=,db=,e=00000 DEBUG: Latch status after wait call: 1
2016-12-23 15:31:36 EST [] [30766]: [33-1] user=,db=,e=00000 DEBUG: Latch status inside for loop before reset: 1
2016-12-23 15:31:36 EST [] [30766]: [34-1] user=,db=,e=00000 DEBUG: Latch status just after reset before interupt check: 0Just to help confirm my above assumption, commenting out this single line of code in my main background worker allowed the WaitLatch timeout to work againThankfully the only thing my background worker does is call another plpgsql function on an interval, and that function has an advisory lock to prevent concurrent runs. Don't think this bgw_notify_pid was actually preventing concurrent runs before, but if someone actually needed that feedback and used a WaitLatch, this could cause it to break. Only reason I had this in there was because I used the worker_spi code as my initial example on how to create a dynamic background worker.
worker.bgw_notify_pid = MyProcPid;Keith
And I spoke too soon. Taking that line out does indeed stop the background worker from going nuts. But it also stops it from working completely. It's basically the same result as me trying to handle SIGUSR1 myself. The main background worker process halts as soon as the dynamic worker unregisters because it seems it needs to get that status from the dynamic worker back to continue working.
So this is quite a big deal for anyone working with background workers that must interact with each other and use the Latch system to allow proper interruption of processes and clean shutdowns.
Keith
On Fri, Dec 23, 2016 at 6:21 PM, Keith Fiske <keith@omniti.com> wrote:
On Fri, Dec 23, 2016 at 5:47 PM, Keith Fiske <keith@omniti.com> wrote:On Fri, Dec 23, 2016 at 4:18 PM, Keith Fiske <keith@omniti.com> wrote:On Tue, Dec 20, 2016 at 12:04 PM, Keith Fiske <keith@omniti.com> wrote:-On Tue, Dec 20, 2016 at 10:26 AM, Keith Fiske <keith@omniti.com> wrote:On Tue, Dec 20, 2016 at 1:42 AM, Michael Paquier <michael.paquier@gmail.com> wrote:On Tue, Dec 20, 2016 at 6:47 AM, Keith Fiske <keith@omniti.com> wrote:
> I'm not quite sure exactly how to debug this further to see what is actually
> setting the latch in 9.6.
The commit you are complaining about here is likely this one:
commit: db0f6cad4884bd4c835156d3a720d9a79dbd63a9
author: Robert Haas <rhaas@postgresql.org>
date: Fri, 9 Oct 2015 14:31:04 -0400
Remove set_latch_on_sigusr1 flag.
This flag has proven to be a recipe for bugs, and it doesn't seem like
it can really buy anything in terms of performance. So let's just
*always* set the process latch when we receive SIGUSR1 instead of
trying to do it only when needed.
So your process gets a SIGUSR1 and its latch is set, causing the loop
to repeat... I would discard that as a backend bug, because the
removal of set_latch_on_sigusr1 was a good move.
--
MichaelAnything I can do in the mean time to fix this, or have to wait for a bugfix patch?KeithSo, attached is my naive attempt to try and handle SIGUSR1. Can at least confirm this is the source of the problem, but I'm unable to figure out how to work around it. Handling it does in fact stop the background worker from going nuts anymore. But it also completely stops the maintenance loop from working properly. It runs once, then never again. It seems to get stuck after the call to WaitForBackgroundWorkerStartup() and never even gets to my WaitLatch() call. There is logging that it successfully unregisters the dynamic BGW, but never seems to go further than that. I tried adding latch_sigusr1_handler() similar to how the handler in procsignal.c does, but didn't seem to fix it. With some additional debugging I added, it doesn't even appear to be calling my custom signal handler function at all. got_sigusr1 is never set to true. it goes back to doing what it was doing before.
The simple act of registering to listen for the SIGUSR1 seems to stop the original bug. If I comment out just this line in pg_partman_bgw_main() (the one in pg_partman_bgw_run_maint() seems to make no difference):
pqsignal(SIGUSR1, pg_partman_bgw_sigusr1);Guessing there's a lot more to SIGUSR1 than I can see right now. But figured I'd at least try to provide some additional investigation. I noticed in the BGW code, it mentions using SIGUSR1 on start/stop.
https://doxygen.postgresql.org/bgworker_8h_source.html#l0009 9
Perhaps that's part of the issue when I try and handle it instead?partman maintenance timer is set for 10 seconds so the timestamp on the log entries shows it's not running on time.
2016-12-20 11:56:46 EST [] [14486]: [7-1] user=,db=,e=00000 LOG: database system is ready to accept connections
2016-12-20 11:56:46 EST [] [14495]: [1-1] user=,db=,e=00000 LOG: pg_partman master background worker master process initialized with role keith
2016-12-20 11:56:46 EST [] [14495]: [2-1] user=,db=,e=00000 DEBUG: Latch status just before for loop: 1
2016-12-20 11:56:46 EST [] [14495]: [3-1] user=,db=,e=00000 DEBUG: Latch status inside for loop before reset: 1
2016-12-20 11:56:46 EST [] [14495]: [4-1] user=,db=,e=00000 DEBUG: Latch status just after reset before interupt check: 0
2016-12-20 11:56:46 EST [] [14495]: [5-1] user=,db=,e=00000 DEBUG: Latch status just after reset after interupt check: 0
2016-12-20 11:56:46 EST [] [14495]: [6-1] user=,db=,e=00000 DEBUG: After sighup check: 0
2016-12-20 11:56:46 EST [] [14495]: [7-1] user=,db=,e=00000 DEBUG: After sigterm check: 0
2016-12-20 11:56:46 EST [] [14495]: [8-1] user=,db=,e=00000 DEBUG: Before sigusr1 check: 0
2016-12-20 11:56:46 EST [] [14495]: [9-1] user=,db=,e=00000 DEBUG: After sigusr1 check: 0
2016-12-20 11:56:46 EST [] [14495]: [10-1] user=,db=,e=00000 DEBUG: Dynamic bgw launch begun for keith (0)
2016-12-20 11:56:46 EST [] [14495]: [11-1] user=,db=,e=00000 DEBUG: Registering dynamic background worker...
2016-12-20 11:56:46 EST [] [14495]: [12-1] user=,db=,e=00000 DEBUG: Waiting for BGW startup...
2016-12-20 11:56:46 EST [] [14486]: [8-1] user=,db=,e=00000 DEBUG: registering background worker "pg_partman dynamic background worker (dbname=keith)"
2016-12-20 11:56:46 EST [] [14486]: [9-1] user=,db=,e=00000 DEBUG: starting background worker process "pg_partman dynamic background worker (dbname=keith)"
2016-12-20 11:56:46 EST [] [14493]: [1-1] user=,db=,e=00000 LOG: autovacuum launcher started
2016-12-20 11:56:46 EST [] [14496]: [1-1] user=,db=,e=00000 DEBUG: Before parsing dbname GUC in dynamic main func: keith
2016-12-20 11:56:46 EST [] [14496]: [2-1] user=,db=,e=00000 DEBUG: GUC rawstring copy: keith
2016-12-20 11:56:46 EST [] [14496]: [3-1] user=,db=,e=00000 DEBUG: Entered foreach loop: name (keith), db_main_counter (0), dbcounter (0)
2016-12-20 11:56:46 EST [] [14496]: [4-1] user=,db=,e=00000 DEBUG: Parsing list: keith (0)
2016-12-20 11:56:46 EST [] [14496]: [5-1] user=,db=,e=00000 DEBUG: Before run_maint initialize connection for db keith
2016-12-20 11:56:46 EST [] [14496]: [6-1] user=,db=,e=00000 DEBUG: After run_maint initialize connection for db keith
2016-12-20 11:56:46 EST [] [14496]: [7-1] user=,db=,e=00000 DEBUG: Checking if pg_partman extension is installed in database: keith
2016-12-20 11:56:46 EST [] [14496]: [8-1] user=,db=,e=00000 LOG: pg_partman dynamic background worker (dbname=keith) dynamic background worker initialized with role keith on database keith
2016-12-20 11:56:46 EST [] [14496]: [9-1] user=,db=,e=00000 LOG: pg_partman dynamic background worker (dbname=keith): SELECT "partman".run_maintenance(p_analyze := true, p_jobmon := true) called by role keith on database keith
2016-12-20 11:56:46 EST [] [14496]: [10-1] user=,db=,e=00000 DEBUG: pg_partman dynamic BGW shutting down gracefully for database keith.
2016-12-20 11:56:46 EST [] [14486]: [10-1] user=,db=,e=00000 DEBUG: worker process: pg_partman dynamic background worker (dbname=keith) (PID 14496) exited with exit code 0
2016-12-20 11:56:46 EST [] [14486]: [11-1] user=,db=,e=00000 DEBUG: unregistering background worker "pg_partman dynamic background worker (dbname=keith)"
2016-12-20 11:57:16 EST [] [14506]: [1-1] user=,db=,e=00000 DEBUG: autovacuum: processing database "keith"
2016-12-20 11:57:46 EST [] [14515]: [1-1] user=,db=,e=00000 DEBUG: autovacuum: processing database "postgres"
2Found this pull request in pg_cron where they suggested using WaitLatch similar to what I was doing in pg_partman.
https://github.com/citusdata/pg_cron/pull/15
Decided to apply that patch and see if it worked. After fixing the missing WL_TIMEOUT flag, everything was working fine and this extension didn't seem to have the same problem pg_partman was. So, went back to adding some more debugging flags and my suspicion about the use of SIGUSR1 on background worker startup/stop seems justified (thanks to whoever added that comment).
I noticed the timing of things in the log (see below). The dynamic background worker is unregistered just before the WaitLatch() is called. So perhaps it's the unregistering of the dynamic BGW worker that the main BGW process had called that's setting the latch...Looking through bgworker.c, I found this comment
https://github.com/postgres/postgres/blob/REL9_6_STABLE/src/ backend/postmaster/bgworker.c# L257 Sure enough, I use bgw_notify_pid so my main BGW process can know when my dynamic worker finishes running. And it seems it sends SIGUSR1 to do this notification if I'm reading this right
https://github.com/postgres/postgres/blob/REL9_6_STABLE/src/ backend/postmaster/bgworker.c# L276 So, now because the SIGUSR1 signal always sets the latch in 9.6, this WaitLatch process doesn't seem like it can be used when a BGW itself starts other dynamic background workers and has to rely on them informing it when they're done running.Can anyone confirm/deny what I think I've found here? If this is true, any idea how this can be handled now in 9.6 or is this a bug that needs to be fixed?
2016-12-23 15:31:36 EST [] [30766]: [1-1] user=,db=,e=00000 LOG: pg_partman master background worker master process initialized with role keith
2016-12-23 15:31:36 EST [] [30766]: [3-1] user=,db=,e=00000 DEBUG: Latch status inside for loop before reset: 1
2016-12-23 15:31:36 EST [] [30766]: [4-1] user=,db=,e=00000 DEBUG: Latch status just after reset before interupt check: 0
[..]
2016-12-23 15:31:36 EST [] [30766]: [14-1] user=,db=,e=00000 DEBUG: Latch status just after BGW status check: 0
2016-12-23 15:31:36 EST [] [30766]: [15-1] user=,db=,e=00000 DEBUG: Latch status just before wait call: 0
[...]
2016-12-23 15:31:36 EST [] [30758]: [11-1] user=,db=,e=00000 DEBUG: unregistering background worker "pg_partman dynamic background worker (dbname=keith)"
2016-12-23 15:31:36 EST [] [30766]: [16-1] user=,db=,e=00000 DEBUG: Latch status after wait call: 1
2016-12-23 15:31:36 EST [] [30766]: [18-1] user=,db=,e=00000 DEBUG: Latch status inside for loop before reset: 1
2016-12-23 15:31:36 EST [] [30766]: [19-1] user=,db=,e=00000 DEBUG: Latch status just after reset before interupt check: 0
[...]
2016-12-23 15:31:36 EST [] [30766]: [29-1] user=,db=,e=00000 DEBUG: Latch status just after BGW status check: 0
2016-12-23 15:31:36 EST [] [30766]: [30-1] user=,db=,e=00000 DEBUG: Latch status just before wait call: 0
[...]
2016-12-23 15:31:36 EST [] [30758]: [15-1] user=,db=,e=00000 DEBUG: unregistering background worker "pg_partman dynamic background worker (dbname=keith)"
2016-12-23 15:31:36 EST [] [30766]: [31-1] user=,db=,e=00000 DEBUG: Latch status after wait call: 1
2016-12-23 15:31:36 EST [] [30766]: [33-1] user=,db=,e=00000 DEBUG: Latch status inside for loop before reset: 1
2016-12-23 15:31:36 EST [] [30766]: [34-1] user=,db=,e=00000 DEBUG: Latch status just after reset before interupt check: 0Just to help confirm my above assumption, commenting out this single line of code in my main background worker allowed the WaitLatch timeout to work againThankfully the only thing my background worker does is call another plpgsql function on an interval, and that function has an advisory lock to prevent concurrent runs. Don't think this bgw_notify_pid was actually preventing concurrent runs before, but if someone actually needed that feedback and used a WaitLatch, this could cause it to break. Only reason I had this in there was because I used the worker_spi code as my initial example on how to create a dynamic background worker.
worker.bgw_notify_pid = MyProcPid;KeithAnd I spoke too soon. Taking that line out does indeed stop the background worker from going nuts. But it also stops it from working completely. It's basically the same result as me trying to handle SIGUSR1 myself. The main background worker process halts as soon as the dynamic worker unregisters because it seems it needs to get that status from the dynamic worker back to continue working.So this is quite a big deal for anyone working with background workers that must interact with each other and use the Latch system to allow proper interruption of processes and clean shutdowns.Keith
Believe I found a solution to the issue. By calling WaitForBackgroundWorkerShutdown() after the dynamic background worker has been confirmed to have started properly, it allows the latch wait to work. Seems to be because WaitForBackgroundWorkerShutdown() itself contains a ResetLatch() call to reset the current process's Latch. Makes me wonder why the starting and stopping of the background worker even sends SIGUSR1 to set the current process latch in the first place.
This has the disadvantage of not allowing multiple dynamic bgws to be started and then run in parallel since I now have to wait for confirmation that it shutdown before going to the next loop to start another one. I guess maybe I could call ResetLatch() instead of waiting for the BGW to shutdown, but that seems hacky and again that makes me wonder why the latch is even being set in the first place on worker startup/shutdown.