bevy icon indicating copy to clipboard operation
bevy copied to clipboard

Move event traces to detailed_trace!

Open james7132 opened this issue 2 years ago • 1 comments

Objective

Noticed while writing #7728 that we are using trace! logs in our event functions. This has shown to have significant overhead, even trace level logs are disabled globally, as seen in #7639.

Solution

Use the detailed_trace! macro introduced in #7639. Also removed the event_trace function that was only used in one location.

This probably shouldn't be merged without #7731 being addressed so we can measure the impact this has on events.


Changelog

Changed: Event trace logs are now feature gated behind the detailed-trace feature.

james7132 avatar Feb 17 '23 20:02 james7132

This may have an impact outside of just user-facing events. Since #7713, this also impacts component removal:

https://github.com/james7132/bevy_asm_tests/blob/9fd5f20e252f6e4401d352a0b675098d7e010aff/results/entity_remove.s#L2340-L2356

james7132 avatar Mar 14 '23 09:03 james7132

When setting up the benchmarks for #8251, I found nearly 5x improvements to event sending. Didn't impact event iteration.

events_send/100         time:   [90.729 ns 95.492 ns 101.49 ns]
                        change: [-79.753% -78.836% -77.676%] (p = 0.00 < 0.05)
                        Performance has improved.
Found 9 outliers among 100 measurements (9.00%)
  9 (9.00%) high severe
events_send/1000        time:   [849.67 ns 860.86 ns 872.59 ns]
                        change: [-81.817% -81.597% -81.366%] (p = 0.00 < 0.05)
                        Performance has improved.
events_send/10000       time:   [8.7305 µs 8.8142 µs 8.9191 µs]
                        change: [-81.592% -81.491% -81.366%] (p = 0.00 < 0.05)
                        Performance has improved.
Found 1 outliers among 100 measurements (1.00%)
  1 (1.00%) high severe
events_send/50000       time:   [43.570 µs 43.714 µs 43.883 µs]
                        change: [-81.689% -81.612% -81.532%] (p = 0.00 < 0.05)
                        Performance has improved.
Found 11 outliers among 100 measurements (11.00%)
  7 (7.00%) high mild
  4 (4.00%) high severe

events_iter/100         time:   [113.66 ns 113.78 ns 113.93 ns]
                        change: [-0.1316% +0.0158% +0.1647%] (p = 0.85 > 0.05)
                        No change in performance detected.
Found 10 outliers among 100 measurements (10.00%)
  3 (3.00%) high mild
  7 (7.00%) high severe
events_iter/1000        time:   [1.0906 µs 1.0921 µs 1.0941 µs]
                        change: [-0.0203% +0.1790% +0.4699%] (p = 0.19 > 0.05)
                        No change in performance detected.
Found 13 outliers among 100 measurements (13.00%)
  4 (4.00%) high mild
events_iter/10000       time:   [10.856 µs 10.867 µs 10.881 µs]
                        change: [-0.1066% +0.0310% +0.2378%] (p = 0.76 > 0.05)
                        No change in performance detected.
Found 8 outliers among 100 measurements (8.00%)
  7 (7.00%) high severe
                        change: [-0.5442% -0.1756% +0.0919%] (p = 0.34 > 0.05)
                        No change in performance detected.
Found 12 outliers among 100 measurements (12.00%)
  5 (5.00%) high mild
  7 (7.00%) high severe

james7132 avatar Mar 29 '23 20:03 james7132

Yikes (or yay?) 5x improvement!

danchia avatar Mar 29 '23 23:03 danchia