What type of bug is this?

Performance issue

What subsystems and features are affected?

Compression

What happened?

I have very recently updated our self-hosted TimescaleDB running on Postgres 13.11 from 2.9.0 to 2.11.1.

I noticed right after the hypertable compression policy started running that chunk compression on TimescaleDB 2.11.1 is very slow compared to chunk compression on TimescaleDB 2.9.0.

Setup:

Compression policy is set to run every day
Chunk size is set to 1 hour
Chunk size in GB: 18.16GB

Findings from Postgres logs provided below

On TimescaleDB 2.9.0, one chunk compression used to take about 7 minutes when looking at the timestamps between two consecutive CALL _timescaledb_internal.policy_compression_execute but on Timescale DB 2.11.1 one chunk compression is taking around 32 minutes when looking at the timestamps between two consecutive CALL _timescaledb_internal.policy_compression_execute.
- This is about 5x performance degradation on chunk compression

I also have provided a screenshot of our TimescaleDB data disk usage in the last 4 days

Notes:
- Continuous decrease in disk_used_percent means compression policy is running
- On TimescaleDB 2.9.0 the compression of chunks for 1 day used to take about 2 hours (07/25, 07/26 UTC)
- On TimescaleDB 2.11.1 the compression of chunks for 1 day has been running for 14 hours and has not even finished yet as you can see in the last few hours of the chart (07/28 UTC)

Please let me know if there is any other information I can provide from my end. Also advice if there is any workaround for this issue.

TimescaleDB version affected

2.11.1

PostgreSQL version used

13.11

What operating system did you use?

Ubuntu 22.04.2 LTS (GNU/Linux 5.19.0-1029-aws x86_64)

What installation method did you use?

Deb/Apt

What platform did you run on?

On prem/Self-hosted

Relevant log output and stack trace

On TimescaleDB 2.9.0, timestamp range for two consecutive calls: 13:21:13 to 13:27:04. This means that compression of one chunk took about 6 minutes.

Jul 25 13:21:13 ip-10-100-3-83 postgres[18089]: [52293-3] #011PL/pgSQL function _timescaledb_internal.policy_compression_execute(integer,integer,anyelement,integer,boolean,boolean) line 38 at PERFORM
Jul 25 13:21:13 ip-10-100-3-83 postgres[18089]: [52293-4] #011SQL statement "CALL _timescaledb_internal.policy_compression_execute(
Jul 25 13:21:13 ip-10-100-3-83 postgres[18089]: [52293-8] #011PL/pgSQL function _timescaledb_internal.policy_compression(integer,jsonb) line 51 at CALL
Jul 25 13:21:13 ip-10-100-3-83 postgres[18089]: [52294-3] #011PL/pgSQL function _timescaledb_internal.policy_compression_execute(integer,integer,anyelement,integer,boolean,boolean) line 38 at PERFORM
Jul 25 13:21:13 ip-10-100-3-83 postgres[18089]: [52294-4] #011SQL statement "CALL _timescaledb_internal.policy_compression_execute(
Jul 25 13:21:13 ip-10-100-3-83 postgres[18089]: [52294-8] #011PL/pgSQL function _timescaledb_internal.policy_compression(integer,jsonb) line 51 at CALL
Jul 25 13:21:13 ip-10-100-3-83 postgres[18089]: [52295-3] #011PL/pgSQL function _timescaledb_internal.policy_compression_execute(integer,integer,anyelement,integer,boolean,boolean) line 38 at PERFORM
Jul 25 13:21:13 ip-10-100-3-83 postgres[18089]: [52295-4] #011SQL statement "CALL _timescaledb_internal.policy_compression_execute(
Jul 25 13:21:13 ip-10-100-3-83 postgres[18089]: [52295-8] #011PL/pgSQL function _timescaledb_internal.policy_compression(integer,jsonb) line 51 at CALL
Jul 25 13:21:13 ip-10-100-3-83 postgres[18089]: [52296-3] #011PL/pgSQL function _timescaledb_internal.policy_compression_execute(integer,integer,anyelement,integer,boolean,boolean) line 38 at PERFORM
Jul 25 13:21:13 ip-10-100-3-83 postgres[18089]: [52296-4] #011SQL statement "CALL _timescaledb_internal.policy_compression_execute(
Jul 25 13:21:13 ip-10-100-3-83 postgres[18089]: [52296-8] #011PL/pgSQL function _timescaledb_internal.policy_compression(integer,jsonb) line 51 at CALL
Jul 25 13:21:13 ip-10-100-3-83 postgres[18089]: [52297-3] #011PL/pgSQL function _timescaledb_internal.policy_compression_execute(integer,integer,anyelement,integer,boolean,boolean) line 38 at PERFORM
Jul 25 13:21:13 ip-10-100-3-83 postgres[18089]: [52297-4] #011SQL statement "CALL _timescaledb_internal.policy_compression_execute(
Jul 25 13:21:13 ip-10-100-3-83 postgres[18089]: [52297-8] #011PL/pgSQL function _timescaledb_internal.policy_compression(integer,jsonb) line 51 at CALL
Jul 25 13:21:13 ip-10-100-3-83 postgres[18089]: [52298-3] #011PL/pgSQL function _timescaledb_internal.policy_compression_execute(integer,integer,anyelement,integer,boolean,boolean) line 38 at PERFORM
Jul 25 13:21:13 ip-10-100-3-83 postgres[18089]: [52298-4] #011SQL statement "CALL _timescaledb_internal.policy_compression_execute(
Jul 25 13:21:13 ip-10-100-3-83 postgres[18089]: [52298-8] #011PL/pgSQL function _timescaledb_internal.policy_compression(integer,jsonb) line 51 at CALL
Jul 25 13:21:13 ip-10-100-3-83 postgres[18089]: [52299-3] #011PL/pgSQL function _timescaledb_internal.policy_compression_execute(integer,integer,anyelement,integer,boolean,boolean) line 38 at PERFORM
Jul 25 13:21:13 ip-10-100-3-83 postgres[18089]: [52299-4] #011SQL statement "CALL _timescaledb_internal.policy_compression_execute(
Jul 25 13:21:13 ip-10-100-3-83 postgres[18089]: [52299-8] #011PL/pgSQL function _timescaledb_internal.policy_compression(integer,jsonb) line 51 at CALL
Jul 25 13:21:13 ip-10-100-3-83 postgres[18089]: [52300-3] #011PL/pgSQL function _timescaledb_internal.policy_compression_execute(integer,integer,anyelement,integer,boolean,boolean) line 38 at PERFORM
Jul 25 13:21:13 ip-10-100-3-83 postgres[18089]: [52300-4] #011SQL statement "CALL _timescaledb_internal.policy_compression_execute(
Jul 25 13:21:13 ip-10-100-3-83 postgres[18089]: [52300-8] #011PL/pgSQL function _timescaledb_internal.policy_compression(integer,jsonb) line 51 at CALL
Jul 25 13:21:13 ip-10-100-3-83 postgres[18089]: [52301-3] #011PL/pgSQL function _timescaledb_internal.policy_compression_execute(integer,integer,anyelement,integer,boolean,boolean) line 38 at PERFORM
Jul 25 13:21:13 ip-10-100-3-83 postgres[18089]: [52301-4] #011SQL statement "CALL _timescaledb_internal.policy_compression_execute(
Jul 25 13:21:13 ip-10-100-3-83 postgres[18089]: [52301-8] #011PL/pgSQL function _timescaledb_internal.policy_compression(integer,jsonb) line 51 at CALL
Jul 25 13:21:13 ip-10-100-3-83 postgres[18089]: [52302-3] #011PL/pgSQL function _timescaledb_internal.policy_compression_execute(integer,integer,anyelement,integer,boolean,boolean) line 38 at PERFORM
Jul 25 13:21:13 ip-10-100-3-83 postgres[18089]: [52302-4] #011SQL statement "CALL _timescaledb_internal.policy_compression_execute(
Jul 25 13:21:13 ip-10-100-3-83 postgres[18089]: [52302-8] #011PL/pgSQL function _timescaledb_internal.policy_compression(integer,jsonb) line 51 at CALL
Jul 25 13:21:14 ip-10-100-3-83 postgres[18089]: [52303-3] #011PL/pgSQL function _timescaledb_internal.policy_compression_execute(integer,integer,anyelement,integer,boolean,boolean) line 38 at PERFORM
Jul 25 13:21:14 ip-10-100-3-83 postgres[18089]: [52303-4] #011SQL statement "CALL _timescaledb_internal.policy_compression_execute(
Jul 25 13:21:14 ip-10-100-3-83 postgres[18089]: [52303-8] #011PL/pgSQL function _timescaledb_internal.policy_compression(integer,jsonb) line 51 at CALL
Jul 25 13:21:14 ip-10-100-3-83 postgres[18089]: [52304-6] #011PL/pgSQL function _timescaledb_internal.policy_compression_execute(integer,integer,anyelement,integer,boolean,boolean) line 38 at PERFORM
Jul 25 13:21:14 ip-10-100-3-83 postgres[18089]: [52304-7] #011SQL statement "CALL _timescaledb_internal.policy_compression_execute(
Jul 25 13:21:14 ip-10-100-3-83 postgres[18089]: [52304-11] #011PL/pgSQL function _timescaledb_internal.policy_compression(integer,jsonb) line 51 at CALL
Jul 25 13:21:14 ip-10-100-3-83 postgres[18089]: [52305-3] #011PL/pgSQL function _timescaledb_internal.policy_compression_execute(integer,integer,anyelement,integer,boolean,boolean) line 38 at PERFORM
Jul 25 13:21:14 ip-10-100-3-83 postgres[18089]: [52305-4] #011SQL statement "CALL _timescaledb_internal.policy_compression_execute(
Jul 25 13:21:14 ip-10-100-3-83 postgres[18089]: [52305-8] #011PL/pgSQL function _timescaledb_internal.policy_compression(integer,jsonb) line 51 at CALL
Jul 25 13:21:14 ip-10-100-3-83 postgres[18089]: [52306-3] #011PL/pgSQL function _timescaledb_internal.policy_compression_execute(integer,integer,anyelement,integer,boolean,boolean) line 38 at PERFORM
Jul 25 13:21:14 ip-10-100-3-83 postgres[18089]: [52306-4] #011SQL statement "CALL _timescaledb_internal.policy_compression_execute(
Jul 25 13:21:14 ip-10-100-3-83 postgres[18089]: [52306-8] #011PL/pgSQL function _timescaledb_internal.policy_compression(integer,jsonb) line 51 at CALL
Jul 25 13:21:14 ip-10-100-3-83 postgres[18089]: [52307-3] #011PL/pgSQL function _timescaledb_internal.policy_compression_execute(integer,integer,anyelement,integer,boolean,boolean) line 38 at PERFORM
Jul 25 13:21:14 ip-10-100-3-83 postgres[18089]: [52307-4] #011SQL statement "CALL _timescaledb_internal.policy_compression_execute(
Jul 25 13:21:14 ip-10-100-3-83 postgres[18089]: [52307-8] #011PL/pgSQL function _timescaledb_internal.policy_compression(integer,jsonb) line 51 at CALL
Jul 25 13:21:14 ip-10-100-3-83 postgres[18089]: [52308-3] #011PL/pgSQL function _timescaledb_internal.policy_compression_execute(integer,integer,anyelement,integer,boolean,boolean) line 38 at PERFORM
Jul 25 13:21:14 ip-10-100-3-83 postgres[18089]: [52308-4] #011SQL statement "CALL _timescaledb_internal.policy_compression_execute(
Jul 25 13:21:14 ip-10-100-3-83 postgres[18089]: [52308-8] #011PL/pgSQL function _timescaledb_internal.policy_compression(integer,jsonb) line 51 at CALL
Jul 25 13:21:14 ip-10-100-3-83 postgres[18089]: [52309-3] #011PL/pgSQL function _timescaledb_internal.policy_compression_execute(integer,integer,anyelement,integer,boolean,boolean) line 38 at PERFORM
Jul 25 13:21:14 ip-10-100-3-83 postgres[18089]: [52309-4] #011SQL statement "CALL _timescaledb_internal.policy_compression_execute(
Jul 25 13:21:14 ip-10-100-3-83 postgres[18089]: [52309-8] #011PL/pgSQL function _timescaledb_internal.policy_compression(integer,jsonb) line 51 at CALL
Jul 25 13:27:03 ip-10-100-3-83 postgres[18089]: [52310-3] #011PL/pgSQL function _timescaledb_internal.policy_compression_execute(integer,integer,anyelement,integer,boolean,boolean) line 38 at PERFORM
Jul 25 13:27:03 ip-10-100-3-83 postgres[18089]: [52310-4] #011SQL statement "CALL _timescaledb_internal.policy_compression_execute(
Jul 25 13:27:03 ip-10-100-3-83 postgres[18089]: [52310-8] #011PL/pgSQL function _timescaledb_internal.policy_compression(integer,jsonb) line 51 at CALL
Jul 25 13:27:03 ip-10-100-3-83 postgres[18089]: [52311-3] #011PL/pgSQL function _timescaledb_internal.policy_compression_execute(integer,integer,anyelement,integer,boolean,boolean) line 38 at PERFORM
Jul 25 13:27:03 ip-10-100-3-83 postgres[18089]: [52311-4] #011SQL statement "CALL _timescaledb_internal.policy_compression_execute(
Jul 25 13:27:03 ip-10-100-3-83 postgres[18089]: [52311-8] #011PL/pgSQL function _timescaledb_internal.policy_compression(integer,jsonb) line 51 at CALL
Jul 25 13:27:03 ip-10-100-3-83 postgres[18089]: [52312-3] #011PL/pgSQL function _timescaledb_internal.policy_compression_execute(integer,integer,anyelement,integer,boolean,boolean) line 38 at PERFORM
Jul 25 13:27:03 ip-10-100-3-83 postgres[18089]: [52312-4] #011SQL statement "CALL _timescaledb_internal.policy_compression_execute(
Jul 25 13:27:03 ip-10-100-3-83 postgres[18089]: [52312-8] #011PL/pgSQL function _timescaledb_internal.policy_compression(integer,jsonb) line 51 at CALL
Jul 25 13:27:03 ip-10-100-3-83 postgres[18089]: [52313-3] #011PL/pgSQL function _timescaledb_internal.policy_compression_execute(integer,integer,anyelement,integer,boolean,boolean) line 38 at PERFORM
Jul 25 13:27:03 ip-10-100-3-83 postgres[18089]: [52313-4] #011SQL statement "CALL _timescaledb_internal.policy_compression_execute(
Jul 25 13:27:03 ip-10-100-3-83 postgres[18089]: [52313-8] #011PL/pgSQL function _timescaledb_internal.policy_compression(integer,jsonb) line 51 at CALL
Jul 25 13:27:03 ip-10-100-3-83 postgres[18089]: [52314-3] #011PL/pgSQL function _timescaledb_internal.policy_compression_execute(integer,integer,anyelement,integer,boolean,boolean) line 38 at PERFORM
Jul 25 13:27:03 ip-10-100-3-83 postgres[18089]: [52314-4] #011SQL statement "CALL _timescaledb_internal.policy_compression_execute(
Jul 25 13:27:03 ip-10-100-3-83 postgres[18089]: [52314-8] #011PL/pgSQL function _timescaledb_internal.policy_compression(integer,jsonb) line 51 at CALL
Jul 25 13:27:03 ip-10-100-3-83 postgres[18089]: [52315-3] #011PL/pgSQL function _timescaledb_internal.policy_compression_execute(integer,integer,anyelement,integer,boolean,boolean) line 38 at PERFORM
Jul 25 13:27:03 ip-10-100-3-83 postgres[18089]: [52315-4] #011SQL statement "CALL _timescaledb_internal.policy_compression_execute(
Jul 25 13:27:03 ip-10-100-3-83 postgres[18089]: [52315-8] #011PL/pgSQL function _timescaledb_internal.policy_compression(integer,jsonb) line 51 at CALL
Jul 25 13:27:03 ip-10-100-3-83 postgres[18089]: [52316-3] #011PL/pgSQL function _timescaledb_internal.policy_compression_execute(integer,integer,anyelement,integer,boolean,boolean) line 38 at PERFORM
Jul 25 13:27:03 ip-10-100-3-83 postgres[18089]: [52316-4] #011SQL statement "CALL _timescaledb_internal.policy_compression_execute(
Jul 25 13:27:03 ip-10-100-3-83 postgres[18089]: [52316-8] #011PL/pgSQL function _timescaledb_internal.policy_compression(integer,jsonb) line 51 at CALL
Jul 25 13:27:03 ip-10-100-3-83 postgres[18089]: [52317-3] #011PL/pgSQL function _timescaledb_internal.policy_compression_execute(integer,integer,anyelement,integer,boolean,boolean) line 38 at PERFORM
Jul 25 13:27:03 ip-10-100-3-83 postgres[18089]: [52317-4] #011SQL statement "CALL _timescaledb_internal.policy_compression_execute(
Jul 25 13:27:03 ip-10-100-3-83 postgres[18089]: [52317-8] #011PL/pgSQL function _timescaledb_internal.policy_compression(integer,jsonb) line 51 at CALL
Jul 25 13:27:03 ip-10-100-3-83 postgres[18089]: [52318-3] #011PL/pgSQL function _timescaledb_internal.policy_compression_execute(integer,integer,anyelement,integer,boolean,boolean) line 38 at PERFORM
Jul 25 13:27:03 ip-10-100-3-83 postgres[18089]: [52318-4] #011SQL statement "CALL _timescaledb_internal.policy_compression_execute(
Jul 25 13:27:03 ip-10-100-3-83 postgres[18089]: [52318-8] #011PL/pgSQL function _timescaledb_internal.policy_compression(integer,jsonb) line 51 at CALL
Jul 25 13:27:03 ip-10-100-3-83 postgres[18089]: [52319-3] #011PL/pgSQL function _timescaledb_internal.policy_compression_execute(integer,integer,anyelement,integer,boolean,boolean) line 38 at PERFORM
Jul 25 13:27:03 ip-10-100-3-83 postgres[18089]: [52319-4] #011SQL statement "CALL _timescaledb_internal.policy_compression_execute(
Jul 25 13:27:03 ip-10-100-3-83 postgres[18089]: [52319-8] #011PL/pgSQL function _timescaledb_internal.policy_compression(integer,jsonb) line 51 at CALL
Jul 25 13:27:04 ip-10-100-3-83 postgres[18089]: [52320-3] #011PL/pgSQL function _timescaledb_internal.policy_compression_execute(integer,integer,anyelement,integer,boolean,boolean) line 38 at PERFORM
Jul 25 13:27:04 ip-10-100-3-83 postgres[18089]: [52320-4] #011SQL statement "CALL _timescaledb_internal.policy_compression_execute(
Jul 25 13:27:04 ip-10-100-3-83 postgres[18089]: [52320-8] #011PL/pgSQL function _timescaledb_internal.policy_compression(integer,jsonb) line 51 at CALL
Jul 25 13:27:04 ip-10-100-3-83 postgres[18089]: [52321-6] #011PL/pgSQL function _timescaledb_internal.policy_compression_execute(integer,integer,anyelement,integer,boolean,boolean) line 38 at PERFORM
Jul 25 13:27:04 ip-10-100-3-83 postgres[18089]: [52321-7] #011SQL statement "CALL _timescaledb_internal.policy_compression_execute(
Jul 25 13:27:04 ip-10-100-3-83 postgres[18089]: [52321-11] #011PL/pgSQL function _timescaledb_internal.policy_compression(integer,jsonb) line 51 at CALL
Jul 25 13:27:04 ip-10-100-3-83 postgres[18089]: [52322-3] #011PL/pgSQL function _timescaledb_internal.policy_compression_execute(integer,integer,anyelement,integer,boolean,boolean) line 38 at PERFORM
Jul 25 13:27:04 ip-10-100-3-83 postgres[18089]: [52322-4] #011SQL statement "CALL _timescaledb_internal.policy_compression_execute(
Jul 25 13:27:04 ip-10-100-3-83 postgres[18089]: [52322-8] #011PL/pgSQL function _timescaledb_internal.policy_compression(integer,jsonb) line 51 at CALL
Jul 25 13:27:04 ip-10-100-3-83 postgres[18089]: [52323-3] #011PL/pgSQL function _timescaledb_internal.policy_compression_execute(integer,integer,anyelement,integer,boolean,boolean) line 38 at PERFORM
Jul 25 13:27:04 ip-10-100-3-83 postgres[18089]: [52323-4] #011SQL statement "CALL _timescaledb_internal.policy_compression_execute(
Jul 25 13:27:04 ip-10-100-3-83 postgres[18089]: [52323-8] #011PL/pgSQL function _timescaledb_internal.policy_compression(integer,jsonb) line 51 at CALL
Jul 25 13:27:04 ip-10-100-3-83 postgres[18089]: [52324-3] #011PL/pgSQL function _timescaledb_internal.policy_compression_execute(integer,integer,anyelement,integer,boolean,boolean) line 38 at PERFORM
Jul 25 13:27:04 ip-10-100-3-83 postgres[18089]: [52324-4] #011SQL statement "CALL _timescaledb_internal.policy_compression_execute(
Jul 25 13:27:04 ip-10-100-3-83 postgres[18089]: [52324-8] #011PL/pgSQL function _timescaledb_internal.policy_compression(integer,jsonb) line 51 at CALL
Jul 25 13:27:04 ip-10-100-3-83 postgres[18089]: [52325-3] #011PL/pgSQL function _timescaledb_internal.policy_compression_execute(integer,integer,anyelement,integer,boolean,boolean) line 38 at PERFORM
Jul 25 13:27:04 ip-10-100-3-83 postgres[18089]: [52325-4] #011SQL statement "CALL _timescaledb_internal.policy_compression_execute(
Jul 25 13:27:04 ip-10-100-3-83 postgres[18089]: [52325-8] #011PL/pgSQL function _timescaledb_internal.policy_compression(integer,jsonb) line 51 at CALL
Jul 25 13:27:04 ip-10-100-3-83 postgres[18089]: [52326-3] #011PL/pgSQL function _timescaledb_internal.policy_compression_execute(integer,integer,anyelement,integer,boolean,boolean) line 38 at PERFORM
Jul 25 13:27:04 ip-10-100-3-83 postgres[18089]: [52326-4] #011SQL statement "CALL _timescaledb_internal.policy_compression_execute(
Jul 25 13:27:04 ip-10-100-3-83 postgres[18089]: [52326-8] #011PL/pgSQL function _timescaledb_internal.policy_compression(integer,jsonb) line 51 at CALL



On TimescaleDB 2.11.1,  timestamp range for two consecutive calls: 02:35:38 to 03:08:08. This means that compression of one chunk took about 32 minutes.

Jul 28 02:35:38 ip-10-100-3-83 postgres[84067]: [904-3] #011PL/pgSQL function _timescaledb_internal.policy_compression_execute(integer,integer,anyelement,integer,boolean,boolean) line 51 at PERFORM
Jul 28 02:35:38 ip-10-100-3-83 postgres[84067]: [904-4] #011SQL statement "CALL _timescaledb_internal.policy_compression_execute(
Jul 28 02:35:38 ip-10-100-3-83 postgres[84067]: [904-8] #011PL/pgSQL function _timescaledb_internal.policy_compression(integer,jsonb) line 51 at CALL
Jul 28 02:35:38 ip-10-100-3-83 postgres[84067]: [905-3] #011PL/pgSQL function _timescaledb_internal.policy_compression_execute(integer,integer,anyelement,integer,boolean,boolean) line 51 at PERFORM
Jul 28 02:35:38 ip-10-100-3-83 postgres[84067]: [905-4] #011SQL statement "CALL _timescaledb_internal.policy_compression_execute(
Jul 28 02:35:38 ip-10-100-3-83 postgres[84067]: [905-8] #011PL/pgSQL function _timescaledb_internal.policy_compression(integer,jsonb) line 51 at CALL
Jul 28 02:35:38 ip-10-100-3-83 postgres[84067]: [906-3] #011PL/pgSQL function _timescaledb_internal.policy_compression_execute(integer,integer,anyelement,integer,boolean,boolean) line 51 at PERFORM
Jul 28 02:35:38 ip-10-100-3-83 postgres[84067]: [906-4] #011SQL statement "CALL _timescaledb_internal.policy_compression_execute(
Jul 28 02:35:38 ip-10-100-3-83 postgres[84067]: [906-8] #011PL/pgSQL function _timescaledb_internal.policy_compression(integer,jsonb) line 51 at CALL
Jul 28 02:35:38 ip-10-100-3-83 postgres[84067]: [907-3] #011PL/pgSQL function _timescaledb_internal.policy_compression_execute(integer,integer,anyelement,integer,boolean,boolean) line 51 at PERFORM
Jul 28 02:35:38 ip-10-100-3-83 postgres[84067]: [907-4] #011SQL statement "CALL _timescaledb_internal.policy_compression_execute(
Jul 28 02:35:38 ip-10-100-3-83 postgres[84067]: [907-8] #011PL/pgSQL function _timescaledb_internal.policy_compression(integer,jsonb) line 51 at CALL
Jul 28 02:35:38 ip-10-100-3-83 postgres[84067]: [908-3] #011PL/pgSQL function _timescaledb_internal.policy_compression_execute(integer,integer,anyelement,integer,boolean,boolean) line 51 at PERFORM
Jul 28 02:35:38 ip-10-100-3-83 postgres[84067]: [908-4] #011SQL statement "CALL _timescaledb_internal.policy_compression_execute(
Jul 28 02:35:38 ip-10-100-3-83 postgres[84067]: [908-8] #011PL/pgSQL function _timescaledb_internal.policy_compression(integer,jsonb) line 51 at CALL
Jul 28 02:35:38 ip-10-100-3-83 postgres[84067]: [909-3] #011PL/pgSQL function _timescaledb_internal.policy_compression_execute(integer,integer,anyelement,integer,boolean,boolean) line 51 at PERFORM
Jul 28 02:35:38 ip-10-100-3-83 postgres[84067]: [909-4] #011SQL statement "CALL _timescaledb_internal.policy_compression_execute(
Jul 28 02:35:38 ip-10-100-3-83 postgres[84067]: [909-8] #011PL/pgSQL function _timescaledb_internal.policy_compression(integer,jsonb) line 51 at CALL
Jul 28 02:35:38 ip-10-100-3-83 postgres[84067]: [910-3] #011PL/pgSQL function _timescaledb_internal.policy_compression_execute(integer,integer,anyelement,integer,boolean,boolean) line 51 at PERFORM
Jul 28 02:35:38 ip-10-100-3-83 postgres[84067]: [910-4] #011SQL statement "CALL _timescaledb_internal.policy_compression_execute(
Jul 28 02:35:38 ip-10-100-3-83 postgres[84067]: [910-8] #011PL/pgSQL function _timescaledb_internal.policy_compression(integer,jsonb) line 51 at CALL
Jul 28 02:35:38 ip-10-100-3-83 postgres[84067]: [911-3] #011PL/pgSQL function _timescaledb_internal.policy_compression_execute(integer,integer,anyelement,integer,boolean,boolean) line 51 at PERFORM
Jul 28 02:35:38 ip-10-100-3-83 postgres[84067]: [911-4] #011SQL statement "CALL _timescaledb_internal.policy_compression_execute(
Jul 28 02:35:38 ip-10-100-3-83 postgres[84067]: [911-8] #011PL/pgSQL function _timescaledb_internal.policy_compression(integer,jsonb) line 51 at CALL
Jul 28 02:35:39 ip-10-100-3-83 postgres[84067]: [912-3] #011PL/pgSQL function _timescaledb_internal.policy_compression_execute(integer,integer,anyelement,integer,boolean,boolean) line 51 at PERFORM
Jul 28 02:35:39 ip-10-100-3-83 postgres[84067]: [912-4] #011SQL statement "CALL _timescaledb_internal.policy_compression_execute(
Jul 28 02:35:39 ip-10-100-3-83 postgres[84067]: [912-8] #011PL/pgSQL function _timescaledb_internal.policy_compression(integer,jsonb) line 51 at CALL
Jul 28 02:35:39 ip-10-100-3-83 postgres[84067]: [913-3] #011PL/pgSQL function _timescaledb_internal.policy_compression_execute(integer,integer,anyelement,integer,boolean,boolean) line 51 at PERFORM
Jul 28 02:35:39 ip-10-100-3-83 postgres[84067]: [913-4] #011SQL statement "CALL _timescaledb_internal.policy_compression_execute(
Jul 28 02:35:39 ip-10-100-3-83 postgres[84067]: [913-8] #011PL/pgSQL function _timescaledb_internal.policy_compression(integer,jsonb) line 51 at CALL
Jul 28 02:35:39 ip-10-100-3-83 postgres[84067]: [914-3] #011PL/pgSQL function _timescaledb_internal.policy_compression_execute(integer,integer,anyelement,integer,boolean,boolean) line 51 at PERFORM
Jul 28 02:35:39 ip-10-100-3-83 postgres[84067]: [914-4] #011SQL statement "CALL _timescaledb_internal.policy_compression_execute(
Jul 28 02:35:39 ip-10-100-3-83 postgres[84067]: [914-8] #011PL/pgSQL function _timescaledb_internal.policy_compression(integer,jsonb) line 51 at CALL
Jul 28 02:35:39 ip-10-100-3-83 postgres[84067]: [915-6] #011PL/pgSQL function _timescaledb_internal.policy_compression_execute(integer,integer,anyelement,integer,boolean,boolean) line 51 at PERFORM
Jul 28 02:35:39 ip-10-100-3-83 postgres[84067]: [915-7] #011SQL statement "CALL _timescaledb_internal.policy_compression_execute(
Jul 28 02:35:39 ip-10-100-3-83 postgres[84067]: [915-11] #011PL/pgSQL function _timescaledb_internal.policy_compression(integer,jsonb) line 51 at CALL
Jul 28 02:35:40 ip-10-100-3-83 postgres[84067]: [916-3] #011PL/pgSQL function _timescaledb_internal.policy_compression_execute(integer,integer,anyelement,integer,boolean,boolean) line 51 at PERFORM
Jul 28 02:35:40 ip-10-100-3-83 postgres[84067]: [916-4] #011SQL statement "CALL _timescaledb_internal.policy_compression_execute(
Jul 28 02:35:40 ip-10-100-3-83 postgres[84067]: [916-8] #011PL/pgSQL function _timescaledb_internal.policy_compression(integer,jsonb) line 51 at CALL
Jul 28 02:35:40 ip-10-100-3-83 postgres[84067]: [917-3] #011PL/pgSQL function _timescaledb_internal.policy_compression_execute(integer,integer,anyelement,integer,boolean,boolean) line 51 at PERFORM
Jul 28 02:35:40 ip-10-100-3-83 postgres[84067]: [917-4] #011SQL statement "CALL _timescaledb_internal.policy_compression_execute(
Jul 28 02:35:40 ip-10-100-3-83 postgres[84067]: [917-8] #011PL/pgSQL function _timescaledb_internal.policy_compression(integer,jsonb) line 51 at CALL
Jul 28 02:35:40 ip-10-100-3-83 postgres[84067]: [918-3] #011PL/pgSQL function _timescaledb_internal.policy_compression_execute(integer,integer,anyelement,integer,boolean,boolean) line 51 at PERFORM
Jul 28 02:35:40 ip-10-100-3-83 postgres[84067]: [918-4] #011SQL statement "CALL _timescaledb_internal.policy_compression_execute(
Jul 28 02:35:40 ip-10-100-3-83 postgres[84067]: [918-8] #011PL/pgSQL function _timescaledb_internal.policy_compression(integer,jsonb) line 51 at CALL
Jul 28 02:35:40 ip-10-100-3-83 postgres[84067]: [919-3] #011PL/pgSQL function _timescaledb_internal.policy_compression_execute(integer,integer,anyelement,integer,boolean,boolean) line 51 at PERFORM
Jul 28 02:35:40 ip-10-100-3-83 postgres[84067]: [919-4] #011SQL statement "CALL _timescaledb_internal.policy_compression_execute(
Jul 28 02:35:40 ip-10-100-3-83 postgres[84067]: [919-8] #011PL/pgSQL function _timescaledb_internal.policy_compression(integer,jsonb) line 51 at CALL
Jul 28 02:35:40 ip-10-100-3-83 postgres[84067]: [920-3] #011PL/pgSQL function _timescaledb_internal.policy_compression_execute(integer,integer,anyelement,integer,boolean,boolean) line 51 at PERFORM
Jul 28 02:35:40 ip-10-100-3-83 postgres[84067]: [920-4] #011SQL statement "CALL _timescaledb_internal.policy_compression_execute(
Jul 28 02:35:40 ip-10-100-3-83 postgres[84067]: [920-8] #011PL/pgSQL function _timescaledb_internal.policy_compression(integer,jsonb) line 51 at CALL
Jul 28 03:08:06 ip-10-100-3-83 postgres[84067]: [921-3] #011PL/pgSQL function _timescaledb_internal.policy_compression_execute(integer,integer,anyelement,integer,boolean,boolean) line 51 at PERFORM
Jul 28 03:08:06 ip-10-100-3-83 postgres[84067]: [921-4] #011SQL statement "CALL _timescaledb_internal.policy_compression_execute(
Jul 28 03:08:06 ip-10-100-3-83 postgres[84067]: [921-8] #011PL/pgSQL function _timescaledb_internal.policy_compression(integer,jsonb) line 51 at CALL
Jul 28 03:08:06 ip-10-100-3-83 postgres[84067]: [922-3] #011PL/pgSQL function _timescaledb_internal.policy_compression_execute(integer,integer,anyelement,integer,boolean,boolean) line 51 at PERFORM
Jul 28 03:08:06 ip-10-100-3-83 postgres[84067]: [922-4] #011SQL statement "CALL _timescaledb_internal.policy_compression_execute(
Jul 28 03:08:06 ip-10-100-3-83 postgres[84067]: [922-8] #011PL/pgSQL function _timescaledb_internal.policy_compression(integer,jsonb) line 51 at CALL
Jul 28 03:08:06 ip-10-100-3-83 postgres[84067]: [923-3] #011PL/pgSQL function _timescaledb_internal.policy_compression_execute(integer,integer,anyelement,integer,boolean,boolean) line 51 at PERFORM
Jul 28 03:08:06 ip-10-100-3-83 postgres[84067]: [923-4] #011SQL statement "CALL _timescaledb_internal.policy_compression_execute(
Jul 28 03:08:06 ip-10-100-3-83 postgres[84067]: [923-8] #011PL/pgSQL function _timescaledb_internal.policy_compression(integer,jsonb) line 51 at CALL
Jul 28 03:08:06 ip-10-100-3-83 postgres[84067]: [924-3] #011PL/pgSQL function _timescaledb_internal.policy_compression_execute(integer,integer,anyelement,integer,boolean,boolean) line 51 at PERFORM
Jul 28 03:08:06 ip-10-100-3-83 postgres[84067]: [924-4] #011SQL statement "CALL _timescaledb_internal.policy_compression_execute(
Jul 28 03:08:06 ip-10-100-3-83 postgres[84067]: [924-8] #011PL/pgSQL function _timescaledb_internal.policy_compression(integer,jsonb) line 51 at CALL
Jul 28 03:08:06 ip-10-100-3-83 postgres[84067]: [925-3] #011PL/pgSQL function _timescaledb_internal.policy_compression_execute(integer,integer,anyelement,integer,boolean,boolean) line 51 at PERFORM
Jul 28 03:08:06 ip-10-100-3-83 postgres[84067]: [925-4] #011SQL statement "CALL _timescaledb_internal.policy_compression_execute(
Jul 28 03:08:06 ip-10-100-3-83 postgres[84067]: [925-8] #011PL/pgSQL function _timescaledb_internal.policy_compression(integer,jsonb) line 51 at CALL
Jul 28 03:08:06 ip-10-100-3-83 postgres[84067]: [926-3] #011PL/pgSQL function _timescaledb_internal.policy_compression_execute(integer,integer,anyelement,integer,boolean,boolean) line 51 at PERFORM
Jul 28 03:08:06 ip-10-100-3-83 postgres[84067]: [926-4] #011SQL statement "CALL _timescaledb_internal.policy_compression_execute(
Jul 28 03:08:06 ip-10-100-3-83 postgres[84067]: [926-8] #011PL/pgSQL function _timescaledb_internal.policy_compression(integer,jsonb) line 51 at CALL
Jul 28 03:08:06 ip-10-100-3-83 postgres[84067]: [927-3] #011PL/pgSQL function _timescaledb_internal.policy_compression_execute(integer,integer,anyelement,integer,boolean,boolean) line 51 at PERFORM
Jul 28 03:08:06 ip-10-100-3-83 postgres[84067]: [927-4] #011SQL statement "CALL _timescaledb_internal.policy_compression_execute(
Jul 28 03:08:06 ip-10-100-3-83 postgres[84067]: [927-8] #011PL/pgSQL function _timescaledb_internal.policy_compression(integer,jsonb) line 51 at CALL
Jul 28 03:08:06 ip-10-100-3-83 postgres[84067]: [928-3] #011PL/pgSQL function _timescaledb_internal.policy_compression_execute(integer,integer,anyelement,integer,boolean,boolean) line 51 at PERFORM
Jul 28 03:08:06 ip-10-100-3-83 postgres[84067]: [928-4] #011SQL statement "CALL _timescaledb_internal.policy_compression_execute(
Jul 28 03:08:06 ip-10-100-3-83 postgres[84067]: [928-8] #011PL/pgSQL function _timescaledb_internal.policy_compression(integer,jsonb) line 51 at CALL
Jul 28 03:08:07 ip-10-100-3-83 postgres[84067]: [929-3] #011PL/pgSQL function _timescaledb_internal.policy_compression_execute(integer,integer,anyelement,integer,boolean,boolean) line 51 at PERFORM
Jul 28 03:08:07 ip-10-100-3-83 postgres[84067]: [929-4] #011SQL statement "CALL _timescaledb_internal.policy_compression_execute(
Jul 28 03:08:07 ip-10-100-3-83 postgres[84067]: [929-8] #011PL/pgSQL function _timescaledb_internal.policy_compression(integer,jsonb) line 51 at CALL
Jul 28 03:08:07 ip-10-100-3-83 postgres[84067]: [930-3] #011PL/pgSQL function _timescaledb_internal.policy_compression_execute(integer,integer,anyelement,integer,boolean,boolean) line 51 at PERFORM
Jul 28 03:08:07 ip-10-100-3-83 postgres[84067]: [930-4] #011SQL statement "CALL _timescaledb_internal.policy_compression_execute(
Jul 28 03:08:07 ip-10-100-3-83 postgres[84067]: [930-8] #011PL/pgSQL function _timescaledb_internal.policy_compression(integer,jsonb) line 51 at CALL
Jul 28 03:08:07 ip-10-100-3-83 postgres[84067]: [931-3] #011PL/pgSQL function _timescaledb_internal.policy_compression_execute(integer,integer,anyelement,integer,boolean,boolean) line 51 at PERFORM
Jul 28 03:08:07 ip-10-100-3-83 postgres[84067]: [931-4] #011SQL statement "CALL _timescaledb_internal.policy_compression_execute(
Jul 28 03:08:07 ip-10-100-3-83 postgres[84067]: [931-8] #011PL/pgSQL function _timescaledb_internal.policy_compression(integer,jsonb) line 51 at CALL
Jul 28 03:08:07 ip-10-100-3-83 postgres[84067]: [932-6] #011PL/pgSQL function _timescaledb_internal.policy_compression_execute(integer,integer,anyelement,integer,boolean,boolean) line 51 at PERFORM
Jul 28 03:08:07 ip-10-100-3-83 postgres[84067]: [932-7] #011SQL statement "CALL _timescaledb_internal.policy_compression_execute(
Jul 28 03:08:07 ip-10-100-3-83 postgres[84067]: [932-11] #011PL/pgSQL function _timescaledb_internal.policy_compression(integer,jsonb) line 51 at CALL
Jul 28 03:08:08 ip-10-100-3-83 postgres[84067]: [933-3] #011PL/pgSQL function _timescaledb_internal.policy_compression_execute(integer,integer,anyelement,integer,boolean,boolean) line 51 at PERFORM
Jul 28 03:08:08 ip-10-100-3-83 postgres[84067]: [933-4] #011SQL statement "CALL _timescaledb_internal.policy_compression_execute(
Jul 28 03:08:08 ip-10-100-3-83 postgres[84067]: [933-8] #011PL/pgSQL function _timescaledb_internal.policy_compression(integer,jsonb) line 51 at CALL
Jul 28 03:08:08 ip-10-100-3-83 postgres[84067]: [934-3] #011PL/pgSQL function _timescaledb_internal.policy_compression_execute(integer,integer,anyelement,integer,boolean,boolean) line 51 at PERFORM
Jul 28 03:08:08 ip-10-100-3-83 postgres[84067]: [934-4] #011SQL statement "CALL _timescaledb_internal.policy_compression_execute(
Jul 28 03:08:08 ip-10-100-3-83 postgres[84067]: [934-8] #011PL/pgSQL function _timescaledb_internal.policy_compression(integer,jsonb) line 51 at CALL
Jul 28 03:08:08 ip-10-100-3-83 postgres[84067]: [935-3] #011PL/pgSQL function _timescaledb_internal.policy_compression_execute(integer,integer,anyelement,integer,boolean,boolean) line 51 at PERFORM
Jul 28 03:08:08 ip-10-100-3-83 postgres[84067]: [935-4] #011SQL statement "CALL _timescaledb_internal.policy_compression_execute(
Jul 28 03:08:08 ip-10-100-3-83 postgres[84067]: [935-8] #011PL/pgSQL function _timescaledb_internal.policy_compression(integer,jsonb) line 51 at CALL
Jul 28 03:08:08 ip-10-100-3-83 postgres[84067]: [936-3] #011PL/pgSQL function _timescaledb_internal.policy_compression_execute(integer,integer,anyelement,integer,boolean,boolean) line 51 at PERFORM
Jul 28 03:08:08 ip-10-100-3-83 postgres[84067]: [936-4] #011SQL statement "CALL _timescaledb_internal.policy_compression_execute(
Jul 28 03:08:08 ip-10-100-3-83 postgres[84067]: [936-8] #011PL/pgSQL function _timescaledb_internal.policy_compression(integer,jsonb) line 51 at CALL
Jul 28 03:08:08 ip-10-100-3-83 postgres[84067]: [937-3] #011PL/pgSQL function _timescaledb_internal.policy_compression_execute(integer,integer,anyelement,integer,boolean,boolean) line 51 at PERFORM
Jul 28 03:08:08 ip-10-100-3-83 postgres[84067]: [937-4] #011SQL statement "CALL _timescaledb_internal.policy_compression_execute(
Jul 28 03:08:08 ip-10-100-3-83 postgres[84067]: [937-8] #011PL/pgSQL function _timescaledb_internal.policy_compression(integer,jsonb) line 51 at CALL

How can we reproduce the bug?

To reproduce the issue just execute the compress_chunk function between TimescaleDB 2.9.0 and TimescaleDB 2.11.1

Jul 28 '23 03:07 ebreijo

After doing some digging, I believe that this PR https://github.com/timescale/timescaledb/pull/4821 is the one causing the performance regression.
SET timescaledb.enable_compression_indexscan = 'OFF';

Compressing 1 hour chunk took: 5 minutes

SET timescaledb.enable_compression_indexscan = 'ON'; (default setting)

Compressing 1 hour chunk took: 40 minutes

Jul 28 '23 15:07 ebreijo

@ebreijo will it possible for you to share the schema of the hypertable along with all the indexes? cc @shhnwz

Jul 31 '23 08:07 nikkhils

@nikkhils This is my hypertable schema and indexes:

CREATE TABLE device_readings (
    time timestamp with time zone,
    device_id integer,
    metric_id integer,
    value double precision NOT NULL,
    metadata jsonb,
    PRIMARY KEY (time, device_id, metric_id)
);

CREATE INDEX ON device_readings(time DESC);
CREATE INDEX ON device_readings (device_id, metric_id, time DESC);

Jul 31 '23 15:07 ebreijo

@ebreijo can you also please provide the compression segment by column details?

Aug 01 '23 06:08 nikkhils

Hi @ebreijo,

Thanks for bringing this up. Help us with the following information.

Whether this issue showed up from the very first cycle of compression job after the upgrade or there was some performant runs too after the upgrade?
Do you have any other hypertables showing similar trend?
Please share the result of these queries: SELECT pg_size_pretty(before_compression_total_bytes) as "before compression", pg_size_pretty(after_compression_total_bytes) as "after compression" FROM hypertable_compression_stats('**HYPERTABLE_NAME**');

SELECT chunk_name,pg_size_pretty(total_bytes) as total_size FROM chunks_detailed_size('**HYPERTABLE_NAME**');

Replace HYPERTABLE_NAME with the hypertable/s from the database.

How big is jsonb data? Any recent change in size for metadata?

Aug 01 '23 10:08 shhnwz

@shhnwz

The issue showed up from the very first cycle of compression job after the upgrade
I don't have any other hypertables, just the one I posted above
Since our chunk size is 1 hour and we store the data for up to 13 months, the second query you posted gives 9,518 chunks. The data gets compressed after 7 days. As a result, I'm going to show a subset of chunks before and after compression.
- Before compression
- After compression
JSONB data is very small, I would say about 120 bytes max. No recent change in size for metadata.

As I mentioned above, I believe the change that caused this issue was introduced on PR https://github.com/timescale/timescaledb/pull/4821. Disabling the timescaledb.enable_compression_indexscan improves the compression time to what it was before the upgrade.

Aug 01 '23 17:08 ebreijo

@nikkhils

From the timescaledb_information.compression_settings view

Aug 01 '23 17:08 ebreijo

Hi @ebreijo , while we try to further investigate the performance regression you report, we can suggest the following workaround you could use in the meantime to make sure that you have a background compression job that performs compression with the GUC set to off (since you've noticed that improves the situation):

-- 1. create a procedure to use as a wrapper around compression policy
CREATE OR REPLACE PROCEDURE compression_wrapper(id INTEGER, config jsonb) AS
$$
DECLARE
    compression_policy_id INTEGER;
BEGIN
    SELECT (config->>'compression_policy_id')::INTEGER INTO compression_policy_id;
    SET timescaledb.enable_compression_indexscan = off;
    CALL run_job(compression_policy_id);

    RESET timescaledb.enable_compression_indexscan;

END
$$
LANGUAGE PLPGSQL;

-- 2. unschedule the existing compression policy (assuming it has id 1000):
SELECT alter_job(1000, scheduled => false);

-- 3. register the custom job with an appropriate schedule interval
select add_job('compression_wrapper', schedule_interval, config => '{"compression_policy_id": 1000}');

Let us know if there are any issues with the suggested workaround

Aug 03 '23 10:08 konskov

Hi @ebreijo ,

Thanks for being patient on this. We are going through this issue in detail and trying to find a trade-off pattern between Seq Access and Random Access. Help us with some more information related to the postgres configuration and hardware.

Information Required

Share the values of shared_buffers, effective_cache_size, bgwriter_delay, bgwriter_lru_maxpages, bgwriter_lru_multiplier, bgwriter_flush_after from postgresql.conf file.
Share us with Hardware Configuration RAM, DISK(HDD,SSD,NVMe), CPUs

Aug 21 '23 18:08 shhnwz

@shhnwz

From postgres.conf file

shared_buffers = 15823MB
effective_cache_size = 47471MB
bgwriter_delay = 200ms (default value)
bgwriter_lru_maxpages = 100 (default value)
bgwriter_lru_multiplier = 2.0 (default value)
bgwriter_flush_after = 512kB (default value)

Hardware Configuration (AWS EC2 m6in.4xlarge)
- RAM: 64 GB
- CPUs: 16
- Disk: 2 General Purpose SSDs in RAID0 configuration with a total of 14 TB, 32000 IOPS and 1500 MB/s throughput

Aug 21 '23 18:08 ebreijo

@ebreijo ,

It would be interesting to compare the I/O stats (cache hits and misses) between Index path and Non-Index path compression.

Please identify Two uncompressed chunk, suppose Chunk1 and Chunk2.
Enable SET timescaledb.enable_compression_indexscan = 'ON'; and run compression manually.

EXPLAIN (ANALYZE,BUFFERS) SELECT compress_chunk('Chunk1'); select * from pg_statio_user_tables where relname = 'Chunk1';
Repeat the same for Chunk2 after disabling Index path SET timescaledb.enable_compression_indexscan = 'ON';

please share us with the output of the above stats and time taken

Aug 23 '23 10:08 shhnwz

@shhnwz

With disabled `SET timescaledb.enable_compression_indexscan = 'OFF'`

Before compression

SELECT * FROM pg_statio_user_tables where relname = '_hyper_1_40061_chunk'
   
relid    |      schemaname       |       relname        | heap_blks_read | heap_blks_hit | idx_blks_read | idx_blks_hit | toast_blks_read | toast_blks_hit | tidx_blks_read | tidx_blks_hit 
------------+-----------------------+----------------------+----------------+---------------+---------------+--------------+-----------------+----------------+----------------+---------------
 1678044768 | _timescaledb_internal | _hyper_1_40061_chunk |        7007344 |     226742517 |       5643362 |   1083073117 |               0 |              0 |              0 |             0
(1 row)

real    0m0.177s
user    0m0.029s
sys     0m0.000s

Compress Chunk

EXPLAIN (ANALYZE,BUFFERS) SELECT compress_chunk('_timescaledb_internal._hyper_1_40061_chunk')
                                                
QUERY PLAN                                                 
-----------------------------------------------------------------------------------------------------------
 Result  (cost=0.00..0.01 rows=1 width=4) (actual time=238904.348..238904.351 rows=1 loops=1)
   Buffers: shared hit=922983 read=1632181 dirtied=76884 written=110354, temp read=1250395 written=1250398
 Planning Time: 0.056 ms
 Execution Time: 238904.435 ms
(4 rows)

real    3m59.978s
user    0m0.022s
sys     0m0.004s

After compression

SELECT * FROM pg_statio_user_tables where relname = '_hyper_1_40061_chunk'

   relid    |      schemaname       |       relname        | heap_blks_read | heap_blks_hit | idx_blks_read | idx_blks_hit | toast_blks_read | toast_blks_hit | tidx_blks_read | tidx_blks_hit 
------------+-----------------------+----------------------+----------------+---------------+---------------+--------------+-----------------+----------------+----------------+---------------
 1678044768 | _timescaledb_internal | _hyper_1_40061_chunk |        8604621 |     226742520 |       5643362 |   1083073120 |               0 |              0 |              0 |             0
(1 row)


real    0m0.172s
user    0m0.030s
sys     0m0.012s

With enabled `SET timescaledb.enable_compression_indexscan = 'ON'`

Before compression

SELECT * FROM pg_statio_user_tables where relname = '_hyper_1_40062_chunk'

   relid    |      schemaname       |       relname        | heap_blks_read | heap_blks_hit | idx_blks_read | idx_blks_hit | toast_blks_read | toast_blks_hit | tidx_blks_read | tidx_blks_hit 
------------+-----------------------+----------------------+----------------+---------------+---------------+--------------+-----------------+----------------+----------------+---------------
 1678045341 | _timescaledb_internal | _hyper_1_40062_chunk |       10352613 |     210899356 |       6927283 |   1065341470 |               0 |              0 |              0 |             0
(1 row)

real    0m0.210s
user    0m0.021s
sys     0m0.010s

Compress Chunk

EXPLAIN (ANALYZE,BUFFERS) SELECT compress_chunk('_timescaledb_internal._hyper_1_40062_chunk')

QUERY PLAN                                               
-------------------------------------------------------------------------------------------------------
 Result  (cost=0.00..0.01 rows=1 width=4) (actual time=1243726.758..1243729.056 rows=1 loops=1)
   Buffers: shared hit=37959037 read=2228001 dirtied=77046 written=135878, temp read=1688 written=1682
 Planning Time: 0.064 ms
 Execution Time: 1243731.216 ms
(4 rows)

real    20m45.367s
user    0m0.020s
sys     0m0.008s

After compression

SELECT * FROM pg_statio_user_tables where relname = '_hyper_1_40062_chunk'

   relid    |      schemaname       |       relname        | heap_blks_read | heap_blks_hit | idx_blks_read | idx_blks_hit | toast_blks_read | toast_blks_hit | tidx_blks_read | tidx_blks_hit 
------------+-----------------------+----------------------+----------------+---------------+---------------+--------------+-----------------+----------------+----------------+---------------
 1678045341 | _timescaledb_internal | _hyper_1_40062_chunk |       12117095 |     247939301 |       7356177 |   1065341509 |               0 |              0 |              0 |             0
(1 row)


real    0m0.176s
user    0m0.030s
sys     0m0.000s

Aug 23 '23 19:08 ebreijo

@ebreijo ,

Thanks again for highlighting this issue.

Brief History about Indexscan path introduction

Before 2.11 cost of compression can be expressed as cost(Seq_IO) + cost(Sort). Usually, cost of sorting depends on the table size and allocated work_mem. If table doesn't fit in the work_mem, in that case tuples will be written out to disk as temp files. Now, Cost of Sorting includes IO too, Cost(Sort) = cpu_time + disk_IO

We have seen trends in our customer's system where large temp files created during large chunk compression leading to performance slowness.

To optimize compression we have added an intelligence in our compression code to cherry pick relevant index that matches the compression settings configuration. This will nullify the cost(Sort) part as the entries are sorted in the indexes. In theory this sounds like a "Victory", until this issue :-)

The Caveat:

Compression through indexscan path changes the cost definition Cost(compression) = Cost(Seq_IO) + Cost(Random_IO) Cost(Seq_IO) is cost of reading Index Keys traversed either forward or backward in direction from Indexes (B-Tree). Cost(Random_IO) is the cost of reading the actual tuple from the table heap and involves page seek.
Demands more shared buffer Increase in shared buffer usage is due to indirect table access. Unlike sorting path (where index is not involved), indexpath demands shared buffer to load indexes. Total_Buffer_Size(Compression) = Table_Size(Chunk) + Index_Size(Chunk_Index)

The Analysis:

Compression through Tuplesort path

Heap_misses: 1597277 (Seq I/O) Heap_hits : 3 Hit Ratio : 3/(1597277 + 3) >> 0%

Compression through IndexScan path

Heap_misses: 1764482 (Random I/O) Heap_hits : 37039945 Hit Ratio : 37039945/(37039945 + 1764482) >>> 0.95%

Idx_misses : 428894 (Seq I/O) Idx_hits : 39 IdxHitRatio: 39/(428894 + 39) >>> 0

Recommendation:

System with high ingestion rate (hourly 10G to 12G data inserts) will put pressure on the shared buffer. Less buffer configuration will invite frequent page eviction leading to higher cache misses. Its worth to try with higher shared buffer configuration and see if it improves the compression performance.

Make shared buffer upto 40% of the RAM.

Aug 28 '23 04:08 shhnwz

@shhnwz

I have follow your recommendation of setting the shared buffers to 40% of the RAM and I still don't see any improvements/benefits when compressing a chunk. It is still taking too much time to compress a chunk with the timescaledb.enable_compression_indexscan set to ON. Below are the results.

Shared Buffers set to 40% (64 GB * 40% = 25.6 GB)
With enabled SET timescaledb.enable_compression_indexscan = 'ON'
Before compression

   relid    |      schemaname       |       relname        | heap_blks_read | heap_blks_hit | idx_blks_read | idx_blks_hit | toast_blks_read | toast_blks_hit | tidx_blks_read | tidx_blks_hit 
------------+-----------------------+----------------------+----------------+---------------+---------------+--------------+-----------------+----------------+----------------+---------------
 1704365727 | _timescaledb_internal | _hyper_1_40466_chunk |        7694825 |     265437081 |      10337481 |   1231590128 |               0 |              0 |              0 |             0
(1 row)

real    0m0.194s
user    0m0.033s
sys     0m0.014s

Compress Chunk

                                              QUERY PLAN                                               
-------------------------------------------------------------------------------------------------------
 Result  (cost=0.00..0.01 rows=1 width=4) (actual time=1576586.242..1576587.674 rows=1 loops=1)
   Buffers: shared hit=40491990 read=2287370 dirtied=86263 written=111323, temp read=1805 written=1799
 Planning Time: 0.070 ms
 Execution Time: 1576587.783 ms
(4 rows)


real    26m17.954s
user    0m0.028s
sys     0m0.015s

After compression

   relid    |      schemaname       |       relname        | heap_blks_read | heap_blks_hit | idx_blks_read | idx_blks_hit | toast_blks_read | toast_blks_hit | tidx_blks_read | tidx_blks_hit 
------------+-----------------------+----------------------+----------------+---------------+---------------+--------------+-----------------+----------------+----------------+---------------
 1704365727 | _timescaledb_internal | _hyper_1_40466_chunk |        9472146 |     304882520 |      10810719 |   1231590206 |               0 |              0 |              0 |             0
(1 row)


real    0m0.181s
user    0m0.020s
sys     0m0.013s

I have also tested with the shared_buffers set at 50% of the RAM and compression is still running very slow.

Please let me know if there is anything else you need from my end to figure out this issue. For now setting timescaledb.enable_compression_indexscan = 'OFF' is what has work best for me.

Aug 29 '23 19:08 ebreijo

Hello @ebreijo,

Thanks for sharing this detailed information. Based on the data, I also recommend keeping the setting timescaledb.enable_compression_indexscan = OFF in your environment to improve the I/O pattern and speed up the data compression.

Sep 15 '23 07:09 jnidzwetzki

Is there any update on the issue because i am also facing the same problem. I have chunk interval of 24 hours and average chunk size is 100GB. Compression policy also set to be applied on chunks older than 24 hours. Following is my schema and other details. Queries were execute in the same order as given below:

Version Details:

PostgreSQL 14.9 (Ubuntu 14.9-1.pgdg22.04+1) on x86_64-pc-linux-gnu, compiled by gcc (Ubuntu 11.4.0-1ubuntu1~22.04) 11.4.0, 64-bit

Create Table

CREATE TABLE IF NOT EXISTS public.sensor_statuses
    (
        dtm timestamp with time zone NOT NULL,
        device_id character(12) COLLATE pg_catalog."default" NOT NULL,
        name character(20) COLLATE pg_catalog."default" NOT NULL,
        event_type character(1) COLLATE pg_catalog."default",
        status character(1) COLLATE pg_catalog."default",
        fault character(1) COLLATE pg_catalog."default",
        is_controlling boolean,
        type character(1) COLLATE pg_catalog."default",
        is_wireless boolean,
        reading numeric,
        rssi smallint,
        bat smallint,
        CONSTRAINT sensor_statuses_pkey1 PRIMARY KEY (dtm, device_id, name)
          USING INDEX TABLESPACE sensorstatusesspace
    );

Create Hyper Table

SELECT create_hypertable(
  'sensor_statuses', 'dtm', create_default_indexes => false, 
  chunk_time_interval => INTERVAL '24 hours', if_not_exists => TRUE);

Create Index

CREATE INDEX IF NOT EXISTS ix_sensor_statuses 
  ON sensor_statuses("device_id", dtm DESC) TABLESPACE sensorstatusesspace;

Attach Tablespace

SELECT attach_tablespace('sensorstatusesspace', 'sensor_statuses', if_not_attached => true);

Enable Compression

ALTER TABLE sensor_statuses SET (timescaledb.compress, timescaledb.compress_segmentby = 'device_id');

Create Compression Policy

SELECT add_compression_policy('sensor_statuses', INTERVAL '24 hours', if_not_exists => true);

I was using timescaledb extension version 2.11.2 and today upgrade the version to 2.12.0. Also please note that i haven't tried with timescaledb.enable_compression_indexscan = OFF so far.

Tried compression using policy and manual both ways but same issue.

During compression of first few chunks i did not noticed the problem and got compression rate of almost 97% but 4 days back i realized this issue.

Oct 07 '23 20:10 waqaschattha

Few other details:

Query:

SELECT 
pg_size_pretty(before_compression_total_bytes) as "before compression", 
pg_size_pretty(after_compression_total_bytes) as "after compression" 
FROM hypertable_compression_stats('sensor_statuses');

Results:

before compression	after compression
853 GB	21 GB

Query:

SELECT chunk_name,pg_size_pretty(total_bytes) as total_size FROM chunks_detailed_size('**HYPERTABLE_NAME**');

Results:

chunk_name	total_size
_hyper_2_21_chunk	1427 MB
_hyper_2_23_chunk	2474 MB
_hyper_2_30_chunk	2486 MB
_hyper_2_33_chunk	2479 MB
_hyper_2_39_chunk	2470 MB
_hyper_2_29_chunk	2497 MB
_hyper_2_67_chunk	100 GB
_hyper_2_71_chunk	99 GB
_hyper_2_60_chunk	2479 MB
_hyper_2_79_chunk	100 GB
_hyper_2_63_chunk	2502 MB
_hyper_2_82_chunk	99 GB
_hyper_2_65_chunk	2519 MB
_hyper_2_85_chunk	99 GB
_hyper_2_90_chunk	69 GB

postgres.config:

shared_buffers = 7647MB
effective_cache_size = 22942MB
bgwriter_delay = 200ms (default value)
bgwriter_lru_maxpages = 100 (default value)
bgwriter_lru_multiplier = 2.0 (default value)
bgwriter_flush_after = 512kB (default value)

Hardware:

AWS EC2 i3.xlarge
4 vCPU
30.5 GB Memory

Ingestion Rate:

1100 records/sec

Oct 07 '23 20:10 waqaschattha

Looks like the timescaledb.enable_compression_indexscan has been disabled by default on TimescaleDB 2.14.1 https://github.com/timescale/timescaledb/pull/6639

Feb 26 '24 17:02 ebreijo

timescaledb
timescaledb copied to clipboard

[Bug]: Performance degradation (5x slower) on chunk compression after update from TimescaleDB 2.9.0 to 2.11.1

What type of bug is this?

What subsystems and features are affected?

What happened?

Findings from Postgres logs provided below

TimescaleDB version affected

PostgreSQL version used

What operating system did you use?

What installation method did you use?

What platform did you run on?

Relevant log output and stack trace

How can we reproduce the bug?

With disabled `SET timescaledb.enable_compression_indexscan = 'OFF'`

With enabled `SET timescaledb.enable_compression_indexscan = 'ON'`

Brief History about Indexscan path introduction

The Caveat:

The Analysis:

Recommendation:

Version Details:

timescaledb timescaledb copied to clipboard

[Bug]: Performance degradation (5x slower) on chunk compression after update from TimescaleDB 2.9.0 to 2.11.1

What type of bug is this?

What subsystems and features are affected?

What happened?

Findings from Postgres logs provided below

TimescaleDB version affected

PostgreSQL version used

What operating system did you use?

What installation method did you use?

What platform did you run on?

Relevant log output and stack trace

How can we reproduce the bug?

With disabled SET timescaledb.enable_compression_indexscan = 'OFF'

With enabled SET timescaledb.enable_compression_indexscan = 'ON'

Brief History about Indexscan path introduction

The Caveat:

The Analysis:

Recommendation:

Version Details:

timescaledb
timescaledb copied to clipboard

With disabled `SET timescaledb.enable_compression_indexscan = 'OFF'`

With enabled `SET timescaledb.enable_compression_indexscan = 'ON'`