Date: Sun, 15 Mar 2020 04:57:28 -0500
From: Justin Pryzby <pryzby@telsasoft.com>
To: Peter Eisentraut <peter.eisentraut@2ndquadrant.com>
Cc: Fujii Masao <masao.fujii@oss.nttdata.com>,
	Julien Rouhaud <rjuju123@gmail.com>, pgsql-hackers@postgresql.org
Subject: Re: backend type in log_line_prefix?
Message-ID: <20200315095728.GA26184@telsasoft.com>
References: <c65e5196-4f04-4ead-9353-6088c19615a3@2ndquadrant.com>
 <20200213091428.GA15600@nol>
 <d7dd4aad-c0f3-ecc3-e0f9-def491951e2f@oss.nttdata.com>
 <20200310190142.GB29065@telsasoft.com>
 <20200311185354.GW29065@telsasoft.com>
 <c14e8db8-3c31-1463-dd49-cbf45643d8e7@2ndquadrant.com>
MIME-Version: 1.0
Content-Type: multipart/mixed; boundary="QTprm0S8XgL7H0Dt"
Content-Disposition: inline
In-Reply-To: <c14e8db8-3c31-1463-dd49-cbf45643d8e7@2ndquadrant.com>
User-Agent: Mutt/1.9.4 (2018-02-28)
Precedence: bulk


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

On Fri, Mar 13, 2020 at 10:22:52PM +0100, Peter Eisentraut wrote:
> >Can I suggest:
> >
> >-               appendCSVLiteral(&buf, MyBgworkerEntry->bgw_type);
> >+               appendCSVLiteral(&buf, MyBgworkerEntry->bgw_name);
> 
> The difference is intentional.  bgw_type is so that you can filter and group
> by type.  The bgw_name could be totally different for each instance.

I found 5373bc2a0867048bb78f93aede54ac1309b5e227

Your patch adds bgw_type, which is also in pg_stat_activity, so I agree it's
good to allow include it log_line_prefix and CSV.

I suggest the CSV/log should also have the leader_pid, corresponding to
| b025f32e0b Add leader_pid to pg_stat_activity

With the attached on top of your patch, CSV logs like:

2020-03-14 22:09:39.395 CDT,"pryzbyj","template1",17030,"[local]",5e6d9c69.4286,2,"idle",2020-03-14 22:09:29 CDT,3/23,0,LOG,00000,"statement: explain analyze SELECT COUNT(1), a.a FROM t a JOIN t b ON a.a=b.a GROUP BY 2;",,,,,,,,,"psql","client backend",
2020-03-14 22:09:43.094 CDT,,,17042,,5e6d9c73.4292,1,,2020-03-14 22:09:39 CDT,4/3,0,LOG,00000,"temporary file: path ""base/pgsql_tmp/pgsql_tmp17042.0"", size 4694016",,,,,,"explain analyze SELECT COUNT(1), a.a FROM t a JOIN t b ON a.a=b.a GROUP BY 2;",,,"psql","parallel worker",17030
2020-03-14 22:09:43.094 CDT,,,17043,,5e6d9c73.4293,1,,2020-03-14 22:09:39 CDT,5/3,0,LOG,00000,"temporary file: path ""base/pgsql_tmp/pgsql_tmp17043.0"", size 4694016",,,,,,"explain analyze SELECT COUNT(1), a.a FROM t a JOIN t b ON a.a=b.a GROUP BY 2;",,,"psql","parallel worker",17030

As for my question "what's using/trying/failing to use parallel workers", I was
able to look into that by parsing "Workers Planned/Launched" from autoexplain.
It's not a *good* way to do it, but I don't see how to do better and I don't
see any way this patch can improve that.

-- 
Justin

--QTprm0S8XgL7H0Dt
Content-Type: text/x-diff; charset=us-ascii
Content-Disposition: attachment; filename="v1-0001-Fix-previous-commit.patch"

From 5b111a3a6cd5282dbdf1e504ef648994b1918302 Mon Sep 17 00:00:00 2001
From: Justin Pryzby <pryzbyj@telsasoft.com>
Date: Sat, 14 Mar 2020 19:09:54 -0500
Subject: [PATCH v1 1/2] Fix previous commit..

---
 doc/src/sgml/config.sgml       | 2 +-
 src/backend/utils/error/elog.c | 5 ++---
 2 files changed, 3 insertions(+), 4 deletions(-)

diff --git a/doc/src/sgml/config.sgml b/doc/src/sgml/config.sgml
index 53d0c480aa..fc0e2c00c3 100644
--- a/doc/src/sgml/config.sgml
+++ b/doc/src/sgml/config.sgml
@@ -6460,7 +6460,7 @@ local0.*    /var/log/postgresql
             <row>
              <entry><literal>%b</literal></entry>
              <entry>Backend process type</entry>
-             <entry>yes</entry>
+             <entry>no</entry>
             </row>
             <row>
              <entry><literal>%u</literal></entry>
diff --git a/src/backend/utils/error/elog.c b/src/backend/utils/error/elog.c
index 3a6f7f9456..62eef7b71f 100644
--- a/src/backend/utils/error/elog.c
+++ b/src/backend/utils/error/elog.c
@@ -72,7 +72,6 @@
 #include "libpq/pqformat.h"
 #include "mb/pg_wchar.h"
 #include "miscadmin.h"
-#include "pgstat.h"
 #include "postmaster/bgworker.h"
 #include "postmaster/postmaster.h"
 #include "postmaster/syslogger.h"
@@ -2503,7 +2502,7 @@ log_line_prefix(StringInfo buf, ErrorData *edata)
 					else if (MyBackendType == B_BG_WORKER)
 						backend_type_str = MyBgworkerEntry->bgw_type;
 					else
-						backend_type_str = pgstat_get_backend_desc(MyBackendType);
+						backend_type_str = GetBackendTypeDesc(MyBackendType);
 
 					if (padding != 0)
 						appendStringInfo(buf, "%*s", padding, backend_type_str);
@@ -2947,7 +2946,7 @@ write_csvlog(ErrorData *edata)
 	else if (MyBackendType == B_BG_WORKER)
 		appendCSVLiteral(&buf, MyBgworkerEntry->bgw_type);
 	else
-		appendCSVLiteral(&buf, pgstat_get_backend_desc(MyBackendType));
+		appendCSVLiteral(&buf, GetBackendTypeDesc(MyBackendType));
 
 	appendStringInfoChar(&buf, '\n');
 
-- 
2.17.0


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

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

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

diff --git a/doc/src/sgml/config.sgml b/doc/src/sgml/config.sgml
index fc0e2c00c3..d53b62e2df 100644
--- a/doc/src/sgml/config.sgml
+++ b/doc/src/sgml/config.sgml
@@ -6487,6 +6487,11 @@ local0.*    /var/log/postgresql
              <entry>Process ID</entry>
              <entry>no</entry>
             </row>
+            <row>
+             <entry><literal>%k</literal></entry>
+             <entry>Leader PID for a parallel process, NULL otherwise</entry>
+             <entry>yes</entry>
+            </row>
             <row>
              <entry><literal>%t</literal></entry>
              <entry>Time stamp without milliseconds</entry>
@@ -6777,7 +6782,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>
@@ -6807,6 +6812,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..e6b3caf414 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"
@@ -177,6 +178,7 @@ static void write_console(const char *line, int len);
 static void setup_formatted_log_time(void);
 static void setup_formatted_start_time(void);
 static const char *process_log_prefix_padding(const char *p, int *padding);
+static pid_t get_leader_pid();
 static void log_line_prefix(StringInfo buf, ErrorData *edata);
 static void write_csvlog(ErrorData *edata);
 static void send_message_to_server_log(ErrorData *edata);
@@ -2402,6 +2404,24 @@ process_log_prefix_padding(const char *p, int *ppadding)
 	return p;
 }
 
+/* Return PID of leader, or InvalidPid if not a parallel worker */
+static pid_t
+get_leader_pid()
+{
+	PGPROC	*proc;
+	pid_t	leader_pid = InvalidPid;
+
+	if (MyBackendType != B_BG_WORKER)
+		return InvalidPid;
+
+	LWLockAcquire(ProcArrayLock, LW_SHARED);
+	proc = BackendPidGetProcWithLock(MyProcPid);
+	if (proc && proc->lockGroupLeader)
+		leader_pid = proc->lockGroupLeader->pid;
+	LWLockRelease(ProcArrayLock);
+	return leader_pid;
+}
+
 /*
  * Format tag info for log lines; append to the provided buffer.
  */
@@ -2413,6 +2433,10 @@ log_line_prefix(StringInfo buf, ErrorData *edata)
 
 	/* has counter been reset in current process? */
 	static int	log_my_pid = 0;
+
+	/* Leader PID is retrieved only once per process after forking from postmaster */
+	static pid_t	leader_pid = InvalidPid;
+
 	int			padding;
 	const char *p;
 
@@ -2427,6 +2451,7 @@ log_line_prefix(StringInfo buf, ErrorData *edata)
 		log_line_number = 0;
 		log_my_pid = MyProcPid;
 		formatted_start_time[0] = '\0';
+		leader_pid = get_leader_pid();
 	}
 	log_line_number++;
 
@@ -2560,6 +2585,18 @@ log_line_prefix(StringInfo buf, ErrorData *edata)
 				else
 					appendStringInfo(buf, "%d", MyProcPid);
 				break;
+
+			case 'k':
+				if (!MyProcPort)
+					; /* Do nothing */
+				else if (leader_pid == InvalidPid)
+					; /* Do nothing */
+				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);
@@ -2768,6 +2805,9 @@ write_csvlog(ErrorData *edata)
 	/* has counter been reset in current process? */
 	static int	log_my_pid = 0;
 
+	/* Leader PID is retrieved only once per process after forking from postmaster */
+	static pid_t	leader_pid = InvalidPid;
+
 	/*
 	 * This is one of the few places where we'd rather not inherit a static
 	 * variable's value from the postmaster.  But since we will, reset it when
@@ -2778,6 +2818,7 @@ write_csvlog(ErrorData *edata)
 		log_line_number = 0;
 		log_my_pid = MyProcPid;
 		formatted_start_time[0] = '\0';
+		leader_pid = get_leader_pid();
 	}
 	log_line_number++;
 
@@ -2948,6 +2989,12 @@ write_csvlog(ErrorData *edata)
 	else
 		appendCSVLiteral(&buf, GetBackendTypeDesc(MyBackendType));
 
+	appendStringInfoChar(&buf, ',');
+
+	/* leader PID */
+	if (MyProcPort && leader_pid != InvalidPid)
+		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 c0e9531f9c..32fc4b18e6 100644
--- a/src/backend/utils/misc/postgresql.conf.sample
+++ b/src/backend/utils/misc/postgresql.conf.sample
@@ -530,6 +530,7 @@
 					#   %r = remote host and port
 					#   %h = remote host
 					#   %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


--QTprm0S8XgL7H0Dt--