Unexpected outcome with higher optimisation levels

Hello.. I noticed something very weird while trying out some rust profiles today. I have this profile.

[profile.release-max]
inherits = "release"
lto = "fat"
codegen-units = 1
panic = "abort"
opt-level = 3

This seems to be completely removing my prometheus metrics and tracing::trace! logs in the following block of code, when compiled for linux-arm64 ..

let updated = self.subs.clone();
tracing::trace!(?updated, "sending updates to writer");
self.metric_active_subs.observe(updated.len() as f64);
self.send_cmd(Cmd::Modes(updated)).await?;
self.ctrl.apply(self.id, to_sub, to_unsub, to_replay).await;

It looks like the tracing::trace! line and the self.metric_active_subs line are getting removed completely (no metrics in my endpoint and this log doesn't come even with trace level enabled)..

Is this expected? observe() has side-effects, so compiler shouldn't end up removing that?..

Interestingly, same profile doesn't remove these on my MacOS M2 arm64.

Note: Tracing is definitely not globally disabled in release builds because I can see other trace logs from different parts of the same module too.

No, profiles and optimization do not delete code with observable side effects. Profiles do control configuration like cfg(debug_assertions) which libraries may choose to use to disable certain code.

Most likely you have some other logic bug causing this code not to run or the effects of those lines to not be observed.

Less likely, you have UB somewhere that’s corrupting the execution so that those lines are effectively skipped. Such UB doesn't usually cause such neat high-level effects, but it is a suspect any time increasing optimization causes misbehavior.

1 Like

Most likely you have some other logic bug causing this code not to run or the effects of those lines to not be observed.

I assumed this too and spent two hours trying to find that logic issue. Ultimately, I gave up and decided to just switch back to normal release profile just to see, and it just worked.

And, I have 5-10 other metrics, and tracing::trace! usage throughout the same module and crate as well. And I was still able to see all those while only this section was not working as expected. I can also confirm that the logic around this (e.g., self.send_cmd(...).await?) was working perfectly fine as well.

I don't know how I can share a proof-of-concept for this because any of my attempt to strip down the code might cause it to be completely different scenario and compiler would most likely behave differently .. Only way I can think of is to get on a call and show this :sweat_smile: .

Okay, never mind..

It was a logic issue, but I spent trying to find it in code while it was in my CI :sweat_smile: .. Since profile name is different, the CI was taking the old build available in the release/ folder and deploying that again and again and I did no realise.

3 Likes

That sounds like you are caching more than you should, and it might bite you again. Consider using something smarter like https://github.com/Swatinem/rust-cache/ — it only caches dependencies and not your own project files, so you can never have a stale build, and the cache is smaller and only needs to be updated if dependencies change.

1 Like

We are using a private GitHub runner and it was uploading the cache to S3 every time and downloading it which was effectively taking long time overall. So we had disabled it and were using a local directory on the runner node to cache.. But I agree with you, at the very least, might need to ensure we cleanup older builds so this kind of issue doesn't happen. I will relook at rust-cache, Thanks!

This topic was automatically closed 90 days after the last reply. We invite you to open a new topic if you have further questions or comments.