Complex Query does work on Native SQL base but not on UI Query Editor

Hi, we are using 0.35.4 Java 11 OpenJDK and created a custom view to enrich some date for our needed questions.
Metabase is talking remotely to another server with a DB replica of the live db data.

When I go to the UI editor and want to get r.g. everything created the last 30 days it will drop the message, it took to long/much time.
image
Message appears after 5 mins.

If I question it via SQL native query it does work within few seconds.

In the log I can see one big error:

[788388f5-ce08-4f97-82b5-bf407bf9992c] 2020-07-03T11:04:43+02:00 ERROR metabase.query-processor.middleware.catch-exceptions Error processing query: null
{:database_id 9,
:started_at (t/zoned-date-time "2020-07-03T09:59:42.779360+01:00[Europe/London]"),
:state "57014",
:json_query
{:type "query",
:query {:source-table 2408, :filter ["time-interval" ["field-id" 17511] -30 "day" {:include-current true}]},
:database 9,
:parameters ,
:middleware {:add-default-userland-constraints? true}},
:native
{:query
"SELECT "public"."myview_enriched_issue"."assignee" AS "assignee", "public"."myview_enriched_issue"."complexity" AS "complexity", "public"."myview_enriched_issue"."created_date" AS "created_date", "public"."myview_enriched_issue"."creator" AS "creator", "public"."myview_enriched_issue"."fix_version" AS "fix_version", "public"."myview_enriched_issue"."issue_components" AS "issue_components", "public"."myview_enriched_issue"."issue_number" AS "issue_number", "public"."myview_enriched_issue"."issue_priority" AS "issue_priority", "public"."myview_enriched_issue"."issue_statuses" AS "issue_statuses", "public"."myview_enriched_issue"."issue_type" AS "issue_type", "public"."myview_enriched_issue"."minutes_spent" AS "minutes_spent", "public"."myview_enriched_issue"."new_or_known" AS "new_or_known", "public"."myview_enriched_issue"."paid_work" AS "paid_work", "public"."myview_enriched_issue"."region" AS "region", "public"."myview_enriched_issue"."reporter" AS "reporter", "public"."myview_enriched_issue"."resolution" AS "resolution", "public"."myview_enriched_issue"."resolved_date" AS "resolved_date", "public"."myview_enriched_issue"."responsible_squad" AS "responsible_squad", "public"."myview_enriched_issue"."salesforce_account" AS "salesforce_account", "public"."myview_enriched_issue"."salesforce_advanced_support" AS "salesforce_advanced_support", "public"."myview_enriched_issue"."salesforce_customer_segment" AS "salesforce_customer_segment", "public"."myview_enriched_issue"."salesforce_success_manager" AS "salesforce_success_manager", "public"."myview_enriched_issue"."system_mode" AS "system_mode", "public"."myview_enriched_issue"."time_to_first_response" AS "time_to_first_response", "public"."myview_enriched_issue"."time_to_resolution" AS "time_to_resolution", "public"."myview_enriched_issue"."updated_date" AS "updated_date" FROM "public"."myview_enriched_issue" WHERE CAST("public"."myview_enriched_issue"."created_date" AS date) BETWEEN CAST((CAST(now() AS timestamp) + (INTERVAL '-30 day')) AS date) AND CAST(now() AS date) LIMIT 2000",
:params nil},
:status :failed,
:class org.postgresql.util.PSQLException,
:stacktrace
["org.postgresql.core.v3.QueryExecutorImpl.receiveErrorResponse(QueryExecutorImpl.java:2497)"
"org.postgresql.core.v3.QueryExecutorImpl.processResults(QueryExecutorImpl.java:2233)"
"org.postgresql.core.v3.QueryExecutorImpl.execute(QueryExecutorImpl.java:310)"
"org.postgresql.jdbc.PgStatement.executeInternal(PgStatement.java:446)"
"org.postgresql.jdbc.PgStatement.execute(PgStatement.java:370)"
"org.postgresql.jdbc.PgPreparedStatement.executeWithFlags(PgPreparedStatement.java:149)"
"org.postgresql.jdbc.PgPreparedStatement.executeQuery(PgPreparedStatement.java:108)"
"com.mchange.v2.c3p0.impl.NewProxyPreparedStatement.executeQuery(NewProxyPreparedStatement.java:431)"
"--> driver.sql_jdbc.execute$fn__70879.invokeStatic(execute.clj:267)"
"driver.sql_jdbc.execute$fn__70879.invoke(execute.clj:265)"
"driver.sql_jdbc.execute$execute_reducible_query.invokeStatic(execute.clj:389)"
"driver.sql_jdbc.execute$execute_reducible_query.invoke(execute.clj:377)"
"driver.sql_jdbc$fn__73052.invokeStatic(sql_jdbc.clj:49)"
"driver.sql_jdbc$fn__73052.invoke(sql_jdbc.clj:47)"
"query_processor.context$executef.invokeStatic(context.clj:59)"
"query_processor.context$executef.invoke(context.clj:48)"
"query_processor.context.default$default_runf.invokeStatic(default.clj:69)"
"query_processor.context.default$default_runf.invoke(default.clj:67)"
"query_processor.context$runf.invokeStatic(context.clj:45)"
"query_processor.context$runf.invoke(context.clj:39)"
"query_processor.reducible$pivot.invokeStatic(reducible.clj:34)"
"query_processor.reducible$pivot.invoke(reducible.clj:31)"
"query_processor.middleware.mbql_to_native$mbql__GT_native$fn__43149.invoke(mbql_to_native.clj:26)"
"query_processor.middleware.check_features$check_features$fn__42463.invoke(check_features.clj:42)"
"query_processor.middleware.optimize_datetime_filters$optimize_datetime_filters$fn__43314.invoke(optimize_datetime_filters.clj:133)"
"query_processor.middleware.wrap_value_literals$wrap_value_literals$fn__47282.invoke(wrap_value_literals.clj:137)"
"query_processor.middleware.annotate$add_column_info$fn__41084.invoke(annotate.clj:577)"
"query_processor.middleware.permissions$check_query_permissions$fn__42338.invoke(permissions.clj:64)"
"query_processor.middleware.pre_alias_aggregations$pre_alias_aggregations$fn__43813.invoke(pre_alias_aggregations.clj:40)"
"query_processor.middleware.cumulative_aggregations$handle_cumulative_aggregations$fn__42536.invoke(cumulative_aggregations.clj:61)"
"query_processor.middleware.resolve_joins$resolve_joins$fn__44345.invoke(resolve_joins.clj:183)"
"query_processor.middleware.add_implicit_joins$add_implicit_joins$fn__39271.invoke(add_implicit_joins.clj:245)"
"query_processor.middleware.limit$limit$fn__43135.invoke(limit.clj:38)"
"query_processor.middleware.format_rows$format_rows$fn__43116.invoke(format_rows.clj:81)"
"query_processor.middleware.desugar$desugar$fn__42602.invoke(desugar.clj:22)"
"query_processor.middleware.binning$update_binning_strategy$fn__41628.invoke(binning.clj:229)"
"query_processor.middleware.resolve_fields$resolve_fields$fn__42144.invoke(resolve_fields.clj:24)"
"query_processor.middleware.add_dimension_projections$add_remapping$fn__38807.invoke(add_dimension_projections.clj:272)"
"query_processor.middleware.add_implicit_clauses$add_implicit_clauses$fn__39027.invoke(add_implicit_clauses.clj:147)"
"query_processor.middleware.add_source_metadata$add_source_metadata_for_source_queries$fn__39420.invoke(add_source_metadata.clj:105)"
"query_processor.middleware.reconcile_breakout_and_order_by_bucketing$reconcile_breakout_and_order_by_bucketing$fn__44010.invoke(reconcile_breakout_and_order_by_bucketing.clj:98)"
"query_processor.middleware.auto_bucket_datetimes$auto_bucket_datetimes$fn__41269.invoke(auto_bucket_datetimes.clj:125)"
"query_processor.middleware.resolve_source_table$resolve_source_tables$fn__42191.invoke(resolve_source_table.clj:46)"
"query_processor.middleware.parameters$substitute_parameters$fn__43795.invoke(parameters.clj:97)"
"query_processor.middleware.resolve_referenced$resolve_referenced_card_resources$fn__42243.invoke(resolve_referenced.clj:80)"
"query_processor.middleware.expand_macros$expand_macros$fn__42858.invoke(expand_macros.clj:158)"
"query_processor.middleware.add_timezone_info$add_timezone_info$fn__39451.invoke(add_timezone_info.clj:15)"
"query_processor.middleware.splice_params_in_response$splice_params_in_response$fn__47166.invoke(splice_params_in_response.clj:32)"
"query_processor.middleware.resolve_database_and_driver$resolve_database_and_driver$fn__44021$fn__44025.invoke(resolve_database_and_driver.clj:33)"
"driver$do_with_driver.invokeStatic(driver.clj:61)"
"driver$do_with_driver.invoke(driver.clj:57)"
"query_processor.middleware.resolve_database_and_driver$resolve_database_and_driver$fn__44021.invoke(resolve_database_and_driver.clj:27)"
"query_processor.middleware.fetch_source_query$resolve_card_id_source_tables$fn__43064.invoke(fetch_source_query.clj:243)"
"query_processor.middleware.store$initialize_store$fn__47175$fn__47176.invoke(store.clj:11)"
"query_processor.store$do_with_store.invokeStatic(store.clj:46)"
"query_processor.store$do_with_store.invoke(store.clj:40)"
"query_processor.middleware.store$initialize_store$fn__47175.invoke(store.clj:10)"
"query_processor.middleware.cache$maybe_return_cached_results$fn__42120.invoke(cache.clj:209)"
"query_processor.middleware.validate$validate_query$fn__47184.invoke(validate.clj:10)"
"query_processor.middleware.normalize_query$normalize$fn__43162.invoke(normalize_query.clj:22)"
"query_processor.middleware.add_rows_truncated$add_rows_truncated$fn__39289.invoke(add_rows_truncated.clj:36)"
"query_processor.middleware.results_metadata$record_and_return_metadata_BANG_$fn__47151.invoke(results_metadata.clj:128)"
"query_processor.middleware.constraints$add_default_userland_constraints$fn__42479.invoke(constraints.clj:42)"
"query_processor.middleware.process_userland_query$process_userland_query$fn__43884.invoke(process_userland_query.clj:136)"
"query_processor.middleware.catch_exceptions$catch_exceptions$fn__42422.invoke(catch_exceptions.clj:174)"
"query_processor.reducible$async_qp$qp_STAR___38090$thunk__38091.invoke(reducible.clj:101)"
"query_processor.reducible$async_qp$qp_STAR___38090.invoke(reducible.clj:107)"
"query_processor.reducible$sync_qp$qp_STAR___38099$fn__38102.invoke(reducible.clj:133)"
"query_processor.reducible$sync_qp$qp_STAR___38099.invoke(reducible.clj:132)"
"query_processor$process_userland_query.invokeStatic(query_processor.clj:218)"
"query_processor$process_userland_query.doInvoke(query_processor.clj:214)"
"query_processor$fn__47350$process_query_and_save_execution_BANG___47359$fn__47362.invoke(query_processor.clj:233)"
"query_processor$fn__47350$process_query_and_save_execution_BANG___47359.invoke(query_processor.clj:225)"
"query_processor$fn__47394$process_query_and_save_with_max_results_constraints_BANG___47403$fn__47406.invoke(query_processor.clj:245)"
"query_processor$fn__47394$process_query_and_save_with_max_results_constraints_BANG___47403.invoke(query_processor.clj:238)"
"api.dataset$fn__50692$fn__50695.invoke(dataset.clj:52)"
"query_processor.streaming$streaming_response_STAR_$fn__34128$fn__34129.invoke(streaming.clj:73)"
"query_processor.streaming$streaming_response_STAR_$fn__34128.invoke(streaming.clj:72)"
"async.streaming_response$do_f_STAR_.invokeStatic(streaming_response.clj:66)"
"async.streaming_response$do_f_STAR_.invoke(streaming_response.clj:64)"
"async.streaming_response$do_f_async$fn__23118.invoke(streaming_response.clj:85)"],
:context :ad-hoc,
:error "ERROR: canceling statement due to user request",
:row_count 0,
:running_time 0,
:preprocessed
{:type :query,
:query
{:source-table 2408,
:filter [:between [:datetime-field [:field-id 17511] :day] [:relative-datetime -30 :day] [:relative-datetime 0 :day]],
:fields
[[:field-id 17514]
[:field-id 17516]
[:datetime-field [:field-id 17511] :default]
[:field-id 17507]
[:field-id 17523]
[:field-id 17526]
[:field-id 17515]
[:field-id 17519]
[:field-id 17527]
[:field-id 17509]
[:field-id 17531]
[:field-id 17522]
[:field-id 17512]
[:field-id 17532]
[:field-id 17529]
[:field-id 17525]
[:datetime-field [:field-id 17518] :default]
[:field-id 17513]
[:field-id 17524]
[:field-id 17520]
[:field-id 17508]
[:field-id 17530]
[:field-id 17517]
[:field-id 17510]
[:field-id 17528]
[:datetime-field [:field-id 17521] :default]],
:limit 2000},
:database 9,
:middleware {:add-default-userland-constraints? true},
:info
{:executed-by 1,
:context :ad-hoc,
:nested? false,
:query-hash [-77, -37, 72, 42, -74, 75, 1, 102, 107, 33, -36, 113, 18, 58, -1, 48, 70, 21, -79, 42, 60, -38, 16, -93, -22, -86, -32, 34, -5, -63, -65, -127]},
:constraints {:max-results 10000, :max-results-bare-rows 2000}},
:data {:rows , :cols }}

[788388f5-ce08-4f97-82b5-bf407bf9992c] 2020-07-03T11:04:43+02:00 DEBUG metabase.middleware.log POST /api/dataset 202 [ASYNC: canceled] 5.0 mins (9 DB calls) App DB connections: 0/7 Jetty threads: 4/50 (2 idle, 0 queued) (127 total active threads) Queries in flight: 0 (0 queued)

What can we do to avoid it/sovle it? Cache was on too, but couldn't solve it. Thanks in advance

Hi @MarslMarcello

Please post “Diagnostic Info” from Admin > Troubleshooting.

It looks like you have a proxy that is closing the connection after 5 minutes - canceling statement due to user request:
https://www.metabase.com/docs/latest/troubleshooting-guide/proxies.html

So you’re saying that if you take the {:query <the generated query> } from the stacktrace and run via Native question, then it only takes a few seconds? That sounds strange, but I don’t know which proxy you’re using and we’ve seen some very strange behaviors with various security/WAF proxies.

{
"browser-info": {
"language": "en-US",
"platform": "MacIntel",
"userAgent": "Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_5) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/83.0.4103.116 Safari/537.36",
"vendor": "Google Inc."
},
"system-info": {
"file.encoding": "UTF-8",
"java.runtime.name": "OpenJDK Runtime Environment",
"java.runtime.version": "11.0.7+10-post-Ubuntu-2ubuntu218.04",
"java.vendor": "Ubuntu",
"java.vendor.url": "https://ubuntu.com/",
"java.version": "11.0.7",
"java.vm.name": "OpenJDK 64-Bit Server VM",
"java.vm.version": "11.0.7+10-post-Ubuntu-2ubuntu218.04",
"os.name": "Linux",
"os.version": "4.15.0-96-generic",
"user.language": "en",
"user.timezone": "Europe/London"
},
"metabase-info": {
"databases": [
"h2",
"postgres",
"googleanalytics"
],
"hosting-env": "unknown",
"application-database": "mysql",
"application-database-details": {
"database": {
"name": "MySQL",
"version": "5.7.30-0ubuntu0.18.04.1"
},
"jdbc-driver": {
"name": "MariaDB Connector/J",
"version": "2.5.1"
}
},
"run-mode": "prod",
"version": {
"date": "2020-05-28",
"tag": "v0.35.4",
"branch": "release-0.35.x",
"hash": "b3080fa"
},
"settings": {
"report-timezone": "Europe/Berlin"
}
}
}

I'm using Apache Webserver + Proxy/Proxypass config to redirect from localhost:3000 to url/domian.

@MarslMarcello
Apache can have a bunch of modules that does security stuff, so that doesn’t say a lot.
Which query are you using in Native question, when it only takes seconds?

For example the metabase created query looks like

SELECT "public"."myview_enriched_issue"."assignee" AS "assignee", "public"."myview_enriched_issue"."complexity" AS "complexity", "public"."myview_enriched_issue"."created_date" AS "created_date", "public"."myview_enriched_issue"."creator" AS "creator", "public"."myview_enriched_issue"."fix_version" AS "fix_version", "public"."myview_enriched_issue"."issue_components" AS "issue_components", "public"."myview_enriched_issue"."issue_number" AS "issue_number", "public"."myview_enriched_issue"."issue_priority" AS "issue_priority", "public"."myview_enriched_issue"."issue_statuses" AS "issue_statuses", "public"."myview_enriched_issue"."issue_type" AS "issue_type", "public"."myview_enriched_issue"."minutes_spent" AS "minutes_spent", "public"."myview_enriched_issue"."new_or_known" AS "new_or_known", "public"."myview_enriched_issue"."paid_work" AS "paid_work", "public"."myview_enriched_issue"."region" AS "region", "public"."myview_enriched_issue"."reporter" AS "reporter", "public"."myview_enriched_issue"."resolution" AS "resolution", "public"."myview_enriched_issue"."resolved_date" AS "resolved_date", "public"."myview_enriched_issue"."responsible_squad" AS "responsible_squad", "public"."myview_enriched_issue"."salesforce_account" AS "salesforce_account", "public"."myview_enriched_issue"."salesforce_advanced_support" AS "salesforce_advanced_support", "public"."myview_enriched_issue"."salesforce_customer_segment" AS "salesforce_customer_segment", "public"."myview_enriched_issue"."salesforce_success_manager" AS "salesforce_success_manager", "public"."myview_enriched_issue"."system_mode" AS "system_mode", "public"."myview_enriched_issue"."time_to_first_response" AS "time_to_first_response", "public"."myview_enriched_issue"."time_to_resolution" AS "time_to_resolution", "public"."myview_enriched_issue"."updated_date" AS "updated_date"
FROM "public"."myview_enriched_issue"
WHERE CAST("public"."myview_enriched_issue"."created_date" AS date) BETWEEN CAST((CAST(now() AS timestamp) + (INTERVAL '-7 day')) AS date)
AND CAST(now() AS date)
LIMIT 1048576;

it does take ~11 min some seconds in my IDE but when I take

SELECT * FROM myview_enriched_issue WHERE (CAST("created_date" AS date) BETWEEN CAST((CAST(now() AS timestamp) + (INTERVAL '-7 day')) AS date) AND CAST(now() AS date));

It takes between 2 and 5 seconds (2s 97ms).
The first Metabase built query (above the big one) failed the second time in my IDE too after 12m 40s

@MarslMarcello
Okay, but if the query also takes 11 minutes in other tools, then it seems like the problem is the database. The only difference is * vs listing all the columns, so it’s not even related to indexes.

Or perhaps you’re querying two different schemas? Try FROM "public"."myview_enriched_issue" to make sure it’s the same schema.

Which version of Postgres? Have you checked the Postgres server log for debugging on why it takes so long?

It just takes so long in my IDE when I try to use the “metabase generated queries” (the big ones).

Regarding PostgresSQL I guess I have to talk to our hoster (it is a 9.6) to figure out why the metabase queries taking so long. Unfortunately we haven’t full access and only read access.

This myview_… is a created custom view that prepares data and other smaller custom views to get all in the “enriched view” with all details what we need. I guess the custom view stuff is maybe to complex and not the optimal solution for our use case.

@MarslMarcello Yes, but the only difference between the “big” and the “small” query, is the SELECT-clause has the columns defined vs wildcard (*).

So that feels like a bug in Postgres, specially since you’re seeing same behavior from other tools.

Perhaps it’s a problem in combination with the view, but without debugging from Postgres, then it’s hard to tell.

You could try running the queries with EXPLAIN prepended the query to see if it will tell hint at the problem:
https://www.postgresql.org/docs/9.6/using-explain.html

@flamber thanks for all the infos, I’ll investigate with explain and try something out to solve it. Will post here with results the next days.