Most of the time, the 5 second timeout for perfetto stop retry fires.
I added some very simple time logging (since we can't take a perfetto trace) to macrobenchmark, and found stopping the perfetto trace takes upwards of 5 seconds much of the time. Sample logs from local change:
07-15 00:30:16.693 20383 20403 D TIMING : 546 ms compilation
07-15 00:30:16.905 20383 20403 D TIMING : 211 ms setupBlock
07-15 00:30:17.036 20383 20403 D TIMING : 131 ms record-start
07-15 00:30:17.036 20383 20403 D TIMING : 0 ms startMetrics
07-15 00:30:18.717 20383 20403 D TIMING : 1680 ms measureBlock
07-15 00:30:18.717 20383 20403 D TIMING : 0 ms stopMetrics
07-15 00:30:23.965 20383 20403 D TIMING : 5247 ms record-stop ### NOTE - bad
07-15 00:30:24.680 20383 20403 D TIMING : 715 ms getMetrics
07-15 00:30:24.698 20383 20403 D TIMING : 18 ms appendUiState
07-15 00:30:24.699 20383 20403 D TIMING : 8005 ms total - iter 0
07-15 00:30:24.949 20383 20403 D TIMING : 250 ms setupBlock
07-15 00:30:25.087 20383 20403 D TIMING : 137 ms record-start
07-15 00:30:25.087 20383 20403 D TIMING : 0 ms startMetrics
07-15 00:30:26.971 20383 20403 D TIMING : 1884 ms measureBlock
07-15 00:30:26.971 20383 20403 D TIMING : 0 ms stopMetrics
07-15 00:30:27.180 20383 20403 D TIMING : 209 ms record-stop ### NOTE - good
07-15 00:30:28.030 20383 20403 D TIMING : 849 ms getMetrics
07-15 00:30:28.050 20383 20403 D TIMING : 20 ms appendUiState
07-15 00:30:28.050 20383 20403 D TIMING : 3351 ms total - iter 1
07-15 00:30:28.294 20383 20403 D TIMING : 243 ms setupBlock
07-15 00:30:28.428 20383 20403 D TIMING : 134 ms record-start
07-15 00:30:28.428 20383 20403 D TIMING : 0 ms startMetrics
07-15 00:30:30.325 20383 20403 D TIMING : 1896 ms measureBlock
07-15 00:30:30.325 20383 20403 D TIMING : 0 ms stopMetrics
07-15 00:30:35.579 20383 20403 D TIMING : 5253 ms record-stop ### NOTE - bad
07-15 00:30:36.416 20383 20403 D TIMING : 837 ms getMetrics
07-15 00:30:36.439 20383 20403 D TIMING : 22 ms appendUiState
07-15 00:30:36.439 20383 20403 D TIMING : 8389 ms total - iter 2
Description
Most of the time, the 5 second timeout for perfetto stop retry fires.
I added some very simple time logging (since we can't take a perfetto trace) to macrobenchmark, and found stopping the perfetto trace takes upwards of 5 seconds much of the time. Sample logs from local change: