plpgsql plugin - stmt_beg/end is not called for top level block of statements

po 19. 11. 2018 v 19:37 odesílatel Pavel Stehule <pavel.stehule@gmail.com>
napsal:

Hi

I am playing with plpgsql profiling and and plpgsql plugin API. I found so
callback stmt_beg and stmt_end was not called for top statement due direct
call exec_stmt_block function.

<-->estate.err_text = NULL;
<-->estate.err_stmt = (PLpgSQL_stmt *) (func->action);
<-->rc = exec_stmt_block(&estate, func->action);
<-->if (rc != PLPGSQL_RC_RETURN)
<-->{
<--><-->estate.err_stmt = NULL;
<--><-->estate.err_text = NULL;

Isn't better to call exec_stmt there? Then plpgsql plugin function will be
called really for every plpgsql statement.

Now, the statement's hook is not called for every plpgsql_stmt_block
statement. It is not big issue, but it is not consistent - and this
inconsistency should be repaired inside extension. Better to be consistent
and every plpgsql statement call identically.

patch attached - all regress tests passed. This patch has a effect only on
plpgsql extensions.

Regards

Pavel

On Sun, Dec 16, 2018 at 10:33:38AM +0100, Pavel Stehule wrote:

Now, the statement's hook is not called for every plpgsql_stmt_block
statement. It is not big issue, but it is not consistent - and this
inconsistency should be repaired inside extension. Better to be consistent
and every plpgsql statement call identically.

patch attached - all regress tests passed. This patch has a effect only on
plpgsql extensions.

I can see the inconsistency in the code, still do you have a simple
plpgsql extension where it is possible to see the difference in
behavior? This involves execution of functions, triggers and event
triggers, and exec_stmt_block is used since the beginning of times.
--
Michael

st 19. 12. 2018 v 6:45 odesílatel Michael Paquier <michael@paquier.xyz>
napsal:

On Sun, Dec 16, 2018 at 10:33:38AM +0100, Pavel Stehule wrote:

Now, the statement's hook is not called for every plpgsql_stmt_block
statement. It is not big issue, but it is not consistent - and this
inconsistency should be repaired inside extension. Better to be

consistent

and every plpgsql statement call identically.

patch attached - all regress tests passed. This patch has a effect only

on

plpgsql extensions.

I can see the inconsistency in the code, still do you have a simple
plpgsql extension where it is possible to see the difference in
behavior? This involves execution of functions, triggers and event
triggers, and exec_stmt_block is used since the beginning of times.

What I know, there is only few plpgsql's extensions - 3 variations on
debugger support, 1 profiler and plpgsql_check. It was not a issue, because
these extensions doesn't hit this problem.

When I wrote a coverity check to plpgsql_check I found it. The outer BEGIN
has a property of usual plpgsql statement - positive lineno, but it was not
executed newer.

I can imagine some tracking extension, that will do some initializations on
plpgsql_stmt_block statement hook - but the most important will not be
called ever.

Regards

Pavel

--

On Wed, Dec 19, 2018 at 07:04:50AM +0100, Pavel Stehule wrote:

I can imagine some tracking extension, that will do some
initializations on plpgsql_stmt_block statement hook - but the most
important will not be called ever.

I was just studying this stuff and reviewing this patch with fresh
eyes, and it seems to me that it is actually incorrect. This changes
the execution logic so as stmt_beg and stmt_end are called
additionally each time a function, a trigger or an event trigger is
executed. If one looks closely at the code, he/she could notice that
func_beg and func_end are already present as hook points to watch what
is happening in the execution, as these are here to give entry points
for execution functions, so it seems to me that we don't need extra
watch calls as proposed, because there is already everything needed,
and that the current points are correct.
--
Michael

st 26. 12. 2018 v 6:09 odesílatel Michael Paquier <michael@paquier.xyz>
napsal:

On Wed, Dec 19, 2018 at 07:04:50AM +0100, Pavel Stehule wrote:

I can imagine some tracking extension, that will do some
initializations on plpgsql_stmt_block statement hook - but the most
important will not be called ever.

I was just studying this stuff and reviewing this patch with fresh
eyes, and it seems to me that it is actually incorrect. This changes
the execution logic so as stmt_beg and stmt_end are called
additionally each time a function, a trigger or an event trigger is
executed. If one looks closely at the code, he/she could notice that
func_beg and func_end are already present as hook points to watch what
is happening in the execution, as these are here to give entry points
for execution functions, so it seems to me that we don't need extra
watch calls as proposed, because there is already everything needed,
and that the current points are correct.

The design about this feature has not clean borders - I see a problem with
func_beg and func_end because these handlers should to share some logic
with stmt_beg, stmt_end when handler for stmt_block is not empty.

More the some behave can be surprise for developer - example - if use
handler for smt_beg

then for code

$$
BEGIN
RETURN x;
END;
$$

is called only once - what is expected;

but for code

$$
BEGIN
BEGIN
RETURN x;
END;
END
$$

is called two times, what is not expected, if you don't know some about
this inconsistency.

So it is reason, why I don't think so current behave is correct. On second
hand, the impact is very small - only few extensions uses plpgsql plugin
API, and workaround is not hard. So I can live with current state if nobody
see this issue (sure - it is minor issue).

Regards

Pavel

On Wed, Dec 26, 2018 at 07:02:04AM +0100, Pavel Stehule wrote:

is called two times, what is not expected, if you don't know some about
this inconsistency.

So it is reason, why I don't think so current behave is correct. On second
hand, the impact is very small - only few extensions uses plpgsql plugin
API, and workaround is not hard. So I can live with current state if nobody
see this issue (sure - it is minor issue).

Hm. Using the following functions based on the code of above, I can
see the following numbers if I place some trackers (elog(WARNING)
entries) at the beginning of each callback part of plpgsql_check.c to
measure how many times a callback is done:
CREATE OR REPLACE FUNCTION public.f2()
RETURNS void
LANGUAGE plpgsql
AS $$
DECLARE x int;
BEGIN
x := 2;
RETURN;
END;
$$;
CREATE OR REPLACE FUNCTION public.f3()
RETURNS void
LANGUAGE plpgsql
AS $$
DECLARE x int;
BEGIN
BEGIN
x := 3;
RETURN;
END;
END
$$;

On HEAD, for plpgsql_check_function_tb('f2()'):
- stmt_beg is called 4 times.
- stmt_end is called 3 times.
- func_setup is called 2 times.
- func_beg is called 2 times.
- func_end is called 2 times.
For plpgsql_check_function_tb('f3()'):
- stmt_beg is called 3 times.
- stmt_end is called 3 times.
- func_setup is called 1 time.
- func_beg is called 1 time.
- func_end is called 2 times.

So based on the previous example f2 gets over f3 one extra stmt_beg,
one extra func_beg and one extra func_setup.

With patched HEAD, I got for f2:
- stmt_beg is called 6 times.
- stmt_end is called 5 times.
- func_setup is called 2 times.
- func_beg is called 2 times.
- func_end is called 2 times.
And for f3:
- stmt_beg is called 6 times.
- stmt_end is called 5 times.
- func_setup is called 2 times.
- func_beg is called 2 times.
- func_end is called 2 times.
--
Michael

pá 28. 12. 2018 v 3:26 odesílatel Michael Paquier <michael@paquier.xyz>
napsal:

On Wed, Dec 26, 2018 at 07:02:04AM +0100, Pavel Stehule wrote:

is called two times, what is not expected, if you don't know some about
this inconsistency.

So it is reason, why I don't think so current behave is correct. On

second

hand, the impact is very small - only few extensions uses plpgsql plugin
API, and workaround is not hard. So I can live with current state if

nobody

see this issue (sure - it is minor issue).

Hm. Using the following functions based on the code of above, I can
see the following numbers if I place some trackers (elog(WARNING)
entries) at the beginning of each callback part of plpgsql_check.c to
measure how many times a callback is done:
CREATE OR REPLACE FUNCTION public.f2()
RETURNS void
LANGUAGE plpgsql
AS $$
DECLARE x int;
BEGIN
x := 2;
RETURN;
END;
$$;
CREATE OR REPLACE FUNCTION public.f3()
RETURNS void
LANGUAGE plpgsql
AS $$
DECLARE x int;
BEGIN
BEGIN
x := 3;
RETURN;
END;
END
$$;

On HEAD, for plpgsql_check_function_tb('f2()'):
- stmt_beg is called 4 times.
- stmt_end is called 3 times.
- func_setup is called 2 times.
- func_beg is called 2 times.
- func_end is called 2 times.
For plpgsql_check_function_tb('f3()'):
- stmt_beg is called 3 times.
- stmt_end is called 3 times.
- func_setup is called 1 time.
- func_beg is called 1 time.
- func_end is called 2 times.

So based on the previous example f2 gets over f3 one extra stmt_beg,
one extra func_beg and one extra func_setup.

With patched HEAD, I got for f2:
- stmt_beg is called 6 times.
- stmt_end is called 5 times.
- func_setup is called 2 times.
- func_beg is called 2 times.
- func_end is called 2 times.
And for f3:
- stmt_beg is called 6 times.
- stmt_end is called 5 times.
- func_setup is called 2 times.
- func_beg is called 2 times.
- func_end is called 2 times.
--
Michael

These numbers are little bit strange - maybe due using plpgsql_check. I
wrote simple extension (see attachment)

CREATE OR REPLACE FUNCTION public.f2()
RETURNS void
LANGUAGE plpgsql
1 AS $function$
2 DECLARE x int;
3 BEGIN
4 x := 2;
5 RETURN;
6 END;
7 $function$

CREATE OR REPLACE FUNCTION public.f3()
RETURNS void
LANGUAGE plpgsql
1 AS $function$
2 DECLARE x int;
3 BEGIN
4 BEGIN
5 x := 3;
6 RETURN;
7 END;
8 END
9 $function$

load 'simple';
select f2();

postgres=# select f2();
NOTICE: func setup: "f2()"
NOTICE: func beg: "f2()"
NOTICE: stmt beg - ln: 4
NOTICE: stmt end - ln: 4
NOTICE: stmt beg - ln: 5
NOTICE: stmt end - ln: 5
NOTICE: func end: "f2()"

NOTICE: func setup: "f3()"
NOTICE: func beg: "f3()"
NOTICE: stmt beg - ln: 4
NOTICE: stmt beg - ln: 5
NOTICE: stmt end - ln: 5
NOTICE: stmt beg - ln: 6
NOTICE: stmt end - ln: 6
NOTICE: stmt end - ln: 4
NOTICE: func end: "f3()"

patched

postgres=# select f2();
NOTICE: func setup: "f2()"
NOTICE: func beg: "f2()"
NOTICE: stmt beg - ln: 3
NOTICE: stmt beg - ln: 4
NOTICE: stmt end - ln: 4
NOTICE: stmt beg - ln: 5
NOTICE: stmt end - ln: 5
NOTICE: stmt end - ln: 3
NOTICE: func end: "f2()"

postgres=# select f3();
NOTICE: func setup: "f3()"
NOTICE: func beg: "f3()"
NOTICE: stmt beg - ln: 3
NOTICE: stmt beg - ln: 4
NOTICE: stmt beg - ln: 5
NOTICE: stmt end - ln: 5
NOTICE: stmt beg - ln: 6
NOTICE: stmt end - ln: 6
NOTICE: stmt end - ln: 4
NOTICE: stmt end - ln: 3
NOTICE: func end: "f3()"

There is only one difference - the plugin routine stmt_begin and stmt_end
is called for line 3. Nothing less, nothing more.

Internal evaluation of plpgsql code is same - the change is only for plugin
code - one more stmt_beg and stmt_end call - as expected and wanted.

Real impact - now, I have to push my code to func_beg, func_end, stmt_beg,
stmt_end. With patch I can push my code just to stmt_beg, stmt_end.

Regards

Pavel

On Fri, Dec 28, 2018 at 07:57:45AM +0100, Pavel Stehule wrote:

There is only one difference - the plugin routine stmt_begin and stmt_end
is called for line 3. Nothing less, nothing more.

Thanks for the detailed explanation! With your simple example it is
easy enough to see the difference, and indeed the callback stack is
more consistent the way you propose.

Internal evaluation of plpgsql code is same - the change is only for plugin
code - one more stmt_beg and stmt_end call - as expected and wanted.

Okay, that makes sense, now I got your point. Perhaps somebody else
has an opinion to offer or has an objection with the proposed change?
--
Michael

On Fri, Dec 28, 2018 at 04:50:11PM +0900, Michael Paquier wrote:

Okay, that makes sense, now I got your point. Perhaps somebody else
has an opinion to offer or has an objection with the proposed change?

And committed this one, after playing more with the instrumentation
callbacks and checking that the change was consistent for functions,
triggers and event triggers.

Attached is the set of tests I used which has some regression tests.
The results won't fail with HEAD at 4203842a, and will generate some
diffs after e0ef136d as Pavel's patch has changed the generated
output.
--
Michael

On Sun, Dec 30, 2018 at 02:40:57PM +0900, Michael Paquier wrote:

Attached is the set of tests I used which has some regression tests.
The results won't fail with HEAD at 4203842a, and will generate some
diffs after e0ef136d as Pavel's patch has changed the generated
output.

And of course those were not attached..
--
Michael

Hi

ne 30. 12. 2018 v 6:51 odesílatel Michael Paquier <michael@paquier.xyz>
napsal:

On Sun, Dec 30, 2018 at 02:40:57PM +0900, Michael Paquier wrote:

Attached is the set of tests I used which has some regression tests.
The results won't fail with HEAD at 4203842a, and will generate some
diffs after e0ef136d as Pavel's patch has changed the generated
output.

And of course those were not attached..

Thank you for commit.

Regards

Pavel

--