Message-ID: <33fadeb6ac1bade5ef01bd08d1fd7807.squirrel@sq.gransy.com>
In-Reply-To: <4E61D6B4.9090804@ai.wu.ac.at>
References: <4E61D6B4.9090804@ai.wu.ac.at>
Date: Mon, 5 Sep 2011 09:48:45 +0200
Subject: Re: Sudden drop in DBb performance
From: "Tomas Vondra" <tv@fuzzy.cz>
To: "Gerhard Wohlgenannt" <wohlg@ai.wu.ac.at>
Cc: pgsql-performance@postgresql.org,
 "Heinz-Peter Lang" <heinz@langatium.net>,
	"Gerhard Wohlgenannt" <wohlg@ai.wu-wien.ac.at>,
	"Weichselbraun, Albert" <albert.weichselbraun@wu.ac.at>
User-Agent: SquirrelMail/1.4.21
MIME-Version: 1.0
Content-Type: text/plain;charset=utf-8
Content-Transfer-Encoding: 8bit
Importance: Normal

On 3 Září 2011, 9:26, Gerhard Wohlgenannt wrote:
> Dear list,
>
> we are encountering serious performance problems with our database.
> Queries which took around 100ms or less last week now take several
> seconds.
>
> The database runs on Ubuntu Server 10.4.3 (kernel: 2.6.32-33) on
> hardware as follows:
> 8-core Intel Xeon CPU with 2.83GHz
> 48 GB RAM
> RAID 5 with 8 SAS disks
> PostgreSQL 8.4.8 (installed from the Ubuntu repository).
>
> Additionally to the DB the machine also hosts a few virtual machines. In
> the past everything worked very well and the described problem occurs
> just out of the blue. We don't know of any postgresql config changes or
> anything else which might explain the performance reduction.
> We have a number of DBs running in the cluster, and the problem seems to
> affect all of them.

What are the virtual machines doing? Are you sure they are not doing a lot
of IO?

>
> We checked the performance of the RAID .. which is reasonable for eg.
> "hdparm -tT". Memory is well used, but not swapping.
> vmstat shows, that the machine isn't using the swap and the load
> shouldn't be also to high:
>    root@host:~# vmstat
>    procs -----------memory---------- ---swap-- -----io---- -system--
> ----cpu----
>     r  b   swpd   free   buff  cache   si   so    bi    bo   in   cs us
> sy id wa
>     0  0      0 308024 884812 40512932    0    0   464   168  353   92
> 4  2 84  9
>
> Bonnie++ results given below, I am no expert at interpreting those :-)
>
>
> Activating log_min_duration shows for instance this query --- there are
> now constantly queries which take absurdely long.
>
> 2011-09-02 22:38:18 CEST LOG:  Dauer: 25520.374 ms  Anweisung: SELECT
> keyword_id FROM keywords.table_x WHERE keyword=E'diplomaten'
>
> db=# explain analyze SELECT keyword_id FROM keywords.table_x WHERE
> keyword=E'diplomaten';
>                                                                                      QUERY
> PLAN
> -----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
>   Index Scan using idx_table_x_keyword on table_x  (cost=0.00..8.29
> rows=1 width=4) (actual time=0.039..0.041 rows=1 loops=1)
>     Index Cond: ((keyword)::text = 'diplomaten'::text)
>   Total runtime: 0.087 ms
> (3 Zeilen)
>
> db=# \d keywords.table_x
>                                           Tabelle »keywords.table_x«
>     Spalte   |        Typ
> |                                              Attribute
> ------------+-------------------+------------------------------------------------------------------------------------------------------
>   keyword_id | integer           | not null Vorgabewert
> nextval('keywords.table_x_keyword_id_seq'::regclass)
>   keyword    | character varying |
>   so         | double precision  |
> Indexe:
>      "table_x_pkey" PRIMARY KEY, btree (keyword_id) CLUSTER
>      "idx_table_x_keyword" btree (keyword)
> Fremdschlüsselverweise von:
>      TABLE "keywords.table_x_has" CONSTRAINT
> "table_x_has_keyword_id_fkey" FOREIGN KEY (keyword_id) REFERENCES
> keywords.table_x(keyword_id) ON UPDATE CASCADE ON DELETE CASCADE

But in this explain analyze, the query finished in 41 ms. Use auto-explain
contrib module to see the explain plan of the slow execution.

> Could you be so kind and give us any advice how to track down the
> problem or comment on possible reasons???

One of the things

>
> Thank you very much in advance!!!
>
> Regards,
>   heinz + gerhard
>
>
>
>
>
>              name
> |                                               current_setting
> ----------------------------+-------------------------------------------------------------------------------------------------------------
>   version                    | PostgreSQL 8.4.8 on x86_64-pc-linux-gnu,
> compiled by GCC gcc-4.4.real (Ubuntu 4.4.3-4ubuntu5) 4.4.3, 64-bit
>   archive_command            | /usr/local/sbin/weblyzard-wal-archiver.sh
> %p %f
>   archive_mode               | on
>   checkpoint_segments        | 192
>   effective_cache_size       | 25000MB
>   external_pid_file          | /var/run/postgresql/8.4-main.pid
>   full_page_writes           | on
>   geqo                       | on
>   lc_collate                 | de_AT.UTF-8
>   lc_ctype                   | de_AT.UTF-8
>   listen_addresses           | *
>   log_line_prefix            | %t
>   log_min_duration_statement | 3s
>   maintenance_work_mem       | 500MB
>   max_connections            | 250
>   max_stack_depth            | 2MB
>   port                       | 5432
>   server_encoding            | UTF8
>   shared_buffers             | 7000MB
>   ssl                        | on
>   TimeZone                   | localtime
>   unix_socket_directory      | /var/run/postgresql
>   work_mem                   | 256MB
>
>
> Results of Bonnie++
>
> Version  1.96       ------Sequential Output------ --Sequential Input-
> --Random-
> Concurrency   1     -Per Chr- --Block-- -Rewrite- -Per Chr- --Block--
> --Seeks--
> Machine        Size K/sec %CP K/sec %CP K/sec %CP K/sec %CP K/sec %CP
> /sec %CP
> voyager         95G  1400  93 27804   3 16324   2  2925  96 41636   3
> 374.9   4
> Latency              7576us      233s      164s   15647us   13120ms
> 3302ms
> Version  1.96       ------Sequential Create------ --------Random
> Create--------
> voyager             -Create-- --Read--- -Delete-- -Create-- --Read---
> -Delete--
>                files  /sec %CP  /sec %CP  /sec %CP  /sec %CP  /sec %CP
> /sec %CP
>                   16   141   0 +++++ +++   146   0   157   0 +++++ +++
> 172   0
> Latency              1020ms     128us    9148ms     598ms      37us
> 485ms
>

That seems a bit slow ... 27MB/s for writes and 41MB/s forreads is ait
slow with 8 drives.

Tomas