RE: libpq debug log

From: Jamison, Kirk/ジャミソン カーク <k(dot)jamison(at)fujitsu(dot)com>
> To make the CFBot happy, I fixed the compiler errors.
> I have not included here the change proposal to move the tracing functions to a
> new file: fe-trace.c or something, so I retained the changes .
> Maybe Iwata-san can consider the proposal.
> Currently, both pqTraceInit() and pqTraceUninit() are called only by one
> function.

I confirmed all mentioned points have been fixed. Additional comments are:

(29)
-void PQtrace(PGconn *conn, FILE *stream);
+void PQtrace(PGconn *conn, FILE *stream, int flags);

As I said before, I'm afraid we cannot change the signature of existing API functions. Please leave the signature of this function unchanged, and add a new function like PQtraceEx() that adds the flags argument.

I guess the purpose of adding the flag argument is to not output the timestamp by default, because getting timestamps would incur significant overhead (however, I'm not sure if that overhead is worth worrying about given the already incurred logging overhead.) So, I think it's better to have a flag like PQTRACE_OUTPUT_TIMESTAMPS instead of PQTRACE_SUPPRESS_TIMESTAMPS, and the functions would look like:

void
PQtrace(PGconn *conn, FILE *stream)
{
PQtraceEx(conn, stream, 0);
}

void
PQtraceEx(PGconn *conn, FILE *stream, int flags)
{
... the new implementation in the patch
}

Remember to add PQtraceEx in exports.txt and make sure it builds on Windows with Visual Studio.

But... can you evaluate the overhead for getting timestamps and see if we can turn it on by default, or further, if we need such a flag and PQtraceEx()? For example, how about comparing the times to run the regression test with and without timestamps?

(30)
+/*
+ * Deallocate FE/BE message tracking memory. We only do this because
+ * FE message can grow arbitrarily large, and skip it in the initial state,
+ * because it's likely pointless.
+ */
+void
+pqTraceUninit(PGconn *conn)
+{
+ if (conn->fe_msg &&
+ conn->fe_msg->num_fields != DEF_FE_MSGFIELDS)
+ {
+ free(conn->fe_msg);
+ conn->fe_msg = NULL;
+ }

What does the second if condition mean? If it's not necessary, change the comment accordingly.

(31)
@@ -1011,11 +1615,16 @@ pqSendSome(PGconn *conn, int len)
int
pqFlush(PGconn *conn)
{
- if (conn->Pfdebug)
- fflush(conn->Pfdebug);
-
if (conn->outCount > 0)
+ {
+ /* XXX comment */
+ if (conn->Pfdebug)
+ {
+ pqLogFrontendMsg(conn, -1);
+ fflush(conn->Pfdebug);
+ }
return pqSendSome(conn, conn->outCount);
+ }

Remove the comment line.

(32)
+#define INT_MAX (2048/2) /* maximum array size */

INT_MAX is available via:
#include <limits.h>

(33)
/* realloc failed. Probably out of memory */
- appendPQExpBufferStr(&conn->errorMessage,
- "cannot allocate memory for input buffer\n");
+ appendPQExpBuffer(&conn->errorMessage,
+ "cannot allocate memory for input buffer\n");

This change appears to be irrelevant.

(34)
+static void
+pqStoreFeMsgStart(PGconn *conn, char type)
+{
+ if (PG_PROTOCOL_MAJOR(conn->pversion) >= 3)
+ conn->fe_msg->msg_type = type;
+}

Protocol version check is unnecessary because this tracing takes effect only in v3 protocol?

(35)
+ conn->fe_msg =
+ realloc(conn->fe_msg,
+ sizeof(pqFrontendMessage) +
+ 2 * conn->fe_msg->max_fields * sizeof(pqFrontendMessageField));

Align this size calculation with that in pqTraceInit().

(36)
+ /* append milliseconds */
+ sprintf(timestr + strlen(timestr), ".%03d", (int) (tval.tv_usec / 1000));

Output microsecond instead. As your example output shows, many lines show the exactly same timestamps and thus they are not distinguishable in time.

(37)
+static char *
+pqLogFormatTimestamp(char *timestr)
+{
...
+#define FORMATTED_TS_LEN 128
+ strftime(timestr, FORMATTED_TS_LEN,

Add an argument to this function that indicates the size of timestr. Define FORMATTED_TS_LEN globally in this source file, and have callers use it. That is, the code like:

+ char timestr[128];
+
+ fprintf(conn->Pfdebug, "%s\t>\t%s\t%d",
+ pqLogFormatTimestamp(timestr),

becomes:

+ char timestr[FORMATTED_TS_LEN];
+
+ fprintf(conn->Pfdebug, "%s\t>\t%s\t%d",
+ pqLogFormatTimestamp(timestr, sizeof(timestr)),

(38)
+ if ((conn->traceFlags & PQTRACE_SUPPRESS_TIMESTAMPS) == 0)
+ {
+ char timestr[128];
+
+ fprintf(conn->Pfdebug, "%s\t>\t%s\t%d",
+ pqLogFormatTimestamp(timestr),
+ pqGetProtocolMsgType(conn->fe_msg->msg_type,
+ MSGDIR_FROM_FRONTEND),
+ msgLen);
+ }
+ else
+ fprintf(conn->Pfdebug, ">\t%s\t%d",
+ pqGetProtocolMsgType(conn->fe_msg->msg_type,
+ MSGDIR_FROM_FRONTEND),
+ msgLen);

To reduce the code for easier modification, change the above code to something like:

+ char timestr[128];
+ char *timestr_p = "";
+
+ if ((conn->traceFlags & PQTRACE_SUPPRESS_TIMESTAMPS) == 0)
+ timestr_p = pqLogFormatTimestamp(timestr);
+ fprintf(conn->Pfdebug, "%s\t>\t%s\t%d",
+ timestr_p,
+ pqGetProtocolMsgType(conn->fe_msg->msg_type,
+ MSGDIR_FROM_FRONTEND),
+ msgLen);

Regards
Takayuki Tsunakawa