Detoasting optionally to make Explain-Analyze less misleading

Started by stepan rutzover 2 years ago28 messages
#1stepan rutz
stepan.rutz@gmx.de
1 attachment(s)

Hi,

I have fallen into this trap and others have too. If you run
EXPLAIN(ANALYZE) no de-toasting happens. This makes query-runtimes
differ a lot. The bigger point is that the average user expects more
from EXPLAIN(ANALYZE) than what it provides. This can be suprising. You
can force detoasting during explain with explicit calls to length(), but
that is tedious. Those of us who are forced to work using java stacks,
orms and still store mostly documents fall into this trap sooner or
later. I have already received some good feedback on this one, so this
is an issue that bother quite a few people out there.

Attached is a patch for addressing the issue in form of adding another
parameter to explain. I don't know if that is a good idea, but I got
some feedback that a solution to this problem would be appreciated by
some people out there. It would also be nice to reflect the detoasting
in the "buffers" option of explain as well. The change for detoasting is
only a few lines though.

So the idea was to allow this

EXPLAIN (ANALYZE, DETOAST) SELECT * FROM sometable;

and perform the detoasting step additionally during the explain. This
just gives a more realistic runtime and by playing around with the
parameter and comparing the execution-times of the query one even gets
an impression about the detoasting cost involved in a query. Since the
parameter is purely optional, it would not affect any existing measures.

It is not uncommon that the runtime of explain-analyze is way
unrealistic in the real world, where people use PostgreSQL to store
larger and larger documents inside tables and not using Large-Objects.

Here is a video of the effect (in an exagerated form):
https://www.stepanrutz.com/short_detoast_subtitles.mp4

It would be great to get some feedback on the subject and how to address
this, maybe in totally different ways.

Greetings from cologne, Stepan

Stepan Rutz - IT Consultant, Cologne Germany, stepan.rutz AT gmx.de

Attachments:

0001_explain_analyze_and_detoast.patchtext/x-patch; charset=UTF-8; name=0001_explain_analyze_and_detoast.patchDownload
diff --git a/src/backend/commands/explain.c b/src/backend/commands/explain.c
index 8570b14f62..50859e6a1e 100644
--- a/src/backend/commands/explain.c
+++ b/src/backend/commands/explain.c
@@ -47,6 +47,8 @@ ExplainOneQuery_hook_type ExplainOneQuery_hook = NULL;
 /* Hook for plugins to get control in explain_get_index_name() */
 explain_get_index_name_hook_type explain_get_index_name_hook = NULL;
 
+/* Forward decl for detoasting analyze */
+static const DestReceiver detoastAnalyzeDR;
 
 /* OR-able flags for ExplainXMLTag() */
 #define X_OPENING 0
@@ -192,6 +194,8 @@ ExplainQuery(ParseState *pstate, ExplainStmt *stmt,
 			es->settings = defGetBoolean(opt);
 		else if (strcmp(opt->defname, "generic_plan") == 0)
 			es->generic = defGetBoolean(opt);
+		else if (strcmp(opt->defname, "detoast") == 0)
+			es->detoast = defGetBoolean(opt);
 		else if (strcmp(opt->defname, "timing") == 0)
 		{
 			timing_set = true;
@@ -244,6 +248,12 @@ ExplainQuery(ParseState *pstate, ExplainStmt *stmt,
 				(errcode(ERRCODE_INVALID_PARAMETER_VALUE),
 				 errmsg("EXPLAIN option TIMING requires ANALYZE")));
 
+	/* check that detoast is used with EXPLAIN ANALYZE */
+	if (es->detoast && !es->analyze)
+		ereport(ERROR,
+				(errcode(ERRCODE_INVALID_PARAMETER_VALUE),
+				 errmsg("EXPLAIN option DETOAST requires ANALYZE")));
+
 	/* check that GENERIC_PLAN is not used with EXPLAIN ANALYZE */
 	if (es->generic && es->analyze)
 		ereport(ERROR,
@@ -565,9 +575,13 @@ ExplainOnePlan(PlannedStmt *plannedstmt, IntoClause *into, ExplainState *es,
 	/*
 	 * Normally we discard the query's output, but if explaining CREATE TABLE
 	 * AS, we'd better use the appropriate tuple receiver.
+	 * Also if we choose to detoast during explain, we need to send the 
+	 * tuples to a receiver that performs the detoasting
 	 */
 	if (into)
 		dest = CreateIntoRelDestReceiver(into);
+	else if (es->analyze && es->detoast)
+		dest = &detoastAnalyzeDR;
 	else
 		dest = None_Receiver;
 
@@ -5052,3 +5066,98 @@ escape_yaml(StringInfo buf, const char *str)
 {
 	escape_json(buf, str);
 }
+
+
+/* ----------------
+ *		detoasting DestReceiver functions
+ * ----------------
+ */
+/* the idea is that running  EXPLAIN (ANALYZE)  sometimes gives results that 
+ * are way unrealistic, since during explain there is no detoasting of 
+ * values. That means you get no idea what your actual query time is going
+ * to be, nor what the actual overhead of detoasting is.
+ * 
+ * if you run EXPLAIN (ANAYLZE, DETOAST) then you get an impression of
+ * what is actually happening when you use postgresql as a document-database
+ * or have large values for some other reason.
+ */
+
+/* this method receives the tuples/records during explain (analyze, detoast)
+ * and detoasts them.
+ * this method is otherwise not called and its purpose is to detoast to
+ * make analyze optionally more realistic
+ */
+static bool
+detoastAnalyzeReceive(TupleTableSlot *slot, DestReceiver *self)
+{
+	MemoryContext cxt;
+	MemoryContext oldcxt;
+	int i;
+	bool shouldFree = true;
+	TupleDesc tupdesc = slot->tts_tupleDescriptor;
+	HeapTuple tuple = ExecFetchSlotHeapTuple(slot, true, &shouldFree);
+	uint16 t_infomask = tuple->t_data->t_infomask;
+	uint16 t_infomask2 = tuple->t_data->t_infomask2;
+	bits8 *t_bits = tuple->t_data->t_bits;
+
+	/* memory context for our work */
+	cxt = AllocSetContextCreate(CurrentMemoryContext, "DetoastTupleReceive",
+		ALLOCSET_DEFAULT_SIZES);
+	oldcxt = MemoryContextSwitchTo(cxt);
+
+	/* fill all of the slot's attributes, we can now use slot->tts_values */
+	slot_getallattrs(slot);
+
+	/* iterate over all attributes of the tuple and potentially detoast them */
+	for (i = 0; i < tupdesc->natts; i++)
+	{
+		Form_pg_attribute attr;
+		bool is_null;
+		char storage;
+
+		attr = TupleDescAttr(tupdesc, i);
+		storage = attr->attstorage;
+		if (i >= (t_infomask2 & HEAP_NATTS_MASK))
+			is_null = true;
+		else
+			is_null = (t_infomask & HEAP_HASNULL) && att_isnull(i, t_bits);
+		if (!is_null && (storage == 'e' || storage == 'x' || storage == 'm')) {
+			Datum datum = slot->tts_values[i];
+			/* here simple detoast the attribute's value, making
+			 * the explain (analyze) slower, but also more realistic
+			 */
+			pg_detoast_datum_packed(datum);
+		}
+	}
+	if (shouldFree)
+		pfree(tuple);
+
+	/* free our memorycontext and return to previous */
+	MemoryContextSwitchTo(oldcxt);
+	MemoryContextDelete(cxt);
+	return true;
+}
+
+static void
+detoastAnalyzeStartup(DestReceiver *self, int operation, TupleDesc typeinfo)
+{
+	/* nothing required */
+}
+
+static void
+detoastAnalyzeCleanup(DestReceiver *self)
+{
+	/* nothing required */
+}
+
+static void
+detoastAnalyzeDestroy(DestReceiver *self)
+{
+	/* nothing required */
+}
+
+
+static const DestReceiver detoastAnalyzeDR = {
+	detoastAnalyzeReceive, detoastAnalyzeStartup, detoastAnalyzeCleanup, detoastAnalyzeDestroy,
+	DestNone
+};
diff --git a/src/include/commands/explain.h b/src/include/commands/explain.h
index 3d3e632a0c..011dffb890 100644
--- a/src/include/commands/explain.h
+++ b/src/include/commands/explain.h
@@ -47,6 +47,8 @@ typedef struct ExplainState
 	bool		summary;		/* print total planning and execution timing */
 	bool		settings;		/* print modified settings */
 	bool		generic;		/* generate a generic plan */
+	bool		detoast;        /* detoast all toasted values, only applicable
+								   when "analyze" is active. */
 	ExplainFormat format;		/* output format */
 	/* state for output formatting --- not reset for each new plan tree */
 	int			indent;			/* current indentation level */
diff --git a/src/test/regress/expected/explain.out b/src/test/regress/expected/explain.out
index 1aca77491b..eef68d1eca 100644
--- a/src/test/regress/expected/explain.out
+++ b/src/test/regress/expected/explain.out
@@ -559,3 +559,23 @@ select explain_filter('explain (verbose) select * from int8_tbl i8');
  Query Identifier: N
 (3 rows)
 
+-- Test detoast is accepted as a parameter to explain
+-- seems hard to test the expected longer runtime of detoasting
+-- since one needs to setup enough data to make such a test stable
+-- also timing are filtered out by explain_filter anyway
+create table test_detoast(id bigserial, val text);
+select explain_filter('explain (analyze,detoast) select * from test_detoast');
+                                         explain_filter                                         
+------------------------------------------------------------------------------------------------
+ Seq Scan on test_detoast  (cost=N.N..N.N rows=N width=N) (actual time=N.N..N.N rows=N loops=N)
+ Planning Time: N.N ms
+ Execution Time: N.N ms
+(3 rows)
+
+drop table test_detoast;
+-- Test detoast is _not_ accepted as a parameter to explain unless analyze is specified
+create table test_detoast(id bigserial, val text);
+select explain_filter('explain (detoast) select * from test_detoast');
+ERROR:  EXPLAIN option DETOAST requires ANALYZE
+CONTEXT:  PL/pgSQL function explain_filter(text) line 5 at FOR over EXECUTE statement
+drop table test_detoast;
diff --git a/src/test/regress/sql/explain.sql b/src/test/regress/sql/explain.sql
index b6b7beab27..43047f9cce 100644
--- a/src/test/regress/sql/explain.sql
+++ b/src/test/regress/sql/explain.sql
@@ -154,3 +154,18 @@ select explain_filter('explain (verbose) select * from t1 where pg_temp.mysin(f1
 -- Test compute_query_id
 set compute_query_id = on;
 select explain_filter('explain (verbose) select * from int8_tbl i8');
+
+-- Test detoast is accepted as a parameter to explain
+-- seems hard to test the expected longer runtime of detoasting
+-- since one needs to setup enough data to make such a test stable
+-- also timing are filtered out by explain_filter anyway
+create table test_detoast(id bigserial, val text);
+select explain_filter('explain (analyze,detoast) select * from test_detoast');
+drop table test_detoast;
+
+-- Test detoast is _not_ accepted as a parameter to explain unless analyze is specified
+create table test_detoast(id bigserial, val text);
+select explain_filter('explain (detoast) select * from test_detoast');
+drop table test_detoast;
+
+
#2Matthias van de Meent
boekewurm+postgres@gmail.com
In reply to: stepan rutz (#1)
Re: Detoasting optionally to make Explain-Analyze less misleading

On Tue, 12 Sept 2023 at 12:56, stepan rutz <stepan.rutz@gmx.de> wrote:

Hi,

I have fallen into this trap and others have too. If you run
EXPLAIN(ANALYZE) no de-toasting happens. This makes query-runtimes
differ a lot. The bigger point is that the average user expects more
from EXPLAIN(ANALYZE) than what it provides. This can be suprising. You
can force detoasting during explain with explicit calls to length(), but
that is tedious. Those of us who are forced to work using java stacks,
orms and still store mostly documents fall into this trap sooner or
later. I have already received some good feedback on this one, so this
is an issue that bother quite a few people out there.

Yes, the lack of being able to see the impact of detoasting (amongst
others) in EXPLAIN (ANALYZE) can hide performance issues.

It would be great to get some feedback on the subject and how to address
this, maybe in totally different ways.

Hmm, maybe we should measure the overhead of serializing the tuples instead.
The difference between your patch and "serializing the tuples, but not
sending them" is that serializing also does the detoasting, but also
includes any time spent in the serialization functions of the type. So
an option "SERIALIZE" which measures all the time the server spent on
the query (except the final step of sending the bytes to the client)
would likely be more useful than "just" detoasting.

0001_explain_analyze_and_detoast.patch

I notice that this patch creates and destroys a memory context for
every tuple that the DestReceiver receives. I think that's quite
wasteful, as you should be able to create only one memory context and
reset it before (or after) each processed tuple. That also reduces the
differences in measurements between EXPLAIN and normal query
processing of the tuples - after all, we don't create new memory
contexts for every tuple in the normal DestRemote receiver either,
right?

Kind regards,

Matthias van de Meent

#3stepan rutz
stepan.rutz@gmx.de
In reply to: Matthias van de Meent (#2)
1 attachment(s)
Re: Detoasting optionally to make Explain-Analyze less misleading

Hi Matthias,

thanks for your feedback.

I wasn't sure on the memory-contexts. I was actually also unsure on
whether the array

  TupleTableSlot.tts_isnull

is also set up correctly by the previous call to slot_getallattrs(slot).
This would allow to get rid of even more code from this patch, which is
in the loop and determines whether a field is null or not. I switched to
using tts_isnull from TupleTableSlot now, seems to be ok and the docs
say it is save to use.

Also I reuse the MemoryContext throughout the livetime of the receiver.
Not sure if that makes a difference. One more thing I noticed. During
explain.c the DestReceiver's destroy callback was never invoked. I added
a line to do that, however I am unsure whether this is the right place
or a good idea in the first place. This potentially affects plain
analyze calls as well, though seems to behave nicely. Even when I
explain (analyze) select * into ....

This is the call I am talking about, which was missing from explain.c

  dest->rDestroy(dest);

Attached a new patch. Hoping for feedback,

Greetings, Stepan

Show quoted text

On 12.09.23 14:25, Matthias van de Meent wrote:

On Tue, 12 Sept 2023 at 12:56, stepan rutz<stepan.rutz@gmx.de> wrote:

Hi,

I have fallen into this trap and others have too. If you run
EXPLAIN(ANALYZE) no de-toasting happens. This makes query-runtimes
differ a lot. The bigger point is that the average user expects more
from EXPLAIN(ANALYZE) than what it provides. This can be suprising. You
can force detoasting during explain with explicit calls to length(), but
that is tedious. Those of us who are forced to work using java stacks,
orms and still store mostly documents fall into this trap sooner or
later. I have already received some good feedback on this one, so this
is an issue that bother quite a few people out there.

Yes, the lack of being able to see the impact of detoasting (amongst
others) in EXPLAIN (ANALYZE) can hide performance issues.

It would be great to get some feedback on the subject and how to address
this, maybe in totally different ways.

Hmm, maybe we should measure the overhead of serializing the tuples instead.
The difference between your patch and "serializing the tuples, but not
sending them" is that serializing also does the detoasting, but also
includes any time spent in the serialization functions of the type. So
an option "SERIALIZE" which measures all the time the server spent on
the query (except the final step of sending the bytes to the client)
would likely be more useful than "just" detoasting.

0001_explain_analyze_and_detoast.patch

I notice that this patch creates and destroys a memory context for
every tuple that the DestReceiver receives. I think that's quite
wasteful, as you should be able to create only one memory context and
reset it before (or after) each processed tuple. That also reduces the
differences in measurements between EXPLAIN and normal query
processing of the tuples - after all, we don't create new memory
contexts for every tuple in the normal DestRemote receiver either,
right?

Kind regards,

Matthias van de Meent

Attachments:

0002_explain_analyze_and_detoast.patchtext/x-patch; charset=UTF-8; name=0002_explain_analyze_and_detoast.patchDownload
diff --git a/src/backend/commands/explain.c b/src/backend/commands/explain.c
index 8570b14f62..95a09dd4cb 100644
--- a/src/backend/commands/explain.c
+++ b/src/backend/commands/explain.c
@@ -47,7 +47,6 @@ ExplainOneQuery_hook_type ExplainOneQuery_hook = NULL;
 /* Hook for plugins to get control in explain_get_index_name() */
 explain_get_index_name_hook_type explain_get_index_name_hook = NULL;
 
-
 /* OR-able flags for ExplainXMLTag() */
 #define X_OPENING 0
 #define X_CLOSING 1
@@ -155,6 +154,8 @@ static void ExplainYAMLLineStarting(ExplainState *es);
 static void escape_yaml(StringInfo buf, const char *str);
 
 
+static DestReceiver *CreateDetoastDestReceiver(void);
+
 
 /*
  * ExplainQuery -
@@ -192,6 +193,8 @@ ExplainQuery(ParseState *pstate, ExplainStmt *stmt,
 			es->settings = defGetBoolean(opt);
 		else if (strcmp(opt->defname, "generic_plan") == 0)
 			es->generic = defGetBoolean(opt);
+		else if (strcmp(opt->defname, "detoast") == 0)
+			es->detoast = defGetBoolean(opt);
 		else if (strcmp(opt->defname, "timing") == 0)
 		{
 			timing_set = true;
@@ -244,6 +247,12 @@ ExplainQuery(ParseState *pstate, ExplainStmt *stmt,
 				(errcode(ERRCODE_INVALID_PARAMETER_VALUE),
 				 errmsg("EXPLAIN option TIMING requires ANALYZE")));
 
+	/* check that detoast is used with EXPLAIN ANALYZE */
+	if (es->detoast && !es->analyze)
+		ereport(ERROR,
+				(errcode(ERRCODE_INVALID_PARAMETER_VALUE),
+				 errmsg("EXPLAIN option DETOAST requires ANALYZE")));
+
 	/* check that GENERIC_PLAN is not used with EXPLAIN ANALYZE */
 	if (es->generic && es->analyze)
 		ereport(ERROR,
@@ -565,9 +574,13 @@ ExplainOnePlan(PlannedStmt *plannedstmt, IntoClause *into, ExplainState *es,
 	/*
 	 * Normally we discard the query's output, but if explaining CREATE TABLE
 	 * AS, we'd better use the appropriate tuple receiver.
+	 * Also if we choose to detoast during explain, we need to send the
+	 * tuples to a receiver that performs the detoasting
 	 */
 	if (into)
 		dest = CreateIntoRelDestReceiver(into);
+	else if (es->analyze && es->detoast)
+		dest = CreateDetoastDestReceiver();
 	else
 		dest = None_Receiver;
 
@@ -606,6 +619,9 @@ ExplainOnePlan(PlannedStmt *plannedstmt, IntoClause *into, ExplainState *es,
 		/* run cleanup too */
 		ExecutorFinish(queryDesc);
 
+		/* call the dest receiver's destroy method even during explain */
+		dest->rDestroy(dest);
+
 		/* We can't run ExecutorEnd 'till we're done printing the stats... */
 		totaltime += elapsed_time(&starttime);
 	}
@@ -5052,3 +5068,116 @@ escape_yaml(StringInfo buf, const char *str)
 {
 	escape_json(buf, str);
 }
+
+
+/* ----------------
+ *		detoasting DestReceiver functions
+ * ----------------
+ */
+/* the idea is that running  EXPLAIN (ANALYZE)  sometimes gives results that
+ * are way unrealistic, since during explain there is no detoasting of
+ * values. That means you get no idea what your actual query time is going
+ * to be, nor what the actual overhead of detoasting is.
+ *
+ * if you run EXPLAIN (ANAYLZE, DETOAST) then you get an impression of
+ * what is actually happening when you use postgresql as a document-database
+ * or have large values for some other reason.
+ */
+
+typedef struct
+{
+	DestReceiver destRecevier;	     /* receiver for the tuples, that just detoasts */
+	MemoryContext memoryContext;     /* used throughout the detoasting analysis run */
+	MemoryContext oldMemoryContext;  /* restore to old when done */
+} DetoastDestReceiver;
+
+
+
+/* this method receives the tuples/records during explain (analyze, detoast)
+ * and detoasts them.
+ * this method is otherwise not called and its purpose is to detoast to
+ * make analyze optionally more realistic
+ */
+static bool
+detoastAnalyzeReceive(TupleTableSlot *slot, DestReceiver *self)
+{
+	DetoastDestReceiver *receiver = (DetoastDestReceiver*) self;
+	int i;
+	bool shouldFree = true;
+	TupleDesc tupdesc;
+	HeapTuple tuple;
+
+	receiver->oldMemoryContext = MemoryContextSwitchTo(receiver->memoryContext);
+	tupdesc  = slot->tts_tupleDescriptor;
+	tuple = ExecFetchSlotHeapTuple(slot, true, &shouldFree);
+
+	/* fill all of the slot's attributes, we can now use slot->tts_values
+	 * and its tts_isnull array which should be long enough even if added
+	 * a null-column to the table */
+	slot_getallattrs(slot);
+
+	/* iterate over all attributes of the tuple and potentially detoast them */
+	for (i = 0; i < tupdesc->natts; i++)
+	{
+		Form_pg_attribute attr;
+		char storage;
+
+		attr = TupleDescAttr(tupdesc, i);
+		storage = attr->attstorage;
+		if (!slot->tts_isnull[i] && (storage == 'e' || storage == 'x' || storage == 'm')) {
+			Datum datum = slot->tts_values[i];
+			/* here simple detoast the attribute's value, making
+			 * the explain (analyze) slower, but also more realistic
+			 * the above storage makes sure, that datum is actually
+			 * a struct varlena pointer */
+			pg_detoast_datum_packed((struct varlena *)datum);
+		}
+	}
+	if (shouldFree)
+		pfree(tuple);
+	MemoryContextSwitchTo(receiver->oldMemoryContext);
+	return true;
+}
+
+static void
+detoastAnalyzeStartup(DestReceiver *self, int operation, TupleDesc typeinfo)
+{
+	DetoastDestReceiver *receiver = (DetoastDestReceiver*) self;
+	/* memory context for our work */
+	receiver->memoryContext = AllocSetContextCreate(CurrentMemoryContext,
+		"DetoastTupleReceive", ALLOCSET_DEFAULT_SIZES);
+}
+
+static void
+detoastAnalyzeCleanup(DestReceiver *self)
+{
+	DetoastDestReceiver *receiver = (DetoastDestReceiver*) self;
+	MemoryContextDelete(receiver->memoryContext);
+}
+
+static void
+detoastAnalyzeDestroy(DestReceiver *self)
+{
+	pfree(self);
+}
+
+static DestReceiver *CreateDetoastDestReceiver(void)
+{
+	DetoastDestReceiver *self = (DetoastDestReceiver*) palloc0(sizeof(DetoastDestReceiver));
+
+	self->destRecevier.receiveSlot = detoastAnalyzeReceive;
+	self->destRecevier.rStartup = detoastAnalyzeStartup;
+	self->destRecevier.rShutdown = detoastAnalyzeCleanup;
+	self->destRecevier.rDestroy = detoastAnalyzeDestroy;
+	self->destRecevier.mydest = DestNone;
+	return (DestReceiver *) self;
+}
+
+
+/*
+static const DestReceiver detoastAnalyzeDR = {
+	detoastAnalyzeReceive, detoastAnalyzeStartup, detoastAnalyzeCleanup, detoastAnalyzeDestroy,
+	DestNone
+};
+
+*/
\ No newline at end of file
diff --git a/src/include/commands/explain.h b/src/include/commands/explain.h
index 3d3e632a0c..011dffb890 100644
--- a/src/include/commands/explain.h
+++ b/src/include/commands/explain.h
@@ -47,6 +47,8 @@ typedef struct ExplainState
 	bool		summary;		/* print total planning and execution timing */
 	bool		settings;		/* print modified settings */
 	bool		generic;		/* generate a generic plan */
+	bool		detoast;        /* detoast all toasted values, only applicable
+								   when "analyze" is active. */
 	ExplainFormat format;		/* output format */
 	/* state for output formatting --- not reset for each new plan tree */
 	int			indent;			/* current indentation level */
diff --git a/src/test/regress/expected/explain.out b/src/test/regress/expected/explain.out
index 1aca77491b..eef68d1eca 100644
--- a/src/test/regress/expected/explain.out
+++ b/src/test/regress/expected/explain.out
@@ -559,3 +559,23 @@ select explain_filter('explain (verbose) select * from int8_tbl i8');
  Query Identifier: N
 (3 rows)
 
+-- Test detoast is accepted as a parameter to explain
+-- seems hard to test the expected longer runtime of detoasting
+-- since one needs to setup enough data to make such a test stable
+-- also timing are filtered out by explain_filter anyway
+create table test_detoast(id bigserial, val text);
+select explain_filter('explain (analyze,detoast) select * from test_detoast');
+                                         explain_filter                                         
+------------------------------------------------------------------------------------------------
+ Seq Scan on test_detoast  (cost=N.N..N.N rows=N width=N) (actual time=N.N..N.N rows=N loops=N)
+ Planning Time: N.N ms
+ Execution Time: N.N ms
+(3 rows)
+
+drop table test_detoast;
+-- Test detoast is _not_ accepted as a parameter to explain unless analyze is specified
+create table test_detoast(id bigserial, val text);
+select explain_filter('explain (detoast) select * from test_detoast');
+ERROR:  EXPLAIN option DETOAST requires ANALYZE
+CONTEXT:  PL/pgSQL function explain_filter(text) line 5 at FOR over EXECUTE statement
+drop table test_detoast;
diff --git a/src/test/regress/sql/explain.sql b/src/test/regress/sql/explain.sql
index b6b7beab27..43047f9cce 100644
--- a/src/test/regress/sql/explain.sql
+++ b/src/test/regress/sql/explain.sql
@@ -154,3 +154,18 @@ select explain_filter('explain (verbose) select * from t1 where pg_temp.mysin(f1
 -- Test compute_query_id
 set compute_query_id = on;
 select explain_filter('explain (verbose) select * from int8_tbl i8');
+
+-- Test detoast is accepted as a parameter to explain
+-- seems hard to test the expected longer runtime of detoasting
+-- since one needs to setup enough data to make such a test stable
+-- also timing are filtered out by explain_filter anyway
+create table test_detoast(id bigserial, val text);
+select explain_filter('explain (analyze,detoast) select * from test_detoast');
+drop table test_detoast;
+
+-- Test detoast is _not_ accepted as a parameter to explain unless analyze is specified
+create table test_detoast(id bigserial, val text);
+select explain_filter('explain (detoast) select * from test_detoast');
+drop table test_detoast;
+
+
#4Tom Lane
tgl@sss.pgh.pa.us
In reply to: Matthias van de Meent (#2)
Re: Detoasting optionally to make Explain-Analyze less misleading

Matthias van de Meent <boekewurm+postgres@gmail.com> writes:

Hmm, maybe we should measure the overhead of serializing the tuples instead.
The difference between your patch and "serializing the tuples, but not
sending them" is that serializing also does the detoasting, but also
includes any time spent in the serialization functions of the type. So
an option "SERIALIZE" which measures all the time the server spent on
the query (except the final step of sending the bytes to the client)
would likely be more useful than "just" detoasting.

+1, that was my immediate reaction to the proposal as well. Some
output functions are far from cheap. Doing only the detoast part
seems like it's still misleading.

Do we need to go as far as offering both text-output and binary-output
options?

regards, tom lane

In reply to: stepan rutz (#3)
Re: Detoasting optionally to make Explain-Analyze less misleading

Hi Stepan & all,

On Tue, 12 Sep 2023 17:16:00 +0200
stepan rutz <stepan.rutz@gmx.de> wrote:

...

Attached a new patch. Hoping for feedback,

Nice addition to EXPLAIN!

On the feature front, what about adding the actual detoasting/serializing time
in the explain output?

That could be:

=> explain (analyze,serialize,costs off,timing off)
select * from test_detoast;
QUERY PLAN
─────────────────────────────────────────────────────────
Seq Scan on public.test_detoast (actual rows=Nv loops=N)
Planning Time: N ms
Execution Time: N ms
Serialize Time: N ms

#6stepan rutz
stepan.rutz@gmx.de
In reply to: Tom Lane (#4)
1 attachment(s)
Re: Detoasting optionally to make Explain-Analyze less misleading

Hi Tom, Hi Matthias,

you are right of course. I have looked at the code from printtup.c and
made a new version of the patch.

Thanks for the MemoryContextReset hint too (@Matthias)

This time is called  EXPLAIN(ANALYZE,SERIALIZE) (hey, it also sounds
nicer phonetically)

If the option SERIALIZE is active, the output functions are called and
they perform the detoasting, which I have even checked.

So things are better this way, however I hardcoded the output option
"Text" (format=0). In printtup.c there is an incoming array which
applies Text (format=0) or Binary (format=1) for each column
individually. I am not sure whether this is even needed. I left in the
if-statement from printtup.c which calls the binary output method of a
given type. The result of the output is ignored and apparently free'd
because of the memory-context-reset at the end.

Please also note, that I added a call to DestReceiver's rDestroy hook,
which was missing from explain.c before altogether.

Feedback is appreciated.

/Stepan

Show quoted text

On 12.09.23 17:26, Tom Lane wrote:

Matthias van de Meent <boekewurm+postgres@gmail.com> writes:

Hmm, maybe we should measure the overhead of serializing the tuples instead.
The difference between your patch and "serializing the tuples, but not
sending them" is that serializing also does the detoasting, but also
includes any time spent in the serialization functions of the type. So
an option "SERIALIZE" which measures all the time the server spent on
the query (except the final step of sending the bytes to the client)
would likely be more useful than "just" detoasting.

+1, that was my immediate reaction to the proposal as well. Some
output functions are far from cheap. Doing only the detoast part
seems like it's still misleading.

Do we need to go as far as offering both text-output and binary-output
options?

regards, tom lane

Attachments:

0003_explain_analyze_and_serialize.patchtext/x-patch; charset=UTF-8; name=0003_explain_analyze_and_serialize.patchDownload
diff --git a/src/backend/commands/explain.c b/src/backend/commands/explain.c
index 8570b14f62..dc52019a3e 100644
--- a/src/backend/commands/explain.c
+++ b/src/backend/commands/explain.c
@@ -47,7 +47,6 @@ ExplainOneQuery_hook_type ExplainOneQuery_hook = NULL;
 /* Hook for plugins to get control in explain_get_index_name() */
 explain_get_index_name_hook_type explain_get_index_name_hook = NULL;
 
-
 /* OR-able flags for ExplainXMLTag() */
 #define X_OPENING 0
 #define X_CLOSING 1
@@ -155,6 +154,8 @@ static void ExplainYAMLLineStarting(ExplainState *es);
 static void escape_yaml(StringInfo buf, const char *str);
 
 
+static DestReceiver *CreateSerializeDestReceiver(void);
+
 
 /*
  * ExplainQuery -
@@ -192,6 +193,8 @@ ExplainQuery(ParseState *pstate, ExplainStmt *stmt,
 			es->settings = defGetBoolean(opt);
 		else if (strcmp(opt->defname, "generic_plan") == 0)
 			es->generic = defGetBoolean(opt);
+		else if (strcmp(opt->defname, "serialize") == 0)
+			es->serialize = defGetBoolean(opt);
 		else if (strcmp(opt->defname, "timing") == 0)
 		{
 			timing_set = true;
@@ -244,6 +247,12 @@ ExplainQuery(ParseState *pstate, ExplainStmt *stmt,
 				(errcode(ERRCODE_INVALID_PARAMETER_VALUE),
 				 errmsg("EXPLAIN option TIMING requires ANALYZE")));
 
+	/* check that serialize is used with EXPLAIN ANALYZE */
+	if (es->serialize && !es->analyze)
+		ereport(ERROR,
+				(errcode(ERRCODE_INVALID_PARAMETER_VALUE),
+				 errmsg("EXPLAIN option SERIALIZE requires ANALYZE")));
+
 	/* check that GENERIC_PLAN is not used with EXPLAIN ANALYZE */
 	if (es->generic && es->analyze)
 		ereport(ERROR,
@@ -565,9 +574,16 @@ ExplainOnePlan(PlannedStmt *plannedstmt, IntoClause *into, ExplainState *es,
 	/*
 	 * Normally we discard the query's output, but if explaining CREATE TABLE
 	 * AS, we'd better use the appropriate tuple receiver.
+	 * Also if we choose to serialize during explain, we need to send the
+	 * tuples to a receiver that performs the serializing
+	 * which includes detoasting and the conversion of the attributes
+	 * into the protocol receiving format. The latter can also be costly
+	 * for some types
 	 */
 	if (into)
 		dest = CreateIntoRelDestReceiver(into);
+	else if (es->analyze && es->serialize)
+		dest = CreateSerializeDestReceiver();
 	else
 		dest = None_Receiver;
 
@@ -606,6 +622,9 @@ ExplainOnePlan(PlannedStmt *plannedstmt, IntoClause *into, ExplainState *es,
 		/* run cleanup too */
 		ExecutorFinish(queryDesc);
 
+		/* call the dest receiver's destroy method even during explain */
+		dest->rDestroy(dest);
+
 		/* We can't run ExecutorEnd 'till we're done printing the stats... */
 		totaltime += elapsed_time(&starttime);
 	}
@@ -5052,3 +5071,193 @@ escape_yaml(StringInfo buf, const char *str)
 {
 	escape_json(buf, str);
 }
+
+
+/* Serializing DestReceiver functions
+ *
+ * the idea is that running  EXPLAIN (ANALYZE)  sometimes gives results that
+ * are way unrealistic, since during explain there is no detoasting of
+ * values. That means you get no idea what your actual query time is going
+ * to be, nor what the actual overhead of detoasting is.
+ * 
+ * Also the output/send functions of some types may add additional overhead
+ * and need to be invoked for a realistic impression of the runtime of explain
+ *
+ * if you run EXPLAIN (ANAYLZE, SERIALIZE) then you get an impression of
+ * what is actually happening when you use postgresql as a document-database
+ * or have large values for some other reason.
+ */
+
+/* an attribute info cached for each column */
+typedef struct
+{								/* Per-attribute information */
+	Oid			typoutput;		/* Oid for the type's text output fn */
+	Oid			typsend;		/* Oid for the type's binary output fn */
+	bool		typisvarlena;	/* is it varlena (ie possibly toastable)? */
+	int16		format;			/* format code for this column */
+	FmgrInfo	finfo;			/* Precomputed call info for output fn */
+} SerializeAttrInfo;
+
+typedef struct
+{
+	/* receiver for the tuples, that just serializes */
+	DestReceiver		destRecevier;
+	MemoryContext		memoryContext;
+	MemoryContext		oldMemoryContext;	/* restore to old when done */
+	TupleDesc			attrinfo;
+	int					nattrs;
+	SerializeAttrInfo	*infos;				/* Cached info about each attr */
+} SerializeDestReceiver;
+
+/*
+ * Get the lookup info that the row-callback of the receiver needs. this code
+ * is similar to the code from printup.c except that it doesn't do any actual
+ * output.
+ */
+static void
+serialize_prepare_info(SerializeDestReceiver *receiver, TupleDesc typeinfo,
+	int nattrs)
+{
+	int i;
+
+	/* get rid of any old data */
+	if (receiver->infos)
+		pfree(receiver->infos);
+	receiver->infos = NULL;
+
+	receiver->attrinfo = typeinfo;
+	receiver->nattrs = nattrs;
+	if (nattrs <= 0)
+		return;
+
+	receiver->infos = (SerializeAttrInfo *) palloc0(
+		nattrs * sizeof(SerializeAttrInfo));
+	for (i = 0; i < nattrs; i++)
+	{
+		SerializeAttrInfo *info = &(receiver->infos[i]);
+		/* assume text output for all attributes */
+		info->format = 0;
+	}
+
+	for (i = 0; i < nattrs; i++)
+	{
+		SerializeAttrInfo *info = &(receiver->infos[i]);
+		Form_pg_attribute attr = TupleDescAttr(typeinfo, i);
+		if (info->format == 0)
+		{
+			getTypeOutputInfo(attr->atttypid,
+							  &info->typoutput,
+							  &info->typisvarlena);
+			fmgr_info(info->typoutput, &info->finfo);
+		}
+		else if (info->format == 1)
+		{
+			getTypeBinaryOutputInfo(attr->atttypid,
+									&info->typsend,
+									&info->typisvarlena);
+			fmgr_info(info->typsend, &info->finfo);
+		}
+		else
+			ereport(ERROR,
+					(errcode(ERRCODE_INVALID_PARAMETER_VALUE),
+					 errmsg("unsupported format code: %d", info->format)));
+	}
+}
+
+
+
+/* this method receives the tuples/records during explain (analyze, serialize)
+ * and serializes them.
+ * this method is otherwise not called and its purpose is to serialize to
+ * make analyze optionally more realistic. serialization includes detoasting
+ * and invoking the type's output (or send) function, which is what happens
+ * when you actually run the query. both steps can add overhead and thus
+ * analyze can be very misleading if those two steps cannot optionally be
+ * performed.
+ */
+static bool
+serializeAnalyzeReceive(TupleTableSlot *slot, DestReceiver *self)
+{
+	int i;
+	TupleDesc tupdesc;
+	SerializeDestReceiver *receiver = (SerializeDestReceiver*) self;
+
+	tupdesc  = slot->tts_tupleDescriptor;
+	/* Cache attribute infos and function oid if outdated */
+	if (receiver->attrinfo != tupdesc || receiver->nattrs != tupdesc->natts)
+		serialize_prepare_info(receiver, tupdesc, tupdesc->natts);
+
+	/* Fill all of the slot's attributes, we can now use slot->tts_values
+	 * and its tts_isnull array which should be long enough even if added
+	 * a null-column to the table */
+	slot_getallattrs(slot);
+
+	receiver->oldMemoryContext = MemoryContextSwitchTo(
+		receiver->memoryContext);
+
+	/* Iterate over all attributes of the tuple and invoke the output func
+	 * (or send function in case of a binary format). completely ignore the
+	 * result. MemoryContext is free'd via reset at the end of the this
+	 * per-tuple callback anyhow.
+	 * NOTE: when invoking the output function detoasting is implicitly
+	 * performed when needed. This adds major overhead to plain 
+	 * explain-analyze and this is what is desired here.
+	 */
+	for (i = 0; i < tupdesc->natts; i++)
+	{
+		SerializeAttrInfo *info = &(receiver->infos[i]);
+		Datum attr = slot->tts_values[i];
+		if (!slot->tts_isnull[i]) {
+			if (info->format == 0)
+			{
+				/* Text output, just ignore the result */
+				(void) OutputFunctionCall(&info->finfo, attr);
+			}
+			else
+			{
+				/* Binary output, just ignore the result */
+				(void) SendFunctionCall(&info->finfo, attr);
+			}
+		}
+	}
+	MemoryContextSwitchTo(receiver->oldMemoryContext);
+	MemoryContextReset(receiver->memoryContext);
+	return true;
+}
+
+static void
+serializeAnalyzeStartup(DestReceiver *self, int operation, TupleDesc typeinfo)
+{
+	SerializeDestReceiver *receiver = (SerializeDestReceiver*) self;
+	/* memory context for our work */
+	receiver->memoryContext = AllocSetContextCreate(CurrentMemoryContext,
+		"SerializeTupleReceive", ALLOCSET_DEFAULT_SIZES);
+}
+
+static void
+serializeAnalyzeCleanup(DestReceiver *self)
+{
+	SerializeDestReceiver *receiver = (SerializeDestReceiver*) self;
+	MemoryContextDelete(receiver->memoryContext);
+}
+
+static void
+serializeAnalyzeDestroy(DestReceiver *self)
+{
+	pfree(self);
+}
+
+static DestReceiver *CreateSerializeDestReceiver(void)
+{
+	/* Attention must palloc0 (like calloc) here, since some fields like
+	 * infos and nattrs are expected to be 0 or NULL initially */
+	SerializeDestReceiver *self = (SerializeDestReceiver*) palloc0(
+		sizeof(SerializeDestReceiver));
+
+	self->destRecevier.receiveSlot = serializeAnalyzeReceive;
+	self->destRecevier.rStartup = serializeAnalyzeStartup;
+	self->destRecevier.rShutdown = serializeAnalyzeCleanup;
+	self->destRecevier.rDestroy = serializeAnalyzeDestroy;
+	self->destRecevier.mydest = DestNone;
+	return (DestReceiver *) self;
+}
diff --git a/src/include/commands/explain.h b/src/include/commands/explain.h
index 3d3e632a0c..5321a7f0a1 100644
--- a/src/include/commands/explain.h
+++ b/src/include/commands/explain.h
@@ -47,6 +47,14 @@ typedef struct ExplainState
 	bool		summary;		/* print total planning and execution timing */
 	bool		settings;		/* print modified settings */
 	bool		generic;		/* generate a generic plan */
+	bool		serialize;      /* serialize all values, only applicable
+								 * when "analyze" is active. serializing
+								 * invokes the type's output function in
+								 * the same way printtup.c does then tuples
+								 * are send to the client. this includes
+								 * detoasting of toasted values and makes
+								 * EXPLAIN(ANALYZE,SERIALIZE) return realistic
+								 * (longer runtimes */
 	ExplainFormat format;		/* output format */
 	/* state for output formatting --- not reset for each new plan tree */
 	int			indent;			/* current indentation level */
diff --git a/src/test/regress/expected/explain.out b/src/test/regress/expected/explain.out
index 1aca77491b..f7a09f3932 100644
--- a/src/test/regress/expected/explain.out
+++ b/src/test/regress/expected/explain.out
@@ -559,3 +559,23 @@ select explain_filter('explain (verbose) select * from int8_tbl i8');
  Query Identifier: N
 (3 rows)
 
+-- Test that SERIALIZABLE is accepted as a parameter to explain
+-- seems hard to test the expected longer runtime of serialize
+-- since one needs to setup enough data to make such a test stable
+-- also timing are filtered out by explain_filter anyway
+create table test_serialize(id bigserial, val text);
+select explain_filter('explain (analyze,serialize) select * from test_serialize');
+                                          explain_filter                                          
+--------------------------------------------------------------------------------------------------
+ Seq Scan on test_serialize  (cost=N.N..N.N rows=N width=N) (actual time=N.N..N.N rows=N loops=N)
+ Planning Time: N.N ms
+ Execution Time: N.N ms
+(3 rows)
+
+drop table test_serialize;
+-- Test SERIALIZE is _not_ accepted as a parameter to explain unless ANALYZE is specified
+create table test_serialize(id bigserial, val text);
+select explain_filter('explain (serialize) select * from test_serialize');
+ERROR:  EXPLAIN option SERIALIZE requires ANALYZE
+CONTEXT:  PL/pgSQL function explain_filter(text) line 5 at FOR over EXECUTE statement
+drop table test_serialize;
diff --git a/src/test/regress/sql/explain.sql b/src/test/regress/sql/explain.sql
index b6b7beab27..823770d546 100644
--- a/src/test/regress/sql/explain.sql
+++ b/src/test/regress/sql/explain.sql
@@ -154,3 +154,18 @@ select explain_filter('explain (verbose) select * from t1 where pg_temp.mysin(f1
 -- Test compute_query_id
 set compute_query_id = on;
 select explain_filter('explain (verbose) select * from int8_tbl i8');
+
+-- Test that SERIALIZABLE is accepted as a parameter to explain
+-- seems hard to test the expected longer runtime of serialize
+-- since one needs to setup enough data to make such a test stable
+-- also timing are filtered out by explain_filter anyway
+create table test_serialize(id bigserial, val text);
+select explain_filter('explain (analyze,serialize) select * from test_serialize');
+drop table test_serialize;
+
+-- Test SERIALIZE is _not_ accepted as a parameter to explain unless ANALYZE is specified
+create table test_serialize(id bigserial, val text);
+select explain_filter('explain (serialize) select * from test_serialize');
+drop table test_serialize;
+
+
#7stepan rutz
stepan.rutz@gmx.de
In reply to: stepan rutz (#6)
1 attachment(s)
Re: Detoasting optionally to make Explain-Analyze less misleading

Hi,

please see a revised version yesterday's mail. The patch attached now
provides the following:

EXPLAIN(ANALYZE,SERIALIZE)

and

EXPLAIN(ANALYZE,SERIALIZEBINARY)

and timing output.

Both options perform the serialization during analyze and provide an
additional output in the plan like this:

template1=# explain (analyze,serialize) select * from t12 limit 1;
                                              QUERY PLAN
-------------------------------------------------------------------------------------------------------

 ...

 Serialized Bytes: 36 bytes
 Execution Time: 0.035 ms
(5 rows)

or also this

template1=# explain (analyze,serialize) select * from t1;
                                         QUERY PLAN
---------------------------------------------------------------------------------------------
 Seq Scan on t1  (cost=0.00..1.02 rows=2 width=19) (actual
time=0.101..0.111 rows=5 loops=1)
 Planning Time: 0.850 ms
 Serialized Bytes: 85777978 bytes
 Execution Time: 354.284 ms
(4 rows)

Its tempting to divide Serialized-Bytes by Execution-Time to get an idea
of the serialization bandwidth. This is /dev/null serialization though.
The results are length-counted and then discarded.

Since detoasting happens implicitly during serialization, the number of
bytes becomes huge in this case and accounts for the detoasted lengths
as well. I tried to get the number of bytes send for the protocol's
messages and the attribute headers correctly. For the actual values I am
quite sure I get the correct measures, as one can really tell by sending
more values across. Null is 4 bytes on the wire interestingly. I didn't
know that, but it makes sense, since its using the same prefix
length-field as all values do.

I have checked the JBDC driver and it uses binary and text formats
depending on an attribute's type oid. So having the SERIALIZEBINARY
option is not accurate, as in reality both formats can be occur for the
same tuple.

Please provide some feedback on the new patch and let me know if this
makes sense. In general this kind of option for EXPLAIN is a good thing
for sure.

Greetings,

Stepan

Show quoted text

On 14.09.23 21:27, stepan rutz wrote:

Hi Tom, Hi Matthias,

you are right of course. I have looked at the code from printtup.c and
made a new version of the patch.

Thanks for the MemoryContextReset hint too (@Matthias)

This time is called  EXPLAIN(ANALYZE,SERIALIZE) (hey, it also sounds
nicer phonetically)

If the option SERIALIZE is active, the output functions are called and
they perform the detoasting, which I have even checked.

So things are better this way, however I hardcoded the output option
"Text" (format=0). In printtup.c there is an incoming array which
applies Text (format=0) or Binary (format=1) for each column
individually. I am not sure whether this is even needed. I left in the
if-statement from printtup.c which calls the binary output method of a
given type. The result of the output is ignored and apparently free'd
because of the memory-context-reset at the end.

Please also note, that I added a call to DestReceiver's rDestroy hook,
which was missing from explain.c before altogether.

Feedback is appreciated.

/Stepan

On 12.09.23 17:26, Tom Lane wrote:

Matthias van de Meent <boekewurm+postgres@gmail.com> writes:

Hmm, maybe we should measure the overhead of serializing the tuples
instead.
The difference between your patch and "serializing the tuples, but not
sending them" is that serializing also does the detoasting, but also
includes any time spent in the serialization functions of the type. So
an option "SERIALIZE" which measures all the time the server spent on
the query (except the final step of sending the bytes to the client)
would likely be more useful than "just" detoasting.

+1, that was my immediate reaction to the proposal as well. Some
output functions are far from cheap.  Doing only the detoast part
seems like it's still misleading.

Do we need to go as far as offering both text-output and binary-output
options?

            regards, tom lane

Attachments:

0004_explain_analyze_and_serialize.patchtext/x-patch; charset=UTF-8; name=0004_explain_analyze_and_serialize.patchDownload
diff --git a/src/backend/commands/explain.c b/src/backend/commands/explain.c
index 8570b14f62..9090e0f114 100644
--- a/src/backend/commands/explain.c
+++ b/src/backend/commands/explain.c
@@ -26,6 +26,7 @@
 #include "nodes/nodeFuncs.h"
 #include "parser/analyze.h"
 #include "parser/parsetree.h"
+#include "mb/pg_wchar.h"
 #include "rewrite/rewriteHandler.h"
 #include "storage/bufmgr.h"
 #include "tcop/tcopprot.h"
@@ -47,7 +48,6 @@ ExplainOneQuery_hook_type ExplainOneQuery_hook = NULL;
 /* Hook for plugins to get control in explain_get_index_name() */
 explain_get_index_name_hook_type explain_get_index_name_hook = NULL;
 
-
 /* OR-able flags for ExplainXMLTag() */
 #define X_OPENING 0
 #define X_CLOSING 1
@@ -154,7 +154,8 @@ static void ExplainJSONLineEnding(ExplainState *es);
 static void ExplainYAMLLineStarting(ExplainState *es);
 static void escape_yaml(StringInfo buf, const char *str);
 
-
+static DestReceiver *CreateSerializeDestReceiver(int16 format);
+static uint64 GetNumberOfSerializedBytes(DestReceiver *dest);
 
 /*
  * ExplainQuery -
@@ -192,6 +193,12 @@ ExplainQuery(ParseState *pstate, ExplainStmt *stmt,
 			es->settings = defGetBoolean(opt);
 		else if (strcmp(opt->defname, "generic_plan") == 0)
 			es->generic = defGetBoolean(opt);
+		else if (strcmp(opt->defname, "serialize") == 0)
+			es->serialize = defGetBoolean(opt);
+		else if (strcmp(opt->defname, "serializebinary") == 0)
+		{
+			es->serialize = es->serializebinary = defGetBoolean(opt);
+		}
 		else if (strcmp(opt->defname, "timing") == 0)
 		{
 			timing_set = true;
@@ -244,6 +251,17 @@ ExplainQuery(ParseState *pstate, ExplainStmt *stmt,
 				(errcode(ERRCODE_INVALID_PARAMETER_VALUE),
 				 errmsg("EXPLAIN option TIMING requires ANALYZE")));
 
+	/* check that serializebinary is used with EXPLAIN ANALYZE */
+	if (es->serializebinary && !es->analyze)
+		ereport(ERROR,
+				(errcode(ERRCODE_INVALID_PARAMETER_VALUE),
+				 errmsg("EXPLAIN option SERIALIZEBINARY requires ANALYZE")));
+	/* check that serialize is used with EXPLAIN ANALYZE */
+	else if (es->serialize && !es->analyze)
+		ereport(ERROR,
+				(errcode(ERRCODE_INVALID_PARAMETER_VALUE),
+				 errmsg("EXPLAIN option SERIALIZE requires ANALYZE")));
+
 	/* check that GENERIC_PLAN is not used with EXPLAIN ANALYZE */
 	if (es->generic && es->analyze)
 		ereport(ERROR,
@@ -535,6 +553,7 @@ ExplainOnePlan(PlannedStmt *plannedstmt, IntoClause *into, ExplainState *es,
 	double		totaltime = 0;
 	int			eflags;
 	int			instrument_option = 0;
+	uint64		bytesSend = 0;
 
 	Assert(plannedstmt->commandType != CMD_UTILITY);
 
@@ -565,9 +584,15 @@ ExplainOnePlan(PlannedStmt *plannedstmt, IntoClause *into, ExplainState *es,
 	/*
 	 * Normally we discard the query's output, but if explaining CREATE TABLE
 	 * AS, we'd better use the appropriate tuple receiver.
+	 * Also if we choose to serialize during explain, we need to send the
+	 * tuples to a dest-receiver that performs serializing
+	 * into the protocol receiving format. this implicitly also detoasts
+	 * values.
 	 */
 	if (into)
 		dest = CreateIntoRelDestReceiver(into);
+	else if (es->analyze && es->serialize)
+		dest = CreateSerializeDestReceiver(es->serializebinary ? 1 : 0);
 	else
 		dest = None_Receiver;
 
@@ -606,6 +631,15 @@ ExplainOnePlan(PlannedStmt *plannedstmt, IntoClause *into, ExplainState *es,
 		/* run cleanup too */
 		ExecutorFinish(queryDesc);
 
+		if (es->serialize)
+		{
+			bytesSend = GetNumberOfSerializedBytes(dest);
+		}
+
+
+		/* call the dest receiver's destroy method even during explain */
+		dest->rDestroy(dest);
+
 		/* We can't run ExecutorEnd 'till we're done printing the stats... */
 		totaltime += elapsed_time(&starttime);
 	}
@@ -643,6 +677,11 @@ ExplainOnePlan(PlannedStmt *plannedstmt, IntoClause *into, ExplainState *es,
 	if (es->costs)
 		ExplainPrintJITSummary(es, queryDesc);
 
+	if (es->analyze && es->serialize)
+	{
+		ExplainPropertyUInteger("Serialized Bytes", "bytes", bytesSend, es);
+	}
+
 	/*
 	 * Close down the query and free resources.  Include time for this in the
 	 * total execution time (although it should be pretty minimal).
@@ -5052,3 +5091,239 @@ escape_yaml(StringInfo buf, const char *str)
 {
 	escape_json(buf, str);
 }
+
+
+/* Serializing DestReceiver functions
+ *
+ * EXPLAIN (ANALYZE)  sometimes gives results that unrealistic.
+ * During EXPLAIN(ANALYZE) there is no detoasting of values.
+ * That means you get no idea what your actual query time is going
+ * to be, nor what the actual overhead of detoasting is.
+ *
+ * EXPLAIN (ANAYLZE, SERIALIZE) will perform detoasting implicitly and
+ * will also do count the number of bytes being send to the client but
+ * will not actually send them. SERIALIZE uses text format for all
+ * attributes.
+ *
+ * EXPLAIN (ANAYLZE, SERIALIZEBINARY) serializes using binary format.
+ */
+
+/* an attribute info cached for each column */
+typedef struct
+{								/* Per-attribute information */
+	Oid			typoutput;		/* Oid for the type's text output fn */
+	Oid			typsend;		/* Oid for the type's binary output fn */
+	bool		typisvarlena;	/* is it varlena (ie possibly toastable)? */
+	int16		format;			/* format code for this column */
+	FmgrInfo	finfo;			/* Precomputed call info for output fn */
+} SerializeAttrInfo;
+
+typedef struct
+{
+	/* receiver for the tuples, that just serializes */
+	DestReceiver		destRecevier;
+	MemoryContext		memoryContext;
+	MemoryContext		oldMemoryContext;	/* restore to old when done */
+	int16				format;				/* text of binary */
+	TupleDesc			attrinfo;
+	int					nattrs;
+	uint64				bytesSend;			/* Num of bytes over the wire */
+	SerializeAttrInfo	*infos;				/* Cached info about each attr */
+} SerializeDestReceiver;
+
+/*
+ * Get the lookup info that the row-callback of the receiver needs. this code
+ * is similar to the code from printup.c except that it doesn't do any actual
+ * output.
+ */
+static void
+serialize_prepare_info(SerializeDestReceiver *receiver, TupleDesc typeinfo,
+	int nattrs)
+{
+	int i;
+
+	/* get rid of any old data */
+	if (receiver->infos)
+		pfree(receiver->infos);
+	receiver->infos = NULL;
+
+	receiver->attrinfo = typeinfo;
+	receiver->nattrs = nattrs;
+	if (nattrs <= 0)
+		return;
+
+	receiver->infos = (SerializeAttrInfo *) palloc0(
+		nattrs * sizeof(SerializeAttrInfo));
+	for (i = 0; i < nattrs; i++)
+	{
+		SerializeAttrInfo *info = &(receiver->infos[i]);
+		Form_pg_attribute attr = TupleDescAttr(typeinfo, i);
+		info->format = receiver->format;
+		if (info->format == 0)
+		{
+			getTypeOutputInfo(attr->atttypid,
+							  &info->typoutput,
+							  &info->typisvarlena);
+			fmgr_info(info->typoutput, &info->finfo);
+		}
+		else if (info->format == 1)
+		{
+			getTypeBinaryOutputInfo(attr->atttypid,
+									&info->typsend,
+									&info->typisvarlena);
+			fmgr_info(info->typsend, &info->finfo);
+		}
+		else
+			ereport(ERROR,
+					(errcode(ERRCODE_INVALID_PARAMETER_VALUE),
+					 errmsg("unsupported format code: %d", info->format)));
+	}
+}
+
+
+
+/* this method receives the tuples/records during explain (analyze, serialize)
+ * and serializes them.
+ * this method is otherwise not called and its purpose is to serialize to
+ * make analyze optionally more realistic. serialization includes detoasting
+ * and invoking the type's output (or send) function, which is what happens
+ * when you actually run the query. both steps cost time and thus
+ * analyze can be very misleading if those two steps are omitted.
+ */
+static bool
+serializeAnalyzeReceive(TupleTableSlot *slot, DestReceiver *self)
+{
+	int i;
+	TupleDesc tupdesc;
+	SerializeDestReceiver *receiver = (SerializeDestReceiver*) self;
+
+	tupdesc  = slot->tts_tupleDescriptor;
+	/* Cache attribute infos and function oid if outdated */
+	if (receiver->attrinfo != tupdesc || receiver->nattrs != tupdesc->natts)
+	{
+		serialize_prepare_info(receiver, tupdesc, tupdesc->natts);
+	}
+
+	/* Fill all of the slot's attributes, we can now use slot->tts_values
+	 * and its tts_isnull array which should be long enough even if added
+	 * a null-column to the table */
+	slot_getallattrs(slot);
+
+	receiver->oldMemoryContext = MemoryContextSwitchTo(
+		receiver->memoryContext);
+
+	/* Iterate over all attributes of the tuple and invoke the output func
+	 * (or send function in case of a binary format). completely ignore the
+	 * result. MemoryContext is free'd via reset at the end of the this
+	 * per-tuple callback anyhow.
+	 * NOTE: when invoking the output function detoasting is implicitly
+	 * performed when needed. This adds major overhead to plain 
+	 * explain-analyze and this is what is desired here.
+	 */
+
+	receiver->bytesSend += 3; /* protocol message type and attribute-count */
+	for (i = 0; i < tupdesc->natts; i++)
+	{
+		SerializeAttrInfo *info = &(receiver->infos[i]);
+		Datum attr = slot->tts_values[i];
+		if (slot->tts_isnull[i])
+		{
+			receiver->bytesSend += 4; /* null is send as -1 length */
+		}
+		else
+		{
+			if (info->format == 0)
+			{
+				/* Text output, ignore the result but count it */
+				char* output = OutputFunctionCall(&info->finfo, attr);
+				size_t outputlen = strlen(output);
+				/* convert from server encoding to client encoding if needed */
+				char *converted = pg_server_to_client(output, outputlen);
+				if (converted != output)
+				{
+					/* converted encoding, get new length */
+					outputlen = strlen(converted);
+					pfree(converted);
+				}
+				/* append length that would have gone over the wire, 4
+				 * the number of preceding bytes that contain the length */
+				receiver->bytesSend += 4 + outputlen;
+			}
+			else
+			{
+				/* Binary output, ignore the result but count it
+				 * length is included in varsize */
+				bytea* bytes = SendFunctionCall(&info->finfo, attr);
+				uint64 n = VARSIZE(bytes);
+				receiver->bytesSend += n;
+			}
+		}
+	}
+	MemoryContextSwitchTo(receiver->oldMemoryContext);
+	MemoryContextReset(receiver->memoryContext);
+	return true;
+}
+
+static void
+serializeAnalyzeStartup(DestReceiver *self, int operation, TupleDesc typeinfo)
+{
+	SerializeDestReceiver *receiver = (SerializeDestReceiver*) self;
+	int i;
+	/* memory context for our work */
+	receiver->memoryContext = AllocSetContextCreate(CurrentMemoryContext,
+		"SerializeTupleReceive", ALLOCSET_DEFAULT_SIZES);
+
+	/* account for the attribute headers for send bytes */
+	receiver->bytesSend += 3; /* protocol message type and attribute-count */
+	for (i = 0; i < typeinfo->natts; ++i)
+	{
+		Form_pg_attribute att = TupleDescAttr(typeinfo, i);
+		char* name = NameStr(att->attname);
+		size_t namelen = strlen(name);
+		/* convert from server encoding to client encoding if needed */
+		char *converted = pg_server_to_client(name, namelen);
+		if (converted != name)
+		{
+			namelen = strlen(converted);
+			pfree(converted);
+		}
+		/* see printtup.h why we add 18 bytes here. These are the infos
+		 * needed for each attribute plus the attributes's name */
+		receiver->bytesSend += namelen + 1 + 18;
+	}
+}
+
+static void
+serializeAnalyzeCleanup(DestReceiver *self)
+{
+	SerializeDestReceiver *receiver = (SerializeDestReceiver*) self;
+	MemoryContextDelete(receiver->memoryContext);
+}
+
+static void
+serializeAnalyzeDestroy(DestReceiver *self)
+{
+	pfree(self);
+}
+
+/* format is either 0 (text) or 1 (binary) */
+static DestReceiver *CreateSerializeDestReceiver(int16 format)
+{
+	/* Attention must palloc0 (like calloc) here.
+	 * infos and nattrs are expected to be 0 or NULL initially */
+	SerializeDestReceiver *self = (SerializeDestReceiver*) palloc0(
+		sizeof(SerializeDestReceiver));
+	self->destRecevier.receiveSlot = serializeAnalyzeReceive;
+	self->destRecevier.rStartup = serializeAnalyzeStartup;
+	self->destRecevier.rShutdown = serializeAnalyzeCleanup;
+	self->destRecevier.rDestroy = serializeAnalyzeDestroy;
+	self->destRecevier.mydest = DestNone;
+	self->format = format;
+	return (DestReceiver *) self;
+}
+
+static uint64 GetNumberOfSerializedBytes(DestReceiver *dest)
+{
+	SerializeDestReceiver *receiver = (SerializeDestReceiver*) dest;
+	return receiver->bytesSend;
+}
diff --git a/src/include/commands/explain.h b/src/include/commands/explain.h
index 3d3e632a0c..777c7578cc 100644
--- a/src/include/commands/explain.h
+++ b/src/include/commands/explain.h
@@ -47,6 +47,16 @@ typedef struct ExplainState
 	bool		summary;		/* print total planning and execution timing */
 	bool		settings;		/* print modified settings */
 	bool		generic;		/* generate a generic plan */
+	bool		serialize;      /* serialize all values, only applicable
+								 * when "analyze" is active. serializing
+								 * invokes the type's output function in
+								 * the same way printtup.c does then tuples
+								 * are send to the client. this includes
+								 * detoasting of toasted values and makes
+								 * EXPLAIN(ANALYZE,SERIALIZE) return realistic
+								 * (longer runtimes */
+	bool		serializebinary;/* serialize in binary format */
+
 	ExplainFormat format;		/* output format */
 	/* state for output formatting --- not reset for each new plan tree */
 	int			indent;			/* current indentation level */
diff --git a/src/test/regress/expected/explain.out b/src/test/regress/expected/explain.out
index 1aca77491b..76e8932a7c 100644
--- a/src/test/regress/expected/explain.out
+++ b/src/test/regress/expected/explain.out
@@ -559,3 +559,40 @@ select explain_filter('explain (verbose) select * from int8_tbl i8');
  Query Identifier: N
 (3 rows)
 
+-- Test that SERIALIZE is accepted as a parameter to explain
+-- timings are filtered out by explain_filter
+create table test_serialize(id bigserial, val text);
+select explain_filter('explain (analyze,serialize) select * from test_serialize');
+                                          explain_filter                                          
+--------------------------------------------------------------------------------------------------
+ Seq Scan on test_serialize  (cost=N.N..N.N rows=N width=N) (actual time=N.N..N.N rows=N loops=N)
+ Planning Time: N.N ms
+ Serialized Bytes: N bytes
+ Execution Time: N.N ms
+(4 rows)
+
+drop table test_serialize;
+-- Test that SERIALIZEBINARY is accepted as a parameter to explain
+create table test_serialize(id bigserial, val text);
+select explain_filter('explain (analyze,serializebinary) select * from test_serialize');
+                                          explain_filter                                          
+--------------------------------------------------------------------------------------------------
+ Seq Scan on test_serialize  (cost=N.N..N.N rows=N width=N) (actual time=N.N..N.N rows=N loops=N)
+ Planning Time: N.N ms
+ Serialized Bytes: N bytes
+ Execution Time: N.N ms
+(4 rows)
+
+drop table test_serialize;
+-- Test SERIALIZE is _not_ accepted as a parameter to explain unless ANALYZE is specified
+create table test_serialize(id bigserial, val text);
+select explain_filter('explain (serialize) select * from test_serialize');
+ERROR:  EXPLAIN option SERIALIZE requires ANALYZE
+CONTEXT:  PL/pgSQL function explain_filter(text) line 5 at FOR over EXECUTE statement
+drop table test_serialize;
+-- Test SERIALIZEBINARY is _not_ accepted as a parameter to explain unless ANALYZE is specified
+create table test_serialize(id bigserial, val text);
+select explain_filter('explain (serializebinary) select * from test_serialize');
+ERROR:  EXPLAIN option SERIALIZEBINARY requires ANALYZE
+CONTEXT:  PL/pgSQL function explain_filter(text) line 5 at FOR over EXECUTE statement
+drop table test_serialize;
diff --git a/src/test/regress/sql/explain.sql b/src/test/regress/sql/explain.sql
index b6b7beab27..bdabc0c36e 100644
--- a/src/test/regress/sql/explain.sql
+++ b/src/test/regress/sql/explain.sql
@@ -154,3 +154,26 @@ select explain_filter('explain (verbose) select * from t1 where pg_temp.mysin(f1
 -- Test compute_query_id
 set compute_query_id = on;
 select explain_filter('explain (verbose) select * from int8_tbl i8');
+
+-- Test that SERIALIZE is accepted as a parameter to explain
+-- timings are filtered out by explain_filter
+create table test_serialize(id bigserial, val text);
+select explain_filter('explain (analyze,serialize) select * from test_serialize');
+drop table test_serialize;
+
+-- Test that SERIALIZEBINARY is accepted as a parameter to explain
+create table test_serialize(id bigserial, val text);
+select explain_filter('explain (analyze,serializebinary) select * from test_serialize');
+drop table test_serialize;
+
+-- Test SERIALIZE is _not_ accepted as a parameter to explain unless ANALYZE is specified
+create table test_serialize(id bigserial, val text);
+select explain_filter('explain (serialize) select * from test_serialize');
+drop table test_serialize;
+
+-- Test SERIALIZEBINARY is _not_ accepted as a parameter to explain unless ANALYZE is specified
+create table test_serialize(id bigserial, val text);
+select explain_filter('explain (serializebinary) select * from test_serialize');
+drop table test_serialize;
+
+
#8Tomas Vondra
tomas.vondra@enterprisedb.com
In reply to: stepan rutz (#7)
Re: Detoasting optionally to make Explain-Analyze less misleading

Hi,

On 9/15/23 22:09, stepan rutz wrote:

Hi,

please see a revised version yesterday's mail. The patch attached now
provides the following:

EXPLAIN(ANALYZE,SERIALIZE)

and

EXPLAIN(ANALYZE,SERIALIZEBINARY)

I haven't looked at the patch in detail yet, but this option name looks
a bit strange/inconsistent. Either it should be SERIALIZE_BINARY (to
match other multi-word options), or maybe there should be just SERIALIZE
with a parameter to determine text/binary (like FORMAT, for example).

So we'd do either

EXPLAIN (SERIALIZE)
EXPLAIN (SERIALIZE TEXT)

to get serialization to text (which I guess 99% of people will do), or

EXPLAIN (SERIALIZE BINARY)

to get binary.

regards

--
Tomas Vondra
EnterpriseDB: http://www.enterprisedb.com
The Enterprise PostgreSQL Company

#9stepan rutz
stepan.rutz@gmx.de
In reply to: Tomas Vondra (#8)
1 attachment(s)
Re: Detoasting optionally to make Explain-Analyze less misleading

Hi Thomas,

you are right of course. Thanks!

I have attached a new version of the patch that supports the syntax like
suggested. The previous patch was insonsistent in style indeed.

explain (analyze, serialize)

and

explain (analyze, serialize binary)

That doesn't make too much of a difference for most scenarios I am
certain. However the the seralize option itself does. Mostly because it
performs the detoasting and that was a trap for me in the past with just
plain analyze.

Eg this scenario really is not too far fetched in a world where people
have large JSONB values.

db1=# create table test(id bigint, val text);

db1=# insert into test(val) select string_agg(s::text, ',') from (select
generate_series(1, 10_000_000) as s) as a1;

now we have a cell that has roughly 80Mb in it. A large detoasting that
will happen in reallife but in explain(analyze).

and then...

db1=# explain (analyze) select * from test;
                                            QUERY PLAN
---------------------------------------------------------------------------------------------------
 Seq Scan on test  (cost=0.00..22.00 rows=1200 width=40) (actual
time=0.018..0.020 rows=1 loops=1)
 Planning Time: 0.085 ms
 Execution Time: 0.044 ms
(3 rows)

db1=# explain (analyze, serialize) select * from test;
                                            QUERY PLAN
---------------------------------------------------------------------------------------------------
 Seq Scan on test  (cost=0.00..22.00 rows=1200 width=40) (actual
time=0.023..0.027 rows=1 loops=1)
 Planning Time: 0.077 ms
 Execution Time: 303.281 ms
 Serialized Bytes: 78888953 Bytes. Mode Text. Bandwidth 248.068 MB/sec
(4 rows)

db1=#

So the explain(analyze) does not process the ~80 MB in 0.044ms in any
way of course.

Actually I could print the serialized bytes using 1. grouping-separators
(eg 78_888_953) or 2. in the way pg_size_pretty does it.

If doing it the pg_size_pretty way I am uncertain if it would be ok to
query the actual pg_size_pretty function via its (certainly frozen) oid
of 3166 and do OidFunctionCall1(3166...) to invoke it. Otherwise I'd say
it would be nice if the code from that function would be made available
as a utility function for all c-code.  Any suggestions on this topic?

Regards,

/Stepan

Show quoted text

On 02.11.23 18:49, Tomas Vondra wrote:

Hi,

On 9/15/23 22:09, stepan rutz wrote:

Hi,

please see a revised version yesterday's mail. The patch attached now
provides the following:

EXPLAIN(ANALYZE,SERIALIZE)

and

EXPLAIN(ANALYZE,SERIALIZEBINARY)

I haven't looked at the patch in detail yet, but this option name looks
a bit strange/inconsistent. Either it should be SERIALIZE_BINARY (to
match other multi-word options), or maybe there should be just SERIALIZE
with a parameter to determine text/binary (like FORMAT, for example).

So we'd do either

EXPLAIN (SERIALIZE)
EXPLAIN (SERIALIZE TEXT)

to get serialization to text (which I guess 99% of people will do), or

EXPLAIN (SERIALIZE BINARY)

to get binary.

regards

Attachments:

0006_explain_analyze_and_serialize.patchtext/x-patch; charset=UTF-8; name=0006_explain_analyze_and_serialize.patchDownload
diff --git a/src/backend/commands/explain.c b/src/backend/commands/explain.c
index f1d71bc54e..bb75ac0b73 100644
--- a/src/backend/commands/explain.c
+++ b/src/backend/commands/explain.c
@@ -26,6 +26,7 @@
 #include "nodes/nodeFuncs.h"
 #include "parser/analyze.h"
 #include "parser/parsetree.h"
+#include "mb/pg_wchar.h"
 #include "rewrite/rewriteHandler.h"
 #include "storage/bufmgr.h"
 #include "tcop/tcopprot.h"
@@ -33,6 +34,7 @@
 #include "utils/guc_tables.h"
 #include "utils/json.h"
 #include "utils/lsyscache.h"
+#include "utils/numeric.h"
 #include "utils/rel.h"
 #include "utils/ruleutils.h"
 #include "utils/snapmgr.h"
@@ -47,7 +49,6 @@ ExplainOneQuery_hook_type ExplainOneQuery_hook = NULL;
 /* Hook for plugins to get control in explain_get_index_name() */
 explain_get_index_name_hook_type explain_get_index_name_hook = NULL;
 
-
 /* OR-able flags for ExplainXMLTag() */
 #define X_OPENING 0
 #define X_CLOSING 1
@@ -154,7 +155,8 @@ static void ExplainJSONLineEnding(ExplainState *es);
 static void ExplainYAMLLineStarting(ExplainState *es);
 static void escape_yaml(StringInfo buf, const char *str);
 
-
+static DestReceiver *CreateSerializeDestReceiver(int16 format);
+static uint64 GetNumberOfSerializedBytes(DestReceiver *dest);
 
 /*
  * ExplainQuery -
@@ -192,6 +194,23 @@ ExplainQuery(ParseState *pstate, ExplainStmt *stmt,
 			es->settings = defGetBoolean(opt);
 		else if (strcmp(opt->defname, "generic_plan") == 0)
 			es->generic = defGetBoolean(opt);
+		else if (strcmp(opt->defname, "serialize") == 0)
+		{
+			es->serialize = true;
+			/* optionally check for BINARY as argument */
+			if (opt->arg)
+			{
+				char *p = defGetString(opt);
+				if (strcmp(p, "binary") == 0)
+					es->serialize = es->serializebinary = true;
+				else
+					ereport(ERROR,
+						(errcode(ERRCODE_INVALID_PARAMETER_VALUE),
+						 errmsg("unrecognized value for EXPLAIN option \"%s\": \"%s\"",
+								opt->defname, p),
+						 parser_errposition(pstate, opt->location)));
+			}
+		}
 		else if (strcmp(opt->defname, "timing") == 0)
 		{
 			timing_set = true;
@@ -244,6 +263,12 @@ ExplainQuery(ParseState *pstate, ExplainStmt *stmt,
 				(errcode(ERRCODE_INVALID_PARAMETER_VALUE),
 				 errmsg("EXPLAIN option TIMING requires ANALYZE")));
 
+	/* check that serialize is used with EXPLAIN ANALYZE */
+	if (es->serialize && !es->analyze)
+		ereport(ERROR,
+				(errcode(ERRCODE_INVALID_PARAMETER_VALUE),
+				 errmsg("EXPLAIN option SERIALIZE requires ANALYZE")));
+
 	/* check that GENERIC_PLAN is not used with EXPLAIN ANALYZE */
 	if (es->generic && es->analyze)
 		ereport(ERROR,
@@ -535,6 +560,7 @@ ExplainOnePlan(PlannedStmt *plannedstmt, IntoClause *into, ExplainState *es,
 	double		totaltime = 0;
 	int			eflags;
 	int			instrument_option = 0;
+	int64		bytesSend = 0;
 
 	Assert(plannedstmt->commandType != CMD_UTILITY);
 
@@ -565,9 +591,15 @@ ExplainOnePlan(PlannedStmt *plannedstmt, IntoClause *into, ExplainState *es,
 	/*
 	 * Normally we discard the query's output, but if explaining CREATE TABLE
 	 * AS, we'd better use the appropriate tuple receiver.
+	 * Also if we choose to serialize during explain, we need to send the
+	 * tuples to a dest-receiver that performs serializing
+	 * into the protocol receiving format. this implicitly also detoasts
+	 * values.
 	 */
 	if (into)
 		dest = CreateIntoRelDestReceiver(into);
+	else if (es->analyze && es->serialize)
+		dest = CreateSerializeDestReceiver(es->serializebinary ? 1 : 0);
 	else
 		dest = None_Receiver;
 
@@ -606,6 +638,15 @@ ExplainOnePlan(PlannedStmt *plannedstmt, IntoClause *into, ExplainState *es,
 		/* run cleanup too */
 		ExecutorFinish(queryDesc);
 
+		if (es->serialize)
+		{
+			bytesSend = GetNumberOfSerializedBytes(dest);
+		}
+
+
+		/* call the dest receiver's destroy method even during explain */
+		dest->rDestroy(dest);
+
 		/* We can't run ExecutorEnd 'till we're done printing the stats... */
 		totaltime += elapsed_time(&starttime);
 	}
@@ -671,6 +712,18 @@ ExplainOnePlan(PlannedStmt *plannedstmt, IntoClause *into, ExplainState *es,
 		ExplainPropertyFloat("Execution Time", "ms", 1000.0 * totaltime, 3,
 							 es);
 
+	/* Print info about serialization of data */
+	if (es->summary && es->analyze && es->serialize)
+	{
+		char *outputbuf;
+		outputbuf = psprintf("%ld Bytes. Mode %s. Bandwidth %.3f MB/sec",
+			bytesSend,
+			es->serializebinary ? "Binary" : "Text",
+			bytesSend / 1024.0 / 1024.0 / totaltime);
+		ExplainPropertyText("Serialized Bytes", outputbuf, es);
+		pfree(outputbuf);
+	}
+
 	ExplainCloseGroup("Query", NULL, true, es);
 }
 
@@ -5082,3 +5135,238 @@ escape_yaml(StringInfo buf, const char *str)
 {
 	escape_json(buf, str);
 }
+
+
+/* Serializing DestReceiver functions
+ *
+ * EXPLAIN (ANALYZE)  sometimes gives results that unrealistic.
+ * During EXPLAIN(ANALYZE) there is no detoasting of values.
+ * That means you get no idea what your actual query time is going
+ * to be, nor what the actual overhead of detoasting is.
+ *
+ * EXPLAIN (ANAYLZE, SERIALIZE) will perform detoasting implicitly and
+ * will also do count the number of bytes being send to the client but
+ * will not actually send them. SERIALIZE uses text format for all
+ * attributes.
+ *
+ * EXPLAIN (ANAYLZE, SERIALIZE BINARY) serializes using binary format.
+ */
+
+/* an attribute info cached for each column */
+typedef struct
+{								/* Per-attribute information */
+	Oid			typoutput;		/* Oid for the type's text output fn */
+	Oid			typsend;		/* Oid for the type's binary output fn */
+	bool		typisvarlena;	/* is it varlena (ie possibly toastable)? */
+	int16		format;			/* format code for this column */
+	FmgrInfo	finfo;			/* Precomputed call info for output fn */
+} SerializeAttrInfo;
+
+typedef struct
+{
+	/* receiver for the tuples, that just serializes */
+	DestReceiver		destRecevier;
+	MemoryContext		memoryContext;
+	MemoryContext		oldMemoryContext;	/* restore to old when done */
+	int16				format;				/* text of binary */
+	TupleDesc			attrinfo;
+	int					nattrs;
+	uint64				bytesSend;			/* Num of bytes over the wire */
+	SerializeAttrInfo	*infos;				/* Cached info about each attr */
+} SerializeDestReceiver;
+
+/*
+ * Get the lookup info that the row-callback of the receiver needs. this code
+ * is similar to the code from printup.c except that it doesn't do any actual
+ * output.
+ */
+static void
+serialize_prepare_info(SerializeDestReceiver *receiver, TupleDesc typeinfo,
+	int nattrs)
+{
+	int i;
+
+	/* get rid of any old data */
+	if (receiver->infos)
+		pfree(receiver->infos);
+	receiver->infos = NULL;
+
+	receiver->attrinfo = typeinfo;
+	receiver->nattrs = nattrs;
+	if (nattrs <= 0)
+		return;
+
+	receiver->infos = (SerializeAttrInfo *) palloc0(
+		nattrs * sizeof(SerializeAttrInfo));
+	for (i = 0; i < nattrs; i++)
+	{
+		SerializeAttrInfo *info = &(receiver->infos[i]);
+		Form_pg_attribute attr = TupleDescAttr(typeinfo, i);
+		info->format = receiver->format;
+		if (info->format == 0)
+		{
+			getTypeOutputInfo(attr->atttypid,
+							  &info->typoutput,
+							  &info->typisvarlena);
+			fmgr_info(info->typoutput, &info->finfo);
+		}
+		else if (info->format == 1)
+		{
+			getTypeBinaryOutputInfo(attr->atttypid,
+									&info->typsend,
+									&info->typisvarlena);
+			fmgr_info(info->typsend, &info->finfo);
+		}
+		else
+			ereport(ERROR,
+					(errcode(ERRCODE_INVALID_PARAMETER_VALUE),
+					 errmsg("unsupported format code: %d", info->format)));
+	}
+}
+
+
+
+/* this method receives the tuples/records during explain (analyze, serialize)
+ * and serializes them.
+ * this method is otherwise not called and its purpose is to serialize to
+ * make analyze optionally more realistic. serialization includes detoasting
+ * and invoking the type's output (or send) function, which is what happens
+ * when you actually run the query. both steps cost time and thus
+ * analyze can be very misleading if those two steps are omitted.
+ */
+static bool
+serializeAnalyzeReceive(TupleTableSlot *slot, DestReceiver *self)
+{
+	int i;
+	TupleDesc tupdesc;
+	SerializeDestReceiver *receiver = (SerializeDestReceiver*) self;
+
+	tupdesc  = slot->tts_tupleDescriptor;
+	/* Cache attribute infos and function oid if outdated */
+	if (receiver->attrinfo != tupdesc || receiver->nattrs != tupdesc->natts)
+	{
+		serialize_prepare_info(receiver, tupdesc, tupdesc->natts);
+	}
+
+	/* Fill all of the slot's attributes, we can now use slot->tts_values
+	 * and its tts_isnull array which should be long enough even if added
+	 * a null-column to the table */
+	slot_getallattrs(slot);
+
+	receiver->oldMemoryContext = MemoryContextSwitchTo(
+		receiver->memoryContext);
+
+	/* Iterate over all attributes of the tuple and invoke the output func
+	 * (or send function in case of a binary format). completely ignore the
+	 * result. MemoryContext is free'd via reset at the end of the this
+	 * per-tuple callback anyhow.
+	 * NOTE: when invoking the output function detoasting is implicitly
+	 * performed when needed.
+	 */
+
+	receiver->bytesSend += 3; /* protocol message type and attribute-count */
+	for (i = 0; i < tupdesc->natts; i++)
+	{
+		SerializeAttrInfo *info = &(receiver->infos[i]);
+		Datum attr = slot->tts_values[i];
+		if (slot->tts_isnull[i])
+		{
+			receiver->bytesSend += 4; /* null is send as -1 length */
+		}
+		else
+		{
+			if (info->format == 0)
+			{
+				/* Text output, ignore the result but count it */
+				char* output = OutputFunctionCall(&info->finfo, attr);
+				size_t outputlen = strlen(output);
+				/* convert from server encoding to client encoding if needed */
+				char *converted = pg_server_to_client(output, outputlen);
+				if (converted != output)
+				{
+					/* converted encoding, get new length */
+					outputlen = strlen(converted);
+					pfree(converted);
+				}
+				/* append length that would have gone over the wire, 4
+				 * the number of preceding bytes that contain the length */
+				receiver->bytesSend += 4 + outputlen;
+			}
+			else
+			{
+				/* Binary output, ignore the result but count it
+				 * length is included in varsize */
+				bytea* bytes = SendFunctionCall(&info->finfo, attr);
+				uint64 n = VARSIZE(bytes);
+				receiver->bytesSend += n;
+			}
+		}
+	}
+	MemoryContextSwitchTo(receiver->oldMemoryContext);
+	MemoryContextReset(receiver->memoryContext);
+	return true;
+}
+
+static void
+serializeAnalyzeStartup(DestReceiver *self, int operation, TupleDesc typeinfo)
+{
+	SerializeDestReceiver *receiver = (SerializeDestReceiver*) self;
+	int i;
+	/* memory context for our work */
+	receiver->memoryContext = AllocSetContextCreate(CurrentMemoryContext,
+		"SerializeTupleReceive", ALLOCSET_DEFAULT_SIZES);
+
+	/* account for the attribute headers for send bytes */
+	receiver->bytesSend += 3; /* protocol message type and attribute-count */
+	for (i = 0; i < typeinfo->natts; ++i)
+	{
+		Form_pg_attribute att = TupleDescAttr(typeinfo, i);
+		char* name = NameStr(att->attname);
+		size_t namelen = strlen(name);
+		/* convert from server encoding to client encoding if needed */
+		char *converted = pg_server_to_client(name, namelen);
+		if (converted != name)
+		{
+			namelen = strlen(converted);
+			pfree(converted);
+		}
+		/* see printtup.h why we add 18 bytes here. These are the infos
+		 * needed for each attribute plus the attributes's name */
+		receiver->bytesSend += namelen + 1 + 18;
+	}
+}
+
+static void
+serializeAnalyzeCleanup(DestReceiver *self)
+{
+	SerializeDestReceiver *receiver = (SerializeDestReceiver*) self;
+	MemoryContextDelete(receiver->memoryContext);
+}
+
+static void
+serializeAnalyzeDestroy(DestReceiver *self)
+{
+	pfree(self);
+}
+
+/* format is either 0 (text) or 1 (binary) */
+static DestReceiver *CreateSerializeDestReceiver(int16 format)
+{
+	/* Attention must palloc0 (like calloc) here.
+	 * infos and nattrs are expected to be 0 or NULL initially */
+	SerializeDestReceiver *self = (SerializeDestReceiver*) palloc0(
+		sizeof(SerializeDestReceiver));
+	self->destRecevier.receiveSlot = serializeAnalyzeReceive;
+	self->destRecevier.rStartup = serializeAnalyzeStartup;
+	self->destRecevier.rShutdown = serializeAnalyzeCleanup;
+	self->destRecevier.rDestroy = serializeAnalyzeDestroy;
+	self->destRecevier.mydest = DestNone;
+	self->format = format;
+	return (DestReceiver *) self;
+}
+
+static uint64 GetNumberOfSerializedBytes(DestReceiver *dest)
+{
+	SerializeDestReceiver *receiver = (SerializeDestReceiver*) dest;
+	return receiver->bytesSend;
+}
diff --git a/src/include/commands/explain.h b/src/include/commands/explain.h
index f9525fb572..dfa1b94cea 100644
--- a/src/include/commands/explain.h
+++ b/src/include/commands/explain.h
@@ -47,6 +47,16 @@ typedef struct ExplainState
 	bool		summary;		/* print total planning and execution timing */
 	bool		settings;		/* print modified settings */
 	bool		generic;		/* generate a generic plan */
+	bool		serialize;      /* serialize all values, only applicable
+								 * when "analyze" is active. serializing
+								 * invokes the type's output function in
+								 * the same way printtup.c does then tuples
+								 * are send to the client. this includes
+								 * detoasting of toasted values and makes
+								 * EXPLAIN(ANALYZE,SERIALIZE) return realistic
+								 * (longer runtimes */
+	bool		serializebinary;/* serialize in binary format */
+
 	ExplainFormat format;		/* output format */
 	/* state for output formatting --- not reset for each new plan tree */
 	int			indent;			/* current indentation level */
diff --git a/src/test/regress/expected/explain.out b/src/test/regress/expected/explain.out
index 809655e16e..3aed4e9356 100644
--- a/src/test/regress/expected/explain.out
+++ b/src/test/regress/expected/explain.out
@@ -563,3 +563,48 @@ select explain_filter('explain (verbose) select * from int8_tbl i8');
  Query Identifier: N
 (3 rows)
 
+-- Test that SERIALIZE is accepted as a parameter to explain
+-- timings are filtered out by explain_filter
+create table test_serialize(id bigserial, val text);
+select explain_filter('explain (analyze,serialize) select * from test_serialize');
+                                          explain_filter                                          
+--------------------------------------------------------------------------------------------------
+ Seq Scan on test_serialize  (cost=N.N..N.N rows=N width=N) (actual time=N.N..N.N rows=N loops=N)
+ Planning Time: N.N ms
+ Execution Time: N.N ms
+ Serialized Bytes: N Bytes. Mode Text. Bandwidth N.N MB/sec
+(4 rows)
+
+drop table test_serialize;
+-- Test that SERIALIZE BINARY is accepted as a parameter to explain
+create table test_serialize(id bigserial, val text);
+select explain_filter('explain (analyze,serialize binary) select * from test_serialize');
+                                          explain_filter                                          
+--------------------------------------------------------------------------------------------------
+ Seq Scan on test_serialize  (cost=N.N..N.N rows=N width=N) (actual time=N.N..N.N rows=N loops=N)
+ Planning Time: N.N ms
+ Execution Time: N.N ms
+ Serialized Bytes: N Bytes. Mode Binary. Bandwidth N.N MB/sec
+(4 rows)
+
+drop table test_serialize;
+-- Test that _SERIALIZE invalidparameter_ is not accepted as a parameter to explain
+create table test_serialize(id bigserial, val text);
+select explain_filter('explain (analyze,serialize invalidparameter) select * from test_serialize');
+ERROR:  unrecognized value for EXPLAIN option "serialize": "invalidparameter"
+LINE 1: select explain_filter('explain (analyze,serialize invalidpar...
+                         ^
+CONTEXT:  PL/pgSQL function explain_filter(text) line 5 at FOR over EXECUTE statement
+drop table test_serialize;
+-- Test SERIALIZE is _not_ accepted as a parameter to explain unless ANALYZE is specified
+create table test_serialize(id bigserial, val text);
+select explain_filter('explain (serialize) select * from test_serialize');
+ERROR:  EXPLAIN option SERIALIZE requires ANALYZE
+CONTEXT:  PL/pgSQL function explain_filter(text) line 5 at FOR over EXECUTE statement
+drop table test_serialize;
+-- Test SERIALIZEBINARY is _not_ accepted as a parameter to explain unless ANALYZE is specified
+create table test_serialize(id bigserial, val text);
+select explain_filter('explain (serialize binary) select * from test_serialize');
+ERROR:  EXPLAIN option SERIALIZE requires ANALYZE
+CONTEXT:  PL/pgSQL function explain_filter(text) line 5 at FOR over EXECUTE statement
+drop table test_serialize;
diff --git a/src/test/regress/sql/explain.sql b/src/test/regress/sql/explain.sql
index b6b7beab27..4dc10066b5 100644
--- a/src/test/regress/sql/explain.sql
+++ b/src/test/regress/sql/explain.sql
@@ -154,3 +154,29 @@ select explain_filter('explain (verbose) select * from t1 where pg_temp.mysin(f1
 -- Test compute_query_id
 set compute_query_id = on;
 select explain_filter('explain (verbose) select * from int8_tbl i8');
+
+-- Test that SERIALIZE is accepted as a parameter to explain
+-- timings are filtered out by explain_filter
+create table test_serialize(id bigserial, val text);
+select explain_filter('explain (analyze,serialize) select * from test_serialize');
+drop table test_serialize;
+
+-- Test that SERIALIZE BINARY is accepted as a parameter to explain
+create table test_serialize(id bigserial, val text);
+select explain_filter('explain (analyze,serialize binary) select * from test_serialize');
+drop table test_serialize;
+
+-- Test that _SERIALIZE invalidparameter_ is not accepted as a parameter to explain
+create table test_serialize(id bigserial, val text);
+select explain_filter('explain (analyze,serialize invalidparameter) select * from test_serialize');
+drop table test_serialize;
+
+-- Test SERIALIZE is _not_ accepted as a parameter to explain unless ANALYZE is specified
+create table test_serialize(id bigserial, val text);
+select explain_filter('explain (serialize) select * from test_serialize');
+drop table test_serialize;
+
+-- Test SERIALIZEBINARY is _not_ accepted as a parameter to explain unless ANALYZE is specified
+create table test_serialize(id bigserial, val text);
+select explain_filter('explain (serialize binary) select * from test_serialize');
+drop table test_serialize;
#10Tomas Vondra
tomas.vondra@enterprisedb.com
In reply to: stepan rutz (#9)
Re: Detoasting optionally to make Explain-Analyze less misleading

On 11/2/23 20:09, stepan rutz wrote:

Hi Thomas,

you are right of course. Thanks!

I have attached a new version of the patch that supports the syntax like
suggested. The previous patch was insonsistent in style indeed.

explain (analyze, serialize)

and

explain (analyze, serialize binary)

That doesn't make too much of a difference for most scenarios I am
certain. However the the seralize option itself does. Mostly because it
performs the detoasting and that was a trap for me in the past with just
plain analyze.

Eg this scenario really is not too far fetched in a world where people
have large JSONB values.

db1=# create table test(id bigint, val text);

db1=# insert into test(val) select string_agg(s::text, ',') from (select
generate_series(1, 10_000_000) as s) as a1;

now we have a cell that has roughly 80Mb in it. A large detoasting that
will happen in reallife but in explain(analyze).

and then...

db1=# explain (analyze) select * from test;
                                            QUERY PLAN
---------------------------------------------------------------------------------------------------
 Seq Scan on test  (cost=0.00..22.00 rows=1200 width=40) (actual
time=0.018..0.020 rows=1 loops=1)
 Planning Time: 0.085 ms
 Execution Time: 0.044 ms
(3 rows)

db1=# explain (analyze, serialize) select * from test;
                                            QUERY PLAN
---------------------------------------------------------------------------------------------------
 Seq Scan on test  (cost=0.00..22.00 rows=1200 width=40) (actual
time=0.023..0.027 rows=1 loops=1)
 Planning Time: 0.077 ms
 Execution Time: 303.281 ms
 Serialized Bytes: 78888953 Bytes. Mode Text. Bandwidth 248.068 MB/sec
(4 rows)

db1=#

So the explain(analyze) does not process the ~80 MB in 0.044ms in any
way of course.

Honestly, I see absolutely no point in printing this. I have little idea
what to do with the "bytes". We have to transfer this over network, but
surely there's other data not included in this sum, right?

But the bandwidth seems pretty bogus/useless, as it's calculated from
execution time, which includes everything else, not just serialization.
So what does it say? It certainly does not include the network transfer.

IMO we should either print nothing or just the bytes. I don't see the
point in printing the mode, which is determined by the command.

Actually I could print the serialized bytes using 1. grouping-separators
(eg 78_888_953) or 2. in the way pg_size_pretty does it.

If doing it the pg_size_pretty way I am uncertain if it would be ok to
query the actual pg_size_pretty function via its (certainly frozen) oid
of 3166 and do OidFunctionCall1(3166...) to invoke it. Otherwise I'd say
it would be nice if the code from that function would be made available
as a utility function for all c-code.  Any suggestions on this topic?

I'm rather skeptical about this proposal, mostly because it makes it
harder to process the explain output in scripts etc.

But more importantly, it's a completely separate matter from what this
patch does, so if you want to pursue this, I suggest you start a
separate thread. If you want to introduce separators, surely this is not
the only place that should do it (e.g. why not to do that for "rows" or
"cost" estimates)?

BTW if you really want to print amount of memory, maybe print it in
kilobytes, like every other place in explain.c? Also, explain generally
prints stuff in "key: value" style (in text format).

regards

--
Tomas Vondra
EnterpriseDB: http://www.enterprisedb.com
The Enterprise PostgreSQL Company

#11stepan rutz
stepan.rutz@gmx.de
In reply to: Tomas Vondra (#10)
1 attachment(s)
Re: Detoasting optionally to make Explain-Analyze less misleading

Hi Thomas,

indeed by doing less the code also becomes trivial and
ExplainPropertyInteger can be used as a oneliner.

My intention was to actually get the realistic payload-bytes from the
wire-protocol counted by the serialization option. I am also adding the
protocol bits and the length of the data that is generated by
serialization output-functions. So it should (hopefully) be the real
numbers.

Attached is a new revision of the patch that prints kB (floor'ed by
integer-division by 1024). Maybe that is also misleading and bytes would
be nicer (though harder to read).

The output is now as follows:

db1=# explain (analyze, serialize) select * from test;
                                            QUERY PLAN
---------------------------------------------------------------------------------------------------
 Seq Scan on test  (cost=0.00..22.00 rows=1200 width=40) (actual
time=0.014..0.017 rows=1 loops=1)
 Planning Time: 0.245 ms
 Execution Time: 292.983 ms
 Serialized Bytes: 77039 kB
(4 rows)

Definately a lot nicer and controlled by  ExplainPropertyInteger in
terms of formatting.

The main motivation was to actually get a correct feeling for the
execution time. Actually counting the bytes gives an impression of what
would go over the wire. Only the big numbers matter here of course.

Regards, Stepan

Show quoted text

On 02.11.23 20:32, Tomas Vondra wrote:

On 11/2/23 20:09, stepan rutz wrote:

Hi Thomas,

you are right of course. Thanks!

I have attached a new version of the patch that supports the syntax like
suggested. The previous patch was insonsistent in style indeed.

explain (analyze, serialize)

and

explain (analyze, serialize binary)

That doesn't make too much of a difference for most scenarios I am
certain. However the the seralize option itself does. Mostly because it
performs the detoasting and that was a trap for me in the past with just
plain analyze.

Eg this scenario really is not too far fetched in a world where people
have large JSONB values.

db1=# create table test(id bigint, val text);

db1=# insert into test(val) select string_agg(s::text, ',') from (select
generate_series(1, 10_000_000) as s) as a1;

now we have a cell that has roughly 80Mb in it. A large detoasting that
will happen in reallife but in explain(analyze).

and then...

db1=# explain (analyze) select * from test;
                                            QUERY PLAN
---------------------------------------------------------------------------------------------------
 Seq Scan on test  (cost=0.00..22.00 rows=1200 width=40) (actual
time=0.018..0.020 rows=1 loops=1)
 Planning Time: 0.085 ms
 Execution Time: 0.044 ms
(3 rows)

db1=# explain (analyze, serialize) select * from test;
                                            QUERY PLAN
---------------------------------------------------------------------------------------------------
 Seq Scan on test  (cost=0.00..22.00 rows=1200 width=40) (actual
time=0.023..0.027 rows=1 loops=1)
 Planning Time: 0.077 ms
 Execution Time: 303.281 ms
 Serialized Bytes: 78888953 Bytes. Mode Text. Bandwidth 248.068 MB/sec
(4 rows)

db1=#

So the explain(analyze) does not process the ~80 MB in 0.044ms in any
way of course.

Honestly, I see absolutely no point in printing this. I have little idea
what to do with the "bytes". We have to transfer this over network, but
surely there's other data not included in this sum, right?

But the bandwidth seems pretty bogus/useless, as it's calculated from
execution time, which includes everything else, not just serialization.
So what does it say? It certainly does not include the network transfer.

IMO we should either print nothing or just the bytes. I don't see the
point in printing the mode, which is determined by the command.

Actually I could print the serialized bytes using 1. grouping-separators
(eg 78_888_953) or 2. in the way pg_size_pretty does it.

If doing it the pg_size_pretty way I am uncertain if it would be ok to
query the actual pg_size_pretty function via its (certainly frozen) oid
of 3166 and do OidFunctionCall1(3166...) to invoke it. Otherwise I'd say
it would be nice if the code from that function would be made available
as a utility function for all c-code.  Any suggestions on this topic?

I'm rather skeptical about this proposal, mostly because it makes it
harder to process the explain output in scripts etc.

But more importantly, it's a completely separate matter from what this
patch does, so if you want to pursue this, I suggest you start a
separate thread. If you want to introduce separators, surely this is not
the only place that should do it (e.g. why not to do that for "rows" or
"cost" estimates)?

BTW if you really want to print amount of memory, maybe print it in
kilobytes, like every other place in explain.c? Also, explain generally
prints stuff in "key: value" style (in text format).

regards

Attachments:

0007_explain_analyze_and_serialize.patchtext/x-patch; charset=UTF-8; name=0007_explain_analyze_and_serialize.patchDownload
diff --git a/src/backend/commands/explain.c b/src/backend/commands/explain.c
index f1d71bc54e..e5aec7ca58 100644
--- a/src/backend/commands/explain.c
+++ b/src/backend/commands/explain.c
@@ -26,6 +26,7 @@
 #include "nodes/nodeFuncs.h"
 #include "parser/analyze.h"
 #include "parser/parsetree.h"
+#include "mb/pg_wchar.h"
 #include "rewrite/rewriteHandler.h"
 #include "storage/bufmgr.h"
 #include "tcop/tcopprot.h"
@@ -33,6 +34,7 @@
 #include "utils/guc_tables.h"
 #include "utils/json.h"
 #include "utils/lsyscache.h"
+#include "utils/numeric.h"
 #include "utils/rel.h"
 #include "utils/ruleutils.h"
 #include "utils/snapmgr.h"
@@ -47,7 +49,6 @@ ExplainOneQuery_hook_type ExplainOneQuery_hook = NULL;
 /* Hook for plugins to get control in explain_get_index_name() */
 explain_get_index_name_hook_type explain_get_index_name_hook = NULL;
 
-
 /* OR-able flags for ExplainXMLTag() */
 #define X_OPENING 0
 #define X_CLOSING 1
@@ -154,7 +155,8 @@ static void ExplainJSONLineEnding(ExplainState *es);
 static void ExplainYAMLLineStarting(ExplainState *es);
 static void escape_yaml(StringInfo buf, const char *str);
 
-
+static DestReceiver *CreateSerializeDestReceiver(int16 format);
+static uint64 GetNumberOfSerializedBytes(DestReceiver *dest);
 
 /*
  * ExplainQuery -
@@ -192,6 +194,23 @@ ExplainQuery(ParseState *pstate, ExplainStmt *stmt,
 			es->settings = defGetBoolean(opt);
 		else if (strcmp(opt->defname, "generic_plan") == 0)
 			es->generic = defGetBoolean(opt);
+		else if (strcmp(opt->defname, "serialize") == 0)
+		{
+			es->serialize = true;
+			/* optionally check for BINARY as argument */
+			if (opt->arg)
+			{
+				char *p = defGetString(opt);
+				if (strcmp(p, "binary") == 0)
+					es->serialize = es->serializebinary = true;
+				else
+					ereport(ERROR,
+						(errcode(ERRCODE_INVALID_PARAMETER_VALUE),
+						 errmsg("unrecognized value for EXPLAIN option \"%s\": \"%s\"",
+								opt->defname, p),
+						 parser_errposition(pstate, opt->location)));
+			}
+		}
 		else if (strcmp(opt->defname, "timing") == 0)
 		{
 			timing_set = true;
@@ -244,6 +263,12 @@ ExplainQuery(ParseState *pstate, ExplainStmt *stmt,
 				(errcode(ERRCODE_INVALID_PARAMETER_VALUE),
 				 errmsg("EXPLAIN option TIMING requires ANALYZE")));
 
+	/* check that serialize is used with EXPLAIN ANALYZE */
+	if (es->serialize && !es->analyze)
+		ereport(ERROR,
+				(errcode(ERRCODE_INVALID_PARAMETER_VALUE),
+				 errmsg("EXPLAIN option SERIALIZE requires ANALYZE")));
+
 	/* check that GENERIC_PLAN is not used with EXPLAIN ANALYZE */
 	if (es->generic && es->analyze)
 		ereport(ERROR,
@@ -535,6 +560,7 @@ ExplainOnePlan(PlannedStmt *plannedstmt, IntoClause *into, ExplainState *es,
 	double		totaltime = 0;
 	int			eflags;
 	int			instrument_option = 0;
+	int64		bytesSend = 0;
 
 	Assert(plannedstmt->commandType != CMD_UTILITY);
 
@@ -565,9 +591,15 @@ ExplainOnePlan(PlannedStmt *plannedstmt, IntoClause *into, ExplainState *es,
 	/*
 	 * Normally we discard the query's output, but if explaining CREATE TABLE
 	 * AS, we'd better use the appropriate tuple receiver.
+	 * Also if we choose to serialize during explain, we need to send the
+	 * tuples to a dest-receiver that performs serializing
+	 * into the protocol receiving format. this implicitly also detoasts
+	 * values.
 	 */
 	if (into)
 		dest = CreateIntoRelDestReceiver(into);
+	else if (es->analyze && es->serialize)
+		dest = CreateSerializeDestReceiver(es->serializebinary ? 1 : 0);
 	else
 		dest = None_Receiver;
 
@@ -606,6 +638,15 @@ ExplainOnePlan(PlannedStmt *plannedstmt, IntoClause *into, ExplainState *es,
 		/* run cleanup too */
 		ExecutorFinish(queryDesc);
 
+		if (es->serialize)
+		{
+			bytesSend = GetNumberOfSerializedBytes(dest);
+		}
+
+
+		/* call the dest receiver's destroy method even during explain */
+		dest->rDestroy(dest);
+
 		/* We can't run ExecutorEnd 'till we're done printing the stats... */
 		totaltime += elapsed_time(&starttime);
 	}
@@ -671,6 +712,10 @@ ExplainOnePlan(PlannedStmt *plannedstmt, IntoClause *into, ExplainState *es,
 		ExplainPropertyFloat("Execution Time", "ms", 1000.0 * totaltime, 3,
 							 es);
 
+	/* Print info about serialization of data */
+	if (es->summary && es->analyze && es->serialize)
+		ExplainPropertyInteger("Serialized Bytes", "kB", bytesSend / 1024, es);
+
 	ExplainCloseGroup("Query", NULL, true, es);
 }
 
@@ -5082,3 +5127,238 @@ escape_yaml(StringInfo buf, const char *str)
 {
 	escape_json(buf, str);
 }
+
+
+/* Serializing DestReceiver functions
+ *
+ * EXPLAIN (ANALYZE)  sometimes gives results that unrealistic.
+ * During EXPLAIN(ANALYZE) there is no detoasting of values.
+ * That means you get no idea what your actual query time is going
+ * to be, nor what the actual overhead of detoasting is.
+ *
+ * EXPLAIN (ANAYLZE, SERIALIZE) will perform detoasting implicitly and
+ * will also do count the number of bytes being send to the client but
+ * will not actually send them. SERIALIZE uses text format for all
+ * attributes.
+ *
+ * EXPLAIN (ANAYLZE, SERIALIZE BINARY) serializes using binary format.
+ */
+
+/* an attribute info cached for each column */
+typedef struct
+{								/* Per-attribute information */
+	Oid			typoutput;		/* Oid for the type's text output fn */
+	Oid			typsend;		/* Oid for the type's binary output fn */
+	bool		typisvarlena;	/* is it varlena (ie possibly toastable)? */
+	int16		format;			/* format code for this column */
+	FmgrInfo	finfo;			/* Precomputed call info for output fn */
+} SerializeAttrInfo;
+
+typedef struct
+{
+	/* receiver for the tuples, that just serializes */
+	DestReceiver		destRecevier;
+	MemoryContext		memoryContext;
+	MemoryContext		oldMemoryContext;	/* restore to old when done */
+	int16				format;				/* text of binary */
+	TupleDesc			attrinfo;
+	int					nattrs;
+	uint64				bytesSend;			/* Num of bytes over the wire */
+	SerializeAttrInfo	*infos;				/* Cached info about each attr */
+} SerializeDestReceiver;
+
+/*
+ * Get the lookup info that the row-callback of the receiver needs. this code
+ * is similar to the code from printup.c except that it doesn't do any actual
+ * output.
+ */
+static void
+serialize_prepare_info(SerializeDestReceiver *receiver, TupleDesc typeinfo,
+	int nattrs)
+{
+	int i;
+
+	/* get rid of any old data */
+	if (receiver->infos)
+		pfree(receiver->infos);
+	receiver->infos = NULL;
+
+	receiver->attrinfo = typeinfo;
+	receiver->nattrs = nattrs;
+	if (nattrs <= 0)
+		return;
+
+	receiver->infos = (SerializeAttrInfo *) palloc0(
+		nattrs * sizeof(SerializeAttrInfo));
+	for (i = 0; i < nattrs; i++)
+	{
+		SerializeAttrInfo *info = &(receiver->infos[i]);
+		Form_pg_attribute attr = TupleDescAttr(typeinfo, i);
+		info->format = receiver->format;
+		if (info->format == 0)
+		{
+			getTypeOutputInfo(attr->atttypid,
+							  &info->typoutput,
+							  &info->typisvarlena);
+			fmgr_info(info->typoutput, &info->finfo);
+		}
+		else if (info->format == 1)
+		{
+			getTypeBinaryOutputInfo(attr->atttypid,
+									&info->typsend,
+									&info->typisvarlena);
+			fmgr_info(info->typsend, &info->finfo);
+		}
+		else
+			ereport(ERROR,
+					(errcode(ERRCODE_INVALID_PARAMETER_VALUE),
+					 errmsg("unsupported format code: %d", info->format)));
+	}
+}
+
+
+
+/* this method receives the tuples/records during explain (analyze, serialize)
+ * and serializes them.
+ * this method is otherwise not called and its purpose is to serialize to
+ * make analyze optionally more realistic. serialization includes detoasting
+ * and invoking the type's output (or send) function, which is what happens
+ * when you actually run the query. both steps cost time and thus
+ * analyze can be very misleading if those two steps are omitted.
+ */
+static bool
+serializeAnalyzeReceive(TupleTableSlot *slot, DestReceiver *self)
+{
+	int i;
+	TupleDesc tupdesc;
+	SerializeDestReceiver *receiver = (SerializeDestReceiver*) self;
+
+	tupdesc  = slot->tts_tupleDescriptor;
+	/* Cache attribute infos and function oid if outdated */
+	if (receiver->attrinfo != tupdesc || receiver->nattrs != tupdesc->natts)
+	{
+		serialize_prepare_info(receiver, tupdesc, tupdesc->natts);
+	}
+
+	/* Fill all of the slot's attributes, we can now use slot->tts_values
+	 * and its tts_isnull array which should be long enough even if added
+	 * a null-column to the table */
+	slot_getallattrs(slot);
+
+	receiver->oldMemoryContext = MemoryContextSwitchTo(
+		receiver->memoryContext);
+
+	/* Iterate over all attributes of the tuple and invoke the output func
+	 * (or send function in case of a binary format). completely ignore the
+	 * result. MemoryContext is free'd via reset at the end of the this
+	 * per-tuple callback anyhow.
+	 * NOTE: when invoking the output function detoasting is implicitly
+	 * performed when needed.
+	 */
+
+	receiver->bytesSend += 3; /* protocol message type and attribute-count */
+	for (i = 0; i < tupdesc->natts; i++)
+	{
+		SerializeAttrInfo *info = &(receiver->infos[i]);
+		Datum attr = slot->tts_values[i];
+		if (slot->tts_isnull[i])
+		{
+			receiver->bytesSend += 4; /* null is send as -1 length */
+		}
+		else
+		{
+			if (info->format == 0)
+			{
+				/* Text output, ignore the result but count it */
+				char* output = OutputFunctionCall(&info->finfo, attr);
+				size_t outputlen = strlen(output);
+				/* convert from server encoding to client encoding if needed */
+				char *converted = pg_server_to_client(output, outputlen);
+				if (converted != output)
+				{
+					/* converted encoding, get new length */
+					outputlen = strlen(converted);
+					pfree(converted);
+				}
+				/* append length that would have gone over the wire, 4
+				 * the number of preceding bytes that contain the length */
+				receiver->bytesSend += 4 + outputlen;
+			}
+			else
+			{
+				/* Binary output, ignore the result but count it
+				 * length is included in varsize */
+				bytea* bytes = SendFunctionCall(&info->finfo, attr);
+				uint64 n = VARSIZE(bytes);
+				receiver->bytesSend += n;
+			}
+		}
+	}
+	MemoryContextSwitchTo(receiver->oldMemoryContext);
+	MemoryContextReset(receiver->memoryContext);
+	return true;
+}
+
+static void
+serializeAnalyzeStartup(DestReceiver *self, int operation, TupleDesc typeinfo)
+{
+	SerializeDestReceiver *receiver = (SerializeDestReceiver*) self;
+	int i;
+	/* memory context for our work */
+	receiver->memoryContext = AllocSetContextCreate(CurrentMemoryContext,
+		"SerializeTupleReceive", ALLOCSET_DEFAULT_SIZES);
+
+	/* account for the attribute headers for send bytes */
+	receiver->bytesSend += 3; /* protocol message type and attribute-count */
+	for (i = 0; i < typeinfo->natts; ++i)
+	{
+		Form_pg_attribute att = TupleDescAttr(typeinfo, i);
+		char* name = NameStr(att->attname);
+		size_t namelen = strlen(name);
+		/* convert from server encoding to client encoding if needed */
+		char *converted = pg_server_to_client(name, namelen);
+		if (converted != name)
+		{
+			namelen = strlen(converted);
+			pfree(converted);
+		}
+		/* see printtup.h why we add 18 bytes here. These are the infos
+		 * needed for each attribute plus the attributes's name */
+		receiver->bytesSend += namelen + 1 + 18;
+	}
+}
+
+static void
+serializeAnalyzeCleanup(DestReceiver *self)
+{
+	SerializeDestReceiver *receiver = (SerializeDestReceiver*) self;
+	MemoryContextDelete(receiver->memoryContext);
+}
+
+static void
+serializeAnalyzeDestroy(DestReceiver *self)
+{
+	pfree(self);
+}
+
+/* format is either 0 (text) or 1 (binary) */
+static DestReceiver *CreateSerializeDestReceiver(int16 format)
+{
+	/* Attention must palloc0 (like calloc) here.
+	 * infos and nattrs are expected to be 0 or NULL initially */
+	SerializeDestReceiver *self = (SerializeDestReceiver*) palloc0(
+		sizeof(SerializeDestReceiver));
+	self->destRecevier.receiveSlot = serializeAnalyzeReceive;
+	self->destRecevier.rStartup = serializeAnalyzeStartup;
+	self->destRecevier.rShutdown = serializeAnalyzeCleanup;
+	self->destRecevier.rDestroy = serializeAnalyzeDestroy;
+	self->destRecevier.mydest = DestNone;
+	self->format = format;
+	return (DestReceiver *) self;
+}
+
+static uint64 GetNumberOfSerializedBytes(DestReceiver *dest)
+{
+	SerializeDestReceiver *receiver = (SerializeDestReceiver*) dest;
+	return receiver->bytesSend;
+}
diff --git a/src/include/commands/explain.h b/src/include/commands/explain.h
index f9525fb572..dfa1b94cea 100644
--- a/src/include/commands/explain.h
+++ b/src/include/commands/explain.h
@@ -47,6 +47,16 @@ typedef struct ExplainState
 	bool		summary;		/* print total planning and execution timing */
 	bool		settings;		/* print modified settings */
 	bool		generic;		/* generate a generic plan */
+	bool		serialize;      /* serialize all values, only applicable
+								 * when "analyze" is active. serializing
+								 * invokes the type's output function in
+								 * the same way printtup.c does then tuples
+								 * are send to the client. this includes
+								 * detoasting of toasted values and makes
+								 * EXPLAIN(ANALYZE,SERIALIZE) return realistic
+								 * (longer runtimes */
+	bool		serializebinary;/* serialize in binary format */
+
 	ExplainFormat format;		/* output format */
 	/* state for output formatting --- not reset for each new plan tree */
 	int			indent;			/* current indentation level */
diff --git a/src/test/regress/expected/explain.out b/src/test/regress/expected/explain.out
index 809655e16e..2720b17923 100644
--- a/src/test/regress/expected/explain.out
+++ b/src/test/regress/expected/explain.out
@@ -563,3 +563,48 @@ select explain_filter('explain (verbose) select * from int8_tbl i8');
  Query Identifier: N
 (3 rows)
 
+-- Test that SERIALIZE is accepted as a parameter to explain
+-- timings are filtered out by explain_filter
+create table test_serialize(id bigserial, val text);
+select explain_filter('explain (analyze,serialize) select * from test_serialize');
+                                          explain_filter                                          
+--------------------------------------------------------------------------------------------------
+ Seq Scan on test_serialize  (cost=N.N..N.N rows=N width=N) (actual time=N.N..N.N rows=N loops=N)
+ Planning Time: N.N ms
+ Execution Time: N.N ms
+ Serialized Bytes: N kB
+(4 rows)
+
+drop table test_serialize;
+-- Test that SERIALIZE BINARY is accepted as a parameter to explain
+create table test_serialize(id bigserial, val text);
+select explain_filter('explain (analyze,serialize binary) select * from test_serialize');
+                                          explain_filter                                          
+--------------------------------------------------------------------------------------------------
+ Seq Scan on test_serialize  (cost=N.N..N.N rows=N width=N) (actual time=N.N..N.N rows=N loops=N)
+ Planning Time: N.N ms
+ Execution Time: N.N ms
+ Serialized Bytes: N kB
+(4 rows)
+
+drop table test_serialize;
+-- Test that _SERIALIZE invalidparameter_ is not accepted as a parameter to explain
+create table test_serialize(id bigserial, val text);
+select explain_filter('explain (analyze,serialize invalidparameter) select * from test_serialize');
+ERROR:  unrecognized value for EXPLAIN option "serialize": "invalidparameter"
+LINE 1: select explain_filter('explain (analyze,serialize invalidpar...
+                         ^
+CONTEXT:  PL/pgSQL function explain_filter(text) line 5 at FOR over EXECUTE statement
+drop table test_serialize;
+-- Test SERIALIZE is _not_ accepted as a parameter to explain unless ANALYZE is specified
+create table test_serialize(id bigserial, val text);
+select explain_filter('explain (serialize) select * from test_serialize');
+ERROR:  EXPLAIN option SERIALIZE requires ANALYZE
+CONTEXT:  PL/pgSQL function explain_filter(text) line 5 at FOR over EXECUTE statement
+drop table test_serialize;
+-- Test SERIALIZEBINARY is _not_ accepted as a parameter to explain unless ANALYZE is specified
+create table test_serialize(id bigserial, val text);
+select explain_filter('explain (serialize binary) select * from test_serialize');
+ERROR:  EXPLAIN option SERIALIZE requires ANALYZE
+CONTEXT:  PL/pgSQL function explain_filter(text) line 5 at FOR over EXECUTE statement
+drop table test_serialize;
diff --git a/src/test/regress/sql/explain.sql b/src/test/regress/sql/explain.sql
index b6b7beab27..4dc10066b5 100644
--- a/src/test/regress/sql/explain.sql
+++ b/src/test/regress/sql/explain.sql
@@ -154,3 +154,29 @@ select explain_filter('explain (verbose) select * from t1 where pg_temp.mysin(f1
 -- Test compute_query_id
 set compute_query_id = on;
 select explain_filter('explain (verbose) select * from int8_tbl i8');
+
+-- Test that SERIALIZE is accepted as a parameter to explain
+-- timings are filtered out by explain_filter
+create table test_serialize(id bigserial, val text);
+select explain_filter('explain (analyze,serialize) select * from test_serialize');
+drop table test_serialize;
+
+-- Test that SERIALIZE BINARY is accepted as a parameter to explain
+create table test_serialize(id bigserial, val text);
+select explain_filter('explain (analyze,serialize binary) select * from test_serialize');
+drop table test_serialize;
+
+-- Test that _SERIALIZE invalidparameter_ is not accepted as a parameter to explain
+create table test_serialize(id bigserial, val text);
+select explain_filter('explain (analyze,serialize invalidparameter) select * from test_serialize');
+drop table test_serialize;
+
+-- Test SERIALIZE is _not_ accepted as a parameter to explain unless ANALYZE is specified
+create table test_serialize(id bigserial, val text);
+select explain_filter('explain (serialize) select * from test_serialize');
+drop table test_serialize;
+
+-- Test SERIALIZEBINARY is _not_ accepted as a parameter to explain unless ANALYZE is specified
+create table test_serialize(id bigserial, val text);
+select explain_filter('explain (serialize binary) select * from test_serialize');
+drop table test_serialize;
#12Matthias van de Meent
boekewurm+postgres@gmail.com
In reply to: Tomas Vondra (#10)
Re: Detoasting optionally to make Explain-Analyze less misleading

On Thu, 2 Nov 2023 at 20:32, Tomas Vondra <tomas.vondra@enterprisedb.com> wrote:

On 11/2/23 20:09, stepan rutz wrote:

db1=# explain (analyze, serialize) select * from test;
QUERY PLAN
---------------------------------------------------------------------------------------------------
Seq Scan on test (cost=0.00..22.00 rows=1200 width=40) (actual
time=0.023..0.027 rows=1 loops=1)
Planning Time: 0.077 ms
Execution Time: 303.281 ms
Serialized Bytes: 78888953 Bytes. Mode Text. Bandwidth 248.068 MB/sec

[...]
BTW if you really want to print amount of memory, maybe print it in
kilobytes, like every other place in explain.c?

Isn't node width in bytes, or is it an opaque value not to be
interpreted by users? I've never really investigated that part of
Postgres' explain output...

Also, explain generally
prints stuff in "key: value" style (in text format).

That'd be key: metrickey=metricvalue for expanded values like those in
plan nodes and the buffer usage, no?

Serialized Bytes: 78888953 Bytes. Mode Text. Bandwidth 248.068 MB/sec

I was thinking more along the lines of something like this:

[...]
Execution Time: xxx ms
Serialization: time=yyy.yyy (in ms) size=yyy (in KiB, or B) mode=text
(or binary)

This is significantly different from your output, as it doesn't hide
the measured time behind a lossy calculation of bandwidth, but gives
the measured data to the user; allowing them to derive their own
precise bandwidth if they're so inclined.

Kind regards,

Matthias van de Meent
Neon (https://neon.tech)

#13Tomas Vondra
tomas.vondra@enterprisedb.com
In reply to: Matthias van de Meent (#12)
Re: Detoasting optionally to make Explain-Analyze less misleading

On 11/2/23 21:02, Matthias van de Meent wrote:

On Thu, 2 Nov 2023 at 20:32, Tomas Vondra <tomas.vondra@enterprisedb.com> wrote:

On 11/2/23 20:09, stepan rutz wrote:

db1=# explain (analyze, serialize) select * from test;
QUERY PLAN
---------------------------------------------------------------------------------------------------
Seq Scan on test (cost=0.00..22.00 rows=1200 width=40) (actual
time=0.023..0.027 rows=1 loops=1)
Planning Time: 0.077 ms
Execution Time: 303.281 ms
Serialized Bytes: 78888953 Bytes. Mode Text. Bandwidth 248.068 MB/sec

[...]
BTW if you really want to print amount of memory, maybe print it in
kilobytes, like every other place in explain.c?

Isn't node width in bytes, or is it an opaque value not to be
interpreted by users? I've never really investigated that part of
Postgres' explain output...

Right, "width=" is always in bytes. But fields like amount of sorted
data is in kB, and this seems closer to that.

Also, explain generally
prints stuff in "key: value" style (in text format).

That'd be key: metrickey=metricvalue for expanded values like those in
plan nodes and the buffer usage, no?

Possibly. But the proposed output does neither. Also, it starts with
"Serialized Bytes" but then prints info about bandwidth.

Serialized Bytes: 78888953 Bytes. Mode Text. Bandwidth 248.068 MB/sec

I was thinking more along the lines of something like this:

[...]
Execution Time: xxx ms
Serialization: time=yyy.yyy (in ms) size=yyy (in KiB, or B) mode=text
(or binary)

This is significantly different from your output, as it doesn't hide

the measured time behind a lossy calculation of bandwidth, but gives
the measured data to the user; allowing them to derive their own
precise bandwidth if they're so inclined.

Might work. I'm still not convinced we need to include the mode, or that
the size is that interesting/useful, though.

regards

--
Tomas Vondra
EnterpriseDB: http://www.enterprisedb.com
The Enterprise PostgreSQL Company

#14Matthias van de Meent
boekewurm+postgres@gmail.com
In reply to: Tomas Vondra (#13)
Re: Detoasting optionally to make Explain-Analyze less misleading

On Thu, 2 Nov 2023 at 22:25, Tomas Vondra <tomas.vondra@enterprisedb.com> wrote:

On 11/2/23 21:02, Matthias van de Meent wrote:

On Thu, 2 Nov 2023 at 20:32, Tomas Vondra <tomas.vondra@enterprisedb.com> wrote:

On 11/2/23 20:09, stepan rutz wrote:

db1=# explain (analyze, serialize) select * from test;
QUERY PLAN
---------------------------------------------------------------------------------------------------
Seq Scan on test (cost=0.00..22.00 rows=1200 width=40) (actual
time=0.023..0.027 rows=1 loops=1)
Planning Time: 0.077 ms
Execution Time: 303.281 ms
Serialized Bytes: 78888953 Bytes. Mode Text. Bandwidth 248.068 MB/sec

[...]
BTW if you really want to print amount of memory, maybe print it in
kilobytes, like every other place in explain.c?

Isn't node width in bytes, or is it an opaque value not to be
interpreted by users? I've never really investigated that part of
Postgres' explain output...

Right, "width=" is always in bytes. But fields like amount of sorted
data is in kB, and this seems closer to that.

Also, explain generally
prints stuff in "key: value" style (in text format).

That'd be key: metrickey=metricvalue for expanded values like those in
plan nodes and the buffer usage, no?

Possibly. But the proposed output does neither. Also, it starts with
"Serialized Bytes" but then prints info about bandwidth.

Serialized Bytes: 78888953 Bytes. Mode Text. Bandwidth 248.068 MB/sec

I was thinking more along the lines of something like this:

[...]
Execution Time: xxx ms
Serialization: time=yyy.yyy (in ms) size=yyy (in KiB, or B) mode=text
(or binary)

This is significantly different from your output, as it doesn't hide

the measured time behind a lossy calculation of bandwidth, but gives
the measured data to the user; allowing them to derive their own
precise bandwidth if they're so inclined.

Might work. I'm still not convinced we need to include the mode, or that
the size is that interesting/useful, though.

I'd say size is interesting for systems where network bandwidth is
constrained, but CPU isn't. We currently only show estimated widths &
accurate number of tuples returned, but that's not an accurate
explanation of why your 30-row 3GB resultset took 1h to transmit on a
10mbit line - that is only explained by the bandwidth of your
connection and the size of the dataset. As we can measure the size of
the returned serialized dataset here, I think it's in the interest of
any debugability to also present it to the user. Sadly, we don't have
good measures of bandwidth without sending that data across, so that's
the only metric that we can't show here, but total query data size is
definitely something that I'd be interested in here.

Kind regards,

Matthias van de Meent
Neon (https://neon.tech)

#15Tomas Vondra
tomas.vondra@enterprisedb.com
In reply to: Matthias van de Meent (#14)
Re: Detoasting optionally to make Explain-Analyze less misleading

On 11/2/23 22:33, Matthias van de Meent wrote:

On Thu, 2 Nov 2023 at 22:25, Tomas Vondra <tomas.vondra@enterprisedb.com> wrote:

On 11/2/23 21:02, Matthias van de Meent wrote:

On Thu, 2 Nov 2023 at 20:32, Tomas Vondra <tomas.vondra@enterprisedb.com> wrote:

On 11/2/23 20:09, stepan rutz wrote:

db1=# explain (analyze, serialize) select * from test;
QUERY PLAN
---------------------------------------------------------------------------------------------------
Seq Scan on test (cost=0.00..22.00 rows=1200 width=40) (actual
time=0.023..0.027 rows=1 loops=1)
Planning Time: 0.077 ms
Execution Time: 303.281 ms
Serialized Bytes: 78888953 Bytes. Mode Text. Bandwidth 248.068 MB/sec

[...]
BTW if you really want to print amount of memory, maybe print it in
kilobytes, like every other place in explain.c?

Isn't node width in bytes, or is it an opaque value not to be
interpreted by users? I've never really investigated that part of
Postgres' explain output...

Right, "width=" is always in bytes. But fields like amount of sorted
data is in kB, and this seems closer to that.

Also, explain generally
prints stuff in "key: value" style (in text format).

That'd be key: metrickey=metricvalue for expanded values like those in
plan nodes and the buffer usage, no?

Possibly. But the proposed output does neither. Also, it starts with
"Serialized Bytes" but then prints info about bandwidth.

Serialized Bytes: 78888953 Bytes. Mode Text. Bandwidth 248.068 MB/sec

I was thinking more along the lines of something like this:

[...]
Execution Time: xxx ms
Serialization: time=yyy.yyy (in ms) size=yyy (in KiB, or B) mode=text
(or binary)

This is significantly different from your output, as it doesn't hide

the measured time behind a lossy calculation of bandwidth, but gives
the measured data to the user; allowing them to derive their own
precise bandwidth if they're so inclined.

Might work. I'm still not convinced we need to include the mode, or that
the size is that interesting/useful, though.

I'd say size is interesting for systems where network bandwidth is
constrained, but CPU isn't. We currently only show estimated widths &
accurate number of tuples returned, but that's not an accurate
explanation of why your 30-row 3GB resultset took 1h to transmit on a
10mbit line - that is only explained by the bandwidth of your
connection and the size of the dataset. As we can measure the size of
the returned serialized dataset here, I think it's in the interest of
any debugability to also present it to the user. Sadly, we don't have
good measures of bandwidth without sending that data across, so that's
the only metric that we can't show here, but total query data size is
definitely something that I'd be interested in here.

Yeah, I agree with that.

regards

--
Tomas Vondra
EnterpriseDB: http://www.enterprisedb.com
The Enterprise PostgreSQL Company

#16Matthias van de Meent
boekewurm+postgres@gmail.com
In reply to: Tomas Vondra (#15)
1 attachment(s)
Re: Detoasting optionally to make Explain-Analyze less misleading

Hi,

I've taken the liberty to update this patch, and register it in the
commitfest app to not lose track of progress [0]https://commitfest.postgresql.org/47/4852/.

The attached v8 patch measures scratch memory allocations (with MEMORY
option), total time spent in serialization (with TIMING on, measures
are inclusive of unseparated memcpy to the message buffer), and a
count of produced bytes plus the output format used (text or binary).
It's a light rework of the earlier 0007 patch, I've reused tests and
some infrastructure, while the implementation details and comments
have been updated significantly.

I think we can bikeshed on format and names, but overall I think the
patch is in a very decent shape.

Stepan, thank you for your earlier work, and feel free to check it out
or pick it up again if you want to; else I'll try to get this done.

Kind regards,

Matthias van de Meent

[0]: https://commitfest.postgresql.org/47/4852/

Attachments:

v8-0001-Explain-Add-SERIALIZE-option.patchapplication/octet-stream; name=v8-0001-Explain-Add-SERIALIZE-option.patchDownload
From c40e9584100c9583ea79c350dc50f7f9a7c1420f Mon Sep 17 00:00:00 2001
From: Matthias van de Meent <boekewurm+postgres@gmail.com>
Date: Mon, 26 Feb 2024 20:17:40 +0100
Subject: [PATCH v8] Explain: Add SERIALIZE option

This option integrates with both MEMORY and TIMING, and is gated behind
ANALYZE.

EXPLAIN (SERIALIZE) allows analysis of the cost of actually serializing
the resultset, which usually can't be tested without actually consuming
the resultset on the client. As sending a resultset of gigabytes across
e.g. a VPN connection can be slow and expensive, this option increases
coverage of EXPLAIN and allows for further diagnostics in case of e.g.
attributes that are slow to deTOAST.

Future iterations may want to further instrument the deTOAST and ANALYZE
infrastructure to measure counts of deTOAST operations, but that is not
part of this patch.

Original patch by Stepan Rutz <stepan.rutz@gmx.de>, heavily modified by
Matthias van de Meent <boekewurm+postgres@gmail.com>
---
 src/backend/commands/explain.c        | 511 +++++++++++++++++++++++++-
 src/include/commands/explain.h        |   9 +
 src/test/regress/expected/explain.out |  57 ++-
 src/test/regress/sql/explain.sql      |  28 +-
 4 files changed, 599 insertions(+), 6 deletions(-)

diff --git a/src/backend/commands/explain.c b/src/backend/commands/explain.c
index 83d00a4663..62205394b7 100644
--- a/src/backend/commands/explain.c
+++ b/src/backend/commands/explain.c
@@ -21,6 +21,7 @@
 #include "executor/nodeHash.h"
 #include "foreign/fdwapi.h"
 #include "jit/jit.h"
+#include "libpq/pqformat.h"
 #include "nodes/extensible.h"
 #include "nodes/makefuncs.h"
 #include "nodes/nodeFuncs.h"
@@ -33,6 +34,7 @@
 #include "utils/guc_tables.h"
 #include "utils/json.h"
 #include "utils/lsyscache.h"
+#include "utils/memdebug.h"
 #include "utils/rel.h"
 #include "utils/ruleutils.h"
 #include "utils/snapmgr.h"
@@ -47,6 +49,15 @@ ExplainOneQuery_hook_type ExplainOneQuery_hook = NULL;
 /* Hook for plugins to get control in explain_get_index_name() */
 explain_get_index_name_hook_type explain_get_index_name_hook = NULL;
 
+/* Instrumentation structures for EXPLAIN's SERIALIZE option */
+typedef struct ExplSerInstrumentation
+{
+	uint64				bytesSent;		/* # of bytes serialized */
+	instr_time			timeSpent;		/* time spent serializing */
+	MemoryContextCounters memory;		/* memory context counters */
+	MemoryContextCounters emptyMemory;		/* memory context counters */
+	ExplainSerializeFormat format;		/* serialization format */
+} ExplSerInstrumentation;
 
 /* OR-able flags for ExplainXMLTag() */
 #define X_OPENING 0
@@ -60,6 +71,8 @@ static void ExplainOneQuery(Query *query, int cursorOptions,
 							QueryEnvironment *queryEnv);
 static void ExplainPrintJIT(ExplainState *es, int jit_flags,
 							JitInstrumentation *ji);
+static void ExplainPrintSerialize(ExplainState *es,
+								  ExplSerInstrumentation *instr);
 static void report_triggers(ResultRelInfo *rInfo, bool show_relname,
 							ExplainState *es);
 static double elapsed_time(instr_time *starttime);
@@ -156,7 +169,8 @@ static void ExplainJSONLineEnding(ExplainState *es);
 static void ExplainYAMLLineStarting(ExplainState *es);
 static void escape_yaml(StringInfo buf, const char *str);
 
-
+static DestReceiver *CreateExplainSerializeDestReceiver(ExplainState *es);
+static ExplSerInstrumentation GetSerializationMetrics(DestReceiver *dest);
 
 /*
  * ExplainQuery -
@@ -194,6 +208,34 @@ ExplainQuery(ParseState *pstate, ExplainStmt *stmt,
 			es->settings = defGetBoolean(opt);
 		else if (strcmp(opt->defname, "generic_plan") == 0)
 			es->generic = defGetBoolean(opt);
+		else if (strcmp(opt->defname, "serialize") == 0)
+		{
+			/* check the optional argument, if defined */
+			if (opt->arg)
+			{
+				char *p = defGetString(opt);
+				if (strcmp(p, "off") == 0)
+					es->serialize = EXPLAIN_SERIALIZE_NONE;
+				else if (strcmp(p, "text") == 0)
+					es->serialize = EXPLAIN_SERIALIZE_TEXT;
+				else if (strcmp(p, "binary") == 0)
+					es->serialize = EXPLAIN_SERIALIZE_BINARY;
+				else
+					ereport(ERROR,
+						(errcode(ERRCODE_INVALID_PARAMETER_VALUE),
+						 errmsg("unrecognized value for EXPLAIN option \"%s\": \"%s\"",
+								opt->defname, p),
+						 parser_errposition(pstate, opt->location)));
+			}
+			else
+			{
+				/*
+				 * The default serialization mode when the option is specified
+				 * is 'text'.
+				 */
+				es->serialize = EXPLAIN_SERIALIZE_TEXT;
+			}
+		}
 		else if (strcmp(opt->defname, "timing") == 0)
 		{
 			timing_set = true;
@@ -248,6 +290,12 @@ ExplainQuery(ParseState *pstate, ExplainStmt *stmt,
 				(errcode(ERRCODE_INVALID_PARAMETER_VALUE),
 				 errmsg("EXPLAIN option TIMING requires ANALYZE")));
 
+	/* check that serialize is used with EXPLAIN ANALYZE */
+	if (es->serialize != EXPLAIN_SERIALIZE_NONE && !es->analyze)
+		ereport(ERROR,
+				(errcode(ERRCODE_INVALID_PARAMETER_VALUE),
+				 errmsg("EXPLAIN option SERIALIZE requires ANALYZE")));
+
 	/* check that GENERIC_PLAN is not used with EXPLAIN ANALYZE */
 	if (es->generic && es->analyze)
 		ereport(ERROR,
@@ -566,6 +614,7 @@ ExplainOnePlan(PlannedStmt *plannedstmt, IntoClause *into, ExplainState *es,
 	double		totaltime = 0;
 	int			eflags;
 	int			instrument_option = 0;
+	ExplSerInstrumentation serializeMetrics = {0};
 
 	Assert(plannedstmt->commandType != CMD_UTILITY);
 
@@ -594,11 +643,15 @@ ExplainOnePlan(PlannedStmt *plannedstmt, IntoClause *into, ExplainState *es,
 	UpdateActiveSnapshotCommandId();
 
 	/*
-	 * Normally we discard the query's output, but if explaining CREATE TABLE
-	 * AS, we'd better use the appropriate tuple receiver.
+	 * We discard the output if we have no use for it.
+	 * If we're explaining CREATE TABLE AS, we'd better use the appropriate
+	 * tuple receiver, and when we EXPLAIN (ANALYZE, SERIALIZE) we better set
+	 * up a serializing (but discarding) DestReceiver.
 	 */
 	if (into)
 		dest = CreateIntoRelDestReceiver(into);
+	else if (es->analyze && es->serialize != EXPLAIN_SERIALIZE_NONE)
+		dest = CreateExplainSerializeDestReceiver(es);
 	else
 		dest = None_Receiver;
 
@@ -637,6 +690,13 @@ ExplainOnePlan(PlannedStmt *plannedstmt, IntoClause *into, ExplainState *es,
 		/* run cleanup too */
 		ExecutorFinish(queryDesc);
 
+		/* grab the metrics before we destroy the DestReceiver */
+		if (es->serialize)
+			serializeMetrics = GetSerializationMetrics(dest);
+
+		/* call the DestReceiver's destroy method even during explain */
+		dest->rDestroy(dest);
+
 		/* We can't run ExecutorEnd 'till we're done printing the stats... */
 		totaltime += elapsed_time(&starttime);
 	}
@@ -718,6 +778,10 @@ ExplainOnePlan(PlannedStmt *plannedstmt, IntoClause *into, ExplainState *es,
 		ExplainPropertyFloat("Execution Time", "ms", 1000.0 * totaltime, 3,
 							 es);
 
+	/* print the info about serialization of data */
+	if (es->summary && es->analyze && es->serialize != EXPLAIN_SERIALIZE_NONE)
+		ExplainPrintSerialize(es, &serializeMetrics);
+
 	ExplainCloseGroup("Query", NULL, true, es);
 }
 
@@ -5182,3 +5246,444 @@ escape_yaml(StringInfo buf, const char *str)
 {
 	escape_json(buf, str);
 }
+
+
+/*
+ * Serializing DestReceiver functions
+ *
+ * EXPLAIN (ANALYZE) can fail to provide accurate results for some queries,
+ * which can usually be attributed to a lack of deTOASTing when the resultset
+ * isn't fully serialized, or other features usually only accessed in the
+ * DestReceiver functions. To measure the overhead of transferring the
+ * resulting dataset of a query, the SERIALIZE option is added, which can show
+ * and measure the relevant metrics available to a PostgreSQL server. This
+ * allows the measuring of server time spent on deTOASTing, serialization and
+ * copying of data.
+ * 
+ * However, this critically does not measure the network performance: All
+ * measured timings are about processes inside the database.
+ */
+
+/* an attribute info cached for each column */
+typedef struct SerializeAttrInfo
+{								/* Per-attribute information */
+	Oid			typoutput;		/* Oid for the type's text output fn */
+	Oid			typsend;		/* Oid for the type's binary output fn */
+	bool		typisvarlena;	/* is it varlena (ie possibly toastable)? */
+	int8		format;			/* text of binary, like pq wire protocol */
+	FmgrInfo	finfo;			/* Precomputed call info for output fn */
+} SerializeAttrInfo;
+
+typedef struct SerializeDestReceiver
+{
+	/* receiver for the tuples, that just serializes */
+	DestReceiver		destRecevier;
+	MemoryContext		memoryContext;
+	ExplainState	   *es;					/* this EXPLAIN-statement's ExplainState */
+	int8				format;				/* text of binary, like pq wire protocol */
+	TupleDesc			attrinfo;
+	int					nattrs;
+	StringInfoData		buf;				/* serialization buffer to hold temporary data */
+	ExplSerInstrumentation metrics;			/* metrics */
+	SerializeAttrInfo	*infos;				/* Cached info about each attr */
+} SerializeDestReceiver;
+
+/*
+ * Get the lookup info that the row-callback of the receiver needs. this code
+ * is similar to the code from printup.c except that it doesn't do any actual
+ * output.
+ */
+static void
+serialize_prepare_info(SerializeDestReceiver *receiver, TupleDesc typeinfo,
+					   int nattrs)
+{
+	/* get rid of any old data */
+	if (receiver->infos)
+		pfree(receiver->infos);
+	receiver->infos = NULL;
+
+	receiver->attrinfo = typeinfo;
+	receiver->nattrs = nattrs;
+	if (nattrs <= 0)
+		return;
+
+	receiver->infos = (SerializeAttrInfo *)
+		palloc0(nattrs * sizeof(SerializeAttrInfo));
+
+	for (int i = 0; i < nattrs; i++)
+	{
+		SerializeAttrInfo *info = &receiver->infos[i];
+		Form_pg_attribute attr = TupleDescAttr(typeinfo, i);
+
+		info->format = receiver->format;
+
+		if (info->format == 0)
+		{
+			/* wire protocol format text */
+			getTypeOutputInfo(attr->atttypid,
+							  &info->typoutput,
+							  &info->typisvarlena);
+			fmgr_info(info->typoutput, &info->finfo);
+		}
+		else if (info->format == 1) 
+		{
+			/* wire protocol format binary */
+			getTypeBinaryOutputInfo(attr->atttypid,
+									&info->typsend,
+									&info->typisvarlena);
+			fmgr_info(info->typsend, &info->finfo);
+		}
+		else
+		{
+			ereport(ERROR,
+					(errcode(ERRCODE_INVALID_PARAMETER_VALUE),
+					 errmsg("unsupported format code: %d", info->format)));
+		}
+	}
+}
+
+
+
+/*
+ * serializeAnalyzeReceive - process tuples for EXPLAIN (SERIALIZE)
+ *
+ * This method receives the tuples/records during EXPLAIN (ANALYZE, SERIALIZE)
+ * and serializes them while measuring various things about that
+ * serialization, in a way that should be as close as possible to printtup.c
+ * without actually sending the data; thus capturing the overhead of
+ * deTOASTing and type's out/sendfuncs, which are not otherwise exercisable
+ * without actually hitting the network, thus increasing the number of paths
+ * you can exercise with EXPLAIN.
+ * 
+ * See also: printtup() in printtup.c, the older twin of this code.
+ */
+static bool
+serializeAnalyzeReceive(TupleTableSlot *slot, DestReceiver *self)
+{
+	TupleDesc		tupdesc;
+	MemoryContext	oldcontext;
+	SerializeDestReceiver *receiver = (SerializeDestReceiver*) self;
+	StringInfo		buf = &receiver->buf;
+	instr_time		start, end;
+
+	tupdesc  = slot->tts_tupleDescriptor;
+
+	/* only measure time if requested */
+	if (receiver->es->timing)
+		INSTR_TIME_SET_CURRENT(start);
+
+	/* Cache attribute infos and function oid if outdated */
+	if (receiver->attrinfo != tupdesc || receiver->nattrs != tupdesc->natts)
+		serialize_prepare_info(receiver, tupdesc, tupdesc->natts);
+
+	/* Fill all the slot's attributes, we can now use slot->tts_values
+	 * and its tts_isnull array which should be long enough even if added
+	 * a null-column to the table */
+	slot_getallattrs(slot);
+
+	oldcontext = MemoryContextSwitchTo(receiver->memoryContext);
+
+	/*
+	 * Note that we us an actual StringInfo buffer. This is to include the
+	 * cost of memory accesses and copy operations, reducing the number of
+	 * operations unique to the true printtup path vs the EXPLAIN (SERIALIZE)
+	 * path.
+	 */
+	pq_beginmessage_reuse(buf, 'D');
+	pq_sendint16(buf, receiver->nattrs);
+
+	/*
+	 * Iterate over all attributes of the tuple and invoke the output func
+	 * (or send function in case of a binary format). We'll completely ignore
+	 * the result. The MemoryContext is reset at the end of this per-tuple
+	 * callback anyhow.
+	 */
+	for (int i = 0; i < tupdesc->natts; i++)
+	{
+		SerializeAttrInfo *thisState = receiver->infos + i;
+		Datum		attr = slot->tts_values[i];
+
+		if (slot->tts_isnull[i])
+		{
+			pq_sendint32(buf, -1);
+			continue;
+		}
+
+		/*
+		 * Here we catch undefined bytes in datums that are returned to the
+		 * client without hitting disk; see comments at the related check in
+		 * PageAddItem().  This test is most useful for uncompressed,
+		 * non-external datums, but we're quite likely to see such here when
+		 * testing new C functions.
+		 */
+		if (thisState->typisvarlena)
+			VALGRIND_CHECK_MEM_IS_DEFINED(DatumGetPointer(attr),
+										  VARSIZE_ANY(attr));
+
+		if (thisState->format == 0)
+		{
+			/* Text output */
+			char	   *outputstr;
+
+			outputstr = OutputFunctionCall(&thisState->finfo, attr);
+			pq_sendcountedtext(buf, outputstr, strlen(outputstr), false);
+		}
+		else
+		{
+			/* Binary output */
+			bytea	   *outputbytes;
+			Assert(thisState->format == 1);
+
+			outputbytes = SendFunctionCall(&thisState->finfo, attr);
+			pq_sendint32(buf, VARSIZE(outputbytes) - VARHDRSZ);
+			pq_sendbytes(buf, VARDATA(outputbytes),
+						 VARSIZE(outputbytes) - VARHDRSZ);
+		}
+	}
+
+	/* finalize the timers */
+	if (receiver->es->timing)
+	{
+		INSTR_TIME_SET_CURRENT(end);
+		INSTR_TIME_ACCUM_DIFF(receiver->metrics.timeSpent, end, start);
+	}
+
+	/*
+	 * Register the size of the packet we would've sent to the client. The
+	 * buffer will be dropped on the next iteration.
+	 */
+	receiver->metrics.bytesSent += buf->len;
+
+	/*
+	 * Now that we're done processing we profile memory usage, if that was
+	 * requested by the user.
+	 */
+	if (receiver->es->memory)
+	{
+		MemoryContextCounters counters;
+		MemoryContextMemConsumed(receiver->memoryContext, &counters);
+
+		/*
+		 * Note: Although the freespace counter can (and likely does!)
+		 * underflow, that won't be an issue for the printed results: this
+		 * will only add used memory if more total space was allocated for
+		 * the context due to excessive allocations, but will always increase
+		 * the difference between the total totalspace and freespace by the
+		 * amount of bytes allocated each iteration by underflowing the
+		 * freespace counter. As memory used = totalspace - freespace, a
+		 * negative value for freespace also adds to the used counter, even
+		 * if it may be meaningless (and even nonsense!) on its own.
+		 *
+		 * However, it was decided to do it this way, to not overwhelm the
+		 * user with stats of at least 8kiB of Memory Allocated per output
+		 * tuple when that memory was actually retained in the Memory Context.
+		 */
+		receiver->metrics.memory.totalspace +=
+			counters.totalspace - receiver->metrics.emptyMemory.totalspace;
+		receiver->metrics.memory.freespace +=
+			counters.freespace - receiver->metrics.emptyMemory.freespace;
+		receiver->metrics.memory.freechunks +=
+			counters.freechunks - receiver->metrics.emptyMemory.freechunks;
+		receiver->metrics.memory.nblocks +=
+			counters.nblocks - receiver->metrics.emptyMemory.nblocks;
+	}
+
+	/* cleanup and reset */
+	MemoryContextSwitchTo(oldcontext);
+	MemoryContextReset(receiver->memoryContext);
+
+	return true;
+}
+
+static void
+serializeAnalyzeStartup(DestReceiver *self, int operation, TupleDesc typeinfo)
+{
+	SerializeDestReceiver *receiver = (SerializeDestReceiver*) self;
+	/* memory context for our work */
+	receiver->memoryContext = AllocSetContextCreate(CurrentMemoryContext,
+		"SerializeTupleReceive", ALLOCSET_DEFAULT_SIZES);
+
+	/* initialize various fields */
+	INSTR_TIME_SET_ZERO(receiver->metrics.timeSpent);
+	initStringInfo(&receiver->buf);
+
+	/*
+	 * We ensure our memory accounting is accurate by subtracting the memory
+	 * usage of the empty memory context from measurements, so that we don't
+	 * count these allocations every time we receive a tuple: we don't
+	 * re-allocate the memory context every iteration; we only reset it.
+	 */
+	if (receiver->es->memory)
+	{
+		MemoryContextMemConsumed(receiver->memoryContext,
+								 &receiver->metrics.emptyMemory);
+		/*
+		 * ... But do count this memory context's empty allocations once at
+		 * the start, so that using a memory context with lower base overhead
+		 * shows up in these metrics.
+		 */
+		receiver->metrics.memory = receiver->metrics.emptyMemory;
+	}
+
+	/*
+	 * Note that we don't actually serialize the RowDescriptor message here.
+	 * It is assumed that this has negligible overhead in the grand scheme of
+	 * things; but if so desired it can be updated without much issue.
+	 */
+
+	/* account for the attribute headers for send bytes */
+	receiver->metrics.bytesSent += 3; /* protocol message type and attribute-count */
+	for (int i = 0; i < typeinfo->natts; ++i)
+	{
+		Form_pg_attribute att = TupleDescAttr(typeinfo, i);
+		char	   *name = NameStr(att->attname);
+		Size		namelen = strlen(name);
+
+		/* convert from server encoding to client encoding if needed */
+		char *converted = pg_server_to_client(name, (int) namelen);
+
+		if (converted != name)
+		{
+			namelen = strlen(converted);
+			pfree(converted); /* don't leak it */
+		}
+
+		/* see printtup.h why we add 18 bytes here. These are the infos
+		 * needed for each attribute plus the attribute's name */
+		receiver->metrics.bytesSent += (int64) namelen + 1 + 18;
+	}
+}
+
+/*
+ * serializeAnalyzeShutdown - shut down the serializeAnalyze receiver
+ */
+static void
+serializeAnalyzeShutdown(DestReceiver *self)
+{
+	SerializeDestReceiver *receiver = (SerializeDestReceiver*) self;
+
+	if (receiver->infos)
+		pfree(receiver->infos);
+	receiver->infos = NULL;
+
+	if (receiver->buf.data)
+		pfree(receiver->buf.data);
+	receiver->buf.data = NULL;
+
+	if (receiver->memoryContext)
+		MemoryContextDelete(receiver->memoryContext);
+	receiver->memoryContext = NULL;
+}
+
+/*
+ * serializeAnalyzeShutdown - shut down the serializeAnalyze receiver
+ */
+static void
+serializeAnalyzeDestroy(DestReceiver *self)
+{
+	pfree(self);
+}
+
+/* Build a DestReceiver with EXPLAIN (SERIALIZE) instrumentation. */
+static DestReceiver *
+CreateExplainSerializeDestReceiver(ExplainState *es)
+{
+	SerializeDestReceiver *self;
+
+	self = (SerializeDestReceiver*) palloc0(sizeof(SerializeDestReceiver));
+
+	self->destRecevier.receiveSlot = serializeAnalyzeReceive;
+	self->destRecevier.rStartup = serializeAnalyzeStartup;
+	self->destRecevier.rShutdown = serializeAnalyzeShutdown;
+	self->destRecevier.rDestroy = serializeAnalyzeDestroy;
+	self->destRecevier.mydest = DestNone;
+
+	switch (es->serialize)
+	{
+		case EXPLAIN_SERIALIZE_NONE:
+			Assert(false);
+			elog(ERROR, "Invalid explain serialization format code %d", es->serialize);
+			break;
+		case EXPLAIN_SERIALIZE_TEXT:
+			self->format = 0; /* wire protocol format text */
+			break;
+		case EXPLAIN_SERIALIZE_BINARY:
+			self->format = 1; /* wire protocol format binary */
+			break;
+	}
+
+	/* store the ExplainState, for easier access to various fields */
+	self->es = es;
+
+	self->metrics.format = es->serialize;
+
+	return (DestReceiver *) self;
+}
+
+static ExplSerInstrumentation
+GetSerializationMetrics(DestReceiver *dest)
+{
+	return ((SerializeDestReceiver*) dest)->metrics;
+}
+
+/* Print data for the SERIALIZE option */
+static void
+ExplainPrintSerialize(ExplainState *es, ExplSerInstrumentation *instr)
+{
+	char	   *format;
+	if (instr->format == EXPLAIN_SERIALIZE_TEXT)
+		format = "text";
+	else
+	{
+		/* We shouldn't get called for EXPLAIN_SERIALIZE_NONE */
+		Assert(instr->format == EXPLAIN_SERIALIZE_BINARY);
+		format = "binary";
+	}
+
+	ExplainOpenGroup("Serialization", "Serialization", true, es);
+
+	if (es->format == EXPLAIN_FORMAT_TEXT)
+	{
+		ExplainIndentText(es);
+		appendStringInfoString(es->str, "Serialization:");
+		appendStringInfoChar(es->str, '\n');
+		es->indent++;
+		ExplainIndentText(es);
+
+		/* timing is optional */
+		if (es->timing)
+			appendStringInfo(es->str, "Serialize: time=%.3f ms  produced=%lld bytes  format=%s",
+							 1000.0 * INSTR_TIME_GET_DOUBLE(instr->timeSpent),
+							 (long long) instr->bytesSent,
+							 format);
+		else
+			appendStringInfo(es->str, "Serialize: produced=%lld bytes  format=%s",
+							 (long long) instr->bytesSent,
+							 format);
+
+		appendStringInfoChar(es->str, '\n');
+
+		/* output memory stats, if applicable */
+		if (es->memory)
+			show_memory_counters(es, &instr->memory);
+		es->indent--;
+	}
+	else
+	{
+		if (es->timing)
+		{
+			ExplainPropertyFloat("Time", "ms",
+								 1000.0 * INSTR_TIME_GET_DOUBLE(instr->timeSpent),
+								 3, es);
+		}
+
+		ExplainPropertyUInteger("Produced", "bytes",
+								instr->bytesSent, es);
+		ExplainPropertyText("Format", format, es);
+
+		if (es->memory)
+			show_memory_counters(es, &instr->memory);
+	}
+
+	ExplainCloseGroup("Serialization", "Serialization", true, es);
+}
diff --git a/src/include/commands/explain.h b/src/include/commands/explain.h
index 7c0f0b5636..ff32a79147 100644
--- a/src/include/commands/explain.h
+++ b/src/include/commands/explain.h
@@ -25,6 +25,13 @@ typedef enum ExplainFormat
 	EXPLAIN_FORMAT_YAML,
 } ExplainFormat;
 
+typedef enum ExplainSerializeFormat
+{
+	EXPLAIN_SERIALIZE_NONE,
+	EXPLAIN_SERIALIZE_TEXT,
+	EXPLAIN_SERIALIZE_BINARY,
+} ExplainSerializeFormat;
+
 typedef struct ExplainWorkersState
 {
 	int			num_workers;	/* # of worker processes the plan used */
@@ -48,6 +55,8 @@ typedef struct ExplainState
 	bool		memory;			/* print planner's memory usage information */
 	bool		settings;		/* print modified settings */
 	bool		generic;		/* generate a generic plan */
+	ExplainSerializeFormat serialize; /* do serialization (in ANALZYE) */
+
 	ExplainFormat format;		/* output format */
 	/* state for output formatting --- not reset for each new plan tree */
 	int			indent;			/* current indentation level */
diff --git a/src/test/regress/expected/explain.out b/src/test/regress/expected/explain.out
index 1299ee79ad..ab39c75606 100644
--- a/src/test/regress/expected/explain.out
+++ b/src/test/regress/expected/explain.out
@@ -135,7 +135,7 @@ select explain_filter('explain (analyze, buffers, format xml) select * from int8
  </explain>
 (1 row)
 
-select explain_filter('explain (analyze, buffers, format yaml) select * from int8_tbl i8');
+select explain_filter('explain (analyze, serialize, buffers, format yaml) select * from int8_tbl i8');
         explain_filter         
 -------------------------------
  - Plan:                      +
@@ -175,7 +175,11 @@ select explain_filter('explain (analyze, buffers, format yaml) select * from int
      Temp Written Blocks: N   +
    Planning Time: N.N         +
    Triggers:                  +
-   Execution Time: N.N
+   Execution Time: N.N        +
+   Serialization:             +
+     Time: N.N                +
+     Produced: N              +
+     Format: "text"
 (1 row)
 
 select explain_filter('explain (buffers, format text) select * from int8_tbl i8');
@@ -639,3 +643,52 @@ select explain_filter('explain (verbose) select * from int8_tbl i8');
  Query Identifier: N
 (3 rows)
 
+-- Test that SERIALIZE is accepted as a parameter to explain
+-- timings are filtered out by explain_filter
+create table test_serialize(id bigserial, val text);
+select explain_filter('explain (analyze,serialize) select * from test_serialize');
+                                          explain_filter                                          
+--------------------------------------------------------------------------------------------------
+ Seq Scan on test_serialize  (cost=N.N..N.N rows=N width=N) (actual time=N.N..N.N rows=N loops=N)
+ Planning Time: N.N ms
+ Execution Time: N.N ms
+ Serialization:
+   Serialize: time=N.N ms  produced=N bytes  format=text
+(5 rows)
+
+drop table test_serialize;
+-- Test that SERIALIZE BINARY is accepted as a parameter to explain
+create table test_serialize(id bigserial, val text);
+select explain_filter('explain (analyze,serialize binary, memory) select * from test_serialize');
+                                          explain_filter                                          
+--------------------------------------------------------------------------------------------------
+ Seq Scan on test_serialize  (cost=N.N..N.N rows=N width=N) (actual time=N.N..N.N rows=N loops=N)
+   Memory: used=N bytes  allocated=N bytes
+ Planning Time: N.N ms
+ Execution Time: N.N ms
+ Serialization:
+   Serialize: time=N.N ms  produced=N bytes  format=binary
+   Memory: used=N bytes  allocated=N bytes
+(7 rows)
+
+drop table test_serialize;
+-- Test that _SERIALIZE invalidparameter_ is not accepted as a parameter to explain
+create table test_serialize(id bigserial, val text);
+select explain_filter('explain (analyze,serialize invalidparameter) select * from test_serialize');
+ERROR:  unrecognized value for EXPLAIN option "serialize": "invalidparameter"
+LINE 1: select explain_filter('explain (analyze,serialize invalidpar...
+                         ^
+CONTEXT:  PL/pgSQL function explain_filter(text) line 5 at FOR over EXECUTE statement
+drop table test_serialize;
+-- Test SERIALIZE is _not_ accepted as a parameter to explain unless ANALYZE is specified
+create table test_serialize(id bigserial, val text);
+select explain_filter('explain (serialize) select * from test_serialize');
+ERROR:  EXPLAIN option SERIALIZE requires ANALYZE
+CONTEXT:  PL/pgSQL function explain_filter(text) line 5 at FOR over EXECUTE statement
+drop table test_serialize;
+-- Test SERIALIZEBINARY is _not_ accepted as a parameter to explain unless ANALYZE is specified
+create table test_serialize(id bigserial, val text);
+select explain_filter('explain (serialize binary) select * from test_serialize');
+ERROR:  EXPLAIN option SERIALIZE requires ANALYZE
+CONTEXT:  PL/pgSQL function explain_filter(text) line 5 at FOR over EXECUTE statement
+drop table test_serialize;
diff --git a/src/test/regress/sql/explain.sql b/src/test/regress/sql/explain.sql
index 2274dc1b5a..02604b0b14 100644
--- a/src/test/regress/sql/explain.sql
+++ b/src/test/regress/sql/explain.sql
@@ -66,7 +66,7 @@ select explain_filter('explain (analyze) select * from int8_tbl i8');
 select explain_filter('explain (analyze, verbose) select * from int8_tbl i8');
 select explain_filter('explain (analyze, buffers, format text) select * from int8_tbl i8');
 select explain_filter('explain (analyze, buffers, format xml) select * from int8_tbl i8');
-select explain_filter('explain (analyze, buffers, format yaml) select * from int8_tbl i8');
+select explain_filter('explain (analyze, serialize, buffers, format yaml) select * from int8_tbl i8');
 select explain_filter('explain (buffers, format text) select * from int8_tbl i8');
 select explain_filter('explain (buffers, format json) select * from int8_tbl i8');
 
@@ -162,3 +162,29 @@ select explain_filter('explain (verbose) select * from t1 where pg_temp.mysin(f1
 -- Test compute_query_id
 set compute_query_id = on;
 select explain_filter('explain (verbose) select * from int8_tbl i8');
+
+-- Test that SERIALIZE is accepted as a parameter to explain
+-- timings are filtered out by explain_filter
+create table test_serialize(id bigserial, val text);
+select explain_filter('explain (analyze,serialize) select * from test_serialize');
+drop table test_serialize;
+
+-- Test that SERIALIZE BINARY is accepted as a parameter to explain
+create table test_serialize(id bigserial, val text);
+select explain_filter('explain (analyze,serialize binary, memory) select * from test_serialize');
+drop table test_serialize;
+
+-- Test that _SERIALIZE invalidparameter_ is not accepted as a parameter to explain
+create table test_serialize(id bigserial, val text);
+select explain_filter('explain (analyze,serialize invalidparameter) select * from test_serialize');
+drop table test_serialize;
+
+-- Test SERIALIZE is _not_ accepted as a parameter to explain unless ANALYZE is specified
+create table test_serialize(id bigserial, val text);
+select explain_filter('explain (serialize) select * from test_serialize');
+drop table test_serialize;
+
+-- Test SERIALIZEBINARY is _not_ accepted as a parameter to explain unless ANALYZE is specified
+create table test_serialize(id bigserial, val text);
+select explain_filter('explain (serialize binary) select * from test_serialize');
+drop table test_serialize;
-- 
2.40.1

#17stepan rutz
stepan.rutz@gmx.de
In reply to: Matthias van de Meent (#16)
Re: Detoasting optionally to make Explain-Analyze less misleading

Hi Matthias, thanks for picking it up. I still believe this is valuable
to a lot of people out there. Thanks for dealing with my proposal.
Matthias, Tom, Tomas everyone.

Two (more or less) controversial remarks from side.

1. Actually serialization should be the default for "analyze" in
explain, as current analyze doesn't detoast and thus distorts the result
in extreme (but common) cases easily by many order of magnitude (see my
original video on that one). So current "explain analyze" only works for
some queries and since detoasting is really transparent, it is quite
something to leave detoasting out of explain analyze. This surprises
people all the time, since explain analyze suggests it "runs" the query
more realistically.

2. The bandwidth I computed in one of the previous versions of the patch
was certainly cluttering up the explain output and it is misleading yes,
but then again it performs a calculation people will now do in their
head. The "bandwidth" here is how much data your query gets out of
backend by means of the query and the deserialization. So of course if
you do id-lookups you get a single row and such querries do have a lower
data-retrieval bandwidth compared to bulk querries. However having some
measure of how fast data is delivered from the backend especially on
larger joins is still a good indicator of one aspect of a query.

Sorry for the remarks. Both are not really important, just restating my
points here. I understand the objections and reasons that speak against
both points and believe the current scope is just right.

/Stepan

Show quoted text

On 26.02.24 20:30, Matthias van de Meent wrote:

Hi,

I've taken the liberty to update this patch, and register it in the
commitfest app to not lose track of progress [0].

The attached v8 patch measures scratch memory allocations (with MEMORY
option), total time spent in serialization (with TIMING on, measures
are inclusive of unseparated memcpy to the message buffer), and a
count of produced bytes plus the output format used (text or binary).
It's a light rework of the earlier 0007 patch, I've reused tests and
some infrastructure, while the implementation details and comments
have been updated significantly.

I think we can bikeshed on format and names, but overall I think the
patch is in a very decent shape.

Stepan, thank you for your earlier work, and feel free to check it out
or pick it up again if you want to; else I'll try to get this done.

Kind regards,

Matthias van de Meent

[0] https://commitfest.postgresql.org/47/4852/

#18Matthias van de Meent
boekewurm+postgres@gmail.com
In reply to: stepan rutz (#17)
2 attachment(s)
Re: Detoasting optionally to make Explain-Analyze less misleading

On Mon, 26 Feb 2024 at 21:54, stepan rutz <stepan.rutz@gmx.de> wrote:

Hi Matthias, thanks for picking it up. I still believe this is valuable
to a lot of people out there. Thanks for dealing with my proposal.
Matthias, Tom, Tomas everyone.

Two (more or less) controversial remarks from side.

1. Actually serialization should be the default for "analyze" in
explain, as current analyze doesn't detoast and thus distorts the result
in extreme (but common) cases easily by many order of magnitude (see my
original video on that one). So current "explain analyze" only works for
some queries and since detoasting is really transparent, it is quite
something to leave detoasting out of explain analyze. This surprises
people all the time, since explain analyze suggests it "runs" the query
more realistically.

I'm not sure about this, but it could easily be a mid-beta decision
(if this is introduced before the feature freeze of 17, whenever that
is).

2. The bandwidth I computed in one of the previous versions of the patch
was certainly cluttering up the explain output and it is misleading yes,
but then again it performs a calculation people will now do in their
head. The "bandwidth" here is how much data your query gets out of
backend by means of the query and the deserialization. So of course if
you do id-lookups you get a single row and such querries do have a lower
data-retrieval bandwidth compared to bulk querries.

I think that's a job for post-processing the EXPLAIN output by the
user. If we don't give users the raw data, they won't be able to do
their own cross-referenced processing: "5MB/sec" doesn't tell you how
much time or data was actually spent.

However having some
measure of how fast data is delivered from the backend especially on
larger joins is still a good indicator of one aspect of a query.

I'm not sure about that. Network speed is a big limiting factor that
we can't measure here, and the size on disk is often going to be
smaller than the data size when transfered across the network.

Sorry for the remarks. Both are not really important, just restating my
points here. I understand the objections and reasons that speak against
both points and believe the current scope is just right.

No problem. Remarks from users (when built on solid arguments) are
always welcome, even if we may not always agree on the specifics.

------>8------

Attached is v9, which is rebased on master to handle 24eebc65's
changed signature of pq_sendcountedtext.
It now also includes autocompletion, and a second patch which adds
documentation to give users insights into this new addition to
EXPLAIN.

Kind regards,

Matthias van de Meent

Attachments:

v9-0002-Add-EXPLAIN-SERIALIZE-docs.patchapplication/octet-stream; name=v9-0002-Add-EXPLAIN-SERIALIZE-docs.patchDownload
From 2e4679bcafafdf3ace60f771f730a226ee682034 Mon Sep 17 00:00:00 2001
From: Matthias van de Meent <boekewurm+postgres@gmail.com>
Date: Fri, 1 Mar 2024 14:23:06 +0100
Subject: [PATCH v9 2/2] Add EXPLAIN (SERIALIZE) docs

---
 doc/src/sgml/ref/explain.sgml | 29 +++++++++++++++++++++++++++++
 1 file changed, 29 insertions(+)

diff --git a/doc/src/sgml/ref/explain.sgml b/doc/src/sgml/ref/explain.sgml
index a4b6564bdb..a1524046b9 100644
--- a/doc/src/sgml/ref/explain.sgml
+++ b/doc/src/sgml/ref/explain.sgml
@@ -41,6 +41,7 @@ EXPLAIN [ ( <replaceable class="parameter">option</replaceable> [, ...] ) ] <rep
     SETTINGS [ <replaceable class="parameter">boolean</replaceable> ]
     GENERIC_PLAN [ <replaceable class="parameter">boolean</replaceable> ]
     BUFFERS [ <replaceable class="parameter">boolean</replaceable> ]
+    SERIALIZE [ { NONE | TEXT | BINARY } ]
     WAL [ <replaceable class="parameter">boolean</replaceable> ]
     TIMING [ <replaceable class="parameter">boolean</replaceable> ]
     SUMMARY [ <replaceable class="parameter">boolean</replaceable> ]
@@ -206,6 +207,34 @@ ROLLBACK;
     </listitem>
    </varlistentry>
 
+   <varlistentry>
+    <term><literal>SERIALIZE</literal></term>
+    <listitem>
+     <para>
+      Specifies whether the query's results should be serialized as if the
+      data was sent to the client using textual or binary representations.
+      If the value value is <literal>NONE</literal> we don't process output
+      tuples, so data from <acronym>TOAST</acronym>ed values is not accessed
+      and EXPLAIN timings may be unexpected.  If the value is
+      <literal>TEXT</literal> or <literal>BINARY</literal>,
+      <productname>PostgreSQL</productname> will measure the size of the
+      would-be transmitted data after serializing the rows to
+      <literal>DataRow</literal> packets, using each column type's
+      <literal>output</literal> (for <literal>TEXT</literal>) or
+      <literal>send</literal> (for <literal>BINARY</literal>) functions for
+      serializing the column's values.  When the <literal>TIMING</literal>
+      option is enabled, the output also includes how much time was spent to
+      serialize the data.  When the <literal>MEMORY</literal> option is
+      enabled, the output will also show how much memory was used and
+      allocated during serialization.
+      This parameter may only be used when <literal>ANALYZE</literal> is also
+      enabled.  The default value for this parameter is <literal>NONE</literal>,
+      but when <literal>SERIALIZE</literal> is provided without parameters,
+      <literal>TEXT</literal> is used instead.
+     </para>
+    </listitem>
+   </varlistentry>
+
    <varlistentry>
     <term><literal>WAL</literal></term>
     <listitem>
-- 
2.40.1

v9-0001-Explain-Add-SERIALIZE-option.patchapplication/octet-stream; name=v9-0001-Explain-Add-SERIALIZE-option.patchDownload
From 257882eb9d6ad6d2c12d0c5be19d972a7f4f6618 Mon Sep 17 00:00:00 2001
From: Matthias van de Meent <boekewurm+postgres@gmail.com>
Date: Mon, 26 Feb 2024 20:17:40 +0100
Subject: [PATCH v9 1/2] Explain: Add SERIALIZE option

This option integrates with both MEMORY and TIMING, and is gated behind
ANALYZE.

EXPLAIN (SERIALIZE) allows analysis of the cost of actually serializing
the resultset, which usually can't be tested without actually consuming
the resultset on the client. As sending a resultset of gigabytes across
e.g. a VPN connection can be slow and expensive, this option increases
coverage of EXPLAIN and allows for further diagnostics in case of e.g.
attributes that are slow to deTOAST.

Future iterations may want to further instrument the deTOAST and ANALYZE
infrastructure to measure counts of deTOAST operations, but that is not
part of this patch.

Original patch by Stepan Rutz <stepan.rutz@gmx.de>, heavily modified by
Matthias van de Meent <boekewurm+postgres@gmail.com>
---
 src/backend/commands/explain.c        | 511 +++++++++++++++++++++++++-
 src/bin/psql/tab-complete.c           |   4 +-
 src/include/commands/explain.h        |   9 +
 src/test/regress/expected/explain.out |  57 ++-
 src/test/regress/sql/explain.sql      |  28 +-
 5 files changed, 602 insertions(+), 7 deletions(-)

diff --git a/src/backend/commands/explain.c b/src/backend/commands/explain.c
index a9d5056af4..9b1f4b6ba1 100644
--- a/src/backend/commands/explain.c
+++ b/src/backend/commands/explain.c
@@ -20,6 +20,7 @@
 #include "commands/prepare.h"
 #include "foreign/fdwapi.h"
 #include "jit/jit.h"
+#include "libpq/pqformat.h"
 #include "nodes/extensible.h"
 #include "nodes/makefuncs.h"
 #include "nodes/nodeFuncs.h"
@@ -32,6 +33,7 @@
 #include "utils/guc_tables.h"
 #include "utils/json.h"
 #include "utils/lsyscache.h"
+#include "utils/memdebug.h"
 #include "utils/rel.h"
 #include "utils/ruleutils.h"
 #include "utils/snapmgr.h"
@@ -46,6 +48,15 @@ ExplainOneQuery_hook_type ExplainOneQuery_hook = NULL;
 /* Hook for plugins to get control in explain_get_index_name() */
 explain_get_index_name_hook_type explain_get_index_name_hook = NULL;
 
+/* Instrumentation structures for EXPLAIN's SERIALIZE option */
+typedef struct ExplSerInstrumentation
+{
+	uint64				bytesSent;		/* # of bytes serialized */
+	instr_time			timeSpent;		/* time spent serializing */
+	MemoryContextCounters memory;		/* memory context counters */
+	MemoryContextCounters emptyMemory;		/* memory context counters */
+	ExplainSerializeFormat format;		/* serialization format */
+} ExplSerInstrumentation;
 
 /* OR-able flags for ExplainXMLTag() */
 #define X_OPENING 0
@@ -59,6 +70,8 @@ static void ExplainOneQuery(Query *query, int cursorOptions,
 							QueryEnvironment *queryEnv);
 static void ExplainPrintJIT(ExplainState *es, int jit_flags,
 							JitInstrumentation *ji);
+static void ExplainPrintSerialize(ExplainState *es,
+								  ExplSerInstrumentation *instr);
 static void report_triggers(ResultRelInfo *rInfo, bool show_relname,
 							ExplainState *es);
 static double elapsed_time(instr_time *starttime);
@@ -155,7 +168,8 @@ static void ExplainJSONLineEnding(ExplainState *es);
 static void ExplainYAMLLineStarting(ExplainState *es);
 static void escape_yaml(StringInfo buf, const char *str);
 
-
+static DestReceiver *CreateExplainSerializeDestReceiver(ExplainState *es);
+static ExplSerInstrumentation GetSerializationMetrics(DestReceiver *dest);
 
 /*
  * ExplainQuery -
@@ -193,6 +207,34 @@ ExplainQuery(ParseState *pstate, ExplainStmt *stmt,
 			es->settings = defGetBoolean(opt);
 		else if (strcmp(opt->defname, "generic_plan") == 0)
 			es->generic = defGetBoolean(opt);
+		else if (strcmp(opt->defname, "serialize") == 0)
+		{
+			/* check the optional argument, if defined */
+			if (opt->arg)
+			{
+				char *p = defGetString(opt);
+				if (strcmp(p, "off") == 0)
+					es->serialize = EXPLAIN_SERIALIZE_NONE;
+				else if (strcmp(p, "text") == 0)
+					es->serialize = EXPLAIN_SERIALIZE_TEXT;
+				else if (strcmp(p, "binary") == 0)
+					es->serialize = EXPLAIN_SERIALIZE_BINARY;
+				else
+					ereport(ERROR,
+						(errcode(ERRCODE_INVALID_PARAMETER_VALUE),
+						 errmsg("unrecognized value for EXPLAIN option \"%s\": \"%s\"",
+								opt->defname, p),
+						 parser_errposition(pstate, opt->location)));
+			}
+			else
+			{
+				/*
+				 * The default serialization mode when the option is specified
+				 * is 'text'.
+				 */
+				es->serialize = EXPLAIN_SERIALIZE_TEXT;
+			}
+		}
 		else if (strcmp(opt->defname, "timing") == 0)
 		{
 			timing_set = true;
@@ -247,6 +289,12 @@ ExplainQuery(ParseState *pstate, ExplainStmt *stmt,
 				(errcode(ERRCODE_INVALID_PARAMETER_VALUE),
 				 errmsg("EXPLAIN option TIMING requires ANALYZE")));
 
+	/* check that serialize is used with EXPLAIN ANALYZE */
+	if (es->serialize != EXPLAIN_SERIALIZE_NONE && !es->analyze)
+		ereport(ERROR,
+				(errcode(ERRCODE_INVALID_PARAMETER_VALUE),
+				 errmsg("EXPLAIN option SERIALIZE requires ANALYZE")));
+
 	/* check that GENERIC_PLAN is not used with EXPLAIN ANALYZE */
 	if (es->generic && es->analyze)
 		ereport(ERROR,
@@ -577,6 +625,7 @@ ExplainOnePlan(PlannedStmt *plannedstmt, IntoClause *into, ExplainState *es,
 	double		totaltime = 0;
 	int			eflags;
 	int			instrument_option = 0;
+	ExplSerInstrumentation serializeMetrics = {0};
 
 	Assert(plannedstmt->commandType != CMD_UTILITY);
 
@@ -605,11 +654,15 @@ ExplainOnePlan(PlannedStmt *plannedstmt, IntoClause *into, ExplainState *es,
 	UpdateActiveSnapshotCommandId();
 
 	/*
-	 * Normally we discard the query's output, but if explaining CREATE TABLE
-	 * AS, we'd better use the appropriate tuple receiver.
+	 * We discard the output if we have no use for it.
+	 * If we're explaining CREATE TABLE AS, we'd better use the appropriate
+	 * tuple receiver, and when we EXPLAIN (ANALYZE, SERIALIZE) we better set
+	 * up a serializing (but discarding) DestReceiver.
 	 */
 	if (into)
 		dest = CreateIntoRelDestReceiver(into);
+	else if (es->analyze && es->serialize != EXPLAIN_SERIALIZE_NONE)
+		dest = CreateExplainSerializeDestReceiver(es);
 	else
 		dest = None_Receiver;
 
@@ -648,6 +701,13 @@ ExplainOnePlan(PlannedStmt *plannedstmt, IntoClause *into, ExplainState *es,
 		/* run cleanup too */
 		ExecutorFinish(queryDesc);
 
+		/* grab the metrics before we destroy the DestReceiver */
+		if (es->serialize)
+			serializeMetrics = GetSerializationMetrics(dest);
+
+		/* call the DestReceiver's destroy method even during explain */
+		dest->rDestroy(dest);
+
 		/* We can't run ExecutorEnd 'till we're done printing the stats... */
 		totaltime += elapsed_time(&starttime);
 	}
@@ -729,6 +789,10 @@ ExplainOnePlan(PlannedStmt *plannedstmt, IntoClause *into, ExplainState *es,
 		ExplainPropertyFloat("Execution Time", "ms", 1000.0 * totaltime, 3,
 							 es);
 
+	/* print the info about serialization of data */
+	if (es->summary && es->analyze && es->serialize != EXPLAIN_SERIALIZE_NONE)
+		ExplainPrintSerialize(es, &serializeMetrics);
+
 	ExplainCloseGroup("Query", NULL, true, es);
 }
 
@@ -5193,3 +5257,444 @@ escape_yaml(StringInfo buf, const char *str)
 {
 	escape_json(buf, str);
 }
+
+
+/*
+ * Serializing DestReceiver functions
+ *
+ * EXPLAIN (ANALYZE) can fail to provide accurate results for some queries,
+ * which can usually be attributed to a lack of deTOASTing when the resultset
+ * isn't fully serialized, or other features usually only accessed in the
+ * DestReceiver functions. To measure the overhead of transferring the
+ * resulting dataset of a query, the SERIALIZE option is added, which can show
+ * and measure the relevant metrics available to a PostgreSQL server. This
+ * allows the measuring of server time spent on deTOASTing, serialization and
+ * copying of data.
+ * 
+ * However, this critically does not measure the network performance: All
+ * measured timings are about processes inside the database.
+ */
+
+/* an attribute info cached for each column */
+typedef struct SerializeAttrInfo
+{								/* Per-attribute information */
+	Oid			typoutput;		/* Oid for the type's text output fn */
+	Oid			typsend;		/* Oid for the type's binary output fn */
+	bool		typisvarlena;	/* is it varlena (ie possibly toastable)? */
+	int8		format;			/* text of binary, like pq wire protocol */
+	FmgrInfo	finfo;			/* Precomputed call info for output fn */
+} SerializeAttrInfo;
+
+typedef struct SerializeDestReceiver
+{
+	/* receiver for the tuples, that just serializes */
+	DestReceiver		destRecevier;
+	MemoryContext		memoryContext;
+	ExplainState	   *es;					/* this EXPLAIN-statement's ExplainState */
+	int8				format;				/* text of binary, like pq wire protocol */
+	TupleDesc			attrinfo;
+	int					nattrs;
+	StringInfoData		buf;				/* serialization buffer to hold temporary data */
+	ExplSerInstrumentation metrics;			/* metrics */
+	SerializeAttrInfo	*infos;				/* Cached info about each attr */
+} SerializeDestReceiver;
+
+/*
+ * Get the lookup info that the row-callback of the receiver needs. this code
+ * is similar to the code from printup.c except that it doesn't do any actual
+ * output.
+ */
+static void
+serialize_prepare_info(SerializeDestReceiver *receiver, TupleDesc typeinfo,
+					   int nattrs)
+{
+	/* get rid of any old data */
+	if (receiver->infos)
+		pfree(receiver->infos);
+	receiver->infos = NULL;
+
+	receiver->attrinfo = typeinfo;
+	receiver->nattrs = nattrs;
+	if (nattrs <= 0)
+		return;
+
+	receiver->infos = (SerializeAttrInfo *)
+		palloc0(nattrs * sizeof(SerializeAttrInfo));
+
+	for (int i = 0; i < nattrs; i++)
+	{
+		SerializeAttrInfo *info = &receiver->infos[i];
+		Form_pg_attribute attr = TupleDescAttr(typeinfo, i);
+
+		info->format = receiver->format;
+
+		if (info->format == 0)
+		{
+			/* wire protocol format text */
+			getTypeOutputInfo(attr->atttypid,
+							  &info->typoutput,
+							  &info->typisvarlena);
+			fmgr_info(info->typoutput, &info->finfo);
+		}
+		else if (info->format == 1) 
+		{
+			/* wire protocol format binary */
+			getTypeBinaryOutputInfo(attr->atttypid,
+									&info->typsend,
+									&info->typisvarlena);
+			fmgr_info(info->typsend, &info->finfo);
+		}
+		else
+		{
+			ereport(ERROR,
+					(errcode(ERRCODE_INVALID_PARAMETER_VALUE),
+					 errmsg("unsupported format code: %d", info->format)));
+		}
+	}
+}
+
+
+
+/*
+ * serializeAnalyzeReceive - process tuples for EXPLAIN (SERIALIZE)
+ *
+ * This method receives the tuples/records during EXPLAIN (ANALYZE, SERIALIZE)
+ * and serializes them while measuring various things about that
+ * serialization, in a way that should be as close as possible to printtup.c
+ * without actually sending the data; thus capturing the overhead of
+ * deTOASTing and type's out/sendfuncs, which are not otherwise exercisable
+ * without actually hitting the network, thus increasing the number of paths
+ * you can exercise with EXPLAIN.
+ * 
+ * See also: printtup() in printtup.c, the older twin of this code.
+ */
+static bool
+serializeAnalyzeReceive(TupleTableSlot *slot, DestReceiver *self)
+{
+	TupleDesc		tupdesc;
+	MemoryContext	oldcontext;
+	SerializeDestReceiver *receiver = (SerializeDestReceiver*) self;
+	StringInfo		buf = &receiver->buf;
+	instr_time		start, end;
+
+	tupdesc  = slot->tts_tupleDescriptor;
+
+	/* only measure time if requested */
+	if (receiver->es->timing)
+		INSTR_TIME_SET_CURRENT(start);
+
+	/* Cache attribute infos and function oid if outdated */
+	if (receiver->attrinfo != tupdesc || receiver->nattrs != tupdesc->natts)
+		serialize_prepare_info(receiver, tupdesc, tupdesc->natts);
+
+	/* Fill all the slot's attributes, we can now use slot->tts_values
+	 * and its tts_isnull array which should be long enough even if added
+	 * a null-column to the table */
+	slot_getallattrs(slot);
+
+	oldcontext = MemoryContextSwitchTo(receiver->memoryContext);
+
+	/*
+	 * Note that we us an actual StringInfo buffer. This is to include the
+	 * cost of memory accesses and copy operations, reducing the number of
+	 * operations unique to the true printtup path vs the EXPLAIN (SERIALIZE)
+	 * path.
+	 */
+	pq_beginmessage_reuse(buf, 'D');
+	pq_sendint16(buf, receiver->nattrs);
+
+	/*
+	 * Iterate over all attributes of the tuple and invoke the output func
+	 * (or send function in case of a binary format). We'll completely ignore
+	 * the result. The MemoryContext is reset at the end of this per-tuple
+	 * callback anyhow.
+	 */
+	for (int i = 0; i < tupdesc->natts; i++)
+	{
+		SerializeAttrInfo *thisState = receiver->infos + i;
+		Datum		attr = slot->tts_values[i];
+
+		if (slot->tts_isnull[i])
+		{
+			pq_sendint32(buf, -1);
+			continue;
+		}
+
+		/*
+		 * Here we catch undefined bytes in datums that are returned to the
+		 * client without hitting disk; see comments at the related check in
+		 * PageAddItem().  This test is most useful for uncompressed,
+		 * non-external datums, but we're quite likely to see such here when
+		 * testing new C functions.
+		 */
+		if (thisState->typisvarlena)
+			VALGRIND_CHECK_MEM_IS_DEFINED(DatumGetPointer(attr),
+										  VARSIZE_ANY(attr));
+
+		if (thisState->format == 0)
+		{
+			/* Text output */
+			char	   *outputstr;
+
+			outputstr = OutputFunctionCall(&thisState->finfo, attr);
+			pq_sendcountedtext(buf, outputstr, strlen(outputstr));
+		}
+		else
+		{
+			/* Binary output */
+			bytea	   *outputbytes;
+			Assert(thisState->format == 1);
+
+			outputbytes = SendFunctionCall(&thisState->finfo, attr);
+			pq_sendint32(buf, VARSIZE(outputbytes) - VARHDRSZ);
+			pq_sendbytes(buf, VARDATA(outputbytes),
+						 VARSIZE(outputbytes) - VARHDRSZ);
+		}
+	}
+
+	/* finalize the timers */
+	if (receiver->es->timing)
+	{
+		INSTR_TIME_SET_CURRENT(end);
+		INSTR_TIME_ACCUM_DIFF(receiver->metrics.timeSpent, end, start);
+	}
+
+	/*
+	 * Register the size of the packet we would've sent to the client. The
+	 * buffer will be dropped on the next iteration.
+	 */
+	receiver->metrics.bytesSent += buf->len;
+
+	/*
+	 * Now that we're done processing we profile memory usage, if that was
+	 * requested by the user.
+	 */
+	if (receiver->es->memory)
+	{
+		MemoryContextCounters counters;
+		MemoryContextMemConsumed(receiver->memoryContext, &counters);
+
+		/*
+		 * Note: Although the freespace counter can (and likely does!)
+		 * underflow, that won't be an issue for the printed results: this
+		 * will only add used memory if more total space was allocated for
+		 * the context due to excessive allocations, but will always increase
+		 * the difference between the total totalspace and freespace by the
+		 * amount of bytes allocated each iteration by underflowing the
+		 * freespace counter. As memory used = totalspace - freespace, a
+		 * negative value for freespace also adds to the used counter, even
+		 * if it may be meaningless (and even nonsense!) on its own.
+		 *
+		 * However, it was decided to do it this way, to not overwhelm the
+		 * user with stats of at least 8kiB of Memory Allocated per output
+		 * tuple when that memory was actually retained in the Memory Context.
+		 */
+		receiver->metrics.memory.totalspace +=
+			counters.totalspace - receiver->metrics.emptyMemory.totalspace;
+		receiver->metrics.memory.freespace +=
+			counters.freespace - receiver->metrics.emptyMemory.freespace;
+		receiver->metrics.memory.freechunks +=
+			counters.freechunks - receiver->metrics.emptyMemory.freechunks;
+		receiver->metrics.memory.nblocks +=
+			counters.nblocks - receiver->metrics.emptyMemory.nblocks;
+	}
+
+	/* cleanup and reset */
+	MemoryContextSwitchTo(oldcontext);
+	MemoryContextReset(receiver->memoryContext);
+
+	return true;
+}
+
+static void
+serializeAnalyzeStartup(DestReceiver *self, int operation, TupleDesc typeinfo)
+{
+	SerializeDestReceiver *receiver = (SerializeDestReceiver*) self;
+	/* memory context for our work */
+	receiver->memoryContext = AllocSetContextCreate(CurrentMemoryContext,
+		"SerializeTupleReceive", ALLOCSET_DEFAULT_SIZES);
+
+	/* initialize various fields */
+	INSTR_TIME_SET_ZERO(receiver->metrics.timeSpent);
+	initStringInfo(&receiver->buf);
+
+	/*
+	 * We ensure our memory accounting is accurate by subtracting the memory
+	 * usage of the empty memory context from measurements, so that we don't
+	 * count these allocations every time we receive a tuple: we don't
+	 * re-allocate the memory context every iteration; we only reset it.
+	 */
+	if (receiver->es->memory)
+	{
+		MemoryContextMemConsumed(receiver->memoryContext,
+								 &receiver->metrics.emptyMemory);
+		/*
+		 * ... But do count this memory context's empty allocations once at
+		 * the start, so that using a memory context with lower base overhead
+		 * shows up in these metrics.
+		 */
+		receiver->metrics.memory = receiver->metrics.emptyMemory;
+	}
+
+	/*
+	 * Note that we don't actually serialize the RowDescriptor message here.
+	 * It is assumed that this has negligible overhead in the grand scheme of
+	 * things; but if so desired it can be updated without much issue.
+	 */
+
+	/* account for the attribute headers for send bytes */
+	receiver->metrics.bytesSent += 3; /* protocol message type and attribute-count */
+	for (int i = 0; i < typeinfo->natts; ++i)
+	{
+		Form_pg_attribute att = TupleDescAttr(typeinfo, i);
+		char	   *name = NameStr(att->attname);
+		Size		namelen = strlen(name);
+
+		/* convert from server encoding to client encoding if needed */
+		char *converted = pg_server_to_client(name, (int) namelen);
+
+		if (converted != name)
+		{
+			namelen = strlen(converted);
+			pfree(converted); /* don't leak it */
+		}
+
+		/* see printtup.h why we add 18 bytes here. These are the infos
+		 * needed for each attribute plus the attribute's name */
+		receiver->metrics.bytesSent += (int64) namelen + 1 + 18;
+	}
+}
+
+/*
+ * serializeAnalyzeShutdown - shut down the serializeAnalyze receiver
+ */
+static void
+serializeAnalyzeShutdown(DestReceiver *self)
+{
+	SerializeDestReceiver *receiver = (SerializeDestReceiver*) self;
+
+	if (receiver->infos)
+		pfree(receiver->infos);
+	receiver->infos = NULL;
+
+	if (receiver->buf.data)
+		pfree(receiver->buf.data);
+	receiver->buf.data = NULL;
+
+	if (receiver->memoryContext)
+		MemoryContextDelete(receiver->memoryContext);
+	receiver->memoryContext = NULL;
+}
+
+/*
+ * serializeAnalyzeShutdown - shut down the serializeAnalyze receiver
+ */
+static void
+serializeAnalyzeDestroy(DestReceiver *self)
+{
+	pfree(self);
+}
+
+/* Build a DestReceiver with EXPLAIN (SERIALIZE) instrumentation. */
+static DestReceiver *
+CreateExplainSerializeDestReceiver(ExplainState *es)
+{
+	SerializeDestReceiver *self;
+
+	self = (SerializeDestReceiver*) palloc0(sizeof(SerializeDestReceiver));
+
+	self->destRecevier.receiveSlot = serializeAnalyzeReceive;
+	self->destRecevier.rStartup = serializeAnalyzeStartup;
+	self->destRecevier.rShutdown = serializeAnalyzeShutdown;
+	self->destRecevier.rDestroy = serializeAnalyzeDestroy;
+	self->destRecevier.mydest = DestNone;
+
+	switch (es->serialize)
+	{
+		case EXPLAIN_SERIALIZE_NONE:
+			Assert(false);
+			elog(ERROR, "Invalid explain serialization format code %d", es->serialize);
+			break;
+		case EXPLAIN_SERIALIZE_TEXT:
+			self->format = 0; /* wire protocol format text */
+			break;
+		case EXPLAIN_SERIALIZE_BINARY:
+			self->format = 1; /* wire protocol format binary */
+			break;
+	}
+
+	/* store the ExplainState, for easier access to various fields */
+	self->es = es;
+
+	self->metrics.format = es->serialize;
+
+	return (DestReceiver *) self;
+}
+
+static ExplSerInstrumentation
+GetSerializationMetrics(DestReceiver *dest)
+{
+	return ((SerializeDestReceiver*) dest)->metrics;
+}
+
+/* Print data for the SERIALIZE option */
+static void
+ExplainPrintSerialize(ExplainState *es, ExplSerInstrumentation *instr)
+{
+	char	   *format;
+	if (instr->format == EXPLAIN_SERIALIZE_TEXT)
+		format = "text";
+	else
+	{
+		/* We shouldn't get called for EXPLAIN_SERIALIZE_NONE */
+		Assert(instr->format == EXPLAIN_SERIALIZE_BINARY);
+		format = "binary";
+	}
+
+	ExplainOpenGroup("Serialization", "Serialization", true, es);
+
+	if (es->format == EXPLAIN_FORMAT_TEXT)
+	{
+		ExplainIndentText(es);
+		appendStringInfoString(es->str, "Serialization:");
+		appendStringInfoChar(es->str, '\n');
+		es->indent++;
+		ExplainIndentText(es);
+
+		/* timing is optional */
+		if (es->timing)
+			appendStringInfo(es->str, "Serialize: time=%.3f ms  produced=%lld bytes  format=%s",
+							 1000.0 * INSTR_TIME_GET_DOUBLE(instr->timeSpent),
+							 (long long) instr->bytesSent,
+							 format);
+		else
+			appendStringInfo(es->str, "Serialize: produced=%lld bytes  format=%s",
+							 (long long) instr->bytesSent,
+							 format);
+
+		appendStringInfoChar(es->str, '\n');
+
+		/* output memory stats, if applicable */
+		if (es->memory)
+			show_memory_counters(es, &instr->memory);
+		es->indent--;
+	}
+	else
+	{
+		if (es->timing)
+		{
+			ExplainPropertyFloat("Time", "ms",
+								 1000.0 * INSTR_TIME_GET_DOUBLE(instr->timeSpent),
+								 3, es);
+		}
+
+		ExplainPropertyUInteger("Produced", "bytes",
+								instr->bytesSent, es);
+		ExplainPropertyText("Format", format, es);
+
+		if (es->memory)
+			show_memory_counters(es, &instr->memory);
+	}
+
+	ExplainCloseGroup("Serialization", "Serialization", true, es);
+}
diff --git a/src/bin/psql/tab-complete.c b/src/bin/psql/tab-complete.c
index 73133ce735..822d65b71e 100644
--- a/src/bin/psql/tab-complete.c
+++ b/src/bin/psql/tab-complete.c
@@ -3849,9 +3849,11 @@ psql_completion(const char *text, int start, int end)
 		 */
 		if (ends_with(prev_wd, '(') || ends_with(prev_wd, ','))
 			COMPLETE_WITH("ANALYZE", "VERBOSE", "COSTS", "SETTINGS", "GENERIC_PLAN",
-						  "BUFFERS", "WAL", "TIMING", "SUMMARY", "FORMAT");
+						  "BUFFERS", "SERIALIZE", "WAL", "TIMING", "SUMMARY", "FORMAT");
 		else if (TailMatches("ANALYZE|VERBOSE|COSTS|SETTINGS|GENERIC_PLAN|BUFFERS|WAL|TIMING|SUMMARY"))
 			COMPLETE_WITH("ON", "OFF");
+		else if (TailMatches("SERIALIZE"))
+			COMPLETE_WITH("NONE", "TEXT", "BINARY");
 		else if (TailMatches("FORMAT"))
 			COMPLETE_WITH("TEXT", "XML", "JSON", "YAML");
 	}
diff --git a/src/include/commands/explain.h b/src/include/commands/explain.h
index cf195f1359..b4bd6a2fcf 100644
--- a/src/include/commands/explain.h
+++ b/src/include/commands/explain.h
@@ -25,6 +25,13 @@ typedef enum ExplainFormat
 	EXPLAIN_FORMAT_YAML,
 } ExplainFormat;
 
+typedef enum ExplainSerializeFormat
+{
+	EXPLAIN_SERIALIZE_NONE,
+	EXPLAIN_SERIALIZE_TEXT,
+	EXPLAIN_SERIALIZE_BINARY,
+} ExplainSerializeFormat;
+
 typedef struct ExplainWorkersState
 {
 	int			num_workers;	/* # of worker processes the plan used */
@@ -48,6 +55,8 @@ typedef struct ExplainState
 	bool		memory;			/* print planner's memory usage information */
 	bool		settings;		/* print modified settings */
 	bool		generic;		/* generate a generic plan */
+	ExplainSerializeFormat serialize; /* do serialization (in ANALZYE) */
+
 	ExplainFormat format;		/* output format */
 	/* state for output formatting --- not reset for each new plan tree */
 	int			indent;			/* current indentation level */
diff --git a/src/test/regress/expected/explain.out b/src/test/regress/expected/explain.out
index 1299ee79ad..ab39c75606 100644
--- a/src/test/regress/expected/explain.out
+++ b/src/test/regress/expected/explain.out
@@ -135,7 +135,7 @@ select explain_filter('explain (analyze, buffers, format xml) select * from int8
  </explain>
 (1 row)
 
-select explain_filter('explain (analyze, buffers, format yaml) select * from int8_tbl i8');
+select explain_filter('explain (analyze, serialize, buffers, format yaml) select * from int8_tbl i8');
         explain_filter         
 -------------------------------
  - Plan:                      +
@@ -175,7 +175,11 @@ select explain_filter('explain (analyze, buffers, format yaml) select * from int
      Temp Written Blocks: N   +
    Planning Time: N.N         +
    Triggers:                  +
-   Execution Time: N.N
+   Execution Time: N.N        +
+   Serialization:             +
+     Time: N.N                +
+     Produced: N              +
+     Format: "text"
 (1 row)
 
 select explain_filter('explain (buffers, format text) select * from int8_tbl i8');
@@ -639,3 +643,52 @@ select explain_filter('explain (verbose) select * from int8_tbl i8');
  Query Identifier: N
 (3 rows)
 
+-- Test that SERIALIZE is accepted as a parameter to explain
+-- timings are filtered out by explain_filter
+create table test_serialize(id bigserial, val text);
+select explain_filter('explain (analyze,serialize) select * from test_serialize');
+                                          explain_filter                                          
+--------------------------------------------------------------------------------------------------
+ Seq Scan on test_serialize  (cost=N.N..N.N rows=N width=N) (actual time=N.N..N.N rows=N loops=N)
+ Planning Time: N.N ms
+ Execution Time: N.N ms
+ Serialization:
+   Serialize: time=N.N ms  produced=N bytes  format=text
+(5 rows)
+
+drop table test_serialize;
+-- Test that SERIALIZE BINARY is accepted as a parameter to explain
+create table test_serialize(id bigserial, val text);
+select explain_filter('explain (analyze,serialize binary, memory) select * from test_serialize');
+                                          explain_filter                                          
+--------------------------------------------------------------------------------------------------
+ Seq Scan on test_serialize  (cost=N.N..N.N rows=N width=N) (actual time=N.N..N.N rows=N loops=N)
+   Memory: used=N bytes  allocated=N bytes
+ Planning Time: N.N ms
+ Execution Time: N.N ms
+ Serialization:
+   Serialize: time=N.N ms  produced=N bytes  format=binary
+   Memory: used=N bytes  allocated=N bytes
+(7 rows)
+
+drop table test_serialize;
+-- Test that _SERIALIZE invalidparameter_ is not accepted as a parameter to explain
+create table test_serialize(id bigserial, val text);
+select explain_filter('explain (analyze,serialize invalidparameter) select * from test_serialize');
+ERROR:  unrecognized value for EXPLAIN option "serialize": "invalidparameter"
+LINE 1: select explain_filter('explain (analyze,serialize invalidpar...
+                         ^
+CONTEXT:  PL/pgSQL function explain_filter(text) line 5 at FOR over EXECUTE statement
+drop table test_serialize;
+-- Test SERIALIZE is _not_ accepted as a parameter to explain unless ANALYZE is specified
+create table test_serialize(id bigserial, val text);
+select explain_filter('explain (serialize) select * from test_serialize');
+ERROR:  EXPLAIN option SERIALIZE requires ANALYZE
+CONTEXT:  PL/pgSQL function explain_filter(text) line 5 at FOR over EXECUTE statement
+drop table test_serialize;
+-- Test SERIALIZEBINARY is _not_ accepted as a parameter to explain unless ANALYZE is specified
+create table test_serialize(id bigserial, val text);
+select explain_filter('explain (serialize binary) select * from test_serialize');
+ERROR:  EXPLAIN option SERIALIZE requires ANALYZE
+CONTEXT:  PL/pgSQL function explain_filter(text) line 5 at FOR over EXECUTE statement
+drop table test_serialize;
diff --git a/src/test/regress/sql/explain.sql b/src/test/regress/sql/explain.sql
index 2274dc1b5a..02604b0b14 100644
--- a/src/test/regress/sql/explain.sql
+++ b/src/test/regress/sql/explain.sql
@@ -66,7 +66,7 @@ select explain_filter('explain (analyze) select * from int8_tbl i8');
 select explain_filter('explain (analyze, verbose) select * from int8_tbl i8');
 select explain_filter('explain (analyze, buffers, format text) select * from int8_tbl i8');
 select explain_filter('explain (analyze, buffers, format xml) select * from int8_tbl i8');
-select explain_filter('explain (analyze, buffers, format yaml) select * from int8_tbl i8');
+select explain_filter('explain (analyze, serialize, buffers, format yaml) select * from int8_tbl i8');
 select explain_filter('explain (buffers, format text) select * from int8_tbl i8');
 select explain_filter('explain (buffers, format json) select * from int8_tbl i8');
 
@@ -162,3 +162,29 @@ select explain_filter('explain (verbose) select * from t1 where pg_temp.mysin(f1
 -- Test compute_query_id
 set compute_query_id = on;
 select explain_filter('explain (verbose) select * from int8_tbl i8');
+
+-- Test that SERIALIZE is accepted as a parameter to explain
+-- timings are filtered out by explain_filter
+create table test_serialize(id bigserial, val text);
+select explain_filter('explain (analyze,serialize) select * from test_serialize');
+drop table test_serialize;
+
+-- Test that SERIALIZE BINARY is accepted as a parameter to explain
+create table test_serialize(id bigserial, val text);
+select explain_filter('explain (analyze,serialize binary, memory) select * from test_serialize');
+drop table test_serialize;
+
+-- Test that _SERIALIZE invalidparameter_ is not accepted as a parameter to explain
+create table test_serialize(id bigserial, val text);
+select explain_filter('explain (analyze,serialize invalidparameter) select * from test_serialize');
+drop table test_serialize;
+
+-- Test SERIALIZE is _not_ accepted as a parameter to explain unless ANALYZE is specified
+create table test_serialize(id bigserial, val text);
+select explain_filter('explain (serialize) select * from test_serialize');
+drop table test_serialize;
+
+-- Test SERIALIZEBINARY is _not_ accepted as a parameter to explain unless ANALYZE is specified
+create table test_serialize(id bigserial, val text);
+select explain_filter('explain (serialize binary) select * from test_serialize');
+drop table test_serialize;
-- 
2.40.1

#19Tom Lane
tgl@sss.pgh.pa.us
In reply to: Matthias van de Meent (#18)
Re: Detoasting optionally to make Explain-Analyze less misleading

Matthias van de Meent <boekewurm+postgres@gmail.com> writes:

Attached is v9, which is rebased on master to handle 24eebc65's
changed signature of pq_sendcountedtext.
It now also includes autocompletion, and a second patch which adds
documentation to give users insights into this new addition to
EXPLAIN.

I took a quick look through this. Some comments in no particular
order:

Documentation is not optional, so I don't really see the point of
splitting this into two patches.

IIUC, it's not possible to use the SERIALIZE option when explaining
CREATE TABLE AS, because you can't install the instrumentation tuple
receiver when the IntoRel one is needed. I think that's fine because
no serialization would happen in that case anyway, but should we
throw an error if that combination is requested? Blindly reporting
that zero bytes were serialized seems like it'd confuse people.

I'd lose the stuff about measuring memory consumption. Nobody asked
for that and the total is completely misleading, because in reality
we'll reclaim the memory used after each row. It would allow cutting
the text-mode output down to one line, too, instead of having your
own format that's not like anything else.

I thought the upthread agreement was to display the amount of
data sent rounded to kilobytes, so why is the code displaying
an exact byte count?

I don't especially care for magic numbers like these:

+		/* see printtup.h why we add 18 bytes here. These are the infos
+		 * needed for each attribute plus the attribute's name */
+		receiver->metrics.bytesSent += (int64) namelen + 1 + 18;

If the protocol is ever changed in a way that invalidates this,
there's about 0 chance that somebody would remember to touch
this code.

However, isn't the bottom half of serializeAnalyzeStartup doing
exactly what the comment above it says we don't do, that is accounting
for the RowDescription message? Frankly I agree with the comment that
it's not worth troubling over, so I'd just drop that code rather than
finding a solution for the magic-number problem.

Don't bother with duplicating valgrind-related logic in
serializeAnalyzeReceive --- that's irrelevant to actual users.

This seems like cowboy coding:

+ self->destRecevier.mydest = DestNone;

You should define a new value of the CommandDest enum and
integrate this receiver type into the support functions
in dest.c.

BTW, "destRecevier" is misspelled...

regards, tom lane

#20Matthias van de Meent
boekewurm+postgres@gmail.com
In reply to: Tom Lane (#19)
1 attachment(s)
Re: Detoasting optionally to make Explain-Analyze less misleading

On Tue, 2 Apr 2024 at 17:47, Tom Lane <tgl@sss.pgh.pa.us> wrote:

Matthias van de Meent <boekewurm+postgres@gmail.com> writes:

Attached is v9, which is rebased on master to handle 24eebc65's
changed signature of pq_sendcountedtext.
It now also includes autocompletion, and a second patch which adds
documentation to give users insights into this new addition to
EXPLAIN.

I took a quick look through this. Some comments in no particular
order:

Thanks!

Documentation is not optional, so I don't really see the point of
splitting this into two patches.

I've seen the inverse several times, but I've merged them in the
attached version 10.

IIUC, it's not possible to use the SERIALIZE option when explaining
CREATE TABLE AS, because you can't install the instrumentation tuple
receiver when the IntoRel one is needed. I think that's fine because
no serialization would happen in that case anyway, but should we
throw an error if that combination is requested? Blindly reporting
that zero bytes were serialized seems like it'd confuse people.

I think it's easily explained as no rows were transfered to the
client. If there is actual confusion, we can document it, but
confusing disk with network is not a case I'd protect against. See
also: EXPLAIN (ANALYZE, SERIALIZE) INSERT without the RETURNING
clause.

I'd lose the stuff about measuring memory consumption. Nobody asked
for that and the total is completely misleading, because in reality
we'll reclaim the memory used after each row. It would allow cutting
the text-mode output down to one line, too, instead of having your
own format that's not like anything else.

Done.

I thought the upthread agreement was to display the amount of
data sent rounded to kilobytes, so why is the code displaying
an exact byte count?

Probably it was because the other explain code I referenced was using
bytes in the json/yaml format. Fixed.

I don't especially care for magic numbers like these:

+               /* see printtup.h why we add 18 bytes here. These are the infos
+                * needed for each attribute plus the attribute's name */
+               receiver->metrics.bytesSent += (int64) namelen + 1 + 18;

If the protocol is ever changed in a way that invalidates this,
there's about 0 chance that somebody would remember to touch
this code.
However, isn't the bottom half of serializeAnalyzeStartup doing
exactly what the comment above it says we don't do, that is accounting
for the RowDescription message? Frankly I agree with the comment that
it's not worth troubling over, so I'd just drop that code rather than
finding a solution for the magic-number problem.

In the comment above I intended to explain that it takes negligible
time to serialize the RowDescription message (when compared to all
other tasks of explain), so skipping the actual writing of the message
would be fine.
I'm not sure I agree with not including the size of RowDescription
itself though, as wide results can have a very large RowDescription
overhead; up to several times the returned data in cases where few
rows are returned.

Either way, I've removed that part of the code.

Don't bother with duplicating valgrind-related logic in
serializeAnalyzeReceive --- that's irrelevant to actual users.

Removed. I've instead added buffer usage, as I realised that wasn't
covered yet, and quite important to detect excessive detoasting (it's
not covered at the top-level scan).

This seems like cowboy coding:

+ self->destRecevier.mydest = DestNone;

You should define a new value of the CommandDest enum and
integrate this receiver type into the support functions
in dest.c.

Done.

BTW, "destRecevier" is misspelled...

Thanks, fixed.

Kind regards,

Matthias van de Meent.

Attachments:

v10-0001-Explain-Add-SERIALIZE-option.patchapplication/octet-stream; name=v10-0001-Explain-Add-SERIALIZE-option.patchDownload
From 90447a90fca3c5a32c16509a296a8a9fefaaf5f8 Mon Sep 17 00:00:00 2001
From: Matthias van de Meent <boekewurm+postgres@gmail.com>
Date: Mon, 26 Feb 2024 20:17:40 +0100
Subject: [PATCH v10] Explain: Add SERIALIZE option

This option integrates with TIMING, and is gated behind ANALYZE.

EXPLAIN (SERIALIZE) allows analysis of the cost of actually serializing
the resultset, which usually can't be tested without actually consuming
the resultset on the client. As sending a resultset of gigabytes across
e.g. a VPN connection can be slow and expensive, this option increases
coverage of EXPLAIN and allows for further diagnostics in case of e.g.
attributes that are slow to deTOAST.

Future iterations may want to further instrument the deTOAST and ANALYZE
infrastructure to measure counts of deTOAST operations, but that is not
part of this patch.

Original patch by Stepan Rutz <stepan.rutz@gmx.de>, heavily modified by
myself (Matthias van de Meent <boekewurm+postgres@gmail.com>)

Reviewed-by: Tom Lane <tgl@sss.pgh.pa.us>
---
 doc/src/sgml/ref/explain.sgml         |  27 ++
 src/backend/commands/explain.c        | 444 +++++++++++++++++++++++++-
 src/backend/tcop/dest.c               |   7 +
 src/include/commands/explain.h        |  11 +
 src/include/tcop/dest.h               |   2 +
 src/test/regress/expected/explain.out |  61 +++-
 src/test/regress/sql/explain.sql      |  28 +-
 src/tools/pgindent/typedefs.list      |   1 +
 8 files changed, 576 insertions(+), 5 deletions(-)

diff --git a/doc/src/sgml/ref/explain.sgml b/doc/src/sgml/ref/explain.sgml
index a4b6564bdb..237fbe00d1 100644
--- a/doc/src/sgml/ref/explain.sgml
+++ b/doc/src/sgml/ref/explain.sgml
@@ -41,6 +41,7 @@ EXPLAIN [ ( <replaceable class="parameter">option</replaceable> [, ...] ) ] <rep
     SETTINGS [ <replaceable class="parameter">boolean</replaceable> ]
     GENERIC_PLAN [ <replaceable class="parameter">boolean</replaceable> ]
     BUFFERS [ <replaceable class="parameter">boolean</replaceable> ]
+    SERIALIZE [ { NONE | TEXT | BINARY } ]
     WAL [ <replaceable class="parameter">boolean</replaceable> ]
     TIMING [ <replaceable class="parameter">boolean</replaceable> ]
     SUMMARY [ <replaceable class="parameter">boolean</replaceable> ]
@@ -206,6 +207,32 @@ ROLLBACK;
     </listitem>
    </varlistentry>
 
+   <varlistentry>
+    <term><literal>SERIALIZE</literal></term>
+    <listitem>
+     <para>
+      Specifies whether the query's results should be serialized as if the
+      data was sent to the client using textual or binary representations.
+      If the value value is <literal>NONE</literal> we don't process output
+      tuples, so data from <acronym>TOAST</acronym>ed values is not accessed
+      and EXPLAIN timings may be unexpected.  If the value is
+      <literal>TEXT</literal> or <literal>BINARY</literal>,
+      <productname>PostgreSQL</productname> will measure the size of the
+      would-be transmitted data after serializing the rows to
+      <literal>DataRow</literal> packets, using each column type's
+      <literal>output</literal> (for <literal>TEXT</literal>) or
+      <literal>send</literal> (for <literal>BINARY</literal>) functions for
+      serializing the column's values.  When the <literal>TIMING</literal>
+      option is enabled, the output also includes how much time was spent to
+      serialize the data.
+      This parameter may only be used when <literal>ANALYZE</literal> is also
+      enabled.  The default value for this parameter is <literal>NONE</literal>,
+      but when <literal>SERIALIZE</literal> is provided without parameters,
+      <literal>TEXT</literal> is used instead.
+     </para>
+    </listitem>
+   </varlistentry>
+
    <varlistentry>
     <term><literal>WAL</literal></term>
     <listitem>
diff --git a/src/backend/commands/explain.c b/src/backend/commands/explain.c
index 926d70afaf..19e9805245 100644
--- a/src/backend/commands/explain.c
+++ b/src/backend/commands/explain.c
@@ -20,6 +20,7 @@
 #include "commands/prepare.h"
 #include "foreign/fdwapi.h"
 #include "jit/jit.h"
+#include "libpq/pqformat.h"
 #include "nodes/extensible.h"
 #include "nodes/makefuncs.h"
 #include "nodes/nodeFuncs.h"
@@ -32,6 +33,7 @@
 #include "utils/guc_tables.h"
 #include "utils/json.h"
 #include "utils/lsyscache.h"
+#include "utils/memdebug.h"
 #include "utils/rel.h"
 #include "utils/ruleutils.h"
 #include "utils/snapmgr.h"
@@ -46,6 +48,14 @@ ExplainOneQuery_hook_type ExplainOneQuery_hook = NULL;
 /* Hook for plugins to get control in explain_get_index_name() */
 explain_get_index_name_hook_type explain_get_index_name_hook = NULL;
 
+/* Instrumentation structures for EXPLAIN's SERIALIZE option */
+typedef struct ExplSerInstrumentation
+{
+	uint64		bytesSent;		/* # of bytes serialized */
+	instr_time	timeSpent;		/* time spent serializing */
+	BufferUsage bufferUsage;	/* buffers accessed for serialization */
+	ExplainSerializeFormat serialize;	/* serialization format */
+}			ExplSerInstrumentation;
 
 /* OR-able flags for ExplainXMLTag() */
 #define X_OPENING 0
@@ -59,6 +69,8 @@ static void ExplainOneQuery(Query *query, int cursorOptions,
 							QueryEnvironment *queryEnv);
 static void ExplainPrintJIT(ExplainState *es, int jit_flags,
 							JitInstrumentation *ji);
+static void ExplainPrintSerialize(ExplainState *es,
+								  ExplSerInstrumentation * instr);
 static void report_triggers(ResultRelInfo *rInfo, bool show_relname,
 							ExplainState *es);
 static double elapsed_time(instr_time *starttime);
@@ -154,7 +166,7 @@ static void ExplainJSONLineEnding(ExplainState *es);
 static void ExplainYAMLLineStarting(ExplainState *es);
 static void escape_yaml(StringInfo buf, const char *str);
 
-
+static ExplSerInstrumentation GetSerializationMetrics(DestReceiver *dest);
 
 /*
  * ExplainQuery -
@@ -192,6 +204,35 @@ ExplainQuery(ParseState *pstate, ExplainStmt *stmt,
 			es->settings = defGetBoolean(opt);
 		else if (strcmp(opt->defname, "generic_plan") == 0)
 			es->generic = defGetBoolean(opt);
+		else if (strcmp(opt->defname, "serialize") == 0)
+		{
+			/* check the optional argument, if defined */
+			if (opt->arg)
+			{
+				char	   *p = defGetString(opt);
+
+				if (strcmp(p, "off") == 0 || strcmp(p, "none") == 0)
+					es->serialize = EXPLAIN_SERIALIZE_NONE;
+				else if (strcmp(p, "text") == 0)
+					es->serialize = EXPLAIN_SERIALIZE_TEXT;
+				else if (strcmp(p, "binary") == 0)
+					es->serialize = EXPLAIN_SERIALIZE_BINARY;
+				else
+					ereport(ERROR,
+							(errcode(ERRCODE_INVALID_PARAMETER_VALUE),
+							 errmsg("unrecognized value for EXPLAIN option \"%s\": \"%s\"",
+									opt->defname, p),
+							 parser_errposition(pstate, opt->location)));
+			}
+			else
+			{
+				/*
+				 * The default serialization mode when the option is specified
+				 * is 'text'.
+				 */
+				es->serialize = EXPLAIN_SERIALIZE_TEXT;
+			}
+		}
 		else if (strcmp(opt->defname, "timing") == 0)
 		{
 			timing_set = true;
@@ -246,6 +287,12 @@ ExplainQuery(ParseState *pstate, ExplainStmt *stmt,
 				(errcode(ERRCODE_INVALID_PARAMETER_VALUE),
 				 errmsg("EXPLAIN option TIMING requires ANALYZE")));
 
+	/* check that serialize is used with EXPLAIN ANALYZE */
+	if (es->serialize != EXPLAIN_SERIALIZE_NONE && !es->analyze)
+		ereport(ERROR,
+				(errcode(ERRCODE_INVALID_PARAMETER_VALUE),
+				 errmsg("EXPLAIN option SERIALIZE requires ANALYZE")));
+
 	/* check that GENERIC_PLAN is not used with EXPLAIN ANALYZE */
 	if (es->generic && es->analyze)
 		ereport(ERROR,
@@ -576,6 +623,7 @@ ExplainOnePlan(PlannedStmt *plannedstmt, IntoClause *into, ExplainState *es,
 	double		totaltime = 0;
 	int			eflags;
 	int			instrument_option = 0;
+	ExplSerInstrumentation serializeMetrics = {0};
 
 	Assert(plannedstmt->commandType != CMD_UTILITY);
 
@@ -604,11 +652,15 @@ ExplainOnePlan(PlannedStmt *plannedstmt, IntoClause *into, ExplainState *es,
 	UpdateActiveSnapshotCommandId();
 
 	/*
-	 * Normally we discard the query's output, but if explaining CREATE TABLE
-	 * AS, we'd better use the appropriate tuple receiver.
+	 * We discard the output if we have no use for it. If we're explaining
+	 * CREATE TABLE AS, we'd better use the appropriate tuple receiver, and
+	 * when we EXPLAIN (ANALYZE, SERIALIZE) we better set up a serializing
+	 * (but discarding) DestReceiver.
 	 */
 	if (into)
 		dest = CreateIntoRelDestReceiver(into);
+	else if (es->analyze && es->serialize != EXPLAIN_SERIALIZE_NONE)
+		dest = CreateExplainSerializeDestReceiver(es);
 	else
 		dest = None_Receiver;
 
@@ -647,6 +699,13 @@ ExplainOnePlan(PlannedStmt *plannedstmt, IntoClause *into, ExplainState *es,
 		/* run cleanup too */
 		ExecutorFinish(queryDesc);
 
+		/* grab the metrics before we destroy the DestReceiver */
+		if (es->serialize != EXPLAIN_SERIALIZE_NONE)
+			serializeMetrics = GetSerializationMetrics(dest);
+
+		/* call the DestReceiver's destroy method even during explain */
+		dest->rDestroy(dest);
+
 		/* We can't run ExecutorEnd 'till we're done printing the stats... */
 		totaltime += elapsed_time(&starttime);
 	}
@@ -700,6 +759,10 @@ ExplainOnePlan(PlannedStmt *plannedstmt, IntoClause *into, ExplainState *es,
 	if (es->costs)
 		ExplainPrintJITSummary(es, queryDesc);
 
+	/* print the info about serialization of data */
+	if (es->analyze && es->serialize != EXPLAIN_SERIALIZE_NONE)
+		ExplainPrintSerialize(es, &serializeMetrics);
+
 	/*
 	 * Close down the query and free resources.  Include time for this in the
 	 * total execution time (although it should be pretty minimal).
@@ -5161,3 +5224,378 @@ escape_yaml(StringInfo buf, const char *str)
 {
 	escape_json(buf, str);
 }
+
+
+/*
+ * Serializing DestReceiver functions
+ *
+ * EXPLAIN (ANALYZE) can fail to provide accurate results for some queries,
+ * which can usually be attributed to a lack of deTOASTing when the resultset
+ * isn't fully serialized, or other features usually only accessed in the
+ * DestReceiver functions. To measure the overhead of transferring the
+ * resulting dataset of a query, the SERIALIZE option is added, which can show
+ * and measure the relevant metrics available to a PostgreSQL server. This
+ * allows the measuring of server time spent on deTOASTing, serialization and
+ * copying of data.
+ *
+ * However, this critically does not measure the network performance: All
+ * measured timings are about processes inside the database.
+ */
+
+/* an attribute info cached for each column */
+typedef struct SerializeAttrInfo
+{								/* Per-attribute information */
+	Oid			typoutput;		/* Oid for the type's text output fn */
+	Oid			typsend;		/* Oid for the type's binary output fn */
+	bool		typisvarlena;	/* is it varlena (ie possibly toastable)? */
+	int8		format;			/* text of binary, like pq wire protocol */
+	FmgrInfo	finfo;			/* Precomputed call info for output fn */
+}			SerializeAttrInfo;
+
+/*
+ * A DestReceiver for query tuples, that serializes passed rows to RowData
+ * messages while measuring time taken in serialization and total serialized
+ * size, while never sending the data to the client.
+ */
+typedef struct SerializeDestReceiver
+{
+	DestReceiver pub;
+	MemoryContext memoryContext;
+	ExplainState *es;			/* this EXPLAIN-statement's ExplainState */
+	int8		format;			/* text or binary, like pq wire protocol */
+	TupleDesc	tupdesc;		/* the output tuple desc */
+	SerializeAttrInfo *attrInfo;	/* Cached info about each attr */
+	int			nattrs;
+	StringInfoData buf;			/* serialization buffer to hold the output
+								 * data */
+	ExplSerInstrumentation metrics; /* metrics */
+} SerializeDestReceiver;
+
+/*
+ * Get the lookup info that the row-callback of the receiver needs. this code
+ * is similar to the code from printup.c except that it doesn't do any actual
+ * output.
+ */
+static void
+serialize_prepare_info(SerializeDestReceiver *receiver, TupleDesc typeinfo,
+					   int nattrs)
+{
+	/* get rid of any old data */
+	if (receiver->attrInfo)
+		pfree(receiver->attrInfo);
+	receiver->attrInfo = NULL;
+
+	receiver->tupdesc = typeinfo;
+	receiver->nattrs = nattrs;
+	if (nattrs <= 0)
+		return;
+
+	receiver->attrInfo = (SerializeAttrInfo *)
+		palloc0(nattrs * sizeof(SerializeAttrInfo));
+
+	for (int i = 0; i < nattrs; i++)
+	{
+		SerializeAttrInfo *info = &receiver->attrInfo[i];
+		Form_pg_attribute attr = TupleDescAttr(typeinfo, i);
+
+		info->format = receiver->format;
+
+		if (info->format == 0)
+		{
+			/* wire protocol format text */
+			getTypeOutputInfo(attr->atttypid,
+							  &info->typoutput,
+							  &info->typisvarlena);
+			fmgr_info(info->typoutput, &info->finfo);
+		}
+		else if (info->format == 1)
+		{
+			/* wire protocol format binary */
+			getTypeBinaryOutputInfo(attr->atttypid,
+									&info->typsend,
+									&info->typisvarlena);
+			fmgr_info(info->typsend, &info->finfo);
+		}
+		else
+		{
+			ereport(ERROR,
+					(errcode(ERRCODE_INVALID_PARAMETER_VALUE),
+					 errmsg("unsupported format code: %d", info->format)));
+		}
+	}
+}
+
+
+
+/*
+ * serializeAnalyzeReceive - process tuples for EXPLAIN (SERIALIZE)
+ *
+ * This method receives the tuples/records during EXPLAIN (ANALYZE, SERIALIZE)
+ * and serializes them while measuring various things about that
+ * serialization, in a way that should be as close as possible to printtup.c
+ * without actually sending the data; thus capturing the overhead of
+ * deTOASTing and type's out/sendfuncs, which are not otherwise exercisable
+ * without actually hitting the network, thus increasing the number of paths
+ * you can exercise with EXPLAIN.
+ *
+ * See also: printtup() in printtup.c, the older twin of this code.
+ */
+static bool
+serializeAnalyzeReceive(TupleTableSlot *slot, DestReceiver *self)
+{
+	TupleDesc	tupdesc;
+	MemoryContext oldcontext;
+	SerializeDestReceiver *receiver = (SerializeDestReceiver *) self;
+	StringInfo	buf = &receiver->buf;
+	instr_time	start,
+				end;
+	BufferUsage instr_start;
+
+	tupdesc = slot->tts_tupleDescriptor;
+
+	/* only measure time, buffers if requested */
+	if (receiver->es->timing)
+		INSTR_TIME_SET_CURRENT(start);
+	if (receiver->es->buffers)
+		instr_start = pgBufferUsage;
+
+	/* Cache attribute infos and function oid if outdated */
+	if (receiver->tupdesc != tupdesc || receiver->nattrs != tupdesc->natts)
+		serialize_prepare_info(receiver, tupdesc, tupdesc->natts);
+
+	/*
+	 * Fill all the slot's attributes, we can now use slot->tts_values and its
+	 * tts_isnull array which should be long enough even if added a
+	 * null-column to the table
+	 */
+	slot_getallattrs(slot);
+
+	oldcontext = MemoryContextSwitchTo(receiver->memoryContext);
+
+	/*
+	 * Note that we us an actual StringInfo buffer. This is to include the
+	 * cost of memory accesses and copy operations, reducing the number of
+	 * operations unique to the true printtup path vs the EXPLAIN (SERIALIZE)
+	 * path.
+	 */
+	pq_beginmessage_reuse(buf, 'D');
+	pq_sendint16(buf, receiver->nattrs);
+
+	/*
+	 * Iterate over all attributes of the tuple and invoke the output func (or
+	 * send function in case of a binary format). We'll completely ignore the
+	 * result. The MemoryContext is reset at the end of this per-tuple
+	 * callback anyhow.
+	 */
+	for (int i = 0; i < tupdesc->natts; i++)
+	{
+		SerializeAttrInfo *thisState = receiver->attrInfo + i;
+		Datum		attr = slot->tts_values[i];
+
+		if (slot->tts_isnull[i])
+		{
+			pq_sendint32(buf, -1);
+			continue;
+		}
+
+		if (thisState->format == 0)
+		{
+			/* Text output */
+			char	   *outputstr;
+
+			outputstr = OutputFunctionCall(&thisState->finfo, attr);
+			pq_sendcountedtext(buf, outputstr, strlen(outputstr));
+		}
+		else
+		{
+			/* Binary output */
+			bytea	   *outputbytes;
+
+			Assert(thisState->format == 1);
+
+			outputbytes = SendFunctionCall(&thisState->finfo, attr);
+			pq_sendint32(buf, VARSIZE(outputbytes) - VARHDRSZ);
+			pq_sendbytes(buf, VARDATA(outputbytes),
+						 VARSIZE(outputbytes) - VARHDRSZ);
+		}
+	}
+
+	/* finalize the timers */
+	if (receiver->es->timing)
+	{
+		INSTR_TIME_SET_CURRENT(end);
+		INSTR_TIME_ACCUM_DIFF(receiver->metrics.timeSpent, end, start);
+	}
+
+	/* finalize buffer metrics */
+	if (receiver->es->buffers)
+		BufferUsageAccumDiff(&receiver->metrics.bufferUsage,
+							 &pgBufferUsage,
+							 &instr_start);
+
+	/*
+	 * Register the size of the packet we would've sent to the client. The
+	 * buffer will be dropped on the next iteration.
+	 */
+	receiver->metrics.bytesSent += buf->len;
+
+	/* cleanup and reset */
+	MemoryContextSwitchTo(oldcontext);
+	MemoryContextReset(receiver->memoryContext);
+
+	return true;
+}
+
+static void
+serializeAnalyzeStartup(DestReceiver *self, int operation, TupleDesc typeinfo)
+{
+	SerializeDestReceiver *receiver = (SerializeDestReceiver *) self;
+
+	Assert(receiver->es != NULL);
+
+	switch (receiver->es->serialize)
+	{
+		case EXPLAIN_SERIALIZE_NONE:
+			Assert(false);
+			elog(ERROR, "Invalid explain serialization format code %d", receiver->es->serialize);
+			break;
+		case EXPLAIN_SERIALIZE_TEXT:
+			receiver->format = 0;	/* wire protocol format text */
+			break;
+		case EXPLAIN_SERIALIZE_BINARY:
+			receiver->format = 1;	/* wire protocol format binary */
+			break;
+	}
+
+	memset(&receiver->metrics, 0, sizeof(ExplSerInstrumentation));
+	receiver->metrics.serialize = receiver->es->serialize;
+
+	/* memory context for our work */
+	receiver->memoryContext = AllocSetContextCreate(CurrentMemoryContext,
+													"SerializeTupleReceive", ALLOCSET_DEFAULT_SIZES);
+
+	/* initialize various fields */
+	INSTR_TIME_SET_ZERO(receiver->metrics.timeSpent);
+	initStringInfo(&receiver->buf);
+}
+
+/*
+ * serializeAnalyzeShutdown - shut down the serializeAnalyze receiver
+ */
+static void
+serializeAnalyzeShutdown(DestReceiver *self)
+{
+	SerializeDestReceiver *receiver = (SerializeDestReceiver *) self;
+
+	if (receiver->attrInfo)
+		pfree(receiver->attrInfo);
+	receiver->attrInfo = NULL;
+
+	if (receiver->buf.data)
+		pfree(receiver->buf.data);
+	receiver->buf.data = NULL;
+
+	if (receiver->memoryContext)
+		MemoryContextDelete(receiver->memoryContext);
+	receiver->memoryContext = NULL;
+}
+
+/*
+ * serializeAnalyzeShutdown - shut down the serializeAnalyze receiver
+ */
+static void
+serializeAnalyzeDestroy(DestReceiver *self)
+{
+	pfree(self);
+}
+
+/* Build a DestReceiver with EXPLAIN (SERIALIZE) instrumentation. */
+DestReceiver *
+CreateExplainSerializeDestReceiver(ExplainState *es)
+{
+	SerializeDestReceiver *self;
+
+	self = (SerializeDestReceiver *) palloc0(sizeof(SerializeDestReceiver));
+
+	self->pub.receiveSlot = serializeAnalyzeReceive;
+	self->pub.rStartup = serializeAnalyzeStartup;
+	self->pub.rShutdown = serializeAnalyzeShutdown;
+	self->pub.rDestroy = serializeAnalyzeDestroy;
+	self->pub.mydest = DestExplainSerialize;
+
+	self->es = es;
+
+	return (DestReceiver *) self;
+}
+
+static ExplSerInstrumentation
+GetSerializationMetrics(DestReceiver *dest)
+{
+	ExplSerInstrumentation empty;
+
+	if (dest->mydest == DestExplainSerialize)
+		return ((SerializeDestReceiver *) dest)->metrics;
+
+	memset(&empty, 0, sizeof(ExplSerInstrumentation));
+	return empty;
+}
+
+/* Print data for the SERIALIZE option */
+static void
+ExplainPrintSerialize(ExplainState *es, ExplSerInstrumentation * instr)
+{
+	char	   *format;
+
+	Assert(es->serialize == instr->serialize);
+	/* We shouldn't get called for EXPLAIN_SERIALIZE_NONE */
+	if (instr->serialize == EXPLAIN_SERIALIZE_TEXT)
+		format = "text";
+	else
+	{
+		Assert(instr->serialize == EXPLAIN_SERIALIZE_BINARY);
+		format = "binary";
+	}
+
+	ExplainOpenGroup("Serialization", "Serialization", true, es);
+
+	if (es->format == EXPLAIN_FORMAT_TEXT)
+	{
+		ExplainIndentText(es);
+
+		/* timing is optional */
+		if (es->timing)
+			appendStringInfo(es->str, "Serialization: time=%.3f  produced=" INT64_FORMAT "kB  format=%s",
+							 1000.0 * INSTR_TIME_GET_DOUBLE(instr->timeSpent),
+							 instr->bytesSent / 1024,
+							 format);
+		else
+			appendStringInfo(es->str, "Serialization: produced=" INT64_FORMAT "kB  format=%s",
+							 instr->bytesSent / 1024,
+							 format);
+
+		appendStringInfoChar(es->str, '\n');
+
+		if (es->buffers && peek_buffer_usage(es, &instr->bufferUsage))
+		{
+			es->indent++;
+			show_buffer_usage(es, &instr->bufferUsage);
+			es->indent--;
+		}
+	}
+	else
+	{
+		if (es->timing)
+		{
+			ExplainPropertyFloat("Time", "ms",
+								 1000.0 * INSTR_TIME_GET_DOUBLE(instr->timeSpent),
+								 3, es);
+		}
+
+		ExplainPropertyUInteger("Written Bytes", "bytes",
+								instr->bytesSent, es);
+		ExplainPropertyText("Format", format, es);
+		show_buffer_usage(es, &instr->bufferUsage);
+	}
+
+	ExplainCloseGroup("Serialization", "Serialization", true, es);
+}
diff --git a/src/backend/tcop/dest.c b/src/backend/tcop/dest.c
index 6d727ae24f..96f80b3046 100644
--- a/src/backend/tcop/dest.c
+++ b/src/backend/tcop/dest.c
@@ -33,6 +33,7 @@
 #include "access/xact.h"
 #include "commands/copy.h"
 #include "commands/createas.h"
+#include "commands/explain.h"
 #include "commands/matview.h"
 #include "executor/functions.h"
 #include "executor/tqueue.h"
@@ -151,6 +152,9 @@ CreateDestReceiver(CommandDest dest)
 
 		case DestTupleQueue:
 			return CreateTupleQueueDestReceiver(NULL);
+
+		case DestExplainSerialize:
+			return CreateExplainSerializeDestReceiver(NULL);
 	}
 
 	/* should never get here */
@@ -186,6 +190,7 @@ EndCommand(const QueryCompletion *qc, CommandDest dest, bool force_undecorated_o
 		case DestSQLFunction:
 		case DestTransientRel:
 		case DestTupleQueue:
+		case DestExplainSerialize:
 			break;
 	}
 }
@@ -231,6 +236,7 @@ NullCommand(CommandDest dest)
 		case DestSQLFunction:
 		case DestTransientRel:
 		case DestTupleQueue:
+		case DestExplainSerialize:
 			break;
 	}
 }
@@ -274,6 +280,7 @@ ReadyForQuery(CommandDest dest)
 		case DestSQLFunction:
 		case DestTransientRel:
 		case DestTupleQueue:
+		case DestExplainSerialize:
 			break;
 	}
 }
diff --git a/src/include/commands/explain.h b/src/include/commands/explain.h
index cf195f1359..9f2da28f93 100644
--- a/src/include/commands/explain.h
+++ b/src/include/commands/explain.h
@@ -25,6 +25,13 @@ typedef enum ExplainFormat
 	EXPLAIN_FORMAT_YAML,
 } ExplainFormat;
 
+typedef enum ExplainSerializeFormat
+{
+	EXPLAIN_SERIALIZE_NONE,
+	EXPLAIN_SERIALIZE_TEXT,
+	EXPLAIN_SERIALIZE_BINARY,
+}			ExplainSerializeFormat;
+
 typedef struct ExplainWorkersState
 {
 	int			num_workers;	/* # of worker processes the plan used */
@@ -48,6 +55,8 @@ typedef struct ExplainState
 	bool		memory;			/* print planner's memory usage information */
 	bool		settings;		/* print modified settings */
 	bool		generic;		/* generate a generic plan */
+	ExplainSerializeFormat serialize;	/* do serialization (in ANALZYE) */
+
 	ExplainFormat format;		/* output format */
 	/* state for output formatting --- not reset for each new plan tree */
 	int			indent;			/* current indentation level */
@@ -132,4 +141,6 @@ extern void ExplainOpenGroup(const char *objtype, const char *labelname,
 extern void ExplainCloseGroup(const char *objtype, const char *labelname,
 							  bool labeled, ExplainState *es);
 
+extern DestReceiver *CreateExplainSerializeDestReceiver(ExplainState *es);
+
 #endif							/* EXPLAIN_H */
diff --git a/src/include/tcop/dest.h b/src/include/tcop/dest.h
index 7e613bd7fc..851272a719 100644
--- a/src/include/tcop/dest.h
+++ b/src/include/tcop/dest.h
@@ -96,6 +96,8 @@ typedef enum
 	DestSQLFunction,			/* results sent to SQL-language func mgr */
 	DestTransientRel,			/* results sent to transient relation */
 	DestTupleQueue,				/* results sent to tuple queue */
+	DestExplainSerialize,		/* results are only serialized, not
+								 * transferred */
 } CommandDest;
 
 /* ----------------
diff --git a/src/test/regress/expected/explain.out b/src/test/regress/expected/explain.out
index 1299ee79ad..bc121b0b52 100644
--- a/src/test/regress/expected/explain.out
+++ b/src/test/regress/expected/explain.out
@@ -135,7 +135,7 @@ select explain_filter('explain (analyze, buffers, format xml) select * from int8
  </explain>
 (1 row)
 
-select explain_filter('explain (analyze, buffers, format yaml) select * from int8_tbl i8');
+select explain_filter('explain (analyze, serialize, buffers, format yaml) select * from int8_tbl i8');
         explain_filter         
 -------------------------------
  - Plan:                      +
@@ -175,6 +175,20 @@ select explain_filter('explain (analyze, buffers, format yaml) select * from int
      Temp Written Blocks: N   +
    Planning Time: N.N         +
    Triggers:                  +
+   Serialization:             +
+     Time: N.N                +
+     Written Bytes: N         +
+     Format: "text"           +
+     Shared Hit Blocks: N     +
+     Shared Read Blocks: N    +
+     Shared Dirtied Blocks: N +
+     Shared Written Blocks: N +
+     Local Hit Blocks: N      +
+     Local Read Blocks: N     +
+     Local Dirtied Blocks: N  +
+     Local Written Blocks: N  +
+     Temp Read Blocks: N      +
+     Temp Written Blocks: N   +
    Execution Time: N.N
 (1 row)
 
@@ -639,3 +653,48 @@ select explain_filter('explain (verbose) select * from int8_tbl i8');
  Query Identifier: N
 (3 rows)
 
+-- Test that SERIALIZE is accepted as a parameter to explain
+-- timings are filtered out by explain_filter
+create table test_serialize(id bigserial, val text);
+select explain_filter('explain (analyze,serialize) select * from test_serialize');
+                                          explain_filter                                          
+--------------------------------------------------------------------------------------------------
+ Seq Scan on test_serialize  (cost=N.N..N.N rows=N width=N) (actual time=N.N..N.N rows=N loops=N)
+ Planning Time: N.N ms
+ Serialization: time=N.N  produced=NkB  format=text
+ Execution Time: N.N ms
+(4 rows)
+
+drop table test_serialize;
+-- Test that SERIALIZE BINARY is accepted as a parameter to explain
+create table test_serialize(id bigserial, val text);
+select explain_filter('explain (analyze,serialize binary,buffers) select * from test_serialize');
+                                          explain_filter                                          
+--------------------------------------------------------------------------------------------------
+ Seq Scan on test_serialize  (cost=N.N..N.N rows=N width=N) (actual time=N.N..N.N rows=N loops=N)
+ Planning Time: N.N ms
+ Serialization: time=N.N  produced=NkB  format=binary
+ Execution Time: N.N ms
+(4 rows)
+
+drop table test_serialize;
+-- Test that _SERIALIZE invalidparameter_ is not accepted as a parameter to explain
+create table test_serialize(id bigserial, val text);
+select explain_filter('explain (analyze,serialize invalidparameter) select * from test_serialize');
+ERROR:  unrecognized value for EXPLAIN option "serialize": "invalidparameter"
+LINE 1: select explain_filter('explain (analyze,serialize invalidpar...
+                         ^
+CONTEXT:  PL/pgSQL function explain_filter(text) line 5 at FOR over EXECUTE statement
+drop table test_serialize;
+-- Test SERIALIZE is _not_ accepted as a parameter to explain unless ANALYZE is specified
+create table test_serialize(id bigserial, val text);
+select explain_filter('explain (serialize) select * from test_serialize');
+ERROR:  EXPLAIN option SERIALIZE requires ANALYZE
+CONTEXT:  PL/pgSQL function explain_filter(text) line 5 at FOR over EXECUTE statement
+drop table test_serialize;
+-- Test SERIALIZEBINARY is _not_ accepted as a parameter to explain unless ANALYZE is specified
+create table test_serialize(id bigserial, val text);
+select explain_filter('explain (serialize binary) select * from test_serialize');
+ERROR:  EXPLAIN option SERIALIZE requires ANALYZE
+CONTEXT:  PL/pgSQL function explain_filter(text) line 5 at FOR over EXECUTE statement
+drop table test_serialize;
diff --git a/src/test/regress/sql/explain.sql b/src/test/regress/sql/explain.sql
index 2274dc1b5a..76e441f258 100644
--- a/src/test/regress/sql/explain.sql
+++ b/src/test/regress/sql/explain.sql
@@ -66,7 +66,7 @@ select explain_filter('explain (analyze) select * from int8_tbl i8');
 select explain_filter('explain (analyze, verbose) select * from int8_tbl i8');
 select explain_filter('explain (analyze, buffers, format text) select * from int8_tbl i8');
 select explain_filter('explain (analyze, buffers, format xml) select * from int8_tbl i8');
-select explain_filter('explain (analyze, buffers, format yaml) select * from int8_tbl i8');
+select explain_filter('explain (analyze, serialize, buffers, format yaml) select * from int8_tbl i8');
 select explain_filter('explain (buffers, format text) select * from int8_tbl i8');
 select explain_filter('explain (buffers, format json) select * from int8_tbl i8');
 
@@ -162,3 +162,29 @@ select explain_filter('explain (verbose) select * from t1 where pg_temp.mysin(f1
 -- Test compute_query_id
 set compute_query_id = on;
 select explain_filter('explain (verbose) select * from int8_tbl i8');
+
+-- Test that SERIALIZE is accepted as a parameter to explain
+-- timings are filtered out by explain_filter
+create table test_serialize(id bigserial, val text);
+select explain_filter('explain (analyze,serialize) select * from test_serialize');
+drop table test_serialize;
+
+-- Test that SERIALIZE BINARY is accepted as a parameter to explain
+create table test_serialize(id bigserial, val text);
+select explain_filter('explain (analyze,serialize binary,buffers) select * from test_serialize');
+drop table test_serialize;
+
+-- Test that _SERIALIZE invalidparameter_ is not accepted as a parameter to explain
+create table test_serialize(id bigserial, val text);
+select explain_filter('explain (analyze,serialize invalidparameter) select * from test_serialize');
+drop table test_serialize;
+
+-- Test SERIALIZE is _not_ accepted as a parameter to explain unless ANALYZE is specified
+create table test_serialize(id bigserial, val text);
+select explain_filter('explain (serialize) select * from test_serialize');
+drop table test_serialize;
+
+-- Test SERIALIZEBINARY is _not_ accepted as a parameter to explain unless ANALYZE is specified
+create table test_serialize(id bigserial, val text);
+select explain_filter('explain (serialize binary) select * from test_serialize');
+drop table test_serialize;
diff --git a/src/tools/pgindent/typedefs.list b/src/tools/pgindent/typedefs.list
index 79745ba913..873eaaa58a 100644
--- a/src/tools/pgindent/typedefs.list
+++ b/src/tools/pgindent/typedefs.list
@@ -2532,6 +2532,7 @@ SerCommitSeqNo
 SerialControl
 SerialIOData
 SerializableXactHandle
+SerializeDestReceiver
 SerializedActiveRelMaps
 SerializedClientConnectionInfo
 SerializedRanges
-- 
2.40.1

#21Tom Lane
tgl@sss.pgh.pa.us
In reply to: Matthias van de Meent (#20)
Re: Detoasting optionally to make Explain-Analyze less misleading

Matthias van de Meent <boekewurm+postgres@gmail.com> writes:

On Tue, 2 Apr 2024 at 17:47, Tom Lane <tgl@sss.pgh.pa.us> wrote:

IIUC, it's not possible to use the SERIALIZE option when explaining
CREATE TABLE AS, because you can't install the instrumentation tuple
receiver when the IntoRel one is needed. I think that's fine because
no serialization would happen in that case anyway, but should we
throw an error if that combination is requested? Blindly reporting
that zero bytes were serialized seems like it'd confuse people.

I think it's easily explained as no rows were transfered to the
client. If there is actual confusion, we can document it, but
confusing disk with network is not a case I'd protect against. See
also: EXPLAIN (ANALYZE, SERIALIZE) INSERT without the RETURNING
clause.

Fair enough. There were a couple of spots in the code where I thought
this was important to comment about, though.

However, isn't the bottom half of serializeAnalyzeStartup doing
exactly what the comment above it says we don't do, that is accounting
for the RowDescription message? Frankly I agree with the comment that
it's not worth troubling over, so I'd just drop that code rather than
finding a solution for the magic-number problem.

I'm not sure I agree with not including the size of RowDescription
itself though, as wide results can have a very large RowDescription
overhead; up to several times the returned data in cases where few
rows are returned.

Meh --- if we're rounding off to kilobytes, you're unlikely to see it.
In any case, if we start counting overhead messages, where shall we
stop? Should we count the eventual CommandComplete or ReadyForQuery,
for instance? I'm content to say that this measures data only; that
seems to jibe with other aspects of EXPLAIN's behavior.

Removed. I've instead added buffer usage, as I realised that wasn't
covered yet, and quite important to detect excessive detoasting (it's
not covered at the top-level scan).

Duh, good catch.

I've pushed this after a good deal of cosmetic polishing -- for
example, I spent some effort on making serializeAnalyzeReceive
look as much like printtup as possible, in hopes of making it
easier to keep the two functions in sync in future.

regards, tom lane

#22Matthias van de Meent
boekewurm+postgres@gmail.com
In reply to: Tom Lane (#21)
Re: Detoasting optionally to make Explain-Analyze less misleading

On Wed, 3 Apr 2024 at 23:50, Tom Lane <tgl@sss.pgh.pa.us> wrote:

Matthias van de Meent <boekewurm+postgres@gmail.com> writes:

On Tue, 2 Apr 2024 at 17:47, Tom Lane <tgl@sss.pgh.pa.us> wrote:

IIUC, it's not possible to use the SERIALIZE option when explaining
CREATE TABLE AS, because you can't install the instrumentation tuple
receiver when the IntoRel one is needed. I think that's fine because
no serialization would happen in that case anyway, but should we
throw an error if that combination is requested? Blindly reporting
that zero bytes were serialized seems like it'd confuse people.

I think it's easily explained as no rows were transfered to the
client. If there is actual confusion, we can document it, but
confusing disk with network is not a case I'd protect against. See
also: EXPLAIN (ANALYZE, SERIALIZE) INSERT without the RETURNING
clause.

Fair enough. There were a couple of spots in the code where I thought
this was important to comment about, though.

Yeah, I'll agree with that.

However, isn't the bottom half of serializeAnalyzeStartup doing
exactly what the comment above it says we don't do, that is accounting
for the RowDescription message? Frankly I agree with the comment that
it's not worth troubling over, so I'd just drop that code rather than
finding a solution for the magic-number problem.

I'm not sure I agree with not including the size of RowDescription
itself though, as wide results can have a very large RowDescription
overhead; up to several times the returned data in cases where few
rows are returned.

Meh --- if we're rounding off to kilobytes, you're unlikely to see it.
In any case, if we start counting overhead messages, where shall we
stop? Should we count the eventual CommandComplete or ReadyForQuery,
for instance? I'm content to say that this measures data only; that
seems to jibe with other aspects of EXPLAIN's behavior.

Fine with me.

Removed. I've instead added buffer usage, as I realised that wasn't
covered yet, and quite important to detect excessive detoasting (it's
not covered at the top-level scan).

Duh, good catch.

I've pushed this after a good deal of cosmetic polishing -- for
example, I spent some effort on making serializeAnalyzeReceive
look as much like printtup as possible, in hopes of making it
easier to keep the two functions in sync in future.

Thanks for the review, and for pushing!

-Matthias

#23Matthias van de Meent
boekewurm+postgres@gmail.com
In reply to: Tom Lane (#21)
Re: Detoasting optionally to make Explain-Analyze less misleading

On Wed, 3 Apr 2024 at 23:50, Tom Lane <tgl@sss.pgh.pa.us> wrote:

I've pushed this after a good deal of cosmetic polishing -- for
example, I spent some effort on making serializeAnalyzeReceive
look as much like printtup as possible, in hopes of making it
easier to keep the two functions in sync in future.

Upthread at [0]/messages/by-id/ea885631-21f1-425a-97ed-c4bfb8cf9c63@gmx.de, Stepan mentioned that we should default to SERIALIZE
when ANALYZE is enabled. I suspect a patch in that direction would
primarily contain updates in the test plan outputs, but I've not yet
worked on that.

Does anyone else have a strong opinion for or against adding SERIALIZE
to the default set of explain features enabled with ANALYZE?

I'll add this to "Decisions to Recheck Mid-Beta"-section if nobody has
a clear objection.

Kind regards,

Matthias van de Meent
Neon (https://neon.tech)

[0]: /messages/by-id/ea885631-21f1-425a-97ed-c4bfb8cf9c63@gmx.de

#24Tom Lane
tgl@sss.pgh.pa.us
In reply to: Matthias van de Meent (#23)
Re: Detoasting optionally to make Explain-Analyze less misleading

Matthias van de Meent <boekewurm+postgres@gmail.com> writes:

Upthread at [0], Stepan mentioned that we should default to SERIALIZE
when ANALYZE is enabled. I suspect a patch in that direction would
primarily contain updates in the test plan outputs, but I've not yet
worked on that.

Does anyone else have a strong opinion for or against adding SERIALIZE
to the default set of explain features enabled with ANALYZE?

I am 100% dead set against that, because it would silently render
EXPLAIN outputs from different versions quite non-comparable.

regards, tom lane

#25stepan rutz
stepan.rutz@gmx.de
In reply to: Tom Lane (#24)
Re: Detoasting optionally to make Explain-Analyze less misleading

First of all thanks for bringing this Feature to PostgreSQL. From a
regular-user perspective (not everyone is a Pro) it is very misleading
that ANALYZE doesn't do what it suggests it does. To run the query into
some kind of /dev/null type of destination is feasible and that is what
people end up doing after they have fallen into the "de-toasting" trap.

Having SERIALIZE is a great improvement for certain. When I said that
SERIALIZE should be the default, then this came mostly out of very
surprising subjective experiences in the past. Turning it on certainly
alters some existing benchmarks and timings. That is destructive in a
way and would destroy some existing work and measures. I lack the
overall understanding of the consequences, so please don't follow this
(emotional) advice.

So thanks again! and this will really help a lot of people. The people
actually bothering with EXPLAIN options are likely to explore the
documentation and now have a hint about this pitfall. The EXPLAIN part
of PostgreSQL "feels" a lot better now.

I appreciate all of your work on this issue, which came up without being
on some kind of plan and of course for the overall work on PostgreSQL.

/Stepan

On 4/10/24 15:57, Tom Lane wrote:

Show quoted text

Matthias van de Meent <boekewurm+postgres@gmail.com> writes:

Upthread at [0], Stepan mentioned that we should default to SERIALIZE
when ANALYZE is enabled. I suspect a patch in that direction would
primarily contain updates in the test plan outputs, but I've not yet
worked on that.
Does anyone else have a strong opinion for or against adding SERIALIZE
to the default set of explain features enabled with ANALYZE?

I am 100% dead set against that, because it would silently render
EXPLAIN outputs from different versions quite non-comparable.

regards, tom lane

#26Michael Christofides
michael@pgmustard.com
In reply to: stepan rutz (#25)
Re: Detoasting optionally to make Explain-Analyze less misleading

So thanks again! and this will really help a lot of people.

I'd like to echo this thanks to you all.

While looking to add support for SERIALIZE in an explain visualisation tool
I work on, I realised there isn't yet an equivalent auto_explain parameter
for SERIALIZE. I'm not sure if this is a deliberate omission (perhaps for a
similar reason planning time is not included in auto_explain?), but I
didn't see it mentioned above, so I thought best to ask in case not.

Thanks again,
Michael

#27Tom Lane
tgl@sss.pgh.pa.us
In reply to: Michael Christofides (#26)
Re: Detoasting optionally to make Explain-Analyze less misleading

Michael Christofides <michael@pgmustard.com> writes:

While looking to add support for SERIALIZE in an explain visualisation tool
I work on, I realised there isn't yet an equivalent auto_explain parameter
for SERIALIZE. I'm not sure if this is a deliberate omission (perhaps for a
similar reason planning time is not included in auto_explain?), but I
didn't see it mentioned above, so I thought best to ask in case not.

I'm not sure there's a need for it. When a query runs under
auto_explain, the output values will be sent to the client,
so those cycles should be accounted for anyway, no?

(Perhaps the auto_explain documentation should mention this?)

regards, tom lane

#28Michael Christofides
michael@pgmustard.com
In reply to: Tom Lane (#27)
Re: Detoasting optionally to make Explain-Analyze less misleading

I'm not sure there's a need for it. When a query runs under
auto_explain, the output values will be sent to the client,
so those cycles should be accounted for anyway, no?

Yes, great point, the total duration reported by auto_explain includes it.
Explicit serialization stats might still be helpful for folks when it is
the bottleneck, but less useful for sure (especially if nothing else causes
big discrepancies between the duration reported by auto_explain and the
"actual total time" of the root node).

(Perhaps the auto_explain documentation should mention this?)

I'd value this. I notice the folks working on the other new explain
parameter (memory) opted to add a comment to the auto_explain source code
to say it wasn't supported.

Thanks again,
Michael