4

We have a number of Postgres functions that each call a number of other Postgres functions. If you simply EXPLAIN ANALYSE a call like SELECT parent_function(), the output is minimal, since it doesn't dive into the calls the parent_function makes.
Thanks to answers like this (Get query plan for SQL statement nested in a PL/pgSQL function), we discovered auto_explain.

So, we turned this stuff on:

auto_explain.log_min_duration = 0
auto_explain.log_analyze = true
auto_explain.log_verbose = true
auto_explain.log_timing = true
auto_explain.log_nested_statements = true

The good news is that it gave us what we were looking for: A way to see the timing of every nested statement called during a long-running function. However, the output is very verbose, and it's hard to see the parent-child relationship I'm "used" to seeing in profilers:

some_big_function           1000ms
  --child_function1          800ms
    --child_child_function   600ms
  --child_function2          200ms

Is there a better way to view this log output? Ideally, it would group nested statements with their parents showing me, at a glance, where I should look.
We tried pgbadger, but it's not configured to parse auto_explain output, since auto_explain of this verbosity isn't usually running on production servers.

Are there other log parsers (or other techniques) to help profile functions?

Erwin Brandstetter
  • 175,982
  • 27
  • 439
  • 600
Taytay
  • 325
  • 2
  • 3
  • 11
  • For those that are reading this question, you'd likely want to know that pganalyze.com can help get timings without auto_explain. It uses pg_stat_statements to give per-statement (rather than per-function) timings of most things in your database. It's not aware of which statements are nested in which functions, but (since pg_stat_statements isn't either), but it's very helpful nonetheless. – Taytay Oct 30 '19 at 17:56

1 Answers1

2

SUGGESTION #1

If you are just looking to take an EXPLAIN plan and instantly present it, here is a SQL-Fiddle like site called explain.depesz.com. Just copy-and-paste the explain and hit Submit.

SUGGESTION #2

You could try pgAdminIII which comes with Graphical Explains

See the following links to how to use pgAdmin and other methods

Community
  • 1
RolandoMySQLDBA
  • 182,700
  • 33
  • 317
  • 520
  • 4
    This does not really help figuring out what the actual log line tries to tell - it is really very convoluted. Sometimes it contains several EXPLAIN ANALYZE outputs mixed with other information. – András Váczi May 28 '15 at 20:56
  • 1
    Thanks for the quick answer, but I'm afraid that this doesn't work for PL/pgSQL functions. I can't just EXPLAIN a Postgres Function, since Postgres functions are optimization boundaries. The only recourse I appear to have is to turn on AUTO EXPLAIN, run our queries, and figure out where the time is going. However, the output from AUTO EXPLAIN in the logs is extremely verbose and disorganized, as @dezso pointed out. – Taytay May 29 '15 at 13:42
  • 1
    Upon further review, the output from nested AUTO_EXPLAIN appears to come out in the correct order and be pasteable inside of explain.depesz.com. Thanks! – Taytay Dec 12 '17 at 16:36