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 (Postgres query plan of a UDF invocation written in pgpsql), 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?

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

  • 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. – dezso 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

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service, privacy policy and cookie policy

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