[jira] [Created] (HAWQ-198) Build-in functions will be executed in resource_negotiator stage which causes it will be executed twice

["Dong Li (JIRA)" <ji...@apache.org>]

Dong Li created HAWQ-198:
----------------------------

             Summary: Build-in functions will be executed in resource_negotiator  stage which causes it will be executed twice 
                 Key: HAWQ-198
                 URL: https://issues.apache.org/jira/browse/HAWQ-198
             Project: Apache HAWQ
          Issue Type: Bug
          Components: Core
            Reporter: Dong Li
            Assignee: Lei Chang


Build-in functions will be executed twice as it will be executed in resource_negotiator stage.
I use function gp_elog() to make a demo. Function gp_elog() permit superuser to insert elog information into pg_log.
{code}
select gp_elog('!!!!!!!!!!again test !!!!!!');
{code}

When I vim the pg_log file, I find that the log information display twice.
2015-11-27 16:35:15.912111 CST,"intern","ff",p40030,th-1593601580,"[local]",,2015-11-25 18:17:21 CST,1080,con25,cmd42,seg-10000,,,x1080,sx1,"LOG","XX100","!!!!!!!!!!again test !!!!!!",,,,,,,0,,,,
2015-11-27 16:35:45.985348 CST,"intern","ff",p40030,th-1593601580,"[local]",,2015-11-25 18:17:21 CST,1080,con25,cmd42,seg-10000,,,x1080,sx1,"LOG","XX100","!!!!!!!!!!again test !!!!!!",,,,,,,0,,,,

When I use lldb to debug and set breakpoint in function gp_elog. I find gp_elog is executed twice. And I put the bt information for the two times calling below, and you will find  it was exectuted in the resource_negotiator stage when it  should not be actually executed. 

The first calling for gp_elog
{code}
* thread #1: tid = 0xe078b, 0x0056ca0d postgres`gp_elog(fcinfo=0xbfffd6bc) + 17 at elog.c:4130, queue = 'com.apple.main-thread', stop reason = breakpoint 1.1
  * frame #0: 0x0056ca0d postgres`gp_elog(fcinfo=0xbfffd6bc) + 17 at elog.c:4130
    frame #1: 0x00294ab8 postgres`ExecMakeFunctionResult(fcache=0x049237c0, econtext=0x04923c58, isNull=0xbfffdb0b, isDone=0x00000000) + 1730 at execQual.c:1749
    frame #2: 0x002957e1 postgres`ExecEvalFunc(fcache=0x049237c0, econtext=0x04923c58, isNull=0xbfffdb0b, isDone=0x00000000) + 104 at execQual.c:2197
    frame #3: 0x0029a3dd postgres`ExecEvalExprSwitchContext(expression=0x049237c0, econtext=0x04923c58, isNull=0xbfffdb0b, isDone=0x00000000) + 58 at execQual.c:4426
    frame #4: 0x003db70a postgres`evaluate_expr(expr=0x04921f14, result_type=2278) + 111 at clauses.c:3354
    frame #5: 0x003dac9a postgres`evaluate_function(funcid=5044, result_type=2278, args=0x04921e8c, func_tuple=0x040e84d0, context=0xbfffe598) + 388 at clauses.c:2960
    frame #6: 0x003daa1e postgres`simplify_function(funcid=5044, result_type=2278, args=0x04921e8c, allow_inline='\x01', context=0xbfffe598) + 208 at clauses.c:2816
    frame #7: 0x003d8a88 postgres`eval_const_expressions_mutator(node=0x04921b18, context=0xbfffe598) + 757 at clauses.c:1757
    frame #8: 0x003dd606 postgres`expression_tree_mutator(node=0x04921adc, mutator=0x003d8793, context=0xbfffe598) + 7705 at clauses.c:3922
    frame #9: 0x003da4b8 postgres`eval_const_expressions_mutator(node=0x04921adc, context=0xbfffe598) + 7461 at clauses.c:2519
    frame #10: 0x003dd6d4 postgres`expression_tree_mutator(node=0x04921c40, mutator=0x003d8793, context=0xbfffe598) + 7911 at clauses.c:3958
    frame #11: 0x003da4b8 postgres`eval_const_expressions_mutator(node=0x04921c40, context=0xbfffe598) + 7461 at clauses.c:2519


    frame #12: 0x003d8742 postgres`eval_const_expressions(root=0x04921c98, node=0x04921c40) + 92 at clauses.c:1643
    frame #13: 0x003b6ee5 postgres`preprocess_expression(root=0x04921c98, expr=0x04921c40, kind=1) + 143 at planner.c:1117
    frame #14: 0x003b690d postgres`subquery_planner(glob=0x050310e8, parse=0x04921a40, parent_root=0x00000000, tuple_fraction=0, subroot=0xbfffe698, config=0x05030aa0) + 896 at planner.c:857
    frame #15: 0x003b60d1 postgres`standard_planner(parse=0x04921a40, cursorOptions=0, boundParams=0x00000000) + 494 at planner.c:587
    frame #16: 0x003b5df4 postgres`resource_negotiator(parse=0x05030ee8, cursorOptions=0, boundParams=0x00000000, resourceLife=QRL_ONCE, result=0xbfffe7b4) + 79 at planner.c:476
    frame #17: 0x003b566b postgres`planner(parse=0x05030ee8, cursorOptions=0, boundParams=0x00000000, resourceLife=QRL_ONCE) + 466 at planner.c:303


    frame #18: 0x0046c773 postgres`pg_plan_query(querytree=0x05030ee8, boundParams=0x00000000, resource_life=QRL_ONCE) + 86 at postgres.c:816
    frame #19: 0x0046c89e postgres`pg_plan_queries(querytrees=0x05031654, boundParams=0x00000000, needSnapshot='\0', resource_life=QRL_ONCE) + 131 at postgres.c:889
    frame #20: 0x0046dfc0 postgres`exec_simple_query(query_string=0x0503022c, seqServerHost=0x00000000, seqServerPort=-1) + 1357 at postgres.c:1647
    frame #21: 0x00473bcc postgres`PostgresMain(argc=4, argv=0x05005d28, username=0x05005c48) + 7964 at postgres.c:4691
    frame #22: 0x0041072d postgres`BackendRun(port=0x0431bc80) + 1008 at postmaster.c:5844
    frame #23: 0x0040fac7 postgres`BackendStartup(port=0x0431bc80) + 381 at postmaster.c:5437
    frame #24: 0x00409259 postgres`ServerLoop + 1111 at postmaster.c:2139
    frame #25: 0x00407fe6 postgres`PostmasterMain(argc=9, argv=0x04319560) + 5127 at postmaster.c:1431
    frame #26: 0x0031f553 postgres`main(argc=9, argv=0x04319560) + 1007 at main.c:226
    frame #27: 0x00001fad postgres`_start + 212
    frame #28: 0x00001ed8 postgres`start + 40
{code}

The second calling for gp_elog
{code}
thread #1: tid = 0xe078b, 0x0056ca0d postgres`gp_elog(fcinfo=0xbfffd76c) + 17 at elog.c:4130, queue = 'com.apple.main-thread', stop reason = breakpoint 1.1
  * frame #0: 0x0056ca0d postgres`gp_elog(fcinfo=0xbfffd76c) + 17 at elog.c:4130
    frame #1: 0x00294ab8 postgres`ExecMakeFunctionResult(fcache=0x0491f3c0, econtext=0x0491f858, isNull=0xbfffdbbb, isDone=0x00000000) + 1730 at execQual.c:1749
    frame #2: 0x002957e1 postgres`ExecEvalFunc(fcache=0x0491f3c0, econtext=0x0491f858, isNull=0xbfffdbbb, isDone=0x00000000) + 104 at execQual.c:2197
    frame #3: 0x0029a3dd postgres`ExecEvalExprSwitchContext(expression=0x0491f3c0, econtext=0x0491f858, isNull=0xbfffdbbb, isDone=0x00000000) + 58 at execQual.c:4426
    frame #4: 0x003db70a postgres`evaluate_expr(expr=0x05035954, result_type=2278) + 111 at clauses.c:3354
    frame #5: 0x003dac9a postgres`evaluate_function(funcid=5044, result_type=2278, args=0x05035928, func_tuple=0x040e84d0, context=0xbfffe6a8) + 388 at clauses.c:2960
    frame #6: 0x003daa1e postgres`simplify_function(funcid=5044, result_type=2278, args=0x05035928, allow_inline='\x01', context=0xbfffe6a8) + 208 at clauses.c:2816
    frame #7: 0x003d8a88 postgres`eval_const_expressions_mutator(node=0x0503535c, context=0xbfffe6a8) + 757 at clauses.c:1757
    frame #8: 0x003dd606 postgres`expression_tree_mutator(node=0x05035320, mutator=0x003d8793, context=0xbfffe6a8) + 7705 at clauses.c:3922
    frame #9: 0x003da4b8 postgres`eval_const_expressions_mutator(node=0x05035320, context=0xbfffe6a8) + 7461 at clauses.c:2519
    frame #10: 0x003dd6d4 postgres`expression_tree_mutator(node=0x050352f4, mutator=0x003d8793, context=0xbfffe6a8) + 7911 at clauses.c:3958
    frame #11: 0x003da4b8 postgres`eval_const_expressions_mutator(node=0x050352f4, context=0xbfffe6a8) + 7461 at clauses.c:2519

    frame #12: 0x003ddb92 postgres`query_tree_mutator(query=0x05035758, mutator=0x003d8793, context=0xbfffe6a8, flags=0) + 222 at clauses.c:4066
    frame #13: 0x003de4b0 postgres`query_or_expression_tree_mutator(node=0x0503521c, mutator=0x003d8793, context=0xbfffe6a8, flags=0) + 56 at clauses.c:4313
    frame #14: 0x003d8674 postgres`fold_constants(q=0x0503521c, boundParams=0x00000000, max_size=102400) + 113 at clauses.c:1550
    frame #15: 0x003cf449 postgres`preprocess_query_optimizer(query=0x0503521c, boundParams=0x00000000) + 52 at transform.c:49
    frame #16: 0x003b5455 postgres`optimize_query(parse=0x05030ee8, boundParams=0x00000000) + 42 at planner.c:247
    frame #17: 0x003b58d2 postgres`planner(parse=0x05030ee8, cursorOptions=0, boundParams=0x00000000, resourceLife=QRL_ONCE) + 1081 at planner.c:356


    frame #18: 0x0046c773 postgres`pg_plan_query(querytree=0x05030ee8, boundParams=0x00000000, resource_life=QRL_ONCE) + 86 at postgres.c:816
    frame #19: 0x0046c89e postgres`pg_plan_queries(querytrees=0x05031654, boundParams=0x00000000, needSnapshot='\0', resource_life=QRL_ONCE) + 131 at postgres.c:889
    frame #20: 0x0046dfc0 postgres`exec_simple_query(query_string=0x0503022c, seqServerHost=0x00000000, seqServerPort=-1) + 1357 at postgres.c:1647
    frame #21: 0x00473bcc postgres`PostgresMain(argc=4, argv=0x05005d28, username=0x05005c48) + 7964 at postgres.c:4691
    frame #22: 0x0041072d postgres`BackendRun(port=0x0431bc80) + 1008 at postmaster.c:5844
    frame #23: 0x0040fac7 postgres`BackendStartup(port=0x0431bc80) + 381 at postmaster.c:5437
    frame #24: 0x00409259 postgres`ServerLoop + 1111 at postmaster.c:2139
    frame #25: 0x00407fe6 postgres`PostmasterMain(argc=9, argv=0x04319560) + 5127 at postmaster.c:1431
    frame #26: 0x0031f553 postgres`main(argc=9, argv=0x04319560) + 1007 at main.c:226
    frame #27: 0x00001fad postgres`_start + 212
    frame #28: 0x00001ed8 postgres`start + 40
{code}




--
This message was sent by Atlassian JIRA
(v6.3.4#6332)