Thread: Measuring the execution time of functions within functions...

I have asked this before, but haven't noticed any response, so if there
were any, I appologize for asking this again...

I have a function that is called by middle-tier (java trough JDBC), and
in postgres log I can see only the execution time of that function. I
have no idea how long are functions insde taking time to execute.

Since the function is written in plpgsql I tried to calculate the
durations by using now() function, but realized that within the
transaction now() always retunrs the same value.

The good thing is that those RAISE NOTICE calls from within my function
are logged as they're encountered, so, with carefully placed RAISE
NOTICE calls I could see how much time are the -inside- functions
taking.

For instance:

CREATE FUNCTION test_outer() RETURNS void
AS
$$BODY$$BEGIN
    RAISE NOTICE 'We start here'
    PERFORM SELECT someInternalFunction1();
    RAISE NOTICE 'InternalFunction1 is done now.';
    PERFORM SELECT someInternalFunction2();
    RAISE NOTICE 'InternalFunction2 is done now.';
    -- ... more code here
END$$BODY$$
LANGUAGE 'plpgsql'

Is there any other, maybe more convinient way to measure the 'inside'
function performance? I also have a problem if the outer function is
written in SQL, like this, for instance:

CREATE FUNCTION getSomeData(param1, param2, param3)
RETURN SETOF someType
AS
$$BODY$$SELECT
    *
FROM
    someTable
    JOIN someOtherFunction($1, $2, $3) ON someTable.col =
someOtherFunction.col
WHERE
    someCondition
$$BODY$$
LANGUAGE 'sql'.

Thank you in advance,

    Mario
--
Mario Splivalo
Mob-Art
mario.splivalo@mobart.hr

"I can do it quick, I can do it cheap, I can do it well. Pick any two."

Mario Splivalo wrote:

> Since the function is written in plpgsql I tried to calculate the
> durations by using now() function, but realized that within the
> transaction now() always retunrs the same value.

Maybe you can use timeofday().

--
Alvaro Herrera                                http://www.CommandPrompt.com/
PostgreSQL Replication, Consulting, Custom Development, 24x7 support

Mario Splivalo <mario.splivalo@mobart.hr> writes:

> I have asked this before, but haven't noticed any response, so if there
> were any, I appologize for asking this again...
>
> I have a function that is called by middle-tier (java trough JDBC), and
> in postgres log I can see only the execution time of that function. I
> have no idea how long are functions insde taking time to execute.
>
> Since the function is written in plpgsql I tried to calculate the
> durations by using now() function, but realized that within the
> transaction now() always retunrs the same value.
>
> The good thing is that those RAISE NOTICE calls from within my function
> are logged as they're encountered, so, with carefully placed RAISE
> NOTICE calls I could see how much time are the -inside- functions
> taking.
>
> For instance:
>
> CREATE FUNCTION test_outer() RETURNS void
> AS
> $$BODY$$BEGIN
>     RAISE NOTICE 'We start here'
>     PERFORM SELECT someInternalFunction1();
>     RAISE NOTICE 'InternalFunction1 is done now.';
>     PERFORM SELECT someInternalFunction2();
>     RAISE NOTICE 'InternalFunction2 is done now.';
>     -- ... more code here
> END$$BODY$$
> LANGUAGE 'plpgsql'
>
> Is there any other, maybe more convinient way to measure the 'inside'
> function performance? I also have a problem if the outer function is
> written in SQL, like this, for instance:

See the timeofday() func which returns the actual time and is not
frozen in the current transaction.  You'll need to cast it to
timestamp or other if wishing to do time arithmetic deltas on it.

HTH

--
-------------------------------------------------------------------------------
Jerry Sievers   305 854-3001 (home)     WWW ECommerce Consultant
                305 321-1144 (mobile    http://www.JerrySievers.com/