From ca4c29d496a9b3eefda6e6f287c3d31f3e4bb0f6 Mon Sep 17 00:00:00 2001 From: Heikki Linnakangas Date: Thu, 16 Nov 2017 10:08:15 +0200 Subject: [PATCH] Remove attempt to make EXPLAIN print something even on error. Compared to upstream, there was a bunch of changes to the error handling in EXPLAIN, to try to catch errors and produce EXPLAIN output even when an error happens. I don't understand how it was supposed to work, but I don't remember it ever doing anything too useful. And it has the strange effect that if an ERROR happens during EXPLAIN ANALYZE, it is reported to the client as merely a NOTICE. So, revert this to the way it is in the upstream. Also reorder the end-of-EXPLAIN steps so that the "Total runtime" is printed at the very end, like in the upstream. I don't see any reason to differ from upstream on that, and this makes the "Total runtime" numbers more comparable with PostgreSQL's, for what it's worth. I dug up the commit that made these changes in the old git repository, from before GPDB was open sourced: --- commit 1413010e71cb8eae860160ac9d5246216b2a80b4 Date: Thu Apr 12 12:34:18 2007 -0800 MPP-1177. EXPLAIN ANALYZE now can usually produce a report, perhaps a partial one, even if the query encounters a runtime error. The Slice Statistics indicate 'ok' for slices whose worker processes all completed successfully; otherwise it shows how many workers returned errors, were canceled, or were not dispatched. The error message from EXPLAIN in such cases will appear as a NOTICE instead of an ERROR. The client is first sent a successful completion response, followed by the NOTICE. (psql displays the NOTICE before the EXPLAIN report, however.) Although presented to the client as a NOTICE, the backend handles it just like an ERROR with regard to logging, rollback, etc. --- I couldn't figure out under what circumstances that would be helpful, and couldn't come up with an example. Perhaps it used to work differently when it was originally committed, but not anymore? I also looked up the MPP-1177 ticket in the old bug tracking system. The description for that was: --- EXPLAIN ANALYZE should report on the amount of data spilled to temporary workfiles on disk, and how much work_mem would be required to complete the query without spilling to disk. ---- Unfortunately, that description, and the comments that followed it, didn't say anything about suppressing errors or being able to print out EXPLAIN output even if an error happens. So I don't know why that change was made as part of MPP-1177. It was seemingly for a different issue. --- src/backend/commands/explain.c | 175 ++++++--------------------------- 1 file changed, 32 insertions(+), 143 deletions(-) diff --git a/src/backend/commands/explain.c b/src/backend/commands/explain.c index 94fa54c0bb..1c42d36eef 100644 --- a/src/backend/commands/explain.c +++ b/src/backend/commands/explain.c @@ -76,7 +76,6 @@ typedef struct ExplainState /* CDB */ struct CdbExplain_ShowStatCtx *showstatctx; /* EXPLAIN ANALYZE info */ Slice *currentSlice; /* slice whose nodes we are visiting */ - ErrorData *deferredError; /* caught error to be re-thrown */ } ExplainState; extern bool Test_print_direct_dispatch_info; @@ -96,7 +95,6 @@ static void ExplainDXL(Query *query, ExplainStmt *stmt, static void ExplainCodegen(PlanState *planstate, TupOutputState *tstate); #endif static double elapsed_time(instr_time *starttime); -static ErrorData *explain_defer_error(ExplainState *es); static void explain_outNode(StringInfo str, Plan *plan, PlanState *planstate, Plan *outer_plan, Plan *parentPlan, @@ -217,7 +215,6 @@ ExplainDXL(Query *query, ExplainStmt *stmt, const char *queryString, /* Initialize ExplainState structure. */ memset(es, 0, sizeof(*es)); es->showstatctx = NULL; - es->deferredError = NULL; es->pstmt = NULL; initStringInfo(&buf); @@ -378,7 +375,6 @@ ExplainOnePlan(PlannedStmt *plannedstmt, ParamListInfo params, EState *estate = NULL; int eflags; char *settings; - MemoryContext explaincxt = CurrentMemoryContext; /* * Use a snapshot with an updated command ID to ensure this query sees @@ -458,37 +454,14 @@ ExplainOnePlan(PlannedStmt *plannedstmt, ParamListInfo params, es->currentSlice = getCurrentSlice(estate, LocallyExecutingSliceIndex(estate)); /* Execute the plan for statistics if asked for */ - /* In GPDB, we attempt to proceed with our report even if there is an error. - */ if (stmt->analyze) { /* run the plan */ - PG_TRY(); - { - ExecutorRun(queryDesc, ForwardScanDirection, 0L); - } - PG_CATCH(); - { - MemoryContextSwitchTo(explaincxt); - es->deferredError = explain_defer_error(es); - } - PG_END_TRY(); - - /* Wait for completion of all qExec processes. */ - PG_TRY(); - { - if (estate->dispatcherState && estate->dispatcherState->primaryResults) - { - CdbCheckDispatchResult(estate->dispatcherState, - DISPATCH_WAIT_NONE); - } - } - PG_CATCH(); - { - MemoryContextSwitchTo(explaincxt); - es->deferredError = explain_defer_error(es); - } - PG_END_TRY(); + ExecutorRun(queryDesc, ForwardScanDirection, 0L); + + /* Wait for completion of all qExec processes. */ + if (estate->dispatcherState && estate->dispatcherState->primaryResults) + CdbCheckDispatchResult(estate->dispatcherState, DISPATCH_WAIT_NONE); /* Suspend timing. */ totaltime += elapsed_time(&starttime); @@ -514,10 +487,8 @@ ExplainOnePlan(PlannedStmt *plannedstmt, ParamListInfo params, initStringInfo(&buf); /* - * Produce the EXPLAIN report into buf. (Sometimes we get internal errors - * while doing this; try to proceed with a partial report anyway.) + * Produce the EXPLAIN report into buf. */ - PG_TRY(); { int indent = 0; CmdType cmd = queryDesc->plannedstmt->commandType; @@ -570,24 +541,21 @@ ExplainOnePlan(PlannedStmt *plannedstmt, ParamListInfo params, explain_outNode(&buf, childPlan, queryDesc->planstate, NULL, NULL, indent, es); } - PG_CATCH(); - { - MemoryContextSwitchTo(explaincxt); - es->deferredError = explain_defer_error(es); - - /* Keep a NUL at the end of the output buffer. */ - buf.data[Min(buf.len, buf.maxlen-1)] = '\0'; - } - PG_END_TRY(); /* * If we ran the command, run any AFTER triggers it queued. (Note this * will not include DEFERRED triggers; since those don't run until end of * transaction, we can't measure them.) Include into total runtime. - * Skip triggers if there has been an error. */ - if (es->printAnalyze && - !es->deferredError) + if (stmt->analyze) + { + INSTR_TIME_SET_CURRENT(starttime); + AfterTriggerEndQuery(queryDesc->estate); + totaltime += elapsed_time(&starttime); + } + + /* Print info about runtime of triggers */ + if (es->printAnalyze) { ResultRelInfo *rInfo; bool show_relname; @@ -596,11 +564,6 @@ ExplainOnePlan(PlannedStmt *plannedstmt, ParamListInfo params, int nr; ListCell *l; - - INSTR_TIME_SET_CURRENT(starttime); - AfterTriggerEndQuery(queryDesc->estate); - totaltime += elapsed_time(&starttime); - show_relname = (numrels > 1 || targrels != NIL); rInfo = queryDesc->estate->es_result_relations; for (nr = 0; nr < numrels; rInfo++, nr++) @@ -640,72 +603,32 @@ ExplainOnePlan(PlannedStmt *plannedstmt, ParamListInfo params, } #endif - totaltime += elapsed_time(&starttime); - - /* - * Display final elapsed time. - */ - if (stmt->analyze) - appendStringInfo(&buf, "Total runtime: %.3f ms\n", - 1000.0 * totaltime); - - /* - * Send EXPLAIN report to client. Some might have been sent already - * by explain_outNode(). - */ - if (buf.len > 0) - do_text_output_multiline(tstate, buf.data); - - pfree(buf.data); - - /* - * Close down the query and free resources. - * - * For EXPLAIN ANALYZE, if a qExec failed or gave an error, ExecutorEnd() - * will reissue the error locally at this point. Intercept any such error - * and reduce it to a NOTICE so it won't interfere with our output. + /* + * Close down the query and free resources. Include time for this in the + * total runtime (although it should be pretty minimal). */ - PG_TRY(); - { - ExecutorEnd(queryDesc); - } - PG_CATCH(); - { - MemoryContextSwitchTo(explaincxt); - es->deferredError = explain_defer_error(es); - } - PG_END_TRY(); - - /* - * If we intercepted an error, now's the time to re-throw it. - * Although we have marked it as a NOTICE instead of an ERROR, - * it will still get the same error handling and cleanup treatment. - * - * We must call EndCommand() to send a successful completion response; - * otherwise libpq clients just discard the nice report they have received. - * Oddly, the NOTICE will be sent *after* the success response; that - * should be good enough for now. - */ - if (es->deferredError) - { - ErrorData *edata = es->deferredError; + INSTR_TIME_SET_CURRENT(starttime); - /* Tell client the command ended successfully. */ - EndCommand("EXPLAIN", tstate->dest->mydest); - - /* Resume handling the error. Clean up and send the NOTICE message. */ - es->deferredError = NULL; - ReThrowError(edata); - } + ExecutorEnd(queryDesc); - FreeQueryDesc(queryDesc); + FreeQueryDesc(queryDesc); PopActiveSnapshot(); /* We need a CCI just in case query expanded to multiple plans */ if (stmt->analyze) CommandCounterIncrement(); -} /* ExplainOnePlan_internal */ + + totaltime += elapsed_time(&starttime); + + if (stmt->analyze) + appendStringInfo(&buf, "Total runtime: %.3f ms\n", + 1000.0 * totaltime); + do_text_output_multiline(tstate, buf.data); + + pfree(buf.data); + pfree(es); +} /* * report_triggers - @@ -764,40 +687,6 @@ elapsed_time(instr_time *starttime) } -/* - * explain_defer_error - * Called within PG_CATCH handler to demote and save the current error. - * - * We'll try to postpone the error cleanup until after we have produced - * the EXPLAIN ANALYZE report, and then reflect the error to the client as - * merely a NOTICE (because an ERROR causes libpq clients to discard the - * report). - * - * If successful, upon return we fall thru the bottom of the PG_CATCH - * handler and continue sequentially. Otherwise we re-throw to the - * next outer error handler. - */ -static ErrorData * -explain_defer_error(ExplainState *es) -{ - ErrorData *edata; - - /* Already saved an earlier error? Rethrow it now. */ - if (es->deferredError) - ReThrowError(es->deferredError); /* does not return */ - - /* Try to downgrade the error to a NOTICE. Rethrow if disallowed. */ - if (!elog_demote(NOTICE)) - PG_RE_THROW(); - - /* Save the error info and expunge it from the error system. */ - edata = CopyErrorData(); - FlushErrorState(); - - /* Caller must eventually ReThrowError() for proper cleanup. */ - return edata; -} /* explain_defer_error */ - static void appendGangAndDirectDispatchInfo(StringInfo str, PlanState *planstate, int sliceId) { -- GitLab