Subscritptions are run twice

[snaggen]

Is there an existing issue for this?

• I have searched the existing issues.

Is this issue related to iced?

• My hardware is compatible and my graphics drivers are up-to-date.

What happened?

I started to notice that the Subscription::channel closure in Cosmic Term run twice on startup, and started to track it backwards in the stack. This only happens with --release builds, and not an all platforms ( https://github.com/jackpot51 could not reproduce this on his hardware ), on my Thinkpad T15 Gen 1, it happens every time.

So, I notice that in iced/winit/src/application.rs we actually have two calls to runtime.track(application.subscription(...)). One in run_instance and another in update. Both these calls will trigger a new call to cosmic terms subscription::channel closure. This should not happen since there is a check in tracker.rs to prevent this:

iced/futures/src/subscription/tracker.rs

Line 85 in 8781348

if self.subscriptions.contains_key(&id) {

But for some reason, this check fails, the id between the first call is different from the calls in the update function. So, when I started to dig further I found that the hashing function for Map, is the one that is getting different from the first to the following calls, and more exact it is the self.mapper.hash(state); that differs.

iced/futures/src/subscription.rs

Line 166 in 8781348

self.mapper.hash(state);

And I debug print the self.mapper, the function pointers have different values. So, for some reason, it seems that the compiler, when run in release mode, decides to perform some optimizations to either move the closure between the calls, or create two different closures (I'm no expert in compiler optimizations, I just see that the closure have different pointers for the call from run_instance and update ).

This is a quite critical bug, since that causes Subscription::channel to be run twice, and if you don't count on that but assume it only run once, you may end up with a dead channel in the application.
In Cosmic Term, this was worked around by commit
pop-os/cosmic-term@4401a7d

The iced version is
https://github.com/pop-os/iced/tree/6115280d5277c50b8539d4eff6ab61050c51b592
since that is what libcosmic uses. But, I don't see anything that would have fixed this.

This is with rustc rustc 1.75.0 (82e1608df 2023-12-21)
some info from /proc/cpuinfo

model name  : Intel(R) Core(TM) i7-10510U CPU @ 1.80GHz
flags       : fpu vme de pse tsc msr pae mce cx8 apic sep mtrr pge mca cmov pat pse36 clflush dts acpi mmx fxsr sse sse2 ss ht tm pbe syscall nx pdpe1gb rdtsc
p lm constant_tsc art arch_perfmon pebs bts rep_good nopl xtopology nonstop_tsc cpuid aperfmperf pni pclmulqdq dtes64 monitor ds_cpl vmx est tm2 ssse3 sdbg fm
a cx16 xtpr pdcm pcid sse4_1 sse4_2 x2apic movbe popcnt tsc_deadline_timer aes xsave avx f16c rdrand lahf_lm abm 3dnowprefetch cpuid_fault epb ssbd ibrs ibpb
stibp ibrs_enhanced tpr_shadow flexpriority ept vpid ept_ad fsgsbase tsc_adjust sgx bmi1 avx2 smep bmi2 erms invpcid mpx rdseed adx smap clflushopt intel_pt x
saveopt xsavec xgetbv1 xsaves dtherm ida arat pln pts hwp hwp_notify hwp_act_window hwp_epp vnmi md_clear flush_l1d arch_capabilities
vmx flags   : vnmi preemption_timer invvpid ept_x_only ept_ad ept_1gb flexpriority tsc_offset vtpr mtf vapic ept vpid unrestricted_guest ple pml ept_mode_base

What is the expected behavior?

The real fix would be to make the self.mapper.hash(state); stable.

Version

master

Operating System

Linux

Do you have any log output?

No response

[hecrj]

mapper is only involved in mapped subscriptions, which does not seem to be the case for the channel subscription mentioned:

pop-os/cosmic-term@4401a7d#diff-42cb6807ad74b3e201c5a7ca98b911c5fa08380e942be6e4ac5807f8377f87fcR1599-R1615

Thus, I don't think the diagnosis here is correct. I will need an SSCCE to further investigate the issue.

[snaggen]

There is a map involved, I realize I'm not sure why it gets in there.

But also, just add a eprintln! and print self.mapper ( or do a hash if you want to do it properly) to see it for your self.

[snaggen]

I have also tested to remove the self.mapper.hash(state) line, and the issue went away.

[hecrj]

There are many mapped subscriptions, so you will see multiple printed messages. That is perfectly normal.

It's unclear what the issue is. We really need an SSCCE here.

[snaggen]

For the channel subscription in cosmic term, I added debug lines to see the exact flow, and I calculated the hashes separately to for comparison. And for the channel subscription there the cash consists of first the hash of the channel is, but then also a map hash.
And I printed the hash of all the parts separately, and the hash of the mapper changed.

As I mentioned in the comment above, the issue goes away if you comment out the hashing of the mapper.

So, I'm quite confident that the issue is with the hashing of the mapper.

[snaggen]

There are many mapped subscriptions, so you will see multiple printed messages. That is perfectly normal.

It's unclear what the issue is. We really need an SSCCE here.

Yes I saw these. But since I had calculated the hash for the id of the subscription, and printed all the parts of the hash calculation, I was able to identify and follow the hash calculation for the specific subscription.

[snaggen]

During testing I used a panic that triggered the second time the channel subscription in cosmic term got invoked. So, it was quite easy to spot that things stopped to panic when the mapper hash was commented out.

[hecrj]

Well, we certainly still need to figure out why there is a mapper involved in an unmapped subscription.

And I need an SSCCE to reproduce, debug, and fix the issue.

[hecrj]

Furthermore, subscriptions are meant to be dropped when changes to the map function or the id happen. That is expected.

[snaggen]

Furthermore, subscriptions are meant to be dropped when changes to the map function or the id happen. That is expected.

Yes, but in this case the hash of the map changes, even though there was no change to the actual subscription. The only change to the mapper function seems to be due to --release causing some optimization behavior, causing the mapper function pointer to change between calls.
So, is it really stable to hash a closure like this?

[snaggen]

Do you have the hardware to reproduce the issue? That can easily be tested by doing a release build of cosmic term master. If you have the hardware to reproduce this, you should see a warning at startup about the workaround used.

[snaggen]

And I don't have a small and contained case for this, I just have used cosmic term to trigger this during my debugging.
If you need I can provide some more testing if needed.

[hecrj]

I think the map we are talking about may be this one here:

https://github.com/pop-os/libcosmic/blob/ca1469a6b26eb7fbdc8e28d6135e86593e6a77fd/src/app/cosmic.rs#L171

I am not sure how optimizations could cause the function pointer super::Message::App to change between calls. Maybe the subscription calls are being inlined by the compiler in some circumstances.

Maybe an #[inline(never)] directive could fix it.

[snaggen]

Not in front of a computer right now, but send a diff if you want me to test it tomorrow morning CET.

[hecrj]

I think a better fix would be to replace the mapper instead of dropping the mapped subscription when it changes. I'll look into it.

[hecrj]

@snaggen I've opened #2237 which suggests a relatively simple fix.