auto_explain log_verbose causes regression failure

Started by Andrew Dunstanover 16 years ago10 messages

andrew.dunstan@pgexperts.com

over 16 years ago

I am getting a repeatable failure on the HEAD regression tests when
auto_explain's log_verbose is set. If auto_explain.log_verbose is turned
off the failure disappears. Data below.

cheers

andrew

config settings:

custom_variable_classes = 'auto_explain'
auto_explain.log_min_duration = 0
auto_explain.log_format = 'xml'
auto_explain.log_analyze = on
auto_explain.log_verbose = on
shared_preload_libraries = 'auto_explain'

regression diffs:

*** 
/home/andrew/pgl/pgsql.hetry/src/test/regress/expected/transactions.out     
2009-08-09 19:29:31.000000000 -0400
--- 
/home/andrew/pgl/pgsql.hetry/src/test/regress/results/transactions.out      
2009-08-19 19:48:20.000000000 -0400
***************
*** 496,504 ****
  (1 row)

  rollback to x;
  -- should fail
  fetch from foo;
! ERROR:  cursor "foo" does not exist
  commit;
  begin;
  create table abc (a int);
--- 496,506 ----
  (1 row)

  rollback to x;
+ WARNING:  AbortSubTransaction while in ABORT state
+ ERROR:  cache lookup failed for attribute 1 of relation 28000
  -- should fail
  fetch from foo;
! ERROR:  current transaction is aborted, commands ignored until end of 
transaction block
  commit;
  begin;
  create table abc (a int);
***************
*** 527,532 ****
--- 529,536 ----
  (1 row)

  abort;
+ WARNING:  AbortTransaction while in ABORT state
+ ERROR:  cache lookup failed for attribute 1 of relation 28003
  -- tests for the "tid" type
  SELECT '(3, 3)'::tid = '(3, 4)'::tid;
   ?column?

======================================================================

*** /home/andrew/pgl/pgsql.hetry/src/test/regress/expected/arrays.out   
2009-08-09 19:29:31.000000000 -0400
--- /home/andrew/pgl/pgsql.hetry/src/test/regress/results/arrays.out    
2009-08-19 19:48:21.000000000 -0400
***************
*** 15,22 ****
--- 15,25 ----
  --
  INSERT INTO arrtest (a[1:5], b[1:1][1:2][1:2], c, d, f, g)
     VALUES ('{1,2,3,4,5}', '{{{0,0},{1,2}}}', '{}', '{}', '{}', '{}');
+ ERROR:  unexpected refassgnexpr
  UPDATE arrtest SET e[0] = '1.1';
+ ERROR:  unexpected refassgnexpr
  UPDATE arrtest SET e[1] = '2.2';
+ ERROR:  unexpected refassgnexpr
  INSERT INTO arrtest (f)
     VALUES ('{"too long"}');
  ERROR:  value too long for type character(5)
***************
*** 24,38 ****
     VALUES ('{11,12,23}', '{{3,4},{4,5}}', '{"foobar"}',
             '{{"elt1", "elt2"}}', '{"3.4", "6.7"}',
             '{"abc","abcde"}', '{"abc","abcde"}');
  INSERT INTO arrtest (a, b[1:2], c, d[1:2])
     VALUES ('{}', '{3,4}', '{foo,bar}', '{bar,foo}');
  SELECT * FROM arrtest;
        a      |        b        |     c     |       d       |        
e        |        f        |      g     
! 
-------------+-----------------+-----------+---------------+-----------------+-----------------+-------------
!  {1,2,3,4,5} | {{{0,0},{1,2}}} | {}        | {}            | 
[0:1]={1.1,2.2} | {}              | {}
!  {11,12,23}  | {{3,4},{4,5}}   | {foobar}  | {{elt1,elt2}} | 
{3.4,6.7}       | {"abc  ",abcde} | {abc,abcde}
!  {}          | {3,4}           | {foo,bar} | {bar,foo}     
|                 |                 |
! (3 rows)

  SELECT arrtest.a[1],
            arrtest.b[1][1][1],
--- 27,40 ----
     VALUES ('{11,12,23}', '{{3,4},{4,5}}', '{"foobar"}',
             '{{"elt1", "elt2"}}', '{"3.4", "6.7"}',
             '{"abc","abcde"}', '{"abc","abcde"}');
+ ERROR:  unexpected refassgnexpr
  INSERT INTO arrtest (a, b[1:2], c, d[1:2])
     VALUES ('{}', '{3,4}', '{foo,bar}', '{bar,foo}');
+ ERROR:  unexpected refassgnexpr
  SELECT * FROM arrtest;
   a | b | c | d | e | f | g
! ---+---+---+---+---+---+---
! (0 rows)

SELECT arrtest.a[1],
arrtest.b[1][1][1],
***************
*** 41,60 ****
arrtest.e[0]
FROM arrtest;
a | b | c | d | e
! ----+---+--------+------+-----
! 1 | 0 | | | 1.1
! 11 | | foobar | elt1 |
! | | foo | |
! (3 rows)

SELECT a[1], b[1][1][1], c[1], d[1][1], e[0]
FROM arrtest;
a | b | c | d | e
! ----+---+--------+------+-----
! 1 | 0 | | | 1.1
! 11 | | foobar | elt1 |
! | | foo | |
! (3 rows)

  SELECT a[1:3],
            b[1:1][1:2][1:2],
--- 43,56 ----
            arrtest.e[0]
     FROM arrtest;
   a | b | c | d | e
! ---+---+---+---+---
! (0 rows)

SELECT a[1], b[1][1][1], c[1], d[1][1], e[0]
FROM arrtest;
a | b | c | d | e
! ---+---+---+---+---
! (0 rows)

SELECT a[1:3],
b[1:1][1:2][1:2],
***************
*** 62,90 ****
d[1:1][1:2]
FROM arrtest;
a | b | c | d
! ------------+-----------------+-----------+---------------
! {1,2,3} | {{{0,0},{1,2}}} | {} | {}
! {11,12,23} | {} | {foobar} | {{elt1,elt2}}
! {} | {} | {foo,bar} | {}
! (3 rows)

SELECT array_ndims(a) AS a,array_ndims(b) AS b,array_ndims(c) AS c
FROM arrtest;
a | b | c
---+---+---
! 1 | 3 |
! 1 | 2 | 1
! | 1 | 1
! (3 rows)

SELECT array_dims(a) AS a,array_dims(b) AS b,array_dims(c) AS c
FROM arrtest;
a | b | c
! -------+-----------------+-------
! [1:5] | [1:1][1:2][1:2] |
! [1:3] | [1:2][1:2] | [1:1]
! | [1:2] | [1:2]
! (3 rows)

  -- returns nothing
  SELECT *
--- 58,77 ----
            d[1:1][1:2]
     FROM arrtest;
   a | b | c | d
! ---+---+---+---
! (0 rows)

SELECT array_ndims(a) AS a,array_ndims(b) AS b,array_ndims(c) AS c
FROM arrtest;
a | b | c
---+---+---
! (0 rows)

SELECT array_dims(a) AS a,array_dims(b) AS b,array_dims(c) AS c
FROM arrtest;
a | b | c
! ---+---+---
! (0 rows)

-- returns nothing
SELECT *
***************
*** 98,117 ****
UPDATE arrtest
SET a[1:2] = '{16,25}'
WHERE NOT a = '{}'::_int2;
UPDATE arrtest
SET b[1:1][1:1][1:2] = '{113, 117}',
b[1:1][1:2][2:2] = '{142, 147}'
WHERE array_dims(b) = '[1:1][1:2][1:2]';
UPDATE arrtest
SET c[2:2] = '{"new_word"}'
WHERE array_dims(c) is not null;
SELECT a,b,c FROM arrtest;
a | b | c
! ---------------+-----------------------+-------------------
! {16,25,3,4,5} | {{{113,142},{1,147}}} | {}
! {} | {3,4} | {foo,new_word}
! {16,25,23} | {{3,4},{4,5}} | {foobar,new_word}
! (3 rows)

  SELECT a[1:3],
            b[1:1][1:2][1:2],
--- 85,104 ----
  UPDATE arrtest
    SET a[1:2] = '{16,25}'
    WHERE NOT a = '{}'::_int2;
+ ERROR:  unexpected refassgnexpr
  UPDATE arrtest
    SET b[1:1][1:1][1:2] = '{113, 117}',
        b[1:1][1:2][2:2] = '{142, 147}'
    WHERE array_dims(b) = '[1:1][1:2][1:2]';
+ ERROR:  unexpected refassgnexpr
  UPDATE arrtest
    SET c[2:2] = '{"new_word"}'
    WHERE array_dims(c) is not null;
+ ERROR:  unexpected refassgnexpr
  SELECT a,b,c FROM arrtest;
   a | b | c
! ---+---+---
! (0 rows)

SELECT a[1:3],
b[1:1][1:2][1:2],
***************
*** 119,156 ****
d[1:1][2:2]
FROM arrtest;
a | b | c | d
! ------------+-----------------------+-------------------+----------
! {16,25,3} | {{{113,142},{1,147}}} | {} | {}
! {} | {} | {foo,new_word} | {}
! {16,25,23} | {} | {foobar,new_word} | {{elt2}}
! (3 rows)

INSERT INTO arrtest(a) VALUES('{1,null,3}');
SELECT a FROM arrtest;
a
! ---------------
! {16,25,3,4,5}
! {}
! {16,25,23}
{1,NULL,3}
! (4 rows)

UPDATE arrtest SET a[4] = NULL WHERE a[2] IS NULL;
SELECT a FROM arrtest WHERE a[2] IS NULL;
a
! -----------------
! [4:4]={NULL}
! {1,NULL,3,NULL}
! (2 rows)

DELETE FROM arrtest WHERE a[2] IS NULL AND b IS NULL;
SELECT a,b,c FROM arrtest;
a | b | c
! ---------------+-----------------------+-------------------
! {16,25,3,4,5} | {{{113,142},{1,147}}} | {}
! {16,25,23} | {{3,4},{4,5}} | {foobar,new_word}
! [4:4]={NULL} | {3,4} | {foo,new_word}
! (3 rows)

  --
  -- test array extension
--- 106,134 ----
            d[1:1][2:2]
     FROM arrtest;
   a | b | c | d
! ---+---+---+---
! (0 rows)

INSERT INTO arrtest(a) VALUES('{1,null,3}');
SELECT a FROM arrtest;
a
! ------------
{1,NULL,3}
! (1 row)

UPDATE arrtest SET a[4] = NULL WHERE a[2] IS NULL;
+ ERROR: unexpected refassgnexpr
SELECT a FROM arrtest WHERE a[2] IS NULL;
a
! ------------
! {1,NULL,3}
! (1 row)

DELETE FROM arrtest WHERE a[2] IS NULL AND b IS NULL;
SELECT a,b,c FROM arrtest;
a | b | c
! ---+---+---
! (0 rows)

--
-- test array extension
***************
*** 164,250 ****
(1 row)

update arrtest1 set i[2] = 22, t[2] = 'twenty-two';
select * from arrtest1;
i | t
! ---------------+----------------------------
! {1,22,NULL,4} | {one,twenty-two,NULL,four}
(1 row)

update arrtest1 set i[5] = 5, t[5] = 'five';
select * from arrtest1;
i | t
! -----------------+---------------------------------
! {1,22,NULL,4,5} | {one,twenty-two,NULL,four,five}
(1 row)

update arrtest1 set i[8] = 8, t[8] = 'eight';
select * from arrtest1;
i |
t
!
-----------------------------+-------------------------------------------------
! {1,22,NULL,4,5,NULL,NULL,8} |
{one,twenty-two,NULL,four,five,NULL,NULL,eight}
(1 row)

update arrtest1 set i[0] = 0, t[0] = 'zero';
select * from arrtest1;
i |
t
!
-------------------------------------+------------------------------------------------------------
! [0:8]={0,1,22,NULL,4,5,NULL,NULL,8} |
[0:8]={zero,one,twenty-two,NULL,four,five,NULL,NULL,eight}
(1 row)

update arrtest1 set i[-3] = -3, t[-3] = 'minus-three';
select * from arrtest1;
i
|
t
!
---------------------------------------------------+-----------------------------------------------------------------------------------
! [-3:8]={-3,NULL,NULL,0,1,22,NULL,4,5,NULL,NULL,8} |
[-3:8]={minus-three,NULL,NULL,zero,one,twenty-two,NULL,four,five,NULL,NULL,eight}
(1 row)

update arrtest1 set i[0:2] = array[10,11,12], t[0:2] =
array['ten','eleven','twelve'];
select * from arrtest1;
i
|
t
!
-----------------------------------------------------+---------------------------------------------------------------------------------
! [-3:8]={-3,NULL,NULL,10,11,12,NULL,4,5,NULL,NULL,8} |
[-3:8]={minus-three,NULL,NULL,ten,eleven,twelve,NULL,four,five,NULL,NULL,eight}
(1 row)

update arrtest1 set i[8:10] = array[18,null,20], t[8:10] =
array['p18',null,'p20'];
select * from arrtest1;
i
|
t
!
---------------------------------------------------------------+-----------------------------------------------------------------------------------------
! [-3:10]={-3,NULL,NULL,10,11,12,NULL,4,5,NULL,NULL,18,NULL,20} |
[-3:10]={minus-three,NULL,NULL,ten,eleven,twelve,NULL,four,five,NULL,NULL,p18,NULL,p20}
(1 row)

update arrtest1 set i[11:12] = array[null,22], t[11:12] =
array[null,'p22'];
select * from arrtest1;
i
|
t
!
-----------------------------------------------------------------------+--------------------------------------------------------------------------------------------------
! [-3:12]={-3,NULL,NULL,10,11,12,NULL,4,5,NULL,NULL,18,NULL,20,NULL,22}
|
[-3:12]={minus-three,NULL,NULL,ten,eleven,twelve,NULL,four,five,NULL,NULL,p18,NULL,p20,NULL,p22}
(1 row)

update arrtest1 set i[15:16] = array[null,26], t[15:16] =
array[null,'p26'];
select * from arrtest1;

i
|
t
!
-----------------------------------------------------------------------------------------+---------------------------------------------------------------------------------------------------------------------
!
[-3:16]={-3,NULL,NULL,10,11,12,NULL,4,5,NULL,NULL,18,NULL,20,NULL,22,NULL,NULL,NULL,26}
|
[-3:16]={minus-three,NULL,NULL,ten,eleven,twelve,NULL,four,five,NULL,NULL,p18,NULL,p20,NULL,p22,NULL,NULL,NULL,p26}
(1 row)

update arrtest1 set i[-5:-3] = array[-15,-14,-13], t[-5:-3] =
array['m15','m14','m13'];
select * from arrtest1;

i
|
t
!
--------------------------------------------------------------------------------------------------+---------------------------------------------------------------------------------------------------------------------
!
[-5:16]={-15,-14,-13,NULL,NULL,10,11,12,NULL,4,5,NULL,NULL,18,NULL,20,NULL,22,NULL,NULL,NULL,26}
|
[-5:16]={m15,m14,m13,NULL,NULL,ten,eleven,twelve,NULL,four,five,NULL,NULL,p18,NULL,p20,NULL,p22,NULL,NULL,NULL,p26}
(1 row)

update arrtest1 set i[-7:-6] = array[-17,null], t[-7:-6] =
array['m17',null];
select * from arrtest1;

i
|
t
!
-----------------------------------------------------------------------------------------------------------+------------------------------------------------------------------------------------------------------------------------------
!
[-7:16]={-17,NULL,-15,-14,-13,NULL,NULL,10,11,12,NULL,4,5,NULL,NULL,18,NULL,20,NULL,22,NULL,NULL,NULL,26}
|
[-7:16]={m17,NULL,m15,m14,m13,NULL,NULL,ten,eleven,twelve,NULL,four,five,NULL,NULL,p18,NULL,p20,NULL,p22,NULL,NULL,NULL,p26}
(1 row)

update arrtest1 set i[-12:-10] = array[-22,null,-20], t[-12:-10] =
array['m22',null,'m20'];
select * from arrtest1;

i
|
t
!
-----------------------------------------------------------------------------------------------------------------------------------+------------------------------------------------------------------------------------------------------------------------------------------------------
!
[-12:16]={-22,NULL,-20,NULL,NULL,-17,NULL,-15,-14,-13,NULL,NULL,10,11,12,NULL,4,5,NULL,NULL,18,NULL,20,NULL,22,NULL,NULL,NULL,26}
|
[-12:16]={m22,NULL,m20,NULL,NULL,m17,NULL,m15,m14,m13,NULL,NULL,ten,eleven,twelve,NULL,four,five,NULL,NULL,p18,NULL,p20,NULL,p22,NULL,NULL,NULL,p26}
(1 row)

  delete from arrtest1;
--- 142,240 ----
  (1 row)

update arrtest1 set i[2] = 22, t[2] = 'twenty-two';
+ ERROR: unexpected refassgnexpr
select * from arrtest1;
i | t
! --------------+---------------------
! {1,2,NULL,4} | {one,two,NULL,four}
(1 row)

update arrtest1 set i[5] = 5, t[5] = 'five';
+ ERROR: unexpected refassgnexpr
select * from arrtest1;
i | t
! --------------+---------------------
! {1,2,NULL,4} | {one,two,NULL,four}
(1 row)

update arrtest1 set i[8] = 8, t[8] = 'eight';
+ ERROR: unexpected refassgnexpr
select * from arrtest1;
i | t
! --------------+---------------------
! {1,2,NULL,4} | {one,two,NULL,four}
(1 row)

update arrtest1 set i[0] = 0, t[0] = 'zero';
+ ERROR: unexpected refassgnexpr
select * from arrtest1;
i | t
! --------------+---------------------
! {1,2,NULL,4} | {one,two,NULL,four}
(1 row)

update arrtest1 set i[-3] = -3, t[-3] = 'minus-three';
+ ERROR: unexpected refassgnexpr
select * from arrtest1;
i | t
! --------------+---------------------
! {1,2,NULL,4} | {one,two,NULL,four}
(1 row)

update arrtest1 set i[0:2] = array[10,11,12], t[0:2] =
array['ten','eleven','twelve'];
+ ERROR: unexpected refassgnexpr
select * from arrtest1;
i | t
! --------------+---------------------
! {1,2,NULL,4} | {one,two,NULL,four}
(1 row)

update arrtest1 set i[8:10] = array[18,null,20], t[8:10] =
array['p18',null,'p20'];
+ ERROR: unexpected refassgnexpr
select * from arrtest1;
i | t
! --------------+---------------------
! {1,2,NULL,4} | {one,two,NULL,four}
(1 row)

update arrtest1 set i[11:12] = array[null,22], t[11:12] =
array[null,'p22'];
+ ERROR: unexpected refassgnexpr
select * from arrtest1;
i | t
! --------------+---------------------
! {1,2,NULL,4} | {one,two,NULL,four}
(1 row)

update arrtest1 set i[15:16] = array[null,26], t[15:16] =
array[null,'p26'];
+ ERROR: unexpected refassgnexpr
select * from arrtest1;
i | t
! --------------+---------------------
! {1,2,NULL,4} | {one,two,NULL,four}
(1 row)

update arrtest1 set i[-5:-3] = array[-15,-14,-13], t[-5:-3] =
array['m15','m14','m13'];
+ ERROR: unexpected refassgnexpr
select * from arrtest1;
i | t
! --------------+---------------------
! {1,2,NULL,4} | {one,two,NULL,four}
(1 row)

update arrtest1 set i[-7:-6] = array[-17,null], t[-7:-6] =
array['m17',null];
+ ERROR: unexpected refassgnexpr
select * from arrtest1;
i | t
! --------------+---------------------
! {1,2,NULL,4} | {one,two,NULL,four}
(1 row)

update arrtest1 set i[-12:-10] = array[-22,null,-20], t[-12:-10] =
array['m22',null,'m20'];
+ ERROR: unexpected refassgnexpr
select * from arrtest1;
i | t
! --------------+---------------------
! {1,2,NULL,4} | {one,two,NULL,four}
(1 row)

delete from arrtest1;
***************
*** 256,265 ****
(1 row)

update arrtest1 set i[0:5] = array[0,1,2,null,4,5], t[0:5] =
array['z','p1','p2',null,'p4','p5'];
select * from arrtest1;
i | t
! ------------------------+----------------------------
! [0:5]={0,1,2,NULL,4,5} | [0:5]={z,p1,p2,NULL,p4,p5}
(1 row)

  --
--- 246,256 ----
  (1 row)

update arrtest1 set i[0:5] = array[0,1,2,null,4,5], t[0:5] =
array['z','p1','p2',null,'p4','p5'];
+ ERROR: unexpected refassgnexpr
select * from arrtest1;
i | t
! --------------+---------------------
! {1,2,NULL,4} | {one,two,NULL,four}
(1 row)

--
***************
*** 369,377 ****
-- operators
SELECT a FROM arrtest WHERE b = ARRAY[[[113,142],[1,147]]];
a
! ---------------
! {16,25,3,4,5}
! (1 row)

  SELECT NOT ARRAY[1.1,1.2,1.3] = ARRAY[1.1,1.2,1.3] AS "FALSE";
   FALSE
--- 360,367 ----
  -- operators
  SELECT a FROM arrtest WHERE b = ARRAY[[[113,142],[1,147]]];
   a
! ---
! (0 rows)

SELECT NOT ARRAY[1.1,1.2,1.3] = ARRAY[1.1,1.2,1.3] AS "FALSE";
FALSE

======================================================================

*** /home/andrew/pgl/pgsql.hetry/src/test/regress/expected/rowtypes.out 
2008-10-14 20:27:28.000000000 -0400
--- /home/andrew/pgl/pgsql.hetry/src/test/regress/results/rowtypes.out  
2009-08-19 19:48:41.000000000 -0400
***************
*** 98,117 ****

-- test insertion/updating of subfields
update people set fn.suffix = 'Jr';
select * from people;
fn | bd
! ---------------+------------
! (Joe,Blow,Jr) | 01-10-1984
(1 row)

insert into quadtable (f1, q.c1.r, q.c2.i) values(44,55,66);
select * from quadtable;
f1 | q
----+---------------------------
1 | ("(3.3,4.4)","(5.5,6.6)")
2 | ("(,4.4)","(5.5,6.6)")
! 44 | ("(55,)","(,66)")
! (3 rows)

  -- The object here is to ensure that toasted references inside
  -- composite values don't cause problems.  The large f1 value will
--- 98,118 ----

-- test insertion/updating of subfields
update people set fn.suffix = 'Jr';
+ ERROR: unexpected FieldStore
select * from people;
fn | bd
! -------------+------------
! (Joe,Blow,) | 01-10-1984
(1 row)

insert into quadtable (f1, q.c1.r, q.c2.i) values(44,55,66);
+ ERROR: unexpected FieldStore
select * from quadtable;
f1 | q
----+---------------------------
1 | ("(3.3,4.4)","(5.5,6.6)")
2 | ("(,4.4)","(5.5,6.6)")
! (2 rows)

-- The object here is to ensure that toasted references inside
-- composite values don't cause problems. The large f1 value will

======================================================================

Robert Haas

robertmhaas@gmail.com

over 16 years ago

In reply to: Andrew Dunstan (#1)

Re: auto_explain log_verbose causes regression failure

On Wed, Aug 19, 2009 at 7:57 PM, Andrew
Dunstan<andrew.dunstan@pgexperts.com> wrot>

I am getting a repeatable failure on the HEAD regression tests when
auto_explain's log_verbose is set. If auto_explain.log_verbose is turned off
the failure disappears. Data below.

cheers

andrew

config settings:

custom_variable_classes = 'auto_explain'
auto_explain.log_min_duration = 0
auto_explain.log_format = 'xml'
auto_explain.log_analyze = on
auto_explain.log_verbose = on
shared_preload_libraries = 'auto_explain'

I can't figure out how to make this config work. I dumped these
settings into a file called "t" and then did, from src/test/regress,
TEMP_CONFIG=t make check. This results in:

make -C ../../../src/port all
make[1]: Entering directory `/home/rhaas/pgsql-git/src/port'
make[1]: Nothing to be done for `all'.
make[1]: Leaving directory `/home/rhaas/pgsql-git/src/port'
rm -rf ./testtablespace
mkdir ./testtablespace
./pg_regress --inputdir=. --dlpath=. --multibyte=SQL_ASCII
--load-language=plpgsql --temp-install=./tmp_check
--top-builddir=../../.. --schedule=./parallel_schedule
--temp-config=t
============== removing existing temp installation ==============
============== creating temporary installation ==============
============== initializing database system ==============
============== starting postmaster ==============

pg_regress: postmaster did not respond within 60 seconds
Examine /home/rhaas/pgsql-git/src/test/regress/log/postmaster.log for the reason
make: *** [check] Error 2

That file contains:

FATAL: could not access file "auto_explain": No such file or directory

I tried copying auto_explain.so into $PWD, but that did not help.

Can you describe how you got this to run the tests at all?

...Robert

Andrew Dunstan

andrew@dunslane.net

over 16 years ago

In reply to: Robert Haas (#2)

Re: auto_explain log_verbose causes regression failure

Robert Haas wrote:

On Wed, Aug 19, 2009 at 7:57 PM, Andrew
Dunstan<andrew.dunstan@pgexperts.com> wrot>

I am getting a repeatable failure on the HEAD regression tests when
auto_explain's log_verbose is set. If auto_explain.log_verbose is turned off
the failure disappears. Data below.

cheers

andrew

config settings:

custom_variable_classes = 'auto_explain'
auto_explain.log_min_duration = 0
auto_explain.log_format = 'xml'
auto_explain.log_analyze = on
auto_explain.log_verbose = on
shared_preload_libraries = 'auto_explain'

I can't figure out how to make this config work. I dumped these
settings into a file called "t" and then did, from src/test/regress,
TEMP_CONFIG=t make check.

I did make install, initdb, put settings in postgresql.conf, then make
installcheck

cheers

andrew

Robert Haas

robertmhaas@gmail.com

over 16 years ago

In reply to: Andrew Dunstan (#3)

Re: auto_explain log_verbose causes regression failure

On Wed, Aug 19, 2009 at 9:39 PM, Andrew Dunstan<andrew@dunslane.net> wrote:

Robert Haas wrote:

On Wed, Aug 19, 2009 at 7:57 PM, Andrew
Dunstan<andrew.dunstan@pgexperts.com> wrot>

I am getting a repeatable failure on the HEAD regression tests when
auto_explain's log_verbose is set. If auto_explain.log_verbose is turned
off
the failure disappears. Data below.

cheers

andrew

config settings:

custom_variable_classes = 'auto_explain'
auto_explain.log_min_duration = 0
auto_explain.log_format = 'xml'
auto_explain.log_analyze = on
auto_explain.log_verbose = on
shared_preload_libraries = 'auto_explain'

I can't figure out how to make this config work. I dumped these
settings into a file called "t" and then did, from src/test/regress,
TEMP_CONFIG=t make check.

I did make install, initdb, put settings in postgresql.conf, then make
installcheck

It looks like this is enough to reproduce the cache lookup failure:

begin;
create table abc (a int);
insert into abc values (5);
insert into abc values (10);
insert into abc values (15);
declare foo cursor for select * from abc;
fetch from foo;
abort;

And here's the backtrace:

#0 elog_start (filename=0x83c251 "lsyscache.c", lineno=805,
funcname=0x83c680 "get_relid_attribute_name") at elog.c:1085
#1 0x00000000006ce1c4 in get_relid_attribute_name (relid=63508,
attnum=<value optimized out>) at lsyscache.c:805
#2 0x00000000006789bb in get_variable (var=0x0, levelsup=33399048,
showstar=1 '\001', context=0x7fff21f99ad0) at ruleutils.c:3515
#3 0x00000000006784e3 in deparse_expression_pretty (expr=0x20033c0,
dpcontext=0x1fda130, forceprefix=0 '\0', showimplicit=-128 '\200',
prettyFlags=0, startIndent=0) at ruleutils.c:1915
#4 0x000000000051bb89 in ExplainNode (plan=0x2003270, planstate=0x202e9f8,
outer_plan=0x0, relationship=0x0, plan_name=<value optimized out>,
es=0x7fff21f99c50) at explain.c:1145
#5 0x00007f3aaf26bfd2 in explain_ExecutorEnd (queryDesc=0x20038b8)
at auto_explain.c:225
#6 0x000000000052aaa7 in PortalCleanup (portal=0x20267b0) at portalcmds.c:268
#7 0x00000000006f1ca0 in AtAbort_Portals () at portalmem.c:678
#8 0x00000000004892de in AbortTransaction () at xact.c:2036
#9 0x000000000048c8d5 in CommitTransactionCommand () at xact.c:2291
#10 0x0000000000619897 in finish_xact_command () at postgres.c:2364
#11 0x000000000061a80d in exec_simple_query (query_string=0x1fe5828 "abort;")
at postgres.c:1023
#12 0x000000000061bc77 in PostgresMain (argc=4, argv=<value optimized out>,
username=0x1f46ec0 "rhaas") at postgres.c:3615
#13 0x00000000005e8960 in ServerLoop () at postmaster.c:3392
#14 0x00000000005e972a in PostmasterMain (argc=3, argv=0x1f442a0)
at postmaster.c:1038
#15 0x000000000058c808 in main (argc=3, argv=0x1f442a0) at main.c:188

It looks to me like the problem might be something along the lines of
"by the time ExplainNode() gets called, the table is not visible any
more, so the syscache lookup fails". But that's just a guess...

...Robert

Robert Haas

robertmhaas@gmail.com

over 16 years ago

In reply to: Robert Haas (#4)

Re: auto_explain log_verbose causes regression failure

On Wed, Aug 19, 2009 at 10:07 PM, Robert Haas<robertmhaas@gmail.com> wrote:

On Wed, Aug 19, 2009 at 9:39 PM, Andrew Dunstan<andrew@dunslane.net> wrote:

Robert Haas wrote:

On Wed, Aug 19, 2009 at 7:57 PM, Andrew
Dunstan<andrew.dunstan@pgexperts.com> wrot>

I am getting a repeatable failure on the HEAD regression tests when
auto_explain's log_verbose is set. If auto_explain.log_verbose is turned
off
the failure disappears. Data below.

cheers

andrew

config settings:

custom_variable_classes = 'auto_explain'
auto_explain.log_min_duration = 0
auto_explain.log_format = 'xml'
auto_explain.log_analyze = on
auto_explain.log_verbose = on
shared_preload_libraries = 'auto_explain'

I can't figure out how to make this config work. I dumped these
settings into a file called "t" and then did, from src/test/regress,
TEMP_CONFIG=t make check.

I did make install, initdb, put settings in postgresql.conf, then make
installcheck

It looks like this is enough to reproduce the cache lookup failure:

begin;
create table abc (a int);
insert into abc values (5);
insert into abc values (10);
insert into abc values (15);
declare foo cursor for select * from abc;
fetch from foo;
abort;

...and it also looks like the same 3 tests fail in REL8_4_STABLE,
which is the oldest branch that contains auto_explain. So I suspect
this has been broken all along. I still don't know how to fix it, but
at least now I don't feel guilty for breaking it...

...Robert

Itagaki Takahiro

itagaki.takahiro@oss.ntt.co.jp

over 16 years ago

In reply to: Robert Haas (#4)

1 attachment(s)

Re: auto_explain log_verbose causes regression failure

Robert Haas <robertmhaas@gmail.com> wrote:

It looks like this is enough to reproduce the cache lookup failure:

The "cache loopup failure" part could be fixed by the attached patch.
It forbids explaining if the transaction is in error state.

I cannot reproduce "unexpected refassgnexpr" and "unexpected FieldStore"
errors yet. We might need another fix for them.

Regards,
---
ITAGAKI Takahiro
NTT Open Source Software Center

Attachments:

auto_explain-20090820.patchapplication/octet-stream; name=auto_explain-20090820.patchDownload

diff -cprN head/contrib/auto_explain/auto_explain.c auto_explain/contrib/auto_explain/auto_explain.c
*** head/contrib/auto_explain/auto_explain.c	2009-08-10 14:46:49.000000000 +0900
--- auto_explain/contrib/auto_explain/auto_explain.c	2009-08-20 11:58:40.334518429 +0900
***************
*** 12,17 ****
--- 12,18 ----
   */
  #include "postgres.h"
  
+ #include "access/xact.h"
  #include "commands/explain.h"
  #include "executor/instrument.h"
  #include "utils/guc.h"
*************** static ExecutorEnd_hook_type prev_Execut
*** 42,48 ****
  
  #define auto_explain_enabled() \
  	(auto_explain_log_min_duration >= 0 && \
! 	 (nesting_level == 0 || auto_explain_log_nested_statements))
  
  void		_PG_init(void);
  void		_PG_fini(void);
--- 43,50 ----
  
  #define auto_explain_enabled() \
  	(auto_explain_log_min_duration >= 0 && \
! 	 (nesting_level == 0 || auto_explain_log_nested_statements) && \
! 	 TransactionBlockStatusCode() == 'T')
  
  void		_PG_init(void);
  void		_PG_fini(void);

Bruce Momjian

bruce@momjian.us

almost 16 years ago

In reply to: Itagaki Takahiro (#6)

Re: auto_explain log_verbose causes regression failure

Uh, I don't see this patch as applied. Was it not necessary?

---------------------------------------------------------------------------

Itagaki Takahiro wrote:

Robert Haas <robertmhaas@gmail.com> wrote:

It looks like this is enough to reproduce the cache lookup failure:

The "cache loopup failure" part could be fixed by the attached patch.
It forbids explaining if the transaction is in error state.

I cannot reproduce "unexpected refassgnexpr" and "unexpected FieldStore"
errors yet. We might need another fix for them.

Regards,
---
ITAGAKI Takahiro
NTT Open Source Software Center

[ Attachment, skipping... ]

--
Sent via pgsql-hackers mailing list (pgsql-hackers@postgresql.org)
To make changes to your subscription:
http://www.postgresql.org/mailpref/pgsql-hackers

-- 
  Bruce Momjian  <bruce@momjian.us>        http://momjian.us
  EnterpriseDB                             http://enterprisedb.com
  PG East:  http://www.enterprisedb.com/community/nav-pg-east-2010.do
  + If your life is a hard drive, Christ can be your backup. +

Takahiro Itagaki

itagaki.takahiro@oss.ntt.co.jp

almost 16 years ago

In reply to: Bruce Momjian (#7)

Re: auto_explain log_verbose causes regression failure

Bruce Momjian <bruce@momjian.us> wrote:

Uh, I don't see this patch as applied. Was it not necessary?

No, the bug was reported again and fixed then with:
- Force READY portals into FAILED state when a transaction or subtransaction is aborted
Message-Id: <20100218030646.500A37541C5@cvs.postgresql.org>
- Fix ExecEvalArrayRef to pass down the old value of the array element or slice being assigned to
Message-Id: <20100218184147.A9EC97541C5@cvs.postgresql.org>

---------------------------------------------------------------------------

Itagaki Takahiro wrote:

Robert Haas <robertmhaas@gmail.com> wrote:

It looks like this is enough to reproduce the cache lookup failure:

The "cache loopup failure" part could be fixed by the attached patch.
It forbids explaining if the transaction is in error state.

I cannot reproduce "unexpected refassgnexpr" and "unexpected FieldStore"
errors yet. We might need another fix for them.

Regards,
---
Takahiro Itagaki
NTT Open Source Software Center

Tom Lane

tgl@sss.pgh.pa.us

almost 16 years ago

In reply to: Bruce Momjian (#7)

Re: auto_explain log_verbose causes regression failure

Bruce Momjian <bruce@momjian.us> writes:

Uh, I don't see this patch as applied. Was it not necessary?

It was not; the real problem was that ExecutorEnd shouldn't have been
called at all, which I fixed in the portal code.

regards, tom lane

#10

Bruce Momjian

bruce@momjian.us

almost 16 years ago

In reply to: Tom Lane (#9)

Re: auto_explain log_verbose causes regression failure

Tom Lane wrote:

Bruce Momjian <bruce@momjian.us> writes:

Uh, I don't see this patch as applied. Was it not necessary?

It was not; the real problem was that ExecutorEnd shouldn't have been
called at all, which I fixed in the portal code.

Thanks, both of you. :-)

-- 
  Bruce Momjian  <bruce@momjian.us>        http://momjian.us
  EnterpriseDB                             http://enterprisedb.com
  PG East:  http://www.enterprisedb.com/community/nav-pg-east-2010.do
  + If your life is a hard drive, Christ can be your backup. +