Movatterモバイル変換

[0]ホーム
URL:

Skip to content

Navigation Menu

Sign in
Appearance settings

Search code, repositories, users, issues, pull requests...

Provide feedback

We read every piece of feedback, and take your input very seriously.

Saved searches

Use saved searches to filter your results more quickly

 Sign up
Appearance settings

Commitc0ac38d

Browse files
committed
Log queries for client-side prepare/execute. Simon Riggs
Log prepare query during execute. Bruce Momjian
1 parentf534820 commitc0ac38d

File tree

2 files changed

+174
-68
lines changed

2 files changed

+174
-68
lines changed

‎src/backend/commands/prepare.c‎

Lines changed: 6 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -10,7 +10,7 @@
1010
* Copyright (c) 2002-2005, PostgreSQL Global Development Group
1111
*
1212
* IDENTIFICATION
13-
* $PostgreSQL: pgsql/src/backend/commands/prepare.c,v 1.36 2005/01/01 05:43:06 momjian Exp $
13+
* $PostgreSQL: pgsql/src/backend/commands/prepare.c,v 1.37 2005/05/24 04:18:04 momjian Exp $
1414
*
1515
*-------------------------------------------------------------------------
1616
*/
@@ -104,9 +104,12 @@ PrepareQuery(PrepareStmt *stmt)
104104
/* Generate plans for queries.Snapshot is already set. */
105105
plan_list=pg_plan_queries(query_list,NULL, false);
106106

107-
/* Save the results. */
107+
/*
108+
*Save the results. We don't have the query string for this PREPARE,
109+
*but we do have the string we got from the client, so use that.
110+
*/
108111
StorePreparedStatement(stmt->name,
109-
NULL,/* text form not available */
112+
debug_query_string,
110113
commandTag,
111114
query_list,
112115
plan_list,

‎src/backend/tcop/postgres.c‎

Lines changed: 168 additions & 65 deletions
Original file line numberDiff line numberDiff line change
@@ -8,7 +8,7 @@
88
*
99
*
1010
* IDENTIFICATION
11-
* $PostgreSQL: pgsql/src/backend/tcop/postgres.c,v 1.443 2005/04/21 19:18:13 tgl Exp $
11+
* $PostgreSQL: pgsql/src/backend/tcop/postgres.c,v 1.444 2005/05/24 04:18:04 momjian Exp $
1212
*
1313
* NOTES
1414
* this is the "main" module of the postgres backend and
@@ -82,9 +82,6 @@ boolLog_disconnections = false;
8282

8383
LogStmtLevellog_statement=LOGSTMT_NONE;
8484

85-
/* flag indicating if the statement satisfies log_statement */
86-
boolstatement_logged;
87-
8885
/* GUC variable for maximum stack depth (measured in kilobytes) */
8986
intmax_stack_depth=2048;
9087

@@ -152,6 +149,8 @@ static intUseNewLine = 0;/* Use EOF as query delimiters */
152149
staticintInteractiveBackend(StringInfoinBuf);
153150
staticintSocketBackend(StringInfoinBuf);
154151
staticintReadCommand(StringInfoinBuf);
152+
staticboollog_after_parse(List*raw_parsetree_list,
153+
constchar*query_string,char**prepare_string);
155154
staticvoidstart_xact_command(void);
156155
staticvoidfinish_xact_command(void);
157156
staticvoidSigHupHandler(SIGNAL_ARGS);
@@ -465,74 +464,94 @@ List *
465464
pg_parse_query(constchar*query_string)
466465
{
467466
List*raw_parsetree_list;
468-
ListCell*parsetree_item;
469-
470-
statement_logged= false;
471-
if (log_statement==LOGSTMT_ALL)
472-
{
473-
ereport(LOG,
474-
(errmsg("statement: %s",query_string)));
475-
statement_logged= true;
476-
}
477467

478468
if (log_parser_stats)
479469
ResetUsage();
480470

481471
raw_parsetree_list=raw_parser(query_string);
482472

483-
/* do log_statement tests for mod and ddl */
484-
if (log_statement==LOGSTMT_MOD||
485-
log_statement==LOGSTMT_DDL)
473+
if (log_parser_stats)
474+
ShowUsage("PARSER STATISTICS");
475+
476+
returnraw_parsetree_list;
477+
}
478+
479+
staticbool
480+
log_after_parse(List*raw_parsetree_list,constchar*query_string,
481+
char**prepare_string)
482+
{
483+
ListCell*parsetree_item;
484+
boollog_this_statement= (log_statement==LOGSTMT_ALL);
485+
486+
*prepare_string=NULL;
487+
488+
/*Check if we need to log the statement, and get prepare_string. */
489+
foreach(parsetree_item,raw_parsetree_list)
486490
{
487-
foreach(parsetree_item,raw_parsetree_list)
491+
Node*parsetree= (Node*)lfirst(parsetree_item);
492+
constchar*commandTag;
493+
494+
if (IsA(parsetree,ExplainStmt)&&
495+
((ExplainStmt*)parsetree)->analyze)
496+
parsetree= (Node*) (((ExplainStmt*)parsetree)->query);
497+
498+
if (IsA(parsetree,PrepareStmt))
499+
parsetree= (Node*) (((PrepareStmt*)parsetree)->query);
500+
501+
if (IsA(parsetree,SelectStmt))
502+
continue;/* optimization for frequent command */
503+
504+
if (log_statement==LOGSTMT_MOD&&
505+
(IsA(parsetree,InsertStmt)||
506+
IsA(parsetree,UpdateStmt)||
507+
IsA(parsetree,DeleteStmt)||
508+
IsA(parsetree,TruncateStmt)||
509+
(IsA(parsetree,CopyStmt)&&
510+
((CopyStmt*)parsetree)->is_from)))/* COPY FROM */
511+
log_this_statement= true;
512+
513+
commandTag=CreateCommandTag(parsetree);
514+
if ((log_statement==LOGSTMT_MOD||
515+
log_statement==LOGSTMT_DDL)&&
516+
(strncmp(commandTag,"CREATE ",strlen("CREATE "))==0||
517+
strncmp(commandTag,"ALTER ",strlen("ALTER "))==0||
518+
strncmp(commandTag,"DROP ",strlen("DROP "))==0||
519+
IsA(parsetree,GrantStmt)||/* GRANT or REVOKE */
520+
IsA(parsetree,CommentStmt)))
521+
log_this_statement= true;
522+
523+
/*
524+
*For the first EXECUTE we find, record the client statement
525+
*used by the PREPARE.
526+
*/
527+
if (IsA(parsetree,ExecuteStmt))
488528
{
489-
Node*parsetree= (Node*)lfirst(parsetree_item);
490-
constchar*commandTag;
491-
492-
if (IsA(parsetree,ExplainStmt)&&
493-
((ExplainStmt*)parsetree)->analyze)
494-
parsetree= (Node*) (((ExplainStmt*)parsetree)->query);
495-
496-
if (IsA(parsetree,PrepareStmt))
497-
parsetree= (Node*) (((PrepareStmt*)parsetree)->query);
498-
499-
if (IsA(parsetree,SelectStmt))
500-
continue;/* optimization for frequent command */
501-
502-
if (log_statement==LOGSTMT_MOD&&
503-
(IsA(parsetree,InsertStmt)||
504-
IsA(parsetree,UpdateStmt)||
505-
IsA(parsetree,DeleteStmt)||
506-
IsA(parsetree,TruncateStmt)||
507-
(IsA(parsetree,CopyStmt)&&
508-
((CopyStmt*)parsetree)->is_from)))/* COPY FROM */
509-
{
510-
ereport(LOG,
511-
(errmsg("statement: %s",query_string)));
512-
statement_logged= true;
513-
break;
514-
}
515-
commandTag=CreateCommandTag(parsetree);
516-
if (strncmp(commandTag,"CREATE ",strlen("CREATE "))==0||
517-
strncmp(commandTag,"ALTER ",strlen("ALTER "))==0||
518-
strncmp(commandTag,"DROP ",strlen("DROP "))==0||
519-
IsA(parsetree,GrantStmt)||/* GRANT or REVOKE */
520-
IsA(parsetree,CommentStmt))
529+
ExecuteStmt*stmt= (ExecuteStmt*)parsetree;
530+
PreparedStatement*entry;
531+
532+
if ((entry=FetchPreparedStatement(stmt->name, false))!=NULL&&
533+
entry->query_string)
521534
{
522-
ereport(LOG,
523-
(errmsg("statement: %s",query_string)));
524-
statement_logged= true;
525-
break;
535+
*prepare_string=palloc(strlen(entry->query_string)+
536+
strlen(" [client PREPARE: %s]")-1);
537+
sprintf(*prepare_string," [client PREPARE: %s]",
538+
entry->query_string);
526539
}
527540
}
528541
}
529-
530-
if (log_parser_stats)
531-
ShowUsage("PARSER STATISTICS");
532-
533-
returnraw_parsetree_list;
542+
543+
if (log_this_statement)
544+
{
545+
ereport(LOG,
546+
(errmsg("statement: %s%s",query_string,
547+
*prepare_string ?*prepare_string :"")));
548+
return true;
549+
}
550+
else
551+
return false;
534552
}
535553

554+
536555
/*
537556
* Given a raw parsetree (gram.y output), and optionally information about
538557
* types of parameter symbols ($n), perform parse analysis and rule rewriting.
@@ -735,12 +754,13 @@ exec_simple_query(const char *query_string)
735754
MemoryContextoldcontext;
736755
List*parsetree_list;
737756
ListCell*parsetree_item;
738-
structtimevalstart_t,
739-
stop_t;
757+
structtimevalstart_t,stop_t;
740758
boolsave_log_duration=log_duration;
741759
intsave_log_min_duration_statement=log_min_duration_statement;
742760
boolsave_log_statement_stats=log_statement_stats;
743-
761+
char*prepare_string=NULL;
762+
boolwas_logged= false;
763+
744764
/*
745765
* Report query to various monitoring facilities.
746766
*/
@@ -796,6 +816,10 @@ exec_simple_query(const char *query_string)
796816
*/
797817
parsetree_list=pg_parse_query(query_string);
798818

819+
if (log_statement!=LOGSTMT_NONE||save_log_min_duration_statement!=-1)
820+
was_logged=log_after_parse(parsetree_list,query_string,
821+
&prepare_string);
822+
799823
/*
800824
* Switch back to transaction context to enter the loop.
801825
*/
@@ -1011,10 +1035,11 @@ exec_simple_query(const char *query_string)
10111035
stop_t.tv_sec--;
10121036
stop_t.tv_usec+=1000000;
10131037
}
1014-
usecs= (long) (stop_t.tv_sec-start_t.tv_sec)*1000000+ (long) (stop_t.tv_usec-start_t.tv_usec);
1038+
usecs= (long) (stop_t.tv_sec-start_t.tv_sec)*1000000+
1039+
(long) (stop_t.tv_usec-start_t.tv_usec);
10151040

10161041
/* Only print duration if we previously printed the statement. */
1017-
if (statement_logged&&save_log_duration)
1042+
if (was_logged&&save_log_duration)
10181043
ereport(LOG,
10191044
(errmsg("duration: %ld.%03ld ms",
10201045
(long) ((stop_t.tv_sec-start_t.tv_sec)*1000+
@@ -1029,16 +1054,20 @@ exec_simple_query(const char *query_string)
10291054
(save_log_min_duration_statement>0&&
10301055
usecs >=save_log_min_duration_statement*1000))
10311056
ereport(LOG,
1032-
(errmsg("duration: %ld.%03ld ms statement: %s",
1057+
(errmsg("duration: %ld.%03ld ms statement: %s%s",
10331058
(long) ((stop_t.tv_sec-start_t.tv_sec)*1000+
10341059
(stop_t.tv_usec-start_t.tv_usec) /1000),
10351060
(long) (stop_t.tv_usec-start_t.tv_usec) %1000,
1036-
query_string)));
1061+
query_string,
1062+
prepare_string ?prepare_string :"")));
10371063
}
10381064

10391065
if (save_log_statement_stats)
10401066
ShowUsage("QUERY STATISTICS");
10411067

1068+
if (prepare_string!=NULL)
1069+
pfree(prepare_string);
1070+
10421071
debug_query_string=NULL;
10431072
}
10441073

@@ -1074,6 +1103,10 @@ exec_parse_message(const char *query_string,/* string to execute */
10741103
if (save_log_statement_stats)
10751104
ResetUsage();
10761105

1106+
if (log_statement==LOGSTMT_ALL)
1107+
ereport(LOG,
1108+
(errmsg("statement: PREPARE %s AS %s",stmt_name,query_string)));
1109+
10771110
/*
10781111
* Start up a transaction command so we can run parse analysis etc.
10791112
* (Note that this will normally change current memory context.)
@@ -1371,6 +1404,10 @@ exec_bind_message(StringInfo input_message)
13711404
else
13721405
portal=CreatePortal(portal_name, false, false);
13731406

1407+
if (log_statement==LOGSTMT_ALL)
1408+
ereport(LOG,
1409+
(errmsg("statement: <BIND> %s",portal_name)));
1410+
13741411
/*
13751412
* Fetch parameters, if any, and store in the portal's memory context.
13761413
*
@@ -1579,6 +1616,10 @@ exec_execute_message(const char *portal_name, long max_rows)
15791616
boolis_trans_exit= false;
15801617
boolcompleted;
15811618
charcompletionTag[COMPLETION_TAG_BUFSIZE];
1619+
structtimevalstart_t,stop_t;
1620+
boolsave_log_duration=log_duration;
1621+
intsave_log_min_duration_statement=log_min_duration_statement;
1622+
boolsave_log_statement_stats=log_statement_stats;
15821623

15831624
/* Adjust destination to tell printtup.c what to do */
15841625
dest=whereToSendOutput;
@@ -1615,6 +1656,24 @@ exec_execute_message(const char *portal_name, long max_rows)
16151656

16161657
set_ps_display(portal->commandTag);
16171658

1659+
/*
1660+
* We use save_log_* so "SET log_duration = true" and "SET
1661+
* log_min_duration_statement = true" don't report incorrect time
1662+
* because gettimeofday() wasn't called. Similarly,
1663+
* log_statement_stats has to be captured once.
1664+
*/
1665+
if (save_log_duration||save_log_min_duration_statement!=-1)
1666+
gettimeofday(&start_t,NULL);
1667+
1668+
if (save_log_statement_stats)
1669+
ResetUsage();
1670+
1671+
if (log_statement==LOGSTMT_ALL)
1672+
/* We have the portal, so output the source query. */
1673+
ereport(LOG,
1674+
(errmsg("statement: EXECUTE %s [PREPARE: %s]",portal_name,
1675+
portal->sourceText ?portal->sourceText :"")));
1676+
16181677
BeginCommand(portal->commandTag,dest);
16191678

16201679
/* Check for transaction-control commands */
@@ -1709,6 +1768,50 @@ exec_execute_message(const char *portal_name, long max_rows)
17091768
pq_putemptymessage('s');
17101769
}
17111770

1771+
/*
1772+
* Combine processing here as we need to calculate the query duration
1773+
* in both instances.
1774+
*/
1775+
if (save_log_duration||save_log_min_duration_statement!=-1)
1776+
{
1777+
longusecs;
1778+
1779+
gettimeofday(&stop_t,NULL);
1780+
if (stop_t.tv_usec<start_t.tv_usec)
1781+
{
1782+
stop_t.tv_sec--;
1783+
stop_t.tv_usec+=1000000;
1784+
}
1785+
usecs= (long) (stop_t.tv_sec-start_t.tv_sec)*1000000+
1786+
(long) (stop_t.tv_usec-start_t.tv_usec);
1787+
1788+
/* Only print duration if we previously printed the statement. */
1789+
if (log_statement==LOGSTMT_ALL&&save_log_duration)
1790+
ereport(LOG,
1791+
(errmsg("duration: %ld.%03ld ms",
1792+
(long) ((stop_t.tv_sec-start_t.tv_sec)*1000+
1793+
(stop_t.tv_usec-start_t.tv_usec) /1000),
1794+
(long) (stop_t.tv_usec-start_t.tv_usec) %1000)));
1795+
1796+
/*
1797+
* Output a duration_statement to the log if the query has
1798+
* exceeded the min duration, or if we are to print all durations.
1799+
*/
1800+
if (save_log_min_duration_statement==0||
1801+
(save_log_min_duration_statement>0&&
1802+
usecs >=save_log_min_duration_statement*1000))
1803+
ereport(LOG,
1804+
(errmsg("duration: %ld.%03ld ms statement: EXECUTE %s [PREPARE: %s]",
1805+
(long) ((stop_t.tv_sec-start_t.tv_sec)*1000+
1806+
(stop_t.tv_usec-start_t.tv_usec) /1000),
1807+
(long) (stop_t.tv_usec-start_t.tv_usec) %1000,
1808+
portal_name,
1809+
portal->sourceText ?portal->sourceText :"")));
1810+
}
1811+
1812+
if (save_log_statement_stats)
1813+
ShowUsage("QUERY STATISTICS");
1814+
17121815
debug_query_string=NULL;
17131816
}
17141817

0 commit comments

Comments
 (0)
[8]ページ先頭
©2009-2025 Movatter.jp