Re: auto_explain log_verbose causes regression failure

On Wed, Aug 19, 2009 at 9:39 PM, Andrew Dunstan<andrew(at)dunslane(dot)net> wrote:
> Robert Haas wrote:
>>
>> On Wed, Aug 19, 2009 at 7:57 PM, Andrew
>> Dunstan<andrew(dot)dunstan(at)pgexperts(dot)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