Re: Fwd: FreeBSD, PostgreSQL, semwait and sbwait!

Hello,

>> We're having a substantial problem with our FreeBSD 5.2 database
>> server
>> running PostgreSQL - it's getting a lot of traffic (figure about 3,000
>> queries per second), but queries are slow, and it's seemingly waiting
>> on
>> other things than CPU time
>>
> Could this be a 5.2 performance issue ?
>
> In spite of certain areas where the 5.x series performance is known to
> be much better than 4.x (e.g networking), this may not be manifested
> in practice for a complete application.
> (e.g. I am still running 4.9 as it outperformed 5.1 vastly for a ~100
> database sessions running queries - note that I have not tried out
> 5.2, so am happy to be corrected on this)
I found the same problem.

I use OpenBSD 3.3,
On Pentium 2,4 GHz with 1 Gb RAM, RAID 10.
With PostgreSQL 7.4.1 with 32 Kb bock's size (to match ffs and raid
block's size)
With pg_autovacuum daemon from Pg 7.5.

I run a web indexer.
sd0 raid-1 with system pg-log and indexer-log
sd1 raid-10 with pg-data and indexer-data
The sd1 disk achives between 10 and 40 Mb/s on normal operation.

When I get semwait in top, system waits ;-)
Not much disk activity.
Not much log in pg or indexer.
Just wait....

What can I do ?

> sudo top -s1 -S -I
load averages: 4.45, 4.45, 3.86
11:25:52
97 processes: 1 running, 96 idle
CPU states: 2.3% user, 0.0% nice, 3.8% system, 0.8% interrupt,
93.1% idle
Memory: Real: 473M/803M act/tot Free: 201M Swap: 0K/3953M used/tot

PID USERNAME PRI NICE SIZE RES STATE WAIT TIME CPU COMMAND
2143 postgres -5 0 4008K 37M sleep biowai 1:02 1.81% postgres
28662 postgres 14 0 4060K 37M sleep semwai 0:59 1.17% postgres
25794 postgres 14 0 4072K 37M sleep semwai 1:30 0.93% postgres
23271 postgres -5 0 4060K 37M sleep biowai 1:13 0.29% postgres
14619 root 28 0 276K 844K run - 0:01 0.00% top

> vmstat -w1 sd0 sd1
r b w avm fre flt re pi po fr sr sd0 sd1 in sy cs
us sy id
0 4 0 527412 36288 1850 0 0 0 0 0 26 72 368 8190 588
0 4 96
0 4 0 527420 36288 1856 0 0 0 0 0 0 86 356 8653 620
2 2 97
0 4 0 527432 36280 1853 0 0 0 0 0 0 54 321 8318 458
1 3 96
0 4 0 527436 36248 1864 0 0 0 0 0 0 77 358 8417 539
1 2 97
0 4 0 522828 40932 2133 0 0 0 0 0 7 70 412 15665 724
2 3 95
0 4 0 522896 40872 1891 0 0 0 0 0 15 72 340 9656 727
3 5 92
0 4 0 522900 40872 1841 0 0 0 0 0 0 69 322 8308 536
1 2 98
0 4 0 522920 40860 1846 0 0 0 0 0 1 69 327 8023 520
2 2 97
0 4 0 522944 40848 1849 0 0 0 0 0 4 76 336 8035 567
1 2 97
0 4 0 522960 40848 1843 0 0 0 0 0 0 77 331 14669 587
3 2 95
0 4 0 522976 40836 1848 0 0 0 0 0 4 81 339 8384 581
1 2 97
0 4 0 522980 40836 1841 0 0 0 0 0 3 65 320 8068 502
1 4 95
0 4 0 523000 40824 1848 0 0 0 0 0 14 74 341 8226 564
3 2 95
0 4 0 523020 40812 1844 0 0 0 0 0 0 67 317 7606 530
2 1 97
1 4 0 523052 40796 1661 0 0 0 0 0 0 68 315 11603 493
2 2 97
1 4 0 523056 40800 233 0 0 0 0 0 12 87 341 12550 609
2 2 96
0 4 0 523076 40788 1845 0 0 0 0 0 0 82 334 12457 626
2 2 96
0 4 0 523100 40776 1851 0 0 0 0 0 0 91 345 10914 623
2 3 95
0 4 0 523120 40764 1845 0 0 0 0 0 0 92 343 19213 596
1 5 95
0 4 0 523136 40752 1845 0 0 0 0 0 0 97 349 8659 605
2 2 96
0 4 0 523144 40748 4501 0 0 0 0 0 32 78 385 15632 934
25 12 64
0 4 0 523168 40728 1853 0 0 0 0 0 3 74 335 3965 531
0 2 98

> ps -Upostgresql -Ostart | grep -v idle
PID STARTED TT STAT TIME COMMAND
8267 10:53AM ?? Is 0:00.28 /usr/local/bin/pg_autovacuum -D -L
/var/pgsql/autovacuum
23271 10:54AM ?? I 1:13.56 postmaster: dps dps 127.0.0.1 SELECT
(postgres)
28662 10:55AM ?? I 0:59.98 postmaster: dps dps 127.0.0.1 SELECT
(postgres)
25794 10:56AM ?? D 1:30.48 postmaster: dps dps 127.0.0.1 SELECT
(postgres)
2143 11:02AM ?? D 1:02.06 postmaster: dps dps 127.0.0.1 DELETE
(postgres)
25904 10:52AM C0- I 0:00.07 /usr/local/bin/postmaster -D
/var/pgsql (postgres)
10908 10:52AM C0- I 0:05.96 postmaster: stats collector process
(postgres)
7045 10:52AM C0- I 0:05.19 postmaster: stats buffer process
(postgres)

> grep -v -E '^#' /var/pgsql/postgresql.conf
tcpip_socket = true
max_connections = 100
shared_buffers = 1024 # 32KB
max_fsm_pages = 1000000 # min max_fsm_relations*16, 6 bytes each
max_fsm_relations = 200 # min 100, ~50 bytes each
wal_buffers = 32 # min 4, 8KB each
checkpoint_segments = 16 # in logfile segments, min 1, 16MB each
commit_delay = 100 # range 0-100000, in microseconds
effective_cache_size = 4096 # 32KB each
random_page_cost = 3
default_statistics_target = 200 # range 1-1000
client_min_messages = notice # Values, in order of decreasing detail:
log_min_messages = log # Values, in order of decreasing detail:
log_min_duration_statement = 20000 # Log all statements whose
log_timestamp = true
stats_start_collector = true
stats_command_string = true
stats_block_level = true
stats_row_level = true
stats_reset_on_server_start = true
lc_messages = 'C' # locale for system error message
strings
lc_monetary = 'C' # locale for monetary formatting
lc_numeric = 'C' # locale for number formatting
lc_time = 'C' # locale for time formatting
explain_pretty_print = true

> sysctl -a | grep seminfo
kern.seminfo.semmni = 256
kern.seminfo.semmns = 2048
kern.seminfo.semmnu = 30
kern.seminfo.semmsl = 60
kern.seminfo.semopm = 100
kern.seminfo.semume = 10
kern.seminfo.semusz = 100
kern.seminfo.semvmx = 32767
kern.seminfo.semaem = 16384

> systat
vmstat
7 users Load 3.48 3.64 3.56 Fri Apr 30
14:42:18 2004

memory totals (in KB) PAGING SWAPPING
Interrupts
real virtual free in out in out 361
total
Active 514768 527436 36280 ops 100
clock
All 992496 1005164 4071736 pages 128
rtc
45
fxp0
Proc:r d s w Csw Trp Sys Int Sof Flt 6 forks 88
twe0
4 26 580 1848 8395 361 249 1856 6 fkppw
fksvm
3.0% Sys 1.1% User 0.0% Nice 95.9% Idle pwait
| | | | | | | | | | | relck
=> rlkok
noram
Namei Sys-cache Proc-cache No-cache 80 ndcpy
Calls hits % hits % miss % 54 fltcp
812 806 99 5 1 1 0 208 zfod
95 cow
Discs cd0 sd0 sd1 sd2 fd0 128 fmin
seeks 6 82 170 ftarg
xfers 6 82 60208 itarg
Kbyte 47 2554 226 wired
sec 1.0 pdfre

> tail -f /var/pgsql/log
2004-04-30 11:35:03 LOG: recycled transaction log file
"000000C8000000CA"
2004-04-30 11:35:03 LOG: recycled transaction log file
"000000C8000000CB"
2004-04-30 11:35:03 LOG: recycled transaction log file
"000000C8000000CC"
2004-04-30 11:35:03 LOG: recycled transaction log file
"000000C8000000BF"
2004-04-30 11:35:03 LOG: recycled transaction log file
"000000C8000000C0"
2004-04-30 11:35:03 LOG: recycled transaction log file
"000000C8000000C1"
2004-04-30 11:35:03 LOG: recycled transaction log file
"000000C8000000C2"
2004-04-30 11:36:46 LOG: duration: 28284.360 ms statement: SELECT
rec_id,url FROM url WHERE status > 300 AND status<>304 AND
(referrer='28615' OR referrer='0') AND bad_since_time<1083317778
2004-04-30 11:36:46 LOG: duration: 24918.201 ms statement: SELECT
rec_id,url FROM url WHERE status > 300 AND status<>304 AND
(referrer='122879' OR referrer='0') AND bad_since_time<1083317781
2004-04-30 11:36:46 LOG: duration: 21173.427 ms statement: SELECT
rec_id,url FROM url WHERE status > 300 AND status<>304 AND
(referrer='586182' OR referrer='0') AND bad_since_time<1083317785

From PhpPgAdmin: Table url: Info
Row Performance
Sequential Index Rows
Scan Read Scan Fetch Insert Udate Delete
1 414173 85711 10963854 20431 8707 594

I/O Performance
Heap Index TOAST TOAST Index
Disk Cache % Disk Cache % Disk Cache % Disk Cache %
3298907 7790769 (70%) 200782 1274898 (86%) 0 0 (0%) 0 0
(0%)

Index Row Performance
Index Scan Read Fetch
url_bad_since_time 0 0 0
url_crc 2924 131566 131566
url_hops 0 0 0
url_last_mod_time 0 0 0
url_next_index_time 5 5120 5120
url_pkey 9187 8980 8980
url_referrer 4431 10753641 10753641
url_seed 0 0 0
url_serverid 0 0 0
url_siteid 0 0 0
url_status 0 0 0
url_url 69164 64547 64547

Index I/O Performance
Index Disk Cache %
url_bad_since_time 7169 80280 (92%)
url_crc 9106 19200 (68%)
url_hops 9071 109864 (92%)
url_last_mod_time 5836 27887 (83%)
url_next_index_time 12004 109887 (90%)
url_pkey 7501 52825 (88%)
url_referrer 58765 97634 (62%)
url_seed 30293 88712 (75%)
url_serverid 8647 110078 (93%)
url_siteid 8888 109864 (93%)
url_status 7448 111250 (94%)
url_url 36054 357417 (91%)

Cordialement,
Jean-Gérard Pailloncy