Thread: enable logging of start time/cookie for all backend processes
The attached patch makes a very small but useful change to the behaviour
of log_line_prefix, by enabling the start time (%s) and cookie (%c)
logging to occur for all backends rather than just for session processes
(i.e. backends started for a client connection). We actually need almost
all of this patch, with or without the change in behaviour, so we can
put the cookie in CSVlogs (which I'm still working on), since the
cookie+line number make the natural primary key for the logs. The actual
change in behaviour from this patch comes from the removal of 2 "if
(MyProcPort)" lines in elog.c. Given that, can I sneak this in or should
I wait for 8.4 given we're long past feature freeze?
Most of this has been factored out (and cleaned up) from my previous
CSVlog patch, so it's not new. I did that so that what is left when I
finish will have a rather smaller footprint, as this part seemed fairly
seperable.
cheers
andrew
Index: doc/src/sgml/config.sgml
===================================================================
RCS file: /cvsroot/pgsql/doc/src/sgml/config.sgml,v
retrieving revision 1.133
diff -c -r1.133 config.sgml
*** doc/src/sgml/config.sgml 24 Jul 2007 04:54:08 -0000 1.133
--- doc/src/sgml/config.sgml 29 Jul 2007 18:14:12 -0000
***************
*** 2861,2867 ****
<row>
<entry><literal>%c</literal></entry>
<entry>Session ID: see below</entry>
! <entry>yes</entry>
</row>
<row>
<entry><literal>%l</literal></entry>
--- 2861,2867 ----
<row>
<entry><literal>%c</literal></entry>
<entry>Session ID: see below</entry>
! <entry>no</entry>
</row>
<row>
<entry><literal>%l</literal></entry>
***************
*** 2871,2877 ****
<row>
<entry><literal>%s</literal></entry>
<entry>Session start time stamp</entry>
! <entry>yes</entry>
</row>
<row>
<entry><literal>%x</literal></entry>
--- 2871,2877 ----
<row>
<entry><literal>%s</literal></entry>
<entry>Session start time stamp</entry>
! <entry>no</entry>
</row>
<row>
<entry><literal>%x</literal></entry>
Index: src/backend/postmaster/autovacuum.c
===================================================================
RCS file: /cvsroot/pgsql/src/backend/postmaster/autovacuum.c,v
retrieving revision 1.55
diff -c -r1.55 autovacuum.c
*** src/backend/postmaster/autovacuum.c 1 Jul 2007 18:30:54 -0000 1.55
--- src/backend/postmaster/autovacuum.c 29 Jul 2007 18:14:14 -0000
***************
*** 385,390 ****
--- 385,393 ----
/* reset MyProcPid */
MyProcPid = getpid();
+ /* record Start Time for logging */
+ MyStartTime = time(NULL);
+
/* Identify myself via ps */
init_ps_display("autovacuum launcher process", "", "", "");
***************
*** 1403,1408 ****
--- 1406,1414 ----
/* reset MyProcPid */
MyProcPid = getpid();
+ /* record Start Time for logging */
+ MyStartTime = time(NULL);
+
/* Identify myself via ps */
init_ps_display("autovacuum worker process", "", "", "");
Index: src/backend/postmaster/pgarch.c
===================================================================
RCS file: /cvsroot/pgsql/src/backend/postmaster/pgarch.c,v
retrieving revision 1.29
diff -c -r1.29 pgarch.c
*** src/backend/postmaster/pgarch.c 10 Feb 2007 14:58:54 -0000 1.29
--- src/backend/postmaster/pgarch.c 29 Jul 2007 18:14:15 -0000
***************
*** 223,228 ****
--- 223,230 ----
MyProcPid = getpid(); /* reset MyProcPid */
+ MyStartTime = time(NULL); /* record Start Time for logging */
+
/*
* If possible, make this process a group leader, so that the postmaster
* can signal any child processes too.
Index: src/backend/postmaster/pgstat.c
===================================================================
RCS file: /cvsroot/pgsql/src/backend/postmaster/pgstat.c,v
retrieving revision 1.161
diff -c -r1.161 pgstat.c
*** src/backend/postmaster/pgstat.c 8 Jul 2007 22:23:16 -0000 1.161
--- src/backend/postmaster/pgstat.c 29 Jul 2007 18:14:17 -0000
***************
*** 2168,2173 ****
--- 2168,2175 ----
MyProcPid = getpid(); /* reset MyProcPid */
+ MyStartTime = time(NULL); /* record Start Time for logging */
+
/*
* If possible, make this process a group leader, so that the postmaster
* can signal any child processes too. (pgstat probably never has
Index: src/backend/postmaster/postmaster.c
===================================================================
RCS file: /cvsroot/pgsql/src/backend/postmaster/postmaster.c,v
retrieving revision 1.535
diff -c -r1.535 postmaster.c
*** src/backend/postmaster/postmaster.c 24 Jul 2007 04:54:09 -0000 1.535
--- src/backend/postmaster/postmaster.c 29 Jul 2007 18:14:19 -0000
***************
*** 386,391 ****
--- 386,393 ----
MyProcPid = PostmasterPid = getpid();
+ MyStartTime = time(NULL);
+
IsPostmasterEnvironment = true;
/*
***************
*** 1103,1108 ****
--- 1105,1112 ----
MyProcPid = PostmasterPid = getpid(); /* reset PID vars to child */
+ MyStartTime = time(NULL);
+
/* GH: If there's no setsid(), we hopefully don't need silent mode.
* Until there's a better solution.
*/
***************
*** 2661,2666 ****
--- 2665,2672 ----
MyProcPid = getpid(); /* reset MyProcPid */
+ MyStartTime = time(NULL);
+
/* We don't want the postmaster's proc_exit() handlers */
on_exit_reset();
***************
*** 2803,2809 ****
/* save process start time */
port->SessionStartTime = GetCurrentTimestamp();
! port->session_start = timestamptz_to_time_t(port->SessionStartTime);
/* set these to empty in case they are needed before we set them up */
port->remote_host = "";
--- 2809,2815 ----
/* save process start time */
port->SessionStartTime = GetCurrentTimestamp();
! MyStartTime = timestamptz_to_time_t(port->SessionStartTime);
/* set these to empty in case they are needed before we set them up */
port->remote_host = "";
***************
*** 3385,3390 ****
--- 3391,3398 ----
MyProcPid = getpid(); /* reset MyProcPid */
+ MyStartTime = time(NULL);
+
/* Lose the postmaster's on-exit routines (really a no-op) */
on_exit_reset();
Index: src/backend/utils/error/elog.c
===================================================================
RCS file: /cvsroot/pgsql/src/backend/utils/error/elog.c,v
retrieving revision 1.190
diff -c -r1.190 elog.c
*** src/backend/utils/error/elog.c 21 Jul 2007 22:12:04 -0000 1.190
--- src/backend/utils/error/elog.c 29 Jul 2007 18:14:20 -0000
***************
*** 1485,1496 ****
}
break;
case 'c':
! if (MyProcPort)
! {
! appendStringInfo(buf, "%lx.%x",
! (long) (MyProcPort->session_start),
! MyProcPid);
! }
break;
case 'p':
appendStringInfo(buf, "%d", MyProcPid);
--- 1485,1491 ----
}
break;
case 'c':
! appendStringInfo(buf, "%lx.%x", (long)(MyStartTime),MyProcPid);
break;
case 'p':
appendStringInfo(buf, "%d", MyProcPid);
***************
*** 1552,1558 ****
}
break;
case 's':
- if (MyProcPort)
{
char strfbuf[128];
--- 1547,1552 ----
***************
*** 1563,1569 ****
#else
"%Y-%m-%d %H:%M:%S",
#endif
! localtime(&MyProcPort->session_start));
appendStringInfoString(buf, strfbuf);
}
break;
--- 1557,1563 ----
#else
"%Y-%m-%d %H:%M:%S",
#endif
! localtime(&MyStartTime));
appendStringInfoString(buf, strfbuf);
}
break;
Index: src/backend/utils/init/globals.c
===================================================================
RCS file: /cvsroot/pgsql/src/backend/utils/init/globals.c,v
retrieving revision 1.101
diff -c -r1.101 globals.c
*** src/backend/utils/init/globals.c 16 Apr 2007 18:29:54 -0000 1.101
--- src/backend/utils/init/globals.c 29 Jul 2007 18:14:21 -0000
***************
*** 33,38 ****
--- 33,39 ----
volatile uint32 CritSectionCount = 0;
int MyProcPid;
+ time_t MyStartTime;
struct Port *MyProcPort;
long MyCancelKey;
Index: src/include/miscadmin.h
===================================================================
RCS file: /cvsroot/pgsql/src/include/miscadmin.h,v
retrieving revision 1.195
diff -c -r1.195 miscadmin.h
*** src/include/miscadmin.h 25 Jul 2007 12:22:53 -0000 1.195
--- src/include/miscadmin.h 29 Jul 2007 18:14:22 -0000
***************
*** 23,28 ****
--- 23,30 ----
#ifndef MISCADMIN_H
#define MISCADMIN_H
+ #include <time.h> /* for time_t */
+
#define PG_VERSIONSTR "postgres (PostgreSQL) " PG_VERSION "\n"
***************
*** 132,137 ****
--- 134,140 ----
extern int MaxConnections;
extern PGDLLIMPORT int MyProcPid;
+ extern PGDLLIMPORT time_t MyStartTime;
extern PGDLLIMPORT struct Port *MyProcPort;
extern long MyCancelKey;
Index: src/include/libpq/libpq-be.h
===================================================================
RCS file: /cvsroot/pgsql/src/include/libpq/libpq-be.h,v
retrieving revision 1.62
diff -c -r1.62 libpq-be.h
*** src/include/libpq/libpq-be.h 23 Jul 2007 10:16:54 -0000 1.62
--- src/include/libpq/libpq-be.h 29 Jul 2007 18:14:22 -0000
***************
*** 130,136 ****
* other members of this struct, we may as well keep it here.
*/
TimestampTz SessionStartTime; /* backend start time */
- time_t session_start; /* same, in time_t format */
/*
* TCP keepalive settings.
--- 130,135 ----
Andrew Dunstan wrote: > > The attached patch makes a very small but useful change to the > behaviour of log_line_prefix, by enabling the start time (%s) and > cookie (%c) logging to occur for all backends rather than just for > session processes (i.e. backends started for a client connection). We > actually need almost all of this patch, with or without the change in > behaviour, so we can put the cookie in CSVlogs (which I'm still > working on), since the cookie+line number make the natural primary key > for the logs. The actual change in behaviour from this patch comes > from the removal of 2 "if (MyProcPort)" lines in elog.c. Given that, > can I sneak this in or should I wait for 8.4 given we're long past > feature freeze? > > Most of this has been factored out (and cleaned up) from my previous > CSVlog patch, so it's not new. I did that so that what is left when I > finish will have a rather smaller footprint, as this part seemed > fairly seperable. > > I haven't seen a response to this. If there's no objection I intend to apply this. cheers andrew
Andrew Dunstan wrote: > > > Andrew Dunstan wrote: >> >> The attached patch makes a very small but useful change to the >> behaviour of log_line_prefix, by enabling the start time (%s) and >> cookie (%c) logging to occur for all backends rather than just for >> session processes (i.e. backends started for a client connection). We >> actually need almost all of this patch, with or without the change in >> behaviour, so we can put the cookie in CSVlogs (which I'm still >> working on), since the cookie+line number make the natural primary key >> for the logs. The actual change in behaviour from this patch comes >> from the removal of 2 "if (MyProcPort)" lines in elog.c. Given that, >> can I sneak this in or should I wait for 8.4 given we're long past >> feature freeze? >> >> Most of this has been factored out (and cleaned up) from my previous >> CSVlog patch, so it's not new. I did that so that what is left when I >> finish will have a rather smaller footprint, as this part seemed >> fairly seperable. >> >> > > I haven't seen a response to this. If there's no objection I intend to > apply this. My only objection would be that we're in feature-freeze. We really should be doing other things ;-) But I'm not going to be the one to put a full stop to it if the patch already exists and is trivial. You can probably sneak it in as part of the cvslog stuff... //Magnus
Andrew Dunstan wrote: > > > Andrew Dunstan wrote: >> >> The attached patch makes a very small but useful change to the behaviour >> of log_line_prefix, by enabling the start time (%s) and cookie (%c) >> logging to occur for all backends rather than just for session processes >> (i.e. backends started for a client connection). We actually need almost >> all of this patch, with or without the change in behaviour, so we can put >> the cookie in CSVlogs (which I'm still working on), since the cookie+line >> number make the natural primary key for the logs. The actual change in >> behaviour from this patch comes from the removal of 2 "if (MyProcPort)" >> lines in elog.c. Given that, can I sneak this in or should I wait for 8.4 >> given we're long past feature freeze? >> >> Most of this has been factored out (and cleaned up) from my previous >> CSVlog patch, so it's not new. I did that so that what is left when I >> finish will have a rather smaller footprint, as this part seemed fairly >> seperable. > > I haven't seen a response to this. If there's no objection I intend to > apply this. I was just looking at it. I was wondering why didn't you set the start time in syslogger and bgwriter. If it isn't necessary for those, why do you bother setting it in autovac launcher? I am also wondering if setting it in InitAuxiliaryProcess is redundant (or rather, whether the extra set in each auxiliary process is redundant with the call in InitAuxiliaryProcess). -- Alvaro Herrera http://www.CommandPrompt.com/ The PostgreSQL Company - Command Prompt, Inc.
Alvaro Herrera wrote: > I am also wondering if setting it in InitAuxiliaryProcess is redundant > (or rather, whether the extra set in each auxiliary process is redundant > with the call in InitAuxiliaryProcess). > Well, it's set right at the front of SubPostmasterMain, immediately after setting MyProcPid. Is that enough to catch every path? I think it's a better place than InitAuxiliaryProcess, because at that stage no logging can have taken place. Maybe we just need to remove the other special cases ... I'll take another look. cheers andrew
Andrew Dunstan wrote: > > > Alvaro Herrera wrote: >> I am also wondering if setting it in InitAuxiliaryProcess is redundant >> (or rather, whether the extra set in each auxiliary process is redundant >> with the call in InitAuxiliaryProcess). >> > > Well, it's set right at the front of SubPostmasterMain, immediately after > setting MyProcPid. Is that enough to catch every path? Only in the EXEC_BACKEND case, right? It's not used at all in the other case. -- Alvaro Herrera http://www.CommandPrompt.com/ PostgreSQL Replication, Consulting, Custom Development, 24x7 support
Alvaro Herrera wrote: > Andrew Dunstan wrote: > >> Alvaro Herrera wrote: >> >>> I am also wondering if setting it in InitAuxiliaryProcess is redundant >>> (or rather, whether the extra set in each auxiliary process is redundant >>> with the call in InitAuxiliaryProcess). >>> >>> >> Well, it's set right at the front of SubPostmasterMain, immediately after >> setting MyProcPid. Is that enough to catch every path? >> > > Only in the EXEC_BACKEND case, right? It's not used at all in the other > case. > > Yeah. I need to stop multitasking - brain functions less well. My original thought was that it needed to be set anywhere MyProcPid was set. That still seems to make sense, it just looks like I missed a few places, which I should fix. cheers andrew
Andrew Dunstan wrote: > Alvaro Herrera wrote: >> Andrew Dunstan wrote: >> >>> Alvaro Herrera wrote: >>> >>>> I am also wondering if setting it in InitAuxiliaryProcess is redundant >>>> (or rather, whether the extra set in each auxiliary process is redundant >>>> with the call in InitAuxiliaryProcess). > My original thought was that it needed to be set anywhere MyProcPid was > set. That still seems to make sense, it just looks like I missed a few > places, which I should fix. +1 because of cleanliness, even if some calls turn out to be redundant. That was in fact what I initially thought you were doing. -- Alvaro Herrera http://www.PlanetPostgreSQL.org/ "Porque francamente, si para saber manejarse a uno mismo hubiera que rendir examen... ¿Quién es el machito que tendría carnet?" (Mafalda)
Alvaro Herrera wrote:
>
>> My original thought was that it needed to be set anywhere MyProcPid was
>> set. That still seems to make sense, it just looks like I missed a few
>> places, which I should fix.
>>
>
> +1 because of cleanliness, even if some calls turn out to be redundant.
> That was in fact what I initially thought you were doing.
>
>
OK, here's the revised patch.
cheers
andrew
Index: doc/src/sgml/config.sgml
===================================================================
RCS file: /cvsroot/pgsql/doc/src/sgml/config.sgml,v
retrieving revision 1.133
diff -c -r1.133 config.sgml
*** doc/src/sgml/config.sgml 24 Jul 2007 04:54:08 -0000 1.133
--- doc/src/sgml/config.sgml 1 Aug 2007 23:51:02 -0000
***************
*** 2861,2867 ****
<row>
<entry><literal>%c</literal></entry>
<entry>Session ID: see below</entry>
! <entry>yes</entry>
</row>
<row>
<entry><literal>%l</literal></entry>
--- 2861,2867 ----
<row>
<entry><literal>%c</literal></entry>
<entry>Session ID: see below</entry>
! <entry>no</entry>
</row>
<row>
<entry><literal>%l</literal></entry>
***************
*** 2871,2877 ****
<row>
<entry><literal>%s</literal></entry>
<entry>Session start time stamp</entry>
! <entry>yes</entry>
</row>
<row>
<entry><literal>%x</literal></entry>
--- 2871,2877 ----
<row>
<entry><literal>%s</literal></entry>
<entry>Session start time stamp</entry>
! <entry>no</entry>
</row>
<row>
<entry><literal>%x</literal></entry>
Index: src/backend/bootstrap/bootstrap.c
===================================================================
RCS file: /cvsroot/pgsql/src/backend/bootstrap/bootstrap.c,v
retrieving revision 1.235
diff -c -r1.235 bootstrap.c
*** src/backend/bootstrap/bootstrap.c 24 Jul 2007 04:54:09 -0000 1.235
--- src/backend/bootstrap/bootstrap.c 1 Aug 2007 23:51:04 -0000
***************
*** 213,218 ****
--- 213,220 ----
*/
MyProcPid = getpid();
+ MyStartTime = time(NULL);
+
/*
* Fire up essential subsystems: error and memory management
*
Index: src/backend/postmaster/autovacuum.c
===================================================================
RCS file: /cvsroot/pgsql/src/backend/postmaster/autovacuum.c,v
retrieving revision 1.55
diff -c -r1.55 autovacuum.c
*** src/backend/postmaster/autovacuum.c 1 Jul 2007 18:30:54 -0000 1.55
--- src/backend/postmaster/autovacuum.c 1 Aug 2007 23:51:05 -0000
***************
*** 385,390 ****
--- 385,393 ----
/* reset MyProcPid */
MyProcPid = getpid();
+ /* record Start Time for logging */
+ MyStartTime = time(NULL);
+
/* Identify myself via ps */
init_ps_display("autovacuum launcher process", "", "", "");
***************
*** 1403,1408 ****
--- 1406,1414 ----
/* reset MyProcPid */
MyProcPid = getpid();
+ /* record Start Time for logging */
+ MyStartTime = time(NULL);
+
/* Identify myself via ps */
init_ps_display("autovacuum worker process", "", "", "");
Index: src/backend/postmaster/pgarch.c
===================================================================
RCS file: /cvsroot/pgsql/src/backend/postmaster/pgarch.c,v
retrieving revision 1.29
diff -c -r1.29 pgarch.c
*** src/backend/postmaster/pgarch.c 10 Feb 2007 14:58:54 -0000 1.29
--- src/backend/postmaster/pgarch.c 1 Aug 2007 23:51:05 -0000
***************
*** 223,228 ****
--- 223,230 ----
MyProcPid = getpid(); /* reset MyProcPid */
+ MyStartTime = time(NULL); /* record Start Time for logging */
+
/*
* If possible, make this process a group leader, so that the postmaster
* can signal any child processes too.
Index: src/backend/postmaster/pgstat.c
===================================================================
RCS file: /cvsroot/pgsql/src/backend/postmaster/pgstat.c,v
retrieving revision 1.161
diff -c -r1.161 pgstat.c
*** src/backend/postmaster/pgstat.c 8 Jul 2007 22:23:16 -0000 1.161
--- src/backend/postmaster/pgstat.c 1 Aug 2007 23:51:07 -0000
***************
*** 2168,2173 ****
--- 2168,2175 ----
MyProcPid = getpid(); /* reset MyProcPid */
+ MyStartTime = time(NULL); /* record Start Time for logging */
+
/*
* If possible, make this process a group leader, so that the postmaster
* can signal any child processes too. (pgstat probably never has
Index: src/backend/postmaster/postmaster.c
===================================================================
RCS file: /cvsroot/pgsql/src/backend/postmaster/postmaster.c,v
retrieving revision 1.535
diff -c -r1.535 postmaster.c
*** src/backend/postmaster/postmaster.c 24 Jul 2007 04:54:09 -0000 1.535
--- src/backend/postmaster/postmaster.c 1 Aug 2007 23:51:10 -0000
***************
*** 386,391 ****
--- 386,393 ----
MyProcPid = PostmasterPid = getpid();
+ MyStartTime = time(NULL);
+
IsPostmasterEnvironment = true;
/*
***************
*** 1103,1108 ****
--- 1105,1112 ----
MyProcPid = PostmasterPid = getpid(); /* reset PID vars to child */
+ MyStartTime = time(NULL);
+
/* GH: If there's no setsid(), we hopefully don't need silent mode.
* Until there's a better solution.
*/
***************
*** 2661,2666 ****
--- 2665,2672 ----
MyProcPid = getpid(); /* reset MyProcPid */
+ MyStartTime = time(NULL);
+
/* We don't want the postmaster's proc_exit() handlers */
on_exit_reset();
***************
*** 2803,2809 ****
/* save process start time */
port->SessionStartTime = GetCurrentTimestamp();
! port->session_start = timestamptz_to_time_t(port->SessionStartTime);
/* set these to empty in case they are needed before we set them up */
port->remote_host = "";
--- 2809,2815 ----
/* save process start time */
port->SessionStartTime = GetCurrentTimestamp();
! MyStartTime = timestamptz_to_time_t(port->SessionStartTime);
/* set these to empty in case they are needed before we set them up */
port->remote_host = "";
***************
*** 3385,3390 ****
--- 3391,3398 ----
MyProcPid = getpid(); /* reset MyProcPid */
+ MyStartTime = time(NULL);
+
/* Lose the postmaster's on-exit routines (really a no-op) */
on_exit_reset();
Index: src/backend/postmaster/syslogger.c
===================================================================
RCS file: /cvsroot/pgsql/src/backend/postmaster/syslogger.c,v
retrieving revision 1.33
diff -c -r1.33 syslogger.c
*** src/backend/postmaster/syslogger.c 19 Jul 2007 19:13:43 -0000 1.33
--- src/backend/postmaster/syslogger.c 1 Aug 2007 23:51:10 -0000
***************
*** 162,167 ****
--- 162,169 ----
MyProcPid = getpid(); /* reset MyProcPid */
+ MyStartTime = time(NULL); /* set our start time in case we call elog */
+
#ifdef EXEC_BACKEND
syslogger_parseArgs(argc, argv);
#endif /* EXEC_BACKEND */
Index: src/backend/tcop/postgres.c
===================================================================
RCS file: /cvsroot/pgsql/src/backend/tcop/postgres.c,v
retrieving revision 1.536
diff -c -r1.536 postgres.c
*** src/backend/tcop/postgres.c 9 Jul 2007 01:15:14 -0000 1.536
--- src/backend/tcop/postgres.c 1 Aug 2007 23:51:13 -0000
***************
*** 2786,2791 ****
--- 2786,2793 ----
*/
MyProcPid = getpid();
+ MyStartTime = time(NULL);
+
/*
* Fire up essential subsystems: error and memory management
*
Index: src/backend/utils/error/elog.c
===================================================================
RCS file: /cvsroot/pgsql/src/backend/utils/error/elog.c,v
retrieving revision 1.190
diff -c -r1.190 elog.c
*** src/backend/utils/error/elog.c 21 Jul 2007 22:12:04 -0000 1.190
--- src/backend/utils/error/elog.c 1 Aug 2007 23:51:14 -0000
***************
*** 1485,1496 ****
}
break;
case 'c':
! if (MyProcPort)
! {
! appendStringInfo(buf, "%lx.%x",
! (long) (MyProcPort->session_start),
! MyProcPid);
! }
break;
case 'p':
appendStringInfo(buf, "%d", MyProcPid);
--- 1485,1491 ----
}
break;
case 'c':
! appendStringInfo(buf, "%lx.%x", (long)(MyStartTime),MyProcPid);
break;
case 'p':
appendStringInfo(buf, "%d", MyProcPid);
***************
*** 1552,1558 ****
}
break;
case 's':
- if (MyProcPort)
{
char strfbuf[128];
--- 1547,1552 ----
***************
*** 1563,1569 ****
#else
"%Y-%m-%d %H:%M:%S",
#endif
! localtime(&MyProcPort->session_start));
appendStringInfoString(buf, strfbuf);
}
break;
--- 1557,1563 ----
#else
"%Y-%m-%d %H:%M:%S",
#endif
! localtime(&MyStartTime));
appendStringInfoString(buf, strfbuf);
}
break;
Index: src/backend/utils/init/globals.c
===================================================================
RCS file: /cvsroot/pgsql/src/backend/utils/init/globals.c,v
retrieving revision 1.101
diff -c -r1.101 globals.c
*** src/backend/utils/init/globals.c 16 Apr 2007 18:29:54 -0000 1.101
--- src/backend/utils/init/globals.c 1 Aug 2007 23:51:14 -0000
***************
*** 33,38 ****
--- 33,39 ----
volatile uint32 CritSectionCount = 0;
int MyProcPid;
+ time_t MyStartTime;
struct Port *MyProcPort;
long MyCancelKey;
Index: src/include/miscadmin.h
===================================================================
RCS file: /cvsroot/pgsql/src/include/miscadmin.h,v
retrieving revision 1.195
diff -c -r1.195 miscadmin.h
*** src/include/miscadmin.h 25 Jul 2007 12:22:53 -0000 1.195
--- src/include/miscadmin.h 1 Aug 2007 23:51:15 -0000
***************
*** 23,28 ****
--- 23,30 ----
#ifndef MISCADMIN_H
#define MISCADMIN_H
+ #include <time.h> /* for time_t */
+
#define PG_VERSIONSTR "postgres (PostgreSQL) " PG_VERSION "\n"
***************
*** 132,137 ****
--- 134,140 ----
extern int MaxConnections;
extern PGDLLIMPORT int MyProcPid;
+ extern PGDLLIMPORT time_t MyStartTime;
extern PGDLLIMPORT struct Port *MyProcPort;
extern long MyCancelKey;
Index: src/include/libpq/libpq-be.h
===================================================================
RCS file: /cvsroot/pgsql/src/include/libpq/libpq-be.h,v
retrieving revision 1.62
diff -c -r1.62 libpq-be.h
*** src/include/libpq/libpq-be.h 23 Jul 2007 10:16:54 -0000 1.62
--- src/include/libpq/libpq-be.h 1 Aug 2007 23:51:16 -0000
***************
*** 130,136 ****
* other members of this struct, we may as well keep it here.
*/
TimestampTz SessionStartTime; /* backend start time */
- time_t session_start; /* same, in time_t format */
/*
* TCP keepalive settings.
--- 130,135 ----
Andrew Dunstan wrote: > > The attached patch makes a very small but useful change to the behaviour of > log_line_prefix, by enabling the start time (%s) and cookie (%c) logging to > occur for all backends rather than just for session processes (i.e. > backends started for a client connection). We actually need almost all of > this patch, with or without the change in behaviour, so we can put the > cookie in CSVlogs (which I'm still working on), since the cookie+line > number make the natural primary key for the logs. The actual change in > behaviour from this patch comes from the removal of 2 "if (MyProcPort)" > lines in elog.c. Given that, can I sneak this in or should I wait for 8.4 > given we're long past feature freeze? Thinking again about the feature itself I wonder if it actually makes sense -- maybe it does make sense to be able to display the session ID, but the start time? Why would anyone care about the start time of syslogger or bgwriter? We don't even have a use for the "hey, this process was started" log line, why would anyone care about having the start time in the log line prefix? Actually having the cookie in all processes is another matter, as far as it's useful for CSV logs. But then, is it? Maybe the auxiliary processes should identify themselves with fixed cookies or something particular that lets one distinguish, say, a bgwriter from a syslogger, but is there a case from distinguishing one bgwriter from another? -- Alvaro Herrera http://www.amazon.com/gp/registry/CTMLCN8V17R4 "Amanece. (Ignacio Reyes) El Cerro San Cristóbal me mira, cÃnicamente, con ojos de virgen"
Alvaro Herrera wrote: > Andrew Dunstan wrote: > >> The attached patch makes a very small but useful change to the behaviour of >> log_line_prefix, by enabling the start time (%s) and cookie (%c) logging to >> occur for all backends rather than just for session processes (i.e. >> backends started for a client connection). We actually need almost all of >> this patch, with or without the change in behaviour, so we can put the >> cookie in CSVlogs (which I'm still working on), since the cookie+line >> number make the natural primary key for the logs. The actual change in >> behaviour from this patch comes from the removal of 2 "if (MyProcPort)" >> lines in elog.c. Given that, can I sneak this in or should I wait for 8.4 >> given we're long past feature freeze? >> > > Thinking again about the feature itself I wonder if it actually makes > sense -- maybe it does make sense to be able to display the session ID, > but the start time? Why would anyone care about the start time of > syslogger or bgwriter? We don't even have a use for the "hey, this > process was started" log line, why would anyone care about having the > start time in the log line prefix? > > Actually having the cookie in all processes is another matter, as far as > it's useful for CSV logs. But then, is it? Maybe the auxiliary > processes should identify themselves with fixed cookies or something > particular that lets one distinguish, say, a bgwriter from a syslogger, > but is there a case from distinguishing one bgwriter from another? > > It's not about distinguishing one bgwriter from another, it's about distinguishing it from any other process at any time whatsoever that has had the same pid. cookie+linenumber should be unique. pid+linenumber isn't. (And every process gets its own line number sequence, so we can't just give, say, all the bgwriter processes the same cookie). Logging the start time on its own isn't much extra benefit, although I expect log parsers will find it nicer to be able to handle a more consistent logging style rather than having to handle non-session processes as a special case. But having the cookie available in all cases is the whole point of this - I wouldn't have done it unless I had needed to be able to set a primary key for loadable logs. If you want to invent some other style of cookie we can look at that. Back when we looked at it originally nobody came up with a better suggestion than process_start.pid. But that surely would be for a later release ;-) So, short answer - yes, I think it makes sense. But if there's any serious argument I won't change the observable behaviour in elog.c, just the infrastructure. cheers andrew
Andrew Dunstan wrote: > > > Alvaro Herrera wrote: >> Andrew Dunstan wrote: >> >>> The attached patch makes a very small but useful change to the >>> behaviour of log_line_prefix, by enabling the start time (%s) and >>> cookie (%c) logging to occur for all backends rather than just for >>> session processes (i.e. backends started for a client connection). >>> We actually need almost all of this patch, with or without the >>> change in behaviour, so we can put the cookie in CSVlogs (which I'm >>> still working on), since the cookie+line number make the natural >>> primary key for the logs. The actual change in behaviour from this >>> patch comes from the removal of 2 "if (MyProcPort)" lines in elog.c. >>> Given that, can I sneak this in or should I wait for 8.4 given we're >>> long past feature freeze? >>> >> >> Thinking again about the feature itself I wonder if it actually makes >> sense -- maybe it does make sense to be able to display the session ID, >> but the start time? Why would anyone care about the start time of >> syslogger or bgwriter? We don't even have a use for the "hey, this >> process was started" log line, why would anyone care about having the >> start time in the log line prefix? >> >> Actually having the cookie in all processes is another matter, as far as >> it's useful for CSV logs. But then, is it? Maybe the auxiliary >> processes should identify themselves with fixed cookies or something >> particular that lets one distinguish, say, a bgwriter from a syslogger, >> but is there a case from distinguishing one bgwriter from another? >> >> > > It's not about distinguishing one bgwriter from another, it's about > distinguishing it from any other process at any time whatsoever that > has had the same pid. cookie+linenumber should be unique. > pid+linenumber isn't. (And every process gets its own line number > sequence, so we can't just give, say, all the bgwriter processes the > same cookie). Logging the start time on its own isn't much extra > benefit, although I expect log parsers will find it nicer to be able > to handle a more consistent logging style rather than having to handle > non-session processes as a special case. But having the cookie > available in all cases is the whole point of this - I wouldn't have > done it unless I had needed to be able to set a primary key for > loadable logs. > > If you want to invent some other style of cookie we can look at that. > Back when we looked at it originally nobody came up with a better > suggestion than process_start.pid. But that surely would be for a > later release ;-) > > So, short answer - yes, I think it makes sense. But if there's any > serious argument I won't change the observable behaviour in elog.c, > just the infrastructure. > > In the absence of further discussion I have committed this. That clears the decks for me to have yet another go at CSVlogs ;-) cheers andrew