Failure while attempting substitution

1

Hi Dremio Team,

There are couple of scenarios we are still getting this error.

  1. create a reflection for a virtual dataset
  2. use that vd as part of another vd’s definition
  3. query on top level vd results in Failure while attempting substitution

query profile: 4d5da33d-3d56-46f5-89ed-bc6d8a8611bd.zip (73.9 KB)
dremio ver: CE 4.1.4

Thanks

2

To debug this, we would have to have some additional logging. Try adding these loggers to the logback.xml and restarting Dremio:

<logger name="com.dremio.service.reflection" additivity="false">
   <level value="debug" />
   <appender-ref ref="text" />
 </logger>


<logger name="com.dremio.service.reflection" additivity="false">
   <level value="debug" />
   <appender-ref ref="text" />
 </logger>

Reproduce the issue, attach the logs and profile, and then remove the extra logging and restart.

3

@ben
attached requested info
profile: 23b59cc7-b170-4825-83e0-b7ad5939a4eb.zip (76.3 KB)
log: dremio master.zip (11.2 KB)

4

Hi @smora,

This does not appear to have the debug logging enabled (you have to restart the Dremio coordinator/master after enabling the debug. That being said have you tried rebuilding the reflection but disabling the reflection, saving this change, and then re-enabling?

5

Hi @ben

yes, i did try disable/enable/delete-all/recreate reflection options.
just accessing vd uses reflections, but if the reflection is part of another vd’s definitions substitution error occurs, I got the logs again from both master&executor

master-log: dremio-master.zip (11.4 KB)
executor-log: dremio-executor.zip (9.5 KB)

direct qry on vd (uses reflection): 977d1204-0724-46a7-b9a5-b51704aac33e.zip (8.4 KB)

vd part of another vd (substitution error): 77c4f257-e9bd-4502-9c58-e3d694b0283f.zip (51.3 KB)

after disable/enable/drop/recreate reflection (same error) : 52ff83d7-7f13-4cd1-a99e-f080b97bf8f9.zip (51.0 KB)

logback:

dremio-logback
dremio-logback1056×558 42.7 KB

6

The problem with the logging is apparently the appender, as there is no “text” in the k8s deployment. You should be able to see the debug logging with:

<logger name="com.dremio.service.reflection" additivity="false">
   <level value="debug" />
   <appender-ref ref="console" />
 </logger>


<logger name="com.dremio.service.reflection" additivity="false">
   <level value="debug" />
   <appender-ref ref="console" />
 </logger>
7

@ben

thanks for pointing. here is the updated log&profile

master-log: dremio-master.zip (7.6 KB)
executor-log: dremio-executor.zip (6.8 KB)

job-profile: 68e0431f-240d-4572-9324-5145f91189d6.zip (51.2 KB)

Thanks

8

@smora

Couple of things

  1. The query ran on “2020-06-17 00:37:43” but the logs are only till “2020-06-16 19:40:31,131”

  2. The error you are seeing may be a generic error. If you see the reflection is was matched, which means it had all the information it needs to accelerate the query. The reason why it did not choose could be because of 2 reasons

A) Dremio’s planner estimated cost of using reflection to be more expensive than going back to PDS, to confirm this, turn on “planner.verbose_profile” and rerun the query and send us the profile
B) There was an exception during substitution, for this we need the server.log right after you run the query

9

@balaji.ramaswamy @ben

Attached logs&profile as per your advice.

profile: cb6bb5a0-ada1-4de2-9a1a-dd7cc74c4806.zip (85.1 KB)
master-log: master.zip (10.7 KB)
executor-log: executor.zip (8.8 KB)

Thanks
Sudheer