After updating from v2, API requests time out for longer time frames #4360

justrealmilk · 2024-07-16T08:30:03Z

justrealmilk
Jul 16, 2024

Past Issues Searched

I have searched open and closed issues to make sure that the bug has not yet been reported

Issue is a Bug Report

This is a bug report and not a feature request, nor asking for self-hosted support

Using official Plausible Cloud hosting or self-hosting?

Self-hosting

Describe the bug

Followed upgrade instructions as per https://github.com/plausible/analytics/releases/tag/v2.1.0

The greater the time frame, the longer the request takes to fulfil. Why is it so slow?

2024-07-16T08:20:02.459404945Z Request: GET /api/stats/MY WEBSITE/countries?period=all&date=2024-07-16&filters=%7B%7D&with_imported=true&limit=300
2024-07-16T08:20:02.459409081Z ** (exit) an exception was raised:
2024-07-16T08:20:02.459413081Z     ** (Mint.TransportError) socket closed
2024-07-16T08:20:02.459416700Z         (ecto_sql 3.11.1) lib/ecto/adapters/sql.ex:1054: Ecto.Adapters.SQL.raise_sql_call_error/1
2024-07-16T08:20:02.459421322Z         (ecto_ch 0.3.5) lib/ecto/adapters/clickhouse.ex:319: Ecto.Adapters.ClickHouse.execute/5
2024-07-16T08:20:02.459426310Z         (ecto 3.11.2) lib/ecto/repo/queryable.ex:232: Ecto.Repo.Queryable.execute/4
2024-07-16T08:20:02.459431047Z         (ecto 3.11.2) lib/ecto/repo/queryable.ex:19: Ecto.Repo.Queryable.all/3
2024-07-16T08:20:02.459435469Z         (plausible 0.0.1) lib/plausible/stats/breakdown.ex:334: Plausible.Stats.Breakdown.paginate_and_execute/3
2024-07-16T08:20:02.459439686Z         (plausible 0.0.1) lib/plausible_web/controllers/api/stats_controller.ex:903: PlausibleWeb.Api.StatsController.countries/2
2024-07-16T08:20:02.459461953Z         (plausible 0.0.1) lib/plausible_web/controllers/api/stats_controller.ex:1: PlausibleWeb.Api.StatsController.action/2
2024-07-16T08:20:02.459466271Z         (plausible 0.0.1) lib/plausible_web/controllers/api/stats_controller.ex:1: PlausibleWeb.Api.StatsController.phoenix_controller_pipeline/2
2024-07-16T08:20:02.462911228Z 08:20:02.461 [error] Ch.Connection (#PID<0.4217.0>) disconnected: ** (DBConnection.ConnectionError) client #PID<0.4882.0> timed out because it queued and checked out the connection for longer than 15000ms
2024-07-16T08:20:02.462931599Z 
2024-07-16T08:20:02.462935928Z #PID<0.4882.0> was at location:
2024-07-16T08:20:02.462939821Z 
2024-07-16T08:20:02.462953875Z     :prim_inet.recv0/3
2024-07-16T08:20:02.462957768Z     (mint 1.6.0) lib/mint/core/transport/tcp.ex:67: Mint.Core.Transport.TCP.recv/3
2024-07-16T08:20:02.462961371Z     (mint 1.6.0) lib/mint/http1.ex:519: Mint.HTTP1.recv/3
2024-07-16T08:20:02.462965126Z     (ch 0.2.5) lib/ch/connection.ex:335: Ch.Connection.recv_all/3
2024-07-16T08:20:02.462968870Z     (ch 0.2.5) lib/ch/connection.ex:313: Ch.Connection.receive_full_response/2
2024-07-16T08:20:02.462972774Z     (ch 0.2.5) lib/ch/connection.ex:249: Ch.Connection.handle_execute/4
2024-07-16T08:20:02.462976490Z     (db_connection 2.6.0) lib/db_connection/holder.ex:354: DBConnection.Holder.holder_apply/4
2024-07-16T08:20:02.462980529Z     (db_connection 2.6.0) lib/db_connection.ex:1512: DBConnection.run_execute/5
2024-07-16T08:20:02.462984654Z 
2024-07-16T08:20:02.463961300Z 08:20:02.461 [error] Task #PID<0.4882.0> started from #PID<0.4874.0> terminating
2024-07-16T08:20:02.463998443Z ** (Mint.TransportError) timeout
2024-07-16T08:20:02.464003378Z     (ecto_sql 3.11.1) lib/ecto/adapters/sql.ex:1054: Ecto.Adapters.SQL.raise_sql_call_error/1
2024-07-16T08:20:02.464008384Z     (ecto_ch 0.3.5) lib/ecto/adapters/clickhouse.ex:319: Ecto.Adapters.ClickHouse.execute/5
2024-07-16T08:20:02.464012271Z     (ecto 3.11.2) lib/ecto/repo/queryable.ex:232: Ecto.Repo.Queryable.execute/4
2024-07-16T08:20:02.464016022Z     (ecto 3.11.2) lib/ecto/repo/queryable.ex:19: Ecto.Repo.Queryable.all/3
2024-07-16T08:20:02.464019946Z     (ecto 3.11.2) lib/ecto/repo/queryable.ex:154: Ecto.Repo.Queryable.one/3
2024-07-16T08:20:02.464024048Z     (elixir 1.16.0) lib/task/supervised.ex:101: Task.Supervised.invoke_mfa/2
2024-07-16T08:20:02.464027778Z     (elixir 1.16.0) lib/task/supervised.ex:36: Task.Supervised.reply/4
2024-07-16T08:20:02.464033459Z Function: &:erlang.apply/2
2024-07-16T08:20:02.464037339Z     Args: [#Function<0.16863069/1 in Plausible.ClickhouseRepo.parallel_tasks/2>, [#Function<0.22789665/0 in Plausible.Stats.Aggregate.aggregate/3>]]
2024-07-16T08:20:02.464653944Z 08:20:02.463 [error] Ranch protocol #PID<0.4874.0> of listener PlausibleWeb.Endpoint.HTTP (connection #PID<0.4873.0>, stream id 1) terminated
2024-07-16T08:20:02.464679230Z an exception was raised:
2024-07-16T08:20:02.464683234Z     ** (Mint.TransportError) timeout
2024-07-16T08:20:02.464686814Z         (ecto_sql 3.11.1) lib/ecto/adapters/sql.ex:1054: Ecto.Adapters.SQL.raise_sql_call_error/1
2024-07-16T08:20:02.464690766Z         (ecto_ch 0.3.5) lib/ecto/adapters/clickhouse.ex:319: Ecto.Adapters.ClickHouse.execute/5
2024-07-16T08:20:02.464694417Z         (ecto 3.11.2) lib/ecto/repo/queryable.ex:232: Ecto.Repo.Queryable.execute/4
2024-07-16T08:20:02.464698057Z         (ecto 3.11.2) lib/ecto/repo/queryable.ex:19: Ecto.Repo.Queryable.all/3
2024-07-16T08:20:02.464712093Z         (ecto 3.11.2) lib/ecto/repo/queryable.ex:154: Ecto.Repo.Queryable.one/3
2024-07-16T08:20:02.464715817Z         (elixir 1.16.0) lib/task/supervised.ex:101: Task.Supervised.invoke_mfa/2
2024-07-16T08:20:02.464719448Z         (elixir 1.16.0) lib/task/supervised.ex:36: Task.Supervised.reply/4
2024-07-16T08:20:02.470954166Z 08:20:02.467 [error] Ch.Connection (#PID<0.4214.0>) disconnected: ** (DBConnection.ConnectionError) client #PID<0.4885.0> timed out because it queued and checked out the connection for longer than 15000ms
2024-07-16T08:20:02.470971517Z 
2024-07-16T08:20:02.470975458Z #PID<0.4885.0> was at location:
2024-07-16T08:20:02.470979047Z 
2024-07-16T08:20:02.470991975Z     :prim_inet.recv0/3
2024-07-16T08:20:02.470995627Z     (mint 1.6.0) lib/mint/core/transport/tcp.ex:67: Mint.Core.Transport.TCP.recv/3
2024-07-16T08:20:02.471002860Z     (mint 1.6.0) lib/mint/http1.ex:519: Mint.HTTP1.recv/3
2024-07-16T08:20:02.471006868Z     (ch 0.2.5) lib/ch/connection.ex:335: Ch.Connection.recv_all/3
2024-07-16T08:20:02.471010545Z     (ch 0.2.5) lib/ch/connection.ex:313: Ch.Connection.receive_full_response/2
2024-07-16T08:20:02.471016790Z     (ch 0.2.5) lib/ch/connection.ex:249: Ch.Connection.handle_execute/4
2024-07-16T08:20:02.471020537Z     (db_connection 2.6.0) lib/db_connection/holder.ex:354: DBConnection.Holder.holder_apply/4
2024-07-16T08:20:02.471024213Z     (db_connection 2.6.0) lib/db_connection.ex:1512: DBConnection.run_execute/5
2024-07-16T08:20:02.471028049Z 
2024-07-16T08:20:02.471031545Z 08:20:02.467 [error] Task #PID<0.4885.0> started from #PID<0.4875.0> terminating
2024-07-16T08:20:02.471035564Z ** (Mint.TransportError) socket closed
2024-07-16T08:20:02.471043978Z     (ecto_sql 3.11.1) lib/ecto/adapters/sql.ex:1054: Ecto.Adapters.SQL.raise_sql_call_error/1
2024-07-16T08:20:02.471047621Z     (ecto_ch 0.3.5) lib/ecto/adapters/clickhouse.ex:319: Ecto.Adapters.ClickHouse.execute/5
2024-07-16T08:20:02.471051515Z     (ecto 3.11.2) lib/ecto/repo/queryable.ex:232: Ecto.Repo.Queryable.execute/4
2024-07-16T08:20:02.471055403Z     (ecto 3.11.2) lib/ecto/repo/queryable.ex:19: Ecto.Repo.Queryable.all/3
2024-07-16T08:20:02.471059220Z     (elixir 1.16.0) lib/task/supervised.ex:101: Task.Supervised.invoke_mfa/2
2024-07-16T08:20:02.471074106Z     (elixir 1.16.0) lib/task/supervised.ex:36: Task.Supervised.reply/4
2024-07-16T08:20:02.471078070Z Function: &:erlang.apply/2
2024-07-16T08:20:02.471081681Z     Args: [#Function<0.16863069/1 in Plausible.ClickhouseRepo.parallel_tasks/2>, [#Function<5.90381287/0 in Plausible.Stats.Timeseries.timeseries/3>]]
2024-07-16T08:20:02.471086065Z 08:20:02.469 [error] Ranch protocol #PID<0.4875.0> of listener PlausibleWeb.Endpoint.HTTP (connection #PID<0.4872.0>, stream id 1) terminated
2024-07-16T08:20:02.471090162Z an exception was raised:
2024-07-16T08:20:02.471093610Z     ** (Mint.TransportError) socket closed
2024-07-16T08:20:02.471097220Z         (ecto_sql 3.11.1) lib/ecto/adapters/sql.ex:1054: Ecto.Adapters.SQL.raise_sql_call_error/1
2024-07-16T08:20:02.471100876Z         (ecto_ch 0.3.5) lib/ecto/adapters/clickhouse.ex:319: Ecto.Adapters.ClickHouse.execute/5
2024-07-16T08:20:02.471105747Z         (ecto 3.11.2) lib/ecto/repo/queryable.ex:232: Ecto.Repo.Queryable.execute/4
2024-07-16T08:20:02.471109559Z         (ecto 3.11.2) lib/ecto/repo/queryable.ex:19: Ecto.Repo.Queryable.all/3
2024-07-16T08:20:02.471113409Z         (elixir 1.16.0) lib/task/supervised.ex:101: Task.Supervised.invoke_mfa/2
2024-07-16T08:20:02.471117373Z         (elixir 1.16.0) lib/task/supervised.ex:36: Task.Supervised.reply/4
2024-07-16T08:20:02.472951588Z 08:20:02.472 [error] Ch.Connection (#PID<0.4218.0>) disconnected: ** (DBConnection.ConnectionError) client #PID<0.4878.0> timed out because it queued and checked out the connection for longer than 15000ms
2024-07-16T08:20:02.472964361Z 
2024-07-16T08:20:02.472967979Z #PID<0.4878.0> was at location:
2024-07-16T08:20:02.472971793Z 
2024-07-16T08:20:02.472975141Z     :prim_inet.recv0/3
2024-07-16T08:20:02.472978698Z     (mint 1.6.0) lib/mint/core/transport/tcp.ex:67: Mint.Core.Transport.TCP.recv/3
2024-07-16T08:20:02.472982444Z     (mint 1.6.0) lib/mint/http1.ex:519: Mint.HTTP1.recv/3
2024-07-16T08:20:02.472985984Z     (ch 0.2.5) lib/ch/connection.ex:335: Ch.Connection.recv_all/3
2024-07-16T08:20:02.472989646Z     (ch 0.2.5) lib/ch/connection.ex:313: Ch.Connection.receive_full_response/2
2024-07-16T08:20:02.472993464Z     (ch 0.2.5) lib/ch/connection.ex:249: Ch.Connection.handle_execute/4
2024-07-16T08:20:02.473005606Z     (db_connection 2.6.0) lib/db_connection/holder.ex:354: DBConnection.Holder.holder_apply/4
2024-07-16T08:20:02.473009423Z     (db_connection 2.6.0) lib/db_connection.ex:1512: DBConnection.run_execute/5
2024-07-16T08:20:02.473013019Z

Expected behavior

A successful API request as per the previous version!

Screenshots

No response

Environment

No response

Answered by ruslandoga

Sep 25, 2024

#4494 has been released in v2.1.2: #4618

To increase the task timeout value, you would need to add it in the query string to CLICKHOUSE_DATABASE_URL like in #3311 (comment)

View full answer

ruslandoga · 2024-07-16T08:34:50Z

ruslandoga
Jul 16, 2024
Collaborator

👋 @justrealmilk

Thank you for reporting this, but I think it's more of a discussion rather than an issue with the code that we could act on. So I'm moving it to discussions.

Note that:

v2.1.0 is not the latest release, so some performance problems might have been fixed in a later release
the latest release, currently v2.1.1, is not the same as master, so even more performance problems might have been fixed since then
please check that ClickHouse doesn't have too many parts and if it does then maybe try running OPTIMIZE TABLE ... FINAL command on sessions_v2 and events_v2 tables, but read these first https://clickhouse.com/docs/en/sql-reference/statements/optimize, https://clickhouse.com/docs/en/optimize/avoidoptimizefinal, https://kb.altinity.com/altinity-kb-queries-and-syntax/altinity-kb-optimize-vs-optimize-final/

29 replies

ruslandoga Aug 30, 2024
Collaborator

Whoops, sorry I forgot to report back!

They said they would prefer to keep sampling features out of CE and to instead increase timeouts (this would require a PR to make the timeouts configurable) and/or get a bigger server :)

justrealmilk Aug 30, 2024
Author

That's super disappointing and feels like they're retroactively locking out features because they feel like with a certain level of usage we should be paying. That's really bad!

When will there be a timeouts PR made and released? Is it happening soon due to the fact they broke it intentionally?

ruslandoga Aug 30, 2024
Collaborator

I'll try to fit it into #4483 tomorrow :) I think I'd just need to make

analytics/lib/plausible/clickhouse_repo.ex

Line 15 in 19ecd3d

@task_timeout 60_000

configurable or :infinity in CE.

PR: #4494

ruslandoga Sep 25, 2024
Collaborator

#4494 has been released in v2.1.2: #4618

To increase the task timeout value, you would need to add it in the query string to CLICKHOUSE_DATABASE_URL like in #3311 (comment)

Answer selected by justrealmilk

justrealmilk Sep 27, 2024
Author

in case anyone is curious on how long it takes my vm to fulfil the api requests

this is for a site with over 1 billion page views

rickytato · 2024-07-18T10:43:21Z

rickytato
Jul 18, 2024

I've downgrade to v2.0.0: #4285
I can't use v2.1.1 , I got timeout.

0 replies

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

After updating from v2, API requests time out for longer time frames #4360

{{title}}

Replies: 2 comments 29 replies

{{title}}

{{editor}}'s edit

{{editor}}'s edit

{{title}}

{{editor}}'s edit

{{editor}}'s edit

{{title}}

{{title}}

{{editor}}'s edit

{{editor}}'s edit

{{title}}

{{editor}}'s edit

{{editor}}'s edit

{{title}}

{{title}}

Select a reply

After updating from v2, API requests time out for longer time frames #4360

justrealmilk Jul 16, 2024

Past Issues Searched

Issue is a Bug Report

Using official Plausible Cloud hosting or self-hosting?

Describe the bug

Expected behavior

Screenshots

Environment

Replies: 2 comments · 29 replies

ruslandoga Jul 16, 2024 Collaborator

ruslandoga Aug 30, 2024 Collaborator

justrealmilk Aug 30, 2024 Author

ruslandoga Aug 30, 2024 Collaborator

ruslandoga Sep 25, 2024 Collaborator

justrealmilk Sep 27, 2024 Author

rickytato Jul 18, 2024

justrealmilk
Jul 16, 2024

Replies: 2 comments 29 replies

ruslandoga
Jul 16, 2024
Collaborator

ruslandoga Aug 30, 2024
Collaborator

justrealmilk Aug 30, 2024
Author

ruslandoga Aug 30, 2024
Collaborator

ruslandoga Sep 25, 2024
Collaborator

justrealmilk Sep 27, 2024
Author

rickytato
Jul 18, 2024