Re: [HACKERS] log_statement output for protocol - Mailing list pgsql-patches

Guillaume Smet wrote:
> On 8/29/06, Bruce Momjian <bruce@momjian.us> wrote:
> > Good point.  I thought it was clear enough, but obviously not.  I had a
> > similar case with bind, and used a comma to separate them:
> >
> >         LOG:  statement: prepare sel1, SELECT $1;
> >         LOG:  statement: bind sel1, $1 = 'a''b'
>
> For this one, I must admit I prefer the colon we used before.
> Something like:
> LOG:  statement: prepare sel1: SELECT $1;
> LOG:  statement: bind sel1: $1 = 'a''b'
> seems better to me as after the colon, we have the details of the
> command which is the common sense of a colon.

OK, done.

> > I am concerned a dash isn't clear enough, and a semicolon is confusing.
> > Using a comma the new output is:
> >
> >         LOG:  duration: 0.023 ms  execute sel1
> >         DETAIL:  prepare: SELECT $1;,  bind: $1 = 'a''b'
>
> A dash is clearer in this case IMHO. ;, is not very readable. But I
> can parse easily both forms so it's not a problem for me if you prefer
> a comma.

I thought about this, and because we are placing two pieces of
information on the same line, it seems "|" is the best choice.

> > Is that OK?  Patch attached and committed.  I also fixed the null bind
> > parameter bug.  It now displays $1 = NULL (no quotes used).
>
> Cool. I'll test that.
>
> > Other suggestions?
>
> I'll compile this new version and make tests in the next few days to
> check everything is consistent and let you know.
>
> I'm still struggling to find a regexp good enough to parse "statement:
> execute y ('a', 4, 'text, with a comma'::text);" :).

Oh.  You want to pull the parameters out of that.  I am thinking you
need something that will go over the line character by character with
some type of state machine, rather than just regex.

> Thanks a lot for your work on this subject. It will help us a lot when
> we use the JDBC driver.

Patch attached and applied.  New output:

    LOG:  statement: begin;
    LOG:  statement: prepare x as select $1::text;
    LOG:  statement: execute x ('a');
    DETAIL:  prepare: prepare x as select $1::text;
    LOG:  statement: commit;
    LOG:  statement: set log_statement = 'none';
    LOG:  duration: 0.222 ms  statement: set log_min_duration_statement = 0;
    LOG:  duration: 0.061 ms  statement: begin;
    LOG:  duration: 0.113 ms  statement: prepare y as select $1::text;
    LOG:  duration: 0.213 ms  statement: execute y ('a');
    DETAIL:  prepare: prepare y as select $1::text;
    LOG:  duration: 0.081 ms  statement: commit;
    LOG:  statement: prepare sel1: SELECT $1;
    LOG:  statement: bind sel1: $1 = 'a''b'
    DETAIL:  prepare: SELECT $1;
    LOG:  statement: execute sel1
    DETAIL:  prepare: SELECT $1;  |  bind: $1 = 'a''b'
    LOG:  duration: 0.445 ms  statement: SET log_min_duration_statement = 0;
    LOG:  duration: 0.018 ms  execute sel1
    DETAIL:  prepare: SELECT $1;  |  bind: $1 = 'a''b'

Additional comments?

--
  Bruce Momjian   bruce@momjian.us
  EnterpriseDB    http://www.enterprisedb.com

  + If your life is a hard drive, Christ can be your backup. +
Index: src/backend/tcop/postgres.c
===================================================================
RCS file: /cvsroot/pgsql/src/backend/tcop/postgres.c,v
retrieving revision 1.502
diff -c -c -r1.502 postgres.c
*** src/backend/tcop/postgres.c    29 Aug 2006 20:10:42 -0000    1.502
--- src/backend/tcop/postgres.c    30 Aug 2006 17:59:05 -0000
***************
*** 1146,1152 ****

      if (log_statement == LOGSTMT_ALL)
          ereport(LOG,
!                 (errmsg("statement: prepare %s, %s",
                          *stmt_name ? stmt_name : "<unnamed>",
                          query_string)));

--- 1146,1152 ----

      if (log_statement == LOGSTMT_ALL)
          ereport(LOG,
!                 (errmsg("statement: prepare %s: %s",
                          *stmt_name ? stmt_name : "<unnamed>",
                          query_string)));

***************
*** 1621,1627 ****
                          *portal->name ? "/" : "",
                          *portal->name ? portal->name : "",
                          /* print bind parameters if we have them */
!                         bind_values_str.len ? ", " : "",
                          bind_values_str.len ? bind_values_str.data : ""),
                          errdetail("prepare: %s", pstmt->query_string)));
      }
--- 1621,1627 ----
                          *portal->name ? "/" : "",
                          *portal->name ? portal->name : "",
                          /* print bind parameters if we have them */
!                         bind_values_str.len ? ": " : "",
                          bind_values_str.len ? bind_values_str.data : ""),
                          errdetail("prepare: %s", pstmt->query_string)));
      }
***************
*** 1788,1794 ****
                          *portal_name ? portal_name : ""),
                          errdetail("prepare: %s%s%s", sourceText,
                          /* optionally print bind parameters */
!                         bindText ? ",  bind: " : "",
                          bindText ? bindText : "")));

      BeginCommand(portal->commandTag, dest);
--- 1788,1794 ----
                          *portal_name ? portal_name : ""),
                          errdetail("prepare: %s%s%s", sourceText,
                          /* optionally print bind parameters */
!                         bindText ? "  |  bind: " : "",
                          bindText ? bindText : "")));

      BeginCommand(portal->commandTag, dest);
***************
*** 1902,1908 ****
                                  *portal_name ? portal_name : ""),
                                  errdetail("prepare: %s%s%s", sourceText,
                                  /* optionally print bind parameters */
!                                 bindText ? ",  bind: " : "",
                                  bindText ? bindText : "")));
          }
      }
--- 1902,1908 ----
                                  *portal_name ? portal_name : ""),
                                  errdetail("prepare: %s%s%s", sourceText,
                                  /* optionally print bind parameters */
!                                 bindText ? "  |  bind: " : "",
                                  bindText ? bindText : "")));
          }
      }