Occasional Really Slow Running Updates/Inserts

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