Dashboard with multiple queries (33) and filters not caching results with metabase pro

[juangc-wavyssa]

Describe the bug When we load a dashboard when multiple queries (33 queries approximately) and we have cache by dashboards and subqueries of the dashboard active, the dashboard loads so slow, and it seems it doesn't use the cache never ( we have some filters on the dashboard with default values on them, but, we are not changing the filters). And when we go to logs to see if there is any error, we get the following message repeated over and over every time we launch our dashboard ( we have now the free trial pro metabase self hosted version)

Logs

[b4b6db97-3cdb-4ecb-9f51-2a66bca3be80] 2024-07-11T12:38:27+02:00 ERROR metabase.query-processor.middleware.process-userland-query Error saving query execution info,clojure.lang.ExceptionInfo: Unknown type of ref {:ref [:sum {:lib/uuid "5acb02b3-b37c-49ee-92d3-247524f20c92"} [:expression {:base-type :type/Decimal, :lib/uuid "fc8ba6b2-0d98-43fd-a851-7bcbfb208dfa"} "REVENUE"]], :toucan2/context-trace [["parse args" {:toucan2.query/query-type :toucan.query-type/insert.update-count, :toucan2.query/unparsed-args (:model/FieldUsage ({:field_id 83, :used_in :filter, :filter_op :=, :query_execution_id 1832} {:field_id 99, :used_in :filter, :filter_op :>=, :query_execution_id 1832} {:field_id 99, :used_in :filter, :filter_op :<, :query_execution_id 1832}))}]]}, at metabase.lib.equality$find_matching_column.invokeStatic(equality.cljc:293), at metabase.lib.equality$find_matching_column.invoke(equality.cljc:249), at metabase.lib.equality$find_matching_column.invokeStatic(equality.cljc:274), at metabase.lib.equality$find_matching_column.invoke(equality.cljc:249), at metabase.lib.aggregation$aggregation_column.invokeStatic(aggregation.cljc:433), at metabase.lib.aggregation$aggregation_column.invoke(aggregation.cljc:423), at metabase.models.field_usage$aggregationGT_field_usage.invokeStatic(field_usage.clj:38), at metabase.models.field_usage$aggregationGT_field_usage.invoke(field_usage.clj:36), at metabase.models.field_usage$stageGT_field_usages$fn75610.invoke(field_usage.clj:77), at clojure.core$keep$fn8649.invoke(core.clj:7406), at clojure.lang.LazySeq.sval(LazySeq.java:42), at clojure.lang.LazySeq.seq(LazySeq.java:58), at clojure.lang.RT.seq(RT.java:535), at clojure.core$seq5467.invokeStatic(core.clj:139), at clojure.core$concat$cat5560$fn5561.invoke(core.clj:736), at clojure.lang.LazySeq.sval(LazySeq.java:42), at clojure.lang.LazySeq.seq(LazySeq.java:51), at clojure.lang.RT.seq(RT.java:535), at clojure.core$seq5467.invokeStatic(core.clj:139), at clojure.core$map$fn5935.invoke(core.clj:2763), at clojure.lang.LazySeq.sval(LazySeq.java:42), at clojure.lang.LazySeq.seq(LazySeq.java:51), at clojure.lang.ChunkedCons.chunkedNext(ChunkedCons.java:59), at clojure.lang.ChunkedCons.next(ChunkedCons.java:43), at clojure.lang.RT.next(RT.java:713), at clojure.core$next5451.invokeStatic(core.clj:64), at clojure.core$next5451.invoke(core.clj:64), at clojure.spec.alpha$re_conform.invokeStatic(alpha.clj:1660), at clojure.spec.alpha$re_conform.invoke(alpha.clj:1660), at clojure.spec.alpha$regex_spec_impl$reify2503.conformSTAR(alpha.clj:1710), at clojure.spec.alpha$conform.invokeStatic(alpha.clj:171), at clojure.spec.alpha$conform.invoke(alpha.clj:167), at clojure.spec.alpha$dt.invokeStatic(alpha.clj:764), at clojure.spec.alpha$dt.invoke(alpha.clj:759), at clojure.spec.alpha$dt.invokeStatic(alpha.clj:760), at clojure.spec.alpha$dt.invoke(alpha.clj:759), at clojure.spec.alpha$deriv.invokeStatic(alpha.clj:1534), at clojure.spec.alpha$deriv.invoke(alpha.clj:1528), at clojure.spec.alpha$deriv$fn2419.invoke(alpha.clj:1544), at clojure.core$map$fn5935.invoke(core.clj:2772), at clojure.lang.LazySeq.sval(LazySeq.java:42), at clojure.lang.LazySeq.seq(LazySeq.java:51), at clojure.lang.RT.seq(RT.java:535), at clojure.core$seq5467.invokeStatic(core.clj:139), at clojure.core$map$fn5942.invoke(core.clj:2780), at clojure.lang.LazySeq.sval(LazySeq.java:42), at clojure.lang.LazySeq.seq(LazySeq.java:51), at clojure.lang.RT.seq(RT.java:535), at clojure.core$seq5467.invokeStatic(core.clj:139), at clojure.core$filter$fn5962.invoke(core.clj:2826), at clojure.lang.LazySeq.sval(LazySeq.java:42), at clojure.lang.LazySeq.seq(LazySeq.java:58), at clojure.lang.RT.seq(RT.java:535), at clojure.core$seq5467.invokeStatic(core.clj:139), at clojure.core$map$fn5935.invoke(core.clj:2763), at clojure.lang.LazySeq.sval(LazySeq.java:42), at clojure.lang.LazySeq.seq(LazySeq.java:51), at clojure.lang.RT.seq(RT.java:535), at clojure.core$seq5467.invokeStatic(core.clj:139), at clojure.core$seq5467.invoke(core.clj:139), at clojure.spec.alpha$filter_alt.invokeStatic(alpha.clj:1431), at clojure.spec.alpha$filter_alt.invoke(alpha.clj:1425), at clojure.spec.alpha$altSTAR.invokeStatic(alpha.clj:1435), at clojure.spec.alpha$altSTAR.invoke(alpha.clj:1434), at clojure.spec.alpha$deriv.invokeStatic(alpha.clj:1544), at clojure.spec.alpha$deriv.invoke(alpha.clj:1528), at clojure.spec.alpha$deriv$fn2419.invoke(alpha.clj:1544), at clojure.core$map$fn5935.invoke(core.clj:2772), at clojure.lang.LazySeq.sval(LazySeq.java:42), at clojure.lang.LazySeq.seq(LazySeq.java:51), at clojure.lang.RT.seq(RT.java:535), at clojure.core$seq5467.invokeStatic(core.clj:139), at clojure.core$map$fn5942.invoke(core.clj:2780), at clojure.lang.LazySeq.sval(LazySeq.java:42), at clojure.lang.LazySeq.seq(LazySeq.java:51), at clojure.lang.RT.seq(RT.java:535), at clojure.core$seq5467.invokeStatic(core.clj:139), at clojure.core$filter$fn5962.invoke(core.clj:2826), at clojure.lang.LazySeq.sval(LazySeq.java:42), at clojure.lang.LazySeq.seq(LazySeq.java:51), at clojure.lang.RT.seq(RT.java:535), at clojure.core$seq5467.invokeStatic(core.clj:139), at clojure.core$map$fn5935.invoke(core.clj:2763), at clojure.lang.LazySeq.sval(LazySeq.java:42), at clojure.lang.LazySeq.seq(LazySeq.java:51), at clojure.lang.RT.seq(RT.java:535), at clojure.core$seq5467.invokeStatic(core.clj:139), at clojure.core$seq5467.invoke(core.clj:139), at clojure.spec.alpha$filter_alt.invokeStatic(alpha.clj:1431), at clojure.spec.alpha$filter_alt.invoke(alpha.clj:1425), at clojure.spec.alpha$altSTAR.invokeStatic(alpha.clj:1435), at clojure.spec.alpha$altSTAR.invoke(alpha.clj:1434), at clojure.spec.alpha$deriv.invokeStatic(alpha.clj:1544), at clojure.spec.alpha$deriv.invoke(alpha.clj:1528), at clojure.spec.alpha$deriv.invokeStatic(alpha.clj:1542), at clojure.spec.alpha$deriv.invoke(alpha.clj:1528), at clojure.spec.alpha$re_conform.invokeStatic(alpha.clj:1669), at clojure.spec.alpha$re_conform.invoke(alpha.clj:1660), at clojure.spec.alpha$regex_spec_impl$reify2503.conformSTAR(alpha.clj:1710), at clojure.spec.alpha$conform.invokeStatic(alpha.clj:171), at clojure.spec.alpha$conform.invoke(alpha.clj:167), at toucan2.query$parse_args_with_spec.invokeStatic(query.clj:71), at toucan2.query$parse_args_with_spec.invoke(query.clj:66), at toucan2.insert$parse_args_primary_method_toucan_query_type_insertSTAR_.invokeStatic(insert.clj:35), at toucan2.insert$parse_args_primary_method_toucan_query_type_insertSTAR_.invoke(insert.clj:32), at clojure.lang.AFn.applyToHelper(AFn.java:160), at clojure.lang.AFn.applyTo(AFn.java:144), at clojure.lang.AFunction$1.doInvoke(AFunction.java:31), at clojure.lang.RestFn.invoke(RestFn.java:436), at clojure.core$partial$fn5908.invoke(core.clj:2642), at clojure.lang.AFn.applyToHelper(AFn.java:156), at clojure.lang.RestFn.applyTo(RestFn.java:132), at clojure.lang.AFunction$1.doInvoke(AFunction.java:31), at clojure.lang.RestFn.invoke(RestFn.java:421), at methodical.impl.combo.threaded$fn18077$fn18078$fn18079.invoke(threaded.clj:70), at methodical.impl.combo.threaded$reducer_fn$fn18047$fn18051.invoke(threaded.clj:23), at clojure.lang.ArrayChunk.reduce(ArrayChunk.java:58), at clojure.core.protocols$fn8244.invokeStatic(protocols.clj:136), at clojure.core.protocols$fn8244.invoke(protocols.clj:124), at clojure.core.protocols$fn8204$G81998213.invoke(protocols.clj:19), at clojure.core.protocols$seq_reduce.invokeStatic(protocols.clj:31), at clojure.core.protocols$fn8236.invokeStatic(protocols.clj:75), at clojure.core.protocols$fn8236.invoke(protocols.clj:75), at clojure.core.protocols$fn8178$G8173__8191.invoke(protocols.clj:13), at clojure.core$reduce.invokeStatic(core.clj:6887), at clojure.core$reduce.invoke(core.clj:6869), at methodical.impl.combo.threaded$reducer_fn$fn18047.invoke(threaded.clj:21), at clojure.core$comp$fn5876.invoke(core.clj:2587), at methodical.impl.combo.threaded$combine_with_threader$fn18057.invoke(threaded.clj:43), at clojure.lang.AFn.applyToHelper(AFn.java:156), at clojure.lang.RestFn.applyTo(RestFn.java:132), at clojure.lang.AFunction$1.doInvoke(AFunction.java:31), at clojure.lang.RestFn.invoke(RestFn.java:421), at methodical.impl.standard$invoke_multifn.invokeStatic(standard.clj:55), at methodical.impl.standard$invoke_multifn.invoke(standard.clj:47), at methodical.impl.standard.StandardMultiFn.invoke(standard.clj:193), at toucan2.pipeline$transduce_unparsed.invokeStatic(pipeline.clj:315), at toucan2.pipeline$transduce_unparsed.invoke(pipeline.clj:311), at toucan2.pipeline$transduce_unparsed_with_default_rf.invokeStatic(pipeline.clj:374), at toucan2.pipeline$transduce_unparsed_with_default_rf.invoke(pipeline.clj:368), at toucan2.insert$insertBANG.invokeStatic(insert.clj:124), at toucan2.insert$insertBANG.doInvoke(insert.clj:74), at clojure.lang.RestFn.invoke(RestFn.java:421), at metabase.query_processor.middleware.process_userland_query$save_execution_metadata_BANG_STAR.invokeStatic(process_userland_query.clj:51), at metabase.query_processor.middleware.process_userland_query$save_execution_metadata_BANGSTAR_.invoke(process_userland_query.clj:42), at metabase.query_processor.middleware.process_userland_query$save_execution_metadataBANG$fn75636.invoke(process_userland_query.clj:68), at clojure.lang.AFn.run(AFn.java:22), at java.base/java.util.concurrent.Executors$RunnableAdapter.call(Unknown Source), at java.base/java.util.concurrent.FutureTask.run(Unknown Source), at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(Unknown Source), at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(Unknown Source), at java.base/java.lang.Thread.run(Unknown Source)

To Reproduce Steps to reproduce the behavior:

1. Create a Dashboard with queries
2. Activate cache 24 hours duration on every query used on the dashboard and activate the cache on the dashboard itself
3. Launch dashboard
4. See logs on log console

Expected behavior Dashboard should load instantly, because we use cache on dashboard and queries used on dashboard

Screenshots

Severity We use it to show data quickly with this dashboard, and we create some light tables, with a few data registries, to improve performance on charging data, but we are not seeing any improvement, and we need to load this dashboard in a few seconds (2 to 3 seconds)

Metabase Diagnostic Info

{
  "browser-info": {
    "language": "es-ES",
    "platform": "MacIntel",
    "userAgent": "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_7) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/126.0.0.0 Safari/537.36",
    "vendor": "Google Inc."
  },
  "system-info": {
    "file.encoding": "UTF-8",
    "java.runtime.name": "OpenJDK Runtime Environment",
    "java.runtime.version": "11.0.23+9",
    "java.vendor": "Eclipse Adoptium",
    "java.vendor.url": "https://adoptium.net/",
    "java.version": "11.0.23",
    "java.vm.name": "OpenJDK 64-Bit Server VM",
    "java.vm.version": "11.0.23+9",
    "os.name": "Linux",
    "os.version": "4.14.252-195.483.amzn2.x86_64",
    "user.language": "en",
    "user.timezone": "GMT"
  },
  "metabase-info": {
    "databases": [
      "postgres",
      "h2"
    ],
    "hosting-env": "unknown",
    "application-database": "postgres",
    "application-database-details": {
      "database": {
        "name": "PostgreSQL",
        "version": "12.17"
      },
      "jdbc-driver": {
        "name": "PostgreSQL JDBC Driver",
        "version": "42.7.3"
      }
    },
    "run-mode": "prod",
    "plan-alias": "pro-self-hosted",
    "version": {
      "date": "2024-07-09",
      "tag": "v1.50.11",
      "hash": "e08c1fb"
    },
    "settings": {
      "report-timezone": null
    }
  }
}

[paoliniluis]

I think this is related, if not the same as https://github.com/metabase/metabase/issues/44359

[juangc-wavyssa]

I don't know if this is related, but is no the same as they describe in the issue

[bshepherdson]

One of the performance fixes we made in the course of fixing #44359 disabled the field-usage logic that's causing the stack traces you highlighted. So from 50.13 that error message will not appear anymore.

That same performance fix may play a factor here, despite appearances. The issue was a lot of CPU work being done before each query in the dashboard request is done. The impact of that perf issue scales strongly with the complexity of the query (more joins, filters, aggregations, expressions, etc.) and weakly with the total number columns in view.

So I suspect what you're seeing here is that while the query results are cached, that post-processing was consuming perhaps 500ms per query, making the overall dashboard load very slow.

@juangc-wavyssa Please try this dashboard again on 50.13 and see how it performs there.

[juangc-wavyssa]

We have updated to 50.13 and we have the same performance issue.

[bshepherdson]

This looks like there is a query caching issue, then.

Can you screenshot the caching settings for this dashboard? (Question-level caching is not used when the dashboard is cached.)

[juangc-wavyssa]

We configure Duration caching policy on dashboard and subqueries, with a 24 hours duration, since our data is updated every 24 hours for this dashboards and queries.