Sorry about the S3 confusion in the query. s3.cisexport.transactionView is
just a view. The actual data resides on HDFS. At dfs.`parquet/transaction`.
Using that in the query itself gives the same result.
The only long gap we see in the log is between these two lines:
2017-02-13 19:30:31,044 [275df6b0-09e6-812b-e75a-b8722138eeb8:foreman] INFO
o.a.d.exec.store.dfs.FileSelection - FileSelection.getStatuses() took 0
ms, numFiles: 1
2017-02-13 19:42:05,877 [275df6b0-09e6-812b-e75a-b8722138eeb8:frag:5:109]
INFO o.a.d.c.s.persistence.ScanResult - loading 6 classes for
org.apache.drill.exec.store.dfs.FormatPlugin took 0ms
Here is most of the raw log output (I bolded the two lines with the 12
minute gap):
017-02-13 19:30:23,666 [275df6b0-09e6-812b-e75a-b8722138eeb8:foreman] INFO
o.a.drill.exec.work.foreman.Foreman - Query text for query id
275df6b0-09e6-812b-e75a-b8722138eeb8: select fltb1.SAPID, yearmo,
COUNT(*) as totalcnt,
count(distinct(CASE
WHEN
(REPEATED_CONTAINS(fltb1.classLabels,
'Thing:Service:MedicalService:Diagnostic:Radiology:Ultrasound.*'))
THEN fltb1.invoiceId
END)) as ultracount,
count(distinct (CASE
WHEN
(REPEATED_CONTAINS(fltb1.classLabels,
'Thing:Service:MedicalService:Diagnostic:LaboratoryTest.*'))
THEN fltb1.invoiceId
END)) as labcount
from (select sapid, invoiceId, TO_CHAR(TO_TIMESTAMP(transactionDate,
'YYYY-MM-dd HH:mm:ss.SSSSSS'), 'yyyy-MM') yearmo, classLabels
from s3.cisexport.transactionView) fltb1
group by fltb1.sapid, yearmo
LIMIT 20
2017-02-13 19:30:24,260 [275df6b0-09e6-812b-e75a-b8722138eeb8:foreman] INFO
o.a.d.c.s.persistence.ScanResult - loading 6 classes for
org.apache.drill.exec.store.dfs.FormatPlugin took 0ms
2017-02-13 19:30:24,260 [275df6b0-09e6-812b-e75a-b8722138eeb8:foreman] INFO
o.a.d.c.s.persistence.ScanResult - loading 7 classes for
org.apache.drill.common.logical.FormatPluginConfig took 0ms
2017-02-13 19:30:24,260 [275df6b0-09e6-812b-e75a-b8722138eeb8:foreman] INFO
o.a.d.c.s.persistence.ScanResult - loading 7 classes for
org.apache.drill.common.logical.FormatPluginConfig took 0ms
2017-02-13 19:30:24,261 [275df6b0-09e6-812b-e75a-b8722138eeb8:foreman] INFO
o.a.d.c.s.persistence.ScanResult - loading 7 classes for
org.apache.drill.common.logical.FormatPluginConfig took 0ms
2017-02-13 19:30:28,021 [275df6b0-09e6-812b-e75a-b8722138eeb8:foreman] INFO
o.a.d.exec.store.dfs.FileSelection - FileSelection.getStatuses() took 0
ms, numFiles: 1
2017-02-13 19:30:28,022 [275df6b0-09e6-812b-e75a-b8722138eeb8:foreman] INFO
o.a.d.exec.store.dfs.FileSelection - FileSelection.getStatuses() took 0
ms, numFiles: 1
2017-02-13 19:30:31,027 [275df6b0-09e6-812b-e75a-b8722138eeb8:foreman] INFO
o.a.d.exec.store.parquet.Metadata - Took 210 ms to read metadata from
cache file
2017-02-13 19:30:31,028 [275df6b0-09e6-812b-e75a-b8722138eeb8:foreman] INFO
o.a.d.exec.store.parquet.Metadata - No directories were modified. Took 1
ms to check modification time of 1 directories
2017-02-13 19:30:31,043 [275df6b0-09e6-812b-e75a-b8722138eeb8:foreman] INFO
o.a.d.exec.store.dfs.FileSelection - FileSelection.getStatuses() took 0
ms, numFiles: 1
*2017-02-13 19:30:31,044 [275df6b0-09e6-812b-e75a-b8722138eeb8:foreman]
INFO o.a.d.exec.store.dfs.FileSelection - FileSelection.getStatuses() took
0 ms, numFiles: 1*
*2017-02-13 19:42:05,877 [275df6b0-09e6-812b-e75a-b8722138eeb8:frag:5:109]
INFO o.a.d.c.s.persistence.ScanResult - loading 6 classes for
org.apache.drill.exec.store.dfs.FormatPlugin took 0ms*
2017-02-13 19:42:05,878 [275df6b0-09e6-812b-e75a-b8722138eeb8:frag:5:109]
INFO o.a.d.c.s.persistence.ScanResult - loading 7 classes for
org.apache.drill.common.logical.FormatPluginConfig took 0ms
2017-02-13 19:42:05,878 [275df6b0-09e6-812b-e75a-b8722138eeb8:frag:5:109]
INFO o.a.d.c.s.persistence.ScanResult - loading 7 classes for
org.apache.drill.common.logical.FormatPluginConfig took 0ms
2017-02-13 19:42:05,878 [275df6b0-09e6-812b-e75a-b8722138eeb8:frag:5:109]
INFO o.a.d.c.s.persistence.ScanResult - loading 7 classes for
org.apache.drill.common.logical.FormatPluginConfig took 0ms
2017-02-13 19:42:05,883 [275df6b0-09e6-812b-e75a-b8722138eeb8:frag:11:123]
INFO o.a.d.c.s.persistence.ScanResult - loading 6 classes for
org.apache.drill.exec.store.dfs.FormatPlugin took 0ms
2017-02-13 19:42:05,884 [275df6b0-09e6-812b-e75a-b8722138eeb8:frag:11:123]
INFO o.a.d.c.s.persistence.ScanResult - loading 7 classes for
org.apache.drill.common.logical.FormatPluginConfig took 0ms
2017-02-13 19:42:05,884 [275df6b0-09e6-812b-e75a-b8722138eeb8:frag:11:123]
INFO o.a.d.c.s.persistence.ScanResult - loading 7 classes for
org.apache.drill.common.logical.FormatPluginConfig took 0ms
2017-02-13 19:42:05,884 [275df6b0-09e6-812b-e75a-b8722138eeb8:frag:11:123]
INFO o.a.d.c.s.persistence.ScanResult - loading 7 classes for
org.apache.drill.common.logical.FormatPluginConfig took 0ms
2017-02-13 19:42:05,948 [275df6b0-09e6-812b-e75a-b8722138eeb8:frag:5:127]
INFO o.a.d.c.s.persistence.ScanResult - loading 6 classes for
org.apache.drill.exec.store.dfs.FormatPlugin took 0ms
2017-02-13 19:42:05,949 [275df6b0-09e6-812b-e75a-b8722138eeb8:frag:5:127]
INFO o.a.d.c.s.persistence.ScanResult - loading 7 classes for
org.apache.drill.common.logical.FormatPluginConfig took 0ms
2017-02-13 19:42:05,949 [275df6b0-09e6-812b-e75a-b8722138eeb8:frag:5:127]
INFO o.a.d.c.s.persistence.ScanResult - loading 7 classes for
org.apache.drill.common.logical.FormatPluginConfig took 0ms
2017-02-13 19:42:05,949 [275df6b0-09e6-812b-e75a-b8722138eeb8:frag:5:127]
INFO o.a.d.c.s.persistence.ScanResult - loading 7 classes for
org.apache.drill.common.logical.FormatPluginConfig took 0ms
2017-02-13 19:42:05,968 [275df6b0-09e6-812b-e75a-b8722138eeb8:frag:5:112]
INFO o.a.d.c.s.persistence.ScanResult - loading 6 classes for
org.apache.drill.exec.store.dfs.FormatPlugin took 0ms
2017-02-13 19:42:05,968 [275df6b0-09e6-812b-e75a-b8722138eeb8:frag:5:112]
INFO o.a.d.c.s.persistence.ScanResult - loading 7 classes for
org.apache.drill.common.logical.FormatPluginConfig took 0ms
On Mon, Feb 13, 2017 at 2:22 PM, Aman Sinha <asi...@mapr.com> wrote:
> In your drillbit.log file, can you look for the entries for the foreman
> node to see where the time is being spent ?
> e.g entries of the following type:
> [275dec51-fcc1-f1bf-cb2f-57a838805a82:foreman] INFO
> o.a.d.exec.store.parquet.Metadata - Took 64 ms to read metadata from
> cache file
>
> Each entry is timestamped, so if you see a long gap between two of them,
> that will give an idea about what’s going on.
> I am not familiar with how the S3 is set up. My guess is there is some
> latency issues there that could be causing it but let’s first get the log
> output.
>
> -Aman
>
> On 2/13/17, 12:05 PM, "David Kincaid" <kincaid.d...@gmail.com> wrote:
>
> We've just recently started working with Drill and I'm seeing something
> that doesn't seem right and I'm not sure how to troubleshoot. We have
> 100
> Parquet files which are each about 400MB each using Snappy compression.
> While trying to query this data I am seeing extraordinary planning
> time for
> certain queries. The planning time is about 12 minutes and the actual
> execution of the query is less than 2 minutes.
>
> A few details of our setup. We are running Drill on an AWS EMR cluster
> on
> m4.16xlarge nodes (64 cores, 256GB each). We've given Drill an 8GB Java
> heap and 100GB Java direct memory. We have verified that the metadata
> cache
> file is being created and used. We have tried a cluster of 10 nodes
> and a
> cluster of 2 nodes with no difference in planning time or execution
> time.
>
> Does anyone have some pointers on troubleshooting excessive planning
> time?
> It seems like we must have something misconfigured or are missing
> something. We're very new to Drill and I think I've exhausted all my
> troubleshooting ideas so far. Any tips anyone can provide?
>
> Here is the main query I've been experimenting with, so you can get a
> feel
> for the query complexity:
>
> select fltb1.sapId, yearmo,
> COUNT(*) as totalcnt,
> count(distinct(CASE
> WHEN
> (REPEATED_CONTAINS(fltb1.classLabels,
> 'Thing:Service:MedicalService:Diagnostic:Radiology:Ultrasound.*'))
> THEN fltb1.invoiceId
> END)) as ultracount,
> count(distinct (CASE
> WHEN
> (REPEATED_CONTAINS(fltb1.classLabels,
> 'Thing:Service:MedicalService:Diagnostic:LaboratoryTest.*'))
> THEN fltb1.invoiceId
> END)) as labcount
> from (select sapid, invoiceId, TO_CHAR(TO_TIMESTAMP(transactionDate,
> 'YYYY-MM-dd HH:mm:ss.SSSSSS'), 'yyyy-MM') yearmo, classLabels
> from s3.cisexport.transactionView) fltb1
> group by fltb1.sapId, yearmo;
>
> Thanks,
>
> Dave
>
>
>
