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


---------------------------(end of broadcast)--------------------------- TIP 2: you can get off all lists at once with the unregister command (send "unregister YourEmailAddressHere" to [EMAIL PROTECTED])

Reply via email to