Thread: auto_explain log_verbose causes regression failure

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 *
fromarrtest1;               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
arrtest1set 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}
(1row) 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}
(1row) 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.
Thelarge 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.
Thelarge f1 value will
 

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

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

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

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=<valueoptimized 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

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

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

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.comPG East:  http://www.enterprisedb.com/community/nav-pg-east-2010.do + If your life is a hard
drive,Christ can be your backup. +
 

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
subtransactionis aborted       Message-Id: <20100218030646.500A37541C5@cvs.postgresql.org> - Fix ExecEvalArrayRef to
passdown 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

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

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.comPG East:  http://www.enterprisedb.com/community/nav-pg-east-2010.do + If your life is a hard
drive,Christ can be your backup. +