Re: plperlu stored procedure seems to freeze for a minute

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 $success
inconcatenation (.) 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?

> out (after 60 seconds, which is also a mystery, because ØMQ doesn't seem
> to have a default timeout of 60 seconds, and I don't set one). But at

Network timeout?

> 09:24:45 (i.e. the time of the error message) the answer for that RPC
> call arrived. So it kind of looks like confess waited for the message to
> arrive (which makes no sense at all) or maybe that confess waited for
> something which also blocked the sending of the request (because
> according to the server logs, the RPC request only arrived there at
> 09:24:45 and was answered within 1 second), but that doesn't make any

So if the request timed out how did you get a reply, a second request?

> sense either. (Just noticed that 60 + 68 == 128, which is also a round
> number).


This looks a question for a ØMQ list.

Another thought, have you tried the code outside Postgres to see if works?

>
>     hp
>
>
> [1] ØMQ is an IPC framework: See http://zeromq.org/ We use it to make
>      RPC calls from stored procedures to a server process.
>
>


--
Adrian Klaver
adrian.klaver@aklaver.com