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 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: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: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: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(at)sai(dot)msu(dot)su, http://www.sai.msu.su/~megera/
phone: +007(095)939-16-83, +007(095)939-23-83