Re: Exec statement logging - Mailing list pgsql-patches

Simon Riggs wrote:
> Following patch is a minor addition to postgres.c that allows the two
> existing statement logging techniques to work with V3 exec. This then
> allows statement logging with PostgreSQL 8.0+ for JDBC and other V3
> connection types.
>
> The rationale of this patch is to add functionality without modifying
> existing behaviour. There is expected to be some difficulty with
> log_statement producing a log line at both parse and exec, but some may
> find that useful. Since there are two ways of producing statement
> logging with duration times, setting log_min_duration_statement=0 will
> avoid the logging of statements for both parse and exec. For many this
> method is already the preferred way of logging statement performance
> stats.

Uh, I am confused by this.  Your code test is:

+       if ((log_statement == LOGSTMT_ALL && save_log_duration) ||
+             save_log_min_duration_statement)
+               gettimeofday(&start_t, NULL);

First, log_min_duration_statement == -1 turns off logging.  Your test
would enable it for -1.  Also, you added "log_statement == LOGSTMT_ALL",
but don't have a similar test lower down where gettimeofday is used, so
I don't understand its usage here, or why it would be used in this
place.  The original test is:

+       if (save_log_duration || save_log_min_duration_statement != -1)
+           gettimeofday(&start_t, NULL);

> There is no attempt to log parameters, since these are not often
> required for performance analysis.

OK.

> The enclosed patch has been tested against cvstip.
>
> I also see this as a backpatch onto 8.0, since it prevents statements
> from being logged as described in the manual and prevents effective
> performance tuning. It has not been tested against 8.0.2, though was
> originally written against 8.0.1 and is believed to apply cleanly.

I don't think it should be backpatched.  This is a behavior changes that
can be seen as a feature addition.

> Some code has been duplicated with this patch; refactoring and cleanup
> can be performed should anybody desire it.

Not sure it is worth it considering how many variables are involved.

> The patch was produced quickly to assist tuning efforts during
> Scalability & Performance benchmarking of PostgreSQL 8.0 carried out at
> Unisys Corporation's Mission Viejo engineering laboratory. The
> development was sponsored by Unisys Corporation and the patch has now
> been donated to the PostgreSQL community under the standard
> PostgreSQL/BSD licence. Approval for release of this code has been given
> in writing to me by the Director, Open Runtime Products, Unisys on April
> 8, 2005.

I have made a new version of the patch using your patch only as a guide.
I copied the sections you suggested.  It compiles fine but I would like
someone to test that it actually works for client-side EXECUTE.  I don't
have a test setup for that here.

One thing you did was to log debug_query_string, but I don't see how
that could be the right value.  I assume it would be empty in a
client-side execute, or be the previous query.  I instead used "EXECUTE
portal_name" because that is what we are passed from the client.

--
  Bruce Momjian                        |  http://candle.pha.pa.us
  pgman@candle.pha.pa.us               |  (610) 359-1001
  +  If your life is a hard drive,     |  13 Roberts Road
  +  Christ can be your backup.        |  Newtown Square, Pennsylvania 19073
Index: src/backend/tcop/postgres.c
===================================================================
RCS file: /cvsroot/pgsql/src/backend/tcop/postgres.c,v
retrieving revision 1.443
diff -c -c -r1.443 postgres.c
*** src/backend/tcop/postgres.c    21 Apr 2005 19:18:13 -0000    1.443
--- src/backend/tcop/postgres.c    14 May 2005 20:22:17 -0000
***************
*** 1011,1017 ****
              stop_t.tv_sec--;
              stop_t.tv_usec += 1000000;
          }
!         usecs = (long) (stop_t.tv_sec - start_t.tv_sec) * 1000000 + (long) (stop_t.tv_usec - start_t.tv_usec);

          /* Only print duration if we previously printed the statement. */
          if (statement_logged && save_log_duration)
--- 1011,1018 ----
              stop_t.tv_sec--;
              stop_t.tv_usec += 1000000;
          }
!         usecs = (long) (stop_t.tv_sec - start_t.tv_sec) * 1000000 +
!                 (long) (stop_t.tv_usec - start_t.tv_usec);

          /* Only print duration if we previously printed the statement. */
          if (statement_logged && save_log_duration)
***************
*** 1579,1584 ****
--- 1580,1590 ----
      bool        is_trans_exit = false;
      bool        completed;
      char        completionTag[COMPLETION_TAG_BUFSIZE];
+     struct timeval start_t,
+                 stop_t;
+     bool        save_log_duration = log_duration;
+     int            save_log_min_duration_statement = log_min_duration_statement;
+     bool        save_log_statement_stats = log_statement_stats;

      /* Adjust destination to tell printtup.c what to do */
      dest = whereToSendOutput;
***************
*** 1615,1620 ****
--- 1621,1646 ----

      set_ps_display(portal->commandTag);

+     /*
+      * We use save_log_* so "SET log_duration = true"  and "SET
+      * log_min_duration_statement = true" don't report incorrect time
+      * because gettimeofday() wasn't called. Similarly,
+      * log_statement_stats has to be captured once.
+      */
+     if (save_log_duration || save_log_min_duration_statement != -1)
+         gettimeofday(&start_t, NULL);
+
+     if (save_log_statement_stats)
+         ResetUsage();
+
+     statement_logged = false;
+     if (log_statement == LOGSTMT_ALL)
+     {
+         ereport(LOG,
+                 (errmsg("statement: EXECUTE %s", portal_name)));
+         statement_logged = true;
+     }
+
      BeginCommand(portal->commandTag, dest);

      /* Check for transaction-control commands */
***************
*** 1709,1714 ****
--- 1735,1783 ----
              pq_putemptymessage('s');
      }

+     /*
+      * Combine processing here as we need to calculate the query duration
+      * in both instances.
+      */
+     if (save_log_duration || save_log_min_duration_statement != -1)
+     {
+         long        usecs;
+
+         gettimeofday(&stop_t, NULL);
+         if (stop_t.tv_usec < start_t.tv_usec)
+         {
+             stop_t.tv_sec--;
+             stop_t.tv_usec += 1000000;
+         }
+         usecs = (long) (stop_t.tv_sec - start_t.tv_sec) * 1000000 +
+                 (long) (stop_t.tv_usec - start_t.tv_usec);
+
+         /* Only print duration if we previously printed the statement. */
+         if (statement_logged && save_log_duration)
+             ereport(LOG,
+                     (errmsg("duration: %ld.%03ld ms",
+                         (long) ((stop_t.tv_sec - start_t.tv_sec) * 1000 +
+                               (stop_t.tv_usec - start_t.tv_usec) / 1000),
+                      (long) (stop_t.tv_usec - start_t.tv_usec) % 1000)));
+
+         /*
+          * Output a duration_statement to the log if the query has
+          * exceeded the min duration, or if we are to print all durations.
+          */
+         if (save_log_min_duration_statement == 0 ||
+             (save_log_min_duration_statement > 0 &&
+              usecs >= save_log_min_duration_statement * 1000))
+             ereport(LOG,
+                     (errmsg("duration: %ld.%03ld ms  statement: EXECUTE %s",
+                         (long) ((stop_t.tv_sec - start_t.tv_sec) * 1000 +
+                               (stop_t.tv_usec - start_t.tv_usec) / 1000),
+                         (long) (stop_t.tv_usec - start_t.tv_usec) % 1000,
+                             portal_name)));
+     }
+
+     if (save_log_statement_stats)
+         ShowUsage("QUERY STATISTICS");
+
      debug_query_string = NULL;
  }