Re: pg16: XX000: could not find pathkey item to sort

[David Rowley]

On Mon, 9 Oct 2023 at 12:42, David Rowley <dgrowle...@gmail.com> wrote:
> Maybe it's worth checking the total planning time spent in a run of
> the regression tests with and without the patch to see how much
> overhead it adds to the "average case".

I've now pushed the patch that trims off the Pathkeys for the ORDER BY
/ DISTINCT aggregates.

As for the patch to verify the pathkeys during create plan, I patched
master with the attached plan_times.patch.txt and used the following
to check the time spent in the planner for 3 runs of make
installcheck.

$ for i in {1..3}; do pg_ctl start -D pgdata -l plantime.log >
/dev/null && cd pg_src && make installcheck > /dev/null && cd .. &&
grep "planning time in" plantime.log|sed -E -e 's/.*planning time in
(.*) nanoseconds/\1/'|awk '{nanoseconds += $1} END{print nanoseconds}'
&& pg_ctl stop -D pgdata > /dev/null && rm plantime.log; done

Master:
1855788104
1839655412
1740769066

Patched:
1917797221
1766606115
1881322655

Those results are a bit noisy.  Perhaps a few more runs might yield
more consistency, but it seems that there's not too much overhead to
it. If I take the minimum value out of the 3 runs from each, it comes
to about 1.5% extra time spent in planning.  Perhaps that's OK.

David

diff --git a/src/backend/optimizer/plan/planner.c 
b/src/backend/optimizer/plan/planner.c
index 1e4dd27dba..3c713782f1 100644
--- a/src/backend/optimizer/plan/planner.c
+++ b/src/backend/optimizer/plan/planner.c
@@ -17,6 +17,7 @@
 
 #include <limits.h>
 #include <math.h>
+#include <time.h>
 
 #include "access/genam.h"
 #include "access/htup_details.h"
@@ -274,11 +275,22 @@ planner(Query *parse, const char *query_string, int 
cursorOptions,
                ParamListInfo boundParams)
 {
        PlannedStmt *result;
+       struct timespec start, end;
+
+       clock_gettime(CLOCK_PROCESS_CPUTIME_ID, &start);
 
        if (planner_hook)
                result = (*planner_hook) (parse, query_string, cursorOptions, 
boundParams);
        else
                result = standard_planner(parse, query_string, cursorOptions, 
boundParams);
+
+       clock_gettime(CLOCK_PROCESS_CPUTIME_ID, &end);
+
+       elog(LOG,
+                "planning time in %f nanoseconds",
+                ((double) (end.tv_sec * 1000000000 + end.tv_nsec) -
+                                (double) (start.tv_sec * 1000000000 + 
start.tv_nsec)));
+
        return result;
 }