| # Timeout in seconds | |
| my $TIMEOUT = 0.004; | |
| # Bin size in microseconds | |
| my $BIN_SIZE = 50; | |
| # Limit of events to gather | |
| my $LIMIT = 2000; | |
| use v5.032; | |
| use strict; | |
| use warnings; | |
| use Term::ANSIColor qw(:constants); | |
| use EV; | |
| use Time::HiRes qw(time); | |
| my @sleep = (); | |
| sub schedule { | |
| my ($s, %opts) = @_; | |
| my $now = time; | |
| push @sleep, ($now-$s)*1_000_000 unless $opts{ignore}; | |
| return EV::unloop if @sleep > $LIMIT; | |
| my $w; $w = EV::timer $TIMEOUT, 0, sub { | |
| undef $w; | |
| schedule($now); | |
| }; | |
| return; | |
| } | |
| my $tm; $tm = EV::timer 0, 0, sub { | |
| undef $tm; | |
| schedule(time, ignore => 1); | |
| }; | |
| EV::loop; | |
| # Build and show histogram | |
| my @hist = (); | |
| my ($min, $max, $sum) = (1e9, 0, 0); | |
| my $total = 0; | |
| for (@sleep) { | |
| my $bin = int($_/$BIN_SIZE); | |
| $hist[$bin]++; | |
| $sum += $_; | |
| $min = $_ if $_ < $min; | |
| $max = $_ if $_ > $max; | |
| $total++; | |
| } | |
| printf "Total: %d Timeout: %dms\nmin: %dµs max: %dµs mean: %dµs\n", $total, $TIMEOUT*1000, $min, $max, $sum/$total; | |
| for my $i (0..$#hist) { | |
| local $Term::ANSIColor::AUTORESET = 1; | |
| next unless $hist[$i]; | |
| my $lo = $i*$BIN_SIZE; | |
| my $hi = $lo+$BIN_SIZE; | |
| my $count = $hist[$i]; | |
| my $pct = 100*$count/$total; | |
| my $text = sprintf "%4dµs-%4dµs: %d\t(%d%%)\n", $lo, $hi, $count, $pct; | |
| if ($pct > 1) { | |
| print BOLD RED $text; | |
| } else { | |
| print $text; | |
| } | |
| } | |
| __END__ | |
| Total: 2001 Timeout: 1ms | |
| min: 1013µs max: 1415µs mean: 1254µs | |
| 1000µs-1050µs: 6 (0%) | |
| 1050µs-1100µs: 14 (0%) | |
| 1100µs-1150µs: 14 (0%) | |
| 1150µs-1200µs: 12 (0%) | |
| 1200µs-1250µs: 50 (2%) | |
| 1250µs-1300µs: 1899 (94%) | |
| 1300µs-1350µs: 2 (0%) | |
| 1350µs-1400µs: 3 (0%) | |
| 1400µs-1450µs: 1 (0%) | |
| Total: 2001 Timeout: 2ms | |
| min: 2020µs max: 9675µs mean: 2508µs | |
| 2000µs-2050µs: 11 (0%) | |
| 2050µs-2100µs: 13 (0%) | |
| 2100µs-2150µs: 11 (0%) | |
| 2150µs-2200µs: 10 (0%) | |
| 2200µs-2250µs: 15 (0%) | |
| 2250µs-2300µs: 13 (0%) | |
| 2300µs-2350µs: 12 (0%) | |
| 2350µs-2400µs: 15 (0%) | |
| 2400µs-2450µs: 24 (1%) | |
| 2450µs-2500µs: 83 (4%) | |
| 2500µs-2550µs: 1772 (88%) | |
| 2550µs-2600µs: 11 (0%) | |
| 2600µs-2650µs: 1 (0%) | |
| 2650µs-2700µs: 1 (0%) | |
| 3050µs-3100µs: 1 (0%) | |
| 3550µs-3600µs: 1 (0%) | |
| 3650µs-3700µs: 1 (0%) | |
| 5100µs-5150µs: 1 (0%) | |
| 5900µs-5950µs: 1 (0%) | |
| 6600µs-6650µs: 1 (0%) | |
| 7950µs-8000µs: 1 (0%) | |
| 8000µs-8050µs: 1 (0%) | |
| 9650µs-9700µs: 1 (0%) | |
| Total: 2001 Timeout: 3ms | |
| min: 3024µs max: 4647µs mean: 3732µs | |
| 3000µs-3050µs: 12 (0%) | |
| 3050µs-3100µs: 6 (0%) | |
| 3100µs-3150µs: 8 (0%) | |
| 3150µs-3200µs: 9 (0%) | |
| 3200µs-3250µs: 18 (0%) | |
| 3250µs-3300µs: 14 (0%) | |
| 3300µs-3350µs: 5 (0%) | |
| 3350µs-3400µs: 11 (0%) | |
| 3400µs-3450µs: 7 (0%) | |
| 3450µs-3500µs: 10 (0%) | |
| 3500µs-3550µs: 5 (0%) | |
| 3550µs-3600µs: 6 (0%) | |
| 3600µs-3650µs: 12 (0%) | |
| 3650µs-3700µs: 7 (0%) | |
| 3700µs-3750µs: 85 (4%) | |
| 3750µs-3800µs: 1765 (88%) | |
| 3800µs-3850µs: 18 (0%) | |
| 3850µs-3900µs: 1 (0%) | |
| 4100µs-4150µs: 1 (0%) | |
| 4600µs-4650µs: 1 (0%) | |
| Total: 2001 Timeout: 4ms | |
| min: 4012µs max: 6078µs mean: 4948µs | |
| 4000µs-4050µs: 11 (0%) | |
| 4050µs-4100µs: 15 (0%) | |
| 4100µs-4150µs: 12 (0%) | |
| 4150µs-4200µs: 10 (0%) | |
| 4200µs-4250µs: 11 (0%) | |
| 4250µs-4300µs: 15 (0%) | |
| 4300µs-4350µs: 18 (0%) | |
| 4350µs-4400µs: 12 (0%) | |
| 4400µs-4450µs: 10 (0%) | |
| 4450µs-4500µs: 16 (0%) | |
| 4500µs-4550µs: 6 (0%) | |
| 4550µs-4600µs: 10 (0%) | |
| 4600µs-4650µs: 8 (0%) | |
| 4650µs-4700µs: 10 (0%) | |
| 4700µs-4750µs: 13 (0%) | |
| 4750µs-4800µs: 13 (0%) | |
| 4800µs-4850µs: 15 (0%) | |
| 4850µs-4900µs: 19 (0%) | |
| 4900µs-4950µs: 11 (0%) | |
| 4950µs-5000µs: 167 (8%) | |
| 5000µs-5050µs: 1581 (79%) | |
| 5050µs-5100µs: 14 (0%) | |
| 5200µs-5250µs: 1 (0%) | |
| 5250µs-5300µs: 2 (0%) | |
| 6050µs-6100µs: 1 (0%) |
I've recently discovered weird behaviour of EV-loop timers.
First in Tarantool, and now in Perl libev.
Subj:
When asking EV-loop to sleep for 1ms, it does 1.2ms when requesting to sleep for 2ms, it does 2.4ms, for 3ms => 3.7ms for 4ms => 5ms and after that this behaviour stop. So asking to sleep 5ms results in sleep of 6ms