cancel
Showing results for 
Search instead for 
Did you mean: 

auto_explain.log_nested_statements=TRUE --- NOT WORKING

SOLVED
Highlighted
Adventurer

auto_explain.log_nested_statements=TRUE --- NOT WORKING

 

SQL> select version();
+--------------------------------------------------------------------------------------------------------------+
| version |
+--------------------------------------------------------------------------------------------------------------+
| EnterpriseDB 10.5.12 on x86_64-pc-linux-gnu, compiled by gcc (GCC) 4.4.7 20120313 (Red Hat 4.4.7-18), 64-bit |
+--------------------------------------------------------------------------------------------------------------+
(1 row)

Time: 3.554 ms
SQL> show auto_explain.log_min_duration ;
+-------------------------------+
| auto_explain.log_min_duration |
+-------------------------------+
| 0 |
+-------------------------------+
(1 row)

SQL> show auto_explain.log_nested_statements ;
+------------------------------------+
| auto_explain.log_nested_statements |
+------------------------------------+
| on |
+------------------------------------+
(1 row)

SQL>
CREATE TABLE test (
event_cd number NOT NULL,
dt varchar2(8)
)
PARTITION BY RANGE(dt)

(
PARTITION pt_201806 VALUES LESS THAN ('20180101'),
PARTITION pt_201812 VALUES LESS THAN ('20200101'),
PARTITION pt_max VALUES LESS THAN (MAXVALUE)
);

insert into test values(1,'20171231');
insert into test values(2,'20191231');

commit;


SQL> CREATE or replace FUNCTION zzz_test_edb(
a_dt varchar)
RETURNS varchar AS
$BODY$
declare
l_event_cd number;
BEGIN
select event_cd into l_event_cd from test where dt=a_dt;

RETURN 'test';

EXCEPTION
WHEN OTHERS THEN
RETURN NULL;
END$BODY$
LANGUAGE edbspl
COST 100;
CREATE FUNCTION

SQL> select /* spiderman */ * from zzz_test_edb('20171231');
+--------------+
| zzz_test_edb |
+--------------+
| NULL |
+--------------+
(1 row)

SQL>

 

.............
2018-10-30 18:22:08 KST [10796]: [9-1] db=perf,user=mig,app=[psql.bin],host=[[local]] LOG: duration: 1.373 ms plan:
Query Text: select /* spiderman */ * from zzz_test_edb('20171231');
Function Scan on mig.zzz_test_edb (cost=0.25..0.26 rows=1 width=32) (actual time=1.350..1.353 rows=1 loops=1)
Output: zzz_test_edb
Function Call: zzz_test_edb('20171231'::character varying)
Buffers: shared hit=36 read=6
I/O Timings: read=0.169

.................
============================================================================
[ppas 9.4]  -- auto_explain.log_nested_statements=TRUE  GOOD!

 

select /* spiderman */ * from zzz_test_edb('20171231');


2018-09-13 15:57:16 KST [22161]: [35-1] db=dhbsc,user=mig,app=[Postgres Enterprise Manager - Query Tool],host=[192.168.0.1] LOG: duration: 0.020 ms plan:
Query Text: select event_cd from test where dt=a_dt
Append (cost=0.00..62.25 rows=13 width=32) (actual time=0.011..0.016 rows=1 loops=1)
Buffers: shared hit=2
> Seq Scan on mig.test (cost=0.00..0.00 rows=1 width=32) (actual time=0.002..0.002 rows=0 loops=1)
Output: test.event_cd
Filter: ((test.dt)::text = ($1)::text)
> Seq Scan on mig.test_pt_201806 (cost=0.00..20.75 rows=4 width=32) (actual time=0.009..0.010 rows=1 loops=1)
Output: test_pt_201806.event_cd
Filter: ((test_pt_201806.dt)::text = ($1)::text)
Buffers: shared hit=1
> Seq Scan on mig.test_pt_201812 (cost=0.00..20.75 rows=4 width=32) (actual time=0.003..0.003 rows=0 loops=1)
Output: test_pt_201812.event_cd
Filter: ((test_pt_201812.dt)::text = ($1)::text)
Rows Removed by Filter: 1
Buffers: shared hit=1
> Seq Scan on mig.test_pt_max (cost=0.00..20.75 rows=4 width=32) (actual time=0.000..0.000 rows=0 loops=1)
Output: test_pt_max.event_cd
Filter: ((test_pt_max.dt)::text = ($1)::text)
2018-09-13 15:57:16 KST [22161]: [36-1] db=dhbsc,user=mig,app=[Postgres Enterprise Manager - Query Tool],host=[192.168.0.1] CONTEXT: SQL statement "select event_cd from test where dt=a_dt"
edb-spl function zzz_test_edb(character varying) line 5 at SQL statement
2018-09-13 15:57:16 KST [22161]: [37-1] db=dhbsc,user=mig,app=[Postgres Enterprise Manager - Query Tool],host=[192.168.0.1] LOG: duration: 0.681 ms plan:
Query Text: select /* spiderman */ * from zzz_test_edb('20171231');
Function Scan on mig.zzz_test_edb (cost=0.25..0.26 rows=1 width=32) (actual time=0.670..0.670 rows=1 loops=1)
Output: zzz_test_edb
Function Call: zzz_test_edb('20171231'::character varying)
Buffers: shared hit=9

1 ACCEPTED SOLUTION

Accepted Solutions
EDB Team Member

Re: auto_explain.log_nested_statements=TRUE --- NOT WORKING

Hi hellower,

 

Thank you for sharing your query with EDB. After making an attempt, We are able to reproduce the issue. Later, upon making certain changes to one more auto_explain parameter, It seems functioning as expected.

 

test=# set auto_explain.log_min_duration=0;
SET
test=# set auto_explain.log_nested_statements=TRUE;
SET
test=# load 'auto_explain';
LOAD

test=# select /* spiderman */ * from zzz_test_edb('20171231');
zzz_test_edb
--------------
test
(1 row)

 

This test case delivers expected result. I am able to see below entries inside log file.

 

2018-10-30 19:01:05 IST LOG: duration: 0.047 ms plan:
Query Text: select event_cd from test where dt=a_dt
Append (cost=0.00..62.25 rows=12 width=32)
-> Seq Scan on test_pt_201806 (cost=0.00..20.75 rows=4 width=32)
Filter: ((dt)::text = ($1)::text)
-> Seq Scan on test_pt_201812 (cost=0.00..20.75 rows=4 width=32)
Filter: ((dt)::text = ($1)::text)
-> Seq Scan on test_pt_max (cost=0.00..20.75 rows=4 width=32)
Filter: ((dt)::text = ($1)::text)
2018-10-30 19:01:05 IST CONTEXT: SQL statement "select event_cd from test where dt=a_dt"
edb-spl function zzz_test_edb(character varying) line 5 at SQL statement
2018-10-30 19:01:05 IST LOG: duration: 1.138 ms plan:
Query Text: select /* spiderman */ * from zzz_test_edb('20171231');
Function Scan on zzz_test_edb (cost=0.25..0.26 rows=1 width=32)

 

Hope this may help you.

 

Thanks & Regards,

Ninad Shah

 

2 REPLIES
EDB Team Member

Re: auto_explain.log_nested_statements=TRUE --- NOT WORKING

Hi hellower,

 

Thank you for sharing your query with EDB. After making an attempt, We are able to reproduce the issue. Later, upon making certain changes to one more auto_explain parameter, It seems functioning as expected.

 

test=# set auto_explain.log_min_duration=0;
SET
test=# set auto_explain.log_nested_statements=TRUE;
SET
test=# load 'auto_explain';
LOAD

test=# select /* spiderman */ * from zzz_test_edb('20171231');
zzz_test_edb
--------------
test
(1 row)

 

This test case delivers expected result. I am able to see below entries inside log file.

 

2018-10-30 19:01:05 IST LOG: duration: 0.047 ms plan:
Query Text: select event_cd from test where dt=a_dt
Append (cost=0.00..62.25 rows=12 width=32)
-> Seq Scan on test_pt_201806 (cost=0.00..20.75 rows=4 width=32)
Filter: ((dt)::text = ($1)::text)
-> Seq Scan on test_pt_201812 (cost=0.00..20.75 rows=4 width=32)
Filter: ((dt)::text = ($1)::text)
-> Seq Scan on test_pt_max (cost=0.00..20.75 rows=4 width=32)
Filter: ((dt)::text = ($1)::text)
2018-10-30 19:01:05 IST CONTEXT: SQL statement "select event_cd from test where dt=a_dt"
edb-spl function zzz_test_edb(character varying) line 5 at SQL statement
2018-10-30 19:01:05 IST LOG: duration: 1.138 ms plan:
Query Text: select /* spiderman */ * from zzz_test_edb('20171231');
Function Scan on zzz_test_edb (cost=0.25..0.26 rows=1 width=32)

 

Hope this may help you.

 

Thanks & Regards,

Ninad Shah

 

Adventurer

Re: auto_explain.log_nested_statements=TRUE --- NOT WORKING

Thanks