auto_explain vs. parallel query

Hi,

While debugging something on 9.6, I've noticed that auto_explain handles
parallel queries in a slightly strange way - both the leader and all the
workers log their chunk of the query (i.e. the leader logs explain for
the whole query, while workers only log the parts they've been executing).

So for example for a query with 2 workers, the log look like this:

2016-10-31 23:10:23.481 CET [12278] LOG: duration: 32.562 ms pl ...
Query Text: <parallel query> ...
Parallel Seq Scan on tables (cost=0.00..15158.25 rows=220 wi ...
Filter: ((table_datoid < '1000000000'::oid) AND (table_nspo ...
Rows Removed by Filter: 140614 ...
2016-10-31 23:10:23.481 CET [12277] LOG: duration: 32.325 ms pl ...
Query Text: <parallel query> ...
Parallel Seq Scan on tables (cost=0.00..15158.25 rows=220 wi ...
Filter: ((table_datoid < '1000000000'::oid) AND (table_nspo ...
Rows Removed by Filter: 80948 ...
2016-10-31 23:10:23.483 CET [12259] LOG: duration: 38.997 ms pl ...
Query Text: explain analyze select * from tables where table_ ...
Gather (cost=1000.00..16211.15 rows=529 width=356) (actual t ...
Workers Planned: 2 ...
Workers Launched: 2 ...
-> Parallel Seq Scan on tables (cost=0.00..15158.25 rows= ...
Filter: ((table_datoid < '1000000000'::oid) AND (tabl ...
Rows Removed by Filter: 105570 ...

I'd say that's fairly surprising, and I haven't found any discussion
about auto_explain vs. parallel queries in the archives (within the last
year), so I assume this may not be entirely intentional.

Not only this does not match the output when running EXPLAIN ANALYZE
manually, it also provides no information about which messages from
workers belong to which "leader" message.

Another thing is that this interacts with sampling in a rather
unfortunate way, because each process evaluates the sampling condition
independently. So for example with auto_explain.sample_rate=0.5 a random
subset of worker/leader explain plans will be logged.

But this also applies to the conditions in ExecutorStart, which enables
instrumentation only when the query gets sampled - so when the leader
gets sampled but not all the workers, the counters in the query logged
by the leader are incomplete.

I do believe those are bugs that make auto_explain rather unusable with
parallel queries. Adding IsParallelWorker() to the condition in
ExecutorEnd should fix the extra logging messages (and log only from the
leader).

Not sure how to fix the sampling - simply adding IsParallelWorker() to
ExecutorStart won't do the trick, because we don't want to enable
instrumentation only for sample queries. So I guess this needs to be
decided in the leader, and communicated to the workers somehow.

regards

--
Tomas Vondra http://www.2ndQuadrant.com
PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services