Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

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

Closed
ebreijo opened this issue Jul 28, 2023 · 21 comments

Comments

@ebreijo
Copy link

ebreijo commented Jul 28, 2023

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
image

  • 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
@ebreijo ebreijo added the bug label Jul 28, 2023
@ebreijo
Copy link
Author

ebreijo commented Jul 28, 2023

After doing some digging, I believe that this PR #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

@nikkhils
Copy link
Contributor

nikkhils commented Jul 31, 2023

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

@ebreijo
Copy link
Author

ebreijo commented Jul 31, 2023

@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);

@shhnwz shhnwz self-assigned this Aug 1, 2023
@nikkhils
Copy link
Contributor

nikkhils commented Aug 1, 2023

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

@shhnwz
Copy link
Contributor

shhnwz commented Aug 1, 2023

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?

@ebreijo
Copy link
Author

ebreijo commented Aug 1, 2023

@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

  • image
  • 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
    image
    • After compression
    image
  • 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 #4821. Disabling the timescaledb.enable_compression_indexscan improves the compression time to what it was before the upgrade.

@ebreijo
Copy link
Author

ebreijo commented Aug 1, 2023

@nikkhils

From the timescaledb_information.compression_settings view
image

@shhnwz shhnwz assigned konskov and unassigned shhnwz Aug 3, 2023
@konskov
Copy link
Contributor

konskov commented Aug 3, 2023

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

@konskov konskov removed their assignment Aug 7, 2023
@shhnwz shhnwz self-assigned this Aug 14, 2023
@shhnwz
Copy link
Contributor

shhnwz commented Aug 21, 2023

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

@ebreijo
Copy link
Author

ebreijo commented Aug 21, 2023

@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

@shhnwz
Copy link
Contributor

shhnwz commented Aug 23, 2023

@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

@ebreijo
Copy link
Author

ebreijo commented Aug 23, 2023

@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

@shhnwz
Copy link
Contributor

shhnwz commented Aug 28, 2023

@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:

  1. Compression through Tuplesort path

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

  1. 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.

@ebreijo
Copy link
Author

ebreijo commented Aug 29, 2023

@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)
    image

  • With enabled SET timescaledb.enable_compression_indexscan = 'ON'
    image

  • 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.

@jnidzwetzki
Copy link
Contributor

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.

@waqaschattha
Copy link

waqaschattha commented Oct 7, 2023

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

  1. 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
    );
  1. Create Hyper Table
SELECT create_hypertable(
  'sensor_statuses', 'dtm', create_default_indexes => false, 
  chunk_time_interval => INTERVAL '24 hours', if_not_exists => TRUE);
  1. Create Index
CREATE INDEX IF NOT EXISTS ix_sensor_statuses 
  ON sensor_statuses("device_id", dtm DESC) TABLESPACE sensorstatusesspace;
  1. Attach Tablespace
SELECT attach_tablespace('sensorstatusesspace', 'sensor_statuses', if_not_attached => true);
  1. Enable Compression
ALTER TABLE sensor_statuses SET (timescaledb.compress, timescaledb.compress_segmentby = 'device_id');
  1. 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.

@waqaschattha
Copy link

waqaschattha commented Oct 7, 2023

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

@ebreijo
Copy link
Author

ebreijo commented Feb 26, 2024

Looks like the timescaledb.enable_compression_indexscan has been disabled by default on TimescaleDB 2.14.1 #6639

@antekresic
Copy link
Contributor

Yes, timescaledb.enable_compression_indexscan was disabled by default because of problems like this.

Are you still experiencing issues with slow compression times on the latest versions?

@antekresic antekresic self-assigned this Dec 9, 2024
@ebreijo
Copy link
Author

ebreijo commented Dec 9, 2024

@antekresic I'm not experiencing issues with slow compression on the version I'm running right now which is timescaledb 2.16.1

@antekresic
Copy link
Contributor

That's great! In that case, I'll close out this ticket and feel free to open another one if the issue arises again.

Thanks!

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Projects
None yet
Development

No branches or pull requests

9 participants