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
186k28 gold badges463 silver badges636 bronze badges
asked Dec 5, 2014 at 23:41
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. Commented 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

answered May 28, 2015 at 19:12
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. Commented 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. Commented 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! Commented Dec 12, 2017 at 16:36

Your Answer

Draft saved
Draft discarded

Sign up or log in

Sign up using Google
Sign up using Email and Password

Post as a guest

Required, but never shown

Post as a guest

Required, but never shown

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

Start asking to get answers

Find the answer to your question by asking.

Ask question

Explore related questions

See similar questions with these tags.