Обсуждение: PGStatement#setPrepareThreshold
Hi all, Question: will PGStatement.setPrepareThreshold(1) cause server side prepare to be used already on the first execution, or only after the second one ? The problem: I want to force server side prepare at least for some of the queries on my system, as the query plan is completely bad if the server knows the parameters when planning (due to null values in IN list, nothing to be fixed in my application unless I completely rewrite some parts of it). I couldn't figure out this from the log files... postgres logs the queries as <unnamed>, but that doesn't tell me too much. Is there a way to force server side prepare from the first query ? Thanks, Csaba.
Csaba Nagy wrote: > Hi all, > > Question: will PGStatement.setPrepareThreshold(1) cause server side > prepare to be used already on the first execution, or only after the > second one ? It should cause it to be used on the first execution (at least that was the intent) The logic looks like: - On statement creation set count=0 - On each execution: - If this statement is a PreparedStatement, increment count - If threshold == 0 or count < threshold, make this execution "oneshot" - Execute query "oneshot" queries use the unnamed statement (with one exception: queries that will be backed by a portal use a named statement) > I couldn't figure out this from the log files... postgres logs the > queries as <unnamed>, but that doesn't tell me too much. If you're seeing <unnamed> then those queries aren't using server-side prepare (the unnamed statement is also special as it's the trigger for the planner behaviour that you are trying to avoid..) .. so it seems that you are not managing to trigger server-side prepare for some reason. Maybe you are using a plain Statement? -O
Oliver, Thanks for your answer. > The logic looks like: > - On statement creation set count=0 > - On each execution: > - If this statement is a PreparedStatement, increment count > - If threshold == 0 or count < threshold, make this execution "oneshot" > - Execute query OK, I've checked the sources. I'm using postgresql-jdbc-8.1dev-400. The relevant piece of code looks to me to be in AbstractJdbc2Statement#execute(Query,ParameterList,int): // Only use named statements after we hit the threshold if (preparedQuery != null) { ++m_useCount; // We used this statement once more. if (m_prepareThreshold == 0 || m_useCount < m_prepareThreshold) flags |= QueryExecutor.QUERY_ONESHOT; } So if preparedQuery is not null for prepared statements, it should work as you said... > "oneshot" queries use the unnamed statement (with one exception: queries > that will be backed by a portal use a named statement) > > > I couldn't figure out this from the log files... postgres logs the > > queries as <unnamed>, but that doesn't tell me too much. > > If you're seeing <unnamed> then those queries aren't using server-side > prepare (the unnamed statement is also special as it's the trigger for > the planner behaviour that you are trying to avoid..) .. so it seems > that you are not managing to trigger server-side prepare for some > reason. Maybe you are using a plain Statement? No, I definitely use a prepared statement, I have lots of parameters in the IN clause... that's part of the problem. And I checked again, and it is logged as <unnamed> in the postgres logs. So the only remaining suspect is that the threshold is not really set to 1. This is somewhat strange, as I use a connection pool and set it to 1 on each connection, and only set it to 0 on specific statements where I do want the parameter values to be taken into account (I know, I'll have to change this, but it was the easiest way to get the system stable after switching from Oracle to postgres). I will have to investigate what is the real problem. Thanks, Csaba.
Csaba, Actually I was debugging some other code and noticed that it doesn't really get set, this just confirms my suspicions. I'll try to get something out in a few hours Dave On 3-Aug-06, at 5:17 AM, Csaba Nagy wrote: > Oliver, > > Thanks for your answer. > >> The logic looks like: >> - On statement creation set count=0 >> - On each execution: >> - If this statement is a PreparedStatement, increment count >> - If threshold == 0 or count < threshold, make this execution >> "oneshot" >> - Execute query > > OK, I've checked the sources. I'm using postgresql-jdbc-8.1dev-400. > The relevant piece of code looks to me to be in > AbstractJdbc2Statement#execute(Query,ParameterList,int): > > // Only use named statements after we hit the threshold > if (preparedQuery != null) > { > ++m_useCount; // We used this statement once more. > if (m_prepareThreshold == 0 || m_useCount < > m_prepareThreshold) > flags |= QueryExecutor.QUERY_ONESHOT; > } > > So if preparedQuery is not null for prepared statements, it should > work > as you said... > >> "oneshot" queries use the unnamed statement (with one exception: >> queries >> that will be backed by a portal use a named statement) >> >>> I couldn't figure out this from the log files... postgres logs the >>> queries as <unnamed>, but that doesn't tell me too much. >> >> If you're seeing <unnamed> then those queries aren't using server- >> side >> prepare (the unnamed statement is also special as it's the trigger >> for >> the planner behaviour that you are trying to avoid..) .. so it seems >> that you are not managing to trigger server-side prepare for some >> reason. Maybe you are using a plain Statement? > > No, I definitely use a prepared statement, I have lots of > parameters in > the IN clause... that's part of the problem. And I checked again, > and it > is logged as <unnamed> in the postgres logs. > > So the only remaining suspect is that the threshold is not really > set to > 1. This is somewhat strange, as I use a connection pool and set it > to 1 > on each connection, and only set it to 0 on specific statements > where I > do want the parameter values to be taken into account (I know, I'll > have > to change this, but it was the easiest way to get the system stable > after switching from Oracle to postgres). > > I will have to investigate what is the real problem. > > Thanks, > Csaba. > > > > > > ---------------------------(end of > broadcast)--------------------------- > TIP 2: Don't 'kill -9' the postmaster >
Ok, further investigation shows that it does work However I'm still puzzled by these backend logs <test test>LOG: statement: PREPARE S_3 AS INSERT INTO texttable (te) VALUES ($1) <test test>LOG: statement: <BIND> <test test>LOG: statement: EXECUTE <unnamed> [PREPARE: INSERT INTO texttable (te) VALUES ($1)] We see the prepare to a named statement, but then the execute is unnamed ? Dave On 3-Aug-06, at 7:53 AM, Dave Cramer wrote: > Csaba, > > Actually I was debugging some other code and noticed that it > doesn't really get set, this just confirms my suspicions. I'll try > to get something out in a few hours > > Dave > On 3-Aug-06, at 5:17 AM, Csaba Nagy wrote: > >> Oliver, >> >> Thanks for your answer. >> >>> The logic looks like: >>> - On statement creation set count=0 >>> - On each execution: >>> - If this statement is a PreparedStatement, increment count >>> - If threshold == 0 or count < threshold, make this execution >>> "oneshot" >>> - Execute query >> >> OK, I've checked the sources. I'm using postgresql-jdbc-8.1dev-400. >> The relevant piece of code looks to me to be in >> AbstractJdbc2Statement#execute(Query,ParameterList,int): >> >> // Only use named statements after we hit the threshold >> if (preparedQuery != null) >> { >> ++m_useCount; // We used this statement once more. >> if (m_prepareThreshold == 0 || m_useCount < >> m_prepareThreshold) >> flags |= QueryExecutor.QUERY_ONESHOT; >> } >> >> So if preparedQuery is not null for prepared statements, it should >> work >> as you said... >> >>> "oneshot" queries use the unnamed statement (with one exception: >>> queries >>> that will be backed by a portal use a named statement) >>> >>>> I couldn't figure out this from the log files... postgres logs the >>>> queries as <unnamed>, but that doesn't tell me too much. >>> >>> If you're seeing <unnamed> then those queries aren't using server- >>> side >>> prepare (the unnamed statement is also special as it's the >>> trigger for >>> the planner behaviour that you are trying to avoid..) .. so it seems >>> that you are not managing to trigger server-side prepare for some >>> reason. Maybe you are using a plain Statement? >> >> No, I definitely use a prepared statement, I have lots of >> parameters in >> the IN clause... that's part of the problem. And I checked again, >> and it >> is logged as <unnamed> in the postgres logs. >> >> So the only remaining suspect is that the threshold is not really >> set to >> 1. This is somewhat strange, as I use a connection pool and set it >> to 1 >> on each connection, and only set it to 0 on specific statements >> where I >> do want the parameter values to be taken into account (I know, >> I'll have >> to change this, but it was the easiest way to get the system stable >> after switching from Oracle to postgres). >> >> I will have to investigate what is the real problem. >> >> Thanks, >> Csaba. >> >> >> >> >> >> ---------------------------(end of >> broadcast)--------------------------- >> TIP 2: Don't 'kill -9' the postmaster >> > > > ---------------------------(end of > broadcast)--------------------------- > TIP 2: Don't 'kill -9' the postmaster >
Dave Cramer <pg@fastcrypt.com> writes: > However I'm still puzzled by these backend logs > <test test>LOG: statement: PREPARE S_3 AS INSERT INTO texttable (te) > VALUES ($1) > <test test>LOG: statement: <BIND> > <test test>LOG: statement: EXECUTE <unnamed> [PREPARE: INSERT INTO > texttable (te) VALUES ($1)] > We see the prepare to a named statement, but then the execute is > unnamed ? What it's showing you there is the name of the protocol-level portal; evidently you're using the unnamed portal to execute the INSERT. This does demonstrate once again that the current approach to logging parse/bind/execute operations is entirely wrongheaded, because it deliberately confuses the protocol and SQL levels. I see that Bruce has changed CVS tip so that the message is <test test>LOG: statement: [protocol] EXECUTE <unnamed> [PREPARE: INSERT INTO texttable (te) VALUES ($1)] but I hardly think that's going to be enough to de-confuse people. All those brackets just serve to make things *more* confusing IMHO. What I'd like to see is something like this: Simple Query produces LOG: statement: ...statement text here... Parse produces LOG: parse statement-name: ...statement text here... Bind produces LOG: bind portal-name to statement-name (someday print arguments here) Execute produces LOG: execute portal-name: ...statement text here... No brackets, no pretending that an Execute message is the same thing as a SQL EXECUTE command or that Parse is the same as PREPARE. regards, tom lane
On 3-Aug-06, at 3:59 PM, Tom Lane wrote: > Dave Cramer <pg@fastcrypt.com> writes: >> However I'm still puzzled by these backend logs > >> <test test>LOG: statement: PREPARE S_3 AS INSERT INTO texttable (te) >> VALUES ($1) >> <test test>LOG: statement: <BIND> >> <test test>LOG: statement: EXECUTE <unnamed> [PREPARE: INSERT INTO >> texttable (te) VALUES ($1)] > >> We see the prepare to a named statement, but then the execute is >> unnamed ? > > What it's showing you there is the name of the protocol-level portal; > evidently you're using the unnamed portal to execute the INSERT. If that's the case then the driver is not doing what it's supposed to be doing. It should be using the named portal (S_3) to do the insert. Dave > > This does demonstrate once again that the current approach to logging > parse/bind/execute operations is entirely wrongheaded, because it > deliberately confuses the protocol and SQL levels. I see that Bruce > has changed CVS tip so that the message is > > <test test>LOG: statement: [protocol] EXECUTE <unnamed> > [PREPARE: INSERT INTO > texttable (te) VALUES ($1)] > > but I hardly think that's going to be enough to de-confuse people. > All those brackets just serve to make things *more* confusing IMHO. > > What I'd like to see is something like this: > > Simple Query produces > > LOG: statement: ...statement text here... > > Parse produces > > LOG: parse statement-name: ...statement text here... > > Bind produces > > LOG: bind portal-name to statement-name (someday print arguments > here) > > Execute produces > > LOG: execute portal-name: ...statement text here... > > No brackets, no pretending that an Execute message is the same thing > as a SQL EXECUTE command or that Parse is the same as PREPARE. > > regards, tom lane > > ---------------------------(end of > broadcast)--------------------------- > TIP 5: don't forget to increase your free space map settings >
Dave Cramer wrote: > If that's the case then the driver is not doing what it's supposed to be > doing. It should be using the named portal (S_3) to do the insert. No, the driver is fine. It is using a named statement (S_3) but an unnamed portal (because it is going to fetch all the data in one go and doesn't need to retain the portal after execution) If your query met the conditions for using a portal-based ResultSet, you'd see it use a named portal as well as a named statement. -O
On 3-Aug-06, at 6:14 PM, Oliver Jowett wrote: > Dave Cramer wrote: > >> If that's the case then the driver is not doing what it's supposed >> to be doing. It should be using the named portal (S_3) to do the >> insert. > > No, the driver is fine. It is using a named statement (S_3) but an > unnamed portal (because it is going to fetch all the data in one go > and doesn't need to retain the portal after execution) > > If your query met the conditions for using a portal-based > ResultSet, you'd see it use a named portal as well as a named > statement. Thanks for clarifying that Oliver, the logs are still misleading in that they don't name the statement used in the bind message. --dc-- > > -O >
Dave Cramer <pg@fastcrypt.com> writes: > Thanks for clarifying that Oliver, the logs are still misleading in > that they don't name the statement used in the bind message. Pretty much exactly my point. The distinction between statement name and portal name is critical at the protocol level and has no real counterpart at the SQL level (prepared statement name vs cursor name is similar but I think not exactly the same namespaces). The logging code is not getting this right. regards, tom lane
Dave Cramer wrote: > > On 3-Aug-06, at 6:14 PM, Oliver Jowett wrote: > > > Dave Cramer wrote: > > > >> If that's the case then the driver is not doing what it's supposed > >> to be doing. It should be using the named portal (S_3) to do the > >> insert. > > > > No, the driver is fine. It is using a named statement (S_3) but an > > unnamed portal (because it is going to fetch all the data in one go > > and doesn't need to retain the portal after execution) > > > > If your query met the conditions for using a portal-based > > ResultSet, you'd see it use a named portal as well as a named > > statement. > > Thanks for clarifying that Oliver, the logs are still misleading in > that they don't name the statement used in the bind message. Current CVS has: (errmsg("statement: [protocol] <BIND> %s", portal_name))); -- Bruce Momjian bruce@momjian.us EnterpriseDB http://www.enterprisedb.com + If your life is a hard drive, Christ can be your backup. +
One complexity of changing the prefix to not use "statement:" is that log_statement does control this output. Changing that might cause confusion, especially for scripts that process the logs. How do you like "statement: <protocol execute>"? --------------------------------------------------------------------------- Tom Lane wrote: > Dave Cramer <pg@fastcrypt.com> writes: > > However I'm still puzzled by these backend logs > > > <test test>LOG: statement: PREPARE S_3 AS INSERT INTO texttable (te) > > VALUES ($1) > > <test test>LOG: statement: <BIND> > > <test test>LOG: statement: EXECUTE <unnamed> [PREPARE: INSERT INTO > > texttable (te) VALUES ($1)] > > > We see the prepare to a named statement, but then the execute is > > unnamed ? > > What it's showing you there is the name of the protocol-level portal; > evidently you're using the unnamed portal to execute the INSERT. > > This does demonstrate once again that the current approach to logging > parse/bind/execute operations is entirely wrongheaded, because it > deliberately confuses the protocol and SQL levels. I see that Bruce > has changed CVS tip so that the message is > > <test test>LOG: statement: [protocol] EXECUTE <unnamed> [PREPARE: INSERT INTO > texttable (te) VALUES ($1)] > > but I hardly think that's going to be enough to de-confuse people. > All those brackets just serve to make things *more* confusing IMHO. > > What I'd like to see is something like this: > > Simple Query produces > > LOG: statement: ...statement text here... > > Parse produces > > LOG: parse statement-name: ...statement text here... > > Bind produces > > LOG: bind portal-name to statement-name (someday print arguments here) > > Execute produces > > LOG: execute portal-name: ...statement text here... > > No brackets, no pretending that an Execute message is the same thing > as a SQL EXECUTE command or that Parse is the same as PREPARE. > > regards, tom lane -- Bruce Momjian bruce@momjian.us EnterpriseDB http://www.enterprisedb.com + If your life is a hard drive, Christ can be your backup. +
On 3-Aug-06, at 11:55 PM, Bruce Momjian wrote: > Dave Cramer wrote: >> >> On 3-Aug-06, at 6:14 PM, Oliver Jowett wrote: >> >>> Dave Cramer wrote: >>> >>>> If that's the case then the driver is not doing what it's supposed >>>> to be doing. It should be using the named portal (S_3) to do the >>>> insert. >>> >>> No, the driver is fine. It is using a named statement (S_3) but an >>> unnamed portal (because it is going to fetch all the data in one go >>> and doesn't need to retain the portal after execution) >>> >>> If your query met the conditions for using a portal-based >>> ResultSet, you'd see it use a named portal as well as a named >>> statement. >> >> Thanks for clarifying that Oliver, the logs are still misleading in >> that they don't name the statement used in the bind message. > > Current CVS has: > > (errmsg("statement: [protocol] <BIND> %s", portal_name))); Bind also has a statement name, as well as a portal name ? Ideally I'd like to see the parameters which were bound and the types, but I suspect I'm reaching here. > > -- > Bruce Momjian bruce@momjian.us > EnterpriseDB http://www.enterprisedb.com > > + If your life is a hard drive, Christ can be your backup. + > > ---------------------------(end of > broadcast)--------------------------- > TIP 5: don't forget to increase your free space map settings >
Dave Cramer wrote: > > On 3-Aug-06, at 11:55 PM, Bruce Momjian wrote: > > > Dave Cramer wrote: > >> > >> On 3-Aug-06, at 6:14 PM, Oliver Jowett wrote: > >> > >>> Dave Cramer wrote: > >>> > >>>> If that's the case then the driver is not doing what it's supposed > >>>> to be doing. It should be using the named portal (S_3) to do the > >>>> insert. > >>> > >>> No, the driver is fine. It is using a named statement (S_3) but an > >>> unnamed portal (because it is going to fetch all the data in one go > >>> and doesn't need to retain the portal after execution) > >>> > >>> If your query met the conditions for using a portal-based > >>> ResultSet, you'd see it use a named portal as well as a named > >>> statement. > >> > >> Thanks for clarifying that Oliver, the logs are still misleading in > >> that they don't name the statement used in the bind message. > > > > Current CVS has: > > > > (errmsg("statement: [protocol] <BIND> %s", portal_name))); > > Bind also has a statement name, as well as a portal name ? > > Ideally I'd like to see the parameters which were bound and the > types, but I suspect I'm reaching here. Right, but do we want to repeat the statement for every bind case? The bind parameter printing is on the TODO list. -- Bruce Momjian bruce@momjian.us EnterpriseDB http://www.enterprisedb.com + If your life is a hard drive, Christ can be your backup. +
Bruce Momjian <bruce@momjian.us> writes: > Dave Cramer wrote: >> Bind also has a statement name, as well as a portal name ? >> >> Ideally I'd like to see the parameters which were bound and the >> types, but I suspect I'm reaching here. > Right, but do we want to repeat the statement for every bind case? My upthread proposal was to print the statement and portal names at bind time. The current printout is very clearly inadequate. > The bind parameter printing is on the TODO list. Yeah, that one's a bit harder to fix :-( It would be relatively easy for the case of parameters supplied in text form, but I'm not sure about binary values. Is JDBC doing anything with binary parameter transmission yet? regards, tom lane
Tom Lane wrote: > Bruce Momjian <bruce@momjian.us> writes: > > Dave Cramer wrote: > >> Bind also has a statement name, as well as a portal name ? > >> > >> Ideally I'd like to see the parameters which were bound and the > >> types, but I suspect I'm reaching here. > > > Right, but do we want to repeat the statement for every bind case? > > My upthread proposal was to print the statement and portal names > at bind time. The current printout is very clearly inadequate. Sure, I can do that. Did you like my idea of? statement: <protocol execute> ... You didn't reply. I want to keep the "statement:" prefix for scripts that process our log files, and because it is output by log_statement, which controls protocol output as well. > > The bind parameter printing is on the TODO list. > > Yeah, that one's a bit harder to fix :-( It would be relatively > easy for the case of parameters supplied in text form, but I'm > not sure about binary values. Is JDBC doing anything with binary > parameter transmission yet? Should we just output text if we have it? How do we know if they parameters are text? The data type? -- Bruce Momjian bruce@momjian.us EnterpriseDB http://www.enterprisedb.com + If your life is a hard drive, Christ can be your backup. +
> Right, but do we want to repeat the statement for every bind case? I'm talking only for myself, but printing the parameter values alone would be already a huge win. I enable the printing of IP+port in the logs, so I can easily trace back the parameters to the statement if the statement is logged too... On the other hand, I usually only enable statement logging with log_min_duration_statement, and there I would like to see both statemnt and params... would that work ? Thanks, Csaba.
On 4-Aug-06, at 12:19 PM, Tom Lane wrote: > Bruce Momjian <bruce@momjian.us> writes: >> Dave Cramer wrote: >>> Bind also has a statement name, as well as a portal name ? >>> >>> Ideally I'd like to see the parameters which were bound and the >>> types, but I suspect I'm reaching here. > >> Right, but do we want to repeat the statement for every bind case? > > My upthread proposal was to print the statement and portal names > at bind time. The current printout is very clearly inadequate. > >> The bind parameter printing is on the TODO list. > > Yeah, that one's a bit harder to fix :-( It would be relatively > easy for the case of parameters supplied in text form, but I'm > not sure about binary values. Is JDBC doing anything with binary > parameter transmission yet? No we aren't, even if we were, just printing the text values would be a huge step forward. Dave > > regards, tom lane >
On Fri, 4 Aug 2006, Dave Cramer wrote: > On 4-Aug-06, at 12:19 PM, Tom Lane wrote: > >> Yeah, that one's a bit harder to fix :-( It would be relatively >> easy for the case of parameters supplied in text form, but I'm >> not sure about binary values. Is JDBC doing anything with binary >> parameter transmission yet? > > No we aren't, even if we were, just printing the text values would be a > huge step forward. > Actually bytea parameters are sent as binary to the server in prepared statements. For fastpath calls integer, oid, and bytea parameters are sent in binary form. Kris Jurka
bruce wrote: > Tom Lane wrote: > > Bruce Momjian <bruce@momjian.us> writes: > > > Dave Cramer wrote: > > >> Bind also has a statement name, as well as a portal name ? > > >> > > >> Ideally I'd like to see the parameters which were bound and the > > >> types, but I suspect I'm reaching here. > > > > > Right, but do we want to repeat the statement for every bind case? > > > > My upthread proposal was to print the statement and portal names > > at bind time. The current printout is very clearly inadequate. > > Sure, I can do that. > > Did you like my idea of? > > statement: <protocol execute> ... > > You didn't reply. I want to keep the "statement:" prefix for scripts > that process our log files, and because it is output by log_statement, > which controls protocol output as well. I have applied this patch to output the statemented referenced by BIND. I also changed the "[protocol]" string to "<protocol>" for clarity. I am ready to pull PREPARE|BIND|EXECUTED into the "protocol" bracket too if someone says that is a good idea. -- 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.493 diff -c -c -r1.493 postgres.c *** src/backend/tcop/postgres.c 29 Jul 2006 03:02:56 -0000 1.493 --- src/backend/tcop/postgres.c 4 Aug 2006 18:50:59 -0000 *************** *** 1146,1153 **** if (log_statement == LOGSTMT_ALL) ereport(LOG, ! (errmsg("statement: [protocol] PREPARE %s AS %s", ! (*stmt_name != '\0') ? stmt_name : "<unnamed>", query_string))); /* --- 1146,1153 ---- if (log_statement == LOGSTMT_ALL) ereport(LOG, ! (errmsg("statement: <protocol> PREPARE %s AS %s", ! *stmt_name ? stmt_name : "<unnamed>", query_string))); /* *************** *** 1452,1458 **** /* We need to output the parameter values someday */ if (log_statement == LOGSTMT_ALL) ereport(LOG, ! (errmsg("statement: [protocol] <BIND> %s", portal_name))); /* * Fetch parameters, if any, and store in the portal's memory context. --- 1452,1460 ---- /* We need to output the parameter values someday */ if (log_statement == LOGSTMT_ALL) ereport(LOG, ! (errmsg("statement: <protocol> <BIND> %s [PREPARE: %s]", ! *portal_name ? portal_name : "<unnamed>", ! portal->sourceText ? portal->sourceText : ""))); /* * Fetch parameters, if any, and store in the portal's memory context. *************** *** 1718,1726 **** if (log_statement == LOGSTMT_ALL) /* We have the portal, so output the source query. */ ereport(LOG, ! (errmsg("statement: [protocol] %sEXECUTE %s [PREPARE: %s]", execute_is_fetch ? "FETCH from " : "", ! (*portal_name) ? portal_name : "<unnamed>", portal->sourceText ? portal->sourceText : ""))); BeginCommand(portal->commandTag, dest); --- 1720,1728 ---- if (log_statement == LOGSTMT_ALL) /* We have the portal, so output the source query. */ ereport(LOG, ! (errmsg("statement: <protocol> %sEXECUTE %s [PREPARE: %s]", execute_is_fetch ? "FETCH from " : "", ! *portal_name ? portal_name : "<unnamed>", portal->sourceText ? portal->sourceText : ""))); BeginCommand(portal->commandTag, dest); *************** *** 1826,1836 **** secs, msecs))); else ereport(LOG, ! (errmsg("duration: %ld.%03d ms statement: [protocol] %sEXECUTE %s [PREPARE: %s]", secs, msecs, execute_is_fetch ? "FETCH from " : "", ! (*portal_name) ? portal_name : "<unnamed>", ! portal->sourceText ? portal->sourceText : ""))); } } --- 1828,1838 ---- secs, msecs))); else ereport(LOG, ! (errmsg("duration: %ld.%03d ms statement: <protocol> %sEXECUTE %s [PREPARE: %s]", secs, msecs, execute_is_fetch ? "FETCH from " : "", ! *portal_name ? portal_name : "<unnamed>", ! portal->sourceText ? portal->sourceText : ""))); } }
Bruce Momjian <bruce@momjian.us> writes: > Did you like my idea of? > statement: <protocol execute> ... No. > I want to keep the "statement:" prefix for scripts > that process our log files, and because it is output by log_statement, > which controls protocol output as well. I think that's an irrelevant consideration, but it's driving you to insist on unnecessarily complicated, confusing output. What's wrong with "parse:", "bind:", and "execute:"? If you really must have the word "statement" in there, then let's do "parse statement:" "bind statement:" and "execute statement:". In any case we've got to drop all the brackets and braces, they look too much like they might be part of the statement string. regards, tom lane
Bruce, Doesn't it make more sense to use the statement name ? If I prepare S_3 as "select * from foo" then the bind log is going to show me "select * from foo" not S_3 I think in the case of named statements I'd prefer "S_3" however as I think about this in the case of unnamed statements I'd prefer the "select * from foo" Comments ? Dave On 4-Aug-06, at 2:56 PM, Bruce Momjian wrote: > bruce wrote: >> Tom Lane wrote: >>> Bruce Momjian <bruce@momjian.us> writes: >>>> Dave Cramer wrote: >>>>> Bind also has a statement name, as well as a portal name ? >>>>> >>>>> Ideally I'd like to see the parameters which were bound and the >>>>> types, but I suspect I'm reaching here. >>> >>>> Right, but do we want to repeat the statement for every bind case? >>> >>> My upthread proposal was to print the statement and portal names >>> at bind time. The current printout is very clearly inadequate. >> >> Sure, I can do that. >> >> Did you like my idea of? >> >> statement: <protocol execute> ... >> >> You didn't reply. I want to keep the "statement:" prefix for scripts >> that process our log files, and because it is output by >> log_statement, >> which controls protocol output as well. > > I have applied this patch to output the statemented referenced by > BIND. > I also changed the "[protocol]" string to "<protocol>" for clarity. I > am ready to pull PREPARE|BIND|EXECUTED into the "protocol" bracket too > if someone says that is a good idea. > > -- > 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.493 > diff -c -c -r1.493 postgres.c > *** src/backend/tcop/postgres.c 29 Jul 2006 03:02:56 -0000 1.493 > --- src/backend/tcop/postgres.c 4 Aug 2006 18:50:59 -0000 > *************** > *** 1146,1153 **** > > if (log_statement == LOGSTMT_ALL) > ereport(LOG, > ! (errmsg("statement: [protocol] PREPARE %s AS %s", > ! (*stmt_name != '\0') ? stmt_name : "<unnamed>", > query_string))); > > /* > --- 1146,1153 ---- > > if (log_statement == LOGSTMT_ALL) > ereport(LOG, > ! (errmsg("statement: <protocol> PREPARE %s AS %s", > ! *stmt_name ? stmt_name : "<unnamed>", > query_string))); > > /* > *************** > *** 1452,1458 **** > /* We need to output the parameter values someday */ > if (log_statement == LOGSTMT_ALL) > ereport(LOG, > ! (errmsg("statement: [protocol] <BIND> %s", portal_name))); > > /* > * Fetch parameters, if any, and store in the portal's memory > context. > --- 1452,1460 ---- > /* We need to output the parameter values someday */ > if (log_statement == LOGSTMT_ALL) > ereport(LOG, > ! (errmsg("statement: <protocol> <BIND> %s [PREPARE: %s]", > ! *portal_name ? portal_name : "<unnamed>", > ! portal->sourceText ? portal->sourceText : ""))); > > /* > * Fetch parameters, if any, and store in the portal's memory > context. > *************** > *** 1718,1726 **** > if (log_statement == LOGSTMT_ALL) > /* We have the portal, so output the source query. */ > ereport(LOG, > ! (errmsg("statement: [protocol] %sEXECUTE %s [PREPARE: %s]", > execute_is_fetch ? "FETCH from " : "", > ! (*portal_name) ? portal_name : "<unnamed>", > portal->sourceText ? portal->sourceText : ""))); > > BeginCommand(portal->commandTag, dest); > --- 1720,1728 ---- > if (log_statement == LOGSTMT_ALL) > /* We have the portal, so output the source query. */ > ereport(LOG, > ! (errmsg("statement: <protocol> %sEXECUTE %s [PREPARE: %s]", > execute_is_fetch ? "FETCH from " : "", > ! *portal_name ? portal_name : "<unnamed>", > portal->sourceText ? portal->sourceText : ""))); > > BeginCommand(portal->commandTag, dest); > *************** > *** 1826,1836 **** > secs, msecs))); > else > ereport(LOG, > ! (errmsg("duration: %ld.%03d ms statement: [protocol] % > sEXECUTE %s [PREPARE: %s]", > secs, msecs, > execute_is_fetch ? "FETCH from " : "", > ! (*portal_name) ? portal_name : "<unnamed>", > ! portal->sourceText ? portal->sourceText : ""))); > } > } > > --- 1828,1838 ---- > secs, msecs))); > else > ereport(LOG, > ! (errmsg("duration: %ld.%03d ms statement: <protocol> % > sEXECUTE %s [PREPARE: %s]", > secs, msecs, > execute_is_fetch ? "FETCH from " : "", > ! *portal_name ? portal_name : "<unnamed>", > ! portal->sourceText ? portal->sourceText : ""))); > } > } >
Dave Cramer wrote: > Bruce, > > Doesn't it make more sense to use the statement name ? > > If I prepare S_3 as "select * from foo" > > then the bind log is going to show me "select * from foo" not S_3 > > I think in the case of named statements I'd prefer "S_3" however as I > think about this in the case of unnamed statements I'd prefer the > "select * from foo" The bind shows: (errmsg("statement: <protocol> <BIND> %s [PREPARE: %s]", The first %s is the statement name, and the second %s is the query. -- Bruce Momjian bruce@momjian.us EnterpriseDB http://www.enterprisedb.com + If your life is a hard drive, Christ can be your backup. +
Bruce Momjian <bruce@momjian.us> writes: > ! (errmsg("statement: [protocol] <BIND> %s", portal_name))); > --- 1452,1460 ---- > ! (errmsg("statement: <protocol> <BIND> %s [PREPARE: %s]", > ! *portal_name ? portal_name : "<unnamed>", > ! portal->sourceText ? portal->sourceText : ""))); This is getting less readable not more so; and you still haven't got the prepared statement's name in there, let alone any place to put the parameter values. Perhaps we should give up on the idea that this can all fit on one log line? Maybe LOG: parse: <statement-name> DETAIL: statement: <source-text> LOG: bind: <portal-name> to <statement-name> DETAIL: statement: <source-text> parameter 1: <parameter value> parameter 2: <parameter value> ... LOG: execute: <portal-name> DETAIL: statement: <source-text> The $64 question here is whether we want to repeat the source-text in all three messages (parse, bind, execute) or try to reduce the verbosity. regards, tom lane
Tom Lane wrote: > Bruce Momjian <bruce@momjian.us> writes: > > ! (errmsg("statement: [protocol] <BIND> %s", portal_name))); > > > --- 1452,1460 ---- > > ! (errmsg("statement: <protocol> <BIND> %s [PREPARE: %s]", > > ! *portal_name ? portal_name : "<unnamed>", > > ! portal->sourceText ? portal->sourceText : ""))); > > This is getting less readable not more so; and you still haven't got the > prepared statement's name in there, let alone any place to put the > parameter values. I thought the portal name was the statement name. Seems I was wrong. > Perhaps we should give up on the idea that this can all fit on one log > line? Maybe > > LOG: parse: <statement-name> > DETAIL: statement: <source-text> > > LOG: bind: <portal-name> to <statement-name> > DETAIL: statement: <source-text> > parameter 1: <parameter value> > parameter 2: <parameter value> > ... > > LOG: execute: <portal-name> > DETAIL: statement: <source-text> > > The $64 question here is whether we want to repeat the source-text > in all three messages (parse, bind, execute) or try to reduce the > verbosity. We don't print DETAIL in the logs, do we? Does anyone have C code that uses these features so I can test? -- Bruce Momjian bruce@momjian.us EnterpriseDB http://www.enterprisedb.com + If your life is a hard drive, Christ can be your backup. +
bruce wrote: > > The $64 question here is whether we want to repeat the source-text > > in all three messages (parse, bind, execute) or try to reduce the > > verbosity. > > We don't print DETAIL in the logs, do we? > > Does anyone have C code that uses these features so I can test? I made a libpq test program and will work on improving the log output. -- Bruce Momjian bruce@momjian.us EnterpriseDB http://www.enterprisedb.com + If your life is a hard drive, Christ can be your backup. +
Bruce Momjian <bruce@momjian.us> writes: > The bind shows: > (errmsg("statement: <protocol> <BIND> %s [PREPARE: %s]", > The first %s is the statement name, and the second %s is the query. No, it's the portal name. There's a difference. regards, tom lane
Bruce Momjian <bruce@momjian.us> writes: > We don't print DETAIL in the logs, do we? Yes, we do, unless you've set log_error_verbosity to less than the default. regards, tom lane