Re: plperlu stored procedure seems to freeze for a minute

On 2015-12-01 10:20:09 -0800, Adrian Klaver wrote:
> On 12/01/2015 09:58 AM, Peter J. Holzer wrote:
> >On 2015-12-01 07:16:04 -0800, Adrian Klaver wrote:
> >>On 12/01/2015 06:51 AM, Peter J. Holzer wrote:
> >>>A rather weird observation from the log files of our server (9.5 beta1):
> >>>
> >>>2015-12-01 09:23:37 CET [26265]: [42-1] user=fragner,db=wds,pid=26265 WARNING:  Use of uninitialized value
$successin concatenation (.) or string at /usr/local/share/perl/5.20.2/WDS/Macrobond/Utils.pm line 36. 
> >>>2015-12-01 09:23:37 CET [26265]: [43-1] user=fragner,db=wds,pid=26265 CONTEXT:  PL/Perl function
"mb_timeseriesdata_zmq"
> >>>[lots of other stuff from different connections]
> >>>2015-12-01 09:24:45 CET [26265]: [44-1] user=fragner,db=wds,pid=26265 ERROR:  impossible result '' (payload=) at
/usr/local/share/perl/5.20.2/WDS/Macrobond/Utils.pmline 36. 
> >>>                 WDS::Macrobond::Utils::decode_result("") called at line 30
> >>>                 main::__ANON__("gen_wqehur") called at -e line 0
> >>>                 eval {...} called at -e line 0
> >>>
> >>>Two messages from the same line of the same plperlu stored procedure, 68
> >>>seconds apart. So what is this line 36?
> >>>
> >>>     confess "impossible result '$success' (payload=$payload)";
> >>>
> >>>What? The first message clearly comes from interpolating $success
> >>>(which is undef at that point) into the argument. The second from
> >>>confess itself. What could cause a plperlu procedure to freeze for 68
> >>>seconds between the call to confess and its output?
> >>>
> >>>Is it possible that only the writing of the log entry is delayed?
> >>>
> >>>Another weird thing: $success is undef because a ØMQ rpc call[1] timed
> >>
> >>And the call is?
> >
> >The sequence is:
> >
> >my $req_sck = zmq_socket($context, ZMQ_REQ);
> >zmq_connect($req_sck, $url);
> >my $qry_msg = join(...);
> >zmq_send($req_sck, $qry_msg);
> >my $res_msg = zmq_msg_init();
> >my $rv = zmq_msg_recv($res_msg, $req_sck);
> ># check rv here.
> >my $data = zmq_msg_data($res_msg); # $data is "" here
> >my $result = WDS::Macrobond::Utils::decode_result($data); # the error messages are from this function
> >
> >(Yeah, ØMQ is quite low-level. There is a higher level Perl Module, but
> >I'm not using it).
> >
> >I omitted that because I don't think it's terribly relevant here.
> >Details of the usage of ØMQ are better discussed on the ØMQ mailing
> >list.
> >
> >But there is something else which may be relevant: ØMQ uses threads
> >internally, and I don't actually know whether zmq_msg_recv returning
>
> Except I see this here:
>
> http://api.zeromq.org/4-0:zmq-socket
>
> Thread safety
>
> ØMQ sockets are not thread safe. Applications MUST NOT use a socket from
> multiple threads except after migrating a socket from one thread to another
> with a "full fence" memory barrier.

Well yes, but I don't use a ØMQ socket in multiple threads, It is
created in the stored procedure and destroyed at the end (just checked
the strace output: Yes it is. For a moment I wasn't sure whether lexical
variables in plperlu procedures go out of scope.). It's the ØMQ library
itself which creates extra threads (And it should terminate them
properly and afaics from strace it does).


[...]
> From here:
>
> http://api.zeromq.org/4-0:zmq-connect
>
> It seems something like(I am not a Perl programmer, so approach carefully):
>
> my $rc = zmq_connect($req_sck, $url);
>
> Then you will have an error code to examine.

Yes. I have been a bit sloppy with error checking. I check only the
return value of the zmq_msg_recv() call which returns the empty message.
It is possible that the problem actually occurs earlier and I should
check those calls as well. Mea culpa.

However, in at least one case the failed call was indeed zmq_msg_recv()
not one of the earlier ones (see my next mail).

> Have you looked at the Notes at the bottom of this page:
>
> http://www.postgresql.org/docs/9.4/interactive/plperl-trusted.html

I have. I don't think that's a problem here: Debian perl is built with
with both multiplicity and ithreads, and I would assume that the .deb
packages from postgresql.org use the shared library provided by the
system.

But even if that wasn't the case it should not be a problem as only
plperlu stored procedures are called.

    hp

--
   _  | Peter J. Holzer    | I want to forget all about both belts and
|_|_) |                    | suspenders; instead, I want to buy pants
| |   | hjp@hjp.at         | that actually fit.
__/   | http://www.hjp.at/ |   -- http://noncombatant.org/