Re: Do I have a hardware or a software problem?

On Dec 11, 2012, at 2:51 AM, Niels Kristian Schjødt <nielskristian(at)autouncle(dot)com> wrote:

> #### Pitch ######################################################################################
> I previously posted this question http://archives.postgresql.org/pgsql-performance/2012-11/msg00289.php about a performance issue with an update query.
> The question evolved into a more general discussion about my setup, and about a lot of I/O wait that I was encountering. Since then, I have gotten a whole lot more familiar with measuring things, and now I "just" need some experienced eyes to judge which direction I should go in - do I have a hardware issue, or a software issue - and what action should I take?
>
> ##### My setup #############################################################################
> The use case:
> At night time we are doing a LOT of data maintenance, and hence the load on the database is very different from the day time. However we would like to be able to do some of it in the daytime, it's simply just too "heavy" on the database as is right now. The stats shown below is from one of those "heavy" load times.
>
> Hardware:
> - 32Gb ram
> - 8 core Xeon E3-1245 processor
> - Two SEAGATE ST33000650NS drives (called sdc and sdd in the stats) in a softeware RAID1 array (called md2 in the stats)
> - Two INTEL SSDSC2CW240A3 SSD drives (called sda and sdb in the stats) in a software RAID1 (called md3 in the stats)
>
> Software:
> Postgres 9.2 running on 64bit ubuntu 12.04 with kernel 3.2
>
> Configuration:
> # postgresql.conf (a shortlist of everything changed from the default)
> data_directory = '/var/lib/postgresql/9.2/main'
> hba_file = '/etc/postgresql/9.2/main/pg_hba.conf'
> ident_file = '/etc/postgresql/9.2/main/pg_ident.conf'
> external_pid_file = '/var/run/postgresql/9.2-main.pid'
> listen_addresses = '192.168.0.2, localhost'
> port = 5432
> max_connections = 300
> unix_socket_directory = '/var/run/postgresql'
> wal_level = hot_standby
> synchronous_commit = off
> archive_mode = on
> archive_command = 'rsync -a %p postgres(at)192(dot)168(dot)0(dot)4:/var/lib/postgresql/9.2/wals/%f </dev/null'
> max_wal_senders = 1
> wal_keep_segments = 32
> log_line_prefix = '%t [%p]: [%l-1] user=%u,db=%d '
> datestyle = 'iso, mdy'
> lc_monetary = 'en_US.UTF-8'
> lc_numeric = 'en_US.UTF-8'
> lc_time = 'en_US.UTF-8'
> default_text_search_config = 'pg_catalog.english'
> default_statistics_target = 100
> maintenance_work_mem = 1GB
> checkpoint_completion_target = 0.9
> effective_cache_size = 22GB
> work_mem = 160MB
> wal_buffers = 4MB
> checkpoint_segments = 100
> shared_buffers = 4GB
> checkpoint_timeout = 10min
>
> The kernel has bee tweaked like so:
> vm.dirty_ratio = 10
> vm.dirty_background_ratio = 1
> kernel.shmmax = 8589934592
> kernel.shmall = 17179869184
>
> The pg_xlog folder has been moved onto the SSD array (md3), and symlinked back into the postgres dir.
>

Actually, you should move xlog to rotating drives, since wal logs written sequentially, and everything else to ssd, because of random io pattern.

> ##### The stats ###############################################################
> These are the typical observations/stats I see in one of these periods:
>
> 1)
> At top level this is what I see in new relic:
> https://rpm.newrelic.com/public/charts/6ewGRle6bmc
>
> 2)
> When the database is loaded like this, I see a lot of queries talking up to 1000 times as long, as they would when the database is not loaded so heavily.
>
> 3)
> sudo iostat -dmx (typical usage)
> Linux 3.2.0-33-generic (master-db) 12/10/2012 _x86_64_ (8 CPU)
>
> Device: rrqm/s wrqm/s r/s w/s rMB/s wMB/s avgrq-sz avgqu-sz await r_await w_await svctm %util
> sda 0.00 6.52 3.59 26.61 0.22 0.74 65.49 0.01 0.40 0.77 0.35 0.14 0.43
> sdb 0.00 8.31 0.03 28.38 0.00 0.97 69.63 0.01 0.52 0.27 0.52 0.15 0.43
> sdc 1.71 46.01 34.83 116.62 0.56 4.06 62.47 1.90 12.57 21.81 9.81 1.89 28.66
> sdd 1.67 46.14 34.89 116.49 0.56 4.06 62.46 1.58 10.43 21.66 7.07 1.89 28.60
> md1 0.00 0.00 0.00 0.00 0.00 0.00 2.69 0.00 0.00 0.00 0.00 0.00 0.00
> md0 0.00 0.00 0.11 0.24 0.00 0.00 8.00 0.00 0.00 0.00 0.00 0.00 0.00
> md2 0.00 0.00 72.99 161.95 1.11 4.06 45.10 0.00 0.00 0.00 0.00 0.00 0.00
> md3 0.00 0.00 0.05 32.32 0.00 0.74 47.00 0.00 0.00 0.00 0.00 0.00 0.00
>
> 3)
> sudo iotop -oa (running for about a minute or so)
> TID PRIO USER DISK READ DISK WRITE SWAPIN IO> COMMAND
> 292 be/4 root 0.00 B 0.00 B 0.00 % 99.33 % [md2_raid1]
> 2815 be/4 postgres 19.51 M 25.90 M 0.00 % 45.49 % postgres: autovacuum worker process production
> 32553 be/4 postgres 45.74 M 9.38 M 0.00 % 37.89 % postgres: user production 192.168.0.3(58866) UPDATE
> 32570 be/4 postgres 6.91 M 35.02 M 0.00 % 16.71 % postgres: user production 192.168.0.3(35547) idle
> 32575 be/4 postgres 4.06 M 43.90 M 0.00 % 16.62 % postgres: user production 192.168.0.3(35561) SELECT
> 31673 be/4 postgres 4.14 M 52.16 M 0.00 % 16.24 % postgres: user production 192.168.0.3(39112) idle
> 32566 be/4 postgres 4.73 M 44.95 M 0.00 % 15.66 % postgres: user production 192.168.0.3(35531) idle
> 32568 be/4 postgres 4.50 M 33.84 M 0.00 % 14.62 % postgres: user production 192.168.0.3(35543) SELECT
> 32573 be/4 postgres 3.20 M 34.44 M 0.00 % 13.98 % postgres: user production 192.168.0.3(35559) idle
> 31590 be/4 postgres 3.23 M 29.72 M 0.00 % 13.90 % postgres: user production 192.168.0.3(50690) idle in transaction
> 32577 be/4 postgres 5.09 M 25.54 M 0.00 % 13.63 % postgres: user production 192.168.0.3(35563) idle
> 32565 be/4 postgres 2.06 M 35.93 M 0.00 % 13.41 % postgres: user production 192.168.0.3(35529) SELECT
> 32546 be/4 postgres 4.48 M 36.49 M 0.00 % 13.39 % postgres: user production 192.168.0.3(56927) UPDATE waiting
> 32569 be/4 postgres 3.50 M 26.75 M 0.00 % 12.82 % postgres: user production 192.168.0.3(35545) INSERT
> 31671 be/4 postgres 4.58 M 24.45 M 0.00 % 12.76 % postgres: user production 192.168.0.3(34841) idle in transaction
> 32551 be/4 postgres 3.26 M 31.77 M 0.00 % 12.06 % postgres: user production 192.168.0.3(58864) idle in transaction
> 32574 be/4 postgres 5.32 M 32.92 M 0.00 % 11.70 % postgres: user production 192.168.0.3(35560) idle
> 32572 be/4 postgres 3.00 M 32.66 M 0.00 % 11.66 % postgres: user production 192.168.0.3(35558) UPDATE
> 32560 be/4 postgres 5.12 M 25.89 M 0.00 % 11.52 % postgres: user production 192.168.0.3(33886) SELECT
> 32567 be/4 postgres 4.66 M 36.47 M 0.00 % 11.44 % postgres: user production 192.168.0.3(35534) SELECT
> 32571 be/4 postgres 2.86 M 31.27 M 0.00 % 11.31 % postgres: user production 192.168.0.3(35557) SELECT
> 32552 be/4 postgres 4.38 M 28.75 M 0.00 % 11.09 % postgres: user production 192.168.0.3(58865) idle in transaction
> 32554 be/4 postgres 3.69 M 30.21 M 0.00 % 10.90 % postgres: user production 192.168.0.3(58870) UPDATE
> 339 be/3 root 0.00 B 2.29 M 0.00 % 9.81 % [jbd2/md2-8]
> 32576 be/4 postgres 3.37 M 19.91 M 0.00 % 9.73 % postgres: user production 192.168.0.3(35562) idle
> 32555 be/4 postgres 3.09 M 31.96 M 0.00 % 9.02 % postgres: user production 192.168.0.3(58875) SELECT
> 27548 be/4 postgres 0.00 B 97.12 M 0.00 % 7.41 % postgres: writer process
> 31445 be/4 postgres 924.00 K 27.35 M 0.00 % 7.11 % postgres: user production 192.168.0.1(34536) idle
> 31443 be/4 postgres 2.54 M 4.56 M 0.00 % 6.32 % postgres: user production 192.168.0.1(34508) idle
> 31459 be/4 postgres 1480.00 K 21.36 M 0.00 % 5.63 % postgres: user production 192.168.0.1(34543) idle
> 1801 be/4 postgres 1896.00 K 10.89 M 0.00 % 5.57 % postgres: user production 192.168.0.3(34177) idle
> 32763 be/4 postgres 1696.00 K 6.95 M 0.00 % 5.33 % postgres: user production 192.168.0.3(57984) SELECT
> 1800 be/4 postgres 2.46 M 5.13 M 0.00 % 5.24 % postgres: user production 192.168.0.3(34175) SELECT
> 1803 be/4 postgres 1816.00 K 9.09 M 0.00 % 5.16 % postgres: user production 192.168.0.3(34206) idle
> 32578 be/4 postgres 2.57 M 11.62 M 0.00 % 5.06 % postgres: user production 192.168.0.3(35564) SELECT
> 31440 be/4 postgres 3.02 M 4.04 M 0.00 % 4.65 % postgres: user production 192.168.0.1(34463) idle
> 32605 be/4 postgres 1844.00 K 11.82 M 0.00 % 4.49 % postgres: user production 192.168.0.3(40399) idle
> 27547 be/4 postgres 0.00 B 0.00 B 0.00 % 3.93 % postgres: checkpointer process
> 31356 be/4 postgres 1368.00 K 3.27 M 0.00 % 3.93 % postgres: user production 192.168.0.1(34450) idle
> 32542 be/4 postgres 1180.00 K 6.05 M 0.00 % 3.90 % postgres: user production 192.168.0.3(56859) idle
> 32523 be/4 postgres 1088.00 K 4.33 M 0.00 % 3.59 % postgres: user production 192.168.0.3(48164) idle
> 32606 be/4 postgres 1964.00 K 6.94 M 0.00 % 3.51 % postgres: user production 192.168.0.3(40426) SELECT
> 31466 be/4 postgres 1596.00 K 3.11 M 0.00 % 3.47 % postgres: user production 192.168.0.1(34550) idle
> 32544 be/4 postgres 1184.00 K 4.25 M 0.00 % 3.38 % postgres: user production 192.168.0.3(56861) idle
> 31458 be/4 postgres 1088.00 K 1528.00 K 0.00 % 3.33 % postgres: user production 192.168.0.1(34541) idle
> 31444 be/4 postgres 884.00 K 4.23 M 0.00 % 3.27 % postgres: user production 192.168.0.1(34510) idle
> 32522 be/4 postgres 408.00 K 2.98 M 0.00 % 3.27 % postgres: user production 192.168.0.5(38361) idle
> 32762 be/4 postgres 1156.00 K 5.28 M 0.00 % 3.20 % postgres: user production 192.168.0.3(57962) idle
> 32582 be/4 postgres 1084.00 K 3.38 M 0.00 % 2.86 % postgres: user production 192.168.0.5(43104) idle
> 31353 be/4 postgres 2.04 M 3.02 M 0.00 % 2.82 % postgres: user production 192.168.0.1(34444) idle
> 31441 be/4 postgres 700.00 K 2.68 M 0.00 % 2.64 % postgres: user production 192.168.0.1(34465) idle
> 31462 be/4 postgres 980.00 K 3.50 M 0.00 % 2.57 % postgres: user production 192.168.0.1(34547) idle
> 32709 be/4 postgres 428.00 K 3.23 M 0.00 % 2.56 % postgres: user production 192.168.0.5(34323) idle
> 685 be/4 postgres 748.00 K 3.59 M 0.00 % 2.41 % postgres: user production 192.168.0.3(34911) idle
> 683 be/4 postgres 728.00 K 3.19 M 0.00 % 2.38 % postgres: user production 192.168.0.3(34868) idle
> 32765 be/4 postgres 464.00 K 3.76 M 0.00 % 2.21 % postgres: user production 192.168.0.3(58074) idle
> 32760 be/4 postgres 808.00 K 6.18 M 0.00 % 2.16 % postgres: user production 192.168.0.3(57958) idle
> 1912 be/4 postgres 372.00 K 3.03 M 0.00 % 2.16 % postgres: user production 192.168.0.5(33743) idle
> 31446 be/4 postgres 1004.00 K 2.09 M 0.00 % 2.16 % postgres: user production 192.168.0.1(34539) idle
> 31460 be/4 postgres 584.00 K 2.74 M 0.00 % 2.10 % postgres: user production 192.168.0.1(34545) idle
>
> 5) vmstat 1
> procs -----------memory---------- ---swap-- -----io---- -system-- ----cpu----
> r b swpd free buff cache si so bi bo in cs us sy id wa
> 1 1 573424 321080 27124 28504352 0 0 143 618 0 4 2 0 91 7
> 0 1 573424 320764 27124 28504496 0 0 104 15654 3788 4961 1 0 85 14
> 0 1 573424 320684 27124 28504616 0 0 276 12736 4099 5374 0 1 84 15
> 0 1 573424 319672 27124 28504900 0 0 80 7746 3624 4949 2 0 82 16
> 0 1 573424 319180 27124 28504972 0 0 36 12489 3653 4761 2 0 86 12
> 0 1 573424 318184 27132 28505000 0 0 8 10482 3413 4898 0 0 87 13
> 0 1 573424 318424 27132 28505016 0 0 0 9564 2746 4290 0 0 87 13
> 0 1 573424 318308 27168 28505016 0 0 36 10562 1895 2149 0 0 87 12
> 0 3 573424 318208 27168 28505020 0 0 84 18529 3035 3265 1 0 85 14
> 0 1 573424 318732 27176 28505080 0 0 84 14574 2986 3231 0 0 84 16
> 0 2 573424 317588 27176 28505184 0 0 4 6681 1991 2207 2 1 86 12
> 0 1 573424 316852 27176 28505260 0 0 76 7670 2910 3996 2 1 85 13
> 0 1 573424 316632 27184 28505256 0 0 0 7186 2661 3740 0 0 87 12
> 0 1 573424 316720 27188 28505260 0 0 0 2590 1731 2474 0 0 88 12
> 0 1 573424 314252 27192 28505696 0 0 460 11612 1757 2431 0 0 82 18
> 0 2 573424 313504 27192 28505724 0 0 0 19656 1775 2099 0 0 83 17
> 0 3 573424 313300 27196 28505780 0 0 188 6237 2746 3193 2 0 80 17
> 0 2 573424 312736 27200 28506348 0 0 804 18466 5014 6430 2 1 75 23
> 2 35 573424 307564 27200 28509920 0 0 3912 16280 14377 15470 14 3 28 56
> 0 5 573424 282848 27208 28533964 0 0 7484 27580 22017 25938 17 3 17 63
> 1 5 573424 221100 27208 28563360 0 0 2852 3120 19639 28664 12 5 52 31
> 0 4 573428 229912 26704 28519184 0 4 1208 5890 13976 20851 13 3 56 28
> 0 2 573448 234680 26672 28513632 0 20 0 17204 1694 2636 0 0 71 28
> 3 7 573452 220836 26644 28525548 0 4 1540 36370 27928 36551 17 5 50 27
> 1 3 573488 234380 26556 28517416 0 36 584 19066 8275 9467 3 2 60 36
> 0 1 573488 234496 26556 28517852 0 0 56 47429 3290 4310 0 0 79 20
>
> 6) sudo lsof - a hell of a lot of output, I can post it if anyone is interested :-)
>
> #### Notes and thoughts ##############################################################################
>
> As you can see, even though I have moved the pg_xlog folder to the SSD array (md3) the by far largest amount of writes still goes to the regular HDD's (md2), which puzzles me - what can that be?
> From stat 3) (the iostat) I notice that the SSD's doesn't seem to be something near fully utilized - maybe something else than just pg_xlog could be moved her?
> I have no idea if the amount of reads/writes is within the acceptable/capable for my kind of hardware, or if it is far beyond?
> In stat 3) (the iotop) it says that the RAID array (md2) is the most "waiting" part, does that taste like a root cause, or more like a symptom of some other bottleneck?
>
> Thanks, for taking the time to look at by data! :-)