RE: libpq debug log

Aya Iwata (Fujitsu) <iwata.aya@fujitsu.com>

From: "iwata.aya@fujitsu.com" <iwata.aya@fujitsu.com>
To: 'Kyotaro Horiguchi' <horikyota.ntt@gmail.com>, "tsunakawa.takay@fujitsu.com" <tsunakawa.takay@fujitsu.com>
Cc: "alvherre@alvh.no-ip.org" <alvherre@alvh.no-ip.org>, "tgl@sss.pgh.pa.us" <tgl@sss.pgh.pa.us>, "k.jamison@fujitsu.com" <k.jamison@fujitsu.com>, "pgsql-hackers@lists.postgresql.org" <pgsql-hackers@lists.postgresql.org>
Date: 2021-03-18T10:01:43Z
Lists: pgsql-hackers

Attachments

Hi Horiguchi san and Tsunakawa san,

Thank you for you review. 

I update patch to v28.  In this patch, I removed array.
And I fixed some code according to Horiguchi san and Tsunakawa san review comment.

> From: Tsunakawa, Takayuki/綱川 貴之 <tsunakawa.takay@fujitsu.com>
> Sent: Thursday, March 18, 2021 12:38 PM
> I sort of think so to remove the big arrays.  But to minimize duplicate code, I
> think the code structure will look like:
> 
> 	fprintf(timestamp, length);
> 	switch (type)
> 	{
> 		case '?':
> 			pqTraceOutput?(...);
> 		break;
> 		case '?':
> 			/* No message content */
> 			fprintf("message_type_name");
> 		break;
> 	}
> 
> void
> pqTraceOutput?(...)
> {
> 	fprintf("message_type_name");
> 	print message content;
> }

The code follows above format.
And I changed .sgml documentation;
- Changed order of message length and type
- Removed byte-16 and byte-32 explanation because I removed # output in previous patch.

Output style is following;

```
2021-03-18 08:59:36.141660  <   5   ReadyForQuery I                                   
2021-03-18 08:59:36.141723  >   4   Terminate                                         
2021-03-18 08:59:36.173263  >   155 Query "CREATE TABLESPACE regress_tblspacewith LOCATION '/home/iwata/pgsql/postgres/src/test/regress/testtablespace' WITH (some_nonexistent_parameter = true);"
2021-03-18 08:59:36.174439  <   124 ErrorResponse S "ERROR" V "ERROR" C "22023" M "unrecognized parameter "some_nonexistent_parameter"" F "reloptions.c" L "1456" R "parseRelOptionsInternal" \x00 "Z"
2021-03-18 08:59:36.174483  <   5   ReadyForQuery I                                   
2021-03-18 08:59:36.174545  >   144 Query "CREATE TABLESPACE regress_tblspacewith LOCATION '/home/iwata/pgsql/postgres/src/test/regress/testtablespace' WITH (random_page_cost = 3.0);"
2021-03-18 08:59:36.176155  <   22  CommandComplete "CREATE TABLESPACE"               
2021-03-18 08:59:36.176190  <   5   ReadyForQuery I                                   
2021-03-18 08:59:36.176243  >   81  Query "SELECT spcoptions FROM pg_tablespace WHERE spcname = 'regress_tblspacewith';"                                                      
2021-03-18 08:59:36.179286  <   35  RowDescription 1 "spcoptions" 1213 5 1009 65535 -1 0
2021-03-18 08:59:36.179326  <   32  DataRow 1 22 '{random_page_cost=3.0}'             
2021-03-18 08:59:36.179339  <   13  CommandComplete "SELECT 1"                  
2021-03-18 08:59:36.179349  <   5   ReadyForQuery I                             
2021-03-18 08:59:36.179504  >   42  Query "DROP TABLESPACE regress_tblspacewith;"
2021-03-18 08:59:36.180400  <   20  CommandComplete "DROP TABLESPACE"           
2021-03-18 08:59:36.180432  <   5   ReadyForQuery I       
```


> -----Original Message-----
> From: Kyotaro Horiguchi <horikyota.ntt@gmail.com>
> Sent: Thursday, March 18, 2021 5:30 PM
> 
> At Thu, 18 Mar 2021 07:34:36 +0000, "tsunakawa.takay@fujitsu.com"
> <tsunakawa.takay@fujitsu.com> wrote in
> > From: Iwata, Aya/岩田 彩 <iwata.aya@fujitsu.com>
> > > > Yes, precisely, 2 bytes for the double quotes needs to be
> > > > subtracted as
> > > > follows:
> > > >
> > > > 	len = fprintf(...);
> > > > 	*cursor += (len - 2);
> > >
> > > Thank you for your advice. I changed pqTraceOutputString set cursor
> > > to fprintf return -2.
> > > And I removed cursor movement from that function.
> >
> > Ouch, not 2 but 3, to include a single whitespace at the beginning.
> >
> > The rest looks good.  I hope we're almost at the finish line.
> 
> Maybe.

String is end by '\0'. So (len -2) is OK. 
However it seems like mistake because fprintf output string and 3 characters. 
So I added explanation here and changed (len -2) to (len -3 +1). 
I think it is OK because I found similar style in ecpg code.

> > + pqTraceOutputR(const char *message, FILE *f) {
> > + 	int	cursor = 0;
> > +
> > + 	pqTraceOutputInt32(message, &cursor, f);
> >
> > I don't understand the reason for spliting message and &cursor here.
> >
> > + pqTraceOutputR(const char *message, FILE *f) {
> > + 	char *p = message;
> > +
> > + 	pqTraceOutputInt32(&p, f);
> >
> > works well.
> 
> Yes, that would also work.  But I like the separate cursor + fixed starting
> point here, probably because it's sometimes confusing to see the pointer
> value changed inside functions.  (And a pointer itself is an allergy for some
> people, not to mention a pointer to ointer...)  Also, libpq uses cursors for
> network I/O buffers.  So, I think the patch can be as it is now.

I think pass message and cursor is better. Because it is easy to understand and
The moving cursor style is used when libpq execute protocol message.
So I didn't make this change.
 
> +/* RowDescription */
> +static void
> +pqTraceOutputT(const char *message, int end, FILE *f) {
> +	int	cursor = 0;
> +	int nfields;
> +	int	i;
> +
> +	nfields = pqTraceOutputInt16(message, &cursor, f);
> +
> +	for (i = 0; i < nfields; i++)
> +	{
> +		pqTraceOutputString(message, &cursor, end, f);
> +		pqTraceOutputInt32(message, &cursor, f);
> +		pqTraceOutputInt16(message, &cursor, f);
> +		pqTraceOutputInt32(message, &cursor, f);
> +		pqTraceOutputInt16(message, &cursor, f);
> +		pqTraceOutputInt32(message, &cursor, f);
> +		pqTraceOutputInt16(message, &cursor, f);
> +	}
> +}
> 
> I didn't looked closer, but lookong the usage of the variable "end", something's
> wrong in the function.

I removed end from the function.
pqTraceOutputString no longer use message end cursor.



Regards,
Aya Iwata