Postgres 10.1 slow on Ubuntu 16.04

Question

Installing a single table-dump is significant slower on U16.04 (and higher) than on U14.04. The test was done on the same computer with default settings.

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

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 logs

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

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 logs

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

I tested this with different PG versions, on different machines, with autovaccum on/off, with a complete database, with single tables - but always the same result: U14.04 is much faster...

May be someone has an idea where the "bug" is...

Thanks Hans

PS: The time difference is much bigger when dumping our 5 GB database.

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

score 0 · Answer 1 · answered Jan 01 '18 at 06:59

0

This isn't enough information to tell you what's happening. It could be disk segmentation or your internal configuration for PostgreSQL, or the operating system itself fsyncing and flushing the file system buffer to disk. Or that in 14.04 the heap (table) was already in the system buffer -- perhaps the DB was hot and the pages didn't have to be read from disk?

We'd have to see the two config files for both version of psql, and we'd have to know if this was on the same hardware.

But seriously, >12min on a restore? Who cares? It's a one time operation. If you're doing it periodically or on the fly you need to check out the streaming replication, logical replication, and wal log shipping.

answered Jan 01 '18 at 06:59

Evan Carroll

2,373
10
34
53

Thanks for your answer. As stated above it was always a fresh installation (Ubuntu and Postgres) on the same system with standard configurations (/etc/postgresql/10/main/postgresql.conf). – Barmi Jan 01 '18 at 22:02
The example shows dumping ONE table only... Our database has nearly 100 tables and then the time difference is really enormous. In production it's the same issue. – Barmi Jan 01 '18 at 22:09
In this example it's only the statement: ALTER TABLE ONLY photos_searchlog ADD CONSTRAINT photos_searchlog_lang_q_key UNIQUE (lang, q); which causes the delay. Any ideas why this statement is problematic? – Barmi Jan 02 '18 at 13:08
Ok.. now I found out the problem are the entries in column q -> These are search queries typed in by users, e.g: ภาพตัดปลาฉลาม, παγκοι φιλιας, dégardé de bleu All entries are in UTF-8. If I replace these entries by non UTF-8 characters like letters and numbers everything is running super fast on U16.04. What can be the difference between U14.04 and U16.04 regarding encoding? The locale is the same on both machines. Also all tables are UTF-8 encoded. Any suggestions? – Barmi Jan 02 '18 at 23:38

score 0 · Answer 2 · answered Feb 13 '18 at 02:23

Interesting that nobody found the answer...

It's a glibc bug: After upgrading from Ubuntu 14.10 (glibc 2.19) to 15.04 (glibc 2.21), we are experiencing a big performance regression in one particular PostgreSQL index creation. The index creation now takes more than 10 minutes, while before it was done in about 30 seconds.

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

Postgres 10.1 slow on Ubuntu 16.04

2 Answers2