run the plpgsql_profiler_function_tb by passing real parameters for the traced function

[slavadba]

Hi, here is a test case :

ALTER SYSTEM SET shared_preload_libraries='plpgsql','plpgsql_check' ;
create extension plpgsql_check;

CREATE OR REPLACE FUNCTION public.fx1(a integer)
         RETURNS integer
         LANGUAGE plpgsql
      AS $function$
      begin
        if a > 10 then
        PERFORM pg_sleep(5);
          raise notice 'ahoj';
          return -1;
        else
        PERFORM pg_sleep(10);
          raise notice 'nazdar';
          return 1;
        end if;
      end;
$function$

SET plpgsql_check.profiler = ON;

SET plpgsql_check.enable_tracer = on;

SET plpgsql_check.tracer = on;

postgres=# select lineno, avg_time, source from plpgsql_profiler_function_tb('fx1(int)');
 lineno | avg_time  |              source              
--------+-----------+----------------------------------
      1 |           | 
      2 |     0.002 |       begin
      3 |     0.105 |         if a > 10 then
      4 |       NaN |   PERFORM pg_sleep(5);
      5 |       NaN |           raise notice 'ahoj';
      6 |       NaN |           return -1;
      7 |           |         else
      8 | 10008.849 |   PERFORM pg_sleep(10);
      9 |     0.146 |           raise notice 'nazdar';
     10 |     0.055 |           return 1;
     11 |           |         end if;
     12 |           |       end;
(12 rows)

postgres=#

that is, in such a program output, a value less than 10 was passed as a parameter. question: and how to call the function by passing it as a parameter, say 11?

I've tried different options like

select lineno, avg_time, source from plpgsql_profiler_function_tb('fx1(1)');

or

select lineno, avg_time, source from plpgsql_profiler_function_tb('fx1('''1'''::int)');

but got errors:

postgres=# select lineno, avg_time, source from plpgsql_profiler_function_tb('fx1('''1'''::int)'); ERROR: syntax error at or near "1" LINE 1: ... source from plpgsql_profiler_function_tb('fx1('''1'''::int)... ^ postgres=#

[kirkw]

I cannot be 100% certain, but I think you are missing the essence of the profiler. Keep in mind, this function exists to CLEAR() the results:

select plpgsql_profiler_reset_all();

You should see no data for the above function.

The query you are running... Reads the results of PREVIOUSLY STORED runs (even in real-time). It does NOT profile that function. It says: (Hey, profiler, I just ran some code... Tell me how this function did). That's why you send just the funcoid (Function OID).

And it pulls the data.

==> To be clear, the process I use is:

-- ONE time: SET plpgsql_check.enable_tracer = on; -- MUST BE DONE BY SUPERUSER

-- now when I need some data: SET plpgsql_check.profiler = ON; select plpgsql_profiler_reset_all();

select fx1(11); -- your case

then... select lineno, avg_time, source from plpgsql_profiler_function_tb('fx1(int)');

will show the results.

Better... If your function called other functions.. You can see how THOSE performed as well...

I hope this helps...

[okbob]

Hi

so 19. 11. 2022 v 13:08 odesílatel slavadba @.***> napsal:

Hi, here is a test case :

ALTER SYSTEM SET shared_preload_libraries='plpgsql','plpgsql_check' ; create extension plpgsql_check;

CREATE OR REPLACE FUNCTION public.fx1(a integer) RETURNS integer LANGUAGE plpgsql AS $function$ begin if a > 10 then PERFORM pg_sleep(5); raise notice 'ahoj'; return -1; else PERFORM pg_sleep(10); raise notice 'nazdar'; return 1; end if; end; $function$

SET plpgsql_check.profiler = ON;

SET plpgsql_check.enable_tracer = on;

SET plpgsql_check.tracer = on;

postgres=# select lineno, avg_time, source from plpgsql_profiler_function_tb('fx1(int)'); lineno | avg_time | source --------+-----------+---------------------------------- 1 | | 2 | 0.002 | begin 3 | 0.105 | if a > 10 then 4 | NaN | PERFORM pg_sleep(5); 5 | NaN | raise notice 'ahoj'; 6 | NaN | return -1; 7 | | else 8 | 10008.849 | PERFORM pg_sleep(10); 9 | 0.146 | raise notice 'nazdar'; 10 | 0.055 | return 1; 11 | | end if; 12 | | end; (12 rows)

postgres=#

that is, in such a program output, a value less than 10 was passed as a parameter. question: and how to call the function by passing it as a parameter, say 11?

I've tried different options like

select lineno, avg_time, source from plpgsql_profiler_function_tb('fx1(1)');

or

select lineno, avg_time, source from plpgsql_profiler_function_tb('fx1('''1'''::int)');

but got errors:

postgres=# select lineno, avg_time, source from plpgsql_profiler_function_tb('fx1('''1'''::int)'); ERROR: syntax error at or near "1" LINE 1: ... source from plpgsql_profiler_function_tb('fx1('''1'''::int)...

The plpgsql_check profiler is executed in the background. You just need to enable plpgsql_check_profiler, and next you start the profiled function like usual.

The plpgsql_profiler_function_tb is used to get a function's profile, but it cannot be used for function execution. And then the parameter is the function's signature - not real arguments.

Regards

Pavel

^ postgres=#

— Reply to this email directly, view it on GitHub https://github.com/okbob/plpgsql_check/issues/132, or unsubscribe https://github.com/notifications/unsubscribe-auth/AAEFO4ZTW62DPQSM7F7KPCTWJC7LZANCNFSM6AAAAAASFJCCOQ . You are receiving this because you are subscribed to this thread.Message ID: @.***>

[slavadba]

thank you very much, it's clearer now. one more question: there is apparently no trace of nested sql? i.e. with this code, only the phrase SQL statement will be output, but there will be no text of the sql itself :

`CREATE OR REPLACE FUNCTION foo(n integer) RETURNS integer AS $$ BEGIN RETURN (select count(*) from pg_class c,pg_class c1,pg_class c2); END; $$ LANGUAGE plpgsql;

CREATE OR REPLACE FUNCTION public.fx1(a integer) RETURNS integer LANGUAGE plpgsql AS $function$ declare n integer; begin if a > 10 then select foo(11) into n; --PERFORM pg_sleep(5); raise notice 'count is:'; return n; else --PERFORM pg_sleep(10); raise notice 'nazdar'; return 1; end if; end; $function$;

postgres=# select * from plpgsql_profiler_function_statements_tb('fx1'); stmtid | parent_stmtid | parent_note | block_num | lineno | queryid | exec_stmts | total_time | avg_time | max_time | processed_rows | stmtname
--------+---------------+-------------+-----------+--------+---------+------------+------------+----------+----------+----------------+----------------- 0 | | | 1 | 4 | | 1 | 0.001 | 0.001 | 0.001 | 1 | statement block 1 | 0 | body | 1 | 5 | | 1 | 0.059 | 0.059 | 0.059 | 1 | IF 2 | 1 | then body | 1 | 6 | | 1 | 4315.97 | 4315.97 | 4315.97 | 1 | SQL statement 3 | 1 | then body | 2 | 8 | | 1 | 0.182 | 0.182 | 0.182 | 1 | RAISE 4 | 1 | then body | 3 | 9 | | 1 | 0 | 0 | 0 | 1 | RETURN 5 | 1 | else body | 1 | 12 | | 0 | 0 | | 0 | 0 | RAISE 6 | 1 | else body | 2 | 13 | | 0 | 0 | | 0 | 0 | RETURN (7 rows)

postgres=#

`

[okbob]

the SQL statements are not printed in profiler result. They can be pretty long, and then the profile can be not well readable. You have possibility to look to source code always.

But you can install extension pg_stat_statements. The profiler's functions returning queryid column. You can join the pg_stat_statements to plpgsql_profiler_function_statements_tb by queryid column.

note: pg_stat_statements is pretty important extension and it is good to use it

[slavadba]

hm... by some reason I cant find queryid from output plpgsql_profiler_function_statements_tb in the pg_stat_statements : ` select * from plpgsql_profiler_function_statements_tb('fx1'); stmtid | parent_stmtid | parent_note | block_num | lineno | queryid | exec_stmts | total_time | avg_time | max_time | processed_rows | stmtname
--------+---------------+-------------+-----------+--------+----------------------+------------+------------+----------+----------+----------------+----------------- 0 | | | 1 | 4 | | 1 | 0.001 | 0.001 | 0.001 | 1 | statement block 1 | 0 | body | 1 | 5 | -2940635431223859570 | 1 | 7.203 | 7.203 | 7.203 | 1 | IF 2 | 1 | then body | 1 | 6 | -6727555361601231379 | 1 | 3327.009 | 3327.009 | 3327.009 | 1 | SQL statement 3 | 1 | then body | 2 | 8 | | 1 | 0.251 | 0.251 | 0.251 | 1 | RAISE 4 | 1 | then body | 3 | 9 | | 1 | 0 | 0 | 0 | 1 | RETURN 5 | 1 | else body | 1 | 12 | | 0 | 0 | | 0 | 0 | RAISE 6 | 1 | else body | 2 | 13 | | 0 | 0 | | 0 | 0 | RETURN (7 rows)

postgres=# select queryid from pg_stat_statements ; queryid

-2957143801391021615 -1032628475049021897 -7759369187797562197 801850495811777624 1377722765556448295 6628303476215242496 -1315493481807294491 2634098840000013830 -6990341819380052289 4689269028257868176 3441479919871847990 -6293137051085111411 -2593911312032930163 (13 rows) postgres=# `

maybe there are some thoughts why this could be?

[okbob]

you need fresh version of plpgsql_check, where queryid is supported

(2022-11-25 19:24:06) postgres=# select * from plpgsql_profiler_function_statements_tb('foo');
┌────────┬───────────────┬─────────────┬───────────┬────────┬─────────────────────┬────────────┬────────────────┬────────────┬──────────┬──────────┬────────────────┬──────────────────────┐
│ stmtid │ parent_stmtid │ parent_note │ block_num │ lineno │       queryid       │ exec_stmts │ exec_stmts_err │ total_time │ avg_time │ max_time │ processed_rows │       stmtname       │
╞════════╪═══════════════╪═════════════╪═══════════╪════════╪═════════════════════╪════════════╪════════════════╪════════════╪══════════╪══════════╪════════════════╪══════════════════════╡
│      0 │             ∅ │ ∅           │         1 │      2 │                   ∅ │          2 │              0 │      0.025 │    0.013 │    1.047 │              0 │ statement block      │
│      1 │             0 │ body        │         1 │      3 │                   ∅ │          2 │              0 │      1.549 │    0.775 │    1.033 │              0 │ FOR over SELECT rows │
│      2 │             1 │ loop body   │         1 │      4 │ 6265006341802524398 │        828 │              0 │      0.423 │    0.001 │    0.035 │              0 │ assignment           │
│      3 │             0 │ body        │         2 │      6 │                   ∅ │          2 │              0 │      0.002 │    0.001 │    0.001 │              0 │ RETURN               │
└────────┴───────────────┴─────────────┴───────────┴────────┴─────────────────────┴────────────┴────────────────┴────────────┴──────────┴──────────┴────────────────┴──────────────────────┘
(4 rows)

(2022-11-25 19:24:17) postgres=# \gdesc
┌────────────────┬──────────────────┐
│     Column     │       Type       │
╞════════════════╪══════════════════╡
│ stmtid         │ integer          │
│ parent_stmtid  │ integer          │
│ parent_note    │ text             │
│ block_num      │ integer          │
│ lineno         │ integer          │
│ queryid        │ bigint           │
│ exec_stmts     │ bigint           │
│ exec_stmts_err │ bigint           │
│ total_time     │ double precision │
│ avg_time       │ double precision │
│ max_time       │ double precision │
│ processed_rows │ bigint           │
│ stmtname       │ text             │
└────────────────┴──────────────────┘
(13 rows)

The extension pg_stat_statements should be installed and active. pg_stat_statements.track should be "all"

Unfortunately I found bug there and for some cases, the queryid is not stored.

[okbob]

should be fixed now in master branch

load 'plpgsql_check';
set plpgsql_check.profiler to on;
set pg_stat_statements.track TO "all" ;

select foo();

(2022-11-25 19:45:46) postgres=# select lineno, queryid, stmtname from plpgsql_profiler_function_statements_tb('foo');
┌────────┬──────────────────────┬──────────────────────┐
│ lineno │       queryid        │       stmtname       │
╞════════╪══════════════════════╪══════════════════════╡
│      2 │                    ∅ │ statement block      │
│      3 │ -1905758228217333571 │ FOR over SELECT rows │
│      4 │  6265006341802524398 │ assignment           │
│      6 │                    ∅ │ RETURN               │
└────────┴──────────────────────┴──────────────────────┘
(4 rows)