Dremio Query very slow

1

I have facing issue with dremio query very slow here is logs

2019-12-23 15:33:02,092 [21ff21d0-85fc-c4db-310e-bae3a0735100/0:foreman-planning] WARN  c.d.e.p.a.MaterializationList - failed to expand materialization 4b90e379-6477-4a2d-b0b3-e7329bb25dc9
java.lang.IllegalArgumentException: Projected column base size %d is not equal to outcome rowtype %d. [370, 360]
        at com.google.common.base.Preconditions.checkArgument(Preconditions.java:263) ~[guava-20.0.jar:na]
        at com.dremio.exec.planner.common.ScanRelBase.setProjectedRowType(ScanRelBase.java:266) ~[dremio-sabot-kernel-4.0.2-201910020123580864-a98a0b9.jar:4.0.2-201910020123580864-a98a0b9]
        at com.dremio.exec.planner.common.ScanRelBase.<init>(ScanRelBase.java:81) ~[dremio-sabot-kernel-4.0.2-201910020123580864-a98a0b9.jar:4.0.2-201910020123580864-a98a0b9]
        at com.dremio.exec.calcite.logical.ScanCrel.<init>(ScanCrel.java:53) ~[dremio-sabot-kernel-4.0.2-201910020123580864-a98a0b9.jar:4.0.2-201910020123580864-a98a0b9]
        at com.dremio.exec.calcite.logical.ScanCrel.copyWith(ScanCrel.java:74) ~[dremio-sabot-kernel-4.0.2-201910020123580864-a98a0b9.jar:4.0.2-201910020123580864-a98a0b9]
        at org.apache.calcite.plan.CopyWithCluster.visit(CopyWithCluster.java:389) ~[dremio-sabot-kernel-4.0.2-201910020123580864-a98a0b9.jar:1.16.0-201909031936280585-3f76472]
        at org.apache.calcite.rel.core.TableScan.accept(TableScan.java:167) ~[calcite-core-1.16.0-201909031936280585-3f76472.jar:1.16.0-201909031936280585-3f76472]
        at org.apache.calcite.plan.CopyWithCluster.visit(CopyWithCluster.java:241) ~[dremio-sabot-kernel-4.0.2-201910020123580864-a98a0b9.jar:1.16.0-201909031936280585-3f76472]
        at org.apache.calcite.rel.logical.LogicalProject.accept(LogicalProject.java:129) ~[calcite-core-1.16.0-201909031936280585-3f76472.jar:1.16.0-201909031936280585-3f76472]
        at org.apache.calcite.plan.CopyWithCluster.visit(CopyWithCluster.java:241) ~[dremio-sabot-kernel-4.0.2-201910020123580864-a98a0b9.jar:1.16.0-201909031936280585-3f76472]
        at org.apache.calcite.rel.logical.LogicalProject.accept(LogicalProject.java:129) ~[calcite-core-1.16.0-201909031936280585-3f76472.jar:1.16.0-201909031936280585-3f76472]
        at com.dremio.exec.planner.acceleration.DremioMaterialization.accept(DremioMaterialization.java:242) ~[dremio-sabot-kernel-4.0.2-201910020123580864-a98a0b9.jar:4.0.2-201910020123580864-a98a0b9]
        at com.dremio.exec.planner.acceleration.CachedMaterializationDescriptor.getMaterializationFor(CachedMaterializationDescriptor.java:49) ~[dremio-sabot-kernel-4.0.2-201910020123580864-a98a0b9.jar:4.0.2-201910020123580864-a98a0b9]
        at com.dremio.exec.planner.acceleration.MaterializationList.build(MaterializationList.java:108) [dremio-sabot-kernel-4.0.2-201910020123580864-a98a0b9.jar:4.0.2-201910020123580864-a98a0b9]
        at com.dremio.exec.planner.acceleration.MaterializationList$1.get(MaterializationList.java:50) [dremio-sabot-kernel-4.0.2-201910020123580864-a98a0b9.jar:4.0.2-201910020123580864-a98a0b9]
        at com.dremio.exec.planner.acceleration.MaterializationList$1.get(MaterializationList.java:47) [dremio-sabot-kernel-4.0.2-201910020123580864-a98a0b9.jar:4.0.2-201910020123580864-a98a0b9]
        at com.google.common.base.Suppliers$MemoizingSupplier.get(Suppliers.java:120) [guava-20.0.jar:na]
        at com.dremio.exec.planner.acceleration.MaterializationList.getMaterializations(MaterializationList.java:73) [dremio-sabot-kernel-4.0.2-201910020123580864-a98a0b9.jar:4.0.2-201910020123580864-a98a0b9]
        at com.dremio.exec.planner.acceleration.substitution.AbstractSubstitutionProvider.getMaterializations(AbstractSubstitutionProvider.java:43) [dremio-sabot-kernel-4.0.2-201910020123580864-a98a0b9.jar:4.0.2-201910020123580864-a98a0b9]
        at com.dremio.exec.planner.acceleration.substitution.DremioSubstitutionProvider.findSubstitutions(DremioSubstitutionProvider.java:123) [dremio-ce-sabot-kernel-4.0.2-201910020123580864-a98a0b9.jar:4.0.2-201910020123580864-a98a0b9]
        at com.dremio.exec.planner.acceleration.substitution.AccelerationAwareSubstitutionProvider.findSubstitutions(AccelerationAwareSubstitutionProvider.java:59) [dremio-sabot-kernel-4.0.2-201910020123580864-a98a0b9.jar:4.0.2-201910020123580864-a98a0b9]
        at com.dremio.exec.planner.DremioVolcanoPlanner.registerMaterializations(DremioVolcanoPlanner.java:101) [dremio-sabot-kernel-4.0.2-201910020123580864-a98a0b9.jar:4.0.2-201910020123580864-a98a0b9]
        at org.apache.calcite.plan.volcano.VolcanoPlanner.findBestExp(VolcanoPlanner.java:600) [calcite-core-1.16.0-201909031936280585-3f76472.jar:1.16.0-201909031936280585-3f76472]
        at com.dremio.exec.planner.DremioVolcanoPlanner.findBestExp(DremioVolcanoPlanner.java:83) [dremio-sabot-kernel-4.0.2-201910020123580864-a98a0b9.jar:4.0.2-201910020123580864-a98a0b9]
        at org.apache.calcite.tools.Programs$RuleSetProgram.run(Programs.java:368) [calcite-core-1.16.0-201909031936280585-3f76472.jar:1.16.0-201909031936280585-3f76472]
        at com.dremio.exec.planner.sql.handlers.PrelTransformer.lambda$transform$2(PrelTransformer.java:498) [dremio-sabot-kernel-4.0.2-201910020123580864-a98a0b9.jar:4.0.2-201910020123580864-a98a0b9]
        at com.dremio.exec.planner.sql.handlers.PrelTransformer.doTransform(PrelTransformer.java:512) [dremio-sabot-kernel-4.0.2-201910020123580864-a98a0b9.jar:4.0.2-201910020123580864-a98a0b9]
        at com.dremio.exec.planner.sql.handlers.PrelTransformer.transform(PrelTransformer.java:505) [dremio-sabot-kernel-4.0.2-201910020123580864-a98a0b9.jar:4.0.2-201910020123580864-a98a0b9]
        at com.dremio.exec.planner.sql.handlers.PrelTransformer.convertToDrel(PrelTransformer.java:229) [dremio-sabot-kernel-4.0.2-201910020123580864-a98a0b9.jar:4.0.2-201910020123580864-a98a0b9]
        at com.dremio.exec.planner.sql.handlers.PrelTransformer.convertToDrel(PrelTransformer.java:318) [dremio-sabot-kernel-4.0.2-201910020123580864-a98a0b9.jar:4.0.2-201910020123580864-a98a0b9]
        at com.dremio.exec.planner.sql.handlers.query.NormalHandler.getPlan(NormalHandler.java:47) ~[dremio-sabot-kernel-4.0.2-201910020123580864-a98a0b9.jar:4.0.2-201910020123580864-a98a0b9]
        at com.dremio.exec.planner.sql.handlers.commands.HandlerToPreparePlan.plan(HandlerToPreparePlan.java:89) ~[dremio-sabot-kernel-4.0.2-201910020123580864-a98a0b9.jar:4.0.2-201910020123580864-a98a0b9]
        at com.dremio.exec.work.foreman.AttemptManager.plan(AttemptManager.java:407) ~[dremio-sabot-kernel-4.0.2-201910020123580864-a98a0b9.jar:4.0.2-201910020123580864-a98a0b9]
        at com.dremio.exec.work.foreman.AttemptManager.lambda$run$0(AttemptManager.java:310) ~[dremio-sabot-kernel-4.0.2-201910020123580864-a98a0b9.jar:4.0.2-201910020123580864-a98a0b9]
        at com.dremio.service.commandpool.CommandWrapper.run(CommandWrapper.java:62) ~[dremio-services-commandpool-4.0.2-201910020123580864-a98a0b9.jar:4.0.2-201910020123580864-a98a0b9]
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) ~[na:1.8.0_222]
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) ~[na:1.8.0_222]
        at java.lang.Thread.run(Thread.java:748) ~[na:1.8.0_222]
2

@Vikash_Singh, I’m not sure this is related to the slowness… do you have a job profile for 21ff21d0-85fc-c4db-310e-bae3a0735100?

3

Hello Ben,

i dont have same job profile but same error i have getting in other jobs too i am attaching that job profile.Also that error i am getting in loop every 2 sec its calling because of this also mine Query slow
cab16e6d-9e83-4c47-b481-44a85cc9bace.zip (104.0 KB)

4

@Vikash_Singh

Is this the same as this Community Post

5

No both are diffrent post

6

@Vikash_Singh

The profile you sent is “cab16e6d-9e83-4c47-b481-44a85cc9bace.zip” is for a failed job. Is there a profile for the slow running query?

7

I cannot able to trace which job cause Query slow mainly i am getting this Error continues in Dremio log java.lang.IllegalArgumentException: Projected column base size %d is not equal to outcome rowtype %d. [370, 360]

8

@Vikash_Singh

Send us the complete server.log as the log snippet you send does not give us complete details

9

where to find all dremio logs in container ?

10

@Vikash_Singh

Are you on K8’s. Do a “ps -ef | grep dremio” and look for “-Ddremio.log.path” in the output

11

I am also facing Long running jobs some time half hour ,i have attached job profile

Screenshot_11
Screenshot_111919×869 141 KB

50fbc10c-c281-48f4-9742-e187427fa147.zip (97.5 KB)

12

@Vikash_Singh

I see the query is waiting on CPU for the full duration. See attached screenshot. How many executors and cores per executor you have? I also see you are running concurrent queries so might be CPU starved

13

I have only one executer and I given 8 cpu,44 GB ram

Some time I have concurrent query is dremio can’t handle this query

14

@balaji.ramaswamy any idea suggestion what i have to do to solve above issue

15

still so many jobs are in running state due to this my Bi dashboard is loading either slow or hanged please suggest necessary steps to solve above issue

16

Failure while attempting substitution, skipping materialization 67fb5e91-bc34-4492-be64-832ae6d31ed0

17

@Vikash_Singh

Have you considered increasing capacity in terms of number of executors?

18

do you want me to increae executor count to 2 and distribute cpu what i have earlier like 4 cpu each .i am also doing metadata cleanup

19

@Vikash_Singh,

You would need to have a separate coordinator and 2 executor nodes to start with. Start with lower concurrency and then you can increase

Thanks
@balaji.ramaswamy