drill-commits mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From meh...@apache.org
Subject [1/2] drill git commit: DRILL-3941: Add timing instrumentation in different phases of partition pruning Add basic timing instrumentation while initializing FileSelection and reading the metadata cache file
Date Wed, 04 Nov 2015 18:27:17 GMT
Repository: drill
Updated Branches:
  refs/heads/master b33326ba6 -> 5db7f33b4


DRILL-3941: Add timing instrumentation in different phases of partition pruning
Add basic timing instrumentation while initializing FileSelection and reading the metadata
cache file

closes #230


Project: http://git-wip-us.apache.org/repos/asf/drill/repo
Commit: http://git-wip-us.apache.org/repos/asf/drill/commit/ea23efcd
Tree: http://git-wip-us.apache.org/repos/asf/drill/tree/ea23efcd
Diff: http://git-wip-us.apache.org/repos/asf/drill/diff/ea23efcd

Branch: refs/heads/master
Commit: ea23efcd2ef946a8371d93050dc6a0a5db3835d5
Parents: b33326b
Author: Mehant Baid <mehantr@gmail.com>
Authored: Fri Oct 23 14:01:09 2015 -0700
Committer: Mehant Baid <mehantr@gmail.com>
Committed: Wed Nov 4 10:25:47 2015 -0800

----------------------------------------------------------------------
 .../logical/partition/PruneScanRule.java        | 45 +++++++++++++++++++-
 .../drill/exec/store/dfs/FileSelection.java     | 10 +++++
 .../drill/exec/store/parquet/Metadata.java      | 10 ++++-
 3 files changed, 62 insertions(+), 3 deletions(-)
----------------------------------------------------------------------


http://git-wip-us.apache.org/repos/asf/drill/blob/ea23efcd/exec/java-exec/src/main/java/org/apache/drill/exec/planner/logical/partition/PruneScanRule.java
----------------------------------------------------------------------
diff --git a/exec/java-exec/src/main/java/org/apache/drill/exec/planner/logical/partition/PruneScanRule.java
b/exec/java-exec/src/main/java/org/apache/drill/exec/planner/logical/partition/PruneScanRule.java
index 562cb71..b7b58ec 100644
--- a/exec/java-exec/src/main/java/org/apache/drill/exec/planner/logical/partition/PruneScanRule.java
+++ b/exec/java-exec/src/main/java/org/apache/drill/exec/planner/logical/partition/PruneScanRule.java
@@ -21,7 +21,9 @@ import java.util.BitSet;
 import java.util.Collections;
 import java.util.List;
 import java.util.Map;
+import java.util.concurrent.TimeUnit;
 
+import com.google.common.base.Stopwatch;
 import org.apache.calcite.rex.RexUtil;
 import org.apache.calcite.util.BitSets;
 
@@ -133,6 +135,12 @@ public abstract class PruneScanRule extends StoragePluginOptimizerRule
{
   }
 
   protected void doOnMatch(RelOptRuleCall call, DrillFilterRel filterRel, DrillProjectRel
projectRel, DrillScanRel scanRel) {
+    final String pruningClassName = getClass().getName();
+    logger.info("Beginning partition pruning, pruning class: {}", pruningClassName);
+    Stopwatch totalPruningTime = new Stopwatch();
+    totalPruningTime.start();
+
+
     final PlannerSettings settings = PrelUtil.getPlannerSettings(call.getPlanner());
     PartitionDescriptor descriptor = getPartitionDescriptor(settings, scanRel);
     final BufferAllocator allocator = optimizerContext.getAllocator();
@@ -166,16 +174,28 @@ public abstract class PruneScanRule extends StoragePluginOptimizerRule
{
     }
 
     if (partitionColumnBitSet.isEmpty()) {
-      logger.debug("No partition columns are projected from the scan..continue.");
+      logger.info("No partition columns are projected from the scan..continue. " +
+          "Total pruning elapsed time: {} ms", totalPruningTime.elapsed(TimeUnit.MILLISECONDS));
       return;
     }
 
+    // stop watch to track how long we spend in different phases of pruning
+    Stopwatch miscTimer = new Stopwatch();
+
+    // track how long we spend building the filter tree
+    miscTimer.start();
+
     FindPartitionConditions c = new FindPartitionConditions(columnBitset, filterRel.getCluster().getRexBuilder());
     c.analyze(condition);
     RexNode pruneCondition = c.getFinalCondition();
 
+    logger.info("Total elapsed time to build and analyze filter tree: {} ms",
+        miscTimer.elapsed(TimeUnit.MILLISECONDS));
+    miscTimer.reset();
+
     if (pruneCondition == null) {
-      logger.debug("No conditions were found eligible for partition pruning.");
+      logger.info("No conditions were found eligible for partition pruning." +
+          "Total pruning elapsed time: {} ms", totalPruningTime.elapsed(TimeUnit.MILLISECONDS));
       return;
     }
 
@@ -208,21 +228,39 @@ public abstract class PruneScanRule extends StoragePluginOptimizerRule
{
           container.add(v);
         }
 
+        // track how long we spend populating partition column vectors
+        miscTimer.start();
+
         // populate partition vectors.
         descriptor.populatePartitionVectors(vectors, partitions, partitionColumnBitSet, fieldNameMap);
 
+        logger.info("Elapsed time to populate partitioning column vectors: {} ms within batchIndex:
{}",
+            miscTimer.elapsed(TimeUnit.MILLISECONDS), batchIndex);
+        miscTimer.reset();
+
         // materialize the expression; only need to do this once
         if (batchIndex == 0) {
           materializedExpr = materializePruneExpr(pruneCondition, settings, scanRel, container);
           if (materializedExpr == null) {
             // continue without partition pruning; no need to log anything here since
             // materializePruneExpr logs it already
+            logger.info("Total pruning elapsed time: {} ms",
+                totalPruningTime.elapsed(TimeUnit.MILLISECONDS));
             return;
           }
         }
 
         output.allocateNew(partitions.size());
+
+        // start the timer to evaluate how long we spend in the interpreter evaluation
+        miscTimer.start();
+
         InterpreterEvaluator.evaluate(partitions.size(), optimizerContext, container, output,
materializedExpr);
+
+        logger.info("Elapsed time in interpreter evaluation: {} ms within batchIndex: {}",
+            miscTimer.elapsed(TimeUnit.MILLISECONDS), batchIndex);
+        miscTimer.reset();
+
         int recordCount = 0;
         int qualifiedCount = 0;
 
@@ -238,6 +276,7 @@ public abstract class PruneScanRule extends StoragePluginOptimizerRule
{
         batchIndex++;
       } catch (Exception e) {
         logger.warn("Exception while trying to prune partition.", e);
+        logger.info("Total pruning elapsed time: {} ms", totalPruningTime.elapsed(TimeUnit.MILLISECONDS));
         return; // continue without partition pruning
       } finally {
         container.clear();
@@ -297,6 +336,8 @@ public abstract class PruneScanRule extends StoragePluginOptimizerRule
{
 
     } catch (Exception e) {
       logger.warn("Exception while using the pruned partitions.", e);
+    } finally {
+      logger.info("Total pruning elapsed time: {} ms", totalPruningTime.elapsed(TimeUnit.MILLISECONDS));
     }
   }
 

http://git-wip-us.apache.org/repos/asf/drill/blob/ea23efcd/exec/java-exec/src/main/java/org/apache/drill/exec/store/dfs/FileSelection.java
----------------------------------------------------------------------
diff --git a/exec/java-exec/src/main/java/org/apache/drill/exec/store/dfs/FileSelection.java
b/exec/java-exec/src/main/java/org/apache/drill/exec/store/dfs/FileSelection.java
index be3e57d..a0cea61 100644
--- a/exec/java-exec/src/main/java/org/apache/drill/exec/store/dfs/FileSelection.java
+++ b/exec/java-exec/src/main/java/org/apache/drill/exec/store/dfs/FileSelection.java
@@ -21,7 +21,9 @@ import java.io.IOException;
 import java.net.URI;
 import java.util.Collections;
 import java.util.List;
+import java.util.concurrent.TimeUnit;
 
+import com.google.common.base.Stopwatch;
 import org.apache.commons.lang3.ArrayUtils;
 import org.apache.commons.lang3.StringUtils;
 import org.apache.drill.exec.store.parquet.Metadata.ParquetTableMetadata_v1;
@@ -92,6 +94,8 @@ public class FileSelection {
   }
 
   public FileSelection minusDirectories(DrillFileSystem fs) throws IOException {
+    Stopwatch timer = new Stopwatch();
+    timer.start();
     init(fs);
     List<FileStatus> newList = Lists.newArrayList();
     for (FileStatus p : statuses) {
@@ -104,6 +108,8 @@ public class FileSelection {
         newList.add(p);
       }
     }
+    logger.info("FileSelection.minusDirectories() took {} ms, numFiles: {}",
+        timer.elapsed(TimeUnit.MILLISECONDS), newList.size());
     return new FileSelection(newList, selectionRoot);
   }
 
@@ -127,12 +133,16 @@ public class FileSelection {
   }
 
   private void init(DrillFileSystem fs) throws IOException {
+    Stopwatch timer = new Stopwatch();
+    timer.start();
     if (files != null && statuses == null) {
       statuses = Lists.newArrayList();
       for (String p : files) {
         statuses.add(fs.getFileStatus(new Path(p)));
       }
     }
+    logger.info("FileSelection.init() took {} ms, numFiles: {}",
+        timer.elapsed(TimeUnit.MILLISECONDS), statuses == null ? 0 : statuses.size());
   }
 
   public List<FileStatus> getFileStatusList(DrillFileSystem fs) throws IOException
{

http://git-wip-us.apache.org/repos/asf/drill/blob/ea23efcd/exec/java-exec/src/main/java/org/apache/drill/exec/store/parquet/Metadata.java
----------------------------------------------------------------------
diff --git a/exec/java-exec/src/main/java/org/apache/drill/exec/store/parquet/Metadata.java
b/exec/java-exec/src/main/java/org/apache/drill/exec/store/parquet/Metadata.java
index 522ff92..05c68db 100644
--- a/exec/java-exec/src/main/java/org/apache/drill/exec/store/parquet/Metadata.java
+++ b/exec/java-exec/src/main/java/org/apache/drill/exec/store/parquet/Metadata.java
@@ -163,7 +163,11 @@ public class Metadata {
     watch.start();
     List<FileStatus> fileStatuses = getFileStatuses(fileStatus);
     logger.info("Took {} ms to get file statuses", watch.elapsed(TimeUnit.MILLISECONDS));
-    return getParquetTableMetadata(fileStatuses);
+    watch.reset();
+    watch.start();
+    ParquetTableMetadata_v1 metadata_v1 = getParquetTableMetadata(fileStatuses);
+    logger.info("Took {} ms to read file metadata", watch.elapsed(TimeUnit.MILLISECONDS));
+    return metadata_v1;
   }
 
   /**
@@ -348,6 +352,8 @@ public class Metadata {
    * @throws IOException
    */
   private ParquetTableMetadata_v1 readBlockMeta(String path) throws IOException {
+    Stopwatch timer = new Stopwatch();
+    timer.start();
     Path p = new Path(path);
     ObjectMapper mapper = new ObjectMapper();
     SimpleModule module = new SimpleModule();
@@ -356,6 +362,8 @@ public class Metadata {
     mapper.configure(DeserializationFeature.FAIL_ON_UNKNOWN_PROPERTIES, false);
     FSDataInputStream is = fs.open(p);
     ParquetTableMetadata_v1 parquetTableMetadata = mapper.readValue(is, ParquetTableMetadata_v1.class);
+    logger.info("Took {} ms to read metadata from cache file", timer.elapsed(TimeUnit.MILLISECONDS));
+    timer.stop();
     if (tableModified(parquetTableMetadata, p)) {
       parquetTableMetadata = createMetaFilesRecursively(Path.getPathWithoutSchemeAndAuthority(p.getParent()).toString());
     }


Mime
View raw message