All my sar statistics sar -r 11:40:02 AM kbmemfree kbmemused %memused kbbuffers kbcached kbcommit %commit 01:15:01 PM 269108 32608084 99.18 367144 29707240 10289444 27.83 01:20:01 PM 293560 32583632 99.11 367428 29674272 10287136 27.82 01:25:01 PM 417640 32459552 98.73 366148 29563220 10289220 27.83 01:30:01 PM 399448 32477744 98.79 366812 29596520 10298876 27.85 01:35:01 PM 432332 32444860 98.69 367412 29616524 10277484 27.80
sar -d -p 11:40:02 AM DEV tps rd_sec/s wr_sec/s avgrq-sz avgqu-sz await svctm %util 01:15:01 PM vg_root-lv_pgsql 73.10 116.59 540.15 8.98 6.98 95.44 1.61 11.78 01:20:01 PM vg_root-lv_pgsql 71.39 170.21 508.21 9.50 5.44 76.23 1.72 12.31 01:25:01 PM vg_root-lv_pgsql 54.32 136.21 381.53 9.53 3.58 65.98 1.81 9.85 01:30:01 PM vg_root-lv_pgsql 81.35 167.98 585.25 9.26 8.15 100.13 1.63 13.25 01:35:01 PM vg_root-lv_pgsql 66.75 126.02 482.72 9.12 5.59 83.73 1.78 11.90 sar -u ALL 11:40:02 AM CPU %usr %nice %sys %iowait %steal %irq %soft %guest %idle 01:15:01 PM all 8.57 0.00 1.52 1.46 0.00 0.00 0.05 0.00 88.40 01:20:01 PM all 8.50 0.00 1.53 1.61 0.00 0.00 0.05 0.00 88.31 01:25:01 PM all 9.00 0.00 1.78 1.27 0.00 0.00 0.06 0.00 87.89 01:30:01 PM all 9.58 0.00 1.63 1.71 0.00 0.00 0.06 0.00 87.01 01:35:01 PM all 8.75 0.00 1.47 1.57 0.00 0.00 0.06 0.00 88.15 As you say i install perf and get statistics with command perf record -g -f -u postgres -e block:block_rq_*,syscalls:sys_enter_write,syscalls:sys_enter_fsync But i really don't understand perf report, what values i need to see. Could you help me with advice how to read perf report. What events from perf list i shoud trace, and what the good and bad values in this report depend of my hardware? 2013/11/7 Merlin Moncure <mmonc...@gmail.com> > On Sat, Nov 2, 2013 at 1:54 PM, Евгений Селявка <evg.selya...@gmail.com> > wrote: > > Please help with advice! > > > > Server > > HP ProLiant BL460c G1 > > > > Architecture: x86_64 > > CPU op-mode(s): 32-bit, 64-bit > > Byte Order: Little Endian > > CPU(s): 8 > > On-line CPU(s) list: 0-7 > > Thread(s) per core: 1 > > Core(s) per socket: 4 > > CPU socket(s): 2 > > NUMA node(s): 1 > > Vendor ID: GenuineIntel > > CPU family: 6 > > Model: 23 > > Stepping: 6 > > CPU MHz: 3000.105 > > BogoMIPS: 6000.04 > > Virtualization: VT-x > > L1d cache: 32K > > L1i cache: 32K > > L2 cache: 6144K > > NUMA node0 CPU(s): 0-7 > > > > 32GB RAM > > [root@db3 ~]# numactl --hardware > > available: 1 nodes (0) > > node 0 cpus: 0 1 2 3 4 5 6 7 > > node 0 size: 32765 MB > > node 0 free: 317 MB > > node distances: > > node 0 > > 0: 10 > > > > > > RAID1 2x146GB 10k rpm > > > > CentOS release 6.3 (Final) > > Linux 2.6.32-279.11.1.el6.x86_64 #1 SMP x86_64 GNU/Linux > > > > > > kernel.msgmnb = 65536 > > kernel.msgmax = 65536 > > kernel.shmmax = 68719476736 > > kernel.shmall = 4294967296 > > vm.swappiness = 30 > > vm.dirty_background_bytes = 67108864 > > vm.dirty_bytes = 536870912 > > > > > > PostgreSQL 9.1.6 on x86_64-unknown-linux-gnu, compiled by gcc (GCC) 4.4.6 > > 20120305 (Red Hat 4.4.6-4), 64-bit > > > > listen_addresses = '*' > > port = 5433 > > max_connections = 350 > > shared_buffers = 8GB > > temp_buffers = 64MB > > max_prepared_transactions = 350 > > work_mem = 256MB > > maintenance_work_mem = 1GB > > max_stack_depth = 4MB > > max_files_per_process = 5000 > > effective_io_concurrency = 2 > > wal_level = hot_standby > > synchronous_commit = off > > checkpoint_segments = 64 > > checkpoint_timeout = 15min > > checkpoint_completion_target = 0.75 > > max_wal_senders = 4 > > wal_sender_delay = 100ms > > wal_keep_segments = 128 > > random_page_cost = 3.0 > > effective_cache_size = 18GB > > autovacuum = on > > autovacuum_max_workers = 5 > > autovacuum_vacuum_threshold = 900 > > autovacuum_analyze_threshold = 350 > > autovacuum_vacuum_scale_factor = 0.1 > > autovacuum_analyze_scale_factor = 0.05 > > log_min_duration_statement = 500 > > deadlock_timeout = 1s > > > > > > DB size is about 20GB. There is no high write activity on DB. But > > periodically in postgresql log i see for example: "select 1" duration is > > about 500-1000 ms. > > > > In this period of time response time from db terribly. This period of > time > > not bound with high traffic. It is not other app on the server. There is > not > > specific cron job on server. > > > > Our app written on java and use jdbc to connect to DB and internal > pooling. > > There is about 100 connection to DB. This is sar output: > > > > 12:00:01 AM pgpgin/s pgpgout/s fault/s majflt/s pgfree/s pgscank/s > > pgscand/s pgsteal/s %vmeff > > 09:30:01 PM 73.17 302.72 134790.16 0.00 46809.73 0.00 > > 0.00 0.00 0.00 > > 09:35:01 PM 63.42 655.80 131740.74 0.00 46182.74 0.00 > > 0.00 0.00 0.00 > > 09:40:01 PM 76.87 400.62 122375.34 0.00 42096.27 0.00 > > 0.00 0.00 0.00 > > 09:45:01 PM 58.49 198.33 121922.86 0.00 42765.27 0.00 > > 0.00 0.00 0.00 > > 09:50:01 PM 52.21 485.45 136775.65 0.15 49098.65 0.00 > > 0.00 0.00 0.00 > > 09:55:01 PM 49.68 476.75 130159.24 0.00 45192.54 0.00 > > 0.00 0.00 0.00 > > 10:00:01 PM 41.35 295.34 118655.80 0.00 40786.52 0.00 > > 0.00 0.00 0.00 > > 10:05:01 PM 60.84 593.85 129890.83 0.00 44170.92 0.00 > > 0.00 0.00 0.00 > > 10:10:01 PM 52.08 471.36 132773.63 0.00 46019.13 0.00 > > 2.41 2.41 100.00 > > 10:15:01 PM 73.93 196.50 129384.21 0.33 45255.76 65.92 > > 1.19 66.87 99.64 > > 10:20:02 PM 70.35 473.16 121940.38 0.11 44061.52 81.95 > > 37.79 119.42 99.73 > > 10:25:01 PM 57.84 471.69 130583.33 0.01 46093.33 0.00 > > 0.00 0.00 0.00 > > 10:30:01 PM 52.91 321.62 119264.34 0.01 41748.19 0.00 > > 0.00 0.00 0.00 > > 10:35:01 PM 47.13 451.78 114625.62 0.02 40600.98 0.00 > > 0.00 0.00 0.00 > > 10:40:01 PM 48.96 472.41 102352.79 0.00 35402.17 0.00 > > 0.00 0.00 0.00 > > 10:45:01 PM 70.07 321.33 121423.02 0.00 43052.04 0.00 > > 0.00 0.00 0.00 > > 10:50:01 PM 46.78 479.95 128938.09 0.02 37864.07 116.64 > > 48.97 165.07 99.67 > > 10:55:02 PM 104.84 453.55 109189.98 0.00 37583.50 0.00 > > 0.00 0.00 0.00 > > 11:00:01 PM 46.23 248.75 107313.26 0.00 37278.10 0.00 > > 0.00 0.00 0.00 > > 11:05:01 PM 44.28 446.41 115598.61 0.01 40070.61 0.00 > > 0.00 0.00 0.00 > > 11:10:01 PM 38.86 457.32 100240.71 0.00 34407.29 0.00 > > 0.00 0.00 0.00 > > 11:15:01 PM 48.23 275.60 104780.84 0.00 36183.84 0.00 > > 0.00 0.00 0.00 > > 11:20:01 PM 92.74 432.49 114698.74 0.01 40413.14 0.00 > > 0.00 0.00 0.00 > > 11:25:01 PM 42.76 428.50 87769.28 0.00 29379.87 0.00 > > 0.00 0.00 0.00 > > 11:30:01 PM 36.83 260.34 85072.46 0.00 28234.50 0.00 > > 0.00 0.00 0.00 > > 11:35:01 PM 62.52 481.56 93150.67 0.00 31137.13 0.00 > > 0.00 0.00 0.00 > > 11:40:01 PM 43.50 459.10 90407.34 0.00 30241.70 0.00 > > 0.00 0.00 0.00 > > > > 12:00:01 AM kbmemfree kbmemused %memused kbbuffers kbcached kbcommit > > %commit > > 09:30:01 PM 531792 32345400 98.38 475504 29583340 10211064 > > 27.62 > > 09:35:01 PM 512096 32365096 98.44 475896 29608660 10200916 > > 27.59 > > 09:40:01 PM 455584 32421608 98.61 476276 29638952 10211652 > > 27.62 > > 09:45:01 PM 425744 32451448 98.71 476604 29662384 10206044 > > 27.60 > > 09:50:01 PM 380960 32496232 98.84 477004 29684296 10243704 > > 27.71 > > 09:55:01 PM 385644 32491548 98.83 477312 29706940 10204776 > > 27.60 > > 10:00:01 PM 348604 32528588 98.94 477672 29725476 10228984 > > 27.67 > > 10:05:01 PM 279216 32597976 99.15 478104 29751016 10281748 > > 27.81 > > 10:10:01 PM 255168 32622024 99.22 478220 29769924 10247404 > > 27.72 > > 10:15:01 PM 321188 32556004 99.02 475124 29721912 10234500 > > 27.68 > > 10:20:02 PM 441660 32435532 98.66 472336 29610476 10246288 > > 27.71 > > 10:25:01 PM 440636 32436556 98.66 472636 29634960 10219940 > > 27.64 > > 10:30:01 PM 469872 32407320 98.57 473016 29651476 10208520 > > 27.61 > > 10:35:01 PM 414540 32462652 98.74 473424 29672728 10223964 > > 27.65 > > 10:40:01 PM 354632 32522560 98.92 473772 29693016 10247752 > > 27.72 > > 10:45:01 PM 333708 32543484 98.98 474092 29720256 10227204 > > 27.66 > > 10:50:01 PM 528004 32349188 98.39 469396 29549832 10219536 > > 27.64 > > 10:55:02 PM 499068 32378124 98.48 469692 29587140 10204836 > > 27.60 > > 11:00:01 PM 462980 32414212 98.59 470032 29606764 10235820 > > 27.68 > > 11:05:01 PM 449540 32427652 98.63 470368 29626136 10209788 > > 27.61 > > 11:10:01 PM 419984 32457208 98.72 470772 29644248 10214480 > > 27.63 > > 11:15:01 PM 429900 32447292 98.69 471104 29664292 10202344 > > 27.59 > > 11:20:01 PM 394852 32482340 98.80 471528 29698052 10207604 > > 27.61 > > 11:25:01 PM 345328 32531864 98.95 471904 29717264 10215632 > > 27.63 > > 11:30:01 PM 368224 32508968 98.88 472236 29733544 10206468 > > 27.61 > > 11:35:01 PM 321800 32555392 99.02 472528 29758548 10211820 > > 27.62 > > 11:40:01 PM 282520 32594672 99.14 472860 29776952 10243516 > > 27.71 > > > > 12:00:01 AM DEV tps rd_sec/s wr_sec/s avgrq-sz avgqu-sz > > await svctm %util > > 09:30:01 PM dev253-5 66.29 146.33 483.33 9.50 6.27 > > 94.53 2.08 13.78 > > 09:35:01 PM dev253-5 154.80 126.85 1192.96 8.53 28.57 > > 184.59 1.45 22.43 > > 09:40:01 PM dev253-5 92.21 153.75 686.75 9.11 11.53 > > 125.00 1.87 17.21 > > 09:45:01 PM dev253-5 39.66 116.99 279.32 9.99 0.42 > > 10.66 2.61 10.36 > > 09:50:01 PM dev253-5 106.73 95.58 820.70 8.58 16.77 > > 157.12 1.68 17.88 > > 09:55:01 PM dev253-5 107.90 99.36 831.46 8.63 16.05 > > 148.76 1.71 18.42 > > 10:00:01 PM dev253-5 62.48 82.70 471.28 8.87 5.91 > > 94.52 2.10 13.11 > > 10:05:01 PM dev253-5 137.84 121.69 1064.03 8.60 24.48 > > 177.31 1.56 21.52 > > 10:10:01 PM dev253-5 107.93 104.16 827.83 8.64 16.69 > > 155.04 1.68 18.11 > > 10:15:01 PM dev253-5 40.55 126.12 277.57 9.96 0.41 > > 10.13 2.57 10.42 > > 10:20:02 PM dev253-5 104.33 136.77 793.49 8.92 16.97 > > 162.69 1.76 18.35 > > 10:25:01 PM dev253-5 108.04 115.36 825.26 8.71 16.68 > > 154.36 1.76 19.05 > > 10:30:01 PM dev253-5 69.72 105.66 523.05 9.02 7.45 > > 106.92 1.90 13.25 > > 10:35:01 PM dev253-5 101.58 91.59 781.85 8.60 15.00 > > 147.68 1.67 16.97 > > 10:40:01 PM dev253-5 107.50 97.91 827.17 8.61 17.68 > > 164.49 1.77 19.06 > > 10:45:01 PM dev253-5 69.98 140.13 519.57 9.43 7.09 > > 101.25 1.96 13.72 > > 10:50:01 PM dev253-5 104.30 83.31 806.12 8.53 16.18 > > 155.10 1.65 17.16 > > 10:55:02 PM dev253-5 106.86 209.65 790.27 9.36 15.59 > > 145.08 1.74 18.60 > > 11:00:01 PM dev253-5 50.42 92.08 371.52 9.19 3.05 > > 62.16 2.28 11.52 > > 11:05:01 PM dev253-5 101.06 88.31 776.57 8.56 15.12 > > 149.58 1.67 16.90 > > 11:10:01 PM dev253-5 103.08 77.73 798.23 8.50 17.14 > > 166.25 1.74 17.90 > > 11:15:01 PM dev253-5 57.74 96.45 428.62 9.09 5.23 > > 90.52 2.13 12.32 > > 11:20:01 PM dev253-5 97.73 185.18 727.38 9.34 14.64 > > 149.84 1.94 18.92 > > 11:25:01 PM dev253-5 95.03 85.52 730.31 8.58 14.42 > > 151.79 1.79 16.97 > > 11:30:01 PM dev253-5 53.76 73.65 404.47 8.89 3.94 > > 73.25 2.17 11.64 > > 11:35:01 PM dev253-5 110.37 125.05 842.17 8.76 16.96 > > 153.63 1.66 18.30 > > 11:40:01 PM dev253-5 103.93 87.00 801.59 8.55 16.01 > > 154.00 1.73 18.00 > > > > As you can see there is no high io activity in this period of time but > db is > > frozen. My opinion that i have incorrect kernel setting and/or i have a > > mistake in postgresql.conf. Because there is not high activity on db. > load > > avg is about 1. When there is high traffic is about 1.15. This is from > > nagios monitoring system. > > > > But sometimes load is about 4 and this time matches with sar %vmeff = > 100% > > and database response time increase. > > > Need to see: iowait, system load. > > Also consider installing perf and grabbing a profile while issue is > happening. > > Probably this problem will go way with 2GB shared buffers, but before > doing that we'd like to diagnose this if possible. > > merlin > -- С уважением Селявка Евгений
