Uploaded image for project: 'Blazegraph (by SYSTAP)'
  1. Blazegraph (by SYSTAP)
  2. BLZG-875

Explain reports incorrect value for opCount

    Details

      Description

      The EXPLAIN view (QueryLog) is reporting the incorrect value for the opCount. This should be the number of times a given operator has executed. However, it is based on BOpStats.opCount.

        Activity

        Hide
        bryanthompson bryanthompson added a comment -

        The problem appears to be that opCount is pre-incremented in the BOpStats constructor and then combined in BOpStats.add(BOpStats). The only other place where it is modified is AbstractRunningQuery#haltOp(). This method is invoked any time an operator halts. Even on a cluster, the query controller for a given receives all startOp and haltOp messages for that query.

        Show
        bryanthompson bryanthompson added a comment - The problem appears to be that opCount is pre-incremented in the BOpStats constructor and then combined in BOpStats.add(BOpStats). The only other place where it is modified is AbstractRunningQuery#haltOp(). This method is invoked any time an operator halts. Even on a cluster, the query controller for a given receives all startOp and haltOp messages for that query.
        Hide
        bryanthompson bryanthompson added a comment -

        The best way to analyze this is to use hint:atOnce to force each operator in the query plan to execute only once. You can then look at the opCount column in the detailed Explain view and see whether the correct number of operator invocations was reported. It should be ONE (1) for each operator where the atOnce hint was correctly applied. If the atOnce hint is applied to an operator, then it sets pipelined:=false as follows:

        com.bigdata.bop.PipelineOp.pipelined = false

        I have modified BOPStats to NOT pre-increment opCount. I have modified AbstractRunningQuery.haltOp() to post-increment opCount

        One consequence is that the opCount will not update until the operator has halted. Thus, it is a "how many times did this operator run successfully counter" rather than a "how many times did this operator start counter". However, it is now reporting the correct values. I cross validated this by logging out the following in ChunkedRunningQuery:

                        if (log.isInfoEnabled())
                            log.info("Running task: bop=" + bundle.bopId
                                    + (pipelined?"":", atOnceReady=" + atOnceReady) + ", bop="
                                    + bop.toShortString() + ", messages=" + naccepted
                                    + ", solutions=" + solutionsAccepted
                                    + (log.isDebugEnabled()?", runState=" + runStateString():""));
                        getQueryEngine().execute(cft);
        

        This is the code that actually runs the operator. I then verified that the data on operator invocations was correct. I also cross correlated where pipelined:=false in the query plan with opCount:=1, i.e., if atOnce evaluation was imposed on the operator, then we had only one invocation reported for that operator.

        Committed revision r7726.

        Show
        bryanthompson bryanthompson added a comment - The best way to analyze this is to use hint:atOnce to force each operator in the query plan to execute only once. You can then look at the opCount column in the detailed Explain view and see whether the correct number of operator invocations was reported. It should be ONE (1) for each operator where the atOnce hint was correctly applied. If the atOnce hint is applied to an operator, then it sets pipelined:=false as follows: com.bigdata.bop.PipelineOp.pipelined = false I have modified BOPStats to NOT pre-increment opCount. I have modified AbstractRunningQuery.haltOp() to post-increment opCount One consequence is that the opCount will not update until the operator has halted. Thus, it is a "how many times did this operator run successfully counter" rather than a "how many times did this operator start counter". However, it is now reporting the correct values. I cross validated this by logging out the following in ChunkedRunningQuery: if (log.isInfoEnabled()) log.info("Running task: bop=" + bundle.bopId + (pipelined?"":", atOnceReady=" + atOnceReady) + ", bop=" + bop.toShortString() + ", messages=" + naccepted + ", solutions=" + solutionsAccepted + (log.isDebugEnabled()?", runState=" + runStateString():"")); getQueryEngine().execute(cft); This is the code that actually runs the operator. I then verified that the data on operator invocations was correct. I also cross correlated where pipelined:=false in the query plan with opCount:=1, i.e., if atOnce evaluation was imposed on the operator, then we had only one invocation reported for that operator. Committed revision r7726.

          People

          • Assignee:
            bryanthompson bryanthompson
            Reporter:
            bryanthompson bryanthompson
          • Votes:
            0 Vote for this issue
            Watchers:
            0 Start watching this issue

            Dates

            • Created:
              Updated:
              Resolved: