Hi all. I am occasionally seeing really slow update/inserts into a fairly
large table. By really slow I mean around 10-40 seconds,
while the majority of queries take milliseconds. I cannot reproduce this
problem myself, but it is occurring multiple times a day
(maybe 30 times).
System Info
---------------
Model: Dell PowerEdge R420
CPU: 12 core Intel(R) Xeon(R) @ 2.20GHz
Memory: 16GB
Disk: PERC H310 Mini Raid Controller using Raid 1
OS: Ubuntu 14.04.3 LTS
DB Settings
----------------
name current_setting
source
-------------------------------+----------------------------------------+----------------------
application_name | psql
| client
auto_explain.log_min_duration | 15s |
configuration file
checkpoint_segments | 16
| configuration file
client_encoding | UTF8
| client
DateStyle | ISO, YMD
| configuration file
default_text_search_config | pg_catalog.english
| configuration file
effective_cache_size | 8GB
| configuration file
external_pid_file |
/var/run/postgresql/9.3-main.pid | configuration file
hot_standby | on
| configuration file
lc_messages | en_CA.UTF-8
| configuration file
lc_monetary | en_CA.UTF-8
| configuration file
lc_numeric | en_CA.UTF-8
| configuration file
lc_time | en_CA.UTF-8
| configuration file
listen_addresses | localhost,x.x.x.x
| configuration file
log_autovacuum_min_duration | -1 |
configuration file
log_checkpoints | on
| configuration file
log_line_prefix | %m %p %v %x
| configuration file
log_lock_waits | on
| configuration file
log_min_duration_statement | 15s |
configuration file
log_timezone | UTC
| configuration file
max_connections | 100
| configuration file
max_stack_depth | 2MB
| environment variable
max_wal_senders | 3
| configuration file
pg_stat_statements.track | all
| configuration file
shared_buffers | 4GB
| configuration file
shared_preload_libraries | pg_stat_statements, auto_explain
| configuration file
ssl | on
| configuration file
TimeZone | UTC
| configuration file
track_activity_query_size | 2048
| configuration file
unix_socket_directories | /var/run/postgresql
| configuration file
wal_keep_segments | 32
| configuration file
wal_level | hot_standby
| configuration file
Schema
-------
Table "public.documents"
Column | Type |
Modifiers
------------------------+-----------------------------+--------------------------------------------------------
id | bigint | not null
default nextval('documents_id_seq'::regclass)
user_id | bigint | not null
biller_id bigint | not null
filename | character varying(255) | not null
resource | character varying(255) | not null
size | integer | not
null
doc_type | character varying(255) | not null
content_type | character varying(255) | not null
account_name | character varying(255) |
account_number | character varying(255) |
bill_date | timestamp without time zone |
due_date | date |
amount | numeric(12,2) |
amount | numeric(12,2) |
amount | numeric(12,2) |
amount | numeric(12,2) |
amount | numeric(12,2) |
paid | boolean |
paid_date | timestamp without time zone |
paid_amount | numeric(12,2) |
contents | text |
contents_search | tsvector |
extra_data | text |
created_at | timestamp without time zone | not null default
now()
updated_at | timestamp without time zone | not null default now()
billercred_id | bigint |
folder_id | bigint |
shasum | character varying(255) |
intake_type | smallint | not null default 1
page_count | smallint |
notes | text |
vendor_name | character varying(255) |
invoice_number | character varying(255) |
tax | numeric(12,2) |
subtotal | numeric(12,2) |
payment_account_number | character varying(255) |
currency | character varying(3) |
payment_method | payment_method |
workflow_state | workflow_states | default
'review'::workflow_states
vendor_id | bigint |
document_type | document_types |
Indexes:
"documents_pkey" PRIMARY KEY, btree (id)
"document_search_ix" gin (contents_search)
"document_user_id_recvd_ix" btree (user_id, bill_date DESC)
Foreign-key constraints:
"documents_biller_id_fkey" FOREIGN KEY (biller_id) REFERENCES
billers(id) ON DELETE SET DEFAULT
"documents_billercred_id_fkey" FOREIGN KEY (billercred_id) REFERENCES
billercreds(id) ON DELETE SET NULL
"documents_folder_id_fkey" FOREIGN KEY (folder_id) REFERENCES
folders(id) ON DELETE CASCADE
"documents_user_id_fkey" FOREIGN KEY (user_id) REFERENCES users(id) ON
DELETE CASCADE
"documents_vendor_id_fkey" FOREIGN KEY (vendor_id) REFERENCES
vendors(id) ON DELETE SET NULL
Referenced by:
TABLE "document_billcom_actions" CONSTRAINT
"document_billcom_actions_document_id_fkey" FOREIGN KEY (document_id)
REFERENCES documents(id) ON DELETE CASCADE
TABLE "document_box_actions" CONSTRAINT
"document_box_actions_document_id_fkey" FOREIGN KEY (document_id)
REFERENCES documents(id) ON DELETE CASCADE
TABLE "document_email_forwarding_actions" CONSTRAINT
"document_email_forwarding_actions_document_id_fkey" FOREIGN KEY
(document_id) REFERENCES documents(id) ON DELETE CASCADE
TABLE "document_qbo_actions" CONSTRAINT
"document_qbo_actions_document_id_fkey" FOREIGN KEY (document_id)
REFERENCES documents(id) ON DELETE CASCADE
TABLE "document_xero_actions" CONSTRAINT
"document_xero_actions_document_id_fkey" FOREIGN KEY (document_id)
REFERENCES documents(id) ON DELETE CASCADE
TABLE "document_xerofiles_actions" CONSTRAINT
"document_xerofiles_actions_document_id_fkey" FOREIGN KEY (document_id)
REFERENCES documents(id) ON DELETE CASCADE
TABLE "documenttagmap" CONSTRAINT "documenttagmap_document_id_fkey"
FOREIGN KEY (document_id) REFERENCES documents(id) ON DELETE CASCADE
TABLE "synced_docs" CONSTRAINT "synced_docs_doc_id_fkey" FOREIGN KEY
(doc_id) REFERENCES documents(id) ON DELETE CASCADE
Triggers:
document_search_update BEFORE INSERT OR UPDATE ON documents FOR EACH
ROW EXECUTE PROCEDURE tsvector_update_trigger('contents_search',
'pg_catalog.english', 'contents', 'filename', 'account_name',
'account_number')
document_updated_at_t BEFORE UPDATE ON documents FOR EACH ROW EXECUTE
PROCEDURE update_updated_at_column()
documents_count BEFORE INSERT OR DELETE ON documents FOR EACH ROW
EXECUTE PROCEDURE count_trig()
folder_document_count_trig BEFORE INSERT OR DELETE OR UPDATE ON
documents FOR EACH ROW EXECUTE PROCEDURE update_folder_count()
tags_in_trash_document_count_trig BEFORE DELETE OR UPDATE ON documents
FOR EACH ROW EXECUTE PROCEDURE update_tag_trash_count()
Table/Index Sizes
-----------------
Current size:
6841 MB | pg_toast_17426
2486 MB | document_search_ix
2172 MB | documents
188 MB | pg_toast_17426_index
113 MB | document_user_id_recvd_ix
76 MB | documents_pkey
Size after building on a new machine from pg_dump:
5564 MB | pg_toast_1599236
1882 MB | documents
1666 MB | document_search_ix
73 MB | pg_toast_1599236_index
40 MB | document_user_id_recvd_ix
Things to know about the table/DB:
----------------------------------
- We currently inserting ~ 5000-10000 documents a day
- We extract text from the documents and store it in the contents field for
full text search
- In the last few months we've added a feature that allows users to update
columns (date, amount, etc), so we're seeing a lot more updates to
the table than before
- 2 massive updates were done to the table in the last few months in which
a particular column was updated for each row in the table
- We're running a pg_dump every hour which takes around 10 min.
What I've tried
---------------
Logging checkpoints: The slow queries happen even in between checkpoints
Logging locks: There are no logs indicating that the slow query is the
result of a lock
Explain plan: Nothing strange, updates are using documents_pkey index
Trying another machine: I switched over to our replica on another box and
was still seeing slow queries
Doing backups less frequently: Slow queries occur even when backup is not
running
Rebuilding document_search_ix index: The index rebuild reduced the index
size from about 4500MB to 1500MB. This didn't appear to reduce the slow
queries
and the size is now at ~ 2400MB after
less than a week
Running vacuum analyze after rebuilding index: Didn't appear to help
Matching iotop output to slow query output: INSERTs are reading a lot of
data, 22MB in this case, but I don't know how to utilize this information.
14:23:03 22739 be/4 postgres 702.11 K/s 66.87 K/s 0.00 % 25.55 %
postgres: ourusername ourdb 192.x.x.x(51168) INSERT
14:23:04 22739 be/4 postgres 2.48 M/s 96.51 K/s 0.00 % 96.33 %
postgres: ourusername ourdb 192.x.x.x(51168) INSERT
14:23:05 22739 be/4 postgres 1221.82 K/s 43.77 K/s 0.00 % 53.84 %
postgres: ourusername ourdb 192.x.x.x(51168) INSERT
14:23:06 22739 be/4 postgres 1242.40 K/s 94.73 K/s 0.00 % 51.53 %
postgres: ourusername ourdb 192.x.x.x(51168) INSERT
14:23:07 22739 be/4 postgres 1376.88 K/s 46.15 K/s 0.00 % 59.85 %
postgres: ourusername ourdb 192.x.x.x(51168) INSERT
14:23:08 22739 be/4 postgres 563.74 K/s 37.09 K/s 0.00 % 29.03 %
postgres: ourusername ourdb 192.x.x.x(51168) INSERT
14:23:09 22739 be/4 postgres 1267.57 K/s 81.54 K/s 0.00 % 47.95 %
postgres: ourusername ourdb 192.x.x.x(51168) INSERT
14:23:10 22739 be/4 postgres 1080.95 K/s 59.43 K/s 0.00 % 48.21 %
postgres: ourusername ourdb 192.x.x.x(51168) INSERT
14:23:11 22739 be/4 postgres 1041.17 K/s 125.98 K/s 0.00 % 49.86 %
postgres: ourusername ourdb 192.x.x.x(51168) INSERT
14:23:13 22739 be/4 postgres 1019.91 K/s 138.55 K/s 0.00 % 42.42 %
postgres: ourusername ourdb 192.x.x.x(51168) INSERT
14:23:14 22739 be/4 postgres 856.88 K/s 103.86 K/s 0.00 % 31.88 %
postgres: ourusername ourdb 192.x.x.x(51168) INSERT
14:23:15 22739 be/4 postgres 1284.18 K/s 170.73 K/s 0.00 % 52.36 %
postgres: ourusername ourdb 192.x.x.x(51168) INSERT
14:23:16 22739 be/4 postgres 1188.97 K/s 74.31 K/s 0.00 % 51.59 %
postgres: ourusername ourdb 192.x.x.x(51168) INSERT
14:23:17 22739 be/4 postgres 1088.19 K/s 111.42 K/s 0.00 % 44.45 %
postgres: ourusername ourdb 192.x.x.x(51168) INSERT
14:23:18 22739 be/4 postgres 1261.87 K/s 133.61 K/s 0.00 % 49.08 %
postgres: ourusername ourdb 192.x.x.x(51168) INSERT
14:23:19 22739 be/4 postgres 1203.82 K/s 137.58 K/s 0.00 % 52.22 %
postgres: ourusername ourdb 192.x.x.x(51168) INSERT
14:23:20 22739 be/4 postgres 1399.45 K/s 133.63 K/s 0.00 % 45.76 %
postgres: ourusername ourdb 192.x.x.x(51168) INSERT
14:23:21 22739 be/4 postgres 1380.05 K/s 126.13 K/s 0.00 % 57.53 %
postgres: ourusername ourdb 192.x.x.x(51168) INSERT
14:23:22 22739 be/4 postgres 1236.00 K/s 148.47 K/s 0.00 % 53.78 %
postgres: ourusername ourdb 192.x.x.x(51168) INSERT
What I haven't tried
--------------------
- more aggressive auto-vacuum
- trying gist table for full text search index instead of gin
- removing full text search altogether (are users don't use it very much)
- rebuilding the production table
- vacuum full
Any help on what the issue might be or how to debug further would be
amazing. I'd like to understand this issue better,
both for my business as well as for my own understanding of databases.
Dave Stibrany
