Horton
Menu

Thread

  1. auto_explain causes regression failures

    Andrew Dunstan <andrew@dunslane.net> — 2010-02-16T15:41:25Z

    With the following 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 am getting regression failures on the rowtypes, transactions and 
arrays tests. Diff file is attached. I'm going to look into it, but if 
anyone has a good idea what's going on please speak up ASAP.

cheers

andrew

  2. Re: auto_explain causes regression failures

    Takahiro Itagaki <itagaki.takahiro@oss.ntt.co.jp> — 2010-02-17T05:23:36Z

    Andrew Dunstan <andrew@dunslane.net> wrote:

> With the following 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 am getting regression failures on the rowtypes, transactions and 
> arrays tests. Diff file is attached. I'm going to look into it, but if 
> anyone has a good idea what's going on please speak up ASAP.

Thank you for the bug report.  Auto_explan tries to explain the query
even if it is failed, but schema objects that are created in the same
transaction might not be available. "cache lookup failed" erros can be
avoided if auto_explain skips explaining queries in aborted transactions.

The attached patch will fix the bug, but I'm not sure whether this usage
of TransactionBlockStatusCode() is sane. Comments or better ideas?

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

  3. Re: auto_explain causes regression failures

    Tom Lane <tgl@sss.pgh.pa.us> — 2010-02-17T06:03:52Z

    Andrew Dunstan <andrew@dunslane.net> writes:
> I am getting regression failures on the rowtypes, transactions and 
> arrays tests. Diff file is attached. I'm going to look into it, but if 
> anyone has a good idea what's going on please speak up ASAP.

Hmm.  Didn't decipher the transactions-test failures yet, but the
errors about "unexpected refassgnexpr" and "unexpected FieldStore"
are a pre-existing bug that you can expose without auto_explain:

regression=# explain verbose 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

The problem is that get_rule_expr() expects any top-level assignment
nodes to have been stripped off by processIndirection(), and explain.c
is failing to cater to that.  It's not just a simple oversight ---
it's not exactly clear how such an expr tree should be printed without
any context.  Normally, we're decoding such things in the context
of reverse-listing a whole INSERT or UPDATE statement, and the upper
level ruleutils.c code takes care of putting the indirection annotation
on the target column name.  But for EXPLAIN we're just trying to treat
the plan target list as a list of standalone expressions.  What should
the display look like?

If you're lost about the point here, it's this: an ArrayExpr can
represent the result of an array assignment.  For example, given
UPDATE foo SET a[42] = x, what is generated is an ArrayExpr
with refexpr = a, refupperindexpr = 42, refassgnexpr = x.
On execution that generates the updated array value that needs to
get stored back into the "a" column.  How would you like to print
that in EXPLAIN?  Same deal for FieldStore: it can represent generating
the new value of a composite column after replacing one field.

			regards, tom lane

  4. Re: auto_explain causes regression failures

    Tom Lane <tgl@sss.pgh.pa.us> — 2010-02-17T06:16:28Z

    Andrew Dunstan <andrew@dunslane.net> writes:
> I am getting regression failures on the rowtypes, transactions and 
> arrays tests. Diff file is attached. I'm going to look into it, but if 
> anyone has a good idea what's going on please speak up ASAP.

And as for the transactions-test failures, a stack trace tells the tale:

#0  errfinish (dummy=0) at elog.c:366
#1  0x00000000006e2d3c in elog_finish (elevel=<value optimized out>, 
    fmt=<value optimized out>) at elog.c:1145
#2  0x00000000006dbf9a in get_relid_attribute_name (relid=64726, 
    attnum=<value optimized out>) at lsyscache.c:786
#3  0x0000000000685d94 in get_variable (var=0x0, levelsup=45293976, 
    showstar=<value optimized out>, context=0x7fffb0e11440) at ruleutils.c:3693
#4  0x000000000068a35d in deparse_expression_pretty (expr=0x2b320c0, 
    dpcontext=0x2a962e0, forceprefix=0 '\0', showimplicit=127 '\177', 
    prettyFlags=0, startIndent=<value optimized out>) at ruleutils.c:2055
#5  0x000000000052552c in show_plan_tlist (es=<value optimized out>, 
    plan=<value optimized out>) at explain.c:1286
#6  ExplainNode (es=<value optimized out>, plan=<value optimized out>)
    at explain.c:1001
#7  0x00007f85f70341a3 in explain_ExecutorEnd (queryDesc=0x2abb918)
    at auto_explain.c:244
#8  0x0000000000535684 in PortalCleanup (portal=<value optimized out>)
    at portalcmds.c:268
#9  0x00000000006ff82f in AtSubAbort_Portals (mySubid=2, 
    parentSubid=<value optimized out>, parentXactOwner=<value optimized out>)
    at portalmem.c:825
#10 0x000000000048a5ea in AbortSubTransaction () at xact.c:4016

We're trying to EXPLAIN a plan that refers to a table that no longer
exists, because the subtransaction that created it is already rolled
back.  I think the proximate fault here is in PortalCleanup, which
claims it ain't gonna do this:

    /*
     * Shut down executor, if still running.  We skip this during error abort,
     * since other mechanisms will take care of releasing executor resources,
     * and we can't be sure that ExecutorEnd itself wouldn't fail.
     */

but the test it's actually using is

        if (portal->status != PORTAL_FAILED)

and this particular portal is not marked FAILED, because it wasn't
running when the abort happened.  I think maybe we should force
portals into FAILED state when aborting a (sub)transaction.
Or leave the state alone but add a check on the transaction state
in this test in PortalCleanup.  Thoughts?

(Again, I think this is a pre-existing bug that auto_explain is just
exposing to the world ...)

			regards, tom lane

  5. Re: auto_explain causes regression failures

    Tom Lane <tgl@sss.pgh.pa.us> — 2010-02-17T06:21:40Z

    Takahiro Itagaki <itagaki.takahiro@oss.ntt.co.jp> writes:
> Thank you for the bug report.  Auto_explan tries to explain the query
> even if it is failed, but schema objects that are created in the same
> transaction might not be available. "cache lookup failed" erros can be
> avoided if auto_explain skips explaining queries in aborted transactions.

I don't think this is auto_explain's fault.  ExecutorEnd() shouldn't
be getting run in an aborted xact --- there are too many other things
that are likely to fall over.  See my response to Andrew.

			regards, tom lane

  6. Re: auto_explain causes regression failures

    Tom Lane <tgl@sss.pgh.pa.us> — 2010-02-18T03:11:11Z

    I wrote:
> Andrew Dunstan <andrew@dunslane.net> writes:
>> I am getting regression failures on the rowtypes, transactions and 
>> arrays tests. Diff file is attached. I'm going to look into it, but if 
>> anyone has a good idea what's going on please speak up ASAP.

> And as for the transactions-test failures, a stack trace tells the tale:
> ...
> (Again, I think this is a pre-existing bug that auto_explain is just
> exposing to the world ...)

I've applied a patch for that one.

			regards, tom lane

  7. Re: auto_explain causes regression failures

    Tom Lane <tgl@sss.pgh.pa.us> — 2010-02-18T03:17:21Z

    I wrote:
> If you're lost about the point here, it's this: an ArrayExpr can
> represent the result of an array assignment.  For example, given
> UPDATE foo SET a[42] = x, what is generated is an ArrayExpr
> with refexpr = a, refupperindexpr = 42, refassgnexpr = x.
> On execution that generates the updated array value that needs to
> get stored back into the "a" column.  How would you like to print
> that in EXPLAIN?  Same deal for FieldStore: it can represent generating
> the new value of a composite column after replacing one field.

After thinking about this for awhile, the best representation I can
come up with is to let the EXPLAIN output look like an UPDATE
assignment.  That is, from something like

	UPDATE foo SET arraycol[42] = x WHERE ...

an EXPLAIN VERBOSE would include this in the targetlist display:

	Output: ... , arraycol[42] = x , ...

An alternative possibility is to strip the indirection node(s) and
just show "x"; but that seems to leave a good deal of information
hidden, especially if the subscript expressions are complicated.

Objections, better ideas?

			regards, tom lane

  8. Re: auto_explain causes regression failures

    Tom Lane <tgl@sss.pgh.pa.us> — 2010-02-18T23:22:48Z

    Andrew Dunstan <andrew@dunslane.net> writes:
> With the following 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 am getting regression failures on the rowtypes, transactions and 
> arrays tests.

This seems to be fixed now in HEAD.  Somebody should try 8.4 as well.

			regards, tom lane

  9. Re: auto_explain causes regression failures

    Andrew Dunstan <andrew@dunslane.net> — 2010-02-20T15:46:35Z

    
Tom Lane wrote:
> Andrew Dunstan <andrew@dunslane.net> writes:
>   
>> With the following 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 am getting regression failures on the rowtypes, transactions and 
>> arrays tests.
>>     
>
> This seems to be fixed now in HEAD.  Somebody should try 8.4 as well.
>
> 			
>   

Done. All is good now. Thanks.

cheers

andrew