Date: Wed, 16 Nov 2005 17:23:45 -0700
From: Michael Fuhr <mike@fuhr.org>
To: "Craig A. James" <cjames@modgraph-usa.com>
Cc: Pgsql-Performance <pgsql-performance@postgresql.org>
Subject: Re: Perl DBD and an alarming problem
Message-ID: <20051117002344.GA55377@winnie.fuhr.org>
References: <BF9F6C0E.13B4A%llonergan@greenplum.com>
	<1132136225.5711.4.camel@Panoramix>
	<437B9DA9.2030806@modgraph-usa.com>
Mime-Version: 1.0
Content-Type: text/plain; charset=us-ascii
Content-Disposition: inline
In-Reply-To: <437B9DA9.2030806@modgraph-usa.com>

On Wed, Nov 16, 2005 at 12:59:21PM -0800, Craig A. James wrote:
>   eval {
>      local $SIG{ALRM} = sub {die("Timeout");};
>      $time = gettimeofday;
>      alarm 20;
>      $sth = $dbh->prepare("a query that may take a long time...");
>      $sth->execute();
>      alarm 0;
>   };
>   if ($@ && $@ =~ /Timeout/) {
>      my $elapsed = gettimeofday - $time;
>      print "Timed out after $elapsed seconds";
>   }
> 
> Now the mystery: It works, but it hardly matters what time I use for the 
> alarm call, the actual alarm event always happens at 26 seconds.  I can set 
> "alarm 1" or "alarm 20", and it almost always hits right at 26 seconds.

High-level languages' signal handlers don't always work well with
low-level libraries.  I haven't dug into the Perl source code but
I'd guess that since only certain things are safe to do in a signal
handler, Perl's handler simply sets some kind of state that the
interpreter will examine later during normal execution.  If you're
using only Perl facilities then that probably happens fairly timely,
but if you're stuck in a low-level library (e.g., libpq) then you
might have to wait until that library returns control to Perl before
Perl recognizes that a signal occurred.

As an example, if I run code such as yours with alarm(2) and a query
that takes 5 seconds, I see the following in a process trace (from
ktrace/kdump on FreeBSD):

55395 perl     0.000978 CALL  poll(0xbfbfe1b8,0x1,0xffffffff)
55395 perl     1.996629 RET   poll -1 errno 4 Interrupted system call
55395 perl     0.000013 PSIG  SIGALRM caught handler=0x281be22c mask=0x0 code=0x0
55395 perl     0.000050 CALL  sigprocmask(0x1,0,0x805411c)
55395 perl     0.000005 RET   sigprocmask 0
55395 perl     0.000020 CALL  sigreturn(0xbfbfde60)
55395 perl     0.000007 RET   sigreturn JUSTRETURN
55395 perl     0.000019 CALL  poll(0xbfbfe1b8,0x1,0xffffffff)
55395 perl     3.004065 RET   poll 1
55395 perl     0.000024 CALL  recvfrom(0x3,0x81c6000,0x4000,0,0,0)
55395 perl     0.000016 GIO   fd 3 read 60 bytes

The poll() call is interrupted by SIGALRM after 2 seconds but then
it starts again and doesn't return until the query completes after
the remaining 3 seconds.  Only sometime later does Perl invoke the
ALRM handler I installed, presumably because it can't do so until
the low-level code returns control to Perl.

Is there a reason you're using alarm() in the client instead of
setting statement_timeout on the server?

-- 
Michael Fuhr