Periodic Stutters on some Mac hardware

[CleanCut]

Bevy version

The problem is on both:

• 0.6.0
• The current main branch (3fcdc5a at the moment)

Bevy 0.5.0 did not exhibit this problem.

If I add the plugins from either of the projects below, then I get periodic stuttering / dropped frames. I'm speculating this has something to do with the big rendering overhaul plus these plugins using custom shaders (?).

• bevy_prototype_debug_lines
• bevy_prototype_lyon

Note: I don't have to use the plugins to see the problem (though I do use them in the code provided)! Just adding the plugin app.add_plugin( ... ) is enough to trigger the problem in my testing.

Operating system & version

Here's the specs for my workstation with the problem.

$ rustc --version
rustc 1.58.0 (02072b482 2022-01-11)

I also tried Rust 1.57 -- no change. I've run cargo update to make sure I'm using the latest crates.io dependencies -- no change.

NOTE: This very similar system does NOT show the problem, or at least I can't reproduce it. I don't know whether the difference is the OS revision, the specific hardware, or something else.

What you did

$ git clone https://github.com/CleanCut/rusty_engine.git
$ cd rusty_engine
$ git checkout choppy
$ cargo run --release --example road_race

# Use the arrow keys to avoid obstacles, just so the game proceeds long enough to observe
# the periodic stutters on some hardware. In my experience, every 0.25 to 5 seconds there
# will be a stutter. The length of the stutter is variable--I've observed stutter durations of
# maybe a single frame to nearly a full second (my guesstimate -- I don't know how to
# measure it!).

# Compare to...

$ git checkout smooth -- Update: no stutters on my Intel boxen, still stutters on my M1 & @mockersf's M1 Max
$ cargo run --release --example road_race

What you expected to happen

No stutters.

What actually happened

Stutters.

Additional information

I originally thought this was a bug in bevy_prototype_debug_lines, so I filed an issue with that project.

There are 5 tags/branches in the CleanCut/rusty_engine repository you can check out if you like. They're all exhibit the stutter for me except the first one:

• The smooth tag uses neither plugin - Update: Though this didn't stutter on my Intel machines, we discovered it still stutters on Apple M1 and M1 Max machines.
• The choppy tag is bevy_prototype_debug_lines with Bevy 0.6.0
• The bevy-main-debug-lines branch is bevy_prototype_debug_lines with Bevy main
• The choppy-lyon tag is bevy_prototype_lyon with Bevy 0.6.0
• The bevy-main-lyon branch is bevy_prototype_lyon with Bevy main

If you prefer an example where you don't have to dodge obstacles, you can run:

• cargo run --release --example collision
• (optional) Press the C key to turn on the debug lines (it doesn't make a difference, but the debug lines are what I'm trying to implement nicely)
• Hold down the left mouse button to rotate the sprite -- then just wait for stutters.

[mockersf]

I tried running branches choppy and smooth on my mac (macOS Monterey 12.1, m1 max) and both run the same for me... they both stutter

[CleanCut]

Whoah! smooth didn't stutter for me on Intel Montery 12.1 (hence the name). 🤔 Do you normally get stutter with Bevy 0.6? Is there something I can do to help narrow down the issue? Maybe try out that "tracy" profiler? I know little to nothing about the guts of rendering, but I'm more than willing to do some legwork if it'll help.

I've got access to a first-gen M1 -- I can try that as well for another data point.

[CleanCut]

I confirmed that I see stutter on all five branches I mentioned on an M1 (including the smooth branch). I guess it's just the current state of the new renderer?

[rparrett]

I enabled the bevy "trace_tracy" and ran road_race from the "choppy" branch. (2021 m1 mac)

Tracy lets you sort all "frame" spans by execution time. One particular long (34ms) frame looked like this:

With the full name of that bottom-most "RenderDevice" span being:

system{�[3mname�[0m�[2m=�[0m"(bevy_ecs::change_detection::ResMut<bevy_render::render_asset::ExtractedAssets<bevy_render::mesh::mesh::Mesh>>, bevy_ecs::change_detection::ResMut<std::collections::hash::map::HashMap<bevy_asset::handle::Handle<bevy_render::mesh::mesh::Mesh>, bevy_render::mesh::mesh::GpuMesh, ahash::random_state::RandomState>>, bevy_ecs::change_detection::ResMut<bevy_render::render_asset::PrepareNextFrameAssets<bevy_render::mesh::mesh::Mesh>>, bevy_ecs::system::system_param::Res<bevy_render::renderer::render_device::RenderDevice>)"}

And lasting 24ms.

I don't really know how to interpret this.

[rparrett]

That particular long frame was captured some number of nanoseconds after startup, so maybe that's not interesting. Here's another "long frame" from 9 seconds into play:

where there seems to be a lot of action in the PostUpdate stage, but not in a named span.

[CleanCut]

@rparrett Is there a doc somewhere that I can read to learn how to get set up with the tracing stuff? The 0.6 news post just mentions the trace_tracy feature and links to https://github.com/wolfpld/tracy - I'm having trouble figuring out how to get/build/run tracy to get the profile. I skimmed through the whole tracy PDF user guide...and it's not helping with the "get started" stuff.

Update: Naturally, right after I ask the question I finally figure out the building step. Sort of. There are hints at the bottom of page 18 in the PDF user manual (sheesh, talk about buried -- put it on the readme, folks -- or better yet add it to homebrew).

Here's what I did to build the tracy profiler on macOS:

# (I've done this on macOS 11.6.2 Big Sur Intel -- I'll try other OS/hardware combinations later)

$ brew install pkg-config glfw freetype capstone gtk+3
# (clone the wolfpld/tracy repo and `cd` into it)
$ git checkout v0.7.8
$ cd profiler/build/unix
$ make release

# I copy `Tracy-release` to `tracy` somewhere in my PATH, but you can do what you want

This builds a binary called Tracy-release in that profiler/build/unix directory. Running it opens a UI.

Then I added the trace_tracy feature to bevy in my Cargo.toml and rebuilt it. The OS prompted me whether I wanted to accept incoming network connections, I OK'd it (twice--once for the bevy app, once for the tracy profiler app).

The tracy profiler UI auto-detects the presence of my running program, but when I mouse over to connect to it a box pops up with the error: Incompatible Protocol! (used: 46, required: 55) Building on tag v0.7.8 fixes that.

Then you click on the line with your program's name (road_race in this screenshot) and it connects!

[rparrett]

Yeah, no kidding. It's not too bad though:

1. https://dev.to/stein/build-the-tracy-profiler-server-on-macos-36k6
2. enable the trace_tracy feature on your bevy dependency
3. run the profiler and click connect
4. run your app

But if anyone has any tips for actually using Tracy well with a touchpad, I'm all ears.

[CleanCut]

Thanks! Now I've just got to figure out which older version of Tracy corresponds to "protocol version 46"

[mockersf]

I'm using tracy tag v0.7.8 to build locally and it works with Bevy

But if anyone has any tips for actually using Tracy well with a touchpad, I'm all ears.

Have a very steady hand when scrolling horizontally

[CleanCut]

I'm using tracy tag v0.7.8 to build locally and it works with Bevy

Thanks! I updated my instructions above.

Now my challenge will be to learn how to use this thing. I get the feeling that this will be a valuable skill in my future life using Bevy.

Maybe I can find some helpful info to add to this issue tonight.

[CleanCut]

Any tips on how best to use the Tracy Profiler UI?

[CleanCut]

Last night I profiled on the M1 for about 20 minutes. Ironically, it ran much more smoothly with the tracing enabled. At the end I figured out how to use the search to identify the longest frame, which was only ~42ms. 🤷🏻‍♂️ I need to try it on the Intel box.

[CleanCut]

Just enabling the trace_tracy feature on both my M1 and Intel boxes decreases the amount of stutter by quite a bit, but it does still occasionally occur. Here's the dump of a quick trace I did. About 11s in a frame took 34ms. Does this shed any light on the subject for anyone? It appears suspiciously like the threads in green and/or yellow are the culprits, but I really don't have any clue how Bevy's (or wgpu's) rendering works. The names on those bars are:

• (green) bevy_render::render_component::prepare_uniform_components<bevy_sprite::mesh2d::mesh::Mesh2dUniform>
• (yellow) bevy_ecs::change_detection::ResMut<bevy_render::render_asset::ExtractedAssets<bevy_render::mesh::mesh::Mesh>>, bevy_ecs::change_detection::ResMut<std::collections::hash::map::HashMap<bevy_asset::handle::Handle<bevy_render::mesh::mesh::Mesh>, bevy_render::mesh::mesh::GpuMesh, ahash::random_state::RandomState>>, bevy_ecs::change_detection::ResMut<bevy_render::render_asset::PrepareNextFrameAssets<bevy_render::mesh::mesh... (I can't find a way to get the rest of it)
• 

If you zoom out a bit, you'll notice that those two threads are not active with those two items at the same time in any of the well-timed frames:

I have no idea where to go from here.

[adsick]

I don't think this is something Mac-specific: Toqozz/bevy_debug_lines#14 (comment)

[CleanCut]

Resolved in Bevy 0.8

[adsick]

@CleanCut which PR is the fix for this?

[rparrett]

Most likely #4744