This happen for both raw and aggregate reflection, for a reflection that was running well in Dremio v1.4.
At the end of the REFRESH REFLECTION job, log file server.out gives following
2018-04-19 12:56:40,087 [FABRIC-rpc-event-queue] INFO query.logger - {“queryId”:“25276e08-ff21-b69a-0076-caf3cb903300”,“schema”:“”,“queryText”:“REFRESH REFLECTION ‘c90c5993-e448-43dd-808e-2ac222c2bc7f’ AS ‘b3b4a1a8-3399-4f4a-8288-5a4f262cf4bf’”,“start”:1524142582547,“finish”:1524142600087,“outcome”:“COMPLETED”,“username”:“$dremio$”,“commandDescription”:“execute; query”}
2018-04-19 12:56:40,158 [dremio-general-2] WARN c.d.s.reflection.ReflectionManager - failed to handle reflection c90c5993-e448-43dd-808e-2ac222c2bc7f (Raw Reflection) job done
java.lang.NullPointerException: null
at com.google.common.base.Preconditions.checkNotNull(Preconditions.java:210) ~[guava-18.0.jar:na]
at com.google.common.collect.FluentIterable.(FluentIterable.java:84) ~[guava-18.0.jar:na]
at com.google.common.collect.FluentIterable$1.(FluentIterable.java:93) ~[guava-18.0.jar:na]
at com.google.common.collect.FluentIterable.from(FluentIterable.java:92) ~[guava-18.0.jar:na]
at com.dremio.service.jobs.JoinAnalyzer$12.apply(JoinAnalyzer.java:325) ~[dremio-services-jobs-2.0.1-201804132205050000-10b1de0.jar:2.0.1-201804132205050000-10b1de0]
at com.dremio.service.jobs.JoinAnalyzer$12.apply(JoinAnalyzer.java:322) ~[dremio-services-jobs-2.0.1-201804132205050000-10b1de0.jar:2.0.1-201804132205050000-10b1de0]
at com.google.common.collect.Iterators$8.transform(Iterators.java:799) ~[guava-18.0.jar:na]
at com.google.common.collect.TransformedIterator.next(TransformedIterator.java:48) ~[guava-18.0.jar:na]
at com.google.common.collect.ImmutableList.copyOf(ImmutableList.java:271) ~[guava-18.0.jar:na]
at com.google.common.collect.ImmutableList.copyOf(ImmutableList.java:226) ~[guava-18.0.jar:na]
at com.google.common.collect.FluentIterable.toList(FluentIterable.java:373) ~[guava-18.0.jar:na]
at com.dremio.service.jobs.JoinAnalyzer.merge(JoinAnalyzer.java:372) ~[dremio-services-jobs-2.0.1-201804132205050000-10b1de0.jar:2.0.1-201804132205050000-10b1de0]
at com.dremio.service.reflection.handlers.RefreshDoneHandler.computeJoinAnalysis(RefreshDoneHandler.java:311) ~[dremio-services-accelerator-2.0.1-201804132205050000-10b1de0.jar:2.0.1-201804132205050000-10b1de0]
at com.dremio.service.reflection.handlers.RefreshDoneHandler.handle(RefreshDoneHandler.java:164) ~[dremio-services-accelerator-2.0.1-201804132205050000-10b1de0.jar:2.0.1-201804132205050000-10b1de0]
at com.dremio.service.reflection.ReflectionManager.refreshingJobSucceded(ReflectionManager.java:519) [dremio-services-accelerator-2.0.1-201804132205050000-10b1de0.jar:2.0.1-201804132205050000-10b1de0]
at com.dremio.service.reflection.ReflectionManager.handleSuccessfulRefreshJob(ReflectionManager.java:506) [dremio-services-accelerator-2.0.1-201804132205050000-10b1de0.jar:2.0.1-201804132205050000-10b1de0]
at com.dremio.service.reflection.ReflectionManager.handleRefreshingEntry(ReflectionManager.java:319) [dremio-services-accelerator-2.0.1-201804132205050000-10b1de0.jar:2.0.1-201804132205050000-10b1de0]
at com.dremio.service.reflection.ReflectionManager.handleEntry(ReflectionManager.java:270) [dremio-services-accelerator-2.0.1-201804132205050000-10b1de0.jar:2.0.1-201804132205050000-10b1de0]
at com.dremio.service.reflection.ReflectionManager.handleEntries(ReflectionManager.java:241) [dremio-services-accelerator-2.0.1-201804132205050000-10b1de0.jar:2.0.1-201804132205050000-10b1de0]
at com.dremio.service.reflection.ReflectionManager.run(ReflectionManager.java:157) [dremio-services-accelerator-2.0.1-201804132205050000-10b1de0.jar:2.0.1-201804132205050000-10b1de0]
at com.dremio.service.reflection.WakeupHandler$1.run(WakeupHandler.java:63) [dremio-services-accelerator-2.0.1-201804132205050000-10b1de0.jar:2.0.1-201804132205050000-10b1de0]
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) [na:1.8.0_161]
at java.util.concurrent.FutureTask.run(FutureTask.java:266) [na:1.8.0_161]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [na:1.8.0_161]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [na:1.8.0_161]
at java.lang.Thread.run(Thread.java:748) [na:1.8.0_161]
Looks like its failing after the reflection has been materialized (if you hover over the orange triangle it should show more information).
Can you give us some information about the dataset your are accelerating (so we can work on a reproduction): is it a physical dataset (so a database table for example) or a virtual dataset?
Hi @doron,
correct, the orange triange gives the following message
Reflection can not accelerate.
1 refresh job attempts failed, will reattempt.
Is it like Dremio does not create the reflection because it does see any added value to it ?
The dataset is a virtual dataset, made of joins from Physical datasets (a reference collection in MongoDB, others in MySQL, and the biggest source being a NAS parquet dataset).
In 1.4 , this VDS was accelerated and the queries returned in less than 2 seconds. Now, without being able to accelerate this dateset, the queries take around 20 seconds. Would you need the query profiles ? Thanks, David
Dremio is running into a bug after the materialization of the reflection has completed which causes us to think that it failed. We made major changes to reflection management in 2.0.0 hence the change in behavior.
Hi @doron, the bug is happening in a lot of situations.
Is it possible to descrive the situation that triggers the bug, so that I can avoid it , or any workaround ?
I’m noticing the same problem, apparently a reflection shows this problem when it is accelerated (that is, when the reflection uses another reflection to accelerate itself).
I tried creating 3 reflections on the same view enabling them in different orders and I noticed that only the first in the sequence (not accelerated) succeed, the other two use the first reflection during their creation and apparently succeed in the job explorer but then show that yellow triangle and are marked as failed (so never used).
This is a known issue we’re working on. We will keep you updated on progress.
Luca: could you check your server.out file and see if you see if you’re seeing the same NullPointerException stack-trace? I just want to make sure the issues you’re seeing are the same as the one we’re investigating.
Yes, a similar error (not in server.out though, I found it in server.log)
2018-06-05 14:03:31,103 [dremio-general-16] WARN c.d.s.reflection.ReflectionManager - failed to handle reflection ed804fa6-2d05-4ced-ab8e-77cc7ddd458e (Raw Reflection) job done java.lang.NullPointerException: null at com.google.common.base.Preconditions.checkNotNull(Preconditions.java:210) ~[guava-18.0.jar:na] at com.google.common.collect.FluentIterable.<init>(FluentIterable.java:84) ~[guava-18.0.jar:na] at com.google.common.collect.FluentIterable$1.<init>(FluentIterable.java:93) ~[guava-18.0.jar:na] at com.google.common.collect.FluentIterable.from(FluentIterable.java:92) ~[guava-18.0.jar:na] at com.dremio.service.jobs.JoinAnalyzer.remapJoinConditions(JoinAnalyzer.java:411) ~[dremio-services-jobs-2.0.1-201804132205050000-10b1de0.jar:2.0.1-201804132205050000-10b1de0] at com.dremio.service.jobs.JoinAnalyzer.access$400(JoinAnalyzer.java:68) ~[dremio-services-jobs-2.0.1-201804132205050000-10b1de0.jar:2.0.1-201804132205050000-10b1de0] at com.dremio.service.jobs.JoinAnalyzer$14.apply(JoinAnalyzer.java:396) ~[dremio-services-jobs-2.0.1-201804132205050000-10b1de0.jar:2.0.1-201804132205050000-10b1de0] at com.dremio.service.jobs.JoinAnalyzer$14.apply(JoinAnalyzer.java:391) ~[dremio-services-jobs-2.0.1-201804132205050000-10b1de0.jar:2.0.1-201804132205050000-10b1de0] at com.google.common.collect.Iterators$8.transform(Iterators.java:799) ~[guava-18.0.jar:na] at com.google.common.collect.TransformedIterator.next(TransformedIterator.java:48) ~[guava-18.0.jar:na] at com.google.common.collect.ImmutableList.copyOf(ImmutableList.java:271) ~[guava-18.0.jar:na] at com.google.common.collect.ImmutableList.copyOf(ImmutableList.java:226) ~[guava-18.0.jar:na] at com.google.common.collect.FluentIterable.toList(FluentIterable.java:373) ~[guava-18.0.jar:na] at com.dremio.service.jobs.JoinAnalyzer.remapJoinAnalysis(JoinAnalyzer.java:404) ~[dremio-services-jobs-2.0.1-201804132205050000-10b1de0.jar:2.0.1-201804132205050000-10b1de0] at com.dremio.service.jobs.JoinAnalyzer.merge(JoinAnalyzer.java:284) ~[dremio-services-jobs-2.0.1-201804132205050000-10b1de0.jar:2.0.1-201804132205050000-10b1de0] at com.dremio.service.reflection.handlers.RefreshDoneHandler.computeJoinAnalysis(RefreshDoneHandler.java:311) ~[dremio-services-accelerator-2.0.1-201804132205050000-10b1de0.jar:2.0.1-201804132205050000-10b1de0] at com.dremio.service.reflection.handlers.RefreshDoneHandler.handle(RefreshDoneHandler.java:164) ~[dremio-services-accelerator-2.0.1-201804132205050000-10b1de0.jar:2.0.1-201804132205050000-10b1de0] at com.dremio.service.reflection.ReflectionManager.refreshingJobSucceded(ReflectionManager.java:519) [dremio-services-accelerator-2.0.1-201804132205050000-10b1de0.jar:2.0.1-201804132205050000-10b1de0] at com.dremio.service.reflection.ReflectionManager.handleSuccessfulRefreshJob(ReflectionManager.java:506) [dremio-services-accelerator-2.0.1-201804132205050000-10b1de0.jar:2.0.1-201804132205050000-10b1de0] at com.dremio.service.reflection.ReflectionManager.handleRefreshingEntry(ReflectionManager.java:319) [dremio-services-accelerator-2.0.1-201804132205050000-10b1de0.jar:2.0.1-201804132205050000-10b1de0] at com.dremio.service.reflection.ReflectionManager.handleEntry(ReflectionManager.java:270) [dremio-services-accelerator-2.0.1-201804132205050000-10b1de0.jar:2.0.1-201804132205050000-10b1de0] at com.dremio.service.reflection.ReflectionManager.handleEntries(ReflectionManager.java:241) [dremio-services-accelerator-2.0.1-201804132205050000-10b1de0.jar:2.0.1-201804132205050000-10b1de0] at com.dremio.service.reflection.ReflectionManager.run(ReflectionManager.java:157) [dremio-services-accelerator-2.0.1-201804132205050000-10b1de0.jar:2.0.1-201804132205050000-10b1de0] at com.dremio.service.reflection.WakeupHandler$1.run(WakeupHandler.java:63) [dremio-services-accelerator-2.0.1-201804132205050000-10b1de0.jar:2.0.1-201804132205050000-10b1de0] at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) [na:1.8.0_171] at java.util.concurrent.FutureTask.run(FutureTask.java:266) [na:1.8.0_171] at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [na:1.8.0_171] at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [na:1.8.0_171] at java.lang.Thread.run(Thread.java:748) [na:1.8.0_171]
Exactly same error. Is it unexpected (has a fix been releases for this issue in 2.0.5 ? )
For me this is worse situation than in 1.4 Community version where a number of these reflections were working properly.
2018-06-08 14:29:14,318 [dremio-general-242] WARN c.d.s.reflection.ReflectionManager - failed to handle reflection 5f8e456b-e1fd-47f1-965d-b18de33606ae (Aggregation Reflection) job done
java.lang.NullPointerException: null
at com.google.common.base.Preconditions.checkNotNull(Preconditions.java:210) ~[guava-18.0.jar:na]
at com.google.common.collect.FluentIterable.(FluentIterable.java:84) ~[guava-18.0.jar:na]
at com.google.common.collect.FluentIterable$1.(FluentIterable.java:93) ~[guava-18.0.jar:na]
at com.google.common.collect.FluentIterable.from(FluentIterable.java:92) ~[guava-18.0.jar:na]
at com.dremio.service.jobs.JoinAnalyzer$12.apply(JoinAnalyzer.java:325) ~[dremio-services-jobs-2.0.5-201806021755080191-767cfb5.jar:2.0.5-201806021755080191-767cfb5]
at com.dremio.service.jobs.JoinAnalyzer$12.apply(JoinAnalyzer.java:322) ~[dremio-services-jobs-2.0.5-201806021755080191-767cfb5.jar:2.0.5-201806021755080191-767cfb5]
at com.google.common.collect.Iterators$8.transform(Iterators.java:799) ~[guava-18.0.jar:na]
at com.google.common.collect.TransformedIterator.next(TransformedIterator.java:48) ~[guava-18.0.jar:na]
at com.google.common.collect.ImmutableList.copyOf(ImmutableList.java:271) ~[guava-18.0.jar:na]
at com.google.common.collect.ImmutableList.copyOf(ImmutableList.java:226) ~[guava-18.0.jar:na]
at com.google.common.collect.FluentIterable.toList(FluentIterable.java:373) ~[guava-18.0.jar:na]
at com.dremio.service.jobs.JoinAnalyzer.merge(JoinAnalyzer.java:372) ~[dremio-services-jobs-2.0.5-201806021755080191-767cfb5.jar:2.0.5-201806021755080191-767cfb5]
at com.dremio.service.reflection.handlers.RefreshDoneHandler.computeJoinAnalysis(RefreshDoneHandler.java:311) ~[dremio-services-accelerator-2.0.5-201806021755080191-767cfb5.jar:2.0.5-201806021755080191-767cfb5]
at com.dremio.service.reflection.handlers.RefreshDoneHandler.handle(RefreshDoneHandler.java:164) ~[dremio-services-accelerator-2.0.5-201806021755080191-767cfb5.jar:2.0.5-201806021755080191-767cfb5]
at com.dremio.service.reflection.ReflectionManager.refreshingJobSucceded(ReflectionManager.java:519) [dremio-services-accelerator-2.0.5-201806021755080191-767cfb5.jar:2.0.5-201806021755080191-767cfb5]
at com.dremio.service.reflection.ReflectionManager.handleSuccessfulRefreshJob(ReflectionManager.java:506) [dremio-services-accelerator-2.0.5-201806021755080191-767cfb5.jar:2.0.5-201806021755080191-767cfb5]
at com.dremio.service.reflection.ReflectionManager.handleRefreshingEntry(ReflectionManager.java:319) [dremio-services-accelerator-2.0.5-201806021755080191-767cfb5.jar:2.0.5-201806021755080191-767cfb5]
at com.dremio.service.reflection.ReflectionManager.handleEntry(ReflectionManager.java:270) [dremio-services-accelerator-2.0.5-201806021755080191-767cfb5.jar:2.0.5-201806021755080191-767cfb5]
at com.dremio.service.reflection.ReflectionManager.handleEntries(ReflectionManager.java:241) [dremio-services-accelerator-2.0.5-201806021755080191-767cfb5.jar:2.0.5-201806021755080191-767cfb5]
at com.dremio.service.reflection.ReflectionManager.run(ReflectionManager.java:157) [dremio-services-accelerator-2.0.5-201806021755080191-767cfb5.jar:2.0.5-201806021755080191-767cfb5]
at com.dremio.service.reflection.WakeupHandler$1.run(WakeupHandler.java:63) [dremio-services-accelerator-2.0.5-201806021755080191-767cfb5.jar:2.0.5-201806021755080191-767cfb5]
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511) [na:1.8.0_171]
at java.util.concurrent.FutureTask.run(FutureTask.java:266) [na:1.8.0_171]
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) [na:1.8.0_171]
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) [na:1.8.0_171]
at java.lang.Thread.run(Thread.java:748) [na:1.8.0_171]
I confirm the same problem even after updating to 2.0.5.
In my case, all the reflections that use other reflections to accelerate themselves show this behavior.
Thank you both for confirming. I’m sure someone in engineering will comment later today (still early at HQ).
Sorry this is happening and thanks for your patience. There were tons of improvements to reflection management in 2.0, so in general things have moved to a better place.
Hi, any idea if a fix will be applied soon ?
For me this one is a blocker, as there is no workaround to have reflections working properly for my scope.
