Re: Fwd: FreeBSD, PostgreSQL, semwait and sbwait! - Mailing list pgsql-performance

From Pailloncy Jean-Gérard
Subject Re: Fwd: FreeBSD, PostgreSQL, semwait and sbwait!
Date
Msg-id 52623D23-9AA4-11D8-9268-000A95DE2550@gdr-isis.enst.fr
Whole thread Raw
In response to Re: Fwd: FreeBSD, PostgreSQL, semwait and sbwait!  (Mark Kirkwood <markir@paradise.net.nz>)
Responses Re: Fwd: FreeBSD, PostgreSQL, semwait and sbwait!  (Mark Kirkwood <markir@paradise.net.nz>)
List pgsql-performance
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


pgsql-performance by date:

Previous
From: Pailloncy Jean-Gérard
Date:
Subject: INSERT RULE
Next
From: Greg Stark
Date:
Subject: Re: linux distro for better pg performance