You are viewing a plain text version of this content. The canonical link for it is here.
Posted to issues@trafodion.apache.org by "Suresh Subbiah (JIRA)" <ji...@apache.org> on 2015/10/05 17:47:27 UTC
[jira] [Updated] (TRAFODION-842) LP Bug: 1404274 -
Compile_time_monitor outputs huge value for Optimization Tasks
[ https://issues.apache.org/jira/browse/TRAFODION-842?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
Suresh Subbiah updated TRAFODION-842:
-------------------------------------
Assignee: Qifan Chen (was: Ravisha Neelakanthappa)
> LP Bug: 1404274 - Compile_time_monitor outputs huge value for Optimization Tasks
> --------------------------------------------------------------------------------
>
> Key: TRAFODION-842
> URL: https://issues.apache.org/jira/browse/TRAFODION-842
> Project: Apache Trafodion
> Issue Type: Bug
> Components: sql-cmp
> Reporter: Ravisha Neelakanthappa
> Assignee: Qifan Chen
>
> I have noticed huge value for optimization ET as shown below:
> Optimization Passes: Time = 3.65e+06 ms ET = 1.41814e+09 s Counts = 3 GoodCnts = 1
> Optimize Group Task: Time = 3.65e+06 ms ET = 1.41814e+09 s Counts = 3 GoodCnts = 1
> >>cqd COMPILE_TIME_MONITOR 'on';
> Memo Groups: 2
> Memo LogExprs: 2
> Memo PhyExprs: 2
> Memo Plans: 3
> Memo Plans: 3
> Memo Contexts: 3
> Optimization Passes: Time = 3.65e+06 ms ET = 1.41771e+09 s Counts = 3 GoodCnts = 1
> Optimize Group Task: Time = 3.65e+06 ms ET = 1.41771e+09 s Counts = 3 GoodCnts = 1
> Optimize Expr Task : Time = 0 ms ET = 3.69549e-05 s Counts = 2 GoodCnts = 0
> Apply Rule Task : Time = 0 ms ET = 2.00272e-05 s Counts = 2 GoodCnts = 0
> Create Plan Task : Time = 0 ms ET = 4.50611e-05 s Counts = 4 GoodCnts = 0
> Explore Group Task : Time = 0 ms ET = 0 s Counts = 0 GoodCnts = 0
> Explore Expr Task : Time = 0 ms ET = 0 s Counts = 0 GoodCnts = 0
> Gbg Collection Task: Time = 0 ms ET = 0 s Counts = 0 GoodCnts = 0
> I narrowed it to this piece of code in opt.cpp:
> void QueryOptimizerDriver::optimizeAPassHelper(Context *context)
> {
> char taskCountStr[100], newTaskCountStr[100];
> Lng32 taskThreshold = CURRSTMT_OPTDEFAULTS->memUsageTaskThreshold();
> Lng32 taskInterval = CURRSTMT_OPTDEFAULTS->memUsageTaskInterval();
> Lng32 taskCountBegin;
> short stride = 0;
> sprintf(taskCountStr, "%d OptTasks", taskCount_);
> taskCountBegin = taskCount_;
> MonitorMemoryUsage_Enter(taskCountStr, NULL, TRUE);
> if (CURRSTMT_OPTDEFAULTS->compileTimeMonitor()) {
> (*CURRSTMT_OPTGLOBALS->cascadesPassMonitor).enter();
> }
> . . .
> if (CURRSTMT_OPTDEFAULTS->compileTimeMonitor())
> (*CURRSTMT_OPTGLOBALS->cascadesTasksMonitor[next_task_type]).enter();
> // remember current & previous task (for debugging & tracking)
> CascadesTask* prev = CURRSTMT_OPTDEFAULTS->getCurrentTask();
> CURRSTMT_OPTDEFAULTS->setCurrentTask(next_task);
> next_task->perform(taskCount_); // tasks destroy themselves
> // previous task becomes current task (for debugging & tracking)
> CURRSTMT_OPTDEFAULTS->setCurrentTask(prev);
> TEST_ERROR_HANDLING();
> if (CURRSTMT_OPTDEFAULTS->compileTimeMonitor())
> (*CURRSTMT_OPTGLOBALS->cascadesTasksMonitor[next_task_type]).exit();
> } // while task list is not empty
> if (CURRSTMT_OPTDEFAULTS->compileTimeMonitor()) {
> (*CURRSTMT_OPTGLOBALS->cascadesPassMonitor).exit();
> }
> . . .
> But the problem happens even before coming here..In the constructor CmpStatement::CmpStatement of "CmpStatement.cpp", we call:
> compStats_ = new (heap_) CompilationStats();
> optGlobals_ = new (heap_) OptGlobals(heap_);
> queryAnalysis_ = NULL;
> cqsWA_ = NULL;
> I stepped-in to OptGlobals() constructor and here are the pointer values for two different data members:
> // TaskMonitor cascadesTasksMonitor[CascadesTask::NUMBER_OF_TASK_TYPES];
> for (Int32 i = 0; i < CascadesTask::NUMBER_OF_TASK_TYPES; i++)
> cascadesTasksMonitor[i] = new (heap_) TaskMonitor;
> (gdb) p cascadesTasksMonitor[0]
> $1 = (TaskMonitor *) 0x7fffd6868f20
> cascadesPassMonitor = new (heap_) TaskMonitor;
> (gdb) p cascadesPassMonitor
> $3 = (TaskMonitor *) 0x7fffd6869038
> But, when get out of OptGlobals() back to calling method CmpStatement::CmpStatement(), I see value 0x7fffd6869038 for both member pointers.
> (gdb) p optGlobals_->cascadesTasksMonitor[0]
> $7 = (TaskMonitor *) 0x7fffd6869038
> The value should have been 0x7fffd6868f20
> (gdb) p optGlobals_->cascadesPassMonitor
> $8 = (TaskMonitor *) 0x7fffd6869038
> This is the root cause for the huge ET value.
> You can reproduce this by :
> >> cqd COMPILE_TIME_MONITOR 'on'; // let it run
> >> cqd COMPILE_TIME_MONITOR_OUTPUT_FILE 'a1.out'; // debug this stmt
> Put a break point in OptGlobals::OptGlobals
--
This message was sent by Atlassian JIRA
(v6.3.4#6332)