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

file_watcher features causing game to freeze #10573

Closed
Testare opened this issue Nov 15, 2023 · 5 comments · Fixed by #10585
Closed

file_watcher features causing game to freeze #10573

Testare opened this issue Nov 15, 2023 · 5 comments · Fixed by #10585
Labels
A-Assets Load files from disk to use for things like images, models, and sounds C-Bug An unexpected or incorrect behavior C-Usability A targeted quality-of-life change that makes Bevy easier to use

Comments

@Testare
Copy link
Contributor

Testare commented Nov 15, 2023

Bevy version

0.12

[Optional] Relevant system information

Rust version: 1.73 (Not nightly)
Operating Systems: Arch Linux, MacOs Ventura

What you did

I had file_watcher flag turned on in Cargo.toml, ran my code, and updated an asset file.

What went wrong

Game didn't update the assets, game FROZE.

Additional information

  • This issue was discovered as somebody on discord asked about hot reloading on Linux. I had previously been successfully hot-reloading assets in 0.11 so I decided to test and discovered I had an error as well, though theres was more like "it's not always working," and mine was "it's causing my game to freeze."
  • Notes about my game: It is TUI game so there'es no issues with rendering or the like. I had to close the terminal to close the game because it was no longer responding to inputs.
  • I was using a patched version of bevy initially that included some extra commits, but I made some code changes and reverted to 0.12 and the issue remains.
  • I added log statements to my asset loader to see if the error occurred before, after, or during asset load. These log statements were not called, indicating the issue happened before asset loading.
  • For extensive testing I also tried creating a non-asset file, modifying a non-asset file, and removing a non-asset file while the code was running. Even if the file wasn't an asset, the game froze when it was modified. The game did NOT freeze when it was deleted. On Arch Linux is also freezes when a file is created, but it freezes on both Arch Linux AND MacOs when a file is modified.
  • I tested modifying files without the file_watcher feature flag, and editing the assets predictably did not cause any failures. I tried adding the feature via command-line instead of in the Cargo.toml, and that still crashed.
  • Most of this testing I did on Arch Linux, but I also tested on MacOs. This test didn't involve reverting the patch, but I did discover that it still freezes when a file is modified and I made sure to update rust to the same version as on Linux.

Trace log

This is the trace log of the error when I modified the file assets/nightfall/whatever (Not an actual asset) on ArchLinux. The MacOs errors are the same. These logs happen and then the game freezes and there are no more logs recorded.

21:53:54 [TRACE] (1) cq_term::demo: [cq_term/src/demo.rs:134] MOUSE EVENT: MouseEventTty { entity: 58v0, pos: UVec2(0, 0), modifiers: NONE, event_kind: Exit, double_click: false }
21:53:57 [TRACE] (3) notify::inotify: [/home/testare/.cargo/registry/src/index.crates.io-6f17d22bba15001f/notify-6.1.1/src/inotify.rs:205] inotify event: Event { wd: WatchDescriptor { id: 3, fd: (Weak) }, mask: CREATE, cookie: 0, name: Some("4913") }
21:53:57 [TRACE] (3) notify_debouncer_full: [/home/testare/.cargo/registry/src/index.crates.io-6f17d22bba15001f/notify-debouncer-full-0.3.1/src/lib.rs:279] raw event: Event { kind: Create(File), paths: ["/home/testare/arch/n_dit/assets/nightfall/4913"], attr:tracker: None, attr:flag: None, attr:info: None, attr:source: None }
21:53:57 [TRACE] (3) notify::inotify: [/home/testare/.cargo/registry/src/index.crates.io-6f17d22bba15001f/notify-6.1.1/src/inotify.rs:205] inotify event: Event { wd: WatchDescriptor { id: 3, fd: (Weak) }, mask: ATTRIB, cookie: 0, name: Some("4913") }
21:53:57 [TRACE] (3) notify_debouncer_full: [/home/testare/.cargo/registry/src/index.crates.io-6f17d22bba15001f/notify-debouncer-full-0.3.1/src/lib.rs:279] raw event: Event { kind: Modify(Metadata(Any)), paths: ["/home/testare/arch/n_dit/assets/nightfall/4913"], attr:tracker: None, attr:flag: None, attr:info: None, attr:source: None }
21:53:57 [TRACE] (3) notify::inotify: [/home/testare/.cargo/registry/src/index.crates.io-6f17d22bba15001f/notify-6.1.1/src/inotify.rs:205] inotify event: Event { wd: WatchDescriptor { id: 3, fd: (Weak) }, mask: CLOSE_WRITE, cookie: 0, name: Some("4913") }
21:53:57 [TRACE] (3) notify_debouncer_full: [/home/testare/.cargo/registry/src/index.crates.io-6f17d22bba15001f/notify-debouncer-full-0.3.1/src/lib.rs:279] raw event: Event { kind: Access(Close(Write)), paths: ["/home/testare/arch/n_dit/assets/nightfall/4913"], attr:tracker: None, attr:flag: None, attr:info: None, attr:source: None }
21:53:57 [TRACE] (3) notify::inotify: [/home/testare/.cargo/registry/src/index.crates.io-6f17d22bba15001f/notify-6.1.1/src/inotify.rs:205] inotify event: Event { wd: WatchDescriptor { id: 3, fd: (Weak) }, mask: DELETE, cookie: 0, name: Some("4913") }
21:53:57 [TRACE] (3) notify_debouncer_full: [/home/testare/.cargo/registry/src/index.crates.io-6f17d22bba15001f/notify-debouncer-full-0.3.1/src/lib.rs:279] raw event: Event { kind: Remove(File), paths: ["/home/testare/arch/n_dit/assets/nightfall/4913"], attr:tracker: None, attr:flag: None, attr:info: None, attr:source: None }
21:53:57 [TRACE] (3) notify::inotify: [/home/testare/.cargo/registry/src/index.crates.io-6f17d22bba15001f/notify-6.1.1/src/inotify.rs:205] inotify event: Event { wd: WatchDescriptor { id: 3, fd: (Weak) }, mask: MOVED_FROM, cookie: 10080, name: Some("whatever") }
21:53:57 [TRACE] (3) notify_debouncer_full: [/home/testare/.cargo/registry/src/index.crates.io-6f17d22bba15001f/notify-debouncer-full-0.3.1/src/lib.rs:279] raw event: Event { kind: Modify(Name(From)), paths: ["/home/testare/arch/n_dit/assets/nightfall/whatever"], attr:tracker: Some(10080), attr:flag: None, attr:info: None, attr:source: None }
21:53:57 [TRACE] (3) notify::inotify: [/home/testare/.cargo/registry/src/index.crates.io-6f17d22bba15001f/notify-6.1.1/src/inotify.rs:205] inotify event: Event { wd: WatchDescriptor { id: 3, fd: (Weak) }, mask: CREATE, cookie: 0, name: Some("whatever") }
21:53:57 [TRACE] (3) notify_debouncer_full: [/home/testare/.cargo/registry/src/index.crates.io-6f17d22bba15001f/notify-debouncer-full-0.3.1/src/lib.rs:279] raw event: Event { kind: Create(File), paths: ["/home/testare/arch/n_dit/assets/nightfall/whatever"], attr:tracker: None, attr:flag: None, attr:info: None, attr:source: None }
21:53:57 [TRACE] (3) notify::inotify: [/home/testare/.cargo/registry/src/index.crates.io-6f17d22bba15001f/notify-6.1.1/src/inotify.rs:205] inotify event: Event { wd: WatchDescriptor { id: 3, fd: (Weak) }, mask: MODIFY, cookie: 0, name: Some("whatever") }
21:53:57 [TRACE] (3) notify_debouncer_full: [/home/testare/.cargo/registry/src/index.crates.io-6f17d22bba15001f/notify-debouncer-full-0.3.1/src/lib.rs:279] raw event: Event { kind: Modify(Data(Any)), paths: ["/home/testare/arch/n_dit/assets/nightfall/whatever"], attr:tracker: None, attr:flag: None, attr:info: None, attr:source: None }
21:53:57 [TRACE] (3) notify::inotify: [/home/testare/.cargo/registry/src/index.crates.io-6f17d22bba15001f/notify-6.1.1/src/inotify.rs:205] inotify event: Event { wd: WatchDescriptor { id: 3, fd: (Weak) }, mask: ATTRIB, cookie: 0, name: Some("whatever") }
21:53:57 [TRACE] (3) notify_debouncer_full: [/home/testare/.cargo/registry/src/index.crates.io-6f17d22bba15001f/notify-debouncer-full-0.3.1/src/lib.rs:279] raw event: Event { kind: Modify(Metadata(Any)), paths: ["/home/testare/arch/n_dit/assets/nightfall/whatever"], attr:tracker: None, attr:flag: None, attr:info: None, attr:source: None }
21:53:57 [TRACE] (3) notify::inotify: [/home/testare/.cargo/registry/src/index.crates.io-6f17d22bba15001f/notify-6.1.1/src/inotify.rs:205] inotify event: Event { wd: WatchDescriptor { id: 3, fd: (Weak) }, mask: CLOSE_WRITE, cookie: 0, name: Some("whatever") }
21:53:57 [TRACE] (3) notify_debouncer_full: [/home/testare/.cargo/registry/src/index.crates.io-6f17d22bba15001f/notify-debouncer-full-0.3.1/src/lib.rs:279] raw event: Event { kind: Access(Close(Write)), paths: ["/home/testare/arch/n_dit/assets/nightfall/whatever"], attr:tracker: None, attr:flag: None, attr:info: None, attr:source: None }
21:53:57 [TRACE] (3) notify::inotify: [/home/testare/.cargo/registry/src/index.crates.io-6f17d22bba15001f/notify-6.1.1/src/inotify.rs:205] inotify event: Event { wd: WatchDescriptor { id: 3, fd: (Weak) }, mask: ATTRIB, cookie: 0, name: Some("whatever") }
21:53:57 [TRACE] (3) notify_debouncer_full: [/home/testare/.cargo/registry/src/index.crates.io-6f17d22bba15001f/notify-debouncer-full-0.3.1/src/lib.rs:279] raw event: Event { kind: Modify(Metadata(Any)), paths: ["/home/testare/arch/n_dit/assets/nightfall/whatever"], attr:tracker: None, attr:flag: None, attr:info: None, attr:source: None }
@Testare Testare added C-Bug An unexpected or incorrect behavior S-Needs-Triage This issue needs to be labelled labels Nov 15, 2023
@Testare
Copy link
Contributor Author

Testare commented Nov 16, 2023

Worked on this a lot today, tried to use some rust debugging tools to try and make it easier but it only made it more difficult >,<

In any case, using logs and print statements I was able to chase the error down, from file_watcher.rs to down to here: https:/bevyengine/bevy/blob/main/crates/bevy_asset/src/server/mod.rs#L495

In this function, I placed different output flags around and determined, that despite the call to detach, the function freezes after the call to spawn before it reaches the detach method. Inside the async(?) thread, the the thread hangs on the call to server.data.infos.read(), which is a "RwLockReadGuard".

So, yeah, seems like a deadlock situation, combined with what seems to be an attempt to spawn a separate detached thread that is actually blocking the calling thread. It's possible that if we could actually spawn this detached thread and continue running the natural course of logic would release the lock?

@Testare
Copy link
Contributor Author

Testare commented Nov 16, 2023

Yeah, looking at docs it looks like IoTaskPool.spawn(..) is NOT supposed to block the thread that calls it.

Yet it seems like the issue isn't with IoTaskPool's code. It looks like for whatever reason when compiling the code, the code inside the async { .. } block is running like a regular block? I added a print statement inside the IoTaskPool::spawn statement and it didn't get called, suggesting the block is executing before the spawn function? But I'm pretty new to async code in rust so I'm not sure how this normally works

@mockersf
Copy link
Member

do you have Bevy feature multi-threaded enabled?

@Testare
Copy link
Contributor Author

Testare commented Nov 16, 2023

Nevermind, I removed the method and the Future code wasn't being executed. Much confusion!

Not explicitly, let me try that

@Testare
Copy link
Contributor Author

Testare commented Nov 16, 2023

That fixed it!

I suppose we need to either make multi-threaded required by file_watcher, or find a way to make the thread work when not multi-threaded.

@nicopap nicopap added A-Assets Load files from disk to use for things like images, models, and sounds C-Usability A targeted quality-of-life change that makes Bevy easier to use and removed S-Needs-Triage This issue needs to be labelled labels Nov 16, 2023
github-merge-queue bot pushed a commit that referenced this issue Nov 20, 2023
# Objective

Fix the `bevy_asset/file_watcher` feature in practice depending on
multithreading, while not informing the user of it.

**As I understand it** (I didn't check it), the file watcher feature
depends on spawning a concurrent thread to receive file update events
from the `notify-debouncer-full` crate. But if multithreading is
disabled, that thread will never have time to read the events and
consume them.

- Fixes #10573 


## Solution

Add a `compile_error!` causing compilation failure if `file_watcher` is
enabled while `multi-threaded` is disabled.

This is considered better than adding a dependency on `multi-threaded`
on the `file_watcher`, as (according to @mockersf) toggling on/off
`multi-threaded` has a non-zero chance of changing behavior. And we
shouldn't implicitly change behavior. A compilation failure prevents
compilation of code that is invalid, while informing the user of the
steps needed to fix it.
rdrpenguin04 pushed a commit to rdrpenguin04/bevy that referenced this issue Jan 9, 2024
# Objective

Fix the `bevy_asset/file_watcher` feature in practice depending on
multithreading, while not informing the user of it.

**As I understand it** (I didn't check it), the file watcher feature
depends on spawning a concurrent thread to receive file update events
from the `notify-debouncer-full` crate. But if multithreading is
disabled, that thread will never have time to read the events and
consume them.

- Fixes bevyengine#10573 


## Solution

Add a `compile_error!` causing compilation failure if `file_watcher` is
enabled while `multi-threaded` is disabled.

This is considered better than adding a dependency on `multi-threaded`
on the `file_watcher`, as (according to @mockersf) toggling on/off
`multi-threaded` has a non-zero chance of changing behavior. And we
shouldn't implicitly change behavior. A compilation failure prevents
compilation of code that is invalid, while informing the user of the
steps needed to fix it.
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
A-Assets Load files from disk to use for things like images, models, and sounds C-Bug An unexpected or incorrect behavior C-Usability A targeted quality-of-life change that makes Bevy easier to use
Projects
None yet
Development

Successfully merging a pull request may close this issue.

3 participants