I have made new test-code for check pure Timers.
And they behave like I expect and everything is clear for me...
So It's seems that problem from my 1 test-code is related to network "magic".
test-code 2: pure timers
#!/usr/bin/perl
use common::sense;
use AnyEvent;
use Data::Dumper;
sub do {
my $iter = shift;
my $cv = AnyEvent->condvar;
my ($n, $t, $d, $e);
($n, $t) = (AnyEvent->now, AnyEvent->time);
$d = $t-$n;
say "$iter start timer diff = $d, time = $t, now = $n";
my $timer = AnyEvent->timer(
after => 2,
cb => sub { warn "Timer\n"; $cv->send },
);
$cv->recv;
($n, $t, $e) = (AnyEvent->now, AnyEvent->time, AnyEvent->time - $
+t);
$d = $t-$n;
say "$iter got timer diff = $d, elapsed = $e, time = $t, now = $n"
+;
}
for (1..4) {
&do($_);
sleep(5);
warn "\n";
}
And result:
1 start timer diff = 0.000634908676147461, time = 1427985442.36442, no
+w = 1427985442.36378
Timer
1 got timer diff = 7.31945037841797e-05, elapsed = 2.00119400024414, t
+ime = 1427985444.36561, now = 1427985444.36554
2 start timer diff = 5.00071620941162, time = 1427985449.36625, now =
+1427985444.36554
Timer
2 got timer diff = 0.000667810440063477, elapsed = 0.00254702568054199
+, time = 1427985449.3688, now = 1427985449.36813
3 start timer diff = 5.00153064727783, time = 1427985454.36966, now =
+1427985449.36813
Timer
3 got timer diff = 4.67300415039062e-05, elapsed = 0.00129199028015137
+, time = 1427985454.37095, now = 1427985454.3709
4 start timer diff = 5.00066781044006, time = 1427985459.37157, now =
+1427985454.3709
Timer
4 got timer diff = 0.000627279281616211, elapsed = 0.00244379043579102
+, time = 1427985459.37401, now = 1427985459.37338
1 - timer invoked exactly after 2 sec of real time
2 - timer set when internal time and real time has 5 sec lag. So timer invoked immediately.
3..4 like 2 iteration
But Im still interested in my first test-code... just for self-education.