Waiting for 8.4 – function stats

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.

8 thoughts on “Waiting for 8.4 – function stats”

  1. 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

  2. @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.

  3. 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)?

  4. @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.

  5. 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?

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

  7. 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 🙂

Comments are closed.