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?

1
  • 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, 2019 at 17:56

1 Answer 1

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

3
  • 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. May 28, 2015 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, 2015 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, 2017 at 16:36

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service and acknowledge you have read our privacy policy.

Not the answer you're looking for? Browse other questions tagged or ask your own question.