duplicate records (6.5.1)

Hello,

Sorry for long postings. I'm triyng to identify my problem with logging 
to Postgres.

I have some problem with comparison of accumulated hits count
from DB, from apache's access_log and what test tool reports (I'm using
ab which comes with apache distribution). 
It's obvious to expect these numbers should be the same, but they're 
different ! Trying to find out what's the problem I wrote
shell script hit_test which simplifies testing.

1: counts number of lines in access_log and current hits count in DB
2: running concurrent requests using Apache benchmark (ab)
3. The same as 1:

Running several times this script I noticed several weirdness:
1) All numbers are different:  ab reports - 100 completed requests  access_log - 109 requests  database   - 87 records
2) As you can see below after running test I got  9 duplicated records !

It's difficult to find the problem for 1) - apache, modperl, database,
but  2) is a postgres issue. This is a latest REL6_5_PATCHES CVS,
Linux 2.0.36 SMP. I had problem with  'vacuum analyze' with this
database, but after dumping-restoring vacuum  seems works ok.
Interesting to note, that at home I never got duplicates,
'vacuum analyze' problem and numbers from access_log and database
are consistent, so I'm fine at home (I think Apache Benchmark reports
wrong number of requests).

Postgres at home is slightly older (Jul 21) than
at work (Jul 23). Another difference is SMP - at work I have
DUAL PPRO system and Linux compiled with SMP support. Could be
SMP the problem ?

Regards,
    Oleg


---------------------------------------------------



19:34[zeus]:~/app/discovery/test>hit_test 1464
--------- START ------------------------------ 1464 31836 /usr/local/apache/logs/proxy.access_log
msg_id|count|first_access|last_access
------+-----+------------+-----------
(0 rows)

--------- RUN ----------------------------
This is ApacheBench, Version 1.3
Copyright (c) 1996 Adam Twiss, Zeus Technology Ltd, http://www.zeustech.net/
Copyright (c) 1998-1999 The Apache Group, http://www.apache.org/

Server Software:        Apache/1.3.6
Server Hostname:        astronet.sai.msu.su
Server Port:            80

Document Path:          /db/pubs.html?msg_id=1464
Document Length:        3535 bytes

Concurrency Level:      10
Time taken for tests:   5.057 seconds
Complete requests:      100
Failed requests:        0
Total transferred:      382000 bytes
HTML transferred:       353500 bytes
Requests per second:    19.77
Transfer rate:          75.54 kb/s received

Connnection Times (ms)             min   avg   max
Connect:        0    42   618
Processing:    49   409  1928
Total:         49   451  2546
--------- STOP -------------------------------
msg_id|count|first_access                |last_access
------+-----+----------------------------+---------------------------- 1464|   87|Sat 24 Jul 19:34:39 1999 MSD|Sat 24
Jul19:34:45 1999 MSD 1464|   87|Sat 24 Jul 19:34:39 1999 MSD|Sat 24 Jul 19:34:45 1999 MSD 1464|   87|Sat 24 Jul
19:34:391999 MSD|Sat 24 Jul 19:34:45 1999 MSD 1464|   87|Sat 24 Jul 19:34:39 1999 MSD|Sat 24 Jul 19:34:45 1999 MSD
1464|  87|Sat 24 Jul 19:34:39 1999 MSD|Sat 24 Jul 19:34:45 1999 MSD 1464|   87|Sat 24 Jul 19:34:40 1999 MSD|Sat 24 Jul
19:34:451999 MSD 1464|   87|Sat 24 Jul 19:34:39 1999 MSD|Sat 24 Jul 19:34:45 1999 MSD 1464|   87|Sat 24 Jul 19:34:39
1999MSD|Sat 24 Jul 19:34:45 1999 MSD 1464|   87|Sat 24 Jul 19:34:40 1999 MSD|Sat 24 Jul 19:34:45 1999 MSD
 
(9 rows)
 31945 /usr/local/apache/logs/proxy.access_log

---------------------------------------------------------------
Script hit_test:
---------------------------------------------------------------
#!/bin/sh
#set -vx

if [ u$1 = 'u' ]
then echo "Usage: $0 msg_id" exit 1
fi

MSG_ID=$1

URL=http://astronet.sai.msu.su/db/pubs.html
LOG=/usr/local/apache/logs/proxy.access_log
CONCURRENCY=10
REQUESTS=100

echo "--------- START ------------------------------" $MSG_ID
wc -l $LOG
psql discovery -c 'select * from hits where msg_id='$MSG_ID";'"
echo "--------- RUN ----------------------------"
ab -c $CONCURRENCY -n $REQUESTS $URL?msg_id=$MSG_ID
echo "--------- STOP -------------------------------"
sleep 5
psql discovery -c 'select * from hits where msg_id='$MSG_ID";'"
sleep 5
wc -l $LOG


---------------------------------------------------------------
I do logging using simple perl handler:
---------------------------------------------------------------
package Apache::HitsDBI;
use Apache::Constants qw(:common);

use strict;
# preloaded in startup.pl
#use DBI ();

sub handler {   my $orig = shift;   my $url  = $orig->uri;   if ( $orig->args() =~ /msg_id=(\d+)/ ) {     my $dbh =
DBI->connect("dbi:Pg:dbname=discovery")|| die DBI->errstr;     my $sth = $dbh->do("SELECT acc_hits($1)") || die
$dbh->errstr;  }    return OK;
 
}

1;
__END__

---------------------------------------------------------------
function acc_hits and table is here:
---------------------------------------------------------------
create table hits ( msg_id int4 not null, count  int4 not null, first_access datetime default now(), last_access
datetime
);
create index idx_hits on hits(msg_id);

CREATE FUNCTION "acc_hits" (int4) RETURNS int4 AS '
Declare   keyval      Alias For $1;   cnt         int4;   curtime     datetime;
Begin   curtime := ''now'';   Select count into cnt from hits where msg_id = keyval;   if Not Found then       cnt :=
1;      -- first_access inserted on default, last_access is NULL       Insert Into hits (msg_id,count) values (keyval,
cnt);  else       cnt := cnt + 1;       Update hits set count = cnt,last_access = curtime where msg_id = keyval   End
If;  return cnt;
 
End;
' LANGUAGE 'plpgsql';


_____________________________________________________________
Oleg Bartunov, sci.researcher, hostmaster of AstroNet,
Sternberg Astronomical Institute, Moscow University (Russia)
Internet: oleg@sai.msu.su, http://www.sai.msu.su/~megera/
phone: +007(095)939-16-83, +007(095)939-23-83