A model encounters an error during persistence, with logs indicating "Persistence already present..."

[vipera7]

Describe the bug

I am attempting to persist a model. The query executes quickly (in less than 20 seconds). However, the tools return a timeout error (ERREUR: annulation de la requête à cause du délai écoulé pour l'exécution de l'instruction). The logs do not reflect this timeout error but instead indicate that 'Persistence already present for model xxx.'

To Reproduce

1. Persist a model

Expected behavior

The model should be persisted with updated data and should not produce an error.

Logs

[41fdb96a-1e84-4a49-840f-3e75ae668ac4] 2024-07-15T16:19:39+02:00 INFO metabase.task.persist-refresh Scheduling refresh for model: 252
[41fdb96a-1e84-4a49-840f-3e75ae668ac4] 2024-07-15T16:19:39+02:00 INFO metabase.task.persist-refresh Persistence already present for model 252 metabase.task.PersistenceRefresh.individual.trigger.150
[41fdb96a-1e84-4a49-840f-3e75ae668ac4] 2024-07-15T16:19:39+02:00 DEBUG metabase.server.middleware.log POST /api/card/252/refresh 204 10,0 ms (3 DB calls) App DB connections: 0/15 Jetty threads: 4/50 (4 idle, 0 queued) (108 total active threads) Queries in flight: 0 (0 queued) {:metabase-user-id 1}

Information about your Metabase installation

Metabase is installed on Windows Server 2016 and is configured for production mode with a MySQL 8 server. It is running version v0.50.12. The database that the model points to is PostgreSQL.

{
  "browser-info": {
    "language": "fr-FR",
    "platform": "Win32",
    "userAgent": "Mozilla/5.0 (Windows NT 10.0; Win64; x64) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/126.0.0.0 Safari/537.36",
    "vendor": "Google Inc."
  },
  "system-info": {
    "file.encoding": "Cp1252",
    "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": "Windows Server 2016",
    "os.version": "10.0",
    "user.language": "fr",
    "user.timezone": "Europe/Paris"
  },
  "metabase-info": {
    "databases": [
      "postgres",
      "mysql"
    ],
    "hosting-env": "unknown",
    "application-database": "mysql",
    "application-database-details": {
      "database": {
        "name": "MySQL",
        "version": "8.0.36"
      },
      "jdbc-driver": {
        "name": "MariaDB Connector/J",
        "version": "2.7.10"
      }
    },
    "run-mode": "prod",
    "plan-alias": "",
    "version": {
      "date": "2024-07-12",
      "tag": "v0.50.12",
      "hash": "86d4671"
    },
    "settings": {
      "report-timezone": "Europe/Paris"
    }
  }
}

Severity

This is important as I'm unable to run my report using these models.

Additional context

No response

[bshepherdson]

Need to determine if this is a widespread issue with model persistence. Feel free to lower the priority if the scope is more limited than it appears at first glance.

[metamben]

@vipera7, can you please provide more details that could help reproduce the issue? Do you have this problem with just one specific model? Have you experienced any problems querying the model with this issue?

[vipera7]

Of my 7 models, any one might fail at random. I have to refresh multiple times to successfully update them.

[vipera7]

I wonder if the name of the last model is related to this issue:

[metamben]

I created seven models with names in the picture from @vipera7 using MySQL both as app DB and as DW. I used both mbql and native models. I couldn't reproduce the issue.

[perivamsi]

Lowering this to P2 based on the difficulty to repro. Not a widespread issue.

@vipera7 what tools are you referring to when you say "However, the tools return a timeout error"? Also, what do you see when you go to the url /admin/tools/model-caching for these models?

[vipera7]

When I'm referecing to tools, I'm mean on this page : /admin/tools/model-caching

[perivamsi]

Can you send a screenshot of the error?

[vipera7]

Hello perivamsi,

Here is the screenshot

Log from this refresh:

[41fdb96a-1e84-4a49-840f-3e75ae668ac4] 2024-07-22T16:14:11+02:00 INFO metabase.task.persist-refresh Error refreshing persisting model with card-id 273,org.postgresql.util.PSQLException: ERREUR: annulation de la requête à cause du délai écoulé pour l'exécution de l'instruction,   at org.postgresql.core.v3.QueryExecutorImpl.receiveErrorResponse(QueryExecutorImpl.java:2725),  at org.postgresql.core.v3.QueryExecutorImpl.processResults(QueryExecutorImpl.java:2412),    at org.postgresql.core.v3.QueryExecutorImpl.execute(QueryExecutorImpl.java:371),    at org.postgresql.jdbc.PgStatement.executeInternal(PgStatement.java:502),   at org.postgresql.jdbc.PgStatement.execute(PgStatement.java:419),   at org.postgresql.jdbc.PgPreparedStatement.executeWithFlags(PgPreparedStatement.java:194),  at org.postgresql.jdbc.PgPreparedStatement.executeUpdate(PgPreparedStatement.java:155), at com.mchange.v2.c3p0.impl.NewProxyPreparedStatement.executeUpdate(NewProxyPreparedStatement.java:1502),   at clojure.java.jdbc$db_do_execute_prepared_statement$fn__42034.invoke(jdbc.clj:1049),  at clojure.java.jdbc$db_transaction_STAR_.invokeStatic(jdbc.clj:860),   at clojure.java.jdbc$db_transaction_STAR_.invoke(jdbc.clj:776), at clojure.java.jdbc$db_transaction_STAR_.invokeStatic(jdbc.clj:789),   at clojure.java.jdbc$db_transaction_STAR_.invoke(jdbc.clj:776), at clojure.java.jdbc$db_do_execute_prepared_statement.invokeStatic(jdbc.clj:1048),  at clojure.java.jdbc$db_do_execute_prepared_statement.invoke(jdbc.clj:1042),    at clojure.java.jdbc$db_do_prepared.invokeStatic(jdbc.clj:1080),    at clojure.java.jdbc$db_do_prepared.invoke(jdbc.clj:1060),  at clojure.java.jdbc$execute_BANG_$execute_helper__42108.invoke(jdbc.clj:1464), at clojure.java.jdbc$execute_BANG_.invokeStatic(jdbc.clj:1466), at clojure.java.jdbc$execute_BANG_.invoke(jdbc.clj:1435),   at clojure.java.jdbc$execute_BANG_.invokeStatic(jdbc.clj:1456), at clojure.java.jdbc$execute_BANG_.invoke(jdbc.clj:1435),   at metabase.driver.sql.ddl$execute_BANG_.invokeStatic(ddl.clj:27),  at metabase.driver.sql.ddl$execute_BANG_.invoke(ddl.clj:24),    at metabase.driver.postgres.ddl$fn__85887$fn__85889$fn__85890.invoke(ddl.clj:49),   at clojure.java.jdbc$db_transaction_STAR_.invokeStatic(jdbc.clj:807),   at clojure.java.jdbc$db_transaction_STAR_.invoke(jdbc.clj:776), at clojure.java.jdbc$db_transaction_STAR_.invokeStatic(jdbc.clj:789),   at clojure.java.jdbc$db_transaction_STAR_.invoke(jdbc.clj:776), at metabase.driver.postgres.ddl$fn__85887$fn__85889.invoke(ddl.clj:46), at metabase.driver.sql_jdbc.execute$fn__81542$fn__81543.invoke(execute.clj:397),    at metabase.driver.sql_jdbc.execute$do_with_resolved_connection.invokeStatic(execute.clj:337),  at metabase.driver.sql_jdbc.execute$do_with_resolved_connection.invoke(execute.clj:320),    at metabase.driver.sql_jdbc.execute$fn__81542.invokeStatic(execute.clj:391),    at metabase.driver.sql_jdbc.execute$fn__81542.invoke(execute.clj:389),  at clojure.lang.MultiFn.invoke(MultiFn.java:244),   at metabase.driver.postgres.ddl$fn__85887.invokeStatic(ddl.clj:41), at metabase.driver.postgres.ddl$fn__85887.invoke(ddl.clj:38),   at clojure.lang.MultiFn.invoke(MultiFn.java:244),   at metabase.task.persist_refresh$reify__86844.refresh_BANG_(persist_refresh.clj:53),    at metabase.task.persist_refresh$refresh_with_stats_BANG_$fn__86847.invoke(persist_refresh.clj:73), at metabase.task.persist_refresh$refresh_with_stats_BANG_.invokeStatic(persist_refresh.clj:72), at metabase.task.persist_refresh$refresh_with_stats_BANG_.invoke(persist_refresh.clj:57),   at clojure.lang.AFn.applyToHelper(AFn.java:165),    at clojure.lang.AFn.applyTo(AFn.java:144),  at clojure.core$apply.invokeStatic(core.clj:673),   at clojure.core$partial$fn__5914.doInvoke(core.clj:2660),   at clojure.lang.RestFn.invoke(RestFn.java:397), at metabase.task.persist_refresh$save_task_history_BANG_$fn__86865.invoke(persist_refresh.clj:123), at metabase.models.task_history$do_with_task_history.invokeStatic(task_history.clj:116),    at metabase.models.task_history$do_with_task_history.invoke(task_history.clj:105),  at metabase.task.persist_refresh$save_task_history_BANG_.invokeStatic(persist_refresh.clj:115), at metabase.task.persist_refresh$save_task_history_BANG_.invoke(persist_refresh.clj:111),   at metabase.task.persist_refresh$refresh_individual_BANG_.invokeStatic(persist_refresh.clj:219),    at metabase.task.persist_refresh$refresh_individual_BANG_.invoke(persist_refresh.clj:211),  at metabase.task.persist_refresh$refresh_job_fn_BANG_.invokeStatic(persist_refresh.clj:235),    at metabase.task.persist_refresh$refresh_job_fn_BANG_.invoke(persist_refresh.clj:229),  at metabase.task.persist_refresh.PersistenceRefresh.execute(persist_refresh.clj:245),   at org.quartz.core.JobRunShell.run(JobRunShell.java:202),   at org.quartz.simpl.SimpleThreadPool$WorkerThread.run(SimpleThreadPool.java:573)
[41fdb96a-1e84-4a49-840f-3e75ae668ac4] 2024-07-22T16:14:11+02:00 INFO metabase.task.persist-refresh Finished updated model-id 273 from persisted-info 161.

[perivamsi]

Thank you @vipera7 this is helpful.

Are you able to run the question based on this model or no? What happens when you try and query the results of the model?

[vipera7]

I can run the query in pgAdmin 4 client, and it takes approximately 17 minutes to complete

[metamben]

@vipera7, queries get terminated after 10 minutes during model synchronization and there is no option to increase this timeout. This is done to protect the Metabase instance from unexpectedly large/long running queries.

[vipera7]

Is there any solution ? I have plenty of reports using this model.

[metamben]

Can the query be optimized? I understand some time ago it was faster than 10 minutes. Did the underlying tables grow that much?

If you are willing to fork Metabase, you can of course raise the timeout in metabase.driver.postgres.ddl/set-statement-timeout!, but that might de-stabilize Metabase.