expose parallel leader in CSV and log_line_prefix
See also:
https://commitfest.postgresql.org/27/2390/
/messages/by-id/CAOBaU_Yy5bt0vTPZ2_LUM6cUcGeqmYNoJ8-Rgto+c2+w3defYA@mail.gmail.com
b025f32e0b Add leader_pid to pg_stat_activity
--
Justin
Attachments:
v2-0001-Include-the-leader-PID-in-logfile.patchtext/x-diff; charset=us-asciiDownload+31-2
On Sun, Mar 15, 2020 at 06:18:31AM -0500, Justin Pryzby wrote:
See also:
https://commitfest.postgresql.org/27/2390/
/messages/by-id/CAOBaU_Yy5bt0vTPZ2_LUM6cUcGeqmYNoJ8-Rgto+c2+w3defYA@mail.gmail.com
b025f32e0b Add leader_pid to pg_stat_activity
FTR this is a followup of /messages/by-id/20200315095728.GA26184@telsasoft.com
+1 for the feature. Regarding the patch:
+ case 'k':
+ if (MyBackendType != B_BG_WORKER)
+ ; /* Do nothing */Isn't the test inverted? Also a bgworker could run parallel queries through
SPI I think, should we really ignore bgworkers?
+ else if (!MyProc->lockGroupLeader)
+ ; /* Do nothing */There should be a test that MyProc isn't NULL.
+ else if (padding != 0)
+ appendStringInfo(buf, "%*d", padding, MyProc->lockGroupLeader->pid);
+ else
+ appendStringInfo(buf, "%d", MyProc->lockGroupLeader->pid);
+ break;I think that if padding was asked we should append spaces rather than doing
nothing.
On Sun, Mar 15, 2020 at 12:49:33PM +0100, Julien Rouhaud wrote:
On Sun, Mar 15, 2020 at 06:18:31AM -0500, Justin Pryzby wrote:
See also:
https://commitfest.postgresql.org/27/2390/
/messages/by-id/CAOBaU_Yy5bt0vTPZ2_LUM6cUcGeqmYNoJ8-Rgto+c2+w3defYA@mail.gmail.com
b025f32e0b Add leader_pid to pg_stat_activityFTR this is a followup of /messages/by-id/20200315095728.GA26184@telsasoft.com
Yes - but I wasn't going to draw attention to the first patch, in which I did
something needlessly complicated and indirect. :)
+ case 'k': + if (MyBackendType != B_BG_WORKER) + ; /* Do nothing */Isn't the test inverted? Also a bgworker could run parallel queries through
SPI I think, should we really ignore bgworkers?
I don't think it's reversed, but I think I see your point: the patch is
supposed to be showing the leader's own PID for the leader itself. So I think
that can just be removed.
+ else if (!MyProc->lockGroupLeader) + ; /* Do nothing */There should be a test that MyProc isn't NULL.
Yes, done.
+ else if (padding != 0) + appendStringInfo(buf, "%*d", padding, MyProc->lockGroupLeader->pid); + else + appendStringInfo(buf, "%d", MyProc->lockGroupLeader->pid); + break;I think that if padding was asked we should append spaces rather than doing
nothing.
Done
It logs like:
template1=# SET log_temp_files=0; explain analyze SELECT a,COUNT(1) FROM t a JOIN t b USING(a) GROUP BY 1;
2020-03-15 21:20:47.288 CDT [5537 5537]LOG: statement: SET log_temp_files=0;
SET
2020-03-15 21:20:47.289 CDT [5537 5537]LOG: statement: explain analyze SELECT a,COUNT(1) FROM t a JOIN t b USING(a) GROUP BY 1;
2020-03-15 21:20:51.253 CDT [5627 5537]LOG: temporary file: path "base/pgsql_tmp/pgsql_tmp5627.0", size 6094848
2020-03-15 21:20:51.253 CDT [5627 5537]STATEMENT: explain analyze SELECT a,COUNT(1) FROM t a JOIN t b USING(a) GROUP BY 1;
2020-03-15 21:20:51.254 CDT [5626 5537]LOG: temporary file: path "base/pgsql_tmp/pgsql_tmp5626.0", size 6103040
2020-03-15 21:20:51.254 CDT [5626 5537]STATEMENT: explain analyze SELECT a,COUNT(1) FROM t a JOIN t b USING(a) GROUP BY 1;
2020-03-15 21:20:51.263 CDT [5537 5537]LOG: temporary file: path "base/pgsql_tmp/pgsql_tmp5537.1.sharedfileset/o15of16.p0.0", size 557056
Now, with the leader showing its own PID.
This also fixes unsafe access to lockGroupLeader->pid, same issue as in the
original v1 patch for b025f32e0b.
--
Justin
Attachments:
v3-0001-Include-the-leader-PID-in-logfile.patchtext/x-diff; charset=us-asciiDownload+38-2
On 18 Mar 2020, at 22:25, Justin Pryzby <pryzby@telsasoft.com> wrote:
This also fixes unsafe access to lockGroupLeader->pid, same issue as in the
original v1 patch for b025f32e0b.
Julian, having been involved in the other threads around this topic, do you
have time to review this latest version during the commitfest?
cheers ./daniel
On Thu, Jul 9, 2020 at 1:48 PM Daniel Gustafsson <daniel@yesql.se> wrote:
On 18 Mar 2020, at 22:25, Justin Pryzby <pryzby@telsasoft.com> wrote:
This also fixes unsafe access to lockGroupLeader->pid, same issue as in the
original v1 patch for b025f32e0b.Julian, having been involved in the other threads around this topic, do you
have time to review this latest version during the commitfest?
Sure! I've been quite busy with internal work duties recently but
I'll review this patch shortly. Thanks for the reminder!
On Thu, Jul 09, 2020 at 01:53:39PM +0200, Julien Rouhaud wrote:
Sure! I've been quite busy with internal work duties recently but
I'll review this patch shortly. Thanks for the reminder!
Hmm. In which cases would it be useful to have this information in
the logs knowing that pg_stat_activity lets us know the link between
both the leader and its workers?
--
Michael
On Fri, Jul 10, 2020 at 11:09:40AM +0900, Michael Paquier wrote:
On Thu, Jul 09, 2020 at 01:53:39PM +0200, Julien Rouhaud wrote:
Sure! I've been quite busy with internal work duties recently but
I'll review this patch shortly. Thanks for the reminder!Hmm. In which cases would it be useful to have this information in
the logs knowing that pg_stat_activity lets us know the link between
both the leader and its workers?
PSA is an instantaneous view whereas the logs are a record. That's important
for shortlived processes (like background workers) or in the case of an ERROR
or later crash.
Right now, the logs fail to include that information, which is deficient. Half
the utility is in showing *that* the log is for a parallel worker, which is
otherwise not apparent.
--
Justin
On Thu, Jul 09, 2020 at 09:20:23PM -0500, Justin Pryzby wrote:
On Fri, Jul 10, 2020 at 11:09:40AM +0900, Michael Paquier wrote:
On Thu, Jul 09, 2020 at 01:53:39PM +0200, Julien Rouhaud wrote:
Sure! I've been quite busy with internal work duties recently but
I'll review this patch shortly. Thanks for the reminder!Hmm. In which cases would it be useful to have this information in
the logs knowing that pg_stat_activity lets us know the link between
both the leader and its workers?PSA is an instantaneous view whereas the logs are a record. That's important
for shortlived processes (like background workers) or in the case of an ERROR
or later crash.Right now, the logs fail to include that information, which is deficient. Half
the utility is in showing *that* the log is for a parallel worker, which is
otherwise not apparent.
Yes, I agree that this is a nice thing to have and another smell step toward
parallel query monitoring.
About the patch:
+ case 'k':
+ if (MyProc)
+ {
+ PGPROC *leader = MyProc->lockGroupLeader;
+ if (leader == NULL)
+ /* padding only */
+ appendStringInfoSpaces(buf,
+ padding > 0 ? padding : -padding);
+ else if (padding != 0)
+ appendStringInfo(buf, "%*d", padding, leader->pid);
+ else
+ appendStringInfo(buf, "%d", leader->pid);
+ }
+ break;There's a thinko in the padding handling. It should be dones whether MyProc
and/or lockGroupLeader is NULL or not, and only if padding was asked, like it's
done for case 'd' for instance.
Also, the '%k' escape sounds a bit random. Is there any reason why we don't
use any uppercase character for log_line_prefix? %P could be a better
alternative, otherwise maybe %g, as GroupLeader/Gather?
On Fri, Jul 10, 2020 at 05:13:26PM +0200, Julien Rouhaud wrote:
There's a thinko in the padding handling. It should be dones whether MyProc
and/or lockGroupLeader is NULL or not, and only if padding was asked, like it's
done for case 'd' for instance.Also, the '%k' escape sounds a bit random. Is there any reason why we don't
use any uppercase character for log_line_prefix? %P could be a better
alternative, otherwise maybe %g, as GroupLeader/Gather?
Thanks for looking. %P is a good idea - it's consistent with ps and pkill and
probably other %commands. I also amended the docs.
--
Justin
Attachments:
v2-0001-Include-the-leader-PID-in-logfile.patchtext/x-diff; charset=us-asciiDownload+41-2
On Fri, Jul 10, 2020 at 11:11:15AM -0500, Justin Pryzby wrote:
On Fri, Jul 10, 2020 at 05:13:26PM +0200, Julien Rouhaud wrote:
There's a thinko in the padding handling. It should be dones whether MyProc
and/or lockGroupLeader is NULL or not, and only if padding was asked, like it's
done for case 'd' for instance.Also, the '%k' escape sounds a bit random. Is there any reason why we don't
use any uppercase character for log_line_prefix? %P could be a better
alternative, otherwise maybe %g, as GroupLeader/Gather?Thanks for looking. %P is a good idea - it's consistent with ps and pkill and
probably other %commands. I also amended the docs.
Thanks!
So for the leader == NULL case, the AppendStringInfoSpace is a no-op if no
padding was asked, so it's probably not worth adding extra code to make it any
more obvious.
It all looks good to me, I'm marking the patch a ready for committer!
On 2020-Mar-18, Justin Pryzby wrote:
On Sun, Mar 15, 2020 at 12:49:33PM +0100, Julien Rouhaud wrote:
template1=# SET log_temp_files=0; explain analyze SELECT a,COUNT(1) FROM t a JOIN t b USING(a) GROUP BY 1;
2020-03-15 21:20:47.288 CDT [5537 5537]LOG: statement: SET log_temp_files=0;
SET
2020-03-15 21:20:47.289 CDT [5537 5537]LOG: statement: explain analyze SELECT a,COUNT(1) FROM t a JOIN t b USING(a) GROUP BY 1;
2020-03-15 21:20:51.253 CDT [5627 5537]LOG: temporary file: path "base/pgsql_tmp/pgsql_tmp5627.0", size 6094848
2020-03-15 21:20:51.253 CDT [5627 5537]STATEMENT: explain analyze SELECT a,COUNT(1) FROM t a JOIN t b USING(a) GROUP BY 1;
2020-03-15 21:20:51.254 CDT [5626 5537]LOG: temporary file: path "base/pgsql_tmp/pgsql_tmp5626.0", size 6103040
2020-03-15 21:20:51.254 CDT [5626 5537]STATEMENT: explain analyze SELECT a,COUNT(1) FROM t a JOIN t b USING(a) GROUP BY 1;
2020-03-15 21:20:51.263 CDT [5537 5537]LOG: temporary file: path "base/pgsql_tmp/pgsql_tmp5537.1.sharedfileset/o15of16.p0.0", size 557056
I think it's overly verbose; all non-parallel backends are going to get
their own PID twice, and I'm not sure this is going to be great to
parse. I think it would be more sensible that if the process does not
have a parent (leader), %P expands to empty.
--
�lvaro Herrera https://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services
On Fri, Jul 10, 2020 at 12:45:29PM -0400, Alvaro Herrera wrote:
On 2020-Mar-18, Justin Pryzby wrote:
On Sun, Mar 15, 2020 at 12:49:33PM +0100, Julien Rouhaud wrote:
template1=# SET log_temp_files=0; explain analyze SELECT a,COUNT(1) FROM t a JOIN t b USING(a) GROUP BY 1;
2020-03-15 21:20:47.288 CDT [5537 5537]LOG: statement: SET log_temp_files=0;
SET
2020-03-15 21:20:47.289 CDT [5537 5537]LOG: statement: explain analyze SELECT a,COUNT(1) FROM t a JOIN t b USING(a) GROUP BY 1;
2020-03-15 21:20:51.253 CDT [5627 5537]LOG: temporary file: path "base/pgsql_tmp/pgsql_tmp5627.0", size 6094848
2020-03-15 21:20:51.253 CDT [5627 5537]STATEMENT: explain analyze SELECT a,COUNT(1) FROM t a JOIN t b USING(a) GROUP BY 1;
2020-03-15 21:20:51.254 CDT [5626 5537]LOG: temporary file: path "base/pgsql_tmp/pgsql_tmp5626.0", size 6103040
2020-03-15 21:20:51.254 CDT [5626 5537]STATEMENT: explain analyze SELECT a,COUNT(1) FROM t a JOIN t b USING(a) GROUP BY 1;
2020-03-15 21:20:51.263 CDT [5537 5537]LOG: temporary file: path "base/pgsql_tmp/pgsql_tmp5537.1.sharedfileset/o15of16.p0.0", size 557056I think it's overly verbose; all non-parallel backends are going to get
their own PID twice, and I'm not sure this is going to be great to
parse. I think it would be more sensible that if the process does not
have a parent (leader), %P expands to empty.
That's what's done.
+ <entry>Process ID of the parallel group leader if this process was
+ at some point involved in parallel query, otherwise null. For a
+ parallel group leader itself, this field is set to its own process
+ ID.</entry>2020-07-10 11:53:32.304 CDT [16699 ]LOG: statement: SELECT 1;
2020-07-10 11:53:32.304 CDT,"pryzbyj","postgres",16699,"[local]",5f089d0b.413b,1,"idle",2020-07-10 11:53:31 CDT,3/4,0,LOG,00000,"statement: SELECT 1;",,,,,,,,,"psql","client backend",
--
Justin
On 2020-Jul-10, Justin Pryzby wrote:
On Fri, Jul 10, 2020 at 12:45:29PM -0400, Alvaro Herrera wrote:
I think it's overly verbose; all non-parallel backends are going to get
their own PID twice, and I'm not sure this is going to be great to
parse. I think it would be more sensible that if the process does not
have a parent (leader), %P expands to empty.That's what's done.
+ <entry>Process ID of the parallel group leader if this process was + at some point involved in parallel query, otherwise null. For a + parallel group leader itself, this field is set to its own process + ID.</entry>
Oh, okay by me then.
--
�lvaro Herrera https://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services
On Fri, Jul 10, 2020 at 01:16:40PM -0400, Alvaro Herrera wrote:
On 2020-Jul-10, Justin Pryzby wrote:
That's what's done.
+ <entry>Process ID of the parallel group leader if this process was + at some point involved in parallel query, otherwise null. For a + parallel group leader itself, this field is set to its own process + ID.</entry>Oh, okay by me then.
Please note that this choice comes from BecomeLockGroupLeader(), where
a leader registers itself in lockGroupLeader, and remains set as such
as long as the process is alive so we would always get a value for a
process once it got involved in parallel query. This patch is just
doing what we do in pg_stat_get_activity(), with the padding handling.
It is true that this may cause log_line_prefix to be overly verbose in
the case where you keep a lot of sessions alive for long time when
they got all involved at least once in parallel query as most of them
would just refer to their own PID, but I think that it is better to be
consistent with what we do already with pg_stat_activity, as that's
the data present in the PGPROC entries.
--
Michael
On 2020-Jul-17, Michael Paquier wrote:
Please note that this choice comes from BecomeLockGroupLeader(), where
a leader registers itself in lockGroupLeader, and remains set as such
as long as the process is alive so we would always get a value for a
process once it got involved in parallel query. This patch is just
Oh, ugh, I don't like that part much. If you run connections through a
connection pooler, it's going to be everywhere. Let's put it there only
if the connection *is* running a parallel query, without being too
stressed about the startup and teardown sequence.
--
�lvaro Herrera https://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services
On Thu, Jul 16, 2020 at 10:55:45PM -0400, Alvaro Herrera wrote:
Oh, ugh, I don't like that part much. If you run connections through a
connection pooler, it's going to be everywhere. Let's put it there only
if the connection *is* running a parallel query, without being too
stressed about the startup and teardown sequence.
Hmm. Knowing if a leader is actually running parallel query or not
requires a lookup at lockGroupMembers, that itself requires a LWLock.
I think that it would be better to not require that. So what if
instead we logged %P only if Myproc has lockGroupLeader set and it
does *not* match MyProcPid? In short, it means that we would get the
information of a leader for each worker currently running parallel
query, but that we would not know from the leader if it is running a
parallel query or not at the moment of the log. One can then easily
guess what was happening on the leader by looking at the logs of the
backend matching with the PID the workers are logging with %P.
--
Michael
Hi,
On Fri, Jul 17, 2020 at 7:01 AM Michael Paquier <michael@paquier.xyz> wrote:
On Thu, Jul 16, 2020 at 10:55:45PM -0400, Alvaro Herrera wrote:
Oh, ugh, I don't like that part much. If you run connections through a
connection pooler, it's going to be everywhere. Let's put it there only
if the connection *is* running a parallel query, without being too
stressed about the startup and teardown sequence.Hmm. Knowing if a leader is actually running parallel query or not
requires a lookup at lockGroupMembers, that itself requires a LWLock.
I think that it would be better to not require that. So what if
instead we logged %P only if Myproc has lockGroupLeader set and it
does *not* match MyProcPid? In short, it means that we would get the
information of a leader for each worker currently running parallel
query, but that we would not know from the leader if it is running a
parallel query or not at the moment of the log. One can then easily
guess what was happening on the leader by looking at the logs of the
backend matching with the PID the workers are logging with %P.
I had the same concern and was thinking about this approach too.
Another argument is that IIUC any log emitted due to
log_min_duration_statement wouldn't see the backend as executing a
parallel query, since the workers would already have been shut down.
On Fri, Jul 17, 2020 at 7:01 AM Michael Paquier <michael@paquier.xyz> wrote:
Hmm. Knowing if a leader is actually running parallel query or not
requires a lookup at lockGroupMembers, that itself requires a LWLock.
I think that it would be better to not require that. So what if
instead we logged %P only if Myproc has lockGroupLeader set and it
does *not* match MyProcPid?
That's what I said first, so +1 for that approach.
--
�lvaro Herrera https://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services
On Fri, Jul 17, 2020 at 11:35:40AM -0400, Alvaro Herrera wrote:
On Fri, Jul 17, 2020 at 7:01 AM Michael Paquier <michael@paquier.xyz> wrote:
Hmm. Knowing if a leader is actually running parallel query or not
requires a lookup at lockGroupMembers, that itself requires a LWLock.
I think that it would be better to not require that. So what if
instead we logged %P only if Myproc has lockGroupLeader set and it
does *not* match MyProcPid?That's what I said first, so +1 for that approach.
Ok, but should we then consider changing pg_stat_activity for consistency ?
Probably in v13 to avoid changing it a year later.
https://git.postgresql.org/gitweb/?p=postgresql.git;a=commitdiff;h=b025f32e0b5d7668daec9bfa957edf3599f4baa8
I think the story is that we're exposing to the user a "leader pid" what's
internally called (and used as) the "lock group leader", which for the leader
process is set to its own PID. But I think what we're exposing as leader_pid
will seem like an implementation artifact to users. It's unnatural to define a
leader PID for the leader itself, and I'm guessing that at least 30% of people
who use pg_stat_activity.leader_pid will be surprised by rows with
| backend_type='client backend' AND leader_pid IS NOT NULL
And maybe additionally confused if PSA doesn't match CSV or other log.
Right now, PSA will include processes "were leader" queries like:
| SELECT pid FROM pg_stat_activity WHERE pid=leader_pid
If we change it, I think you can get the same thing for a *current* leader like:
| SELECT pid FROM pg_stat_activity a WHERE EXISTS (SELECT 1 FROM pg_stat_activity b WHERE b.leader_pid=a.pid);
But once the children die, you can't get that anymore. Is that a problem ?
I didn't think of it until now, but it would be useful to query logs for
processes which were involved in parallel process. (It would be more useful if
it indicated the query, and not just the process)
I agree that showing the PID as the leader PID while using a connection pooler
is "noisy". But I think that's maybe just a consequence of connection pooling.
As an analogy, I would normally use a query like:
| SELECT session_line, message, query FROM postgres_log WHERE session_id='..' ORDER BY 1
But that already doesn't work usefully with connection pooling (and I'm not
sure how to resolve that other than by not using pooling when logs are useful)
I'm not sure what the answer. Probably we should either make both expose
lockGroupLeader exactly (and not filtered) or make both show lockGroupLeader
only if lockGroupLeader!=getpid().
--
Justin
On 2020-Jul-17, Justin Pryzby wrote:
Ok, but should we then consider changing pg_stat_activity for consistency ?
Probably in v13 to avoid changing it a year later.
https://git.postgresql.org/gitweb/?p=postgresql.git;a=commitdiff;h=b025f32e0b5d7668daec9bfa957edf3599f4baa8I think the story is that we're exposing to the user a "leader pid" what's
internally called (and used as) the "lock group leader", which for the leader
process is set to its own PID. But I think what we're exposing as leader_pid
will seem like an implementation artifact to users.
IMO it *is* an implementation artifact if, as you say, the leader PID
remains set after the parallel query is done. I mentioned the pgbouncer
case before: if you run a single parallel query, then the process
remains a "parallel leader" for days or weeks afterwards even if it
hasn't run a parallel query ever since. That doesn't sound great to me.
I think it's understandable and OK if there's a small race condition
that means you report a process as a leader shortly before or shortly
after a parallel query is actually executed. But doing so until backend
termination seems confusing as well as useless.
--
�lvaro Herrera https://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services
