http://qs321.pair.com?node_id=1122184

bash has asked for the wisdom of the Perl Monks concerning the following question:

Im stuck on understanding how EV calculcate timers. I have this code:
#!/usr/bin/perl use common::sense; use AnyEvent::HTTP; use Data::Dumper; sub do { my $iter = shift; # It will resolve every timeout problems, but it is not question # AnyEvent->now_update; my $cv = AnyEvent->condvar; $cv->begin; http_get 'https://imasheep.hurrdurr.org/category/about.html', timeout => 2, sub { my ($body, $hdr) = @_; say "$iter $hdr->{Status}"; unless ($hdr->{Status} == 200) { warn Data::Dumper->Dump([$hdr],['hdr']); } $cv->end; } ; my $timer = AnyEvent->timer( after => 300, cb => sub { warn "Exit by timer"; $cv->send }, ); my ($n, $t) = (AnyEvent->now, AnyEvent->time); my $d = $t-$n; say "$iter diff = $d, time = $t, now = $n"; $cv->recv; } for (1..4) { &do($_); sleep(5); }
output:
1 diff = 0.0233771800994873, time = 1427912097.54858, now = 1427912097 +.5252 1 200 2 diff = 5.0014123916626, time = 1427912103.05933, now = 1427912098.05 +791 2 596 $hdr = { 'Reason' => 'Connection timed out', 'URL' => 'https://imasheep.hurrdurr.org/category/about.html', 'Status' => 596 }; 3 diff = 5.00508308410645, time = 1427912108.06631, now = 1427912103.0 +6123 3 200 4 diff = 5.00244045257568, time = 1427912113.56622, now = 1427912108.5 +6378 4 596 $hdr = { 'Status' => 596, 'Reason' => 'Connection timed out', 'URL' => 'https://imasheep.hurrdurr.org/category/about.html' };
Iteration 2 - This is OK for me. Timer was set when internal time has 5 sec lag
Iteration 3 - But I do not understand this case. Everything is the same. Why there is no timeout ???
Iteration 4 - And once again. So every even call to do() generate timeout, and every odd call doesn't generate.
Could you please clarify me about this behaviour?

Replies are listed 'Best First'.
Re: AnyEvent timers by EV
by Krambambuli (Curate) on Apr 03, 2015 at 18:40 UTC
    Here's what's going on with the noticed odd-good/even-bad behavior:
    #!/usr/bin/perl use common::sense; use AnyEvent::HTTP; use Data::Dumper; sub do { my $iter = shift; my $cv = AnyEvent->condvar; $cv->begin; http_get 'https://imasheep.hurrdurr.org/category/about.html', timeout => 2, # out-comment to get the even/odd behavior persistent => 0, sub { my ($body, $hdr) = @_; say "$iter $hdr->{Status}"; unless ($hdr->{Status} == 200) { warn Data::Dumper->Dump([$hdr],['hdr']); } $cv->end; } ; $cv->recv; } for (1..4) { &do($_); sleep(5); }
    The documentation for that 'persistent' reads as follows:
            persistent => $boolean
                   Try to create/reuse a persistent connection. When this flag is set (default: true for idempotent
                   requests, false for all others), then "http_request" tries to re-use an existing (previously-created)
                   persistent connection to the host and, failing that, tries to create a new one.
    
                   Requests failing in certain ways will be automatically retried once, which is dangerous for non-
                   idempotent requests, which is why it defaults to off for them. The reason for this is because the bozos
                   who designed HTTP/1.1 made it impossible to distinguish between a fatal error and a normal connection
                   timeout, so you never know whether there was a problem with your request or not.
    
                   When reusing an existent connection, many parameters (such as TLS context) will be ignored. See the
                   "session" parameter for a workaround.
    
    This default persistence for idempotent requests conflicts with your 5 seconds sleeps - and that's why only every second connection attempt succeeds.


    Krambambuli
    ---
      Ok, if this is "persistent" problem, how AnyEvent->now_update solves it?

      And why there is no time-out's at all like in my test-code #2?
        Most probably ->now_update clears the internal 'cache' entirely, so the persistence is swapped away.

        There is no *timer* timeout because in the example code the timeout is set to 300 seconds - a long time after every action is over. There are however *connection* timeouts - most probably the server closes connections that are idle for seconds, and you are keeping them idle by sleeping 5 seconds between the calls.

        That's what's happening, in sequence:

        1) successful GET; try to keep connection alive
        2) enter sleep
        3) server closes connection
        4) get awake and try a GET; failure. Clear connection cache
        5) sleep
        6) go to 1)

        Krambambuli
        ---
Re: AnyEvent timers for EV
by Anonymous Monk on Apr 01, 2015 at 18:35 UTC
    timeouts are never x exact, its not like 1+1 = 2, they're fuzzy, like 1+1 = 2.12 or 3.12 or 5 ...
Re: AnyEvent timers by EV
by Krambambuli (Curate) on Apr 03, 2015 at 16:10 UTC
    At least for the particular URL you're using in the text code, I can confirm that the odd calls are fine whereas the even ones do generate a timeout. (I've checked letting the counter be 4, 10, 20 and the behavior was consistent!).

    And that's the same even when increasing the sleep to 10. So there is something here to be understood... :)

    It doesn't really look like anything random.
    And it's not anything like throttling on the server end, since that would make the issue disappear (I guess) when using a 10 seconds sleep.


    Krambambuli
    ---
Re: AnyEvent timers by EV
by Krambambuli (Curate) on Apr 03, 2015 at 16:31 UTC
    One quick observation is that there's actually _never_ a trigger for your timer, since you've set it to 300 seconds, i.e. 5 minutes. (There's no "Exit by timer" in the output...)


    Krambambuli
    ---
      Yep, this is "ghost-code" from my real project. Forgot to remove it ;)
Re: AnyEvent timers by EV
by sundialsvc4 (Abbot) on Apr 01, 2015 at 21:59 UTC

    My sense is that you are comparing apples and oranges here:   a local timer-watcher, which by definition concerns only a single machine (yours), is being weighed against the timeouts of a transaction that is being attempted against a remote.   (There seems to be some specific discussion of this issue in the “Timing Issues” section of the page for AnyEvent.)   I suspect that the “every odd call” phenomenon that you seem to be observing is, in fact, just a fluke.   What you are probably dealing with here is an innocuous expression of what’s called a “race condition.”   The particular results that you deem to be meaningful are probably just the luck of the draw.

      What you are probably dealing with here is an innocuous expression of what’s called a “race condition.”

      Balooney, its simple granularity, same as with sleep

        Not so fast . . . kindly please do not automatically presume that I know not whereof I speak, and thus to dismiss what <<I>&;gt; say on just that reason.   :-)

        In the instant case, a local timer, running for so-many milliseconds locally, is being set against a timeout of a remote TCP/IP exchange.   Necessarily, a timeout against a remote machine will require some additional milliseconds to resolve ... milliseconds spent informing the client that a timeout has, in fact, occurred.   The AnyEvent authors were obviously very sensitive to such issues, and they actually spent quite a bit of time in their documentation discussing it.   It appears to me that the OP’s test-case does not take these issues into proper account, thereby leading to the (erroneous?) observation of “even/odd.”

        Basically, “it will take you somewhat-more than 200 milliseconds to conclude that a 200-millisecond timeout has timed-out.”   (And, as Anonymous Monk originally observed, it is actually quite unpredictable just how many “more than” milliseconds, might be required.)   A strictly-local timer knows nothing of real-world network delays, whereas a valid conclusion cannot ignore them.   C’est la guerre ...

        EDIT:   Kindly now draw your attention to what krambambuli subsequently posted.   I think he hit an important nail on the head here ... and something I did not know ... to decisively explain the “even/odd” behavior.