May 15th, 2008 by depesz | Tags: , , , , , , | 8 comments »
Did it help? If yes - maybe you can help me? Donate BTC to 19zPa5diT2LZqGtTi8f8bfApLn8rw9zBHx

Today another great patch, committed by Tom Lane. This patch was written by Martin Pihlak (with some edits by Tom).

Commit log:

Add support for tracking call counts and elapsed runtime for user-defined
functions.
Note that because this patch changes FmgrInfo, any external C functions
you might be testing with 8.4 will need to be recompiled.
Patch by Martin Pihlak, some editorialization by me (principally, removing
tracking of getrusage() numbers)

Description sound very interesting.

First, to use it at all we have to enable it. To do it, there is new option in postgresql.conf:

#track_functions = none # none, pl, all

Values mean:

  • none – function tracking is disabled
  • pl – only functions in pl/* languages will be monitored
  • all – like “pl", but functions in SQL and C will be also monitored

What does it do?

Let's check:

# select * from pg_stat_user_functions ;
funcid | schemaname | funcname | calls | total_time | self_time
--------+------------+----------+-------+------------+-----------
(0 rows)

OK. So, let's add some simple function:

# create function x(float8) returns void as $$
begin
perform pg_sleep($1);
return;
end;
$$ language plpgsql;
CREATE FUNCTION

And now, let's test it:

# select x(0.5); select * from pg_stat_user_functions ;
x
---
 
(1 row)
funcid | schemaname | funcname | calls | total_time | self_time
--------+------------+----------+-------+------------+-----------
(0 rows)

Does it look like if it didn't work? Let's recheck:

# select * from pg_stat_user_functions ;
funcid | schemaname | funcname | calls | total_time | self_time
--------+------------+----------+-------+------------+-----------
18671 | public | x | 1 | 504 | 504
(1 row)

OK. Worked. The reason why it didn't show immediately is that statistics collector works with some buffering/delay.

Let's test it again with something more interesting:

# select x(random()/2) from generate_series(1,10);
...
# select * from pg_stat_user_functions ;
funcid | schemaname | funcname | calls | total_time | self_time
--------+------------+----------+-------+------------+-----------
18671 | public | x | 11 | 3222 | 3222
(1 row)

Sweet.

Let's check one more thing:

# create function x() returns void as $$
begin
perform x(random());
return;
end;
$$ language plpgsql;
CREATE FUNCTION

Now, I have x() function which calls x(TIME) with some random value of time.

Let's call it:

# select x();
x
---
 
(1 row)
# select * from pg_stat_user_functions ;
funcid | schemaname | funcname | calls | total_time | self_time
--------+------------+----------+-------+------------+-----------
18671 | public | x | 12 | 3425 | 3425
18672 | public | x | 1 | 203 | 0
(2 rows)

As You can see I now have 2 rows with funcname x (their arguments are not listed here, but I have funcid, so I can easily match exact function).

Interesting thing is that “self_time" of this new function x() is 0. This is because self_time checks runtime of this particular function without any functions it called! Very handy.

Let's run it couple more times:

# select x() from generate_series(1, 1000);
...
# select * from pg_stat_user_functions ;
funcid | schemaname | funcname | calls | total_time | self_time
--------+------------+----------+-------+------------+-----------
18671 | public | x | 1012 | 502679 | 502679
18672 | public | x | 1001 | 499513 | 56
(2 rows)

Great. Finally we have something to profile our functions.

  1. 8 comments

  2. # Vincent
    Oct 6, 2008

    That sounds really interesting !
    If I understand well, this will give us general stats on functions.
    Is there going to be a way to trace the function call stack, in order to fully profile a specific function call and all of their subfunctions ?
    This tool will greatly improve our work process, as for the moment profiling and monitoring pl/pgsql is quite complicated.
    Thanks for the explanations,
    vincent

  3. Oct 6, 2008

    @Vincent:
    nope – there will be only basic statistical information – just like in case of tables.

    if is still useful, but for more detailed profiling, you have to roll your own solution.

  4. # alex
    Nov 7, 2008

    Hi,
    I would like to know the meaning of the column self_time. Is that the time spent only within the body of the function (excluding any calling overhead)?

  5. Nov 7, 2008

    @alex:
    “This is because self_time checks runtime of this particular function without any functions it called! Very handy.”

    basically – self_time (as i understand) is time spent evaluating body of given function, without any oerhead of calling – either the function itself, or any other function this one can call.

  6. # Mathew
    Nov 23, 2011

    Hi ..
    When we have overloaded functions like X() in the above example..how do i find out the details of the one being refered to in pg_stat_user_functions..

    there is no function OID in pg_proc..so how do join tables like pg_proc and pg_stat_user_functions?

  7. Nov 23, 2011

    @Mathew:
    not sure what you mean by “there is no function OID in pg_proc” – sure there is: select oid, * from pg_proc;

  8. # Tim
    Nov 29, 2011

    How do tell when the stats were last reset. Is there a table that stores the last time that pg_stat_reset() was run?

    ps Glad you had a good hols :)

  9. Nov 29, 2011

    @Tim:
    http://www.depesz.com/index.php/2011/03/02/waiting-for-9-1-stats-reset-tracking/

Leave a comment