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)