Обсуждение: Latch-ifying the syslogger process

Поиск
Список
Период
Сортировка

Latch-ifying the syslogger process

От
Tom Lane
Дата:
I noticed a large oversight in our efforts to reduce the server's idle
wakeup frequency: if you've got logging_collector turned on, the
syslogger process will wake up once a second, whether it has anything
to do or not.  But the only reasons it has for waking up are signals,
data arrival, and time-based logfile rotation, and it is easy to
calculate the time until the next logfile rotation event.  So this
seems really easy to latch-ify, and I would like to apply the attached
patch if there are not objections.  I do not however have the ability
to test the Windows side of it, so it'd be nice if someone would check
that that still works (particularly, that it shuts down cleanly).

While testing this I discovered a pre-existing bug in the Unix
implementation of WaitLatchOrSocket: EOF on the socket is reported as
POLLHUP not POLLIN (at least on my Linux box), which results in
WaitLatchOrSocket going into an infinite loop, because poll() returns
immediately but the result bitmask never becomes nonzero.  So at least
the first hunk of this patch had better get applied and back-patched
in any case.

            regards, tom lane

diff --git a/src/backend/port/unix_latch.c b/src/backend/port/unix_latch.c
index 30d1a48..de0af87 100644
*** a/src/backend/port/unix_latch.c
--- b/src/backend/port/unix_latch.c
*************** WaitLatchOrSocket(volatile Latch *latch,
*** 293,299 ****
              result |= WL_TIMEOUT;
          }
          if ((wakeEvents & WL_SOCKET_READABLE) &&
!             (pfds[0].revents & POLLIN))
          {
              /* data available in socket */
              result |= WL_SOCKET_READABLE;
--- 293,299 ----
              result |= WL_TIMEOUT;
          }
          if ((wakeEvents & WL_SOCKET_READABLE) &&
!             (pfds[0].revents & (POLLIN | POLLHUP | POLLERR)))
          {
              /* data available in socket */
              result |= WL_SOCKET_READABLE;
diff --git a/src/backend/postmaster/syslogger.c b/src/backend/postmaster/syslogger.c
index f5ae841..3528879 100644
*** a/src/backend/postmaster/syslogger.c
--- b/src/backend/postmaster/syslogger.c
***************
*** 9,16 ****
   * in postgresql.conf. If these limits are reached or passed, the
   * current logfile is closed and a new one is created (rotated).
   * The logfiles are stored in a subdirectory (configurable in
!  * postgresql.conf), using an internal naming scheme that mangles
!  * creation time and current postmaster pid.
   *
   * Author: Andreas Pflug <pgadmin@pse-consulting.de>
   *
--- 9,15 ----
   * in postgresql.conf. If these limits are reached or passed, the
   * current logfile is closed and a new one is created (rotated).
   * The logfiles are stored in a subdirectory (configurable in
!  * postgresql.conf), using a user-selectable naming scheme.
   *
   * Author: Andreas Pflug <pgadmin@pse-consulting.de>
   *
***************
*** 40,45 ****
--- 39,45 ----
  #include "postmaster/postmaster.h"
  #include "postmaster/syslogger.h"
  #include "storage/ipc.h"
+ #include "storage/latch.h"
  #include "storage/pg_shmem.h"
  #include "utils/guc.h"
  #include "utils/ps_status.h"
*************** static FILE *syslogFile = NULL;
*** 93,98 ****
--- 93,99 ----
  static FILE *csvlogFile = NULL;
  static char *last_file_name = NULL;
  static char *last_csv_file_name = NULL;
+ static Latch sysLoggerLatch;

  /*
   * Buffers for saving partial messages from different backends.
*************** SysLoggerMain(int argc, char *argv[])
*** 168,179 ****
--- 169,182 ----
      char       *currentLogDir;
      char       *currentLogFilename;
      int            currentLogRotationAge;
+     pg_time_t    now;

      IsUnderPostmaster = true;    /* we are a postmaster subprocess now */

      MyProcPid = getpid();        /* reset MyProcPid */

      MyStartTime = time(NULL);    /* set our start time in case we call elog */
+     now = MyStartTime;

  #ifdef EXEC_BACKEND
      syslogger_parseArgs(argc, argv);
*************** SysLoggerMain(int argc, char *argv[])
*** 246,251 ****
--- 249,257 ----
          elog(FATAL, "setsid() failed: %m");
  #endif

+     /* Initialize private latch for use by signal handlers */
+     InitLatch(&sysLoggerLatch);
+
      /*
       * Properly accept or ignore signals the postmaster might send us
       *
*************** SysLoggerMain(int argc, char *argv[])
*** 296,309 ****
      {
          bool        time_based_rotation = false;
          int            size_rotation_for = 0;

  #ifndef WIN32
-         int            bytesRead;
          int            rc;
-         fd_set        rfds;
-         struct timeval timeout;
  #endif

          if (got_SIGHUP)
          {
              got_SIGHUP = false;
--- 302,320 ----
      {
          bool        time_based_rotation = false;
          int            size_rotation_for = 0;
+         long        cur_timeout;
+         int            cur_flags;

  #ifndef WIN32
          int            rc;
  #endif

+         /* Clear any already-pending wakeups */
+         ResetLatch(&sysLoggerLatch);
+
+         /*
+          * Process any requests or signals received recently.
+          */
          if (got_SIGHUP)
          {
              got_SIGHUP = false;
*************** SysLoggerMain(int argc, char *argv[])
*** 353,363 ****
              }
          }

!         if (!rotation_requested && Log_RotationAge > 0 && !rotation_disabled)
          {
              /* Do a logfile rotation if it's time */
!             pg_time_t    now = (pg_time_t) time(NULL);
!
              if (now >= next_rotation_time)
                  rotation_requested = time_based_rotation = true;
          }
--- 364,373 ----
              }
          }

!         if (Log_RotationAge > 0 && !rotation_disabled)
          {
              /* Do a logfile rotation if it's time */
!             now = (pg_time_t) time(NULL);
              if (now >= next_rotation_time)
                  rotation_requested = time_based_rotation = true;
          }
*************** SysLoggerMain(int argc, char *argv[])
*** 389,416 ****
              logfile_rotate(time_based_rotation, size_rotation_for);
          }

- #ifndef WIN32
-
          /*
!          * Wait for some data, timing out after 1 second
           */
!         FD_ZERO(&rfds);
!         FD_SET(syslogPipe[0], &rfds);
!
!         timeout.tv_sec = 1;
!         timeout.tv_usec = 0;
!
!         rc = select(syslogPipe[0] + 1, &rfds, NULL, NULL, &timeout);
!
!         if (rc < 0)
          {
!             if (errno != EINTR)
!                 ereport(LOG,
!                         (errcode_for_socket_access(),
!                          errmsg("select() failed in logger process: %m")));
          }
!         else if (rc > 0 && FD_ISSET(syslogPipe[0], &rfds))
          {
              bytesRead = read(syslogPipe[0],
                               logbuffer + bytes_in_logbuffer,
                               sizeof(logbuffer) - bytes_in_logbuffer);
--- 399,438 ----
              logfile_rotate(time_based_rotation, size_rotation_for);
          }

          /*
!          * Calculate time till next time-based rotation, so that we don't
!          * sleep longer than that.  We assume the value of "now" obtained
!          * above is still close enough.  Note we can't make this calculation
!          * until after calling logfile_rotate(), since it will advance
!          * next_rotation_time.
           */
!         if (Log_RotationAge > 0 && !rotation_disabled)
          {
!             if (now < next_rotation_time)
!                 cur_timeout = (next_rotation_time - now) * 1000L; /* msec */
!             else
!                 cur_timeout = 0;
!             cur_flags = WL_TIMEOUT;
          }
!         else
!         {
!             cur_timeout = -1L;
!             cur_flags = 0;
!         }
!
!         /*
!          * Sleep until there's something to do
!          */
! #ifndef WIN32
!         rc = WaitLatchOrSocket(&sysLoggerLatch,
!                                WL_LATCH_SET | WL_SOCKET_READABLE | cur_flags,
!                                syslogPipe[0],
!                                cur_timeout);
!
!         if (rc & WL_SOCKET_READABLE)
          {
+             int            bytesRead;
+
              bytesRead = read(syslogPipe[0],
                               logbuffer + bytes_in_logbuffer,
                               sizeof(logbuffer) - bytes_in_logbuffer);
*************** SysLoggerMain(int argc, char *argv[])
*** 445,452 ****

          /*
           * On Windows we leave it to a separate thread to transfer data and
!          * detect pipe EOF.  The main thread just wakes up once a second to
!          * check for SIGHUP and rotation conditions.
           *
           * Server code isn't generally thread-safe, so we ensure that only one
           * of the threads is active at a time by entering the critical section
--- 467,474 ----

          /*
           * On Windows we leave it to a separate thread to transfer data and
!          * detect pipe EOF.  The main thread just wakes up to handle SIGHUP
!          * and rotation conditions.
           *
           * Server code isn't generally thread-safe, so we ensure that only one
           * of the threads is active at a time by entering the critical section
*************** SysLoggerMain(int argc, char *argv[])
*** 454,460 ****
           */
          LeaveCriticalSection(&sysloggerSection);

!         pg_usleep(1000000L);

          EnterCriticalSection(&sysloggerSection);
  #endif   /* WIN32 */
--- 476,484 ----
           */
          LeaveCriticalSection(&sysloggerSection);

!         (void) WaitLatch(&sysLoggerLatch,
!                          WL_LATCH_SET | cur_flags,
!                          cur_timeout);

          EnterCriticalSection(&sysloggerSection);
  #endif   /* WIN32 */
*************** write_syslogger_file(const char *buffer,
*** 957,963 ****
  /*
   * Worker thread to transfer data from the pipe to the current logfile.
   *
!  * We need this because on Windows, WaitForSingleObject does not work on
   * unnamed pipes: it always reports "signaled", so the blocking ReadFile won't
   * allow for SIGHUP; and select is for sockets only.
   */
--- 981,987 ----
  /*
   * Worker thread to transfer data from the pipe to the current logfile.
   *
!  * We need this because on Windows, WaitforMultipleObjects does not work on
   * unnamed pipes: it always reports "signaled", so the blocking ReadFile won't
   * allow for SIGHUP; and select is for sockets only.
   */
*************** pipeThread(void *arg)
*** 1010,1015 ****
--- 1034,1042 ----
      /* if there's any data left then force it out now */
      flush_pipe_input(logbuffer, &bytes_in_logbuffer);

+     /* set the latch to waken the main thread, which will quit */
+     SetLatch(&sysLoggerLatch);
+
      LeaveCriticalSection(&sysloggerSection);
      _endthread();
      return 0;
*************** set_next_rotation_time(void)
*** 1285,1296 ****
--- 1312,1333 ----
  static void
  sigHupHandler(SIGNAL_ARGS)
  {
+     int            save_errno = errno;
+
      got_SIGHUP = true;
+     SetLatch(&sysLoggerLatch);
+
+     errno = save_errno;
  }

  /* SIGUSR1: set flag to rotate logfile */
  static void
  sigUsr1Handler(SIGNAL_ARGS)
  {
+     int            save_errno = errno;
+
      rotation_requested = true;
+     SetLatch(&sysLoggerLatch);
+
+     errno = save_errno;
  }

Re: Latch-ifying the syslogger process

От
Andrew Dunstan
Дата:

On 05/12/2012 03:36 PM, Tom Lane wrote:
> I noticed a large oversight in our efforts to reduce the server's idle
> wakeup frequency: if you've got logging_collector turned on, the
> syslogger process will wake up once a second, whether it has anything
> to do or not.  But the only reasons it has for waking up are signals,
> data arrival, and time-based logfile rotation, and it is easy to
> calculate the time until the next logfile rotation event.  So this
> seems really easy to latch-ify, and I would like to apply the attached
> patch if there are not objections.  I do not however have the ability
> to test the Windows side of it, so it'd be nice if someone would check
> that that still works (particularly, that it shuts down cleanly).


I can do that. I'm doing some Windows investigation ATM so this won't be 
hard to add on to it.

It's worth pointing out that the buildfarm client doesn't currently test 
the syslogger at all. It probably should, at least optionally. That 
wouldn't be too hard to arrange. A SMOP :-)

cheers

andrew




Re: Latch-ifying the syslogger process

От
Andrew Dunstan
Дата:

On 05/12/2012 04:00 PM, Andrew Dunstan wrote:
>
>
> On 05/12/2012 03:36 PM, Tom Lane wrote:
>> I noticed a large oversight in our efforts to reduce the server's idle
>> wakeup frequency: if you've got logging_collector turned on, the
>> syslogger process will wake up once a second, whether it has anything
>> to do or not.  But the only reasons it has for waking up are signals,
>> data arrival, and time-based logfile rotation, and it is easy to
>> calculate the time until the next logfile rotation event.  So this
>> seems really easy to latch-ify, and I would like to apply the attached
>> patch if there are not objections.  I do not however have the ability
>> to test the Windows side of it, so it'd be nice if someone would check
>> that that still works (particularly, that it shuts down cleanly).
>
>
> I can do that. I'm doing some Windows investigation ATM so this won't 
> be hard to add on to it.
>
> It's worth pointing out that the buildfarm client doesn't currently 
> test the syslogger at all. It probably should, at least optionally. 
> That wouldn't be too hard to arrange. A SMOP :-)
>
>


Everything looks kosher on my Windows machine (tested both MSVC and 
Mingw64 builds)

cheers

andrew





Re: Latch-ifying the syslogger process

От
Tom Lane
Дата:
Andrew Dunstan <andrew@dunslane.net> writes:
>> On 05/12/2012 03:36 PM, Tom Lane wrote:
> ... I do not however have the ability
> to test the Windows side of it, so it'd be nice if someone would check
> that that still works (particularly, that it shuts down cleanly).

> Everything looks kosher on my Windows machine (tested both MSVC and 
> Mingw64 builds)

Great, thanks for testing!  I've committed that patch, and am back to
wondering what the heck was wrong with the stats collector latch
patch...
        regards, tom lane


Re: Latch-ifying the syslogger process

От
Tom Lane
Дата:
I wrote:
> While testing this I discovered a pre-existing bug in the Unix
> implementation of WaitLatchOrSocket: EOF on the socket is reported as
> POLLHUP not POLLIN (at least on my Linux box), which results in
> WaitLatchOrSocket going into an infinite loop, because poll() returns
> immediately but the result bitmask never becomes nonzero.

BTW, I just came across this in Microsoft's documentation of
WSAEventSelect:
Note that Windows Sockets will record only an FD_CLOSE network eventto indicate closure of a virtual circuit. It will
notrecord anFD_READ network event to indicate this condition.
 

which seems to me to indicate that the Windows version of
WaitLatchOrSocket has a related bug.  We want socket EOF to result in
WL_SOCKET_READABLE being returned, no?  Otherwise the caller may never
realize that it has an EOF condition to deal with.
        regards, tom lane