Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Timer resolution is half what it should be. #126

Open
lhallam opened this issue Apr 19, 2016 · 14 comments
Open

Timer resolution is half what it should be. #126

lhallam opened this issue Apr 19, 2016 · 14 comments

Comments

@lhallam
Copy link

lhallam commented Apr 19, 2016

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
Copy link
Owner

dpc commented Apr 20, 2016

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
Copy link
Owner

dpc commented Apr 20, 2016

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

@dpc
Copy link
Owner

dpc commented Apr 20, 2016

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

@lhallam
Copy link
Author

lhallam commented Apr 20, 2016

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 lhallam closed this as completed Apr 20, 2016
@lhallam
Copy link
Author

lhallam commented Apr 20, 2016

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

@lhallam lhallam reopened this Apr 20, 2016
@dpc
Copy link
Owner

dpc commented Apr 20, 2016

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
Copy link
Owner

dpc commented Apr 20, 2016

Also, I should fix the documentation, yes.

@lhallam
Copy link
Author

lhallam commented Apr 20, 2016

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 lhallam changed the title Timers only work in 200ms intervals Timer resolution is half what it should be. Apr 20, 2016
@lhallam
Copy link
Author

lhallam commented Apr 20, 2016

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
Copy link
Owner

dpc commented Apr 21, 2016

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
Copy link
Owner

dpc commented Apr 29, 2016

Any findings? I might look into it during weekend.

@lhallam
Copy link
Author

lhallam commented Apr 29, 2016

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
Copy link
Author

lhallam commented Apr 29, 2016

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
Copy link
Owner

dpc commented Apr 29, 2016

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. :)

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

2 participants