AnsweredAssumed Answered

Drill query is taking substantial time in planning phase if some directory name is provided in where clause.

Question asked by anshul09013 on May 14, 2018
Latest reply on May 16, 2018 by Hao Zhu

Hi,

We have spark application which reads data from MapR stream's topic in batches of 10 seconds and save that data into parquet files under path "/data/parquet_data/<current_timestamp i.e. batch time>" after partitionBy function on one column say "appId". After partitionBy directory structure becomes

 

/data/parquet_data/<current_timestamp i.e. batch time>/appId=<appId>

e.g.

/data/parquet_data/1526298816786/appId=839/ and parquet files for particular batch and appId are stored under it.

 

When we perform drill query to fetch all records of appId=18 for a particular batch from parquet data, it has been observed that planning phase takes lot of time.

Query performed is select * from dfs.`/data/parquet_data/` where dir0='1526028303390' AND dir1='appId=839'

 

It takes approx 14 seconds in which planning time is dominating.

 

PlanningQueuedExecutionTotal
13.507 sec0.013 sec0.020 sec13.540 sec

Following logs are observed in drillbit.log:

2018-05-14 13:15:16,431 [2506741b-75e4-8f84-04c6-cc76693599be:foreman] DEBUG o.a.d.exec.store.dfs.FileSelection - FileSelection.create() took 0 ms 
2018-05-14 13:15:16,431 [2506741b-75e4-8f84-04c6-cc76693599be:foreman] INFO o.a.d.exec.store.dfs.FileSelection - FileSelection.getStatuses() took 0 ms, numFiles: 1
2018-05-14 13:15:16,433 [2506741b-75e4-8f84-04c6-cc76693599be:foreman] INFO o.a.d.exec.store.dfs.FileSelection - FileSelection.getStatuses() took 0 ms, numFiles: 1
2018-05-14 13:15:16,443 [2506741b-75e4-8f84-04c6-cc76693599be:foreman] INFO o.a.d.exec.store.dfs.FileSelection - FileSelection.getStatuses() took 0 ms, numFiles: 1
2018-05-14 13:15:16,443 [2506741b-75e4-8f84-04c6-cc76693599be:foreman] INFO o.a.d.exec.store.dfs.FileSelection - FileSelection.getStatuses() took 0 ms, numFiles: 1
2018-05-14 13:15:29,801 [2506741b-75e4-8f84-04c6-cc76693599be:foreman] DEBUG o.a.d.exec.store.dfs.FileSelection - FileSelection.minusDirectories() took 13357 ms, numFiles: 1
2018-05-14 13:15:29,801 [2506741b-75e4-8f84-04c6-cc76693599be:foreman] INFO o.a.d.exec.store.dfs.FileSelection - FileSelection.getStatuses() took 0 ms, numFiles: 5040
2018-05-14 13:15:29,801 [2506741b-75e4-8f84-04c6-cc76693599be:foreman] INFO o.a.d.exec.store.dfs.FileSelection - FileSelection.getStatuses() took 0 ms, numFiles: 5040
2018-05-14 13:15:29,801 [2506741b-75e4-8f84-04c6-cc76693599be:foreman] INFO o.a.d.exec.store.dfs.FileSelection - FileSelection.getStatuses() took 0 ms, numFiles: 5040
2018-05-14 13:15:29,801 [2506741b-75e4-8f84-04c6-cc76693599be:foreman] INFO o.a.d.exec.store.dfs.FileSelection - FileSelection.getStatuses() took 0 ms, numFiles: 5040
2018-05-14 13:15:29,801 [2506741b-75e4-8f84-04c6-cc76693599be:foreman] INFO o.a.d.exec.store.dfs.FileSelection - FileSelection.getStatuses() took 0 ms, numFiles: 5040

Here
FileSelection.minusDirectories() took 13 seconds,
2018-05-14 13:15:29,801 [2506741b-75e4-8f84-04c6-cc76693599be:foreman] DEBUG o.a.d.exec.store.dfs.FileSelection - FileSelection.minusDirectories() took 13357 ms, numFiles: 1
Partition pruning is also working fine, as following logs are observed

2018-05-14 13:15:29,807 [2506741b-75e4-8f84-04c6-cc76693599be:foreman] INFO o.a.d.e.p.l.partition.PruneScanRule - Beginning partition pruning, pruning class: org.apache.drill.exec.planner.logical.partition.PruneScanRule$DirPruneScanFilterOnScanRule
2018-05-14 13:15:29,807 [2506741b-75e4-8f84-04c6-cc76693599be:foreman] INFO o.a.d.e.p.l.partition.PruneScanRule - Total elapsed time to build and analyze filter tree: 0 ms
2018-05-14 13:15:29,863 [2506741b-75e4-8f84-04c6-cc76693599be:foreman] DEBUG o.a.d.e.p.l.partition.PruneScanRule - Evaluating partition pruning for batch 0
2018-05-14 13:15:29,866 [2506741b-75e4-8f84-04c6-cc76693599be:foreman] DEBUG o.a.drill.exec.vector.UInt4Vector - Reallocating vector [$offsets$(UINT4:REQUIRED)]. # of bytes: [16384] -> [32768]
2018-05-14 13:15:29,866 [2506741b-75e4-8f84-04c6-cc76693599be:foreman] DEBUG o.a.drill.exec.vector.UInt4Vector - Reallocating vector [$offsets$(UINT4:REQUIRED)]. # of bytes: [16384] -> [32768]
2018-05-14 13:15:29,866 [2506741b-75e4-8f84-04c6-cc76693599be:foreman] DEBUG o.a.drill.exec.vector.UInt1Vector - Reallocating vector [$bits$(UINT1:REQUIRED)]. # of bytes: [4096] -> [8192]
2018-05-14 13:15:29,866 [2506741b-75e4-8f84-04c6-cc76693599be:foreman] DEBUG o.a.drill.exec.vector.UInt1Vector - Reallocating vector [$bits$(UINT1:REQUIRED)]. # of bytes: [4096] -> [8192]
2018-05-14 13:15:29,867 [2506741b-75e4-8f84-04c6-cc76693599be:foreman] INFO o.a.d.e.p.l.partition.PruneScanRule - Elapsed time to populate partitioning column vectors: 3 ms within batchIndex: 0
2018-05-14 13:15:29,867 [2506741b-75e4-8f84-04c6-cc76693599be:foreman] DEBUG o.a.d.e.p.l.partition.PruneScanRule - Attempting to prune AND(=($1, '1526028303390'), =($2, 'appId=839'))
2018-05-14 13:15:29,867 [2506741b-75e4-8f84-04c6-cc76693599be:foreman] DEBUG o.a.d.e.planner.logical.DrillOptiq - Binary
2018-05-14 13:15:29,867 [2506741b-75e4-8f84-04c6-cc76693599be:foreman] DEBUG o.a.d.e.planner.logical.DrillOptiq - Binary
2018-05-14 13:15:29,867 [2506741b-75e4-8f84-04c6-cc76693599be:foreman] DEBUG o.a.d.e.planner.logical.DrillOptiq - Binary
2018-05-14 13:15:29,884 [2506741b-75e4-8f84-04c6-cc76693599be:foreman] INFO o.a.d.e.p.l.partition.PruneScanRule - Elapsed time in interpreter evaluation: 16 ms within batchIndex: 0 with # of partitions : 5040
2018-05-14 13:15:29,886 [2506741b-75e4-8f84-04c6-cc76693599be:foreman] DEBUG o.a.d.e.p.l.partition.PruneScanRule - Within batch 0: total records: 5040, qualified records: 1
2018-05-14 13:15:29,886 [2506741b-75e4-8f84-04c6-cc76693599be:foreman] INFO o.a.d.e.p.l.partition.PruneScanRule - Pruned 5040 partitions down to 1
2018-05-14 13:15:29,886 [2506741b-75e4-8f84-04c6-cc76693599be:foreman] INFO o.a.d.e.p.l.partition.PruneScanRule - Total pruning elapsed time: 79 ms


If similar query is performed by providing it in path like
select * from dfs.`/data/parquet_data/1526028303390/appId=839`, it takes less than a second. In logs, it has been observed that very few files are scanned.

Logs:
2018-05-14 13:30:28,787 [2506708a-f4d0-ac90-1fc2-bc1e6d8edbc7:foreman] DEBUG o.a.d.exec.store.dfs.FileSelection - FileSelection.create() took 1 ms
2018-05-14 13:30:28,787 [2506708a-f4d0-ac90-1fc2-bc1e6d8edbc7:foreman] INFO o.a.d.exec.store.dfs.FileSelection - FileSelection.getStatuses() took 0 ms, numFiles: 1
2018-05-14 13:30:28,788 [2506708a-f4d0-ac90-1fc2-bc1e6d8edbc7:foreman] INFO o.a.d.exec.store.dfs.FileSelection - FileSelection.getStatuses() took 0 ms, numFiles: 1

Can you please suggest reason for this behavior?

 

Outcomes