Reccuring Background SQL Statement times out leading to high load on postgres

[baresel]

Is there an existing issue for this?

• I have searched the existing issues

What happened?

Since some time the postgres container is running on high load (load around 4) while the car is sleeping.
Behavior was visible with postgres version 13 and is the same after upgrade to version 16.
Stopping the teslamate container reduces the load immediatly as restarting it will start the high load again.

Based on the logs the following behavior is seen:
Teslamate runs a query:

(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)

which times out after 60000 ms. After 2 seconds the query is started again.

In rare situations it seems the query can finish, then the load is reduced to a normal value for some hours but restarting again later. It looks like the problem comes up more often with the growing size of the database (DB Backup size now 3 GB)

Teslamate is running on a Raspi4 with 4 GB of RAM. There are some other containers running (iobroker) on the system. Normal load without teslamate running is around 0,25, with teslamate running and postgres high load it is running at a load around 4 all the time

Expected Behavior

Perhabs increasing the timeout for the query can help or some other optimizations to reduce the query time omn

Steps To Reproduce

No response

Relevant log output

2024-09-26 20:35:00.815 [error] Postgrex.Protocol (#PID<0.2455.0>) disconnected: ** (DBConnection.ConnectionError) client #PID<0.39063.0> timed out because it queued and checked out the connection for longer than 60000ms
#PID<0.39063.0> was at location:
    :prim_inet.recv0/3
    (postgrex 0.17.3) lib/postgrex/protocol.ex:3188: Postgrex.Protocol.msg_recv/4
    (postgrex 0.17.3) lib/postgrex/protocol.ex:2213: Postgrex.Protocol.recv_bind/3
    (postgrex 0.17.3) lib/postgrex/protocol.ex:2105: Postgrex.Protocol.bind_execute/4
    (db_connection 2.6.0) lib/db_connection/holder.ex:354: DBConnection.Holder.holder_apply/4
    (db_connection 2.6.0) lib/db_connection.ex:1512: DBConnection.run_execute/5
    (db_connection 2.6.0) lib/db_connection.ex:1607: DBConnection.run/6
    (db_connection 2.6.0) lib/db_connection.ex:743: DBConnection.parsed_prepare_execute/5
2024-09-26 20:35:00.825 [error] GenStateMachine TeslaMate.Terrain terminating
** (DBConnection.ConnectionError) tcp recv: closed (the connection was closed by the pool, possibly due to a timeout or because the pool has been terminated)
    (ecto_sql 3.10.2) lib/ecto/adapters/sql.ex:1047: Ecto.Adapters.SQL.raise_sql_call_error/1
    (ecto_sql 3.10.2) lib/ecto/adapters/sql.ex:945: Ecto.Adapters.SQL.execute/6
    (ecto 3.10.3) lib/ecto/repo/queryable.ex:229: Ecto.Repo.Queryable.execute/4
    (ecto 3.10.3) lib/ecto/repo/queryable.ex:19: Ecto.Repo.Queryable.all/3
    (teslamate 1.30.1) lib/teslamate/log.ex:197: TeslaMate.Log.get_positions_without_elevation/2
    (teslamate 1.30.1) lib/teslamate/terrain.ex:77: TeslaMate.Terrain.handle_event/4
    (stdlib 5.2.3) gen_statem.erl:1397: :gen_statem.loop_state_callback/11
    (stdlib 5.2.3) proc_lib.erl:241: :proc_lib.init_p_do_apply/3


Database Logs (same time):

2024-09-26 20:35:00.819 UTC [9696] ERROR:  canceling statement due to user request
2024-09-26 20:35:00.819 UTC [9696] 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
2024-09-26 20:35:00.819 UTC [9794] FATAL:  terminating background worker "parallel worker" due to administrator command
2024-09-26 20:35:00.819 UTC [9794] 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
2024-09-26 20:35:00.820 UTC [9795] FATAL:  terminating background worker "parallel worker" due to administrator command
2024-09-26 20:35:00.820 UTC [9795] 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
2024-09-26 20:35:00.844 UTC [1] LOG:  background worker "parallel worker" (PID 9794) exited with exit code 1
2024-09-26 20:35:00.847 UTC [1] LOG:  background worker "parallel worker" (PID 9795) exited with exit code 1

Screenshots

No response

Additional data

No response

Type of installation

Docker

Version

v1.30.1

[JakobLichterfeld]

Thanks for reporting.

May you add your steps to temporarily increased the number of parallel workers in the DB (from 2 to 4). which resulted in "the query ran through and now the load is normal"

[JakobLichterfeld]

@swiffer Do you encounter this behavior with the positions index before? Position table does have 4 years with 115.000 km logged (taken from TFF forum answer).

[baresel]

The problem is actually (temporary) solved. I stopped all other containers on the system and increased the parallel workers:

docker compose exec -T database psql -U teslamate teslamate << .
> SET max_parallel_workers_per_gather = 4;
> .

Now i changed the /var/lib/postgresql/data/postgresql.conf inside the container and set the parallel workers permanently from 2 to 4:

# - Asynchronous Behavior -

#backend_flush_after = 0                # measured in pages, 0 disables
#effective_io_concurrency = 1           # 1-1000; 0 disables prefetching
#maintenance_io_concurrency = 10        # 1-1000; 0 disables prefetching
#max_worker_processes = 8               # (change requires restart)
max_parallel_workers_per_gather = 4     # limited by max_parallel_workers
max_parallel_maintenance_workers = 4    # limited by max_parallel_workers
#max_parallel_workers = 8               # number of max_worker_processes that
                                        # can be used in parallel operations

[baresel]

The behavior was seen before (as already described in the original post), but the query was able to finish after some time.
I checked today, i have 21 Mio rows in the positions table.

[baresel]

I did some more investigation. The query is issued shortly after restarting teslamate and it is also timing out several times with 4 parallel workers. I "fixed" it again with stopping all other containers on the same raspi.

[swiffer]

@baresel - if you have the chance to log the query (incl. parameters instead of $1, $2, $3) that would be very useful.

if i understood the code correctly teslamate tries to set elevation for all positions of drives not recorded via streaming api.

also could you list the indexes you currently have on the positions table?

thanks!

[baresel]

The problem reoccured today starting at 19:32, without restarting teslamate, so i assume its a scheduled job within teslamate.

I changed the logging settings and was able to collect a log, which is attached.

This seems to be the problematic query and there are also the variables:
postgresql-2024-09-27_181806.log

2024-09-27 18:19:06.504 UTC [43] LOG:  execute ecto_547: 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
2024-09-27 18:19:06.504 UTC [43] DETAIL:  parameters: $1 = '0', $2 = '{2,3,4,5,6,8,9,10,12,30,32,33,50,124,138,149,155,163,171,172,188,197,217,219,220,223,226,227,233,234,235,237,238,245,246,247,267,268,270,271,285,296,297,300,301,304,306,307,323,326,333,345,346,347,354,358,378,394,395,402,409,468,469,472,477,478,482,484,491,498,500,501,504,507,517,521,526,532,542,549,550,560,563,564,566,569,575,585,599,600,603,619,620,638,652,665,672,680,694,695,708,710,718,719,720,733,735,742,754,786,788,789,796,812,853,859,884,893,899,904,917,919,920,922,941,949,952,964,965,966,967,968,969,970,984,998,1007,1009,1158,1159,1230,1232,1250,1307,1420,1421,1444,1485,1486,1487,1488,1489,1490,1491,1492,1493,1494,1495,1496,1497,1498,1499,1500,1501,1502,1503,1504,1505,1506,1507,1508,1509,1510,1511,1512,1513,1514,1515,1516,1517,1518,1519,1520,1521,1522,1523,1524,1525,1526,1527,1528,1529,1530,1531,1532,1590,1845,1896,1898,1899,1924,1927,1949,2379,2698,2765,2771,2875,3286,3349,3793,3827,3971,4007,4021,4099,4109,4130,4193,4194,4238,4239,4240,4306,4324,4533,4534,4839,4840,4841,4945,4962,5328,6462,6653,6673,6936,6937,7107,7518,7595,7596,7745,7764,8378,8379,8380,8696,8755,8945,8946,8957,9111,9112,9240}', $3 = '1000'

The Indexes are:

docker compose exec -T database psql -U teslamate teslamate << .
> select * from pg_indexes where tablename = 'positions'
> .
 schemaname | tablename |           indexname           | tablespace |                                          indexdef                          
------------+-----------+-------------------------------+------------+---------------------------------------------------------------------------------------------
 public     | positions | positions_pkey                |            | CREATE UNIQUE INDEX positions_pkey ON public.positions USING btree (id)
 public     | positions | positions_car_id_index        |            | CREATE INDEX positions_car_id_index ON public.positions USING btree (car_id)
 public     | positions | positions_date_index          |            | CREATE INDEX positions_date_index ON public.positions USING btree (date)
 public     | positions | positions_drive_id_date_index |            | CREATE INDEX positions_drive_id_date_index ON public.positions USING btree (drive_id, date)
(4 rows)

[baresel]

Thats the behavior if 4 parallel workers are running ... the load is up to 6, but the query is timing out all the time until i stop all other applications on the raspi.

top - 20:37:44 up 2 days, 12:19,  2 users,  load average: 6.17, 5.98, 5.69
Tasks: 212 total,   1 running, 211 sleeping,   0 stopped,   0 zombie
%Cpu(s): 24.2 us,  7.7 sy,  0.0 ni,  9.9 id, 57.9 wa,  0.0 hi,  0.3 si,  0.0 st
MiB Mem :   3794.3 total,     61.4 free,   1211.8 used,   2521.1 buff/cache
MiB Swap:    100.0 total,     97.5 free,      2.5 used.   2372.7 avail Mem

  PID USER      PR  NI    VIRT    RES    SHR S  %CPU  %MEM     TIME+ COMMAND
 1440 999       20   0  330920  66728  55180 D  21.6   1.7   0:01.24 postgres
 1439 999       20   0  330928  66748  55196 D  20.3   1.7   0:01.19 postgres
  827 999       20   0  331196  66296  54416 D  19.3   1.7   0:01.29 postgres
 1442 999       20   0  330892  67680  56132 D  18.9   1.7   0:01.15 postgres
 1441 999       20   0  330928  67688  56140 D  17.6   1.7   0:01.11 postgres

[swiffer]

Thanks, will have a look tomorrow

[swiffer]

So with introduction of Streaming API positions table row count is growing way faster (has been noted back in 2020 here: #417 (comment)) than before. this will result in increased compute / storage requirements long term as we are seeing in dashboards (where additional indexes / rewritten queries have helped) as well as in issues like this one.

@JakobLichterfeld - We might need to consider further improving index usage / rewrite queries / evaluate usage of timescaledb / partitioning the positions table or other solutions but this might best be discussed & explored in a different thread or on call before kicking of exploration.

Back to the Issue - running an explain analyze on the query I see 80ms exec time here (4mio rows).

While the following index would help /speed up executing the query currently timing out i think there is a non-optimal two step query processing in get_positions_without_elevation that is causing unneccessary stress on the database:

create index temp_elevation_index on positions (id, drive_id, (elevation is null)) where (elevation is null);

it currently is quite expensive to fetch positions of non streamed drives not having elevation. not really sure why the decision has been taken to only add elevation to non streamed drives back then:

a691784#diff-631119271d8b463261e34a8dd6a9dd1138383d79b8d0fe920c40a7bc0a708234

In addition Teslamate does not remember when elevation for non-streamed drives has been set successfully and runs these queries every 6 hours without limiting the positions via primary_pkey or date filter.

teslamate/lib/teslamate/terrain.ex

Line 189 in 6871ef7

{:state_timeout, :timer.hours(6), {:fetch_positions, 0}}

IMHO we should not add an additional index but instead rework the elixir code setting the elevation. as the code is executed every 6 hours why not limit the positions that are checked to a month or even less? if elevation could not been set for whatever reason for data older than a month why should we keep trying?

-> opened PR #4228

[JakobLichterfeld]

IMHO we should not add an additional index but instead rework the elixir code setting the elevation. as the code is executed every 6 hours why not limit the positions that are checked to a month or even less? if elevation could not been set for whatever reason for data older than a month why should we keep trying?

Total agree.

Thank you very much for your quick investigation!