Timer resolution is half what it should be.

[lhallam]

This is a strange one. Timers seem to work in 200ms intervals, between 1 and 200ms it's always rounded up to 200ms, after that it's the closest 200ms interval.

Here's a test comparing std::thread::sleep_ms and mioco::sleep_ms (which uses timers):

extern crate mioco;
extern crate time;

fn main(){
    for i in 0..10{
        let ms = 2i64.pow(i);
        println!("std::thread::sleep_ms({})...",ms);
        time(|| std::thread::sleep_ms(ms as u32));
    }
    println!("starting mioco");
    mioco::start(move ||{
        for i in 0..10{
            let ms = 2i64.pow(i);
            println!("mioco::sleep_ms({})...",ms);
            time(|| mioco::sleep_ms(ms as u32));
        }
    }).unwrap();
}

fn time<F: Fn()>(f: F){
    let start = time::precise_time_ns();
    f();
    let time_taken = time::precise_time_ns() - start;
    println!("done! took {}ms", (time_taken as f64) / 1000000f64);
}

And the results in a table:

time(ms) std::thread::sleep_ms   mioco::sleep_ms
------------------------------------------------
1        1.057826ms              32.131549ms
2        2.05608ms               200.293778ms
4        4.056809ms              200.295234ms
8        8.059839ms              200.30042ms
16       16.075645ms             199.276578ms
32       32.070559ms             200.271908ms
64       64.073655ms             200.27593ms
128      128.071303ms            199.30185ms
256      256.068135ms            400.502087ms
512      512.071987ms            599.767383ms

I'm looking into this, I'll post if I find anything interesting ^^

[dpc]

Could it be:

http://dpc.pw/mioco/mioco/fn.sleep.html

"Warning: When issued inside of mioco, the precision of this call (and other time based functionality) is limited by mio event loop settings. Any small value of time_ms will effectively be rounded up to mio_orig::EventLoop::timer_tick_ms()."

?

[dpc]

Default timer_tick_ms is 100ms it seems: http://dpc.pw/mioco/src/mio/event_loop.rs.html#28

[dpc]

I think it's a combination of the above and #31

[lhallam]

Ah, that's it. I checked the docs for Timer, but not sleep >_<

So it looks like the only way to have arbitrary precision timers is using EventLoop::run_once(timout)?

[lhallam]

Actually, perhaps this should be kept open as a documentation issue?

[dpc]

You can create a Mioco instance with arbitrary settings using http://dpc.pw/mioco/mioco/struct.Mioco.html#method.new_configured

Config exposes mio settings via http://dpc.pw/mioco/mioco/struct.Config.html#method.event_loop , where you can just change the timer resolution to your requirements.

Also, I'm keeping this issue open as there is still something wrong. default tick is 100ms, while in mioco the timer is firing in 200ms.

[dpc]

Also, I should fix the documentation, yes.

[lhallam]

Yeah, the precision seems to be half of what it should be, setting mioco_conf.event_loop().timer_tick_ms(10) gives 20ms jumps.

As for the arbitrary precision thing, I was just reading the mio code wrong, I though EventLoop::io_poll would time out on every tick, rather than just on those with timers set, which would make large timers with high precision expensive... It's too early for this :3

[lhallam]

A 100ms timer using mioco: (https://gist.github.com/xalri/c3ff520c2a0da24eb1b446e9fa3b64b2)

timer_res: 27760132.555586 : starting timer
mioco::src::timer: Timer: should_resume? false
mioco::src::coroutine: T0: C1: blocked on RW { read: true, write: false }
mioco::src::coroutine: T0: C1: pausing
mioco::src::timer: Timer(1024): set timeout in 99ms
mioco::src::timer: 27760132.633695 : ^^^
mio::timer: inserted timout; slot=2; token=Token(0)
mio::event_loop: event loop tick
mio::timer: tick_to; now=1; tick=0
mio::timer: ticking; curr=Token(18446744073709551615)
mio::timer: ticking; curr=Token(18446744073709551615)
mio::event_loop: event loop tick
mio::timer: tick_to; now=3; tick=2
mio::timer: ticking; curr=Token(0)
mio::timer: triggering; token=Token(0)
mio::timer: unlinking timeout; slot=2; token=Token(0)
mioco::src::thread: 27760417.167199 : got timeout for Token(1024)
mioco::src::thread: T0: token(Token(1024)) ready
mioco::src::coroutine: T0: C1: event for io(0)
mioco::src::coroutine: T0: C1: ready
mioco::src::coroutine: T0: C1: resuming
mioco::src::evented: T0: C1: resumed due to event Event { id: EventSourceId(0), rw: RW { read: true, write: false } }
mioco::src::timer: Timer: should_resume? true
timer_res: 27760417.289966 : timer finished

A 100ms timer using just mio: (https://gist.github.com/xalri/6dd14b0ddcbec85778be9e54845839e5)

mio: 30502274.147963 : starting timer
mio::poll: registering with poller
mio::timer: inserted timout; slot=1; token=Token(0)
mio::event_loop: event loop tick
mio::timer: tick_to; now=1; tick=0
mio::timer: ticking; curr=Token(18446744073709551615)
mio::timer: ticking; curr=Token(0)
mio::timer: triggering; token=Token(0)
mio::timer: unlinking timeout; slot=1; token=Token(0)
mio: 30502385.200879 : got timeout
mio::timer: tick_to; now=1; tick=1
mio::timer: ticking; curr=Token(18446744073709551615)

So, if I'm reading it right, in the mioco timer mio inserts the timeout in the slot past where you would expect it to be?..

I'll have another look in the morning, I'm sure I can figure this one out.

[dpc]

I did some similiar analysis, and for whatever reason even when mioco is calling timeout_ms(0) the mio timer seem to kick in two ticks, not just in next one.

If you have time, please try to figure out this one, I appreciate any help, since I'm very short on time. :)

[dpc]

Any findings? I might look into it during weekend.

[lhallam]

13292646.237421 | mioco::src::timer | Timer(1024): set timeout in 99ms
13292646.246189 | mio::event_loop | event_loop.timeout Duration { secs: 0, nanos: 99000000 }
13292646.251632 | mio::timer | timeout_ms now: 13292646   delay: 99
13292646.257049 | mio::timer | timeout_at_ms 13292745
13292646.262397 | mio::timer | timeout_at_ms -start = 110
13292646.268261 | mio::timer | timeout_at_ms tick = 2, self.tick 0
13292646.275068 | mio::timer | inserted timout; slot=2; token=Token(0)
13292646.285556 | mio::event_loop | event loop tick
13292646.290401 | mio::timer | next_tick_in_ms  self.tick: 0, self.tick_ms: 100
13292646.293627 | mio::timer | next_tick_in_ms  now: 13292646, next: 13292735, nxt-now: 89
13292735.421547 | mio::event_loop | io_process(..); cnt=0; len=0
13292735.454249 | mio::timer | tick_to; now=1; tick=0
13292735.468544 | mio::timer | ticking; curr=Token(18446744073709551615)
13292735.481389 | mio::timer | ticking; curr=Token(18446744073709551615)
13292735.49797 | mio::event_loop | event loop tick
13292735.508683 | mio::timer | next_tick_in_ms  self.tick: 2, self.tick_ms: 100
13292735.520443 | mio::timer | next_tick_in_ms  now: 13292735, next: 13292935, nxt-now: 200
13292935.75364 | mio::event_loop | io_process(..); cnt=0; len=0
13292935.776166 | mio::timer | tick_to; now=3; tick=2
13292935.790972 | mio::timer | ticking; curr=Token(0)
13292935.807 | mio::timer | triggering; token=Token(0)

13292646.262397 | mio::timer | timeout_at_ms -start = 110

This might be part of it, there's an offset between the eventloop starting and the timer being set, mio rounds up to 2 ticks, otherwise it would be firing early. So it would make sense for the first timer to fire after 200ms, but then:

13292735.49797 | mio::event_loop | event loop tick 13292735.508683 | mio::timer | next_tick_in_ms self.tick: 2, self.tick_ms: 100 13292735.520443 | mio::timer | next_tick_in_ms now: 13292735, next: 13292935, nxt-now: 200 13292935.75364 | mio::event_loop | io_process(..); cnt=0; len=0 13292935.776166 | mio::timer | tick_to; now=3; tick=2

.. it doesn't fire for 300ms. Mio just seems to skip the tick with the timeout.

https://github.com/carllerche/mio/blob/master/src/timer.rs#L202

At the end of the first Timer::tick_to(), self.tick = 2, but then:

https://github.com/carllerche/mio/blob/master/src/timer.rs#L69 (called by https://github.com/carllerche/mio/blob/master/src/event_loop.rs#L320)

let nxt = self.start + (self.tick + 1) * self.tick_ms;

.. this gives the time at the end of self.tick, skipping the actual time it should trigger. I tried changing tick_to so that it wouldn't advance self.tick past now (https://gist.github.com/xalri/bc54030fa7ca48496fa253586d6f6a99), and it seems to have done something, the first timer fires after ~180ms rather than 280ms, and further timers take 100ms. I really don't understand mio timers enough to know what's actually happening, but I suppose the next step would be to try to replicate this in just mio.

[lhallam]

the next step would be to try to replicate this in just mio.

Well that was easy, all you need is the offset between creating and starting the event loop:

#[macro_use] extern crate log;
extern crate mio;

mod logger;
use std::time::Duration;
use std::thread;

struct Timer;
impl mio::Handler for Timer{
    type Timeout = ();
    type Message = ();

    fn timeout(&mut self, evl: &mut mio::EventLoop<Timer>, t: ()){
        info!("got timeout");
        evl.timeout((),Duration::from_millis(100));
    }
}

fn main() {
    logger::init().unwrap();
    info!("starting timer");
    let mut event_loop = mio::EventLoop::new().unwrap();
    std::thread::sleep_ms(10);
    event_loop.timeout((),Duration::from_millis(100));
    event_loop.run(&mut Timer{});
}

15722145.382777 | mio | starting timer
15722457.027286 | mio | got timeout
15722656.289368 | mio | got timeout
15722856.572325 | mio | got timeout
15723056.844613 | mio | got timeout
15723257.115592 | mio | got timeout
15723456.381801 | mio | got timeout
15723656.65503 | mio | got timeout
15723856.924654 | mio | got timeout
15724057.186565 | mio | got timeout

The first timer takes 300ms, the rest 200ms.

So am I missing something or is this a bug in mio?

[dpc]

Last time I checked it looked like a mio bug, yes, but I wanted to double check before blaming mio. :D

Could you report and explain it to mio authors? They are really nice people too. :)