Назад | Перейти на главную страницу

Postgres 10.1 медленно на Ubuntu 16.04

Установка единственного дампа таблицы выполняется значительно медленнее на U16.04 (и выше), чем на U14.04. Тест проводился на том же компьютере с настройками по умолчанию.

testdb=# \d photos_searchlog
                                      Table "public.photos_searchlog"
  Column  |           Type           | Collation | Nullable |                   Default                    
----------+--------------------------+-----------+----------+----------------------------------------------
 id       | integer                  |           | not null | nextval('photos_searchlog_id_seq'::regclass)
 created  | timestamp with time zone |           | not null | 
 updated  | timestamp with time zone |           | not null | 
 lang     | character varying(2)     |           | not null | 
 q        | character varying(255)   |           | not null | 
 hits     | integer                  |           | not null | 
 count    | integer                  |           | not null | 
 ip_list  | text                     |           | not null | 
 locked   | boolean                  |           | not null | 
 ts_list  | text                     |           | not null | 
 ts_count | integer                  |           | not null | 
Indexes:
    "photos_searchlog_pkey" PRIMARY KEY, btree (id)
    "photos_searchlog_lang_q_key" UNIQUE CONSTRAINT, btree (lang, q)
    "photos_searchlog_count" btree (count)
    "photos_searchlog_created" btree (created)
    "photos_searchlog_ts_count" btree (ts_count)
    "photos_searchlog_updated" btree (updated)

testdb=# select count(*) from photos_searchlog;
  count  
---------
 4006671
(1 row)

U16.04 - Время

time psql testdb < searchlog_noowner.sql
SET
SET
SET
SET
SET
SET
SET
SET
SET
CREATE TABLE
CREATE SEQUENCE
ALTER SEQUENCE
ALTER TABLE
COPY 4006671
  setval  
----------
 16211932
(1 row)

ALTER TABLE
ALTER TABLE
CREATE INDEX
CREATE INDEX
CREATE INDEX
CREATE INDEX

real    13m7.987s
user    0m0.688s
sys 0m0.268s

U16.04 - Журналы Postgres 10.1

tail -f postgresql-10-main.log 
    FROM pg_catalog.pg_database d
    ORDER BY 1;
2017-12-31 03:30:59.567 CET [1114] postgres@postgres LOG:  duration: 1.809 ms  statement: SELECT d.datname as "Name",
           pg_catalog.pg_get_userbyid(d.datdba) as "Owner",
           pg_catalog.pg_encoding_to_char(d.encoding) as "Encoding",
           d.datcollate as "Collate",
           d.datctype as "Ctype",
           pg_catalog.array_to_string(d.datacl, E'\n') AS "Access privileges"
    FROM pg_catalog.pg_database d
    ORDER BY 1;
2017-12-31 03:31:27.766 CET [1128] hans@postgres LOG:  duration: 244.787 ms  statement: CREATE DATABASE testdb;
2017-12-31 03:31:40.223 CET [1143] hans@testdb LOG:  duration: 0.098 ms  statement: SET statement_timeout = 0;
2017-12-31 03:31:40.224 CET [1143] hans@testdb LOG:  duration: 0.038 ms  statement: SET lock_timeout = 0;
2017-12-31 03:31:40.224 CET [1143] hans@testdb LOG:  duration: 0.018 ms  statement: SET client_encoding = 'UTF8';
2017-12-31 03:31:40.224 CET [1143] hans@testdb LOG:  duration: 0.017 ms  statement: SET standard_conforming_strings = on;
2017-12-31 03:31:40.224 CET [1143] hans@testdb LOG:  duration: 0.013 ms  statement: SET check_function_bodies = false;
2017-12-31 03:31:40.224 CET [1143] hans@testdb LOG:  duration: 0.012 ms  statement: SET client_min_messages = warning;
2017-12-31 03:31:40.224 CET [1143] hans@testdb LOG:  duration: 0.022 ms  statement: SET search_path = public, pg_catalog;
2017-12-31 03:31:40.224 CET [1143] hans@testdb LOG:  duration: 0.013 ms  statement: SET default_tablespace = '';
2017-12-31 03:31:40.224 CET [1143] hans@testdb LOG:  duration: 0.011 ms  statement: SET default_with_oids = false;
2017-12-31 03:31:40.245 CET [1143] hans@testdb LOG:  duration: 21.011 ms  statement: CREATE TABLE photos_searchlog (
        id integer NOT NULL,
        created timestamp with time zone NOT NULL,
        updated timestamp with time zone NOT NULL,
        lang character varying(2) NOT NULL,
        q character varying(255) NOT NULL,
        hits integer NOT NULL,
        count integer NOT NULL,
        ip_list text NOT NULL,
        locked boolean NOT NULL,
        ts_list text NOT NULL,
        ts_count integer NOT NULL
    );
2017-12-31 03:31:40.250 CET [1143] hans@testdb LOG:  duration: 4.735 ms  statement: CREATE SEQUENCE photos_searchlog_id_seq
        START WITH 1
        INCREMENT BY 1
        NO MINVALUE
        NO MAXVALUE
        CACHE 1;
2017-12-31 03:31:40.255 CET [1143] hans@testdb LOG:  duration: 4.476 ms  statement: ALTER SEQUENCE photos_searchlog_id_seq OWNED BY photos_searchlog.id;
2017-12-31 03:31:40.261 CET [1143] hans@testdb LOG:  duration: 5.990 ms  statement: ALTER TABLE ONLY photos_searchlog ALTER COLUMN id SET DEFAULT nextval('photos_searchlog_id_seq'::regclass);
2017-12-31 03:31:47.883 CET [1095] LOG:  checkpoints are occurring too frequently (20 seconds apart)
2017-12-31 03:31:47.883 CET [1095] HINT:  Consider increasing the configuration parameter "max_wal_size".
2017-12-31 03:31:51.556 CET [1143] hans@testdb LOG:  duration: 11294.817 ms  statement: COPY photos_searchlog (id, created, updated, lang, q, hits, count, ip_list, locked, ts_list, ts_count) FROM stdin;
2017-12-31 03:31:51.560 CET [1143] hans@testdb LOG:  duration: 4.234 ms  statement: SELECT pg_catalog.setval('photos_searchlog_id_seq', 16211932, true);
2017-12-31 03:44:28.160 CET [1143] hans@testdb LOG:  duration: 756599.117 ms  statement: ALTER TABLE ONLY photos_searchlog
        ADD CONSTRAINT photos_searchlog_lang_q_key UNIQUE (lang, q);
2017-12-31 03:44:32.092 CET [1143] hans@testdb LOG:  duration: 3932.650 ms  statement: ALTER TABLE ONLY photos_searchlog
        ADD CONSTRAINT photos_searchlog_pkey PRIMARY KEY (id);
2017-12-31 03:44:36.149 CET [1143] hans@testdb LOG:  duration: 4056.127 ms  statement: CREATE INDEX photos_searchlog_count ON photos_searchlog USING btree (count);
2017-12-31 03:44:40.210 CET [1143] hans@testdb LOG:  duration: 4061.228 ms  statement: CREATE INDEX photos_searchlog_created ON photos_searchlog USING btree (created);
2017-12-31 03:44:44.602 CET [1143] hans@testdb LOG:  duration: 4391.615 ms  statement: CREATE INDEX photos_searchlog_ts_count ON photos_searchlog USING btree (ts_count);
2017-12-31 03:44:48.166 CET [1143] hans@testdb LOG:  duration: 3563.880 ms  statement: CREATE INDEX photos_searchlog_updated ON photos_searchlog USING btree (updated);

U14.04 - Время

time psql testdb < searchlog_noowner.sql
SET
SET
SET
SET
SET
SET
SET
SET
SET
SET
SET
CREATE TABLE
CREATE SEQUENCE
ALTER SEQUENCE
ALTER TABLE
COPY 4006671
  setval  
----------
 16211932
(1 row)

ALTER TABLE
ALTER TABLE
CREATE INDEX
CREATE INDEX
CREATE INDEX
CREATE INDEX

real 1m46.952s
user 0m0.784s
sys 0m0.240s

U14.04 - Журналы Postgres 10.1

tail -f postgresql-10-main.log 
FROM pg_catalog.pg_database d
ORDER BY 1;
2017-12-31 03:32:38.645 CET [17171] postgres@postgres LOG:  duration: 0.618 ms  statement: SELECT d.datname as "Name",
       pg_catalog.pg_get_userbyid(d.datdba) as "Owner",
       pg_catalog.pg_encoding_to_char(d.encoding) as "Encoding",
       d.datcollate as "Collate",
       d.datctype as "Ctype",
       pg_catalog.array_to_string(d.datacl, E'\n') AS "Access privileges"
FROM pg_catalog.pg_database d
ORDER BY 1;
2017-12-31 03:33:22.935 CET [17201] hans@postgres LOG:  duration: 291.882 ms  statement: CREATE DATABASE testdb;
2017-12-31 03:34:09.304 CET [17247] hans@testdb LOG:  duration: 0.069 ms  statement: SET statement_timeout = 0;
2017-12-31 03:34:09.304 CET [17247] hans@testdb LOG:  duration: 0.015 ms  statement: SET lock_timeout = 0;
2017-12-31 03:34:09.304 CET [17247] hans@testdb LOG:  duration: 0.013 ms  statement: SET idle_in_transaction_session_timeout = 0;
2017-12-31 03:34:09.304 CET [17247] hans@testdb LOG:  duration: 0.014 ms  statement: SET client_encoding = 'UTF8';
2017-12-31 03:34:09.304 CET [17247] hans@testdb LOG:  duration: 0.015 ms  statement: SET standard_conforming_strings = on;
2017-12-31 03:34:09.304 CET [17247] hans@testdb LOG:  duration: 0.012 ms  statement: SET check_function_bodies = false;
2017-12-31 03:34:09.304 CET [17247] hans@testdb LOG:  duration: 0.011 ms  statement: SET client_min_messages = warning;
2017-12-31 03:34:09.304 CET [17247] hans@testdb LOG:  duration: 0.010 ms  statement: SET row_security = off;
2017-12-31 03:34:09.304 CET [17247] hans@testdb LOG:  duration: 0.019 ms  statement: SET search_path = public, pg_catalog;
2017-12-31 03:34:09.304 CET [17247] hans@testdb LOG:  duration: 0.010 ms  statement: SET default_tablespace = '';
2017-12-31 03:34:09.304 CET [17247] hans@testdb LOG:  duration: 0.008 ms  statement: SET default_with_oids = false;
2017-12-31 03:34:09.312 CET [17247] hans@testdb LOG:  duration: 8.316 ms  statement: CREATE TABLE photos_searchlog (
    id integer NOT NULL,
    created timestamp with time zone NOT NULL,
    updated timestamp with time zone NOT NULL,
    lang character varying(2) NOT NULL,
    q character varying(255) NOT NULL,
    hits integer NOT NULL,
    count integer NOT NULL,
    ip_list text NOT NULL,
    locked boolean NOT NULL,
    ts_list text NOT NULL,
    ts_count integer NOT NULL
);
2017-12-31 03:34:09.314 CET [17247] hans@testdb LOG:  duration: 1.382 ms  statement: CREATE SEQUENCE photos_searchlog_id_seq
    START WITH 1
    INCREMENT BY 1
    NO MINVALUE
    NO MAXVALUE
    CACHE 1;
2017-12-31 03:34:09.315 CET [17247] hans@testdb LOG:  duration: 1.097 ms  statement: ALTER SEQUENCE photos_searchlog_id_seq OWNED BY photos_searchlog.id;
2017-12-31 03:34:09.316 CET [17247] hans@testdb LOG:  duration: 1.453 ms  statement: ALTER TABLE ONLY photos_searchlog ALTER COLUMN id SET DEFAULT nextval('photos_searchlog_id_seq'::regclass);
2017-12-31 03:34:27.048 CET [17247] hans@testdb LOG:  duration: 17731.032 ms  statement: COPY photos_searchlog (id, created, updated, lang, q, hits, count, ip_list, locked, ts_list, ts_count) FROM stdin;
2017-12-31 03:34:27.049 CET [17247] hans@testdb LOG:  duration: 1.126 ms  statement: SELECT pg_catalog.setval('photos_searchlog_id_seq', 16211932, true);
2017-12-31 03:35:36.752 CET [17247] hans@testdb LOG:  duration: 69703.146 ms  statement: ALTER TABLE ONLY photos_searchlog
    ADD CONSTRAINT photos_searchlog_lang_q_key UNIQUE (lang, q);
2017-12-31 03:35:40.236 CET [17247] hans@testdb LOG:  duration: 3483.664 ms  statement: ALTER TABLE ONLY photos_searchlog
    ADD CONSTRAINT photos_searchlog_pkey PRIMARY KEY (id);
2017-12-31 03:35:44.521 CET [17247] hans@testdb LOG:  duration: 4284.701 ms  statement: CREATE INDEX photos_searchlog_count ON photos_searchlog USING btree (count);
2017-12-31 03:35:48.969 CET [17247] hans@testdb LOG:  duration: 4447.547 ms  statement: CREATE INDEX photos_searchlog_created ON photos_searchlog USING btree (created);
2017-12-31 03:35:52.850 CET [17247] hans@testdb LOG:  duration: 3881.215 ms  statement: CREATE INDEX photos_searchlog_ts_count ON photos_searchlog USING btree (ts_count);
2017-12-31 03:35:56.222 CET [17247] hans@testdb LOG:  duration: 3371.491 ms  statement: CREATE INDEX photos_searchlog_updated ON photos_searchlog USING btree (updated);

Я тестировал это с разными версиями PG, на разных машинах, с включением / выключением autovaccum, с полной базой данных, с отдельными таблицами - но всегда один и тот же результат: U14.04 намного быстрее ...

Может у кого-то есть идея, где «жучок» ...

Спасибо, Ганс

PS: Разница во времени намного больше при сбросе нашей базы данных 5 ГБ.

U14.04: Always around 7 minutes
U16.04:  27 minutes (autovacuum off)
U16.04: 268 minutes (autovacuum on)!!!

Интересно, что ответа никто не нашел ...

Это ошибка glibc: после обновления Ubuntu 14.10 (glibc 2.19) до 15.04 (glibc 2.21) мы наблюдаем большой спад производительности при создании одного конкретного индекса PostgreSQL. Создание индекса теперь занимает более 10 минут, тогда как раньше оно выполнялось примерно за 30 секунд.

https://sourceware.org/bugzilla/show_bug.cgi?id=18441

Этой информации недостаточно, чтобы сказать вам, что происходит. Это может быть сегментация диска или ваша внутренняя конфигурация для PostgreSQL, или сама операционная система выполняет синхронизацию и сбрасывает буфер файловой системы на диск. Или что в 14.04 куча (таблица) уже была в системном буфере - возможно, БД была горячей и страницы не нужно было читать с диска?

Нам нужно будет увидеть два файла конфигурации для обеих версий psql и узнать, было ли это на одном оборудовании.

А если серьезно,> 12 минут на восстановление? Какая разница? Это одноразовая операция. Если вы делаете это периодически или на лету, вам необходимо проверить потоковую репликацию, логическую репликацию и доставку журналов.