Date: Wed, 18 Mar 2020 16:25:11 -0500
From: Justin Pryzby <pryzby@telsasoft.com>
To: Julien Rouhaud <rjuju123@gmail.com>
Cc: pgsql-hackers@postgresql.org
Subject: Re: expose parallel leader in CSV and log_line_prefix
Message-ID: <20200318212511.GN26184@telsasoft.com>
References: <20200315111831.GA21492@telsasoft.com>
 <20200315114933.udjdx5wcgwkjnw45@nol>
MIME-Version: 1.0
Content-Type: multipart/mixed; boundary="MdJ3p2aQbVp3YFXz"
Content-Disposition: inline
In-Reply-To: <20200315114933.udjdx5wcgwkjnw45@nol>
User-Agent: Mutt/1.9.4 (2018-02-28)
Precedence: bulk


--MdJ3p2aQbVp3YFXz
Content-Type: text/plain; charset=us-ascii
Content-Disposition: inline

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/
> > https://www.postgresql.org/message-id/flat/CAOBaU_Yy5bt0vTPZ2_LUM6cUcGeqmYNoJ8-Rgto+c2+w3defYA@mail.gmail.com
> > b025f32e0b Add leader_pid to pg_stat_activity
> 
> FTR this is a followup of https://www.postgresql.org/message-id/20200315095728.GA26184%40telsasoft.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

--MdJ3p2aQbVp3YFXz
Content-Type: text/x-diff; charset=us-ascii
Content-Disposition: attachment;
 filename="v3-0001-Include-the-leader-PID-in-logfile.patch"

From 53d766e88537ca018d46efc671d5b586862fb30b Mon Sep 17 00:00:00 2001
From: Justin Pryzby <pryzbyj@telsasoft.com>
Date: Fri, 13 Mar 2020 22:03:06 -0500
Subject: [PATCH v3] Include the leader PID in logfile

See also: b025f32e0b, which adds the leader PID to pg_stat_activity
---
 doc/src/sgml/config.sgml                      | 11 +++++++-
 src/backend/utils/error/elog.c                | 27 +++++++++++++++++++
 src/backend/utils/misc/postgresql.conf.sample |  1 +
 3 files changed, 38 insertions(+), 1 deletion(-)

diff --git a/doc/src/sgml/config.sgml b/doc/src/sgml/config.sgml
index 672bf6f1ee..b9a1bd9a31 100644
--- a/doc/src/sgml/config.sgml
+++ b/doc/src/sgml/config.sgml
@@ -6511,6 +6511,14 @@ local0.*    /var/log/postgresql
              <entry>Process ID</entry>
              <entry>no</entry>
             </row>
+            <row>
+             <entry><literal>%k</literal></entry>
+             <entry>Process ID of the parallel group leader if this
+             process is or was involved in parallel query, null
+             otherwise.  For a parallel group leader, this field is
+             set to its own process ID.</entry>
+             <entry>no</entry>
+            </row>
             <row>
              <entry><literal>%t</literal></entry>
              <entry>Time stamp without milliseconds</entry>
@@ -6809,7 +6817,7 @@ log_line_prefix = '%m [%p] %q%u@%d/%a '
         character count of the error position therein,
         location of the error in the PostgreSQL source code
         (if <varname>log_error_verbosity</varname> is set to <literal>verbose</literal>),
-        application name, and backend type.
+        application name, backend type, and leader PID.
         Here is a sample table definition for storing CSV-format log output:
 
 <programlisting>
@@ -6839,6 +6847,7 @@ CREATE TABLE postgres_log
   location text,
   application_name text,
   backend_type text,
+  leader_pid integer,
   PRIMARY KEY (session_id, session_line_num)
 );
 </programlisting>
diff --git a/src/backend/utils/error/elog.c b/src/backend/utils/error/elog.c
index 62eef7b71f..5328664f4d 100644
--- a/src/backend/utils/error/elog.c
+++ b/src/backend/utils/error/elog.c
@@ -77,6 +77,7 @@
 #include "postmaster/syslogger.h"
 #include "storage/ipc.h"
 #include "storage/proc.h"
+#include "storage/procarray.h"
 #include "tcop/tcopprot.h"
 #include "utils/guc.h"
 #include "utils/memutils.h"
@@ -2560,6 +2561,22 @@ log_line_prefix(StringInfo buf, ErrorData *edata)
 				else
 					appendStringInfo(buf, "%d", MyProcPid);
 				break;
+
+			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;
+
 			case 'l':
 				if (padding != 0)
 					appendStringInfo(buf, "%*ld", padding, log_line_number);
@@ -2948,6 +2965,16 @@ write_csvlog(ErrorData *edata)
 	else
 		appendCSVLiteral(&buf, GetBackendTypeDesc(MyBackendType));
 
+	appendStringInfoChar(&buf, ',');
+
+	/* leader PID */
+	if (MyProc)
+	{
+		PGPROC *leader = MyProc->lockGroupLeader;
+		if (leader)
+			appendStringInfo(&buf, "%d", leader->pid);
+	}
+
 	appendStringInfoChar(&buf, '\n');
 
 	/* If in the syslogger process, try to write messages direct to file */
diff --git a/src/backend/utils/misc/postgresql.conf.sample b/src/backend/utils/misc/postgresql.conf.sample
index aa44f0c9bf..6874792a15 100644
--- a/src/backend/utils/misc/postgresql.conf.sample
+++ b/src/backend/utils/misc/postgresql.conf.sample
@@ -530,6 +530,7 @@
 					#   %h = remote host
 					#   %b = backend type
 					#   %p = process ID
+					#   %k = leader PID
 					#   %t = timestamp without milliseconds
 					#   %m = timestamp with milliseconds
 					#   %n = timestamp with milliseconds (as a Unix epoch)
-- 
2.17.0


--MdJ3p2aQbVp3YFXz--