select * from depesz;

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