diff --git a/tez-api/src/main/java/org/apache/tez/common/counters/TaskCounter.java b/tez-api/src/main/java/org/apache/tez/common/counters/TaskCounter.java index 2ee82a3965..d011ffaec2 100644 --- a/tez-api/src/main/java/org/apache/tez/common/counters/TaskCounter.java +++ b/tez-api/src/main/java/org/apache/tez/common/counters/TaskCounter.java @@ -215,6 +215,11 @@ public enum TaskCounter { */ MERGE_PHASE_TIME, + /** + * Time taken to sort data in milliseconds. + */ + SORT_TIME, + /** * First event received from source relative to task start time. * diff --git a/tez-runtime-library/src/main/java/org/apache/tez/runtime/library/common/sort/impl/ExternalSorter.java b/tez-runtime-library/src/main/java/org/apache/tez/runtime/library/common/sort/impl/ExternalSorter.java index 3ff74f72bb..e19642e31f 100644 --- a/tez-runtime-library/src/main/java/org/apache/tez/runtime/library/common/sort/impl/ExternalSorter.java +++ b/tez-runtime-library/src/main/java/org/apache/tez/runtime/library/common/sort/impl/ExternalSorter.java @@ -162,6 +162,9 @@ public void progress() { protected final TezCounter numAdditionalSpills; // Number of files offered via shuffle-handler to consumers. protected final TezCounter numShuffleChunks; + // Time (in ms) spent with sorting (includes only the actual sorting time, doesn't include Span related operations) + protected final TezCounter sortTimeMsCounter; + // How partition stats should be reported. final ReportPartitionStats reportPartitionStats; @@ -220,6 +223,7 @@ public ExternalSorter(OutputContext outputContext, Configuration conf, int numOu additionalSpillBytesRead = outputContext.getCounters().findCounter(TaskCounter.ADDITIONAL_SPILLS_BYTES_READ); numAdditionalSpills = outputContext.getCounters().findCounter(TaskCounter.ADDITIONAL_SPILL_COUNT); numShuffleChunks = outputContext.getCounters().findCounter(TaskCounter.SHUFFLE_CHUNK_COUNT); + sortTimeMsCounter = outputContext.getCounters().findCounter(TaskCounter.SORT_TIME); // compression this.codec = CodecUtils.getCodec(conf); diff --git a/tez-runtime-library/src/main/java/org/apache/tez/runtime/library/common/sort/impl/PipelinedSorter.java b/tez-runtime-library/src/main/java/org/apache/tez/runtime/library/common/sort/impl/PipelinedSorter.java index b70d6c4360..389c0e6456 100644 --- a/tez-runtime-library/src/main/java/org/apache/tez/runtime/library/common/sort/impl/PipelinedSorter.java +++ b/tez-runtime-library/src/main/java/org/apache/tez/runtime/library/common/sort/impl/PipelinedSorter.java @@ -966,8 +966,10 @@ public SpanIterator sort(IndexedSorter sorter) { if(length() > 1) { sorter.sort(this, 0, length(), progressable); } + long sortTime = System.currentTimeMillis() - start; LOG.info(outputContext.getDestinationVertexName() + ": " + "done sorting span=" + index + ", length=" + length() + ", " - + "time=" + (System.currentTimeMillis() - start)); + + "time=" + sortTime); + sortTimeMsCounter.increment(sortTime); return new SpanIterator((SortSpan)this); } diff --git a/tez-runtime-library/src/main/java/org/apache/tez/runtime/library/common/sort/impl/dflt/DefaultSorter.java b/tez-runtime-library/src/main/java/org/apache/tez/runtime/library/common/sort/impl/dflt/DefaultSorter.java index dd6c083109..c05fc91fa1 100644 --- a/tez-runtime-library/src/main/java/org/apache/tez/runtime/library/common/sort/impl/dflt/DefaultSorter.java +++ b/tez-runtime-library/src/main/java/org/apache/tez/runtime/library/common/sort/impl/dflt/DefaultSorter.java @@ -859,7 +859,11 @@ protected void sortAndSpill(long sameKeyCount, long totalKeysCount) throws IOException, InterruptedException { final int mstart = getMetaStart(); final int mend = getMetaEnd(); + + long start = System.currentTimeMillis(); sorter.sort(this, mstart, mend, progressable); + sortTimeMsCounter.increment(System.currentTimeMillis() - start); + spill(mstart, mend, sameKeyCount, totalKeysCount); }