Dremio 2.0.1rc : some reflections fail at creation

For some reflections, the job provides a success status

,

however reflection is not used and a flag is displayed in the reflection window

.

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]

1 Like

Hi,

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?

thanks,
Doron

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, thanks for the information. Do you know if it"s corrected in 2.0 release ?

It is not in the current release but it is on the list of things to work on.

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 ?

Thanks

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).

Hey guys,

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.

Christy

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]

After a migration to 2.0.5, I’ve tested an acceleration that was failing, and it appears the bug remains.

1 Like

Are you getting the same error? Can you confirm what that is from server.log?

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.

Sadly the issue was not fixed in 2.0.5 as its still being worked on. We will update this thread once we have a release with a fix.

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.

This should be fixed in our next major release, will update this once we know when (hopefully this month)

1 Like

Hi @doron, any visibility on your next release ?

Should be very soon now. Have a few small items to resolve and hopefully next week if all goes well.