libpq debug log
Hi,
I'm going to propose libpq debug log for analysis of queries on the application side.
I think that it is useful to determine whether the cause is on the application side or the server side when a slow query occurs.
The provided information is "date and time" at which execution of processing is started, "query", "application side processing", which is picked up information from PQtrace(), and "connection id", which is for uniquely identifying the connection.
To collect the log, set the connection string or environment variable.
- logdir or PGLOGDIR : directory where log file written
- logsize or PGLOGSIZE : maximum log size
What do you think about this? Do you think that such feature is necessary?
Regards,
Aya Iwata
"Iwata, Aya" <iwata.aya@jp.fujitsu.com> writes:
I'm going to propose libpq debug log for analysis of queries on the application side.
I think that it is useful to determine whether the cause is on the application side or the server side when a slow query occurs.
Hm, how will you tell that really? And what's the advantage over the
existing server-side query logging capability?
The provided information is "date and time" at which execution of processing is started, "query", "application side processing", which is picked up information from PQtrace(), and "connection id", which is for uniquely identifying the connection.
PQtrace() is utterly useless for anything except debugging libpq
internals, and it's not tremendously useful even for that. Don't
bother with that part.
Where will you get a "unique connection id" from?
How will you deal with asynchronously-executed queries --- either
the PQgetResult style, or the single-row-at-a-time style?
regards, tom lane
On Fri, 24 Aug 2018 04:38:22 +0000
"Iwata, Aya" <iwata.aya@jp.fujitsu.com> wrote:
Hi,
I'm going to propose libpq debug log for analysis of queries on the application side.
I think that it is useful to determine whether the cause is on the application side or the server side when a slow query occurs.
Do you mean you want to monitor the protocol message exchange at
the client side to analyze performance issues, right? Actually,
this might be useful to determin where is the problem, for example,
the client application, the backend PostgreSQL, or somewhere in the
network.
Such logging can be implemented in the application, but if libpq
provides the standard way, it would be helpful to resolve a problem
without modifying the application code.
The provided information is "date and time" at which execution of processing is started, "query", "application side processing", which is picked up information from PQtrace(), and "connection id", which is for uniquely identifying the connection.
I couldn't image how this is like. Could you show us a sample of log lines
in your head?
To collect the log, set the connection string or environment variable.
- logdir or PGLOGDIR : directory where log file written
- logsize or PGLOGSIZE : maximum log size
How we can specify the log file name? What should happen if a file size
exceeds to PGLOGSIZE?
Regards,
--
Yugo Nagata <nagata@sraoss.co.jp>
On Fri, Aug 24, 2018 at 9:48 AM, Tom Lane <tgl@sss.pgh.pa.us> wrote:
PQtrace() is utterly useless for anything except debugging libpq
internals, and it's not tremendously useful even for that. Don't
bother with that part.
I think that improving the output format could help with that a lot.
What it current produces is almost unreadable; adjusting it to emit
one line per protocol message would, I think, help a lot. There are
probably other improvements that could be made at the same time.
--
Robert Haas
EnterpriseDB: http://www.enterprisedb.com
The Enterprise PostgreSQL Company
Robert Haas <robertmhaas@gmail.com> writes:
On Fri, Aug 24, 2018 at 9:48 AM, Tom Lane <tgl@sss.pgh.pa.us> wrote:
PQtrace() is utterly useless for anything except debugging libpq
internals, and it's not tremendously useful even for that. Don't
bother with that part.
I think that improving the output format could help with that a lot.
What it current produces is almost unreadable; adjusting it to emit
one line per protocol message would, I think, help a lot. There are
probably other improvements that could be made at the same time.
I wouldn't mind throwing it out and reimplementing it ;-) ... tracing
at the logical message level rather than the byte level would help.
But still, I'm not really convinced that it has very much to do with
what you'd want in a user-level debug log.
Part of what's really bad about the PQtrace output is that in v2 protocol
the same output can be repeated several times as we try to parse a message
and conclude we don't have it all yet. I believe that problem is gone
in v3, but it may be hard to do a consistent redesign until we nuke libpq's
v2 support. Still, it might be past time for the latter, seeing that
we no longer promise pre-7.4 compatibility in either psql or pg_dump.
regards, tom lane
"Iwata, Aya" <iwata.aya@jp.fujitsu.com> writes:
I'm going to propose libpq debug log for analysis of queries on the application
side.
I think that it is useful to determine whether the cause is on the application
side or the server side when a slow query occurs.
Hm, how will you tell that really? And what's the advantage over the existing
server-side query logging capability?
The log I would like to propose is used when the performance issue happen,
system administrator knows the process of application internally and check if there is any problem.
"debug" is not the correct description of the feature. The correct one should be "trace". Should I create another thread?
The provided information is "date and time" at which execution of processing
is started, "query", "application side processing", which is picked up
information from PQtrace(), and "connection id", which is for uniquely
identifying the connection.PQtrace() is utterly useless for anything except debugging libpq internals,
and it's not tremendously useful even for that. Don't bother with that part.
My initial intention was to get only useful information from PQTrace () since it acquires a lot of information.
Is there another way to obtain application side information besides PQTrace() ?
Where will you get a "unique connection id" from?
When collecting trace log file in the application side,
I think it is necessary to identify different connection.
In order to do this, when new empty PQconn structure is created, new connection id is also created.
Then we output it in the trace log file for one application.
How will you deal with asynchronously-executed queries --- either the
PQgetResult style, or the single-row-at-a-time style?
In my understanding, PQgetResult style outputs logs of multiple result queries at once,
While the single-row-at-a-time style outputs log for each query. Is this correct?
I think PQgetResult style is better,
because this style traces the internal process of the application.
Regards,
Aya Iwata
I'm going to propose libpq debug log for analysis of queries on the application
side.
I think that it is useful to determine whether the cause is on the application
side or the server side when a slow query occurs.
Do you mean you want to monitor the protocol message exchange at the client
side to analyze performance issues, right? Actually, this might be useful to
determin where is the problem, for example, the client application, the backend
PostgreSQL, or somewhere in the network.Such logging can be implemented in the application, but if libpq provides the
standard way, it would be helpful to resolve a problem without modifying the
application code.
Since I'd like to monitor the information the server and the client exchange,
I think monitoring protocol messages is good.
When a slow query is occurs, we check this client side trace log.
The purpose of this log acquisition I thought is to identify where is the problem:
server side, application side or traffic.
And if the problem is in application side, checking the trace log to identify what is the problem.
The provided information is "date and time" at which execution of processing
is started, "query", "application side processing", which is picked up
information from PQtrace(), and "connection id", which is for uniquely
identifying the connection.I couldn't image how this is like. Could you show us a sample of log lines in
your head?
I am roughly thinking as follows;
...
START : 2018/09/03 18:16:35.357 CONNECTION(1)
STATUS : Connection
SEND MESSAGE : 2018/09/03 18:16:35.358
<information send to backend...>
RECEIVE MESSAGE : 2018/09/03 18:16:35.359
<information receive from backend...>
END : 2018/09/03 18:16:35.360
...
START : 2018/09/03 18:16:35.357 CONNECTION(1)
QUERY : DECLARE myportal CURSOR FOR select * from pg_database
SEND MESSAGE : 2018/09/03 18:16:35.358
<information send to backend...>
RECEIVE MESSAGE : 2018/09/03 18:16:35.359
<information receive from backend...>
END : 2018/09/03 18:16:35.360
...
To collect the log, set the connection string or environment variable.
- logdir or PGLOGDIR : directory where log file written
- logsize or PGLOGSIZE : maximum log sizeHow we can specify the log file name? What should happen if a file size exceeds
to PGLOGSIZE?
The log file name is determined as follow.
libpq-%ApplicationName-%Y-%m-%d_%H%M%S.log
When the log file size exceeds to PGLOGSIZE, the log is output to another file.
Regards,
Aya Iwata
"Iwata, Aya" <iwata.aya@jp.fujitsu.com> writes:
The purpose of this log acquisition I thought is to identify where is the problem:
server side, application side or traffic.
TBH, I think the sort of logging you're proposing would be expensive
enough that *it* would be the bottleneck in a lot of cases. A lot
of people find that the existing server-side "log_statement" support
is too expensive to keep turned on in production --- and that logs only
received SQL queries, not the returned data, and certainly not every
message passed over the wire.
regards, tom lane
On 04/09/2018 02:29, Iwata, Aya wrote:
Since I'd like to monitor the information the server and the client exchange,
I think monitoring protocol messages is good.When a slow query is occurs, we check this client side trace log.
The purpose of this log acquisition I thought is to identify where is the problem:
server side, application side or traffic.
And if the problem is in application side, checking the trace log to identify what is the problem.
Between perf/systemtap/dtrace and wireshark, you can already do pretty
much all of that. Have you looked at those and found anything missing?
--
Peter Eisentraut http://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services
Let me explain this trace log in a bit more detail.
This log is not turned on in the system by default.
Turn it on when an issue occurs and you want to check the information in the application in order to clarify the cause.
I will present three use cases for this log.
1. Confirmation on cause of out-of-memory
We assume that Out-of-memory occurred in the process of storing the data received from the database.
However, the contents or length of the data is not known.
A trace log is obtained to find these out and what kind of data you have in which part (i.e. query result when receiving from database).
2. Protocol error confirmation
When there is an error in the protocol transmitted from the client and an error occurs in the database server, the protocol sent by the client is checked.
When the network is unstable, log is checked whether the database server is receiving protocol messages.
3. Processing delay survey
If the processing in the application is slow and the processing in the database is fast, investigate the cause of the processing delay.
4 kind of time can be obtained by the log;
Timestamp when SQL started
Timestamp when information began to be sent to the backend
Timestamp when information is successfully received in the application
Timestamp when SQL ended
Then the difference between the time is checked to find out which part of process takes time.
I reconfirm the function I proposed.
If get the trace log, set PGLOGDIR/logdir and PGLOGSIZE/logsize.
These parameters are set in the environment variable or the connection service file.
- logdir or PGLOGDIR : directory where log file written
- logsize or PGLOGSIZE : maximum log size. When the log file size exceeds to PGLOGSIZE, the log is output to another file.
The log file name is determined as follow.
libpq-%ConnectionID-%Y-%m-%d_%H%M%S.log
This is a trace log example;
...
Start: 2018-09-03 18:16:35.357 Connection(1)
Status: Connection
Send message: 2018-09-03 18:16:35.358
<information send to backend...>
Receive message: 2018-09-03 18:16:35.359
<information receive from backend...>
End: 2018-09-03 18:16:35.360
...
Start: 2018-09-03 18:16:35.357 Connection(1) ...(1), (2)
Query: DECLARE myportal CURSOR FOR select * from pg_database ...(3)
Send message: 2018-09-03 18:16:35.358 ...(4)
<information send to backend...> ...(5)
Receive message: 2018/09/03 18:16:35.359 ...(6)
<information receive from backend...> ...(7)
End: 2018-09-03 18:16:35.360 ...(8)
...
(1) Timestamp when SQL started
(2) Connection ID (Identify the connection)
(3) SQL statement
(4) Timestamp when information began to be sent to the backend
(5) send message to backend (Result of query, Protocol messages)
(6) Timestamp when information is successfully received in the application
(7) receive message from backend (Result of query, Protocol messages)
(8) Timestamp when SQL ended
Regards,
Iwata Aya
Hi,
Sorry for my late response.
Between perf/systemtap/dtrace and wireshark, you can already do pretty much
all of that. Have you looked at those and found anything missing?
These commands provide detailed information to us.
However, I think the trace log is necessary from the following point.
1. ease of use for users
It is necessary to take information that is easy to understand for database users.
This trace log is retrieved on the application server side.
Not only the database developer but also application developer will get and check this log.
Also, some of these commands return detailed PostgreSQL function names.
The trace log would be useful for users who do not know the inside of PostgreSQL (e.g. application developers)
2. obtain the same information on all OS
Some commands depend on the OS.
I think that it is important that the trace log information is compatible to each OS.
Regards,
Aya Iwata
Hi,
I create a first libpq trace log patch.
In this patch,
- All message that PQtrace() gets are output to the libpq trace log file
(I maybe select more effective message in the future patch)
- Trace log output style is changed slightly from previously proposed
This patch not include documentation,
but you can see parameter detail and how to use it by looking at my previous e-mail.
If get the trace log, set PGLOGDIR/logdir and PGLOGSIZE/logsize.
These parameters are set in the environment variable or the connection service
file.
- logdir or PGLOGDIR : directory where log file written
- logsize or PGLOGSIZE : maximum log size(M). When the log file size exceeds to
PGLOGSIZE, the log is output to another file.
The log file name is determined as follow.
libpq-%ProcessID-%Y-%m-%d_%H%M%S.log
Trace log example;
Start : 2018/10/30 08:02:24.433 ... time(a)
Query: SELECT pg_catalog.set_config('search_path', '', false)
To backend> Msg Q
To backend> "SELECT pg_catalog.set_config('search_path', '', false)"
To backend> Msg complete, length 60
Start sending message to backend: 2018/10/30 08:02:24.433 ... time(b)
End sending message to backend: 2018/10/30 08:02:24.433 ... time(c)
Start receiving message from backend: 2018/10/30 08:02:24.434 ... time(d)
End receiving message from backend: 2018/10/30 08:02:24.434 ... time(e)
From backend> T
From backend (#4)> 35
From backend (#2)> 1
From backend> "set_config"
From backend (#4)> 0
From backend (#2)> 0
From backend (#4)> 25
From backend (#2)> 65535
From backend (#4)> -1
From backend (#2)> 0
From backend> D
From backend (#4)> 10
From backend (#2)> 1
From backend (#4)> 0
From backend> C
From backend (#4)> 13
From backend> "SELECT 1"
From backend> Z
From backend (#4)> 5
From backend> Z
From backend (#4)> 5
From backend> I
End : 2018/10/30 08:02:24.435 ... time(f)
From time(a) to time(b): time for libpq processing
From time(b) to time(c): time for traffic
From time(c) to time(d): time for backend processing
From time(d) to time(e): time for traffic
From time(e) to time(f): time for libpq processing
Regards,
Aya Iwata
Attachments:
v1-0001-libpq-trace-log.patchapplication/octet-stream; name=v1-0001-libpq-trace-log.patchDownload
diff --git a/src/interfaces/libpq/fe-connect.c b/src/interfaces/libpq/fe-connect.c
index d001bc5..6bdf2df 100644
--- a/src/interfaces/libpq/fe-connect.c
+++ b/src/interfaces/libpq/fe-connect.c
@@ -325,6 +325,15 @@ static const internalPQconninfoOption PQconninfoOptions[] = {
"Target-Session-Attrs", "", 11, /* sizeof("read-write") = 11 */
offsetof(struct pg_conn, target_session_attrs)},
+ /* libpq trace log options */
+ {"logdir", "PGLOGDIR", NULL, NULL,
+ "Logdir", "", MAXPGPATH - 4,
+ offsetof(struct pg_conn, logdir)},
+
+ {"logsize", "PGLOGSIZE", NULL, NULL,
+ "Logsize", "", 5,
+ offsetof(struct pg_conn, logsize_str)},
+
/* Terminating entry --- MUST BE LAST */
{NULL, NULL, NULL, NULL,
NULL, NULL, 0}
@@ -1128,6 +1137,19 @@ connectOptions2(PGconn *conn)
}
/*
+ * If both size and directory of trace log was given,
+ * initialize a trace log.
+ */
+ if (conn->logsize_str && conn->logsize_str[0] != '\0')
+ conn->logsize = atoi(conn->logsize_str);
+
+ if (conn->logdir != NULL && conn->logsize > 0 && conn->logsize < 2048)
+ {
+ conn->logsize = conn->logsize * 1024 * 1024;
+ initTraceLog(conn);
+ }
+
+ /*
* If password was not given, try to look it up in password file. Note
* that the result might be different for each host/port pair.
*/
@@ -3687,6 +3709,14 @@ freePGconn(PGconn *conn)
termPQExpBuffer(&conn->errorMessage);
termPQExpBuffer(&conn->workBuffer);
+ /* clean up libpq trace log structures */
+ if (conn->logsize_str)
+ free(conn->logsize_str);
+ if (conn->logdir)
+ free(conn->logdir);
+ if (conn->traceDebug)
+ fclose(conn->traceDebug);
+
free(conn);
#ifdef WIN32
@@ -3722,6 +3752,8 @@ sendTerminateConn(PGconn *conn)
*/
if (conn->sock != PGINVALID_SOCKET && conn->status == CONNECTION_OK)
{
+ if (conn->Pfdebug || conn->traceDebug)
+ traceLog_fprintf(conn, true, "Send connection terminate message to backend: ");
/*
* Try to send "close connection" message to backend. Ignore any
* error.
@@ -4124,6 +4156,9 @@ int
pqPacketSend(PGconn *conn, char pack_type,
const void *buf, size_t buf_len)
{
+ if (conn->Pfdebug || conn->traceDebug)
+ traceLog_fprintf(conn, true, "Send connection start message to backend: ");
+
/* Start the message. */
if (pqPutMsgStart(pack_type, true, conn))
return STATUS_ERROR;
diff --git a/src/interfaces/libpq/fe-exec.c b/src/interfaces/libpq/fe-exec.c
index 6aed8c8..d326e66 100644
--- a/src/interfaces/libpq/fe-exec.c
+++ b/src/interfaces/libpq/fe-exec.c
@@ -879,7 +879,7 @@ pqInternalNotice(const PGNoticeHooks *hooks, const char *fmt,...)
res->errMsg = (char *) pqResultAlloc(res, strlen(msgBuf) + 2, false);
if (res->errMsg)
{
- sprintf(res->errMsg, "%s\n", msgBuf);
+ sprintf(res->errMsg, "NOTICE: %s\n", msgBuf);
/*
* Pass to receiver, then free it.
@@ -991,9 +991,9 @@ pqSaveParameterStatus(PGconn *conn, const char *name, const char *value)
pgParameterStatus *pstatus;
pgParameterStatus *prev;
- if (conn->Pfdebug)
- fprintf(conn->Pfdebug, "pqSaveParameterStatus: '%s' = '%s'\n",
- name, value);
+ if (conn->Pfdebug || conn->traceDebug)
+ traceLog_fprintf(conn, false, "pqSaveParameterStatus: '%s' = '%s'\n",
+ name, value);
/*
* Forget any old information about the parameter
@@ -1219,6 +1219,9 @@ PQsendQuery(PGconn *conn, const char *query)
return 0;
}
+ if (conn->traceDebug)
+ traceLog_fprintf(conn, false, "Query: %s \n",query);
+
/* construct the outgoing Query message */
if (pqPutMsgStart('Q', false, conn) < 0 ||
pqPuts(query, conn) < 0 ||
@@ -1337,6 +1340,9 @@ PQsendPrepare(PGconn *conn,
return 0;
}
+ if (conn->traceDebug)
+ traceLog_fprintf(conn, false, "Statement name: %s, Query: %s \n",stmtName, query);
+
/* construct the Parse message */
if (pqPutMsgStart('P', false, conn) < 0 ||
pqPuts(stmtName, conn) < 0 ||
@@ -1507,6 +1513,9 @@ PQsendQueryGuts(PGconn *conn,
if (command)
{
+ if (conn->traceDebug)
+ traceLog_fprintf(conn, false, "Statement name: %s, Command: %s \n",stmtName, command);
+
/* construct the Parse message */
if (pqPutMsgStart('P', false, conn) < 0 ||
pqPuts(stmtName, conn) < 0 ||
@@ -1820,6 +1829,7 @@ PQgetResult(PGconn *conn)
/* Parse it. */
parseInput(conn);
+
}
/* Return the appropriate thing. */
@@ -2006,6 +2016,9 @@ PQexecStart(PGconn *conn)
{
PGresult *result;
+ if (conn->traceDebug)
+ traceLog_fprintf(conn, true, "Start :");
+
if (!conn)
return false;
@@ -2120,6 +2133,9 @@ PQexecFinish(PGconn *conn)
break;
}
+ if (conn->traceDebug)
+ traceLog_fprintf(conn, true, "End :");
+
return lastResult;
}
@@ -2218,6 +2234,9 @@ PQsendDescribe(PGconn *conn, char desc_type, const char *desc_target)
return 0;
}
+ if (conn->traceDebug)
+ traceLog_fprintf(conn, false, "Describe type: %c, target: %s \n",desc_type, desc_target);
+
/* construct the Describe message */
if (pqPutMsgStart('D', false, conn) < 0 ||
pqPutc(desc_type, conn) < 0 ||
diff --git a/src/interfaces/libpq/fe-misc.c b/src/interfaces/libpq/fe-misc.c
index 46ece1a..fcf7c8e 100644
--- a/src/interfaces/libpq/fe-misc.c
+++ b/src/interfaces/libpq/fe-misc.c
@@ -35,6 +35,7 @@
#ifdef WIN32
#include "win32.h"
+#include <windows.h>
#else
#include <unistd.h>
#include <sys/time.h>
@@ -45,6 +46,7 @@
#endif
#ifdef HAVE_SYS_SELECT_H
#include <sys/select.h>
+#include <sys/timeb.h>
#endif
#include "libpq-fe.h"
@@ -60,6 +62,168 @@ static int pqSocketCheck(PGconn *conn, int forRead, int forWrite,
time_t end_time);
static int pqSocketPoll(int sock, int forRead, int forWrite, time_t end_time);
+static void getTraceLogFilename(PGconn *conn,char* filename);
+static void traceLog_fputnbytes(PGconn *conn, const char *head, const char *str, size_t n);
+static void fputnbytes(FILE *f, const char *str, size_t n);
+static void getCurrentTime(char* currenttime,int type);
+#define TRACELOG_TIME_SIZE 28
+
+/*
+ * getCurrentTime: get current time for trace log output
+ *
+ * type=0 currenttime formate %Y-%m-%d_%H%M%S
+ * type=1 currenttime formate %Y/%m/%d %H:%M:%S.%Milliseconds
+ */
+static void
+getCurrentTime(char* currenttime,int type)
+{
+#ifdef WIN32
+ SYSTEMTIME localTime;
+ GetLocalTime(&localTime);
+ if(type==0)
+ snprintf(currenttime,TRACELOG_TIME_SIZE,"%4d-%02d-%02d_%02d%02d%02d",
+ localTime.wYear,localTime.wMonth,localTime.wDay,
+ localTime.wHour,localTime.wMinute,localTime.wSecond);
+ else if(type==1)
+ snprintf(currenttime,TRACELOG_TIME_SIZE,"%4d/%02d/%02d %02d:%02d:%02d.%03d",
+ localTime.wYear,localTime.wMonth,localTime.wDay,
+ localTime.wHour,localTime.wMinute,localTime.wSecond,
+ localTime.wMilliseconds);
+#else
+ struct timeb localTime;
+ struct tm *tm;
+ ftime(&localTime);
+ tm = localtime(&localTime.time);
+ if(type == 0)
+ snprintf(currenttime, TRACELOG_TIME_SIZE,"%4d-%02d-%02d_%02d%02d%02d",
+ 1900+ tm->tm_year,1 + tm->tm_mon, tm->tm_mday,
+ tm->tm_hour, tm->tm_min, tm->tm_sec);
+ else if(type==1)
+ snprintf(currenttime, TRACELOG_TIME_SIZE,"%4d/%02d/%02d %02d:%02d:%02d.%03d",
+ 1900+ tm->tm_year,1 + tm->tm_mon, tm->tm_mday,
+ tm->tm_hour, tm->tm_min, tm->tm_sec, localTime.millitm);
+#endif
+}
+
+/*
+ * getTraceLogFilename: build trace log file name
+ * The name is libpq-%ProcessID-%Y-%m-%d_%H%M%S.log.
+ */
+static void
+getTraceLogFilename(PGconn *conn,char* filename)
+{
+ char currenttime[TRACELOG_TIME_SIZE]; /* %Y-%m-%d_%H%M%S */
+ getCurrentTime(currenttime,0);
+
+#ifdef WIN32
+ snprintf(filename, MAXPGPATH, "%s\\libpq-%d-%s.log", conn->logdir,getpid(),currenttime);
+#else
+ snprintf(filename, MAXPGPATH, "%s/libpq-%d-%s.log", conn->logdir,getpid(),currenttime);
+#endif
+}
+
+/*
+ * initTraceLog: initialize a trace log file
+ */
+void
+initTraceLog(PGconn *conn)
+{
+ char logfilename[MAXPGPATH];
+ getTraceLogFilename(conn,logfilename);
+ conn->traceDebug=fopen(logfilename,"w");
+}
+
+/*
+ * traceLog_fprintf: output trace log to file
+ * If PQtrace() is called, PQtrace() is output followed by libpq trace log.
+ */
+void
+traceLog_fprintf(PGconn *conn, bool addTime, const char *fmt,...)
+{
+ char logfilename[MAXPGPATH];
+ char msgBuf[MAXPGPATH];
+ va_list args;
+ int ret;
+ char currenttime[TRACELOG_TIME_SIZE];
+
+ va_start(args, fmt);
+ vsnprintf(msgBuf, sizeof(msgBuf), fmt, args);
+ msgBuf[sizeof(msgBuf) - 1] = '\0';
+ va_end(args);
+
+ if(conn->Pfdebug)
+ {
+ fprintf(conn->Pfdebug, "%s", msgBuf);
+ }
+ else if(conn->traceDebug)
+ {
+ if((int)ftell(conn->traceDebug) >= conn->logsize)
+ {
+ fclose(conn->traceDebug);
+ getTraceLogFilename(conn,logfilename);
+ conn->traceDebug = fopen(logfilename,"w");
+ if(conn->traceDebug == NULL)
+ return;
+ }
+
+ /* Select trace log message style */
+ if(addTime)
+ {
+ getCurrentTime(currenttime,1);
+ ret = fprintf(conn->traceDebug, "%s %s\n", msgBuf, currenttime);
+ }
+ else
+ {
+ ret = fprintf(conn->traceDebug, "%s",msgBuf);
+ }
+
+ if(ret < 0)
+ {
+ fclose(conn->traceDebug);
+ conn->traceDebug = NULL;
+ return;
+ }
+ fflush(conn->traceDebug);
+ }
+}
+/*
+ * traceLog_fputnbytes: output trace log to file using fputnbytes()
+ */
+static void
+traceLog_fputnbytes(PGconn *conn,const char *head, const char *str, size_t n)
+{
+ char logfilename[MAXPGPATH];
+ int ret;
+
+ if (conn->Pfdebug)
+ {
+ fprintf(conn->Pfdebug, "%s", head);
+ fputnbytes(conn->Pfdebug,str, n);
+ fprintf(conn->Pfdebug, "\n");
+ }
+ else if(conn->traceDebug)
+ {
+ if((int)ftell(conn->traceDebug) >= conn->logsize)
+ {
+ fclose(conn->traceDebug);
+ getTraceLogFilename(conn,logfilename);
+ conn->traceDebug = fopen(logfilename,"w");
+ if(conn->traceDebug == NULL)
+ return;
+ }
+ ret = fprintf(conn->traceDebug, "%s", head);
+ if(ret < 0)
+ {
+ fclose(conn->traceDebug);
+ conn->traceDebug = NULL;
+ return;
+ }
+ fputnbytes(conn->traceDebug,str,n);
+ fprintf(conn->traceDebug,"\n");
+ fflush(conn->traceDebug);
+ }
+}
+
/*
* PQlibVersion: return the libpq version number
*/
@@ -98,8 +262,8 @@ pqGetc(char *result, PGconn *conn)
*result = conn->inBuffer[conn->inCursor++];
- if (conn->Pfdebug)
- fprintf(conn->Pfdebug, "From backend> %c\n", *result);
+ if(conn->Pfdebug||conn->traceDebug)
+ traceLog_fprintf(conn, false, "From backend> %c\n", *result);
return 0;
}
@@ -114,8 +278,8 @@ pqPutc(char c, PGconn *conn)
if (pqPutMsgBytes(&c, 1, conn))
return EOF;
- if (conn->Pfdebug)
- fprintf(conn->Pfdebug, "To backend> %c\n", c);
+ if(conn->Pfdebug||conn->traceDebug)
+ traceLog_fprintf(conn, false, "To backend> %c\n", c);
return 0;
}
@@ -152,9 +316,9 @@ pqGets_internal(PQExpBuffer buf, PGconn *conn, bool resetbuffer)
conn->inCursor = ++inCursor;
- if (conn->Pfdebug)
- fprintf(conn->Pfdebug, "From backend> \"%s\"\n",
- buf->data);
+ if(conn->Pfdebug||conn->traceDebug)
+ traceLog_fprintf(conn, false, "From backend> \"%s\"\n",
+ buf->data);
return 0;
}
@@ -181,8 +345,8 @@ pqPuts(const char *s, PGconn *conn)
if (pqPutMsgBytes(s, strlen(s) + 1, conn))
return EOF;
- if (conn->Pfdebug)
- fprintf(conn->Pfdebug, "To backend> \"%s\"\n", s);
+ if(conn->Pfdebug||conn->traceDebug)
+ traceLog_fprintf(conn, false, "To backend> \"%s\"\n", s);
return 0;
}
@@ -194,6 +358,7 @@ pqPuts(const char *s, PGconn *conn)
int
pqGetnchar(char *s, size_t len, PGconn *conn)
{
+ char buf[100];
if (len > (size_t) (conn->inEnd - conn->inCursor))
return EOF;
@@ -202,11 +367,10 @@ pqGetnchar(char *s, size_t len, PGconn *conn)
conn->inCursor += len;
- if (conn->Pfdebug)
+ if(conn->Pfdebug||conn->traceDebug)
{
- fprintf(conn->Pfdebug, "From backend (%lu)> ", (unsigned long) len);
- fputnbytes(conn->Pfdebug, s, len);
- fprintf(conn->Pfdebug, "\n");
+ sprintf(buf, "From backend (%lu)> ", (unsigned long) len);
+ traceLog_fputnbytes(conn,buf,s, len);
}
return 0;
@@ -228,7 +392,7 @@ pqSkipnchar(size_t len, PGconn *conn)
if (conn->Pfdebug)
{
- fprintf(conn->Pfdebug, "From backend (%lu)> ", (unsigned long) len);
+ fprintf(conn->Pfdebug, "(pqSkipnchar)From backend (%lu)> ", (unsigned long) len);
fputnbytes(conn->Pfdebug, conn->inBuffer + conn->inCursor, len);
fprintf(conn->Pfdebug, "\n");
}
@@ -245,14 +409,14 @@ pqSkipnchar(size_t len, PGconn *conn)
int
pqPutnchar(const char *s, size_t len, PGconn *conn)
{
+ char buf[100];
if (pqPutMsgBytes(s, len, conn))
return EOF;
- if (conn->Pfdebug)
+ if(conn->Pfdebug||conn->traceDebug)
{
- fprintf(conn->Pfdebug, "To backend> ");
- fputnbytes(conn->Pfdebug, s, len);
- fprintf(conn->Pfdebug, "\n");
+ sprintf(buf,"To backend (%lu)> ", (unsigned long) len);
+ traceLog_fputnbytes(conn,buf,s,len);
}
return 0;
@@ -292,8 +456,8 @@ pqGetInt(int *result, size_t bytes, PGconn *conn)
return EOF;
}
- if (conn->Pfdebug)
- fprintf(conn->Pfdebug, "From backend (#%lu)> %d\n", (unsigned long) bytes, *result);
+ if(conn->Pfdebug||conn->traceDebug)
+ traceLog_fprintf(conn, false, "From backend (#%lu)> %d\n", (unsigned long) bytes, *result);
return 0;
}
@@ -328,8 +492,8 @@ pqPutInt(int value, size_t bytes, PGconn *conn)
return EOF;
}
- if (conn->Pfdebug)
- fprintf(conn->Pfdebug, "To backend (%lu#)> %d\n", (unsigned long) bytes, value);
+ if(conn->Pfdebug||conn->traceDebug)
+ traceLog_fprintf(conn, false, "To backend (%lu#)> %d\n", (unsigned long) bytes, value);
return 0;
}
@@ -548,9 +712,9 @@ pqPutMsgStart(char msg_type, bool force_len, PGconn *conn)
conn->outMsgEnd = endPos;
/* length word, if needed, will be filled in by pqPutMsgEnd */
- if (conn->Pfdebug)
- fprintf(conn->Pfdebug, "To backend> Msg %c\n",
- msg_type ? msg_type : ' ');
+ if(conn->Pfdebug||conn->traceDebug)
+ traceLog_fprintf(conn, false, "To backend> Msg %c\n",
+ msg_type ? msg_type : ' ');
return 0;
}
@@ -586,9 +750,9 @@ pqPutMsgBytes(const void *buf, size_t len, PGconn *conn)
int
pqPutMsgEnd(PGconn *conn)
{
- if (conn->Pfdebug)
- fprintf(conn->Pfdebug, "To backend> Msg complete, length %u\n",
- conn->outMsgEnd - conn->outCount);
+ if(conn->Pfdebug||conn->traceDebug)
+ traceLog_fprintf(conn, false, "To backend> Msg complete, length %u\n",
+ conn->outMsgEnd - conn->outCount);
/* Fill in length word if needed */
if (conn->outMsgStart >= 0)
@@ -677,9 +841,16 @@ pqReadData(PGconn *conn)
}
/* OK, try to read some data */
+
+ if (conn->traceDebug)
+ traceLog_fprintf(conn, true, "Start receiving message from backend:");
retry3:
nread = pqsecure_read(conn, conn->inBuffer + conn->inEnd,
conn->inBufSize - conn->inEnd);
+
+ if (conn->traceDebug)
+ traceLog_fprintf(conn, true, "End receiving message from backend:");
+
if (nread < 0)
{
if (SOCK_ERRNO == EINTR)
@@ -767,9 +938,16 @@ retry3:
* Still not sure that it's EOF, because some data could have just
* arrived.
*/
+
+ if (conn->traceDebug)
+ traceLog_fprintf(conn, true, "Start receiving message from backend:");
retry4:
nread = pqsecure_read(conn, conn->inBuffer + conn->inEnd,
conn->inBufSize - conn->inEnd);
+
+ if (conn->traceDebug)
+ traceLog_fprintf(conn, true, "End receiving message from backend:");
+
if (nread < 0)
{
if (SOCK_ERRNO == EINTR)
@@ -846,6 +1024,9 @@ pqSendSome(PGconn *conn, int len)
{
int sent;
+ if (conn->traceDebug)
+ traceLog_fprintf(conn, true, "Start sending message to backend:");
+
#ifndef WIN32
sent = pqsecure_write(conn, ptr, len);
#else
@@ -858,6 +1039,9 @@ pqSendSome(PGconn *conn, int len)
sent = pqsecure_write(conn, ptr, Min(len, 65536));
#endif
+ if (conn->traceDebug)
+ traceLog_fprintf(conn, true, "End sending message to backend:");
+
if (sent < 0)
{
/* Anything except EAGAIN/EWOULDBLOCK/EINTR is trouble */
diff --git a/src/interfaces/libpq/libpq-int.h b/src/interfaces/libpq/libpq-int.h
index 975ab33..2aa8a51 100644
--- a/src/interfaces/libpq/libpq-int.h
+++ b/src/interfaces/libpq/libpq-int.h
@@ -499,6 +499,11 @@ struct pg_conn
/* Buffer for receiving various parts of messages */
PQExpBufferData workBuffer; /* expansible string */
+
+ char *logsize_str; /* Trace log maximum size (string) */
+ int logsize; /* Trace log maximum size */
+ char *logdir; /* Trace log directory to save log */
+ FILE *traceDebug; /* Trace log file to write trace info */
};
/* PGcancel stores all data necessary to cancel a connection. A copy of this
@@ -665,6 +670,10 @@ extern void pq_reset_sigpipe(sigset_t *osigset, bool sigpipe_pending,
bool got_epipe);
#endif
+/* libpq trace log */
+extern void initTraceLog(PGconn *conn);
+extern void traceLog_fprintf(PGconn *conn, bool addTime, const char *fmt,...) pg_attribute_printf(3, 4);
+
/* === SSL === */
/*
Greetings,
This is my first attempt at a patch review, so I will take a pass at the
low hanging fruit.
Initial Pass
============
+ Patch applies
+ Patch builds
+ Patch behaves as described in the thread
I tried a few small things:
When I set a relative path for `PGLOGDIR`, the files were correctly
written to the directory.
When I set a path for `PGLOGDIR` that didn't exist or was not
write-able, the patch writes no files, and does not alert the user that
no files are being written.
Performance
===========
I ran two permutations of make check, one with the patch applied but not
activated, and the other with with the files being written to disk. Each
permutation was run ten times, and the stats are below (times are in
seconds):
min max median mean
not logging 50.4 57.6 53.3 53.4
logging 58.3 77.7 65.0 65.8
Cheers,
Jim Doty
On Tue, Oct 30, 2018 at 2:39 AM Iwata, Aya <iwata.aya@jp.fujitsu.com> wrote:
I create a first libpq trace log patch.
Couple additional thoughts from a read-through of the patch:
- PQtrace() and the new trace-logging machinery overlap in some places
but not others -- and if both are set, PQtrace() will take precedence.
It seems like the two should not be separate.
- It isn't immediately clear to me how the new information in the logs
is intended to be used in concert with the old information. Maybe this
goes back to the comments by Tom and Robert higher in the thread --
that an overhaul of the PQtrace system is due. This patch as presented
would make things a little worse before they got better, I think.
That said, I think the overall idea -- application performance
information that can be enabled via the environment, without requiring
debugging privileges on a machine or the need to manually correlate
traces made by other applications -- is a good one, and something I
would use.
--Jacob
On Tue, Oct 30, 2018 at 8:38 PM Iwata, Aya <iwata.aya@jp.fujitsu.com> wrote:
Hi,
I create a first libpq trace log patch.
In this patch,
- All message that PQtrace() gets are output to the libpq trace log file
(I maybe select more effective message in the future patch)
- Trace log output style is changed slightly from previously proposedThis patch not include documentation,
but you can see parameter detail and how to use it by looking at my
previous e-mail.If get the trace log, set PGLOGDIR/logdir and PGLOGSIZE/logsize.
These parameters are set in the environment variable or the connection
service
file.
- logdir or PGLOGDIR : directory where log file written
- logsize or PGLOGSIZE : maximum log size(M). When the log file size
exceeds to
PGLOGSIZE, the log is output to another file.The log file name is determined as follow.
libpq-%ProcessID-%Y-%m-%d_%H%M%S.logTrace log example;
Start : 2018/10/30 08:02:24.433
... time(a)
Query: SELECT pg_catalog.set_config('search_path', '', false)
To backend> Msg Q
To backend> "SELECT pg_catalog.set_config('search_path', '', false)"
To backend> Msg complete, length 60
Start sending message to backend: 2018/10/30 08:02:24.433
... time(b)
End sending message to backend: 2018/10/30 08:02:24.433
... time(c)
Start receiving message from backend: 2018/10/30 08:02:24.434 ... time(d)
End receiving message from backend: 2018/10/30 08:02:24.434 ... time(e)
From backend> T
From backend (#4)> 35
From backend (#2)> 1
From backend> "set_config"
From backend (#4)> 0
From backend (#2)> 0
From backend (#4)> 25
From backend (#2)> 65535
From backend (#4)> -1
From backend (#2)> 0
From backend> D
From backend (#4)> 10
From backend (#2)> 1
From backend (#4)> 0
From backend> C
From backend (#4)> 13
From backend> "SELECT 1"
From backend> Z
From backend (#4)> 5
From backend> Z
From backend (#4)> 5
From backend> I
End : 2018/10/30 08:02:24.435 ... time(f)From time(a) to time(b): time for libpq processing
From time(b) to time(c): time for traffic
From time(c) to time(d): time for backend processing
From time(d) to time(e): time for traffic
From time(e) to time(f): time for libpq processing
Thanks for the patch.
I have some comments related to the trace output that is getting
printed. The amount of log it is generating may not be understood
to many of the application developers. IMO, this should print
only the necessary information that can understood by any one
by default and full log with more configuration?
Regards,
Haribabu Kommi
Fujitsu Australia
Hi Jim Doty san,
Thank you for review! I'm sorry my late reply...
Initial Pass
============+ Patch applies + Patch builds + Patch behaves as described in the thread
Thank you for your check.
When I set a path for `PGLOGDIR` that didn't exist or was not write-able,
the patch writes no files, and does not alert the user that no files are being
written.
I understand. I think it means that it is necessary to confirm how the setting is going well.
There is no warning method when connection string or the environment variable is wrong.
So I added following document:
+ If the setting of the file path by the connection string or the environment variable is
+ incorrect, the log file is not created in the intended location.
+ The maximum log file size you set is output to the beginning of the file, so you can check it.
And I added the process. Please see my v2 patch.
Performance
===========I ran two permutations of make check, one with the patch applied but not
activated, and the other with with the files being written to disk. Each
permutation was run ten times, and the stats are below (times are in
seconds):min max median mean
not logging 50.4 57.6 53.3 53.4
logging 58.3 77.7 65.0 65.8
Thank you for your measurement.
I'm thinking about adding a logging level so that only the necessary information can be printed by default. It was pointed out by Haribabu san's e-mail.
This minimizes the impact of logging on performance.
Regards,
Aya Iwata
Attachments:
v2-0001-libpq-trace-log.patchapplication/octet-stream; name=v2-0001-libpq-trace-log.patchDownload
diff --git a/doc/src/sgml/libpq.sgml b/doc/src/sgml/libpq.sgml
index d2e5b08..0d46d38 100644
--- a/doc/src/sgml/libpq.sgml
+++ b/doc/src/sgml/libpq.sgml
@@ -1589,6 +1589,28 @@ postgresql://%2Fvar%2Flib%2Fpostgresql/dbname
</para>
</listitem>
</varlistentry>
+
+ <varlistentry id="libpq-connect-log-dir" xreflabel="logdir">
+ <term><literal>logdir</literal></term>
+ <listitem>
+ <para>
+ Path of directory where log file written. When both <literal>logdir</literal>
+ and <literal>logsize</literal> is set, logging is enabled.
+ </para>
+ </listitem>
+ </varlistentry>
+
+ <varlistentry id="libpq-connect-log-size" xreflabel="logsize">
+ <term><literal>logsize</literal></term>
+ <listitem>
+ <para>
+ Maximum log size. The unit is megabyte. When the log file size exceeds
+ to <literal>logsize</literal>, the log is output to another file.
+ When both <literal>logdir</literal> and <literal>logsize</literal> is set,
+ logging is enabled.
+ </para>
+ </listitem>
+ </varlistentry>
</variablelist>
</para>
</sect2>
@@ -7472,6 +7494,26 @@ myEventProc(PGEventId evtId, void *evtInfo, void *passThrough)
linkend="libpq-connect-target-session-attrs"/> connection parameter.
</para>
</listitem>
+
+ <listitem>
+ <para>
+ <indexterm>
+ <primary><envar>PGLOGDIR</envar></primary>
+ </indexterm>
+ <envar>PGLOGDIR</envar> behaves the same as the <xref
+ linkend="libpq-connect-log-dir"/> connection parameter.
+ </para>
+ </listitem>
+
+ <listitem>
+ <para>
+ <indexterm>
+ <primary><envar>PGLOGSIZE</envar></primary>
+ </indexterm>
+ <envar>PGLOGSIZE</envar> behaves the same as the <xref
+ linkend="libpq-connect-log-size"/> connection parameter.
+ </para>
+ </listitem>
</itemizedlist>
</para>
@@ -8300,6 +8342,35 @@ int PQisthreadsafe();
</para>
</sect1>
+ <sect1 id="libpq-logging">
+ <title>Logging</title>
+
+ <indexterm zone="libpq-logging">
+ <primary>trace log</primary>
+ </indexterm>
+ <indexterm zone="libpq-logging">
+ <primary>logging</primary>
+ </indexterm>
+
+ <para>
+ Libpq trace log can trace information about SQL queries which issued by
+ the libpq application. This output help determine whether the couse is
+ on backend side or application side and solve issues with the libpq Driver
+ when it use. The log without requiring recompile of the libpq application.
+ </para>
+
+ <para>
+ You can activate this log by setting both <parameter>logdir</parameter> and
+ <parameter>logsize</parameter> of the connection string, or by setting both
+ the environment variables <envar>PGLOGDIR</envar> and <envar>PGLOGSIZE</envar>.
+ The log trace file is written in a directory setting by <envar>PGLOGDIR</envar>
+ or <parameter>logdir</parameter>.
+ The file name is determined as <filename>libpq-%ProcessID-%Y-%m-%d_%H%M%S.log</filename>.
+ If the setting of the file path by the connection string or the environment variable is
+ incorrect, the log file is not created in the intended location.
+ The maximum log file size you set is output to the beginning of the file, so you can check it.
+ </para>
+ </sect1>
<sect1 id="libpq-build">
<title>Building <application>libpq</application> Programs</title>
diff --git a/src/interfaces/libpq/fe-connect.c b/src/interfaces/libpq/fe-connect.c
index bc456fe..67c1f12 100644
--- a/src/interfaces/libpq/fe-connect.c
+++ b/src/interfaces/libpq/fe-connect.c
@@ -325,6 +325,15 @@ static const internalPQconninfoOption PQconninfoOptions[] = {
"Target-Session-Attrs", "", 11, /* sizeof("read-write") = 11 */
offsetof(struct pg_conn, target_session_attrs)},
+ /* libpq trace log options */
+ {"logdir", "PGLOGDIR", NULL, NULL,
+ "Logdir", "", MAXPGPATH - 4,
+ offsetof(struct pg_conn, logdir)},
+
+ {"logsize", "PGLOGSIZE", NULL, NULL,
+ "Logsize", "", 5,
+ offsetof(struct pg_conn, logsize_str)},
+
/* Terminating entry --- MUST BE LAST */
{NULL, NULL, NULL, NULL,
NULL, NULL, 0}
@@ -1128,6 +1137,19 @@ connectOptions2(PGconn *conn)
}
/*
+ * If both size and directory of trace log was given,
+ * initialize a trace log.
+ */
+ if (conn->logsize_str && conn->logsize_str[0] != '\0')
+ conn->logsize = atoi(conn->logsize_str);
+
+ if (conn->logdir != NULL && conn->logsize > 0 && conn->logsize < 2048)
+ {
+ conn->logsize = conn->logsize * 1024 * 1024;
+ initTraceLog(conn);
+ }
+
+ /*
* If password was not given, try to look it up in password file. Note
* that the result might be different for each host/port pair.
*/
@@ -3716,6 +3738,14 @@ freePGconn(PGconn *conn)
termPQExpBuffer(&conn->errorMessage);
termPQExpBuffer(&conn->workBuffer);
+ /* clean up libpq trace log structures */
+ if (conn->logsize_str)
+ free(conn->logsize_str);
+ if (conn->logdir)
+ free(conn->logdir);
+ if (conn->traceDebug)
+ fclose(conn->traceDebug);
+
free(conn);
#ifdef WIN32
@@ -3751,6 +3781,8 @@ sendTerminateConn(PGconn *conn)
*/
if (conn->sock != PGINVALID_SOCKET && conn->status == CONNECTION_OK)
{
+ if (conn->Pfdebug || conn->traceDebug)
+ traceLog_fprintf(conn, true, "Send connection terminate message to backend: ");
/*
* Try to send "close connection" message to backend. Ignore any
* error.
@@ -4153,6 +4185,9 @@ int
pqPacketSend(PGconn *conn, char pack_type,
const void *buf, size_t buf_len)
{
+ if (conn->Pfdebug || conn->traceDebug)
+ traceLog_fprintf(conn, true, "Send connection start message to backend: ");
+
/* Start the message. */
if (pqPutMsgStart(pack_type, true, conn))
return STATUS_ERROR;
diff --git a/src/interfaces/libpq/fe-exec.c b/src/interfaces/libpq/fe-exec.c
index 6aed8c8..675d1bd 100644
--- a/src/interfaces/libpq/fe-exec.c
+++ b/src/interfaces/libpq/fe-exec.c
@@ -879,7 +879,7 @@ pqInternalNotice(const PGNoticeHooks *hooks, const char *fmt,...)
res->errMsg = (char *) pqResultAlloc(res, strlen(msgBuf) + 2, false);
if (res->errMsg)
{
- sprintf(res->errMsg, "%s\n", msgBuf);
+ sprintf(res->errMsg, "NOTICE: %s\n", msgBuf);
/*
* Pass to receiver, then free it.
@@ -991,9 +991,9 @@ pqSaveParameterStatus(PGconn *conn, const char *name, const char *value)
pgParameterStatus *pstatus;
pgParameterStatus *prev;
- if (conn->Pfdebug)
- fprintf(conn->Pfdebug, "pqSaveParameterStatus: '%s' = '%s'\n",
- name, value);
+ if (conn->Pfdebug || conn->traceDebug)
+ traceLog_fprintf(conn, false, "pqSaveParameterStatus: '%s' = '%s'\n",
+ name, value);
/*
* Forget any old information about the parameter
@@ -1208,6 +1208,9 @@ fail:
int
PQsendQuery(PGconn *conn, const char *query)
{
+ if (conn->traceDebug)
+ traceLog_fprintf(conn, true, "PQsendQuery start :");
+
if (!PQsendQueryStart(conn))
return 0;
@@ -1219,6 +1222,9 @@ PQsendQuery(PGconn *conn, const char *query)
return 0;
}
+ if (conn->traceDebug)
+ traceLog_fprintf(conn, false, "Query: %s \n",query);
+
/* construct the outgoing Query message */
if (pqPutMsgStart('Q', false, conn) < 0 ||
pqPuts(query, conn) < 0 ||
@@ -1249,6 +1255,10 @@ PQsendQuery(PGconn *conn, const char *query)
/* OK, it's launched! */
conn->asyncStatus = PGASYNC_BUSY;
+
+ if (conn->traceDebug)
+ traceLog_fprintf(conn, true, "PQsendQuery end :");
+
return 1;
}
@@ -1266,6 +1276,9 @@ PQsendQueryParams(PGconn *conn,
const int *paramFormats,
int resultFormat)
{
+ if (conn->traceDebug)
+ traceLog_fprintf(conn, true, "PQsendQueryParams start :");
+
if (!PQsendQueryStart(conn))
return 0;
@@ -1283,6 +1296,9 @@ PQsendQueryParams(PGconn *conn,
return 0;
}
+ if (conn->traceDebug)
+ traceLog_fprintf(conn, true, "PQsendQueryParams end :");
+
return PQsendQueryGuts(conn,
command,
"", /* use unnamed statement */
@@ -1306,6 +1322,9 @@ PQsendPrepare(PGconn *conn,
const char *stmtName, const char *query,
int nParams, const Oid *paramTypes)
{
+ if (conn->traceDebug)
+ traceLog_fprintf(conn, true, "PQsendPrepare start :");
+
if (!PQsendQueryStart(conn))
return 0;
@@ -1337,6 +1356,9 @@ PQsendPrepare(PGconn *conn,
return 0;
}
+ if (conn->traceDebug)
+ traceLog_fprintf(conn, false, "Statement name: %s, Query: %s \n",stmtName, query);
+
/* construct the Parse message */
if (pqPutMsgStart('P', false, conn) < 0 ||
pqPuts(stmtName, conn) < 0 ||
@@ -1386,6 +1408,10 @@ PQsendPrepare(PGconn *conn,
/* OK, it's launched! */
conn->asyncStatus = PGASYNC_BUSY;
+
+ if (conn->traceDebug)
+ traceLog_fprintf(conn, true, "PQsendPrepare end :");
+
return 1;
sendFailed:
@@ -1492,6 +1518,9 @@ PQsendQueryGuts(PGconn *conn,
{
int i;
+ if (conn->traceDebug)
+ traceLog_fprintf(conn, true, "PQsendQueryGuts start :");
+
/* This isn't gonna work on a 2.0 server */
if (PG_PROTOCOL_MAJOR(conn->pversion) < 3)
{
@@ -1507,6 +1536,9 @@ PQsendQueryGuts(PGconn *conn,
if (command)
{
+ if (conn->traceDebug)
+ traceLog_fprintf(conn, false, "Statement name: %s, Command: %s \n",stmtName, command);
+
/* construct the Parse message */
if (pqPutMsgStart('P', false, conn) < 0 ||
pqPuts(stmtName, conn) < 0 ||
@@ -1638,6 +1670,10 @@ PQsendQueryGuts(PGconn *conn,
/* OK, it's launched! */
conn->asyncStatus = PGASYNC_BUSY;
+
+ if (conn->traceDebug)
+ traceLog_fprintf(conn, true, "PQsendQueryGuts end :");
+
return 1;
sendFailed:
@@ -1820,6 +1856,7 @@ PQgetResult(PGconn *conn)
/* Parse it. */
parseInput(conn);
+
}
/* Return the appropriate thing. */
@@ -2081,6 +2118,9 @@ PQexecFinish(PGconn *conn)
PGresult *result;
PGresult *lastResult;
+ if (conn->traceDebug)
+ traceLog_fprintf(conn, true, "PQexecFinish start :");
+
/*
* For backwards compatibility, return the last result if there are more
* than one --- but merge error messages if we get more than one error
@@ -2120,6 +2160,9 @@ PQexecFinish(PGconn *conn)
break;
}
+ if (conn->traceDebug)
+ traceLog_fprintf(conn, true, "PQexecFinish end :");
+
return lastResult;
}
@@ -2203,6 +2246,9 @@ PQsendDescribePortal(PGconn *conn, const char *portal)
static int
PQsendDescribe(PGconn *conn, char desc_type, const char *desc_target)
{
+ if (conn->traceDebug)
+ traceLog_fprintf(conn, true, "PQsendDescribe start :");
+
/* Treat null desc_target as empty string */
if (!desc_target)
desc_target = "";
@@ -2218,6 +2264,9 @@ PQsendDescribe(PGconn *conn, char desc_type, const char *desc_target)
return 0;
}
+ if (conn->traceDebug)
+ traceLog_fprintf(conn, false, "Describe type: %c, target: %s \n",desc_type, desc_target);
+
/* construct the Describe message */
if (pqPutMsgStart('D', false, conn) < 0 ||
pqPutc(desc_type, conn) < 0 ||
@@ -2249,6 +2298,10 @@ PQsendDescribe(PGconn *conn, char desc_type, const char *desc_target)
/* OK, it's launched! */
conn->asyncStatus = PGASYNC_BUSY;
+
+ if (conn->traceDebug)
+ traceLog_fprintf(conn, true, "PQsendDescribe end :");
+
return 1;
sendFailed:
diff --git a/src/interfaces/libpq/fe-misc.c b/src/interfaces/libpq/fe-misc.c
index 46ece1a..ba60acb 100644
--- a/src/interfaces/libpq/fe-misc.c
+++ b/src/interfaces/libpq/fe-misc.c
@@ -35,6 +35,7 @@
#ifdef WIN32
#include "win32.h"
+#include <windows.h>
#else
#include <unistd.h>
#include <sys/time.h>
@@ -45,6 +46,7 @@
#endif
#ifdef HAVE_SYS_SELECT_H
#include <sys/select.h>
+#include <sys/timeb.h>
#endif
#include "libpq-fe.h"
@@ -60,6 +62,169 @@ static int pqSocketCheck(PGconn *conn, int forRead, int forWrite,
time_t end_time);
static int pqSocketPoll(int sock, int forRead, int forWrite, time_t end_time);
+static void getTraceLogFilename(PGconn *conn,char* filename);
+static void traceLog_fputnbytes(PGconn *conn, const char *head, const char *str, size_t n);
+static void fputnbytes(FILE *f, const char *str, size_t n);
+static void getCurrentTime(char* currenttime,int type);
+#define TRACELOG_TIME_SIZE 28
+
+/*
+ * getCurrentTime: get current time for trace log output
+ *
+ * type=0 currenttime formate %Y-%m-%d_%H%M%S
+ * type=1 currenttime formate %Y/%m/%d %H:%M:%S.%Milliseconds
+ */
+static void
+getCurrentTime(char* currenttime,int type)
+{
+#ifdef WIN32
+ SYSTEMTIME localTime;
+ GetLocalTime(&localTime);
+ if(type==0)
+ snprintf(currenttime,TRACELOG_TIME_SIZE,"%4d-%02d-%02d_%02d%02d%02d",
+ localTime.wYear,localTime.wMonth,localTime.wDay,
+ localTime.wHour,localTime.wMinute,localTime.wSecond);
+ else if(type==1)
+ snprintf(currenttime,TRACELOG_TIME_SIZE,"%4d/%02d/%02d %02d:%02d:%02d.%03d",
+ localTime.wYear,localTime.wMonth,localTime.wDay,
+ localTime.wHour,localTime.wMinute,localTime.wSecond,
+ localTime.wMilliseconds);
+#else
+ struct timeb localTime;
+ struct tm *tm;
+ ftime(&localTime);
+ tm = localtime(&localTime.time);
+ if(type == 0)
+ snprintf(currenttime, TRACELOG_TIME_SIZE,"%4d-%02d-%02d_%02d%02d%02d",
+ 1900+ tm->tm_year,1 + tm->tm_mon, tm->tm_mday,
+ tm->tm_hour, tm->tm_min, tm->tm_sec);
+ else if(type==1)
+ snprintf(currenttime, TRACELOG_TIME_SIZE,"%4d/%02d/%02d %02d:%02d:%02d.%03d",
+ 1900+ tm->tm_year,1 + tm->tm_mon, tm->tm_mday,
+ tm->tm_hour, tm->tm_min, tm->tm_sec, localTime.millitm);
+#endif
+}
+
+/*
+ * getTraceLogFilename: build trace log file name
+ * The name is libpq-%ProcessID-%Y-%m-%d_%H%M%S.log.
+ */
+static void
+getTraceLogFilename(PGconn *conn,char* filename)
+{
+ char currenttime[TRACELOG_TIME_SIZE]; /* %Y-%m-%d_%H%M%S */
+ getCurrentTime(currenttime,0);
+
+#ifdef WIN32
+ snprintf(filename, MAXPGPATH, "%s\\libpq-%d-%s.log", conn->logdir,getpid(),currenttime);
+#else
+ snprintf(filename, MAXPGPATH, "%s/libpq-%d-%s.log", conn->logdir,getpid(),currenttime);
+#endif
+}
+
+/*
+ * initTraceLog: initialize a trace log file
+ */
+void
+initTraceLog(PGconn *conn)
+{
+ char logfilename[MAXPGPATH];
+ getTraceLogFilename(conn,logfilename);
+ conn->traceDebug=fopen(logfilename,"w");
+ fprintf(conn->traceDebug, "Maximum log size is %d B.\n", conn->logsize);
+}
+
+/*
+ * traceLog_fprintf: output trace log to file
+ * If PQtrace() is called, PQtrace() is output followed by libpq trace log.
+ */
+void
+traceLog_fprintf(PGconn *conn, bool addTime, const char *fmt,...)
+{
+ char logfilename[MAXPGPATH];
+ char msgBuf[MAXPGPATH];
+ va_list args;
+ int ret;
+ char currenttime[TRACELOG_TIME_SIZE];
+
+ va_start(args, fmt);
+ vsnprintf(msgBuf, sizeof(msgBuf), fmt, args);
+ msgBuf[sizeof(msgBuf) - 1] = '\0';
+ va_end(args);
+
+ if(conn->Pfdebug)
+ {
+ fprintf(conn->Pfdebug, "%s", msgBuf);
+ }
+ else if(conn->traceDebug)
+ {
+ if((int)ftell(conn->traceDebug) >= conn->logsize)
+ {
+ fclose(conn->traceDebug);
+ getTraceLogFilename(conn,logfilename);
+ conn->traceDebug = fopen(logfilename,"w");
+ if(conn->traceDebug == NULL)
+ return;
+ }
+
+ /* Select trace log message style */
+ if(addTime)
+ {
+ getCurrentTime(currenttime,1);
+ ret = fprintf(conn->traceDebug, "%s %s\n", msgBuf, currenttime);
+ }
+ else
+ {
+ ret = fprintf(conn->traceDebug, "%s",msgBuf);
+ }
+
+ if(ret < 0)
+ {
+ fclose(conn->traceDebug);
+ conn->traceDebug = NULL;
+ return;
+ }
+ fflush(conn->traceDebug);
+ }
+}
+/*
+ * traceLog_fputnbytes: output trace log to file using fputnbytes()
+ */
+static void
+traceLog_fputnbytes(PGconn *conn,const char *head, const char *str, size_t n)
+{
+ char logfilename[MAXPGPATH];
+ int ret;
+
+ if (conn->Pfdebug)
+ {
+ fprintf(conn->Pfdebug, "%s", head);
+ fputnbytes(conn->Pfdebug,str, n);
+ fprintf(conn->Pfdebug, "\n");
+ }
+ else if(conn->traceDebug)
+ {
+ if((int)ftell(conn->traceDebug) >= conn->logsize)
+ {
+ fclose(conn->traceDebug);
+ getTraceLogFilename(conn,logfilename);
+ conn->traceDebug = fopen(logfilename,"w");
+ if(conn->traceDebug == NULL)
+ return;
+ }
+ ret = fprintf(conn->traceDebug, "%s", head);
+ if(ret < 0)
+ {
+ fclose(conn->traceDebug);
+ conn->traceDebug = NULL;
+ return;
+ }
+ fputnbytes(conn->traceDebug,str,n);
+ fprintf(conn->traceDebug,"\n");
+ fflush(conn->traceDebug);
+ }
+}
+
/*
* PQlibVersion: return the libpq version number
*/
@@ -98,8 +263,8 @@ pqGetc(char *result, PGconn *conn)
*result = conn->inBuffer[conn->inCursor++];
- if (conn->Pfdebug)
- fprintf(conn->Pfdebug, "From backend> %c\n", *result);
+ if(conn->Pfdebug||conn->traceDebug)
+ traceLog_fprintf(conn, false, "From backend> %c\n", *result);
return 0;
}
@@ -114,8 +279,8 @@ pqPutc(char c, PGconn *conn)
if (pqPutMsgBytes(&c, 1, conn))
return EOF;
- if (conn->Pfdebug)
- fprintf(conn->Pfdebug, "To backend> %c\n", c);
+ if(conn->Pfdebug||conn->traceDebug)
+ traceLog_fprintf(conn, false, "To backend> %c\n", c);
return 0;
}
@@ -152,9 +317,9 @@ pqGets_internal(PQExpBuffer buf, PGconn *conn, bool resetbuffer)
conn->inCursor = ++inCursor;
- if (conn->Pfdebug)
- fprintf(conn->Pfdebug, "From backend> \"%s\"\n",
- buf->data);
+ if(conn->Pfdebug||conn->traceDebug)
+ traceLog_fprintf(conn, false, "From backend> \"%s\"\n",
+ buf->data);
return 0;
}
@@ -181,8 +346,8 @@ pqPuts(const char *s, PGconn *conn)
if (pqPutMsgBytes(s, strlen(s) + 1, conn))
return EOF;
- if (conn->Pfdebug)
- fprintf(conn->Pfdebug, "To backend> \"%s\"\n", s);
+ if(conn->Pfdebug||conn->traceDebug)
+ traceLog_fprintf(conn, false, "To backend> \"%s\"\n", s);
return 0;
}
@@ -194,6 +359,7 @@ pqPuts(const char *s, PGconn *conn)
int
pqGetnchar(char *s, size_t len, PGconn *conn)
{
+ char buf[100];
if (len > (size_t) (conn->inEnd - conn->inCursor))
return EOF;
@@ -202,11 +368,10 @@ pqGetnchar(char *s, size_t len, PGconn *conn)
conn->inCursor += len;
- if (conn->Pfdebug)
+ if(conn->Pfdebug||conn->traceDebug)
{
- fprintf(conn->Pfdebug, "From backend (%lu)> ", (unsigned long) len);
- fputnbytes(conn->Pfdebug, s, len);
- fprintf(conn->Pfdebug, "\n");
+ sprintf(buf, "From backend (%lu)> ", (unsigned long) len);
+ traceLog_fputnbytes(conn,buf,s, len);
}
return 0;
@@ -228,7 +393,7 @@ pqSkipnchar(size_t len, PGconn *conn)
if (conn->Pfdebug)
{
- fprintf(conn->Pfdebug, "From backend (%lu)> ", (unsigned long) len);
+ fprintf(conn->Pfdebug, "(pqSkipnchar)From backend (%lu)> ", (unsigned long) len);
fputnbytes(conn->Pfdebug, conn->inBuffer + conn->inCursor, len);
fprintf(conn->Pfdebug, "\n");
}
@@ -245,14 +410,14 @@ pqSkipnchar(size_t len, PGconn *conn)
int
pqPutnchar(const char *s, size_t len, PGconn *conn)
{
+ char buf[100];
if (pqPutMsgBytes(s, len, conn))
return EOF;
- if (conn->Pfdebug)
+ if(conn->Pfdebug||conn->traceDebug)
{
- fprintf(conn->Pfdebug, "To backend> ");
- fputnbytes(conn->Pfdebug, s, len);
- fprintf(conn->Pfdebug, "\n");
+ sprintf(buf,"To backend (%lu)> ", (unsigned long) len);
+ traceLog_fputnbytes(conn,buf,s,len);
}
return 0;
@@ -292,8 +457,8 @@ pqGetInt(int *result, size_t bytes, PGconn *conn)
return EOF;
}
- if (conn->Pfdebug)
- fprintf(conn->Pfdebug, "From backend (#%lu)> %d\n", (unsigned long) bytes, *result);
+ if(conn->Pfdebug||conn->traceDebug)
+ traceLog_fprintf(conn, false, "From backend (#%lu)> %d\n", (unsigned long) bytes, *result);
return 0;
}
@@ -328,8 +493,8 @@ pqPutInt(int value, size_t bytes, PGconn *conn)
return EOF;
}
- if (conn->Pfdebug)
- fprintf(conn->Pfdebug, "To backend (%lu#)> %d\n", (unsigned long) bytes, value);
+ if(conn->Pfdebug||conn->traceDebug)
+ traceLog_fprintf(conn, false, "To backend (%lu#)> %d\n", (unsigned long) bytes, value);
return 0;
}
@@ -548,9 +713,9 @@ pqPutMsgStart(char msg_type, bool force_len, PGconn *conn)
conn->outMsgEnd = endPos;
/* length word, if needed, will be filled in by pqPutMsgEnd */
- if (conn->Pfdebug)
- fprintf(conn->Pfdebug, "To backend> Msg %c\n",
- msg_type ? msg_type : ' ');
+ if(conn->Pfdebug||conn->traceDebug)
+ traceLog_fprintf(conn, false, "To backend> Msg %c\n",
+ msg_type ? msg_type : ' ');
return 0;
}
@@ -586,9 +751,9 @@ pqPutMsgBytes(const void *buf, size_t len, PGconn *conn)
int
pqPutMsgEnd(PGconn *conn)
{
- if (conn->Pfdebug)
- fprintf(conn->Pfdebug, "To backend> Msg complete, length %u\n",
- conn->outMsgEnd - conn->outCount);
+ if(conn->Pfdebug||conn->traceDebug)
+ traceLog_fprintf(conn, false, "To backend> Msg complete, length %u\n",
+ conn->outMsgEnd - conn->outCount);
/* Fill in length word if needed */
if (conn->outMsgStart >= 0)
@@ -677,9 +842,17 @@ pqReadData(PGconn *conn)
}
/* OK, try to read some data */
+
retry3:
+ if (conn->traceDebug)
+ traceLog_fprintf(conn, true, "Start receiving message from backend:");
+
nread = pqsecure_read(conn, conn->inBuffer + conn->inEnd,
conn->inBufSize - conn->inEnd);
+
+ if (conn->traceDebug)
+ traceLog_fprintf(conn, true, "End receiving message from backend:");
+
if (nread < 0)
{
if (SOCK_ERRNO == EINTR)
@@ -767,9 +940,16 @@ retry3:
* Still not sure that it's EOF, because some data could have just
* arrived.
*/
+
+ if (conn->traceDebug)
+ traceLog_fprintf(conn, true, "Start receiving message from backend:");
retry4:
nread = pqsecure_read(conn, conn->inBuffer + conn->inEnd,
conn->inBufSize - conn->inEnd);
+
+ if (conn->traceDebug)
+ traceLog_fprintf(conn, true, "End receiving message from backend:");
+
if (nread < 0)
{
if (SOCK_ERRNO == EINTR)
@@ -846,6 +1026,9 @@ pqSendSome(PGconn *conn, int len)
{
int sent;
+ if (conn->traceDebug)
+ traceLog_fprintf(conn, true, "Start sending message to backend:");
+
#ifndef WIN32
sent = pqsecure_write(conn, ptr, len);
#else
@@ -858,6 +1041,9 @@ pqSendSome(PGconn *conn, int len)
sent = pqsecure_write(conn, ptr, Min(len, 65536));
#endif
+ if (conn->traceDebug)
+ traceLog_fprintf(conn, true, "End sending message to backend:");
+
if (sent < 0)
{
/* Anything except EAGAIN/EWOULDBLOCK/EINTR is trouble */
diff --git a/src/interfaces/libpq/libpq-int.h b/src/interfaces/libpq/libpq-int.h
index 66fd317..71d4329 100644
--- a/src/interfaces/libpq/libpq-int.h
+++ b/src/interfaces/libpq/libpq-int.h
@@ -500,6 +500,11 @@ struct pg_conn
/* Buffer for receiving various parts of messages */
PQExpBufferData workBuffer; /* expansible string */
+
+ char *logsize_str; /* Trace log maximum size (string) */
+ int logsize; /* Trace log maximum size */
+ char *logdir; /* Trace log directory to save log */
+ FILE *traceDebug; /* Trace log file to write trace info */
};
/* PGcancel stores all data necessary to cancel a connection. A copy of this
@@ -666,6 +671,10 @@ extern void pq_reset_sigpipe(sigset_t *osigset, bool sigpipe_pending,
bool got_epipe);
#endif
+/* libpq trace log */
+extern void initTraceLog(PGconn *conn);
+extern void traceLog_fprintf(PGconn *conn, bool addTime, const char *fmt,...) pg_attribute_printf(3, 4);
+
/* === SSL === */
/*
Hi Hari san,
Thank you for your comment! And sorry my late reply…
I have some comments related to the trace output that is getting
printed. The amount of log it is generating may not be understood
to many of the application developers. IMO, this should print
only the necessary information that can understood by any one
by default and full log with more configuration?
I understand. And I agree your opinion.
I will add feature called “log level” that changes the amount of log output information with my future version patch.
Regards,
Aya Iwata
Hi Jacob san,
Thank you for your comment! And sorry for late reply...
Couple additional thoughts from a read-through of the patch:
- PQtrace() and the new trace-logging machinery overlap in some places but
not others -- and if both are set, PQtrace() will take precedence.
It seems like the two should not be separate.
I understand. This log is acquired for the purpose of investigating the cause part (server side or application side) when performance is bad.
So I will search whether getting other place of PQtrace() is necessary or not.
And I will reply after the research, please wait for a while a little.
- It isn't immediately clear to me how the new information in the logs is
intended to be used in concert with the old information. Maybe this goes back
to the comments by Tom and Robert higher in the thread -- that an overhaul
of the PQtrace system is due. This patch as presented would make things a
little worse before they got better, I think.That said, I think the overall idea -- application performance information
that can be enabled via the environment, without requiring debugging
privileges on a machine or the need to manually correlate traces made by other
applications -- is a good one, and something I would use.
Thank you. I think so, too. Some applications cannot be stopped to add the PQtrace() code.
Regards,
Aya Iwata
Hi,
I created a new version patch. Please find attached my patch.
Changes:
Since v2 patch
I forgot to write the detail of v2 patch changes. So I write these.
- Fixed the " Start receiving message from backend:" message location. Because I found that message located at outside of "retry4".
- Changed location where output "start :" / "end :" messages and timestamp. The reason of the change is that v1 patch did not correspond to Asynchronous Command Processing.
- Added documentation
- Added documentation how to check mistake of logdir and/or logsize. (Based on review comment of Jim san's)
Since v3 patch
- Fixed my mistake on fe-connect.c. Time and message were output at the place where does not output in originally PQtrace(). These messages are needed only new trace log. So I fixed it.
- Fixed two points so that new trace log overlaps all places in PQtrace(). (Based on review comment of Jacob san's)
TODO:
I will add the feature called "logging level" on next version patch. I will attach it as soon as possible.
I'm marking it as "Needs review".
Regards,
Aya Iwata
Attachments:
v3-0001-libpq-trace-log.patchapplication/octet-stream; name=v3-0001-libpq-trace-log.patchDownload
diff --git a/doc/src/sgml/libpq.sgml b/doc/src/sgml/libpq.sgml
index d2e5b08..0d46d38 100644
--- a/doc/src/sgml/libpq.sgml
+++ b/doc/src/sgml/libpq.sgml
@@ -1589,6 +1589,28 @@ postgresql://%2Fvar%2Flib%2Fpostgresql/dbname
</para>
</listitem>
</varlistentry>
+
+ <varlistentry id="libpq-connect-log-dir" xreflabel="logdir">
+ <term><literal>logdir</literal></term>
+ <listitem>
+ <para>
+ Path of directory where log file written. When both <literal>logdir</literal>
+ and <literal>logsize</literal> is set, logging is enabled.
+ </para>
+ </listitem>
+ </varlistentry>
+
+ <varlistentry id="libpq-connect-log-size" xreflabel="logsize">
+ <term><literal>logsize</literal></term>
+ <listitem>
+ <para>
+ Maximum log size. The unit is megabyte. When the log file size exceeds
+ to <literal>logsize</literal>, the log is output to another file.
+ When both <literal>logdir</literal> and <literal>logsize</literal> is set,
+ logging is enabled.
+ </para>
+ </listitem>
+ </varlistentry>
</variablelist>
</para>
</sect2>
@@ -7472,6 +7494,26 @@ myEventProc(PGEventId evtId, void *evtInfo, void *passThrough)
linkend="libpq-connect-target-session-attrs"/> connection parameter.
</para>
</listitem>
+
+ <listitem>
+ <para>
+ <indexterm>
+ <primary><envar>PGLOGDIR</envar></primary>
+ </indexterm>
+ <envar>PGLOGDIR</envar> behaves the same as the <xref
+ linkend="libpq-connect-log-dir"/> connection parameter.
+ </para>
+ </listitem>
+
+ <listitem>
+ <para>
+ <indexterm>
+ <primary><envar>PGLOGSIZE</envar></primary>
+ </indexterm>
+ <envar>PGLOGSIZE</envar> behaves the same as the <xref
+ linkend="libpq-connect-log-size"/> connection parameter.
+ </para>
+ </listitem>
</itemizedlist>
</para>
@@ -8300,6 +8342,35 @@ int PQisthreadsafe();
</para>
</sect1>
+ <sect1 id="libpq-logging">
+ <title>Logging</title>
+
+ <indexterm zone="libpq-logging">
+ <primary>trace log</primary>
+ </indexterm>
+ <indexterm zone="libpq-logging">
+ <primary>logging</primary>
+ </indexterm>
+
+ <para>
+ Libpq trace log can trace information about SQL queries which issued by
+ the libpq application. This output help determine whether the couse is
+ on backend side or application side and solve issues with the libpq Driver
+ when it use. The log without requiring recompile of the libpq application.
+ </para>
+
+ <para>
+ You can activate this log by setting both <parameter>logdir</parameter> and
+ <parameter>logsize</parameter> of the connection string, or by setting both
+ the environment variables <envar>PGLOGDIR</envar> and <envar>PGLOGSIZE</envar>.
+ The log trace file is written in a directory setting by <envar>PGLOGDIR</envar>
+ or <parameter>logdir</parameter>.
+ The file name is determined as <filename>libpq-%ProcessID-%Y-%m-%d_%H%M%S.log</filename>.
+ If the setting of the file path by the connection string or the environment variable is
+ incorrect, the log file is not created in the intended location.
+ The maximum log file size you set is output to the beginning of the file, so you can check it.
+ </para>
+ </sect1>
<sect1 id="libpq-build">
<title>Building <application>libpq</application> Programs</title>
diff --git a/src/interfaces/libpq/fe-connect.c b/src/interfaces/libpq/fe-connect.c
index bc456fe..d6d16a0 100644
--- a/src/interfaces/libpq/fe-connect.c
+++ b/src/interfaces/libpq/fe-connect.c
@@ -325,6 +325,15 @@ static const internalPQconninfoOption PQconninfoOptions[] = {
"Target-Session-Attrs", "", 11, /* sizeof("read-write") = 11 */
offsetof(struct pg_conn, target_session_attrs)},
+ /* libpq trace log options */
+ {"logdir", "PGLOGDIR", NULL, NULL,
+ "Logdir", "", MAXPGPATH - 4,
+ offsetof(struct pg_conn, logdir)},
+
+ {"logsize", "PGLOGSIZE", NULL, NULL,
+ "Logsize", "", 5,
+ offsetof(struct pg_conn, logsize_str)},
+
/* Terminating entry --- MUST BE LAST */
{NULL, NULL, NULL, NULL,
NULL, NULL, 0}
@@ -1128,6 +1137,19 @@ connectOptions2(PGconn *conn)
}
/*
+ * If both size and directory of trace log was given,
+ * initialize a trace log.
+ */
+ if (conn->logsize_str && conn->logsize_str[0] != '\0')
+ conn->logsize = atoi(conn->logsize_str);
+
+ if (conn->logdir != NULL && conn->logsize > 0 && conn->logsize < 2048)
+ {
+ conn->logsize = conn->logsize * 1024 * 1024;
+ initTraceLog(conn);
+ }
+
+ /*
* If password was not given, try to look it up in password file. Note
* that the result might be different for each host/port pair.
*/
@@ -3716,6 +3738,14 @@ freePGconn(PGconn *conn)
termPQExpBuffer(&conn->errorMessage);
termPQExpBuffer(&conn->workBuffer);
+ /* clean up libpq trace log structures */
+ if (conn->logsize_str)
+ free(conn->logsize_str);
+ if (conn->logdir)
+ free(conn->logdir);
+ if (conn->traceDebug)
+ fclose(conn->traceDebug);
+
free(conn);
#ifdef WIN32
@@ -3751,6 +3781,8 @@ sendTerminateConn(PGconn *conn)
*/
if (conn->sock != PGINVALID_SOCKET && conn->status == CONNECTION_OK)
{
+ if (conn->traceDebug)
+ traceLog_fprintf(conn, true, "Send connection terminate message to backend: ");
/*
* Try to send "close connection" message to backend. Ignore any
* error.
@@ -4153,6 +4185,9 @@ int
pqPacketSend(PGconn *conn, char pack_type,
const void *buf, size_t buf_len)
{
+ if (conn->traceDebug)
+ traceLog_fprintf(conn, true, "Send connection start message to backend: ");
+
/* Start the message. */
if (pqPutMsgStart(pack_type, true, conn))
return STATUS_ERROR;
diff --git a/src/interfaces/libpq/fe-exec.c b/src/interfaces/libpq/fe-exec.c
index 6aed8c8..d45e795 100644
--- a/src/interfaces/libpq/fe-exec.c
+++ b/src/interfaces/libpq/fe-exec.c
@@ -879,7 +879,7 @@ pqInternalNotice(const PGNoticeHooks *hooks, const char *fmt,...)
res->errMsg = (char *) pqResultAlloc(res, strlen(msgBuf) + 2, false);
if (res->errMsg)
{
- sprintf(res->errMsg, "%s\n", msgBuf);
+ sprintf(res->errMsg, "NOTICE: %s\n", msgBuf);
/*
* Pass to receiver, then free it.
@@ -991,9 +991,9 @@ pqSaveParameterStatus(PGconn *conn, const char *name, const char *value)
pgParameterStatus *pstatus;
pgParameterStatus *prev;
- if (conn->Pfdebug)
- fprintf(conn->Pfdebug, "pqSaveParameterStatus: '%s' = '%s'\n",
- name, value);
+ if (conn->Pfdebug || conn->traceDebug)
+ traceLog_fprintf(conn, false, "pqSaveParameterStatus: '%s' = '%s'\n",
+ name, value);
/*
* Forget any old information about the parameter
@@ -1208,6 +1208,9 @@ fail:
int
PQsendQuery(PGconn *conn, const char *query)
{
+ if (conn->traceDebug)
+ traceLog_fprintf(conn, true, "PQsendQuery start :");
+
if (!PQsendQueryStart(conn))
return 0;
@@ -1219,6 +1222,9 @@ PQsendQuery(PGconn *conn, const char *query)
return 0;
}
+ if (conn->traceDebug)
+ traceLog_fprintf(conn, false, "Query: %s \n",query);
+
/* construct the outgoing Query message */
if (pqPutMsgStart('Q', false, conn) < 0 ||
pqPuts(query, conn) < 0 ||
@@ -1249,6 +1255,10 @@ PQsendQuery(PGconn *conn, const char *query)
/* OK, it's launched! */
conn->asyncStatus = PGASYNC_BUSY;
+
+ if (conn->traceDebug)
+ traceLog_fprintf(conn, true, "PQsendQuery end :");
+
return 1;
}
@@ -1266,6 +1276,9 @@ PQsendQueryParams(PGconn *conn,
const int *paramFormats,
int resultFormat)
{
+ if (conn->traceDebug)
+ traceLog_fprintf(conn, true, "PQsendQueryParams start :");
+
if (!PQsendQueryStart(conn))
return 0;
@@ -1283,6 +1296,9 @@ PQsendQueryParams(PGconn *conn,
return 0;
}
+ if (conn->traceDebug)
+ traceLog_fprintf(conn, true, "PQsendQueryParams end :");
+
return PQsendQueryGuts(conn,
command,
"", /* use unnamed statement */
@@ -1306,6 +1322,9 @@ PQsendPrepare(PGconn *conn,
const char *stmtName, const char *query,
int nParams, const Oid *paramTypes)
{
+ if (conn->traceDebug)
+ traceLog_fprintf(conn, true, "PQsendPrepare start :");
+
if (!PQsendQueryStart(conn))
return 0;
@@ -1337,6 +1356,9 @@ PQsendPrepare(PGconn *conn,
return 0;
}
+ if (conn->traceDebug)
+ traceLog_fprintf(conn, false, "Statement name: %s, Query: %s \n",stmtName, query);
+
/* construct the Parse message */
if (pqPutMsgStart('P', false, conn) < 0 ||
pqPuts(stmtName, conn) < 0 ||
@@ -1386,6 +1408,10 @@ PQsendPrepare(PGconn *conn,
/* OK, it's launched! */
conn->asyncStatus = PGASYNC_BUSY;
+
+ if (conn->traceDebug)
+ traceLog_fprintf(conn, true, "PQsendPrepare end :");
+
return 1;
sendFailed:
@@ -1492,6 +1518,9 @@ PQsendQueryGuts(PGconn *conn,
{
int i;
+ if (conn->traceDebug)
+ traceLog_fprintf(conn, true, "PQsendQueryGuts start :");
+
/* This isn't gonna work on a 2.0 server */
if (PG_PROTOCOL_MAJOR(conn->pversion) < 3)
{
@@ -1507,6 +1536,9 @@ PQsendQueryGuts(PGconn *conn,
if (command)
{
+ if (conn->traceDebug)
+ traceLog_fprintf(conn, false, "Statement name: %s, Command: %s \n",stmtName, command);
+
/* construct the Parse message */
if (pqPutMsgStart('P', false, conn) < 0 ||
pqPuts(stmtName, conn) < 0 ||
@@ -1638,6 +1670,10 @@ PQsendQueryGuts(PGconn *conn,
/* OK, it's launched! */
conn->asyncStatus = PGASYNC_BUSY;
+
+ if (conn->traceDebug)
+ traceLog_fprintf(conn, true, "PQsendQueryGuts end :");
+
return 1;
sendFailed:
@@ -1780,6 +1816,9 @@ PQgetResult(PGconn *conn)
{
PGresult *res;
+ if (conn->traceDebug)
+ traceLog_fprintf(conn, true, "PQgetResult start :");
+
if (!conn)
return NULL;
@@ -1820,6 +1859,7 @@ PQgetResult(PGconn *conn)
/* Parse it. */
parseInput(conn);
+
}
/* Return the appropriate thing. */
@@ -1874,6 +1914,9 @@ PQgetResult(PGconn *conn)
}
}
+ if (conn->traceDebug)
+ traceLog_fprintf(conn, true, "PQgetResult end :");
+
return res;
}
@@ -2203,6 +2246,9 @@ PQsendDescribePortal(PGconn *conn, const char *portal)
static int
PQsendDescribe(PGconn *conn, char desc_type, const char *desc_target)
{
+ if (conn->traceDebug)
+ traceLog_fprintf(conn, true, "PQsendDescribe start :");
+
/* Treat null desc_target as empty string */
if (!desc_target)
desc_target = "";
@@ -2218,6 +2264,9 @@ PQsendDescribe(PGconn *conn, char desc_type, const char *desc_target)
return 0;
}
+ if (conn->traceDebug)
+ traceLog_fprintf(conn, false, "Describe type: %c, target: %s \n",desc_type, desc_target);
+
/* construct the Describe message */
if (pqPutMsgStart('D', false, conn) < 0 ||
pqPutc(desc_type, conn) < 0 ||
@@ -2249,6 +2298,10 @@ PQsendDescribe(PGconn *conn, char desc_type, const char *desc_target)
/* OK, it's launched! */
conn->asyncStatus = PGASYNC_BUSY;
+
+ if (conn->traceDebug)
+ traceLog_fprintf(conn, true, "PQsendDescribe end :");
+
return 1;
sendFailed:
diff --git a/src/interfaces/libpq/fe-misc.c b/src/interfaces/libpq/fe-misc.c
index 46ece1a..75c5040 100644
--- a/src/interfaces/libpq/fe-misc.c
+++ b/src/interfaces/libpq/fe-misc.c
@@ -35,6 +35,7 @@
#ifdef WIN32
#include "win32.h"
+#include <windows.h>
#else
#include <unistd.h>
#include <sys/time.h>
@@ -45,6 +46,7 @@
#endif
#ifdef HAVE_SYS_SELECT_H
#include <sys/select.h>
+#include <sys/timeb.h>
#endif
#include "libpq-fe.h"
@@ -60,6 +62,169 @@ static int pqSocketCheck(PGconn *conn, int forRead, int forWrite,
time_t end_time);
static int pqSocketPoll(int sock, int forRead, int forWrite, time_t end_time);
+static void getTraceLogFilename(PGconn *conn,char* filename);
+static void traceLog_fputnbytes(PGconn *conn, const char *head, const char *str, size_t n);
+static void fputnbytes(FILE *f, const char *str, size_t n);
+static void getCurrentTime(char* currenttime,int type);
+#define TRACELOG_TIME_SIZE 28
+
+/*
+ * getCurrentTime: get current time for trace log output
+ *
+ * type=0 currenttime formate %Y-%m-%d_%H%M%S
+ * type=1 currenttime formate %Y/%m/%d %H:%M:%S.%Milliseconds
+ */
+static void
+getCurrentTime(char* currenttime,int type)
+{
+#ifdef WIN32
+ SYSTEMTIME localTime;
+ GetLocalTime(&localTime);
+ if(type==0)
+ snprintf(currenttime,TRACELOG_TIME_SIZE,"%4d-%02d-%02d_%02d%02d%02d",
+ localTime.wYear,localTime.wMonth,localTime.wDay,
+ localTime.wHour,localTime.wMinute,localTime.wSecond);
+ else if(type==1)
+ snprintf(currenttime,TRACELOG_TIME_SIZE,"%4d/%02d/%02d %02d:%02d:%02d.%03d",
+ localTime.wYear,localTime.wMonth,localTime.wDay,
+ localTime.wHour,localTime.wMinute,localTime.wSecond,
+ localTime.wMilliseconds);
+#else
+ struct timeb localTime;
+ struct tm *tm;
+ ftime(&localTime);
+ tm = localtime(&localTime.time);
+ if(type == 0)
+ snprintf(currenttime, TRACELOG_TIME_SIZE,"%4d-%02d-%02d_%02d%02d%02d",
+ 1900+ tm->tm_year,1 + tm->tm_mon, tm->tm_mday,
+ tm->tm_hour, tm->tm_min, tm->tm_sec);
+ else if(type==1)
+ snprintf(currenttime, TRACELOG_TIME_SIZE,"%4d/%02d/%02d %02d:%02d:%02d.%03d",
+ 1900+ tm->tm_year,1 + tm->tm_mon, tm->tm_mday,
+ tm->tm_hour, tm->tm_min, tm->tm_sec, localTime.millitm);
+#endif
+}
+
+/*
+ * getTraceLogFilename: build trace log file name
+ * The name is libpq-%ProcessID-%Y-%m-%d_%H%M%S.log.
+ */
+static void
+getTraceLogFilename(PGconn *conn,char* filename)
+{
+ char currenttime[TRACELOG_TIME_SIZE]; /* %Y-%m-%d_%H%M%S */
+ getCurrentTime(currenttime,0);
+
+#ifdef WIN32
+ snprintf(filename, MAXPGPATH, "%s\\libpq-%d-%s.log", conn->logdir,getpid(),currenttime);
+#else
+ snprintf(filename, MAXPGPATH, "%s/libpq-%d-%s.log", conn->logdir,getpid(),currenttime);
+#endif
+}
+
+/*
+ * initTraceLog: initialize a trace log file
+ */
+void
+initTraceLog(PGconn *conn)
+{
+ char logfilename[MAXPGPATH];
+ getTraceLogFilename(conn,logfilename);
+ conn->traceDebug=fopen(logfilename,"w");
+ fprintf(conn->traceDebug, "Maximum log size is %d B.\n", conn->logsize);
+}
+
+/*
+ * traceLog_fprintf: output trace log to file
+ * If PQtrace() is called, PQtrace() is output followed by libpq trace log.
+ */
+void
+traceLog_fprintf(PGconn *conn, bool addTime, const char *fmt,...)
+{
+ char logfilename[MAXPGPATH];
+ char msgBuf[MAXPGPATH];
+ va_list args;
+ int ret;
+ char currenttime[TRACELOG_TIME_SIZE];
+
+ va_start(args, fmt);
+ vsnprintf(msgBuf, sizeof(msgBuf), fmt, args);
+ msgBuf[sizeof(msgBuf) - 1] = '\0';
+ va_end(args);
+
+ if(conn->Pfdebug)
+ {
+ fprintf(conn->Pfdebug, "%s", msgBuf);
+ }
+ else if(conn->traceDebug)
+ {
+ if((int)ftell(conn->traceDebug) >= conn->logsize)
+ {
+ fclose(conn->traceDebug);
+ getTraceLogFilename(conn,logfilename);
+ conn->traceDebug = fopen(logfilename,"w");
+ if(conn->traceDebug == NULL)
+ return;
+ }
+
+ /* Select trace log message style */
+ if(addTime)
+ {
+ getCurrentTime(currenttime,1);
+ ret = fprintf(conn->traceDebug, "%s %s\n", msgBuf, currenttime);
+ }
+ else
+ {
+ ret = fprintf(conn->traceDebug, "%s",msgBuf);
+ }
+
+ if(ret < 0)
+ {
+ fclose(conn->traceDebug);
+ conn->traceDebug = NULL;
+ return;
+ }
+ fflush(conn->traceDebug);
+ }
+}
+/*
+ * traceLog_fputnbytes: output trace log to file using fputnbytes()
+ */
+static void
+traceLog_fputnbytes(PGconn *conn,const char *head, const char *str, size_t n)
+{
+ char logfilename[MAXPGPATH];
+ int ret;
+
+ if (conn->Pfdebug)
+ {
+ fprintf(conn->Pfdebug, "%s", head);
+ fputnbytes(conn->Pfdebug,str, n);
+ fprintf(conn->Pfdebug, "\n");
+ }
+ else if(conn->traceDebug)
+ {
+ if((int)ftell(conn->traceDebug) >= conn->logsize)
+ {
+ fclose(conn->traceDebug);
+ getTraceLogFilename(conn,logfilename);
+ conn->traceDebug = fopen(logfilename,"w");
+ if(conn->traceDebug == NULL)
+ return;
+ }
+ ret = fprintf(conn->traceDebug, "%s", head);
+ if(ret < 0)
+ {
+ fclose(conn->traceDebug);
+ conn->traceDebug = NULL;
+ return;
+ }
+ fputnbytes(conn->traceDebug,str,n);
+ fprintf(conn->traceDebug,"\n");
+ fflush(conn->traceDebug);
+ }
+}
+
/*
* PQlibVersion: return the libpq version number
*/
@@ -98,8 +263,8 @@ pqGetc(char *result, PGconn *conn)
*result = conn->inBuffer[conn->inCursor++];
- if (conn->Pfdebug)
- fprintf(conn->Pfdebug, "From backend> %c\n", *result);
+ if(conn->Pfdebug||conn->traceDebug)
+ traceLog_fprintf(conn, false, "From backend> %c\n", *result);
return 0;
}
@@ -114,8 +279,8 @@ pqPutc(char c, PGconn *conn)
if (pqPutMsgBytes(&c, 1, conn))
return EOF;
- if (conn->Pfdebug)
- fprintf(conn->Pfdebug, "To backend> %c\n", c);
+ if(conn->Pfdebug||conn->traceDebug)
+ traceLog_fprintf(conn, false, "To backend> %c\n", c);
return 0;
}
@@ -152,9 +317,9 @@ pqGets_internal(PQExpBuffer buf, PGconn *conn, bool resetbuffer)
conn->inCursor = ++inCursor;
- if (conn->Pfdebug)
- fprintf(conn->Pfdebug, "From backend> \"%s\"\n",
- buf->data);
+ if(conn->Pfdebug||conn->traceDebug)
+ traceLog_fprintf(conn, false, "From backend> \"%s\"\n",
+ buf->data);
return 0;
}
@@ -181,8 +346,8 @@ pqPuts(const char *s, PGconn *conn)
if (pqPutMsgBytes(s, strlen(s) + 1, conn))
return EOF;
- if (conn->Pfdebug)
- fprintf(conn->Pfdebug, "To backend> \"%s\"\n", s);
+ if(conn->Pfdebug||conn->traceDebug)
+ traceLog_fprintf(conn, false, "To backend> \"%s\"\n", s);
return 0;
}
@@ -194,6 +359,7 @@ pqPuts(const char *s, PGconn *conn)
int
pqGetnchar(char *s, size_t len, PGconn *conn)
{
+ char buf[100];
if (len > (size_t) (conn->inEnd - conn->inCursor))
return EOF;
@@ -202,11 +368,10 @@ pqGetnchar(char *s, size_t len, PGconn *conn)
conn->inCursor += len;
- if (conn->Pfdebug)
+ if(conn->Pfdebug||conn->traceDebug)
{
- fprintf(conn->Pfdebug, "From backend (%lu)> ", (unsigned long) len);
- fputnbytes(conn->Pfdebug, s, len);
- fprintf(conn->Pfdebug, "\n");
+ sprintf(buf, "From backend (%lu)> ", (unsigned long) len);
+ traceLog_fputnbytes(conn,buf,s, len);
}
return 0;
@@ -223,14 +388,14 @@ pqGetnchar(char *s, size_t len, PGconn *conn)
int
pqSkipnchar(size_t len, PGconn *conn)
{
+ char buf[100];
if (len > (size_t) (conn->inEnd - conn->inCursor))
return EOF;
- if (conn->Pfdebug)
+ if (conn->Pfdebug||conn->traceDebug)
{
- fprintf(conn->Pfdebug, "From backend (%lu)> ", (unsigned long) len);
- fputnbytes(conn->Pfdebug, conn->inBuffer + conn->inCursor, len);
- fprintf(conn->Pfdebug, "\n");
+ sprintf(buf, "From backend (%lu)> ", (unsigned long) len);
+ traceLog_fputnbytes(conn,buf,conn->inBuffer + conn->inCursor, len);
}
conn->inCursor += len;
@@ -245,14 +410,14 @@ pqSkipnchar(size_t len, PGconn *conn)
int
pqPutnchar(const char *s, size_t len, PGconn *conn)
{
+ char buf[100];
if (pqPutMsgBytes(s, len, conn))
return EOF;
- if (conn->Pfdebug)
+ if(conn->Pfdebug||conn->traceDebug)
{
- fprintf(conn->Pfdebug, "To backend> ");
- fputnbytes(conn->Pfdebug, s, len);
- fprintf(conn->Pfdebug, "\n");
+ sprintf(buf,"To backend (%lu)> ", (unsigned long) len);
+ traceLog_fputnbytes(conn,buf,s,len);
}
return 0;
@@ -292,8 +457,8 @@ pqGetInt(int *result, size_t bytes, PGconn *conn)
return EOF;
}
- if (conn->Pfdebug)
- fprintf(conn->Pfdebug, "From backend (#%lu)> %d\n", (unsigned long) bytes, *result);
+ if(conn->Pfdebug||conn->traceDebug)
+ traceLog_fprintf(conn, false, "From backend (#%lu)> %d\n", (unsigned long) bytes, *result);
return 0;
}
@@ -328,8 +493,8 @@ pqPutInt(int value, size_t bytes, PGconn *conn)
return EOF;
}
- if (conn->Pfdebug)
- fprintf(conn->Pfdebug, "To backend (%lu#)> %d\n", (unsigned long) bytes, value);
+ if(conn->Pfdebug||conn->traceDebug)
+ traceLog_fprintf(conn, false, "To backend (%lu#)> %d\n", (unsigned long) bytes, value);
return 0;
}
@@ -548,9 +713,9 @@ pqPutMsgStart(char msg_type, bool force_len, PGconn *conn)
conn->outMsgEnd = endPos;
/* length word, if needed, will be filled in by pqPutMsgEnd */
- if (conn->Pfdebug)
- fprintf(conn->Pfdebug, "To backend> Msg %c\n",
- msg_type ? msg_type : ' ');
+ if(conn->Pfdebug||conn->traceDebug)
+ traceLog_fprintf(conn, false, "To backend> Msg %c\n",
+ msg_type ? msg_type : ' ');
return 0;
}
@@ -586,9 +751,9 @@ pqPutMsgBytes(const void *buf, size_t len, PGconn *conn)
int
pqPutMsgEnd(PGconn *conn)
{
- if (conn->Pfdebug)
- fprintf(conn->Pfdebug, "To backend> Msg complete, length %u\n",
- conn->outMsgEnd - conn->outCount);
+ if(conn->Pfdebug||conn->traceDebug)
+ traceLog_fprintf(conn, false, "To backend> Msg complete, length %u\n",
+ conn->outMsgEnd - conn->outCount);
/* Fill in length word if needed */
if (conn->outMsgStart >= 0)
@@ -677,9 +842,17 @@ pqReadData(PGconn *conn)
}
/* OK, try to read some data */
+
retry3:
+ if (conn->traceDebug)
+ traceLog_fprintf(conn, true, "Start receiving message from backend:");
+
nread = pqsecure_read(conn, conn->inBuffer + conn->inEnd,
conn->inBufSize - conn->inEnd);
+
+ if (conn->traceDebug)
+ traceLog_fprintf(conn, true, "End receiving message from backend:");
+
if (nread < 0)
{
if (SOCK_ERRNO == EINTR)
@@ -767,9 +940,16 @@ retry3:
* Still not sure that it's EOF, because some data could have just
* arrived.
*/
+
+ if (conn->traceDebug)
+ traceLog_fprintf(conn, true, "Start receiving message from backend:");
retry4:
nread = pqsecure_read(conn, conn->inBuffer + conn->inEnd,
conn->inBufSize - conn->inEnd);
+
+ if (conn->traceDebug)
+ traceLog_fprintf(conn, true, "End receiving message from backend:");
+
if (nread < 0)
{
if (SOCK_ERRNO == EINTR)
@@ -846,6 +1026,9 @@ pqSendSome(PGconn *conn, int len)
{
int sent;
+ if (conn->traceDebug)
+ traceLog_fprintf(conn, true, "Start sending message to backend:");
+
#ifndef WIN32
sent = pqsecure_write(conn, ptr, len);
#else
@@ -858,6 +1041,9 @@ pqSendSome(PGconn *conn, int len)
sent = pqsecure_write(conn, ptr, Min(len, 65536));
#endif
+ if (conn->traceDebug)
+ traceLog_fprintf(conn, true, "End sending message to backend:");
+
if (sent < 0)
{
/* Anything except EAGAIN/EWOULDBLOCK/EINTR is trouble */
@@ -963,6 +1149,9 @@ pqFlush(PGconn *conn)
if (conn->Pfdebug)
fflush(conn->Pfdebug);
+ if (conn->traceDebug)
+ fflush(conn->traceDebug);
+
if (conn->outCount > 0)
return pqSendSome(conn, conn->outCount);
diff --git a/src/interfaces/libpq/libpq-int.h b/src/interfaces/libpq/libpq-int.h
index 66fd317..71d4329 100644
--- a/src/interfaces/libpq/libpq-int.h
+++ b/src/interfaces/libpq/libpq-int.h
@@ -500,6 +500,11 @@ struct pg_conn
/* Buffer for receiving various parts of messages */
PQExpBufferData workBuffer; /* expansible string */
+
+ char *logsize_str; /* Trace log maximum size (string) */
+ int logsize; /* Trace log maximum size */
+ char *logdir; /* Trace log directory to save log */
+ FILE *traceDebug; /* Trace log file to write trace info */
};
/* PGcancel stores all data necessary to cancel a connection. A copy of this
@@ -666,6 +671,10 @@ extern void pq_reset_sigpipe(sigset_t *osigset, bool sigpipe_pending,
bool got_epipe);
#endif
+/* libpq trace log */
+extern void initTraceLog(PGconn *conn);
+extern void traceLog_fprintf(PGconn *conn, bool addTime, const char *fmt,...) pg_attribute_printf(3, 4);
+
/* === SSL === */
/*
On 27/11/2018 08:42, Iwata, Aya wrote:
I created a new version patch. Please find attached my patch.
This does not excite me. It seems mostly redundant with using tcpdump.
If I were to debug networking problems, I wouldn't even trust this very
much because it relies on the willpower of all future PostgreSQL
developers to keep this accurately up to date, whereas tcpdump gives me
the truth from the kernel.
--
Peter Eisentraut http://www.2ndQuadrant.com/
PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services
Hi Peter,
Thank you for your reply!
On 27/11/2018 08:42, Iwata, Aya wrote:
I created a new version patch. Please find attached my patch.
This does not excite me. It seems mostly redundant with using tcpdump.
I will develop "log level". I'm planning not to output redundant message at the default level.
If I were to debug networking problems, I wouldn't even trust this very much
because it relies on the willpower of all future PostgreSQL developers to
keep this accurately up to date, whereas tcpdump gives me the truth from the
kernel.
I agree your concern about log trusty. It would be a good choice for only
skilled users to use tcpdump. I think libpq trace log will be used many users,
it includes users who not familiar with PostgreSQL protocols. The log would be easier to use
because it shows "start time" and "end time". On tcpdump also shows
the starting time and ending time but people need to know PostgreSQL protocol
to get them.
And this log also is useful for Windows users.
Windows does not have originally networking trace tool.
If you have any ideas about maintain this feature, I would like to know it.
Regards,
Aya Iwata
Hi,
TODO:
I will add the feature called "logging level" on next version patch. I will
attach it as soon as possible.
I created v4 patch. Please find attached the patch.
This patch developed "logminlevel" parameter. level1 and level2 can be set, level1 is the default.
If level1 is set, it outputs the time in the functions. It helps to find out where it takes time.
If level2 is set, it outputs information on the protocol being exchanged in addition to level1 information.
I would appreciate if you could review my latest patch.
Regards,
Aya Iwata
Attachments:
v4-0001-libpq-trace-log.patchapplication/octet-stream; name=v4-0001-libpq-trace-log.patchDownload
diff --git a/doc/src/sgml/libpq.sgml b/doc/src/sgml/libpq.sgml
index d2e5b08..080d24c 100644
--- a/doc/src/sgml/libpq.sgml
+++ b/doc/src/sgml/libpq.sgml
@@ -1589,6 +1589,42 @@ postgresql://%2Fvar%2Flib%2Fpostgresql/dbname
</para>
</listitem>
</varlistentry>
+
+ <varlistentry id="libpq-connect-log-dir" xreflabel="logdir">
+ <term><literal>logdir</literal></term>
+ <listitem>
+ <para>
+ Path of directory where log file written. When both <literal>logdir</literal>
+ and <literal>logsize</literal> is set, logging is enabled.
+ </para>
+ </listitem>
+ </varlistentry>
+
+ <varlistentry id="libpq-connect-log-size" xreflabel="logsize">
+ <term><literal>logsize</literal></term>
+ <listitem>
+ <para>
+ Maximum log size. The unit is megabyte. When the log file size exceeds
+ to <literal>logsize</literal>, the log is output to another file.
+ When both <literal>logdir</literal> and <literal>logsize</literal> is set,
+ logging is enabled.
+ </para>
+ </listitem>
+ </varlistentry>
+
+ <varlistentry id="libpq-connect-log-min-level" xreflabel="logminlevel">
+ <term><literal>logminlevel</literal></term>
+ <listitem>
+ <para>
+ Level of the log. <literal>level1</literal> and <literal>level2</literal>
+ can be set, <literal>level1</literal> is the default.
+ When this parameter is <literal>level1</literal>,it outputs the time
+ in the function and connection time. <literal>level2</literal> outputs
+ information on the protocol being exchanged in addition to
+ <literal>level1</literal> information.
+ </para>
+ </listitem>
+ </varlistentry>
</variablelist>
</para>
</sect2>
@@ -7472,6 +7508,36 @@ myEventProc(PGEventId evtId, void *evtInfo, void *passThrough)
linkend="libpq-connect-target-session-attrs"/> connection parameter.
</para>
</listitem>
+
+ <listitem>
+ <para>
+ <indexterm>
+ <primary><envar>PGLOGDIR</envar></primary>
+ </indexterm>
+ <envar>PGLOGDIR</envar> behaves the same as the <xref
+ linkend="libpq-connect-log-dir"/> connection parameter.
+ </para>
+ </listitem>
+
+ <listitem>
+ <para>
+ <indexterm>
+ <primary><envar>PGLOGSIZE</envar></primary>
+ </indexterm>
+ <envar>PGLOGSIZE</envar> behaves the same as the <xref
+ linkend="libpq-connect-log-size"/> connection parameter.
+ </para>
+ </listitem>
+
+ <listitem>
+ <para>
+ <indexterm>
+ <primary><envar>PGLOGMINLEVEL</envar></primary>
+ </indexterm>
+ <envar>PGLOGMINLEVEL</envar> behaves the same as the <xref
+ linkend="libpq-connect-log-min-level"/> connection parameter.
+ </para>
+ </listitem>
</itemizedlist>
</para>
@@ -8300,6 +8366,38 @@ int PQisthreadsafe();
</para>
</sect1>
+ <sect1 id="libpq-logging">
+ <title>Logging</title>
+
+ <indexterm zone="libpq-logging">
+ <primary>trace log</primary>
+ </indexterm>
+ <indexterm zone="libpq-logging">
+ <primary>logging</primary>
+ </indexterm>
+
+ <para>
+ Libpq trace log can trace information about SQL queries which issued by
+ the libpq application. This output help determine whether the couse is
+ on backend side or application side and solve issues with the libpq Driver
+ when it use. The log without requiring recompile of the libpq application.
+ </para>
+
+ <para>
+ You can activate this log by setting both <parameter>logdir</parameter> and
+ <parameter>logsize</parameter> of the connection string, or by setting both
+ the environment variables <envar>PGLOGDIR</envar> and <envar>PGLOGSIZE</envar>.
+ The log trace file is written in a directory setting by <envar>PGLOGDIR</envar>
+ or <parameter>logdir</parameter>.
+ Information to be output to the log file can be controlled by setting
+ <parameter>logminlevel</parameter> or <envar>PGLOGMINLEVEL</envar>.
+ The file name is determined as <filename>libpq-%ProcessID-%Y-%m-%d_%H%M%S.log</filename>.
+ If the setting of the file path by the connection string or the environment variable is
+ incorrect, the log file is not created in the intended location.
+ The maximum log file size and log level you set is output to the beginning of the file,
+ so you can check it.
+ </para>
+ </sect1>
<sect1 id="libpq-build">
<title>Building <application>libpq</application> Programs</title>
diff --git a/src/interfaces/libpq/fe-connect.c b/src/interfaces/libpq/fe-connect.c
index bc456fe..2b441be 100644
--- a/src/interfaces/libpq/fe-connect.c
+++ b/src/interfaces/libpq/fe-connect.c
@@ -128,6 +128,7 @@ static int ldapServiceLookup(const char *purl, PQconninfoOption *options,
#define DefaultSSLMode "prefer"
#else
#define DefaultSSLMode "disable"
+#define DefaultLogMinLevel "level1"
#endif
/* ----------
@@ -325,6 +326,19 @@ static const internalPQconninfoOption PQconninfoOptions[] = {
"Target-Session-Attrs", "", 11, /* sizeof("read-write") = 11 */
offsetof(struct pg_conn, target_session_attrs)},
+ /* libpq trace log options */
+ {"logdir", "PGLOGDIR", NULL, NULL,
+ "Logdir", "", MAXPGPATH - 4,
+ offsetof(struct pg_conn, logdir)},
+
+ {"logsize", "PGLOGSIZE", NULL, NULL,
+ "Logsize", "", 5,
+ offsetof(struct pg_conn, logsize_str)},
+
+ {"logminlevel", "PGLOGMINLEVEL", DefaultLogMinLevel, NULL,
+ "LogMinlevel", "", 7,
+ offsetof(struct pg_conn, logminlevel_str)},
+
/* Terminating entry --- MUST BE LAST */
{NULL, NULL, NULL, NULL,
NULL, NULL, 0}
@@ -1128,6 +1142,26 @@ connectOptions2(PGconn *conn)
}
/*
+ * If both size and directory of trace log was given,
+ * initialize a trace log.
+ */
+ if (conn->logsize_str && conn->logsize_str[0] != '\0')
+ conn->logsize = atoi(conn->logsize_str);
+
+ if (conn->logdir != NULL && conn->logsize > 0 && conn->logsize < 2048)
+ {
+ conn->logsize = conn->logsize * 1024 * 1024;
+
+ if(strcmp(conn->logminlevel_str, "level1") == 0)
+ conn->logminlevel = LEVEL1;
+
+ if(strcmp(conn->logminlevel_str, "level2") == 0)
+ conn->logminlevel = LEVEL2;
+
+ initTraceLog(conn);
+ }
+
+ /*
* If password was not given, try to look it up in password file. Note
* that the result might be different for each host/port pair.
*/
@@ -3716,6 +3750,16 @@ freePGconn(PGconn *conn)
termPQExpBuffer(&conn->errorMessage);
termPQExpBuffer(&conn->workBuffer);
+ /* clean up libpq trace log structures */
+ if (conn->logsize_str)
+ free(conn->logsize_str);
+ if (conn->logdir)
+ free(conn->logdir);
+ if (conn->logminlevel_str)
+ free(conn->logminlevel_str);
+ if (conn->traceDebug)
+ fclose(conn->traceDebug);
+
free(conn);
#ifdef WIN32
@@ -3751,6 +3795,7 @@ sendTerminateConn(PGconn *conn)
*/
if (conn->sock != PGINVALID_SOCKET && conn->status == CONNECTION_OK)
{
+ traceLog_fprintf(conn, LEVEL1, "Send connection terminate message to backend: ");
/*
* Try to send "close connection" message to backend. Ignore any
* error.
@@ -4153,6 +4198,8 @@ int
pqPacketSend(PGconn *conn, char pack_type,
const void *buf, size_t buf_len)
{
+ traceLog_fprintf(conn, LEVEL1, "Send connection start message to backend: ");
+
/* Start the message. */
if (pqPutMsgStart(pack_type, true, conn))
return STATUS_ERROR;
diff --git a/src/interfaces/libpq/fe-exec.c b/src/interfaces/libpq/fe-exec.c
index 6aed8c8..42279a6 100644
--- a/src/interfaces/libpq/fe-exec.c
+++ b/src/interfaces/libpq/fe-exec.c
@@ -879,7 +879,7 @@ pqInternalNotice(const PGNoticeHooks *hooks, const char *fmt,...)
res->errMsg = (char *) pqResultAlloc(res, strlen(msgBuf) + 2, false);
if (res->errMsg)
{
- sprintf(res->errMsg, "%s\n", msgBuf);
+ sprintf(res->errMsg, "NOTICE: %s\n", msgBuf);
/*
* Pass to receiver, then free it.
@@ -991,9 +991,8 @@ pqSaveParameterStatus(PGconn *conn, const char *name, const char *value)
pgParameterStatus *pstatus;
pgParameterStatus *prev;
- if (conn->Pfdebug)
- fprintf(conn->Pfdebug, "pqSaveParameterStatus: '%s' = '%s'\n",
- name, value);
+ traceLog_fprintf(conn, LEVEL2, "pqSaveParameterStatus: '%s' = '%s'\n",
+ name, value);
/*
* Forget any old information about the parameter
@@ -1208,6 +1207,8 @@ fail:
int
PQsendQuery(PGconn *conn, const char *query)
{
+ traceLog_fprintf(conn, LEVEL1, "PQsendQuery start :");
+
if (!PQsendQueryStart(conn))
return 0;
@@ -1219,6 +1220,8 @@ PQsendQuery(PGconn *conn, const char *query)
return 0;
}
+ traceLog_fprintf(conn, LEVEL1, "Query: %s \n",query);
+
/* construct the outgoing Query message */
if (pqPutMsgStart('Q', false, conn) < 0 ||
pqPuts(query, conn) < 0 ||
@@ -1249,6 +1252,9 @@ PQsendQuery(PGconn *conn, const char *query)
/* OK, it's launched! */
conn->asyncStatus = PGASYNC_BUSY;
+
+ traceLog_fprintf(conn, LEVEL1, "PQsendQuery end :");
+
return 1;
}
@@ -1266,6 +1272,8 @@ PQsendQueryParams(PGconn *conn,
const int *paramFormats,
int resultFormat)
{
+ traceLog_fprintf(conn, LEVEL1, "PQsendQueryParams start :");
+
if (!PQsendQueryStart(conn))
return 0;
@@ -1283,6 +1291,8 @@ PQsendQueryParams(PGconn *conn,
return 0;
}
+ traceLog_fprintf(conn, LEVEL1, "PQsendQueryParams end :");
+
return PQsendQueryGuts(conn,
command,
"", /* use unnamed statement */
@@ -1306,6 +1316,8 @@ PQsendPrepare(PGconn *conn,
const char *stmtName, const char *query,
int nParams, const Oid *paramTypes)
{
+ traceLog_fprintf(conn, LEVEL1, "PQsendPrepare start :");
+
if (!PQsendQueryStart(conn))
return 0;
@@ -1337,6 +1349,8 @@ PQsendPrepare(PGconn *conn,
return 0;
}
+ traceLog_fprintf(conn, LEVEL1, "Statement name: %s, Query: %s \n",stmtName, query);
+
/* construct the Parse message */
if (pqPutMsgStart('P', false, conn) < 0 ||
pqPuts(stmtName, conn) < 0 ||
@@ -1386,6 +1400,9 @@ PQsendPrepare(PGconn *conn,
/* OK, it's launched! */
conn->asyncStatus = PGASYNC_BUSY;
+
+ traceLog_fprintf(conn, LEVEL1, "PQsendPrepare end :");
+
return 1;
sendFailed:
@@ -1492,6 +1509,8 @@ PQsendQueryGuts(PGconn *conn,
{
int i;
+ traceLog_fprintf(conn, LEVEL1, "PQsendQueryGuts start :");
+
/* This isn't gonna work on a 2.0 server */
if (PG_PROTOCOL_MAJOR(conn->pversion) < 3)
{
@@ -1507,6 +1526,8 @@ PQsendQueryGuts(PGconn *conn,
if (command)
{
+ traceLog_fprintf(conn, LEVEL1, "Statement name: %s, Command: %s \n",stmtName, command);
+
/* construct the Parse message */
if (pqPutMsgStart('P', false, conn) < 0 ||
pqPuts(stmtName, conn) < 0 ||
@@ -1638,6 +1659,9 @@ PQsendQueryGuts(PGconn *conn,
/* OK, it's launched! */
conn->asyncStatus = PGASYNC_BUSY;
+
+ traceLog_fprintf(conn, LEVEL1, "PQsendQueryGuts end :");
+
return 1;
sendFailed:
@@ -1780,6 +1804,8 @@ PQgetResult(PGconn *conn)
{
PGresult *res;
+ traceLog_fprintf(conn, LEVEL1, "PQgetResult start :");
+
if (!conn)
return NULL;
@@ -1820,6 +1846,7 @@ PQgetResult(PGconn *conn)
/* Parse it. */
parseInput(conn);
+
}
/* Return the appropriate thing. */
@@ -1874,6 +1901,8 @@ PQgetResult(PGconn *conn)
}
}
+ traceLog_fprintf(conn, LEVEL1, "PQgetResult end :");
+
return res;
}
@@ -2203,6 +2232,8 @@ PQsendDescribePortal(PGconn *conn, const char *portal)
static int
PQsendDescribe(PGconn *conn, char desc_type, const char *desc_target)
{
+ traceLog_fprintf(conn, LEVEL1, "PQsendDescribe start :");
+
/* Treat null desc_target as empty string */
if (!desc_target)
desc_target = "";
@@ -2218,6 +2249,8 @@ PQsendDescribe(PGconn *conn, char desc_type, const char *desc_target)
return 0;
}
+ traceLog_fprintf(conn, LEVEL1, "Describe type: %c, target: %s \n",desc_type, desc_target);
+
/* construct the Describe message */
if (pqPutMsgStart('D', false, conn) < 0 ||
pqPutc(desc_type, conn) < 0 ||
@@ -2249,6 +2282,9 @@ PQsendDescribe(PGconn *conn, char desc_type, const char *desc_target)
/* OK, it's launched! */
conn->asyncStatus = PGASYNC_BUSY;
+
+ traceLog_fprintf(conn, LEVEL1, "PQsendDescribe end :");
+
return 1;
sendFailed:
diff --git a/src/interfaces/libpq/fe-misc.c b/src/interfaces/libpq/fe-misc.c
index 46ece1a..4c77749 100644
--- a/src/interfaces/libpq/fe-misc.c
+++ b/src/interfaces/libpq/fe-misc.c
@@ -35,6 +35,7 @@
#ifdef WIN32
#include "win32.h"
+#include <windows.h>
#else
#include <unistd.h>
#include <sys/time.h>
@@ -45,6 +46,7 @@
#endif
#ifdef HAVE_SYS_SELECT_H
#include <sys/select.h>
+#include <sys/timeb.h>
#endif
#include "libpq-fe.h"
@@ -60,6 +62,186 @@ static int pqSocketCheck(PGconn *conn, int forRead, int forWrite,
time_t end_time);
static int pqSocketPoll(int sock, int forRead, int forWrite, time_t end_time);
+static void getTraceLogFilename(PGconn *conn,char* filename);
+static void traceLog_fputnbytes(PGconn *conn, int loglevel ,const char *head, const char *str, size_t n);
+static void fputnbytes(FILE *f, const char *str, size_t n);
+static void getCurrentTime(char* currenttime,int type);
+#define TRACELOG_TIME_SIZE 28
+
+/*
+ * getCurrentTime: get current time for trace log output
+ *
+ * type=0 currenttime formate %Y-%m-%d_%H%M%S
+ * type=1 currenttime formate %Y/%m/%d %H:%M:%S.%Milliseconds
+ */
+static void
+getCurrentTime(char* currenttime,int type)
+{
+#ifdef WIN32
+ SYSTEMTIME localTime;
+ GetLocalTime(&localTime);
+ if(type==0)
+ snprintf(currenttime,TRACELOG_TIME_SIZE,"%4d-%02d-%02d_%02d%02d%02d",
+ localTime.wYear,localTime.wMonth,localTime.wDay,
+ localTime.wHour,localTime.wMinute,localTime.wSecond);
+ else if(type==1)
+ snprintf(currenttime,TRACELOG_TIME_SIZE,"%4d/%02d/%02d %02d:%02d:%02d.%03d",
+ localTime.wYear,localTime.wMonth,localTime.wDay,
+ localTime.wHour,localTime.wMinute,localTime.wSecond,
+ localTime.wMilliseconds);
+#else
+ struct timeb localTime;
+ struct tm *tm;
+ ftime(&localTime);
+ tm = localtime(&localTime.time);
+ if(type == 0)
+ snprintf(currenttime, TRACELOG_TIME_SIZE,"%4d-%02d-%02d_%02d%02d%02d",
+ 1900+ tm->tm_year,1 + tm->tm_mon, tm->tm_mday,
+ tm->tm_hour, tm->tm_min, tm->tm_sec);
+ else if(type==1)
+ snprintf(currenttime, TRACELOG_TIME_SIZE,"%4d/%02d/%02d %02d:%02d:%02d.%03d",
+ 1900+ tm->tm_year,1 + tm->tm_mon, tm->tm_mday,
+ tm->tm_hour, tm->tm_min, tm->tm_sec, localTime.millitm);
+#endif
+}
+
+/*
+ * getTraceLogFilename: build trace log file name
+ * The name is libpq-%ProcessID-%Y-%m-%d_%H%M%S.log.
+ */
+static void
+getTraceLogFilename(PGconn *conn,char* filename)
+{
+ char currenttime[TRACELOG_TIME_SIZE]; /* %Y-%m-%d_%H%M%S */
+ getCurrentTime(currenttime,0);
+
+#ifdef WIN32
+ snprintf(filename, MAXPGPATH, "%s\\libpq-%d-%s.log", conn->logdir,getpid(),currenttime);
+#else
+ snprintf(filename, MAXPGPATH, "%s/libpq-%d-%s.log", conn->logdir,getpid(),currenttime);
+#endif
+}
+
+/*
+ * initTraceLog: initialize a trace log file
+ */
+void
+initTraceLog(PGconn *conn)
+{
+ char logfilename[MAXPGPATH];
+ getTraceLogFilename(conn,logfilename);
+ conn->traceDebug=fopen(logfilename,"w");
+ fprintf(conn->traceDebug, "Max log size is %sB, log min level is %s\n",
+ conn->logsize_str, conn->logminlevel_str);
+}
+
+/*
+ * traceLog_fprintf: output trace log to file
+ * If PQtrace() is called, PQtrace() is output followed by libpq trace log.
+ */
+void
+traceLog_fprintf(PGconn *conn, int loglevel, const char *fmt,...)
+{
+ char logfilename[MAXPGPATH];
+ char msgBuf[MAXPGPATH];
+ va_list args;
+ int ret;
+ char currenttime[TRACELOG_TIME_SIZE];
+ bool output_tracelog = true;
+
+ va_start(args, fmt);
+ vsnprintf(msgBuf, sizeof(msgBuf), fmt, args);
+ msgBuf[sizeof(msgBuf) - 1] = '\0';
+ va_end(args);
+
+ if(conn->logminlevel < loglevel)
+ output_tracelog = false;
+
+ if(conn->Pfdebug)
+ {
+ fprintf(conn->Pfdebug, "%s", msgBuf);
+ }
+ else if(conn->traceDebug && output_tracelog)
+ {
+ if((int)ftell(conn->traceDebug) >= conn->logsize)
+ {
+ fclose(conn->traceDebug);
+ getTraceLogFilename(conn,logfilename);
+ conn->traceDebug = fopen(logfilename,"w");
+ if(conn->traceDebug == NULL)
+ return;
+ fprintf(conn->traceDebug, "Max log size is %sB, log min level is %s\n",
+ conn->logsize_str, conn->logminlevel_str);
+ }
+
+ /* Select trace log message style */
+ if(loglevel == LEVEL1)
+ {
+ getCurrentTime(currenttime,1);
+ ret = fprintf(conn->traceDebug, "%s %s\n", currenttime, msgBuf);
+ }
+
+ if(loglevel == LEVEL2)
+ {
+ ret = fprintf(conn->traceDebug, "%s",msgBuf);
+ }
+
+ if(ret < 0)
+ {
+ fclose(conn->traceDebug);
+ conn->traceDebug = NULL;
+ return;
+ }
+ fflush(conn->traceDebug);
+ }
+}
+/*
+ * traceLog_fputnbytes: output trace log to file using fputnbytes()
+ */
+static void
+traceLog_fputnbytes(PGconn *conn,int loglevel, const char *head, const char *str, size_t n)
+{
+ char logfilename[MAXPGPATH];
+ int ret;
+ bool output_tracelog = true;
+
+ if(conn->logminlevel < loglevel)
+ output_tracelog = false;
+
+ if (conn->Pfdebug)
+ {
+ fprintf(conn->Pfdebug, "%s", head);
+ fputnbytes(conn->Pfdebug,str, n);
+ fprintf(conn->Pfdebug, "\n");
+ }
+ else if(conn->traceDebug && output_tracelog)
+ {
+ if(conn->logminlevel < loglevel)
+ {
+ return;
+ }
+
+ if((int)ftell(conn->traceDebug) >= conn->logsize)
+ {
+ fclose(conn->traceDebug);
+ getTraceLogFilename(conn,logfilename);
+ conn->traceDebug = fopen(logfilename,"w");
+ if(conn->traceDebug == NULL)
+ return;
+ }
+ ret = fprintf(conn->traceDebug, "%s", head);
+ if(ret < 0)
+ {
+ fclose(conn->traceDebug);
+ conn->traceDebug = NULL;
+ return;
+ }
+ fputnbytes(conn->traceDebug,str,n);
+ fprintf(conn->traceDebug,"\n");
+ fflush(conn->traceDebug);
+ }
+}
+
/*
* PQlibVersion: return the libpq version number
*/
@@ -98,8 +280,7 @@ pqGetc(char *result, PGconn *conn)
*result = conn->inBuffer[conn->inCursor++];
- if (conn->Pfdebug)
- fprintf(conn->Pfdebug, "From backend> %c\n", *result);
+ traceLog_fprintf(conn, LEVEL2, "From backend> %c\n", *result);
return 0;
}
@@ -114,8 +295,7 @@ pqPutc(char c, PGconn *conn)
if (pqPutMsgBytes(&c, 1, conn))
return EOF;
- if (conn->Pfdebug)
- fprintf(conn->Pfdebug, "To backend> %c\n", c);
+ traceLog_fprintf(conn, LEVEL2, "To backend> %c\n", c);
return 0;
}
@@ -152,9 +332,8 @@ pqGets_internal(PQExpBuffer buf, PGconn *conn, bool resetbuffer)
conn->inCursor = ++inCursor;
- if (conn->Pfdebug)
- fprintf(conn->Pfdebug, "From backend> \"%s\"\n",
- buf->data);
+ traceLog_fprintf(conn, LEVEL2, "From backend> \"%s\"\n",
+ buf->data);
return 0;
}
@@ -181,8 +360,7 @@ pqPuts(const char *s, PGconn *conn)
if (pqPutMsgBytes(s, strlen(s) + 1, conn))
return EOF;
- if (conn->Pfdebug)
- fprintf(conn->Pfdebug, "To backend> \"%s\"\n", s);
+ traceLog_fprintf(conn, LEVEL2, "To backend> \"%s\"\n", s);
return 0;
}
@@ -194,6 +372,7 @@ pqPuts(const char *s, PGconn *conn)
int
pqGetnchar(char *s, size_t len, PGconn *conn)
{
+ char buf[100];
if (len > (size_t) (conn->inEnd - conn->inCursor))
return EOF;
@@ -202,12 +381,8 @@ pqGetnchar(char *s, size_t len, PGconn *conn)
conn->inCursor += len;
- if (conn->Pfdebug)
- {
- fprintf(conn->Pfdebug, "From backend (%lu)> ", (unsigned long) len);
- fputnbytes(conn->Pfdebug, s, len);
- fprintf(conn->Pfdebug, "\n");
- }
+ sprintf(buf, "From backend (%lu)> ", (unsigned long) len);
+ traceLog_fputnbytes(conn, LEVEL2, buf, s, len);
return 0;
}
@@ -223,15 +398,12 @@ pqGetnchar(char *s, size_t len, PGconn *conn)
int
pqSkipnchar(size_t len, PGconn *conn)
{
+ char buf[100];
if (len > (size_t) (conn->inEnd - conn->inCursor))
return EOF;
- if (conn->Pfdebug)
- {
- fprintf(conn->Pfdebug, "From backend (%lu)> ", (unsigned long) len);
- fputnbytes(conn->Pfdebug, conn->inBuffer + conn->inCursor, len);
- fprintf(conn->Pfdebug, "\n");
- }
+ sprintf(buf, "From backend (%lu)> ", (unsigned long) len);
+ traceLog_fputnbytes(conn, LEVEL2, buf, conn->inBuffer + conn->inCursor, len);
conn->inCursor += len;
@@ -245,15 +417,12 @@ pqSkipnchar(size_t len, PGconn *conn)
int
pqPutnchar(const char *s, size_t len, PGconn *conn)
{
+ char buf[100];
if (pqPutMsgBytes(s, len, conn))
return EOF;
- if (conn->Pfdebug)
- {
- fprintf(conn->Pfdebug, "To backend> ");
- fputnbytes(conn->Pfdebug, s, len);
- fprintf(conn->Pfdebug, "\n");
- }
+ sprintf(buf,"To backend (%lu)> ", (unsigned long) len);
+ traceLog_fputnbytes(conn, LEVEL2, buf, s, len);
return 0;
}
@@ -292,8 +461,7 @@ pqGetInt(int *result, size_t bytes, PGconn *conn)
return EOF;
}
- if (conn->Pfdebug)
- fprintf(conn->Pfdebug, "From backend (#%lu)> %d\n", (unsigned long) bytes, *result);
+ traceLog_fprintf(conn, LEVEL2, "From backend (#%lu)> %d\n", (unsigned long) bytes, *result);
return 0;
}
@@ -328,8 +496,7 @@ pqPutInt(int value, size_t bytes, PGconn *conn)
return EOF;
}
- if (conn->Pfdebug)
- fprintf(conn->Pfdebug, "To backend (%lu#)> %d\n", (unsigned long) bytes, value);
+ traceLog_fprintf(conn, LEVEL2, "To backend (%lu#)> %d\n", (unsigned long) bytes, value);
return 0;
}
@@ -548,9 +715,8 @@ pqPutMsgStart(char msg_type, bool force_len, PGconn *conn)
conn->outMsgEnd = endPos;
/* length word, if needed, will be filled in by pqPutMsgEnd */
- if (conn->Pfdebug)
- fprintf(conn->Pfdebug, "To backend> Msg %c\n",
- msg_type ? msg_type : ' ');
+ traceLog_fprintf(conn, LEVEL2, "To backend> Msg %c\n",
+ msg_type ? msg_type : ' ');
return 0;
}
@@ -586,9 +752,8 @@ pqPutMsgBytes(const void *buf, size_t len, PGconn *conn)
int
pqPutMsgEnd(PGconn *conn)
{
- if (conn->Pfdebug)
- fprintf(conn->Pfdebug, "To backend> Msg complete, length %u\n",
- conn->outMsgEnd - conn->outCount);
+ traceLog_fprintf(conn, LEVEL2, "To backend> Msg complete, length %u\n",
+ conn->outMsgEnd - conn->outCount);
/* Fill in length word if needed */
if (conn->outMsgStart >= 0)
@@ -677,9 +842,15 @@ pqReadData(PGconn *conn)
}
/* OK, try to read some data */
+
retry3:
+ traceLog_fprintf(conn, LEVEL1, "Start receiving message from backend:");
+
nread = pqsecure_read(conn, conn->inBuffer + conn->inEnd,
conn->inBufSize - conn->inEnd);
+
+ traceLog_fprintf(conn, LEVEL1, "End receiving message from backend:");
+
if (nread < 0)
{
if (SOCK_ERRNO == EINTR)
@@ -767,9 +938,14 @@ retry3:
* Still not sure that it's EOF, because some data could have just
* arrived.
*/
+
+ traceLog_fprintf(conn, LEVEL1, "Start receiving message from backend:");
retry4:
nread = pqsecure_read(conn, conn->inBuffer + conn->inEnd,
conn->inBufSize - conn->inEnd);
+
+ traceLog_fprintf(conn, LEVEL1, "End receiving message from backend:");
+
if (nread < 0)
{
if (SOCK_ERRNO == EINTR)
@@ -846,6 +1022,8 @@ pqSendSome(PGconn *conn, int len)
{
int sent;
+ traceLog_fprintf(conn, LEVEL1, "Start sending message to backend:");
+
#ifndef WIN32
sent = pqsecure_write(conn, ptr, len);
#else
@@ -858,6 +1036,8 @@ pqSendSome(PGconn *conn, int len)
sent = pqsecure_write(conn, ptr, Min(len, 65536));
#endif
+ traceLog_fprintf(conn, LEVEL1, "End sending message to backend:");
+
if (sent < 0)
{
/* Anything except EAGAIN/EWOULDBLOCK/EINTR is trouble */
@@ -963,6 +1143,9 @@ pqFlush(PGconn *conn)
if (conn->Pfdebug)
fflush(conn->Pfdebug);
+ if (conn->traceDebug)
+ fflush(conn->traceDebug);
+
if (conn->outCount > 0)
return pqSendSome(conn, conn->outCount);
diff --git a/src/interfaces/libpq/libpq-fe.h b/src/interfaces/libpq/libpq-fe.h
index 3f13ddf..dd8edf3 100644
--- a/src/interfaces/libpq/libpq-fe.h
+++ b/src/interfaces/libpq/libpq-fe.h
@@ -36,6 +36,10 @@ extern "C"
#define PG_COPYRES_EVENTS 0x04
#define PG_COPYRES_NOTICEHOOKS 0x08
+/* trace log level */
+#define LEVEL1 10 /* Time and process (by default) */
+#define LEVEL2 11 /* Server and Client exchange messages */
+
/* Application-visible enum types */
/*
diff --git a/src/interfaces/libpq/libpq-int.h b/src/interfaces/libpq/libpq-int.h
index 66fd317..4f9726a 100644
--- a/src/interfaces/libpq/libpq-int.h
+++ b/src/interfaces/libpq/libpq-int.h
@@ -500,6 +500,13 @@ struct pg_conn
/* Buffer for receiving various parts of messages */
PQExpBufferData workBuffer; /* expansible string */
+
+ char *logdir; /* Trace log directory to save log */
+ char *logsize_str; /* Trace log maximum size (string) */
+ char *logminlevel_str; /* Trace log level (string)*/
+ int logsize; /* Trace log maximum size */
+ int logminlevel; /* Trace log level( "level1"(default) or "level2") */
+ FILE *traceDebug; /* Trace log file to write trace info */
};
/* PGcancel stores all data necessary to cancel a connection. A copy of this
@@ -666,6 +673,10 @@ extern void pq_reset_sigpipe(sigset_t *osigset, bool sigpipe_pending,
bool got_epipe);
#endif
+/* libpq trace log */
+extern void initTraceLog(PGconn *conn);
+extern void traceLog_fprintf(PGconn *conn, int loglevel, const char *fmt,...) pg_attribute_printf(3, 4);
+
/* === SSL === */
/*
Hi,
I created v5 patch. Please find attached the patch.
This patch updated following items;
- Changed "else if" to "if" in traceLog_fprintf(). This means that both PQtrace() and new trace log are set, you can get both log result.
- Implemented loglevel with enum. This change makes it easier if you want to add new log levels.
- Checked http://commitfest.cputube.org/, I modified the code slightly.
I would appreciate if you could review my latest patch.
Regards,
Aya Iwata
Attachments:
v5-0001-libpq-trace-log.patchapplication/octet-stream; name=v5-0001-libpq-trace-log.patchDownload
diff --git a/doc/src/sgml/libpq.sgml b/doc/src/sgml/libpq.sgml
index d2e5b08..080d24c 100644
--- a/doc/src/sgml/libpq.sgml
+++ b/doc/src/sgml/libpq.sgml
@@ -1589,6 +1589,42 @@ postgresql://%2Fvar%2Flib%2Fpostgresql/dbname
</para>
</listitem>
</varlistentry>
+
+ <varlistentry id="libpq-connect-log-dir" xreflabel="logdir">
+ <term><literal>logdir</literal></term>
+ <listitem>
+ <para>
+ Path of directory where log file written. When both <literal>logdir</literal>
+ and <literal>logsize</literal> is set, logging is enabled.
+ </para>
+ </listitem>
+ </varlistentry>
+
+ <varlistentry id="libpq-connect-log-size" xreflabel="logsize">
+ <term><literal>logsize</literal></term>
+ <listitem>
+ <para>
+ Maximum log size. The unit is megabyte. When the log file size exceeds
+ to <literal>logsize</literal>, the log is output to another file.
+ When both <literal>logdir</literal> and <literal>logsize</literal> is set,
+ logging is enabled.
+ </para>
+ </listitem>
+ </varlistentry>
+
+ <varlistentry id="libpq-connect-log-min-level" xreflabel="logminlevel">
+ <term><literal>logminlevel</literal></term>
+ <listitem>
+ <para>
+ Level of the log. <literal>level1</literal> and <literal>level2</literal>
+ can be set, <literal>level1</literal> is the default.
+ When this parameter is <literal>level1</literal>,it outputs the time
+ in the function and connection time. <literal>level2</literal> outputs
+ information on the protocol being exchanged in addition to
+ <literal>level1</literal> information.
+ </para>
+ </listitem>
+ </varlistentry>
</variablelist>
</para>
</sect2>
@@ -7472,6 +7508,36 @@ myEventProc(PGEventId evtId, void *evtInfo, void *passThrough)
linkend="libpq-connect-target-session-attrs"/> connection parameter.
</para>
</listitem>
+
+ <listitem>
+ <para>
+ <indexterm>
+ <primary><envar>PGLOGDIR</envar></primary>
+ </indexterm>
+ <envar>PGLOGDIR</envar> behaves the same as the <xref
+ linkend="libpq-connect-log-dir"/> connection parameter.
+ </para>
+ </listitem>
+
+ <listitem>
+ <para>
+ <indexterm>
+ <primary><envar>PGLOGSIZE</envar></primary>
+ </indexterm>
+ <envar>PGLOGSIZE</envar> behaves the same as the <xref
+ linkend="libpq-connect-log-size"/> connection parameter.
+ </para>
+ </listitem>
+
+ <listitem>
+ <para>
+ <indexterm>
+ <primary><envar>PGLOGMINLEVEL</envar></primary>
+ </indexterm>
+ <envar>PGLOGMINLEVEL</envar> behaves the same as the <xref
+ linkend="libpq-connect-log-min-level"/> connection parameter.
+ </para>
+ </listitem>
</itemizedlist>
</para>
@@ -8300,6 +8366,38 @@ int PQisthreadsafe();
</para>
</sect1>
+ <sect1 id="libpq-logging">
+ <title>Logging</title>
+
+ <indexterm zone="libpq-logging">
+ <primary>trace log</primary>
+ </indexterm>
+ <indexterm zone="libpq-logging">
+ <primary>logging</primary>
+ </indexterm>
+
+ <para>
+ Libpq trace log can trace information about SQL queries which issued by
+ the libpq application. This output help determine whether the couse is
+ on backend side or application side and solve issues with the libpq Driver
+ when it use. The log without requiring recompile of the libpq application.
+ </para>
+
+ <para>
+ You can activate this log by setting both <parameter>logdir</parameter> and
+ <parameter>logsize</parameter> of the connection string, or by setting both
+ the environment variables <envar>PGLOGDIR</envar> and <envar>PGLOGSIZE</envar>.
+ The log trace file is written in a directory setting by <envar>PGLOGDIR</envar>
+ or <parameter>logdir</parameter>.
+ Information to be output to the log file can be controlled by setting
+ <parameter>logminlevel</parameter> or <envar>PGLOGMINLEVEL</envar>.
+ The file name is determined as <filename>libpq-%ProcessID-%Y-%m-%d_%H%M%S.log</filename>.
+ If the setting of the file path by the connection string or the environment variable is
+ incorrect, the log file is not created in the intended location.
+ The maximum log file size and log level you set is output to the beginning of the file,
+ so you can check it.
+ </para>
+ </sect1>
<sect1 id="libpq-build">
<title>Building <application>libpq</application> Programs</title>
diff --git a/src/interfaces/libpq/fe-connect.c b/src/interfaces/libpq/fe-connect.c
index bc456fe..0080209 100644
--- a/src/interfaces/libpq/fe-connect.c
+++ b/src/interfaces/libpq/fe-connect.c
@@ -129,6 +129,7 @@ static int ldapServiceLookup(const char *purl, PQconninfoOption *options,
#else
#define DefaultSSLMode "disable"
#endif
+#define DefaultLogMinLevel "LEVEL1"
/* ----------
* Definition of the conninfo parameters and their fallback resources.
@@ -325,6 +326,19 @@ static const internalPQconninfoOption PQconninfoOptions[] = {
"Target-Session-Attrs", "", 11, /* sizeof("read-write") = 11 */
offsetof(struct pg_conn, target_session_attrs)},
+ /* libpq trace log options */
+ {"logdir", "PGLOGDIR", NULL, NULL,
+ "Logdir", "", MAXPGPATH - 4,
+ offsetof(struct pg_conn, logdir)},
+
+ {"logsize", "PGLOGSIZE", NULL, NULL,
+ "Logsize", "", 5,
+ offsetof(struct pg_conn, logsize_str)},
+
+ {"logminlevel", "PGLOGMINLEVEL", DefaultLogMinLevel, NULL,
+ "LogMinlevel", "", 7,
+ offsetof(struct pg_conn, logminlevel_str)},
+
/* Terminating entry --- MUST BE LAST */
{NULL, NULL, NULL, NULL,
NULL, NULL, 0}
@@ -1128,6 +1142,26 @@ connectOptions2(PGconn *conn)
}
/*
+ * If both size and directory of trace log was given,
+ * initialize a trace log.
+ */
+ if (conn->logsize_str && conn->logsize_str[0] != '\0')
+ conn->logsize = atoi(conn->logsize_str);
+
+ if (conn->logdir != NULL && conn->logsize > 0 && conn->logsize < 2048)
+ {
+ conn->logsize = conn->logsize * 1024 * 1024;
+
+ if(strcmp(conn->logminlevel_str, "level1") == 0)
+ conn->logminlevel = LEVEL1;
+
+ if(strcmp(conn->logminlevel_str, "level2") == 0)
+ conn->logminlevel = LEVEL2;
+
+ initTraceLog(conn);
+ }
+
+ /*
* If password was not given, try to look it up in password file. Note
* that the result might be different for each host/port pair.
*/
@@ -3716,6 +3750,16 @@ freePGconn(PGconn *conn)
termPQExpBuffer(&conn->errorMessage);
termPQExpBuffer(&conn->workBuffer);
+ /* clean up libpq trace log structures */
+ if (conn->logsize_str)
+ free(conn->logsize_str);
+ if (conn->logdir)
+ free(conn->logdir);
+ if (conn->logminlevel_str)
+ free(conn->logminlevel_str);
+ if (conn->traceDebug)
+ fclose(conn->traceDebug);
+
free(conn);
#ifdef WIN32
@@ -3751,6 +3795,7 @@ sendTerminateConn(PGconn *conn)
*/
if (conn->sock != PGINVALID_SOCKET && conn->status == CONNECTION_OK)
{
+ traceLog_fprintf(conn, LEVEL1, "Send connection terminate message to backend: ");
/*
* Try to send "close connection" message to backend. Ignore any
* error.
@@ -4153,6 +4198,8 @@ int
pqPacketSend(PGconn *conn, char pack_type,
const void *buf, size_t buf_len)
{
+ traceLog_fprintf(conn, LEVEL1, "Send connection start message to backend: ");
+
/* Start the message. */
if (pqPutMsgStart(pack_type, true, conn))
return STATUS_ERROR;
diff --git a/src/interfaces/libpq/fe-exec.c b/src/interfaces/libpq/fe-exec.c
index 6aed8c8..42279a6 100644
--- a/src/interfaces/libpq/fe-exec.c
+++ b/src/interfaces/libpq/fe-exec.c
@@ -879,7 +879,7 @@ pqInternalNotice(const PGNoticeHooks *hooks, const char *fmt,...)
res->errMsg = (char *) pqResultAlloc(res, strlen(msgBuf) + 2, false);
if (res->errMsg)
{
- sprintf(res->errMsg, "%s\n", msgBuf);
+ sprintf(res->errMsg, "NOTICE: %s\n", msgBuf);
/*
* Pass to receiver, then free it.
@@ -991,9 +991,8 @@ pqSaveParameterStatus(PGconn *conn, const char *name, const char *value)
pgParameterStatus *pstatus;
pgParameterStatus *prev;
- if (conn->Pfdebug)
- fprintf(conn->Pfdebug, "pqSaveParameterStatus: '%s' = '%s'\n",
- name, value);
+ traceLog_fprintf(conn, LEVEL2, "pqSaveParameterStatus: '%s' = '%s'\n",
+ name, value);
/*
* Forget any old information about the parameter
@@ -1208,6 +1207,8 @@ fail:
int
PQsendQuery(PGconn *conn, const char *query)
{
+ traceLog_fprintf(conn, LEVEL1, "PQsendQuery start :");
+
if (!PQsendQueryStart(conn))
return 0;
@@ -1219,6 +1220,8 @@ PQsendQuery(PGconn *conn, const char *query)
return 0;
}
+ traceLog_fprintf(conn, LEVEL1, "Query: %s \n",query);
+
/* construct the outgoing Query message */
if (pqPutMsgStart('Q', false, conn) < 0 ||
pqPuts(query, conn) < 0 ||
@@ -1249,6 +1252,9 @@ PQsendQuery(PGconn *conn, const char *query)
/* OK, it's launched! */
conn->asyncStatus = PGASYNC_BUSY;
+
+ traceLog_fprintf(conn, LEVEL1, "PQsendQuery end :");
+
return 1;
}
@@ -1266,6 +1272,8 @@ PQsendQueryParams(PGconn *conn,
const int *paramFormats,
int resultFormat)
{
+ traceLog_fprintf(conn, LEVEL1, "PQsendQueryParams start :");
+
if (!PQsendQueryStart(conn))
return 0;
@@ -1283,6 +1291,8 @@ PQsendQueryParams(PGconn *conn,
return 0;
}
+ traceLog_fprintf(conn, LEVEL1, "PQsendQueryParams end :");
+
return PQsendQueryGuts(conn,
command,
"", /* use unnamed statement */
@@ -1306,6 +1316,8 @@ PQsendPrepare(PGconn *conn,
const char *stmtName, const char *query,
int nParams, const Oid *paramTypes)
{
+ traceLog_fprintf(conn, LEVEL1, "PQsendPrepare start :");
+
if (!PQsendQueryStart(conn))
return 0;
@@ -1337,6 +1349,8 @@ PQsendPrepare(PGconn *conn,
return 0;
}
+ traceLog_fprintf(conn, LEVEL1, "Statement name: %s, Query: %s \n",stmtName, query);
+
/* construct the Parse message */
if (pqPutMsgStart('P', false, conn) < 0 ||
pqPuts(stmtName, conn) < 0 ||
@@ -1386,6 +1400,9 @@ PQsendPrepare(PGconn *conn,
/* OK, it's launched! */
conn->asyncStatus = PGASYNC_BUSY;
+
+ traceLog_fprintf(conn, LEVEL1, "PQsendPrepare end :");
+
return 1;
sendFailed:
@@ -1492,6 +1509,8 @@ PQsendQueryGuts(PGconn *conn,
{
int i;
+ traceLog_fprintf(conn, LEVEL1, "PQsendQueryGuts start :");
+
/* This isn't gonna work on a 2.0 server */
if (PG_PROTOCOL_MAJOR(conn->pversion) < 3)
{
@@ -1507,6 +1526,8 @@ PQsendQueryGuts(PGconn *conn,
if (command)
{
+ traceLog_fprintf(conn, LEVEL1, "Statement name: %s, Command: %s \n",stmtName, command);
+
/* construct the Parse message */
if (pqPutMsgStart('P', false, conn) < 0 ||
pqPuts(stmtName, conn) < 0 ||
@@ -1638,6 +1659,9 @@ PQsendQueryGuts(PGconn *conn,
/* OK, it's launched! */
conn->asyncStatus = PGASYNC_BUSY;
+
+ traceLog_fprintf(conn, LEVEL1, "PQsendQueryGuts end :");
+
return 1;
sendFailed:
@@ -1780,6 +1804,8 @@ PQgetResult(PGconn *conn)
{
PGresult *res;
+ traceLog_fprintf(conn, LEVEL1, "PQgetResult start :");
+
if (!conn)
return NULL;
@@ -1820,6 +1846,7 @@ PQgetResult(PGconn *conn)
/* Parse it. */
parseInput(conn);
+
}
/* Return the appropriate thing. */
@@ -1874,6 +1901,8 @@ PQgetResult(PGconn *conn)
}
}
+ traceLog_fprintf(conn, LEVEL1, "PQgetResult end :");
+
return res;
}
@@ -2203,6 +2232,8 @@ PQsendDescribePortal(PGconn *conn, const char *portal)
static int
PQsendDescribe(PGconn *conn, char desc_type, const char *desc_target)
{
+ traceLog_fprintf(conn, LEVEL1, "PQsendDescribe start :");
+
/* Treat null desc_target as empty string */
if (!desc_target)
desc_target = "";
@@ -2218,6 +2249,8 @@ PQsendDescribe(PGconn *conn, char desc_type, const char *desc_target)
return 0;
}
+ traceLog_fprintf(conn, LEVEL1, "Describe type: %c, target: %s \n",desc_type, desc_target);
+
/* construct the Describe message */
if (pqPutMsgStart('D', false, conn) < 0 ||
pqPutc(desc_type, conn) < 0 ||
@@ -2249,6 +2282,9 @@ PQsendDescribe(PGconn *conn, char desc_type, const char *desc_target)
/* OK, it's launched! */
conn->asyncStatus = PGASYNC_BUSY;
+
+ traceLog_fprintf(conn, LEVEL1, "PQsendDescribe end :");
+
return 1;
sendFailed:
diff --git a/src/interfaces/libpq/fe-misc.c b/src/interfaces/libpq/fe-misc.c
index 46ece1a..5a4b6c3 100644
--- a/src/interfaces/libpq/fe-misc.c
+++ b/src/interfaces/libpq/fe-misc.c
@@ -35,6 +35,7 @@
#ifdef WIN32
#include "win32.h"
+#include <windows.h>
#else
#include <unistd.h>
#include <sys/time.h>
@@ -45,6 +46,7 @@
#endif
#ifdef HAVE_SYS_SELECT_H
#include <sys/select.h>
+#include <sys/timeb.h>
#endif
#include "libpq-fe.h"
@@ -60,6 +62,191 @@ static int pqSocketCheck(PGconn *conn, int forRead, int forWrite,
time_t end_time);
static int pqSocketPoll(int sock, int forRead, int forWrite, time_t end_time);
+static void getTraceLogFilename(PGconn *conn,char* filename);
+static void traceLog_fputnbytes(PGconn *conn, int loglevel ,const char *head, const char *str, size_t n);
+static void fputnbytes(FILE *f, const char *str, size_t n);
+static void getCurrentTime(char* currenttime,int type);
+#define TRACELOG_TIME_SIZE 28
+
+/*
+ * getCurrentTime: get current time for trace log output
+ *
+ * type=0 currenttime formate %Y-%m-%d_%H%M%S
+ * type=1 currenttime formate %Y/%m/%d %H:%M:%S.%Milliseconds
+ */
+static void
+getCurrentTime(char* currenttime,int type)
+{
+#ifdef WIN32
+ SYSTEMTIME localTime;
+ GetLocalTime(&localTime);
+ if(type==0)
+ snprintf(currenttime,TRACELOG_TIME_SIZE,"%4d-%02d-%02d_%02d%02d%02d",
+ localTime.wYear,localTime.wMonth,localTime.wDay,
+ localTime.wHour,localTime.wMinute,localTime.wSecond);
+ else if(type==1)
+ snprintf(currenttime,TRACELOG_TIME_SIZE,"%4d/%02d/%02d %02d:%02d:%02d.%03d",
+ localTime.wYear,localTime.wMonth,localTime.wDay,
+ localTime.wHour,localTime.wMinute,localTime.wSecond,
+ localTime.wMilliseconds);
+#else
+ struct timeb localTime;
+ struct tm *tm;
+ ftime(&localTime);
+ tm = localtime(&localTime.time);
+ if(type == 0)
+ snprintf(currenttime, TRACELOG_TIME_SIZE,"%4d-%02d-%02d_%02d%02d%02d",
+ 1900+ tm->tm_year,1 + tm->tm_mon, tm->tm_mday,
+ tm->tm_hour, tm->tm_min, tm->tm_sec);
+ else if(type==1)
+ snprintf(currenttime, TRACELOG_TIME_SIZE,"%4d/%02d/%02d %02d:%02d:%02d.%03d",
+ 1900+ tm->tm_year,1 + tm->tm_mon, tm->tm_mday,
+ tm->tm_hour, tm->tm_min, tm->tm_sec, localTime.millitm);
+#endif
+}
+
+/*
+ * getTraceLogFilename: build trace log file name
+ * The name is libpq-%ProcessID-%Y-%m-%d_%H%M%S.log.
+ */
+static void
+getTraceLogFilename(PGconn *conn,char* filename)
+{
+ char currenttime[TRACELOG_TIME_SIZE]; /* %Y-%m-%d_%H%M%S */
+ getCurrentTime(currenttime,0);
+
+#ifdef WIN32
+ snprintf(filename, MAXPGPATH, "%s\\libpq-%d-%s.log", conn->logdir,getpid(),currenttime);
+#else
+ snprintf(filename, MAXPGPATH, "%s/libpq-%d-%s.log", conn->logdir,getpid(),currenttime);
+#endif
+}
+
+/*
+ * initTraceLog: initialize a trace log file
+ */
+void
+initTraceLog(PGconn *conn)
+{
+ char logfilename[MAXPGPATH];
+ getTraceLogFilename(conn,logfilename);
+ conn->traceDebug=fopen(logfilename,"w");
+ fprintf(conn->traceDebug, "Max log size is %sB, log min level is %s\n",
+ conn->logsize_str, conn->logminlevel_str);
+}
+
+/*
+ * traceLog_fprintf: output trace log to file
+ * If PQtrace() is called, PQtrace() is output followed by libpq trace log.
+ */
+void
+traceLog_fprintf(PGconn *conn, PGTraceLogLevel loglevel, const char *fmt,...)
+{
+ char logfilename[MAXPGPATH];
+ char msgBuf[MAXPGPATH];
+ va_list args;
+ int ret = 0;
+ char currenttime[TRACELOG_TIME_SIZE];
+ bool output_tracelog = true;
+
+ va_start(args, fmt);
+ vsnprintf(msgBuf, sizeof(msgBuf), fmt, args);
+ msgBuf[sizeof(msgBuf) - 1] = '\0';
+ va_end(args);
+
+ /* Determin whether to output the log message to the file */
+ if(conn->logminlevel < loglevel)
+ output_tracelog = false;
+
+ if(conn->Pfdebug)
+ {
+ fprintf(conn->Pfdebug, "%s", msgBuf);
+ }
+
+ if(conn->traceDebug && output_tracelog)
+ {
+ if((int)ftell(conn->traceDebug) >= conn->logsize)
+ {
+ fclose(conn->traceDebug);
+ getTraceLogFilename(conn,logfilename);
+ conn->traceDebug = fopen(logfilename,"w");
+ if(conn->traceDebug == NULL)
+ return;
+ fprintf(conn->traceDebug, "Max log size is %sB, log min level is %s\n",
+ conn->logsize_str, conn->logminlevel_str);
+ }
+
+ /*
+ * Select trace log message style. The output style of LEVEL1 or LEVEL2 is
+ * always selected.
+ */
+ if(loglevel == LEVEL1)
+ {
+ getCurrentTime(currenttime,1);
+ ret = fprintf(conn->traceDebug, "%s %s\n", currenttime, msgBuf);
+ }
+
+ if(loglevel == LEVEL2)
+ {
+ ret = fprintf(conn->traceDebug, "%s",msgBuf);
+ }
+
+ if(ret < 0)
+ {
+ fclose(conn->traceDebug);
+ conn->traceDebug = NULL;
+ return;
+ }
+ fflush(conn->traceDebug);
+ }
+}
+/*
+ * traceLog_fputnbytes: output trace log to file using fputnbytes()
+ */
+static void
+traceLog_fputnbytes(PGconn *conn,int loglevel, const char *head, const char *str, size_t n)
+{
+ char logfilename[MAXPGPATH];
+ int ret;
+ bool output_tracelog = true;
+
+ if(conn->logminlevel < loglevel)
+ output_tracelog = false;
+
+ if (conn->Pfdebug)
+ {
+ fprintf(conn->Pfdebug, "%s", head);
+ fputnbytes(conn->Pfdebug,str, n);
+ fprintf(conn->Pfdebug, "\n");
+ }
+ else if(conn->traceDebug && output_tracelog)
+ {
+ if(conn->logminlevel < loglevel)
+ {
+ return;
+ }
+
+ if((int)ftell(conn->traceDebug) >= conn->logsize)
+ {
+ fclose(conn->traceDebug);
+ getTraceLogFilename(conn,logfilename);
+ conn->traceDebug = fopen(logfilename,"w");
+ if(conn->traceDebug == NULL)
+ return;
+ }
+ ret = fprintf(conn->traceDebug, "%s", head);
+ if(ret < 0)
+ {
+ fclose(conn->traceDebug);
+ conn->traceDebug = NULL;
+ return;
+ }
+ fputnbytes(conn->traceDebug,str,n);
+ fprintf(conn->traceDebug,"\n");
+ fflush(conn->traceDebug);
+ }
+}
+
/*
* PQlibVersion: return the libpq version number
*/
@@ -98,8 +285,7 @@ pqGetc(char *result, PGconn *conn)
*result = conn->inBuffer[conn->inCursor++];
- if (conn->Pfdebug)
- fprintf(conn->Pfdebug, "From backend> %c\n", *result);
+ traceLog_fprintf(conn, LEVEL2, "From backend> %c\n", *result);
return 0;
}
@@ -114,8 +300,7 @@ pqPutc(char c, PGconn *conn)
if (pqPutMsgBytes(&c, 1, conn))
return EOF;
- if (conn->Pfdebug)
- fprintf(conn->Pfdebug, "To backend> %c\n", c);
+ traceLog_fprintf(conn, LEVEL2, "To backend> %c\n", c);
return 0;
}
@@ -152,9 +337,8 @@ pqGets_internal(PQExpBuffer buf, PGconn *conn, bool resetbuffer)
conn->inCursor = ++inCursor;
- if (conn->Pfdebug)
- fprintf(conn->Pfdebug, "From backend> \"%s\"\n",
- buf->data);
+ traceLog_fprintf(conn, LEVEL2, "From backend> \"%s\"\n",
+ buf->data);
return 0;
}
@@ -181,8 +365,7 @@ pqPuts(const char *s, PGconn *conn)
if (pqPutMsgBytes(s, strlen(s) + 1, conn))
return EOF;
- if (conn->Pfdebug)
- fprintf(conn->Pfdebug, "To backend> \"%s\"\n", s);
+ traceLog_fprintf(conn, LEVEL2, "To backend> \"%s\"\n", s);
return 0;
}
@@ -194,6 +377,7 @@ pqPuts(const char *s, PGconn *conn)
int
pqGetnchar(char *s, size_t len, PGconn *conn)
{
+ char buf[100];
if (len > (size_t) (conn->inEnd - conn->inCursor))
return EOF;
@@ -202,12 +386,8 @@ pqGetnchar(char *s, size_t len, PGconn *conn)
conn->inCursor += len;
- if (conn->Pfdebug)
- {
- fprintf(conn->Pfdebug, "From backend (%lu)> ", (unsigned long) len);
- fputnbytes(conn->Pfdebug, s, len);
- fprintf(conn->Pfdebug, "\n");
- }
+ sprintf(buf, "From backend (%lu)> ", (unsigned long) len);
+ traceLog_fputnbytes(conn, LEVEL2, buf, s, len);
return 0;
}
@@ -223,15 +403,12 @@ pqGetnchar(char *s, size_t len, PGconn *conn)
int
pqSkipnchar(size_t len, PGconn *conn)
{
+ char buf[100];
if (len > (size_t) (conn->inEnd - conn->inCursor))
return EOF;
- if (conn->Pfdebug)
- {
- fprintf(conn->Pfdebug, "From backend (%lu)> ", (unsigned long) len);
- fputnbytes(conn->Pfdebug, conn->inBuffer + conn->inCursor, len);
- fprintf(conn->Pfdebug, "\n");
- }
+ sprintf(buf, "From backend (%lu)> ", (unsigned long) len);
+ traceLog_fputnbytes(conn, LEVEL2, buf, conn->inBuffer + conn->inCursor, len);
conn->inCursor += len;
@@ -245,15 +422,12 @@ pqSkipnchar(size_t len, PGconn *conn)
int
pqPutnchar(const char *s, size_t len, PGconn *conn)
{
+ char buf[100];
if (pqPutMsgBytes(s, len, conn))
return EOF;
- if (conn->Pfdebug)
- {
- fprintf(conn->Pfdebug, "To backend> ");
- fputnbytes(conn->Pfdebug, s, len);
- fprintf(conn->Pfdebug, "\n");
- }
+ sprintf(buf,"To backend (%lu)> ", (unsigned long) len);
+ traceLog_fputnbytes(conn, LEVEL2, buf, s, len);
return 0;
}
@@ -292,8 +466,7 @@ pqGetInt(int *result, size_t bytes, PGconn *conn)
return EOF;
}
- if (conn->Pfdebug)
- fprintf(conn->Pfdebug, "From backend (#%lu)> %d\n", (unsigned long) bytes, *result);
+ traceLog_fprintf(conn, LEVEL2, "From backend (#%lu)> %d\n", (unsigned long) bytes, *result);
return 0;
}
@@ -328,8 +501,7 @@ pqPutInt(int value, size_t bytes, PGconn *conn)
return EOF;
}
- if (conn->Pfdebug)
- fprintf(conn->Pfdebug, "To backend (%lu#)> %d\n", (unsigned long) bytes, value);
+ traceLog_fprintf(conn, LEVEL2, "To backend (%lu#)> %d\n", (unsigned long) bytes, value);
return 0;
}
@@ -548,9 +720,8 @@ pqPutMsgStart(char msg_type, bool force_len, PGconn *conn)
conn->outMsgEnd = endPos;
/* length word, if needed, will be filled in by pqPutMsgEnd */
- if (conn->Pfdebug)
- fprintf(conn->Pfdebug, "To backend> Msg %c\n",
- msg_type ? msg_type : ' ');
+ traceLog_fprintf(conn, LEVEL2, "To backend> Msg %c\n",
+ msg_type ? msg_type : ' ');
return 0;
}
@@ -586,9 +757,8 @@ pqPutMsgBytes(const void *buf, size_t len, PGconn *conn)
int
pqPutMsgEnd(PGconn *conn)
{
- if (conn->Pfdebug)
- fprintf(conn->Pfdebug, "To backend> Msg complete, length %u\n",
- conn->outMsgEnd - conn->outCount);
+ traceLog_fprintf(conn, LEVEL2, "To backend> Msg complete, length %u\n",
+ conn->outMsgEnd - conn->outCount);
/* Fill in length word if needed */
if (conn->outMsgStart >= 0)
@@ -677,9 +847,15 @@ pqReadData(PGconn *conn)
}
/* OK, try to read some data */
+
retry3:
+ traceLog_fprintf(conn, LEVEL1, "Start receiving message from backend:");
+
nread = pqsecure_read(conn, conn->inBuffer + conn->inEnd,
conn->inBufSize - conn->inEnd);
+
+ traceLog_fprintf(conn, LEVEL1, "End receiving message from backend:");
+
if (nread < 0)
{
if (SOCK_ERRNO == EINTR)
@@ -767,9 +943,14 @@ retry3:
* Still not sure that it's EOF, because some data could have just
* arrived.
*/
+
+ traceLog_fprintf(conn, LEVEL1, "Start receiving message from backend:");
retry4:
nread = pqsecure_read(conn, conn->inBuffer + conn->inEnd,
conn->inBufSize - conn->inEnd);
+
+ traceLog_fprintf(conn, LEVEL1, "End receiving message from backend:");
+
if (nread < 0)
{
if (SOCK_ERRNO == EINTR)
@@ -846,6 +1027,8 @@ pqSendSome(PGconn *conn, int len)
{
int sent;
+ traceLog_fprintf(conn, LEVEL1, "Start sending message to backend:");
+
#ifndef WIN32
sent = pqsecure_write(conn, ptr, len);
#else
@@ -858,6 +1041,8 @@ pqSendSome(PGconn *conn, int len)
sent = pqsecure_write(conn, ptr, Min(len, 65536));
#endif
+ traceLog_fprintf(conn, LEVEL1, "End sending message to backend:");
+
if (sent < 0)
{
/* Anything except EAGAIN/EWOULDBLOCK/EINTR is trouble */
@@ -963,6 +1148,9 @@ pqFlush(PGconn *conn)
if (conn->Pfdebug)
fflush(conn->Pfdebug);
+ if (conn->traceDebug)
+ fflush(conn->traceDebug);
+
if (conn->outCount > 0)
return pqSendSome(conn, conn->outCount);
diff --git a/src/interfaces/libpq/libpq-fe.h b/src/interfaces/libpq/libpq-fe.h
index 3f13ddf..aa3d56a 100644
--- a/src/interfaces/libpq/libpq-fe.h
+++ b/src/interfaces/libpq/libpq-fe.h
@@ -134,6 +134,16 @@ typedef enum
PQPING_NO_ATTEMPT /* connection not attempted (bad params) */
} PGPing;
+/*
+ * libpq trce log level
+ */
+
+typedef enum
+{
+ LEVEL1, /* Time and process (by default) */
+ LEVEL2 /* Server and Client exchange messages */
+} PGTraceLogLevel;
+
/* PGconn encapsulates a connection to the backend.
* The contents of this struct are not supposed to be known to applications.
*/
diff --git a/src/interfaces/libpq/libpq-int.h b/src/interfaces/libpq/libpq-int.h
index 66fd317..1c8a749 100644
--- a/src/interfaces/libpq/libpq-int.h
+++ b/src/interfaces/libpq/libpq-int.h
@@ -500,6 +500,13 @@ struct pg_conn
/* Buffer for receiving various parts of messages */
PQExpBufferData workBuffer; /* expansible string */
+
+ char *logdir; /* Trace log directory to save log */
+ char *logsize_str; /* Trace log maximum size (string) */
+ char *logminlevel_str; /* Trace log level (string)*/
+ int logsize; /* Trace log maximum size */
+ PGTraceLogLevel logminlevel; /* Trace log level( "level1"(default) or "level2") */
+ FILE *traceDebug; /* Trace log file to write trace info */
};
/* PGcancel stores all data necessary to cancel a connection. A copy of this
@@ -666,6 +673,10 @@ extern void pq_reset_sigpipe(sigset_t *osigset, bool sigpipe_pending,
bool got_epipe);
#endif
+/* libpq trace log */
+extern void initTraceLog(PGconn *conn);
+extern void traceLog_fprintf(PGconn *conn, PGTraceLogLevel loglevel, const char *fmt,...) pg_attribute_printf(3, 4);
+
/* === SSL === */
/*
Hi,
I have developed a new libpq trace logging aimed at checking which side (server or client) is causing the performance issue.
The new libpq trace log can do the following things;
- Setting whether to get log or not by using connection strings or environment variables. It means that application source code changes is not needed to get the log.
- Getting time when receive and send process start/end. Functions too.
- Setting log level; When level1(default) is set, it outputs the time in the function and connection time. When level2 is set, it outputs information on the protocol message being exchanged, in addition to level1 information.
I updated patch, but I am not sure if these changes and implementation are correct or not. So I need your comment and advice.
I would appreciate your advice and develop/fix my patch further.
Regards,
Aya Iwata
Hi Iwata-san,
I used your patch for my private work, so I write my opinion and four feedback below.
On Fri, Jan 18, 2019 at 8:19 AM, Iwata, Aya wrote:
- Setting whether to get log or not by using connection strings or environment
variables. It means that application source code changes is not needed to get
the log.
- Getting time when receive and send process start/end. Functions too.
This merit was very helpful for my use, so I want your proposal function in postgres.
The followings are feedback from me.
1)
It would be better making the log format the same as the server log format, I think.
Your log format:
2019/01/22 04:15:25.496 ...
Server log format:
2019-01-22 04:15:25.496 UTC ...
There are two differences:
One is separator character of date, "/" and "-".
The another is standard time information.
2)
It was difficult for me to understand the first line message in the log file.
"Max log size is 10B, log min level is LEVEL1"
Does this mean as follows?
"The maximum size of this file is 10 Bytes, the parameter 'log min level' is set to LEVEL 1."
3)
Under the circumstance that the environment variables "PGLOGDIR" and "PGLOGSIZE" are set correctly,
the log file will also be created when the user connect the server with "psql".
Does this follow the specification you have thought?
Is there any option to unset only in that session when you want to connect with "psql"?
4)
Your patch affects the behavior of PQtrace().
The log of the existing PQtrace() is as follows:
From backend> "id"
From backend (#4)> 16387
From backend (#2)> 1
From backend (#4)> 23
...
Your patch makes PQtrace() including the following log in addition to the above.
To backend> Msg complete, length 27
Start sending message to backend:End sending message to backend:PQsendQuery end :PQgetResult start :Start receiving message from backend:End receiving message from backend:From backend> T
...
For your information.
Best regards,
---------------------
Ryohei Nagaura
Hi,
On 2018-11-28 23:20:03 +0100, Peter Eisentraut wrote:
This does not excite me. It seems mostly redundant with using tcpdump.
I think the one counter-argument to this is that using tcpdump in
real-world scenarios has become quite hard, due to encryption. Even with
access to the private key you cannot decrypt the stream. Wonder if the
solution to that would be an option to write out the decrypted data into
a .pcap or such.
Greetings,
Andres Freund
On Thu, Feb 14, 2019 at 10:17 AM Andres Freund <andres@anarazel.de> wrote:
On 2018-11-28 23:20:03 +0100, Peter Eisentraut wrote:
This does not excite me. It seems mostly redundant with using tcpdump.
I think the one counter-argument to this is that using tcpdump in
real-world scenarios has become quite hard, due to encryption.
+1. Another difficulty is having the OS permissions to do the raw
packet dumps in the first place.
--Jacob
On February 14, 2019 6:16 PM +0000, Andres Freund wrote:
Hi,
On 2018-11-28 23:20:03 +0100, Peter Eisentraut wrote:
This does not excite me. It seems mostly redundant with using tcpdump.
I think the one counter-argument to this is that using tcpdump in real-world
scenarios has become quite hard, due to encryption. Even with access to the
private key you cannot decrypt the stream. Wonder if the solution to that
would be an option to write out the decrypted data into a .pcap or such.
I agree that network debug trace logs would be useful for users not knowledgeable
of postgres internals, so I understand the value of the feature,
as long as only necessary/digestible information is outputted.
I'll also check the patch later.
For Andres, I haven't looked into tcpdump yet, but I'd like to ask whether
or not the decrypted output to .pcap (if implemented) may be useful to
application users. What could be the limitations?
Could you explain a bit further on the idea?
Regards,
Kirk Jamison
Hi,
On 2019-02-18 02:23:12 +0000, Jamison, Kirk wrote:
For Andres, I haven't looked into tcpdump yet, but I'd like to ask whether
or not the decrypted output to .pcap (if implemented) may be useful to
application users. What could be the limitations?
Could you explain a bit further on the idea?
Well, wireshark (and also tcpdump in a less comfortable manner) has a
dissector for the postgresql protocol. That allows to dig into various
parts. See e.g. the attached as an example of what you can see as the
response to a SELECT 1;
Right now that's not usable if the connection is via TLS, as pretty much
all encrypted connection use some form of forward secrecy, so even if
you had access the the private key, we'd not be able to parse it into an
unencrypted manner.
Greetings,
Andres Freund
Attachments:
wireshark.pngimage/pngDownload
�PNG
IHDR � � ,2q� pHYs 9�R
tIME�#/�(�� tEXtComment Created with GIMPW� IDATx���wX�����F;���*J�P�wc "�����f���D�1�M1�c5��{o(b���q�+�����5�#H9�h������������������p$ ���. x�!� ��C� ���O�777����}��{��Z��_;��:u��{�������_n<�u�<o���V�����&������o�W�K�.�n�z��^��� �uj<�f^��[�����/_�����'���p&�K�.��M#�dff��s���\�dI�#�O�n���J�3fL�>}��p�����;::��������Mj���*?v��������m;f��7n4��9s���,�w�}gnn��Nw��6l����������\�B��}{���Z���������io���V����}��W� ���?���k��z�{�nB���]\\Z����+��'���3G�������<77k �:��]�jU���v�jdd4e���q6����@
�l�������k����w��iZ{d��]|>?,,����_��-[���93"""&&&!!a����.]***j�����n��}���7�|s����E-����s�����p�-���:22�O�> ����?>����*�G`�o�:�x<��hcc�c�����c_�'`HH��7�q[\\,��<x�}����>�lllj~�a�F�����s� �Q:�~�|���8N}�����788���u��Q���z�
���
���c��u��������>���.:q�D�R����������{�!C�TUU]�z�}[QQq�����(���v�m�!f?
|��7�����w�����J��_~�d��i��9;;o������RUU5w��v��y{{/Y���)U�R��W_-^�����rpp������� !G�
urr���������O�<quu]�bE��������[G��g��C�V�Z���;w�\B����v��E�/^L��y����g���a�� ������+W����B�`��������%��X�������),,������?~���k�o{��y���%K��������E�!EEES�N���������_�z����%%%�g�655533���������-Zt��U__��������0��@�L6u�Tww�>}�TVV��??77w�� ���[�n��^nAA���S������g��MIII<x���[�6m�~��&5G{'�|p��F�o���y���_}��i�{����gtt����[����]\\f���R���.\sqq8p`\\{���{��U������[X�R�m�V[���������P�f���B���G�~�zhhh��o������H���g��1���#Gv������*�����������|���d2Y�����?d�77����.��?�����}�?����]�5k����{xxL�<�������j��4������^�b���w�����+�J�� h��*�t������o�=y�d��A�'Of���feeM�>��~HII���x6��u�V�P��];�k
�������;��tss�5���F��������d2Yll,�0�������W�����H$���z��~��7n�8{����'�\l�*/--��t-!���BLLL6l������_-_�\�tpyy9��9{�������]{���1c��9r���qqq
/�|��������������H��c��F�%N�8Q��L�<9::z������.{��������f�z����ry������5{ !�=���<x�_|������t��ccc��&M�dkk����[�?~�I���������;��;wN"���������=z������:���a�y�f�\������������\����a��mqqq'N��df�������o�NJJz��7 !�/<xpZZ��G��z���N��/]�4e���/���o���T*e��������w���w���}�!���'N����RSS###���M����8q����O�<��o��=z�������G����6���^�v�r������k��S~k9z�����z��=�+V��q���sqqq���K�.�Y���$<<|������?����i���� !o�����k��
�<�����]�{��6��@�������+��=~����W��� ��tJ���?������c������q���3����\�����������z6�������Q�!����g���y<����ojj���?~�����L���;�)��6������������]��������G���������v:*))
�fff����Hv��S�!{�������������k��&5���T(���?�Q�����kGQT���G�����*jii9v�X6 �#��={B8N�G�B�8p�@DD��9rd�5� !������b�����666\.w�� ����&4(+++99��k��Q�Fi'����M�8���������G�����d�GG��3g<x�I�-N�:emm�`�//�������&����|~QQQJJ
����������/_.�A�������������]���]���m�����u���]��g������kgggee5|������w}HH�����|��i��b�v����3�|>�����[8**j�������v�7n\S[��z�_���{w�[��k3f���;�7m����_���.\����9p����xx8��
������� !<���R�T,w���9]�={���1������p����N��J�
��v�5�Lj>����+�����|>���5kV�A @�i/�O?��M�6�wiVV��7jf�
��i���2d��e���|>���������\y<v�����[7�#G�t��=66�]yU�F���^�z577744���&:::..��,Q,,,�JeYY������T*��!C
�L&+//wvvfK�������Q�D"y6�{���o��&%%�a�T:u�T��P(�D�kv����lmm[p$?~���A�B"##�ZXX�N����`�p�\>�_UU%�����n����|.�[PP�]��%���w������������g��4=m��~���?�=m�Z���Y]]�������q��������w�y��w�9t����_��'���O�4���j�����y}?/���qpp`W�����o������{[YY}��������k���...�O��Fkk��F;�����w�v����`hh����777�t��#�a��5�E!!!k���J�yyy���NNN��O�J�<�s��v�������Y�f��a�JUs�������o�?V �TUU�l��}���-���gy�<�T�n���
�yyy
�mK�������2���h_�$5G �H��/;���2������3g�l���
dggw��m�����Z_��f�Y=n���;wfee�����
��kThh�������~�m��[�����K�������������'O&��9Z6/bdd$�����|gff&���|||���8Ps�V�a8��)S>�����H.�����R*��kzz:�V�i7�,--����.%�R#a��
�B���F���gO}��fdd|��G�����!�[�n������2eJ�^�x<^pp0{����������o��mbb�������4i���*����*
?����>��������~~~�F������cnn�R��93���~����\�t)22�w��MZY�;]�t�����}���>|���B���������g��vqq>|���aS[��kW�\�q���� �cdd����q�FKKK�g�kG����������;v�X__���m���������{�*����W��=;&&�y\);;;�����B�Rioo�h�6�Lj>�������v��� �k��~�L����?��s�a����C�=;��Q�FQ!d���.\HOO'�8p��)�&KKK�J��<5���c�\��a��gW{n�Q�
����...����.]�����Op��B��_~��_l��1''�������eeelb)""b����L�~���s��B��������M�6������9r��> �TTTx{{s�����c����P��e��)����������[[[?y�D[���������������m�H(,,�p���m������>�9�����
CC��m�B��=����l�.]�� W�{<�{�������\N��������E�*++i�NNN��������o��&99Y�P���o���MbY[[gff�T*� ?���
�+W�<~��av��g/���;t���'�TVVVWW_�~�r�����"�cmmMQT��[�No��<y�u�V�F�o�����~���b�������O�V��6l�J��{�n�.>q����;�X���Y�t��v�Zv�lBHpp���ku��?e��O?�4''�����]��5j�����}���T*�Ry�����,�\~��!�\�.��^��q�"""�������\��_8P,7����Lt�+��5k���$���_�>� P�K����g���������KPP����k�������k())qqq����&L�0|�������;�������~��gOWW�����Fttt
����s������fff��566����&u7y���k����3 �m�����[�h���C !K�,������o���g������x��_�u��m�;w������������?}���#G.^������&&&:t���=z��y���{'L�p��]77����B�-[�y��~��}���|#a��]���0`���f�����R���:u������gDD��+W�������JHH�f��n��&����������;��e������]������3��HXw&&&999c��qss4h����/��B sss�����������������...���C�e����s�,Y����a�mI��u����R??�����3M�]���GWW���'�^�Z�Z������~��]�~���}���[�l��r�,gg�-[�,^��M�6;v���k���q�dkk��[7�Z��G�ZTT����{����:W{�e���!!!��
srr1bDbbb�Omll����y�f//��;~�����a�
6t�����}���� yW���_�>}����;v�(��W�^�K�>�3���XC����K���?��C�� h�D"A/��'O���SsI�W���{���3g��Z��7o>u���m��S�s��577���/��//oo�]�v��� =����S(�����I���������K� �g5��577�u�9�~6����@��T�h�sx��k=g~����������c���g�Y��Z��;+7���
_���z�s}� @���3 �K�B ��xyyy� ������ �R��4�^ x�a�_ ��R� /=�0� ��)>>^*�����`�fff����0. ��#��� �P|||UU���+E��
4Mgdd�D��;��� �<t @�$�J=<<8�Z�n�j�\���kjjjk� ��b�_��KKK���
�B�����z�������a�L&�J+**�j�J�R�T^^^b��I�(������������bB����������������K�'nX_YU�KI_0b�(G��fhA
�����|�k� g��l?���Q���WB�F���x
,���� @s��^�
�����)))���������E�?������cbb�=88�E:B�V�����|CCC�HdllLQ��G����u�%��<xobbbmmmgg����0Lii�D"IKK���������O�����TVU��[�5��0J�TkH��q4������jI5�a���-�U�:>r������v���HLJ:s���+W���MMM���zs�xW<�j�r�������������{����r�S��;�bn\�h4z|����t����_��q����4M�:NQT���A!M�0|��fv����k���������{���v|����=[��������� ��f�����~��ajjj�������������|��_���C>��h%>>>���U(������F���WXXhkk(
+++
,--������t�9I$���h�3l��Z������yyy���YYY������/�(�2��Tk����.F}��ly���&�Vs8�j�kkdRm���/����_������h �0k��v�����.�j���QEEeLl�����������s8�����V�*|���S�99:�o�}����������2YC�7���s���7�X[��qnEE�;vn�#�{���9��566�u���j������x�x3���T��/*nM4M��w���+�����D��Q���~�-5_��.��?~����w ^z�~�j5�����;vlB�r���{����J/7�A=L333G��KU<����I'`kk��e�k&}���JKK������***������JKK���u�-99����;v�����������KIIIII!�xzzzzz���:;;�5���['O�������W��feeyyy��u'�����),M������
�p_�6�-����"4E.�!L��aoG�.���r��r��C3�"�rM��|:v�R���F�GZXX��GKJ����h�i-^�MvN������s���TUU-^���qcG�>��Ek�����-x���r����HJG�744z~O�\v��~ss?_{{�������k;��������A�#f��r����������S��t����������i�
��^�u|I��g��p:���������2y�>�~\����J+���/�f������}jgk���x5B ��> B�Ju��ySS�1c��U�e�f�M,g���L� ���d777�@�c����k�9�=����9-�h4�=244
����q�F^^��S���|KKK��J$���o8���I�Rm��m���5�L�������(*<<|���������g������o�o���������W3FB�����J5�d:�~�����@d������)F�al��!�>�|B�y�B�P\5Mh�0*�Xz7����������{#����tl��
q����k��n]x��Q�7o=HHX����}8�����u�--,������/�r����t���[�a��kWRSu71]����O�����v����������mCC��:}9���{��j4�H���w�*��*�S%�Q�V���8|�`Hp�������K�������^��L��������������������5�������|<�Kg��g���������m���o�������_�F$2���`Fl�RlH�s�70Tn��M�UI�t������{��C ��&���T*��;���t�\��#�2����!|�Ow��o����;�9�E�V?z�������#--->>^�Vk?�(���111����Y4MGGGw�����)++k����4��cG33�3g��x<�GQ����ccc.\�����C����!C�4�����QP��]"�)�Qf��1��8c#���&���6R*.��G9���b��B;q��y�*F�P*�p�-5O*�i�6���Mz�-�"i��y����)�:C����q���Y�[��B�
B�;O�%���%ee���Z[� �H�V4<N6m�<q���G���h3��9�>555�0.�������7�v���'O���'�e``���y����z'����������}��G�:ph���C
u�����sf�+�#EQ���
������w'�i����/!� IDATq�l�k���������z�����R���
�E9u��G���������[��f_�������b��4{����x�7={�Nysb�x�)oN����h��_�I�
�_��������*��Am�*wn�M����lf������ ��4m��\.?{�l�N��zv�����Gl��a��/�������� ((���Y�R%&&:99���EGG?������@ (//www���p8�n���T*6���hd2�P(����G)((����:u*����o_zz���~�j����������6y��j5�a���=!�����������aSG���d�*�V�}�����!C.�Cq!B�P� ;#�0B1��0���O����f���{s��~�|�8�����n���E������^!�Iok��E��~!�V�%����DJf�vL8rUzR=��5�u�i�AB�w�.������:���������r��$Mk)(,8q�X��>!!�/dmx"�9�������z7U��x�u��z��>�Z��]{v������4mll����
�Q���&��6g���{��9�{p���u�f~A���3�e����Sgn���������`1�&��{��
����������
���g��1���q����Z*D-�?!DV�Qk��gSCm�^rC�=�����j
� �+� �_�Ry����� 77�/~~|7�B��e�0��7G#�D"
k��k=�juBB������������cX,WUU��t�P�P<x����^�r���mc������G�f���������
���� �����o�4iRHH���������u1�Q��u�V������I��;!�_)>��Q�a���pEq45���(�F�����4��P�������bC����i��NKO�6k����67kC��H���~zz�����+�s�A�nb����44��h�lk��V4n��;cy\E1�iE����M���\���k}eD&&B�@�P���M}����C�t4^?#��!$�&N�T�����o~���s}� k��s�����zv��(N�*.��av���e1c�9889v�O���nmt?
�j��������������w;�T��%���KNNJH|����G�W^��M��>w��M�"S/�v-����i:zQ>\p��qw.���;v�?vL�G����B����.\�/iZg����u�`�\�&�(�57
��*7
�*
[�V���i�; <WMH���y�����G�%�<�/���}��a<\�
�X,n�
NOO777���������oMb�X�T��hmII������]VV����������e������������9�V�������(�JHH���E����o�����&&&%%%���Mj�RE�K�wWT�i�n�~��!�SYU���of&�r������������D"�P(�V�D"333����M�P����4���og��aZz�[3�|���v^m�\���G������vrt���e�f��B(�5�pTC3#{z-��0%������833������U*]���(��������w���;f\)7����)�Os����9���h�u~K.���a}�������5�����O�\���-jZI�������q��EF��w`O�T���Y�&����W���[��s��[� Cn�}Qrss�D_�;�F��+�[��W����v��;vm311qpp��f�B}�J�����R(R�l�(�
��6�ib"273
���-����N��B�B������6Z�g���2����?����J]�����������*5-�Q���:��������ZM��T�� �B������UVV��_��[2��������%q��t�@ ��6lR���R�L��S������RKKKCCC###CCC�D���t�\ccc��y<�:���������h4���
[��M�V�^���gO�~�����?�p����D�����9;;[ZZ;884�����"C�s�r5Equ�@���5w��KK��Z^^�����_�������}���������"B���5�u�:OCdfd2�����YY>���_Wedd/�fe�D�`o5&�����b�����e�f�i�yff�K�M}\=Jnf+(cme%�&&%uhW�D��'O�-�ur�\������8a���cO~����s���I_�M���/�����h���h����9��p1��R�*�����O�0i��]U�������B��u)�!��?
**+N�>>�������+�s��<^i��1���G��=Vd"j��8r����S��]yL�������6�|���Qn��.j'))���C��/�@���}!q�+*�"S�u��i��CI��)��%=O���Qs��Z��b ����B>��mI����\�W�i��\w x�tJ�T��w�<8�����
];�K��[6��+�6�&++���������������w���U��t�P+�H���!)))l_m��e��������/���s'N�x�������^�|999y��ab��������P\#c3�S�J������ ��d2�H����B���j[PP����\�c��2Y���Oaa�LV�V��\=����������w��dfe�3w�Z�)�H�lm���G�)��E����VU?�V��o��G��l ��i�� ���Qs~A~Jr���3Nd|w1������o�Fk��OWW������\�&���?���{���5>u[���'c������^��S�#����'��l�kc���.
!=|A�����'��~}��mRG �|k'G�����(�������B\M}?<,)-),,�������l�f��mtM�o2D��b���i��C/�>^�����T$j��j�
d����1r&�4�{B�9T=������JS�@HPO�{ ��S����;���"���o����2�����4�T�44M���V����L[[[CC�3g�X[[����L���r�k��9��)���ooo�w�W�V���[YY9r���W�\y����.�i�����URRRS���8F�Sc��Z��8G��!�P�S�T�nn���
�j5M�4����u��>77O*-����p��M�%�!||�:��O�X���G����a�R�B���i��{3���M}�01��ncF������CG�G��}=JJ^�h�5_�~�G�����s�������[��i��ZN������G�k�����h�~Mc>Sn�������������7l������K�/XZXv������+����EEu��q�>
<���w����}�7��:w�z�������[�|"mhI���=U*U���aa�n���|��)���%���~�j���F�Pr�c{;��"D�e�C��'w���33��W�P�s������U�j���! �WN���������q��m=���)#�i��i�!�0M�C��4�T�h�a�jukk�R��H$���KJJ��������5�)�lmm?~L�4���oL??��+W6����y�n��a������r8"����w���5\G��4�����cE�L,������D"C??/�Tjff�T����j�����uF��R�
�N$
66�"Q�C��BH�.�ll��lEU�f�����O���-5�LE�V~;��ws���"#,-,����%[���v���_~
�z���hx<�(�]�Y;��E4Z�����a���)������OF��g3��MZ��5�����fG:m����W�q�c�kEVvf~~��IS�=Y���f}���<�d���s7��gVv�����!��\���O�<6����{"�Sg�6�.C����1;;�&��_��w��%r�h�������f�Z�}��E�,l�������f&|B�Z ����MNN����r;���T���:����4���y8�Q�5�F�T���~
����\.;�������Y�)M�����0�����i�V�T�TnaaQRR����������P(�^�=��][�p�^�!���<��(OOOBHqq���E�����C#e,���:#�!��{���P�������:yUT�JK�MM
rr
��
����d�%������ �F��x�?����G����wr���tNn��Y�/������f�����t;�����#�l��+�
y����h������u����5u����"����*=3��Z%���� =w����3�8�u��5?�����4����g=���q2���������p��]����W���
#]����n3�7T���Z�Mm��;����������
�3�/<=������w��rrtn�E��{����o������k��T�Z�����~�}�NIiI���/}�/������lf�����K���ddl�f��wg���5qv������>�����QK+����o��w�{`�= �
hd��Z��������t���D�0�fhZ�n��4��N�dC�R��@�T��F�4]ZZ���[]]Mqww4M'&&v��A�PTUUi����_�.[XX���B<==��;���=q�����9s���1c��������4h!���?������r���!R����i���8���1���5����3a!
�"/�H&�*((�LSS3<=]�B~yy�R�������eeR''{1��j�OC~�����|K���J.W����Y��|�����������c1���
���Z����>�G��fN�[h�g����{o������U|������>x�p�����F~���M�������e��m����=����Y�t���ot+^m�������2�a��]�\�]�b`@p`@�J�����]�]
�D�}lo����[/�?w1���v�WO��s��B�Vf�dO���.�-�����y�2�:,58�f�d������<h����mlFL�]���1��B�8����+
U�7cF�G6i/������_H\BEQ+�-���{7o}c�8��h��y��'���5��� ��E���Qk`��}����?� �5k$�������
��LR�4�&����OW�eB�L�������hU�,**233���O�������������*�������kgff&�HD"�� lKKK�Z___.�K�tVV��
F�5c�����s��UWW���S.����SEQ���/!����������(b(��/�l(���q�Bh�F-
�b1��
4M�r�@`�0���r�&&&UU�\.!DM�<q�i�R�i����Bg'�CME�Y�&m��33+g��S'�kN��C��8� �@��L�{Q5[�Rkv��H+���&m�W����D>�:i�*�
B�0�N����O��M��W�>�7ol��i��qvA��xGV-%�������{��/��r]F EQr�|����
{�fo�2Z�B��YAk
�7o����>���y&cc���(��J�:z�hIi���gN����6d���W��?SUUI���Y�n��������u���rMLDfb�aC��Hd"4`������N�l�t��O��������������LD�#�xg�L��v��oW���� �"����E��������/�qs{����������+*&O��� �H�7---88��Dy�fM�u�{�����vV��*���o-� ����i�F&�����G����W��������4MK$WWW�F��h��gaaQYY�������g�###;;;B������[������/wrr�J�E���;;;geeUVV�7�W��������(�g���cckk3��j��%7������@XY���x<����F���p02�a��/M�+d?��kAa������},��dC8�������~�(+;g��}aa������/��u��k{.�?L���lY.���%�9�5����BM�����&k��&-=C�V+���+��m�FN6`~*0 H,o��e��Q_�?�:zfZ�}B���n��_��)������h��~]����FS��W�H�7�A�"�w+�wz�&/e�������g;��El*NJJ������ncc3����fu-��}����}-M��3�b�4�T*gN���X��=Bz������S�+3O=��2���0�I��n�������u����:Z�����;��)���������s���G�VTV��v���;~�>k�����B����v�$���7}�C`�g `5���\.W(������i4����5�{XL177/..fs��[��"�T���j���$�A�TJ������-((��d��������DRRRB122���455m�~�P��c�����5***������j�z���]�t���ommm�l�bddt��Y�SRR���������V�cbb����BaS��%����&�[�K�y�_����Z(�h4*s##"��
�@@�����G��&M���������\g'����X[��I�!����7u������?Y�m�Z�BB����0+��KH�$�I~��X[�����I]�:;4�zon=s�[/_V���;yr�`}���lgld|������E����]|��6�����sf���3����O7o��!t6����{���wn���3��`{{�&�I��C�|E�5\=V�~�'�MZd���m=���=�vM��:��uB�����[:������!^�w��'�T��U
�\�Q�i>�2r�
�"C^HG�q}��ZxY�=w?��A3�B�����t������q�O�='�Hh�f����7k�%
������� �
�����uvv�p8NgFS_������D�Pj������o���t)�JOO�LMM���022
+..V��666E���G���r�Zmbb�K��������}������/\���o�MOO�v���+Wx<^AA�_|���SSS���)�rww_�p�@ �z�*!�c���%�p�KQ��S!�����V��)}�Z\ffv`�wU�:--�_�n����aa~��O�<��������3Y�!�6���:�_!�'&��
QT(�3���S�Vz�`[�,��m~���������v���t�h[��Y^n�o+����:*r���{�J�B��e��>�z�Q���S��cN�9���>���]>����L����LD9g���*������2I��c�X�����/��������K7�B���u�{�&�������G�.��G��
���5�(U�JSVYM�2�O�W�������kWO��������n���C8�&N@ �Oi$������Q���.[w����js7��������������������J{P�V��q#((�������=X]]}��-�Xii���ivv�.!(�
:{���������U��o���~�F���i�����(���
���������������������n-4��f�~iB���,CG&S��{x8WV���qMNNU*�m=�
�jU�6�yy�2Y�Z]���B7�tB8K������T��������������CW/x+����}����_�~�s�����hia3Z��7�G8|��[Z�R����w������D4jD��+7��gHH���|��������y��������mm�F�o�L���>�����6m�^��&��?���^��^�yH'�Y�Q�kO��p����������� ���� v=?�N���^�v��9�h����n<p����!D�|�� �J���������VB��to�%��Eg/��M���IM[[���G7��mmm�j�.%�r���iiii��%%%�O������EI�����L�~�����C����at�{��������������4iR��}������SRR!���^^^������j���������������]9
���P4�?�[��4�n�M�!�
�j���B�����WJ�U�&WZ,�������ER���ZDC��0ML��!�"
?x���/�+�J�����N����_B�����_Vv��{wTj����=���z��������0g'��il������3�i���{�N������[�U������
/�L�$�} IDAT��P1o]l�B���r8������@w;yf�ey�(nf���ill��]=}��eR)M���162���h��� �j�w�_�J��h����i�[�&w����/�� ��>�occ��������(
KK�&��Z�V(��
5
M�"�������������������~���MLL$�����m�ZYY������;;;;;;6�V�������a���off���um�I��Lq����*%�0���K�|���M��61166�[Zt�*��P����X�'p�\!t}��U
���2����e��'��l=2�����9:9:;9:���5L(�>rt�5���F�(J�T��Z��3��(=�r���IoL���ghQQ��[��:7���Dk�����7�U*���q)�1���AvF:?X��u��S\k��kV/������/>��������j�h�' ����-++cWB=�u������M���]R������y2������������V����>1���l��� 'O�411�����l7I�R�DRYY���������h;;����g�[�0A.��j������X�B����Q�p�
�B"$���L
���B ���
!B�<�i����!��@M����?�����~����5~� ������u��t�OP��sW=*�������
�����
��h1]�F�
y��(�{�$-���q����d���z������/�lmm6������V��9��KV�qB��sg�L xp�Ri����^�~���5�2�0B����^{���J�iii�����u�����R(��������]k��������Xl�� ����[6V���������'�wB@s����^������t\���O��7o8�U� ���7� /R� �;v� h��b1M�\.W�u����ri����=�_T\ h� �u233KOOwss��Z�YM�tzz���Yk� ��)++C/ �NIIIR��eW���fff^^^�0. �
�_ ���� x�Q� ��/&&� �R�TWW� ^j<��� /5�� ���1�^ x�a�/ �K�W�MEE��c��/ ����@GGGooo�@��x�82�L�f���������kR,X�b� �?%&&���sNNN�������~=zT3�����|��f�!�0�0�`a8�_t @+��[q�^~�RS�8��#�0���k������!����EM��`�\�����~sK���i��
�hhFC��"z
��8s�v��a���N�<E��C����G�)�����AO��xg�����0������u��a�=z�x���G��=����7q�D��K����w����������=��W�z�Jm xYT)�?���L_���-#�R�}�R�k�3������~v��v�6o����3o�<>��:[���c``�/���urr�>}:!$--��X�jUDD���Sk�"�Lv�����$�\nf���w\S���a�
���l"nq��m�\��V}����j[W����q��SAP���lI���j^
�B���~���]9���p��quu�����������i��Q�
Q� N�A�1�,5x��19Ee��A_��x��`��Y���_�p�[����l{{����Z=z4!$""B��3�R
g��4b_ZZJ�k���t�����T������RkkkE@$��l��P >��k�.MM��c������{7//����!<W~��U]]���aee�����B� ����u0�$����������b���Zq���/���i��-��+..~[i5f�--�����3=�+�����D333kk�������u�����<y���-,,����\nqq���[�������|������������omm��sg�����{wggg�/_����*((�p8����r��g����;w������C�Q��3��?~�xFFEQ����&M��x��V|�H$���233�B�����A�ttt�������p�B�C��K�f��%>+22��������������u�V��O�:UVVv��.�������w�����B--�~���o��NI??������s�*�(������=x� 44������{|>��qt�
@QT�@ZYYm���^�������N�������III7o����������C[ �B�����@k+C5���8�a��-�UO�����������;����������)�
� �AD�����q�F�-��j����������^�Z�OoV8e]��Y�MHH�������u�Vyy���&�=++k���,+"""::�G������5}������[�������B<<<�]�F��z�����^l{��aiiYUU�������]�J�������;���::::77�^hccc���,X��p�����[i������a�X,����O�<9~�xSSSMM�'O�888B���$?($$�����������tNMM��\UU�g����`gg������9�N�g��M�:U�����LLL������nnn��O��c322�U�U/����555uuu�f��(*))I����������������}������������2e ��'pRir�W�������3����F300��?x������!\.w��������p8����d����--��/N�6-&&��������O?�p�Byyy�N���]��������G���{7,,,<<�����W���������a���Mee��Y�._�,�lllN�>����r��;vTUUn���S�N�g�����|��a��-[����w���o����B���������JJJ���6o�����3fL�o8���L�)J(��"J��q������b���D�.???��f�;u�$9FH��USSsss�7vhoo_ZZ���BHbb���K��HCCC�����������z�INN������e����u��x
�Yee���/ !fff��K-}���������R�=����N����&--���os=x���������f[ZZ��������:u���r[�fryy����7l����?`��y�����S<
���J<f�$z��!<� ++K�����Ypp���;w�����n��c�� �B�� r�'s�(J��u��"�LPw7�//QRR��}���[�����������z�j������722�w����={�������k���7^�|y���qqqaaaW�\Y�l�������0q�D��v��]SS�������~�z%%������w��u+77��������8r����>��������������s���{��edd���?�K1`Z�Y$�g�s||������!�c�� �i��F�Eyy��p���X
���|��q8WW�����={&%%
>���UTT�;w.;;[(
]]�z����7��lmm�zxzz���<x���{xx����~�n��}�2���/�������X,>�O�+wss�r�Jmm��G�,,,Z�JxiiiNN�x�;��755���-QWW���MMMCC�z�jjj�b-
��k8g766�����KK�)S�<}������Dp8###��������;� ���z&'E(B�V���r��'�����^�J�G����/������po�=�:}�4����-**��f���}����k��A�������5g��9���K�B<==�w�N�}����pwwwB��Y���]�����r?~��cG�9����:11�[�n��������Kc8p <<�^r��~�����W������p: AAA���c��Ul~1$������|_�d_Y����
�@ x���P(\�f
!D(VWW����c�%%%�XzII�xF�@ �����2%��������?��]:K$]�pAYYy�����}LLL�455����o+++�'���g��={���������EZhi�������~����zyy��o
444���=z������)GJ��jii����=��0����}��g��?�����qc�v�����Z[[����>}�HN��(��b���F������%~���&�Rwuu���JJJ:v�8a�ccc4� ��("����SB�o)�]!���n��:�(�N���b�#��0��������W�\I��*���>|������_I,��kll���'~-> +++&&f����-�|�I~~�� ������b�
''�~���o�MMM�����U��W&�����k�N|q����K���UUUm�<�w[��B�O�����S5k����������g�������{o��UYYY]]}��uWW�7�e]�tI ��������E��9����p����F___II�������
�������QRRBy��a���O�>-**�(JUU������hh�������N�7����~�����<'''9�C]]����~���������DOh~����W��O�q�FNN�:::����XYY���,X�������{k���G�}||������������_�|y������z��QZZ����:11��_~y��I�n�,X��_?�� ��x�fzN+E��D%�^�~=L��������N��I+I���������ahhHo|����]�F��x�b�Y���=�/�+9Phnn>���7���;w�����/_���x����G��+��?���+<���Z�j�d�LLL�����������fff�u1��05���^�r?����%$$�����������EEE������c��;wVUU9::��x<##�_���bu��]�8XI���.\5jT�]AAA��KNN��x���O�<�w�������8���jbb�0�^�zUYY���LO{��7Z���gFF�����!>����x�� ���E�n�N�>}���^�z���N�0���s�N�b�Xfffd>=..NUU���KW�z����������QRRB~+++O�<���K���������quu���d ��o�d�^�|��p��n���}���jjjh� Br���3}��@�"���}B�=�W!#��c�E ���j�>�?m�����j���AAA����i�����r��W�1b��*��S�N�5k������gEE����mff��}{]]]eee.����RRR�����������r���(j���+V���������_?---���HQTEE���+.\���WVV��O?5|�����+?7���M/���DctWKBHie���
����Wo����x�������������m2d��[mmm}}�������������1�������6�?������������������$c������r��������@|YB��������SS�I�&��������9s��?���F_3�|X�����A�
T��z�\�dI�$�$9��b``�� @�4T��U�A�����A_u��aDDDDD�����O��CC�3f�X�m������g���#DG���o������/\�������~����s�>}�TKK+ $$$33s���/^����3f������/^�������v����_J^d��999C������������_YY�a���S�������7�����_cu�����
��"�|��f��t�u[����s�����{Q�RRR�B�,sa?���H ��3�������*�|���u��.�Z)x?���O?�To���/~���,^{���[�Y�fI<i��z&�>|�p�-&L�0a��OO��������7�/X,��y����W�����k��Lcc���2����y��eajj�������}||n��-��:g�������y����fdd��������\�w�_����?l�0��&F��" Z�������[��[�nyyy5k]bY(��Vii��Mbb���W�-[����/����(= |�n��u���������������;v���m�
����?~\r
3 @����lll8�-�z��R ���F ��0� ���R�T x�a�/ �{�{��m� �{��b��
�5.!�W�^U�?~�����G��
�� ^Hy ��8s�LQQQ+]\___UU�g��"��BQEQ��HD��wB����� �w�x�Wr��(6�M�Y������' ��Pl/�<