Author: jolee Date: 2013-07-31 16:13:22 -0400 (Wed, 31 Jul 2013) New Revision: 4583 Modified: branches/7.7.x/engine/src/main/java/org/teiid/query/processor/relational/RelationalNode.java branches/7.7.x/engine/src/main/java/org/teiid/query/processor/relational/RelationalNodeStatistics.java branches/7.7.x/engine/src/test/java/org/teiid/query/processor/relational/TestRelationalNodeStatistics.java Log: TEIID-2475: The RelationalNode.collectNodeStats is only subtracting out the last node Modified: branches/7.7.x/engine/src/main/java/org/teiid/query/processor/relational/RelationalNode.java =================================================================== --- branches/7.7.x/engine/src/main/java/org/teiid/query/processor/relational/RelationalNode.java 2013-07-31 05:51:06 UTC (rev 4582) +++ branches/7.7.x/engine/src/main/java/org/teiid/query/processor/relational/RelationalNode.java 2013-07-31 20:13:22 UTC (rev 4583) @@ -284,7 +284,7 @@ this.getProcessingState().nodeStatistics.stopBatchTimer(); this.getProcessingState().nodeStatistics.collectCumulativeNodeStats(batch, RelationalNodeStatistics.BATCHCOMPLETE_STOP); if (batch.getTerminationFlag()) { - this.getProcessingState().nodeStatistics.collectNodeStats(this.getChildren(), this.getClassName()); + this.getProcessingState().nodeStatistics.collectNodeStats(this.getChildren()); //this.nodeStatistics.dumpProperties(this.getClassName()); } } @@ -305,20 +305,14 @@ // stop timer for this batch (BlockedException) this.getProcessingState().nodeStatistics.stopBatchTimer(); this.getProcessingState().nodeStatistics.collectCumulativeNodeStats(null, RelationalNodeStatistics.BLOCKEDEXCEPTION_STOP); + recordStats = false; } throw e; - } catch (QueryProcessor.ExpiredTimeSliceException e) { - if(recordStats && this.getProcessingState().context.getCollectNodeStatistics()) { - this.getProcessingState().nodeStatistics.stopBatchTimer(); - } - throw e; - } catch (TeiidComponentException e) { - // stop timer for this batch (MetaMatrixComponentException) - if(recordStats && this.getProcessingState().context.getCollectNodeStatistics()) { - this.getProcessingState().nodeStatistics.stopBatchTimer(); - } - throw e; - } + } finally { + if(recordStats && this.getProcessingState().context.getCollectNodeStatistics()) { + this.getProcessingState().nodeStatistics.stopBatchTimer(); + } + } } /** Modified: branches/7.7.x/engine/src/main/java/org/teiid/query/processor/relational/RelationalNodeStatistics.java =================================================================== --- branches/7.7.x/engine/src/main/java/org/teiid/query/processor/relational/RelationalNodeStatistics.java 2013-07-31 05:51:06 UTC (rev 4582) +++ branches/7.7.x/engine/src/main/java/org/teiid/query/processor/relational/RelationalNodeStatistics.java 2013-07-31 20:13:22 UTC (rev 4583) @@ -74,10 +74,18 @@ this.batchStartTime = System.currentTimeMillis(); } + void setBatchStartTime(long batchStartTime) { + this.batchStartTime = batchStartTime; + } + public void stopBatchTimer() { this.batchEndTime = System.currentTimeMillis(); } + void setBatchEndTime(long batchEndTime) { + this.batchEndTime = batchEndTime; + } + public void collectCumulativeNodeStats(TupleBatch batch, int stopType) { this.nodeNextBatchCalls++; if(!this.setNodeStartTime) { @@ -95,25 +103,18 @@ } } - public void collectNodeStats(RelationalNode[] relationalNodes, String className) { - // set nodeEndTime to the time gathered at the end of the last batch - this.nodeEndTime = this.batchEndTime; - this.nodeCumulativeProcessingTime = this.nodeEndTime - this.nodeStartTime; - if(relationalNodes[0] != null) { - long maxUnionChildCumulativeProcessingTime = 0; - for (int i = 0; i < relationalNodes.length; i++) { - if(relationalNodes[i] != null) { - maxUnionChildCumulativeProcessingTime = Math.max(maxUnionChildCumulativeProcessingTime, relationalNodes[i].getNodeStatistics().getNodeCumulativeProcessingTime()); - this.nodeProcessingTime = this.nodeCumulativeProcessingTime - relationalNodes[i].getNodeStatistics().getNodeCumulativeProcessingTime(); - } - } - if(className.equals("UnionAllNode")){ //$NON-NLS-1$ - this.nodeProcessingTime = this.nodeCumulativeProcessingTime - maxUnionChildCumulativeProcessingTime; - } - }else { - this.nodeProcessingTime = this.nodeCumulativeProcessingTime; - } - } + public void collectNodeStats(RelationalNode[] relationalNodes) { + // set nodeEndTime to the time gathered at the end of the last batch + this.nodeEndTime = this.batchEndTime; + this.nodeCumulativeProcessingTime = this.nodeEndTime - this.nodeStartTime; + this.nodeProcessingTime = this.nodeCumulativeProcessingTime; + for (int i = 0; i < relationalNodes.length; i++) { + if (relationalNodes[i] == null) { + break; + } + this.nodeProcessingTime -= relationalNodes[i].getNodeStatistics().getNodeCumulativeProcessingTime(); + } + } public List<String> getStatisticsList() { ArrayList<String> statisticsList = new ArrayList<String>(6); Modified: branches/7.7.x/engine/src/test/java/org/teiid/query/processor/relational/TestRelationalNodeStatistics.java =================================================================== --- branches/7.7.x/engine/src/test/java/org/teiid/query/processor/relational/TestRelationalNodeStatistics.java 2013-07-31 05:51:06 UTC (rev 4582) +++ branches/7.7.x/engine/src/test/java/org/teiid/query/processor/relational/TestRelationalNodeStatistics.java 2013-07-31 20:13:22 UTC (rev 4583) @@ -22,36 +22,24 @@ package org.teiid.query.processor.relational; +import static org.junit.Assert.*; + import java.util.ArrayList; import java.util.List; +import org.junit.Test; import org.teiid.common.buffer.BufferManagerFactory; import org.teiid.common.buffer.TupleBatch; import org.teiid.core.TeiidComponentException; import org.teiid.core.TeiidProcessingException; import org.teiid.core.types.DataTypeManager; -import org.teiid.query.processor.relational.RelationalNodeStatistics; import org.teiid.query.sql.symbol.ElementSymbol; import org.teiid.query.util.CommandContext; -import junit.framework.TestCase; - - -/** - * @since 4.2 - */ -public class TestRelationalNodeStatistics extends TestCase { - - private int actualNodeOutputRows; - private int actualNodeNextBatchCalls; - private int actualNodeCumulativeBlocks; - private int actualNodeBlocks; -// private long actualNodeProcessingTime; -// private long actualNodeCumulativeProcessingTime; -// private long actualNodeCumulativeNextBatchProcessingTime; - - - public void testBatchTimer() { +@SuppressWarnings({"rawtypes", "nls"}) +public class TestRelationalNodeStatistics { + + @Test public void testBatchTimer() { RelationalNodeStatistics testnodeStatistics = new RelationalNodeStatistics(); testnodeStatistics.startBatchTimer(); assertTrue("The batch timer did not yield a start time", testnodeStatistics.getBatchStartTime()!= 0); //$NON-NLS-1$ @@ -59,9 +47,9 @@ assertTrue("The batch timer did not yield an end time", testnodeStatistics.getBatchEndTime()!= 0); //$NON-NLS-1$ } - public void testStatsCollection() throws TeiidComponentException, TeiidProcessingException { + @Test public void testStatsCollection() throws TeiidComponentException, TeiidProcessingException { List[] data = createData(1000); - FakeRelationalNode fakeNode = this.createFakeNode(data); + FakeRelationalNode fakeNode = createFakeNode(data); // read from fake node while(true) { @@ -71,26 +59,33 @@ } } - this.actualNodeBlocks = fakeNode.getNodeStatistics().getNodeBlocks(); - this.actualNodeNextBatchCalls = fakeNode.getNodeStatistics().getNodeNextBatchCalls(); - this.actualNodeOutputRows = fakeNode.getNodeStatistics().getNodeOutputRows(); -// this.actualNodeCumulativeNextBatchProcessingTime = fakeNode.getNodeStatistics().getNodeCumulativeNextBatchProcessingTime(); -// this.actualNodeCumulativeProcessingTime = fakeNode.getNodeStatistics().getNodeCumulativeProcessingTime(); -// this.actualNodeProcessingTime = fakeNode.getNodeStatistics().getNodeProcessingTime(); - - //System.out.println("Actual NodeComulativeNextBatchProcessingTime: "+ this.actualNodeCumulativeNextBatchProcessingTime); //$NON-NLS-1$ - //System.out.println("Actual NodeComulativeProcessingTime: "+ this.actualNodeCumulativeProcessingTime); //$NON-NLS-1$ - //System.out.println("Actual NodeProcessingTime: "+ this.actualNodeProcessingTime); //$NON-NLS-1$ - - assertEquals("The NodeOutputRows was Inccorrect. Correct: 1000 Actual: "+ this.actualNodeOutputRows, 1000, this.actualNodeOutputRows); //$NON-NLS-1$ - assertEquals("The NodeNextBatchCalls was Inccorrect. Correct: 10 Actual: "+ this.actualNodeNextBatchCalls, 10, this.actualNodeNextBatchCalls); //$NON-NLS-1$ - assertEquals("The NodeBlocks was Inccorrect. Correct: 0 Actual: "+ this.actualNodeBlocks, 0, this.actualNodeBlocks); //$NON-NLS-1$ - assertEquals("The NodeComulativeBlocks was Inccorrect. Correct: 0 Actual: "+ this.actualNodeCumulativeBlocks, 0, this.actualNodeCumulativeBlocks); //$NON-NLS-1$ - } + int actualNodeBlocks = fakeNode.getNodeStatistics().getNodeBlocks(); + int actualNodeNextBatchCalls = fakeNode.getNodeStatistics().getNodeNextBatchCalls(); + int actualNodeOutputRows = fakeNode.getNodeStatistics().getNodeOutputRows(); + + assertEquals("The NodeOutputRows was Inccorrect. Correct: 1000 Actual: "+ actualNodeOutputRows, 1000, actualNodeOutputRows); //$NON-NLS-1$ + assertEquals("The NodeNextBatchCalls was Inccorrect. Correct: 10 Actual: "+ actualNodeNextBatchCalls, 10, actualNodeNextBatchCalls); //$NON-NLS-1$ + assertEquals("The NodeBlocks was Inccorrect. Correct: 0 Actual: "+ actualNodeBlocks, 0, actualNodeBlocks); //$NON-NLS-1$ + } + + @Test public void testCumulativeCalculation() throws TeiidComponentException, TeiidProcessingException { + RelationalNode[] children = new RelationalNode[2]; + children[0] = createFakeNode(createData(1)); + children[1] = createFakeNode(createData(1)); + children[0].getNodeStatistics().setBatchEndTime(100); + children[0].getNodeStatistics().collectNodeStats(new RelationalNode[0]); + children[1].getNodeStatistics().setBatchEndTime(200); + children[1].getNodeStatistics().collectNodeStats(new RelationalNode[0]); + RelationalNodeStatistics stats = new RelationalNodeStatistics(); + stats.setBatchEndTime(1000); + stats.collectNodeStats(children); + assertEquals(1000, stats.getNodeCumulativeProcessingTime()); + assertEquals(700, stats.getNodeProcessingTime()); + } - public void testDescriptionProperties() throws Exception { + @Test public void testDescriptionProperties() throws Exception { List[] data = createData(1000); - FakeRelationalNode fakeNode = this.createFakeNode(data); + FakeRelationalNode fakeNode = createFakeNode(data); // read from fake node while(true) {