"ERROR: canceling statement due to statement timeout" during VACUUM

[ramusus]

I'm starting pgcompact with command:

$ pgcompact --all --reindex -v info -U postgres

and it works with some tables, but crashes with error. After restarting it crashes again with the same error, but ON ANOTHER TABLE. And I don't see that table in the output between tables processed by the next call. I start to google the error and all recomendations is about setting variable _statementtimeout, which i have by default:

#statement_timeout = 0          # in milliseconds, 0 is disabled

Output log I see (dates are different, because i copied from different execution times):

$ pgcompact --all --reindex -v info -U postgres
Sat Feb  8 20:35:47 2014 INFO Database connection method: psql.
Sat Feb  8 20:35:47 2014 postgres INFO Created environment.
Sat Feb  8 20:35:47 2014 postgres INFO Statictics calculation method: pgstattuple.
Sat Feb  8 20:35:47 2014 template1 INFO Created environment.
Sat Feb  8 20:35:47 2014 template1 NOTICE Statictics calculation method: approximation.
Sat Feb  8 20:35:47 2014 manufacture INFO Created environment.
Sat Feb  8 20:35:47 2014 manufacture INFO Statictics calculation method: pgstattuple.
Sat Feb  8 20:35:48 2014 manufacture, public.ads_ad INFO Vacuum initial: 0 pages left, duration 0.032 seconds.
......
Sat Feb  8 16:46:02 2014 manufacture, public.facebook_posts_post_like_users INFO Skipping reindex: public.facebook_posts_post_like_users_user_id, 11.40% space to compact from 20% minimum required.
Sat Feb  8 16:46:02 2014 manufacture, public.facebook_posts_post_like_users INFO Skipping reindex: public.facebook_posts_post_like_users_post_id, 19.20% space to compact from 20% minimum required.
Sat Feb  8 16:46:05 2014 manufacture, public.facebook_posts_post_like_users INFO Reindex: public.facebook_posts_post_like_users_pkey, initial size 7394 pages (58 MB), has been reduced by 30% (18 MB), duration 2.593 seconds, attempts 1.
Sat Feb  8 16:46:05 2014 manufacture, public.facebook_posts_post_like_users NOTICE Processing complete.
Sat Feb  8 16:46:05 2014 manufacture, public.facebook_posts_post_like_users NOTICE Processing results: 12485 pages left (35350 pages including toasts and indexes), size reduced by 0 bytes (18 MB including toasts and indexes) in total.
Sat Feb  8 16:46:06 2014 manufacture, public.facebook_page_activity_groupuser ERROR A database error occurred, exiting:
DatabaseError Can not executie command:
 VACUUM public.facebook_page_activity_groupuser
 ERROR:  canceling statement due to statement timeout

One time I receive another error, so it varies from time to time:

Sat Feb  8 20:57:36 2014 manufacture, public.posts_users_activity_postuseractivitystat ERROR A database error occurred, exiting:
DatabaseError Can not executie command: 
 CREATE INDEX CONCURRENTLY pgcompact_index_11386 ON posts_users_activity_postuseractivitystat USING btree (actions_count); -- manufacture
 ERROR:  canceling statement due to statement timeout

The non-default settings are:

SELECT name, current_setting(name) FROM pg_settings WHERE source = 'configuration file'

"archive_command";"cp %p /var/lib/postgresql/9.1/main/pg_xlog_archive/%f"
"archive_mode";"on"
"autovacuum";"on"
"checkpoint_completion_target";"0.9"
"checkpoint_segments";"128"
"constraint_exclusion";"on"
"default_statistics_target";"50"
"default_text_search_config";"pg_catalog.english"
"effective_cache_size";"44GB"
"external_pid_file";"/var/run/postgresql/9.1-main.pid"
"lc_messages";"en_US.UTF-8"
"lc_monetary";"en_US.UTF-8"
"lc_numeric";"en_US.UTF-8"
"lc_time";"en_US.UTF-8"
"listen_addresses";"*"
"log_autovacuum_min_duration";"0"
"log_checkpoints";"on"
"log_connections";"on"
"log_directory";"pg_log"
"log_disconnections";"on"
"log_line_prefix";"%t [%p]: [%l-1] "
"log_lock_waits";"on"
"log_min_duration_statement";"2s"
"log_temp_files";"0"
"logging_collector";"on"
"maintenance_work_mem";"6GB"
"max_connections";"80"
"max_stack_depth";"7MB"
"max_wal_senders";"5"
"port";"5432"
"shared_buffers";"15GB"
"ssl";"on"
"track_counts";"on"
"unix_socket_directory";"/var/run/postgresql"
"vacuum_cost_delay";"10ms"
"wal_buffers";"8MB"
"wal_keep_segments";"2000"
"wal_level";"hot_standby"
"work_mem";"1GB"

Any ideas, how to solve?

[grayhemp]

You probably were in either master or v1.0testing branch before the 98618a6918bf7df154d10ef201251efcf0914704 commit (Added forgoten LOCAL in the ALTER's SET). The master branch is a development one and 1.0testing is used to fix pre-release versions to find bugs by public testing. I don't recommend using either of them except if you are developing new features or perform testing. Instead use the stable branch that currently contains thr v1.0.1 release or follow the instructions on the main page of the toolkit's repository.

[ramusus]

Updated pgcompact from stable branch, but the error is still here:

Sat Feb  8 22:41:44 2014 manufacture, public.posts_users_activity_postuseractivitystat ERROR A database error occurred, exiting:
DatabaseError Can not executie command:
 CREATE INDEX CONCURRENTLY pgcompact_index_15493 ON posts_users_activity_postuseractivitystat USING btree (date_to); -- manufacture
 ERROR:  canceling statement due to statement timeout

another time

Sat Feb  8 22:43:59 2014 manufacture, public.posts_users_activity_postuseractivitystat ERROR A database error occurred, exiting:
DatabaseError Can not executie command: 
 CREATE INDEX CONCURRENTLY pgcompact_index_15611 ON posts_users_activity_postuseractivitystat USING btree (user_object_id); -- manufacture
 ERROR:  canceling statement due to statement timeout 

[grayhemp]

Could you please run it with -v debug0 and show me the log output?

[ramusus]

Sat Feb  8 23:18:12 2014 manufacture, public.posts_users_activity_postuseractivitystat INFO Skipping reindex: public.posts_users_activity_postuser
activitystat_date_from, 0.12% space to compact from 20% minimum required.
Sat Feb  8 23:18:12 2014 manufacture, public.posts_users_activity_postuseractivitystat DEBUG0 Executed SQL: duration 0.001s, statement:
SELECT size, ceil(size / bs) AS page_count
FROM (
    SELECT
        pg_catalog.pg_relation_size('public.pgcompact_index_15493'::regclass) AS size,
        current_setting('block_size')::real AS bs
) AS sq

Sat Feb  8 23:18:12 2014 manufacture, public.posts_users_activity_postuseractivitystat DEBUG0 Executed SQL: duration 0.003s, statement:
SELECT
    CASE
        WHEN avg_leaf_density = 'NaN' THEN 0
        ELSE
            round(
                (100 * (1 - avg_leaf_density / fillfactor))::numeric, 2
            )
        END AS free_percent,
    CASE
        WHEN avg_leaf_density = 'NaN' THEN 0
        ELSE
            ceil(
                index_size * (1 - avg_leaf_density / fillfactor)
            )
        END AS free_space
FROM (
    SELECT
        coalesce(
            (
                SELECT (
                    regexp_matches(
                        reloptions::text, E'.*fillfactor=(\\d+).*'))[1]),
            '90')::real AS fillfactor,
        pgsi.*
    FROM pg_catalog.pg_class
    CROSS JOIN public.pgstatindex(
        'public.pgcompact_index_15493') AS pgsi
    WHERE pg_catalog.pg_class.oid = 'public.pgcompact_index_15493'::regclass
) AS oq

Sat Feb  8 23:18:12 2014 manufacture, public.posts_users_activity_postuseractivitystat INFO Skipping reindex: public.pgcompact_index_15493, 0.20% space to compact from 20% minimum required.
Sat Feb  8 23:18:12 2014 manufacture, public.posts_users_activity_postuseractivitystat DEBUG0 Executed SQL: duration 0.001s, statement:
SELECT size, ceil(size / bs) AS page_count
FROM (
    SELECT
        pg_catalog.pg_relation_size('public.posts_users_activity_postuseractivitystat_date_to'::regclass) AS size,
        current_setting('block_size')::real AS bs
) AS sq

Sat Feb  8 23:18:12 2014 manufacture, public.posts_users_activity_postuseractivitystat DEBUG0 Executed SQL: duration 0.003s, statement:
SELECT
    CASE
        WHEN avg_leaf_density = 'NaN' THEN 0
        ELSE
            round(
                (100 * (1 - avg_leaf_density / fillfactor))::numeric, 2
            )
        END AS free_percent,
    CASE
        WHEN avg_leaf_density = 'NaN' THEN 0
        ELSE
            ceil(
                index_size * (1 - avg_leaf_density / fillfactor)
            )
        END AS free_space
FROM (
    SELECT
        coalesce(
            (
                SELECT (
                    regexp_matches(
                        reloptions::text, E'.*fillfactor=(\\d+).*'))[1]),
            '90')::real AS fillfactor,
        pgsi.*
    FROM pg_catalog.pg_class
    CROSS JOIN public.pgstatindex(
        'public.posts_users_activity_postuseractivitystat_date_to') AS pgsi
    WHERE pg_catalog.pg_class.oid = 'public.posts_users_activity_postuseractivitystat_date_to'::regclass
) AS oq

Sat Feb  8 23:18:12 2014 manufacture, public.posts_users_activity_postuseractivitystat INFO Skipping reindex: public.posts_users_activity_postuser
activitystat_date_to, 0.20% space to compact from 20% minimum required.
Sat Feb  8 23:18:12 2014 manufacture, public.posts_users_activity_postuseractivitystat DEBUG0 Executed SQL: duration 0.001s, statement:
SELECT size, ceil(size / bs) AS page_count
FROM (
    SELECT
        pg_catalog.pg_relation_size('public.posts_users_activity_postuseractivitystat_user_object_id'::regclass) AS size,
        current_setting('block_size')::real AS bs
) AS sq

Sat Feb  8 23:18:12 2014 manufacture, public.posts_users_activity_postuseractivitystat DEBUG0 Executed SQL: duration 0.007s, statement:
SELECT
    CASE
        WHEN avg_leaf_density = 'NaN' THEN 0
        ELSE
            round(
                (100 * (1 - avg_leaf_density / fillfactor))::numeric, 2
            )
        END AS free_percent,
    CASE
        WHEN avg_leaf_density = 'NaN' THEN 0
        ELSE
            ceil(
                index_size * (1 - avg_leaf_density / fillfactor)
            )
        END AS free_space
FROM (
    SELECT
        coalesce(
            (
                SELECT (
                    regexp_matches(
                        reloptions::text, E'.*fillfactor=(\\d+).*'))[1]),
            '90')::real AS fillfactor,
        pgsi.*
    FROM pg_catalog.pg_class
    CROSS JOIN public.pgstatindex(
        'public.posts_users_activity_postuseractivitystat_user_object_id') AS pgsi
    WHERE pg_catalog.pg_class.oid = 'public.posts_users_activity_postuseractivitystat_user_object_id'::regclass
) AS oq

Sat Feb  8 23:39:01 2014 manufacture, public.posts_users_activity_postuseractivitystat DEBUG0 Executed SQL: duration 1248.902s, statement:
CREATE INDEX CONCURRENTLY pgcompact_index_18874 ON posts_users_activity_postuseractivitystat USING btree (user_object_id); -- manufacture
Sat Feb  8 23:39:18 2014 manufacture, public.posts_users_activity_postuseractivitystat DEBUG0 Executed SQL: duration 13.150s, statement:
BEGIN; SET statement_timeout TO 1000; DROP INDEX public.posts_users_activity_postuseractivitystat_user_object_id; ALTER INDEX public.pgcompact_index_18874 RENAME TO posts_users_activity_postuseractivitystat_user_object_id; END; -- manufacture
Sat Feb  8 23:39:18 2014 manufacture, public.posts_users_activity_postuseractivitystat DEBUG0 Executed SQL: duration 0.001s, statement:
SELECT size, ceil(size / bs) AS page_count
FROM (
    SELECT
        pg_catalog.pg_relation_size('public.posts_users_activity_postuseractivitystat_user_object_id'::regclass) AS size,
        current_setting('block_size')::real AS bs
) AS sq

Sat Feb  8 23:39:18 2014 manufacture, public.posts_users_activity_postuseractivitystat INFO Reindex: public.posts_users_activity_postuseractivitystat_user_object_id, initial size 5447 pages (43 MB), has been reduced by 55% (24 MB), duration 1262.052 seconds, attempts 5.
Sat Feb  8 23:39:18 2014 manufacture, public.posts_users_activity_postuseractivitystat DEBUG0 Executed SQL: duration 0.001s, statement:
SELECT size, ceil(size / bs) AS page_count
FROM (
    SELECT
        pg_catalog.pg_relation_size('public.posts_users_activity_postuseractivitystat_period'::regclass) AS size,
        current_setting('block_size')::real AS bs
) AS sq

Sat Feb  8 23:39:18 2014 manufacture, public.posts_users_activity_postuseractivitystat DEBUG0 Executed SQL: duration 0.024s, statement:
SELECT
    CASE
        WHEN avg_leaf_density = 'NaN' THEN 0
        ELSE
            round(
                (100 * (1 - avg_leaf_density / fillfactor))::numeric, 2
            )
        END AS free_percent,
    CASE
        WHEN avg_leaf_density = 'NaN' THEN 0
        ELSE
            ceil(
                index_size * (1 - avg_leaf_density / fillfactor)
            )
        END AS free_space
FROM (
    SELECT
        coalesce(
            (
                SELECT (
                    regexp_matches(
                        reloptions::text, E'.*fillfactor=(\\d+).*'))[1]),
            '90')::real AS fillfactor,
        pgsi.*
    FROM pg_catalog.pg_class
    CROSS JOIN public.pgstatindex(
        'public.posts_users_activity_postuseractivitystat_period') AS pgsi
    WHERE pg_catalog.pg_class.oid = 'public.posts_users_activity_postuseractivitystat_period'::regclass
) AS oq

Sat Feb  8 23:39:19 2014 manufacture, public.posts_users_activity_postuseractivitystat ERROR A database error occurred, exiting:
DatabaseError Can not executie command:
 CREATE INDEX CONCURRENTLY pgcompact_index_18874 ON posts_users_activity_postuseractivitystat USING btree (period); -- manufacture
 ERROR:  canceling statement due to statement timeout

[grayhemp]

Oh, I see. It looks like I forgot to rebuild the fatpacked version before releasing, my fault. Fixed now. Get the stable version once again. And, please, let me know if everything is okay. Thanks for the feedback.

[ramusus]

Now it works fine, thanks a lot!