Skip to content

debounced watcher 100% cpu with many writes on a single file #177

@vemoo

Description

@vemoo

The time is spent here;
https://github.com/passcod/notify/blob/8130fa759c600d6c92d97c95e72a5a50f6036cf9/src/debounce/timer.rs#L66
because a lot of Action::Schedule followed by a Action::Ignore are sent for the same event drain_request_queue and can't receive them fast enough.

Here some code to reproduce it:

let tdir = TempDir::new("temp_dir")?;
let dir = tdir.path();

let delay = Duration::from_millis(250);

let (tx, rx) = mpsc::channel();
let mut watcher: RecommendedWatcher = Watcher::new(tx, delay)?;

watcher.watch(&dir, RecursiveMode::Recursive)?;

let dir = dir.to_path_buf();
let now = Instant::now();

let io_thread = thread::spawn(move || {
    let mut file = File::create(dir.join("foo.txt")).unwrap();
    while now.elapsed() < Duration::from_millis(500) {
        // spam with writes
        file.write_all(b"Hello, world!").unwrap();
    }
});
// wait for 1 event
let _ = rx.recv()?;

println!("elapsed: {:?}", now.elapsed());
io_thread.join().unwrap();

In my machine this takes around 5s on debug and 40s on release.

I've fixed that issue here: https://github.com/vemoo/notify/tree/timer-fix. But in the process I've found another issue.

Whats the meaning or delay in the debounced watcher?

  • Don't emit and event until delay has passed since last event for a given path
  • or, emit at most one event per delay for a given path

Because at the moment, at least for many writes on the same file, the first is happening. If we take code and sleep between writes:

let tdir = TempDir::new("temp_dir")?;
let dir = tdir.path();

let delay = Duration::from_millis(250);

let (tx, rx) = mpsc::channel();
let mut watcher: RecommendedWatcher = Watcher::new(tx, delay)?;

watcher.watch(&dir, RecursiveMode::Recursive)?;

let dir = dir.to_path_buf();
let now = Instant::now();

let io_thread = thread::spawn(move || {
    let mut file = File::create(dir.join("foo.txt")).unwrap();
    while now.elapsed() < Duration::from_secs(1) {
        file.write_all(b"Hello, world!").unwrap();
        std::thread::sleep(Duration::from_millis(100));
    }
});
// wait for 1 event
let _ = rx.recv()?;

println!("elapsed: {:?}", now.elapsed());
io_thread.join().unwrap();

It takes more than 1s, when I would expect the first event to be recieved after delay has passed. I've also started on working on a fix for this, but I'm not sure what the behaviour should be.

Metadata

Metadata

Assignees

No one assigned

    Labels

    No labels
    No labels

    Type

    No type

    Projects

    No projects

    Milestone

    No milestone

    Relationships

    None yet

    Development

    No branches or pull requests

    Issue actions