Postgres using full CPU and database+teslamate indicating issues on a query

[matmly24]

Hi,

Using teslamate for the last 2 years for my tesla (with 60 000 km now), I recently noticed a permanent usage of postgres instances using the utility top. Teslamate is running in docker on a Raspberry Pi running Debian version 11.9 (/etc/debian_version).

Docker is up-to-date and I did this evening a full backup (backup file is 1,3 GB), full teslamate uninstall from docker, full reinstall, reimport the backup (took around 1 hour) and seems to run well again - but still with high CPU usage from postgres.

With "docker compose up" (without detach), I see around every 2 minutes the following messages.

What do you think is generating such load and errors ?

Thank you for your answers.

database-1 | 2024-06-08 22:34:47.194 UTC [207] ERROR: canceling statement due to user request
database-1 | 2024-06-08 22:34:47.194 UTC [207] STATEMENT: SELECT p0."id", p0."date", p0."latitude", p0."longitude", p0."elevation", p0."speed", p0."power", p0."odometer", p0."ideal_battery_range_km", p0."est_battery_range_km", p0."rated_battery_range_km", p0."battery_level", p0."usable_battery_level", p0."battery_heater", p0."battery_heater_on", p0."battery_heater_no_power", p0."outside_temp", p0."inside_temp", p0."fan_status", p0."driver_temp_setting", p0."passenger_temp_setting", p0."is_climate_on", p0."is_rear_defroster_on", p0."is_front_defroster_on", p0."tpms_pressure_fl", p0."tpms_pressure_fr", p0."tpms_pressure_rl", p0."tpms_pressure_rr", p0."car_id", p0."drive_id" FROM "positions" AS p0 WHERE (((p0."id" > $1) AND (p0."elevation" IS NULL)) AND p0."drive_id" = ANY($2)) ORDER BY p0."id" LIMIT $3
teslamate-1 | 2024-06-08 22:34:46.764 [error] Postgrex.Protocol (#PID<0.2448.0>) disconnected: ** (DBConnection.ConnectionError) client #PID<0.2769.0> timed out because it queued and checked out the connection for longer than 60000ms
database-1 | 2024-06-08 22:34:47.346 UTC [256] FATAL: terminating background worker "parallel worker" due to administrator command
teslamate-1 |
teslamate-1 | #PID<0.2769.0> was at location:
database-1 | 2024-06-08 22:34:47.346 UTC [256] STATEMENT: SELECT p0."id", p0."date", p0."latitude", p0."longitude", p0."elevation", p0."speed", p0."power", p0."odometer", p0."ideal_battery_range_km", p0."est_battery_range_km", p0."rated_battery_range_km", p0."battery_level", p0."usable_battery_level", p0."battery_heater", p0."battery_heater_on", p0."battery_heater_no_power", p0."outside_temp", p0."inside_temp", p0."fan_status", p0."driver_temp_setting", p0."passenger_temp_setting", p0."is_climate_on", p0."is_rear_defroster_on", p0."is_front_defroster_on", p0."tpms_pressure_fl", p0."tpms_pressure_fr", p0."tpms_pressure_rl", p0."tpms_pressure_rr", p0."car_id", p0."drive_id" FROM "positions" AS p0 WHERE (((p0."id" > $1) AND (p0."elevation" IS NULL)) AND p0."drive_id" = ANY($2)) ORDER BY p0."id" LIMIT $3
teslamate-1 |
database-1 | 2024-06-08 22:34:47.345 UTC [255] FATAL: terminating background worker "parallel worker" due to administrator command
database-1 | 2024-06-08 22:34:47.345 UTC [255] STATEMENT: SELECT p0."id", p0."date", p0."latitude", p0."longitude", p0."elevation", p0."speed", p0."power", p0."odometer", p0."ideal_battery_range_km", p0."est_battery_range_km", p0."rated_battery_range_km", p0."battery_level", p0."usable_battery_level", p0."battery_heater", p0."battery_heater_on", p0."battery_heater_no_power", p0."outside_temp", p0."inside_temp", p0."fan_status", p0."driver_temp_setting", p0."passenger_temp_setting", p0."is_climate_on", p0."is_rear_defroster_on", p0."is_front_defroster_on", p0."tpms_pressure_fl", p0."tpms_pressure_fr", p0."tpms_pressure_rl", p0."tpms_pressure_rr", p0."car_id", p0."drive_id" FROM "positions" AS p0 WHERE (((p0."id" > $1) AND (p0."elevation" IS NULL)) AND p0."drive_id" = ANY($2)) ORDER BY p0."id" LIMIT $3
teslamate-1 | :prim_inet.recv0/3
teslamate-1 | (postgrex 0.17.3) lib/postgrex/protocol.ex:3188: Postgrex.Protocol.msg_recv/4
teslamate-1 | (postgrex 0.17.3) lib/postgrex/protocol.ex:2213: Postgrex.Protocol.recv_bind/3
database-1 | 2024-06-08 22:34:47.442 UTC [1] LOG: background worker "parallel worker" (PID 255) exited with exit code 1
teslamate-1 | (postgrex 0.17.3) lib/postgrex/protocol.ex:2105: Postgrex.Protocol.bind_execute/4
database-1 | 2024-06-08 22:34:47.443 UTC [1] LOG: background worker "parallel worker" (PID 256) exited with exit code 1
teslamate-1 | (db_connection 2.6.0) lib/db_connection/holder.ex:354: DBConnection.Holder.holder_apply/4
database-1 | 2024-06-08 22:34:47.444 UTC [207] LOG: could not send data to client: Broken pipe
teslamate-1 | (db_connection 2.6.0) lib/db_connection.ex:1512: DBConnection.run_execute/5
database-1 | 2024-06-08 22:34:47.444 UTC [207] FATAL: connection to client lost
teslamate-1 | (db_connection 2.6.0) lib/db_connection.ex:1607: DBConnection.run/6
teslamate-1 | (db_connection 2.6.0) lib/db_connection.ex:743: DBConnection.parsed_prepare_execute/5
teslamate-1 |
teslamate-1 | 2024-06-08 22:34:47.188 [error] GenStateMachine TeslaMate.Terrain terminating
teslamate-1 | ** (DBConnection.ConnectionError) tcp recv: closed (the connection was closed by the pool, possibly due to a timeout or because the pool has been terminated)
teslamate-1 | (ecto_sql 3.10.2) lib/ecto/adapters/sql.ex:1047: Ecto.Adapters.SQL.raise_sql_call_error/1
teslamate-1 | (ecto_sql 3.10.2) lib/ecto/adapters/sql.ex:945: Ecto.Adapters.SQL.execute/6
teslamate-1 | (ecto 3.10.3) lib/ecto/repo/queryable.ex:229: Ecto.Repo.Queryable.execute/4
teslamate-1 | (ecto 3.10.3) lib/ecto/repo/queryable.ex:19: Ecto.Repo.Queryable.all/3
teslamate-1 | (teslamate 1.29.1) lib/teslamate/log.ex:197: TeslaMate.Log.get_positions_without_elevation/2
teslamate-1 | (teslamate 1.29.1) lib/teslamate/terrain.ex:77: TeslaMate.Terrain.handle_event/4
teslamate-1 | (stdlib 5.2) gen_statem.erl:1397: :gen_statem.loop_state_callback/11
teslamate-1 | (stdlib 5.2) proc_lib.erl:241: :proc_lib.init_p_do_apply/3
teslamate-1 | 2024-06-08 22:36:38.623 [error] Postgrex.Protocol (#PID<0.2445.0>) disconnected: ** (DBConnection.ConnectionError) client #PID<0.2775.0> timed out because it queued and checked out the connection for longer than 60000ms
teslamate-1 |
teslamate-1 | #PID<0.2775.0> was at location:
teslamate-1 |
teslamate-1 | :prim_inet.recv0/3
teslamate-1 | (postgrex 0.17.3) lib/postgrex/protocol.ex:3188: Postgrex.Protocol.msg_recv/4
teslamate-1 | (postgrex 0.17.3) lib/postgrex/protocol.ex:2213: Postgrex.Protocol.recv_bind/3
teslamate-1 | (postgrex 0.17.3) lib/postgrex/protocol.ex:2105: Postgrex.Protocol.bind_execute/4
teslamate-1 | (db_connection 2.6.0) lib/db_connection/holder.ex:354: DBConnection.Holder.holder_apply/4
teslamate-1 | (db_connection 2.6.0) lib/db_connection.ex:1512: DBConnection.run_execute/5
teslamate-1 | (db_connection 2.6.0) lib/db_connection.ex:1607: DBConnection.run/6
teslamate-1 | (db_connection 2.6.0) lib/db_connection.ex:743: DBConnection.parsed_prepare_execute/5
teslamate-1 |

[matmly24]

Hi,
If anybody else get the same issue, this is a description of what I performed to correct it.

For information, I have more than 9M of rows in the positions table (60 000 km driving on 2 years) and run Teslamate on a Raspberry Pi 2 Model B with 1 GB RAM (and quadcore 900 MHz) rolled out in 02/2015 (quite old now).

With the "top" and "iotop" utilities, I saw the heavy CPU load and IO usage (15 to 20 MB permanent).

Using SELECT * FROM pg_stat_activity WHERE datname='teslamate' AND STATE='active';
I see that the following query executed by teslamate take a very long time exceeding the 60 s database timeout of Teslamate.

SELECT p0."id", p0."date", p0."latitude", p0."longitude", p0."elevation", p0."speed", p0."power", p0."odometer", p0."ideal_battery_range_km", p0."est_battery_range_km", p0."rated_battery_range_km", p0."battery_level", p0."usable_battery_level", p0."battery_heater", p0."battery_heater_on", p0."battery_heater_no_power", p0."outside_temp", p0."inside_temp", p0."fan_status", p0."driver_temp_setting", p0."passenger_temp_setting", p0."is_climate_on", p0."is_rear_defroster_on", p0."is_front_defroster_on", p0."tpms_pressure_fl", p0."tpms_pressure_fr", p0."tpms_pressure_rl", p0."tpms_pressure_rr", p0."car_id", p0."drive_id" FROM "positions" AS p0 WHERE (((p0."id" > $1) AND (p0."elevation" IS NULL)) AND p0."drive_id" = ANY($2)) ORDER BY p0."id" LIMIT $3

By changing the DATABASE_TIMEOUT environment variable of Teslamate to 120000 ms (instead of default value of 60000 ms), the query is now fully executed (probably requiring after so much positions a little bit more than 60 s to execute now) and the CPU load of the Raspberry is back to normal (close to zero instead of 4 ou 5 probably because teslamate was restarting the query in loop again and again after the 60 s expiration).

If anybody find a way to reduce the time by optimizing the request...

[brianmay]

Something seems really wrong if it takes over 60s to run that query. e.g. lack of correct indexing.

Wonder what that LIMIT value is. If it is excessive that could explain it also. Wonder where the query comes from in Teslamate.

In general, if you prefix the command with EXPLAIN, it should tell you more about the query, e.g.:

EXPLAIN SELECT p0."id", p0."date", p0."latitude", p0."longitude", p0."elevation", p0."speed", p0."power", p0."odometer", p0."ideal_battery_range_km", p0."est_battery_range_km", p0."rated_battery_range_km", p0."battery_level", p0."usable_battery_level", p0."battery_heater", p0."battery_heater_on", p0."battery_heater_no_power", p0."outside_temp", p0."inside_temp", p0."fan_status", p0."driver_temp_setting", p0."passenger_temp_setting", p0."is_climate_on", p0."is_rear_defroster_on", p0."is_front_defroster_on", p0."tpms_pressure_fl", p0."tpms_pressure_fr", p0."tpms_pressure_rl", p0."tpms_pressure_rr", p0."car_id", p0."drive_id" FROM "positions" AS p0 WHERE (((p0."id" > $1) AND (p0."elevation" IS NULL)) AND p0."drive_id" = ANY($2)) ORDER BY p0."id" LIMIT $3

[adjego]

I have simular issues with Teslamate with data for many years. When i for example are in the "trips" view, and i want to see a full year, the load index goes way up, and the Raspberry pi 4 with 4 GB (256 GB SSD) i'm running it on starts to be very very slow. Most of the time most fields are not even filled with data due to grafana timeouts.

EDIT: I see this same query fail with the same error!

[matmly24]

@brianmay Thank you for your answer. I don't manage to use the EXPLAIN query because the $1, $2 or $3 values are not defined. Maybe a prepared or stored query (as with MySQL) ?