Span parenting so that system spans are correctly linked in multithreaded executor

[mockersf]

Objective

When using a parallel executor, system spans are not correctly related to the stage/frame spans

Example logs:

Jul 01 18:39:40.772  INFO system{name="load_gltf::rotator_system"}: load_gltf: rotating light
Jul 01 18:39:40.853  INFO system{name="load_gltf::rotator_system"}: load_gltf: rotating light
Jul 01 18:39:40.866  INFO system{name="load_gltf::rotator_system"}: load_gltf: rotating light
Jul 01 18:39:40.881  INFO system{name="load_gltf::rotator_system"}: load_gltf: rotating light
Jul 01 18:39:40.907  INFO system{name="load_gltf::rotator_system"}: load_gltf: rotating light
Jul 01 18:39:40.928  INFO system{name="load_gltf::rotator_system"}: load_gltf: rotating light
Jul 01 18:39:40.972  INFO bevy_app:frame:stage{name="Update"}:system{name="load_gltf::rotator_system"}: load_gltf: rotating light
Jul 01 18:39:40.997  INFO system{name="load_gltf::rotator_system"}: load_gltf: rotating light
Jul 01 18:39:41.027  INFO system{name="load_gltf::rotator_system"}: load_gltf: rotating light
Jul 01 18:39:41.064  INFO system{name="load_gltf::rotator_system"}: load_gltf: rotating light
Jul 01 18:39:41.092  INFO system{name="load_gltf::rotator_system"}: load_gltf: rotating light
Jul 01 18:39:41.108  INFO system{name="load_gltf::rotator_system"}: load_gltf: rotating light
Jul 01 18:39:41.140  INFO system{name="load_gltf::rotator_system"}: load_gltf: rotating light
Jul 01 18:39:41.176  INFO system{name="load_gltf::rotator_system"}: load_gltf: rotating light
Jul 01 18:39:41.208  INFO bevy_app:frame:stage{name="Update"}:system{name="load_gltf::rotator_system"}: load_gltf: rotating light
Jul 01 18:39:41.237  INFO system{name="load_gltf::rotator_system"}: load_gltf: rotating light
Jul 01 18:39:41.258  INFO system{name="load_gltf::rotator_system"}: load_gltf: rotating light
Jul 01 18:39:41.288  INFO system{name="load_gltf::rotator_system"}: load_gltf: rotating light

Logs with bevy_app:frame... are when the system is executed on the main thread, the other lines are on other threads

Solution

Correctly pass the parent span, and set it as parent when creating a new one. I also added the frame count to the frame span as this was how this issue was noticed on discord

Jul 01 19:05:46.288  INFO bevy_app:frame{frame_count=1}:stage{name="Update"}:system{name="load_gltf::rotator_system"}: load_gltf: rotating light
Jul 01 19:05:46.390  INFO bevy_app:frame{frame_count=2}:stage{name="Update"}:system{name="load_gltf::rotator_system"}: load_gltf: rotating light
Jul 01 19:05:46.400  INFO bevy_app:frame{frame_count=3}:stage{name="Update"}:system{name="load_gltf::rotator_system"}: load_gltf: rotating light
Jul 01 19:05:46.426  INFO bevy_app:frame{frame_count=4}:stage{name="Update"}:system{name="load_gltf::rotator_system"}: load_gltf: rotating light
Jul 01 19:05:46.460  INFO bevy_app:frame{frame_count=5}:stage{name="Update"}:system{name="load_gltf::rotator_system"}: load_gltf: rotating light
Jul 01 19:05:46.501  INFO bevy_app:frame{frame_count=6}:stage{name="Update"}:system{name="load_gltf::rotator_system"}: load_gltf: rotating light
Jul 01 19:05:46.524  INFO bevy_app:frame{frame_count=7}:stage{name="Update"}:system{name="load_gltf::rotator_system"}: load_gltf: rotating light
Jul 01 19:05:46.564  INFO bevy_app:frame{frame_count=8}:stage{name="Update"}:system{name="load_gltf::rotator_system"}: load_gltf: rotating light
Jul 01 19:05:46.596  INFO bevy_app:frame{frame_count=9}:stage{name="Update"}:system{name="load_gltf::rotator_system"}: load_gltf: rotating light
Jul 01 19:05:46.626  INFO bevy_app:frame{frame_count=10}:stage{name="Update"}:system{name="load_gltf::rotator_system"}: load_gltf: rotating light
Jul 01 19:05:46.657  INFO bevy_app:frame{frame_count=11}:stage{name="Update"}:system{name="load_gltf::rotator_system"}: load_gltf: rotating light
Jul 01 19:05:46.690  INFO bevy_app:frame{frame_count=12}:stage{name="Update"}:system{name="load_gltf::rotator_system"}: load_gltf: rotating light
Jul 01 19:05:46.725  INFO bevy_app:frame{frame_count=13}:stage{name="Update"}:system{name="load_gltf::rotator_system"}: load_gltf: rotating light
Jul 01 19:05:46.758  INFO bevy_app:frame{frame_count=14}:stage{name="Update"}:system{name="load_gltf::rotator_system"}: load_gltf: rotating light
Jul 01 19:05:46.791  INFO bevy_app:frame{frame_count=15}:stage{name="Update"}:system{name="load_gltf::rotator_system"}: load_gltf: rotating light
Jul 01 19:05:46.825  INFO bevy_app:frame{frame_count=16}:stage{name="Update"}:system{name="load_gltf::rotator_system"}: load_gltf: rotating light
Jul 01 19:05:46.858  INFO bevy_app:frame{frame_count=17}:stage{name="Update"}:system{name="load_gltf::rotator_system"}: load_gltf: rotating light
Jul 01 19:05:46.892  INFO bevy_app:frame{frame_count=18}:stage{name="Update"}:system{name="load_gltf::rotator_system"}: load_gltf: rotating light
Jul 01 19:05:46.923  INFO bevy_app:frame{frame_count=19}:stage{name="Update"}:system{name="load_gltf::rotator_system"}: load_gltf: rotating light
Jul 01 19:05:46.958  INFO bevy_app:frame{frame_count=20}:stage{name="Update"}:system{name="load_gltf::rotator_system"}: load_gltf: rotating light

[DJMcNab]

As far as I can see this is an exact copy of the SingleThreadedExecutor's code to calculate this - it might be worth factoring it out?

[CAD97]

I didn't find this when I was looking, so I also made #2905 to fix this same instance of the span parent chain breaking. #2905 accomplishes this in a simpler fashion, as it manages to continue to use tracing's implicit TLS scoping (by hoisting span creation outside of the task onto the main thread) rather than adding a new channel to pass the span parent down.

[mockersf]

closed for better fix in #2905