Index: src/backend/commands/prepare.c =================================================================== RCS file: /cvsroot/pgsql/src/backend/commands/prepare.c,v retrieving revision 1.36 diff -c -c -r1.36 prepare.c *** src/backend/commands/prepare.c 1 Jan 2005 05:43:06 -0000 1.36 --- src/backend/commands/prepare.c 20 May 2005 14:15:12 -0000 *************** *** 104,112 **** /* Generate plans for queries. Snapshot is already set. */ plan_list = pg_plan_queries(query_list, NULL, false); ! /* Save the results. */ StorePreparedStatement(stmt->name, ! NULL, /* text form not available */ commandTag, query_list, plan_list, --- 104,115 ---- /* Generate plans for queries. Snapshot is already set. */ plan_list = pg_plan_queries(query_list, NULL, false); ! /* ! * Save the results. We don't have the query string for this PREPARE, ! * but we do have the string we got from the client, so use that. ! */ StorePreparedStatement(stmt->name, ! debug_query_string, commandTag, query_list, plan_list, 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 20 May 2005 14:15:17 -0000 *************** *** 82,90 **** LogStmtLevel log_statement = LOGSTMT_NONE; - /* flag indicating if the statement satisfies log_statement */ - bool statement_logged; - /* GUC variable for maximum stack depth (measured in kilobytes) */ int max_stack_depth = 2048; --- 82,87 ---- *************** *** 152,157 **** --- 149,156 ---- static int InteractiveBackend(StringInfo inBuf); static int SocketBackend(StringInfo inBuf); static int ReadCommand(StringInfo inBuf); + static bool log_after_parse(List *raw_parsetree_list, + const char *query_string, char **prepare_string); static void start_xact_command(void); static void finish_xact_command(void); static void SigHupHandler(SIGNAL_ARGS); *************** *** 465,538 **** pg_parse_query(const char *query_string) { List *raw_parsetree_list; - ListCell *parsetree_item; - - statement_logged = false; - if (log_statement == LOGSTMT_ALL) - { - ereport(LOG, - (errmsg("statement: %s", query_string))); - statement_logged = true; - } if (log_parser_stats) ResetUsage(); raw_parsetree_list = raw_parser(query_string); - /* do log_statement tests for mod and ddl */ - if (log_statement == LOGSTMT_MOD || - log_statement == LOGSTMT_DDL) - { - foreach(parsetree_item, raw_parsetree_list) - { - Node *parsetree = (Node *) lfirst(parsetree_item); - const char *commandTag; - - if (IsA(parsetree, ExplainStmt) && - ((ExplainStmt *) parsetree)->analyze) - parsetree = (Node *) (((ExplainStmt *) parsetree)->query); - - if (IsA(parsetree, PrepareStmt)) - parsetree = (Node *) (((PrepareStmt *) parsetree)->query); - - if (IsA(parsetree, SelectStmt)) - continue; /* optimization for frequent command */ - - if (log_statement == LOGSTMT_MOD && - (IsA(parsetree, InsertStmt) || - IsA(parsetree, UpdateStmt) || - IsA(parsetree, DeleteStmt) || - IsA(parsetree, TruncateStmt) || - (IsA(parsetree, CopyStmt) && - ((CopyStmt *) parsetree)->is_from))) /* COPY FROM */ - { - ereport(LOG, - (errmsg("statement: %s", query_string))); - statement_logged = true; - break; - } - commandTag = CreateCommandTag(parsetree); - if (strncmp(commandTag, "CREATE ", strlen("CREATE ")) == 0 || - strncmp(commandTag, "ALTER ", strlen("ALTER ")) == 0 || - strncmp(commandTag, "DROP ", strlen("DROP ")) == 0 || - IsA(parsetree, GrantStmt) || /* GRANT or REVOKE */ - IsA(parsetree, CommentStmt)) - { - ereport(LOG, - (errmsg("statement: %s", query_string))); - statement_logged = true; - break; - } - } - } - if (log_parser_stats) ShowUsage("PARSER STATISTICS"); return raw_parsetree_list; } /* * Given a raw parsetree (gram.y output), and optionally information about * types of parameter symbols ($n), perform parse analysis and rule rewriting. --- 464,557 ---- pg_parse_query(const char *query_string) { List *raw_parsetree_list; if (log_parser_stats) ResetUsage(); raw_parsetree_list = raw_parser(query_string); if (log_parser_stats) ShowUsage("PARSER STATISTICS"); return raw_parsetree_list; } + static bool + log_after_parse(List *raw_parsetree_list, const char *query_string, + char **prepare_string) + { + ListCell *parsetree_item; + bool log_this_statement = (log_statement == LOGSTMT_ALL); + + *prepare_string = NULL; + + /* Check if we need to log the statement, and get prepare_string. */ + foreach(parsetree_item, raw_parsetree_list) + { + Node *parsetree = (Node *) lfirst(parsetree_item); + const char *commandTag; + + if (IsA(parsetree, ExplainStmt) && + ((ExplainStmt *) parsetree)->analyze) + parsetree = (Node *) (((ExplainStmt *) parsetree)->query); + + if (IsA(parsetree, PrepareStmt)) + parsetree = (Node *) (((PrepareStmt *) parsetree)->query); + + if (IsA(parsetree, SelectStmt)) + continue; /* optimization for frequent command */ + + if (log_statement == LOGSTMT_MOD && + (IsA(parsetree, InsertStmt) || + IsA(parsetree, UpdateStmt) || + IsA(parsetree, DeleteStmt) || + IsA(parsetree, TruncateStmt) || + (IsA(parsetree, CopyStmt) && + ((CopyStmt *) parsetree)->is_from))) /* COPY FROM */ + log_this_statement = true; + + commandTag = CreateCommandTag(parsetree); + if ((log_statement == LOGSTMT_MOD || + log_statement == LOGSTMT_DDL) && + (strncmp(commandTag, "CREATE ", strlen("CREATE ")) == 0 || + strncmp(commandTag, "ALTER ", strlen("ALTER ")) == 0 || + strncmp(commandTag, "DROP ", strlen("DROP ")) == 0 || + IsA(parsetree, GrantStmt) || /* GRANT or REVOKE */ + IsA(parsetree, CommentStmt))) + log_this_statement = true; + + /* + * For the first EXECUTE we find, record the client statement + * used by the PREPARE. + */ + if (IsA(parsetree, ExecuteStmt)) + { + ExecuteStmt *stmt = (ExecuteStmt *) parsetree; + PreparedStatement *entry; + + if ((entry = FetchPreparedStatement(stmt->name, false)) != NULL && + entry->query_string) + { + *prepare_string = palloc(strlen(entry->query_string) + + strlen(" [client PREPARE: %s]") - 1); + sprintf(*prepare_string, " [client PREPARE: %s]", + entry->query_string); + } + } + } + + if (log_this_statement) + { + ereport(LOG, + (errmsg("statement: %s%s", query_string, + *prepare_string ? *prepare_string : ""))); + return true; + } + else + return false; + } + + /* * Given a raw parsetree (gram.y output), and optionally information about * types of parameter symbols ($n), perform parse analysis and rule rewriting. *************** *** 735,746 **** MemoryContext oldcontext; List *parsetree_list; ListCell *parsetree_item; ! 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; ! /* * Report query to various monitoring facilities. */ --- 754,766 ---- MemoryContext oldcontext; List *parsetree_list; ListCell *parsetree_item; ! 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; ! char *prepare_string = NULL; ! bool was_logged = false; ! /* * Report query to various monitoring facilities. */ *************** *** 796,801 **** --- 816,825 ---- */ parsetree_list = pg_parse_query(query_string); + if (log_statement != LOGSTMT_NONE || save_log_min_duration_statement != -1) + was_logged = log_after_parse(parsetree_list, query_string, + &prepare_string); + /* * Switch back to transaction context to enter the loop. */ *************** *** 1011,1020 **** 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 + --- 1035,1045 ---- 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 (was_logged && save_log_duration) ereport(LOG, (errmsg("duration: %ld.%03ld ms", (long) ((stop_t.tv_sec - start_t.tv_sec) * 1000 + *************** *** 1029,1044 **** (save_log_min_duration_statement > 0 && usecs >= save_log_min_duration_statement * 1000)) ereport(LOG, ! (errmsg("duration: %ld.%03ld ms statement: %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, ! query_string))); } if (save_log_statement_stats) ShowUsage("QUERY STATISTICS"); debug_query_string = NULL; } --- 1054,1073 ---- (save_log_min_duration_statement > 0 && usecs >= save_log_min_duration_statement * 1000)) ereport(LOG, ! (errmsg("duration: %ld.%03ld ms statement: %s%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, ! query_string, ! prepare_string ? prepare_string : ""))); } if (save_log_statement_stats) ShowUsage("QUERY STATISTICS"); + if (prepare_string != NULL) + pfree(prepare_string); + debug_query_string = NULL; } *************** *** 1074,1079 **** --- 1103,1112 ---- if (save_log_statement_stats) ResetUsage(); + if (log_statement == LOGSTMT_ALL) + ereport(LOG, + (errmsg("statement: PREPARE %s AS %s", stmt_name, query_string))); + /* * Start up a transaction command so we can run parse analysis etc. * (Note that this will normally change current memory context.) *************** *** 1371,1376 **** --- 1404,1413 ---- else portal = CreatePortal(portal_name, false, false); + if (log_statement == LOGSTMT_ALL) + ereport(LOG, + (errmsg("statement: %s", portal_name))); + /* * Fetch parameters, if any, and store in the portal's memory context. * *************** *** 1579,1584 **** --- 1616,1625 ---- 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 **** --- 1656,1679 ---- 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(); + + if (log_statement == LOGSTMT_ALL) + /* We have the portal, so output the source query. */ + ereport(LOG, + (errmsg("statement: EXECUTE %s [PREPARE: %s]", portal_name, + portal->sourceText ? portal->sourceText : ""))); + BeginCommand(portal->commandTag, dest); /* Check for transaction-control commands */ *************** *** 1709,1714 **** --- 1768,1817 ---- 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 (log_statement == LOGSTMT_ALL && 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 [PREPARE: %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, + portal->sourceText ? portal->sourceText : ""))); + } + + if (save_log_statement_stats) + ShowUsage("QUERY STATISTICS"); + debug_query_string = NULL; }