feat(core): Log protocol upgrades on trace

[rkuhn]

Description

Previously, every inbound or outbound upgrade generated a log at debug level, without information about the upgrade.
This commit changes it such that successful upgrades are logged at trace level (due to ubiquitous use of OneShot handlers) and that the negotiated protocol name is included in the message.

Notes

Links to any relevant issues

Open Questions

Change checklist

• I have performed a self-review of my own code
• I have made corresponding changes to the documentation
• I have added tests that prove my fix is effective or that my feature works
• A changelog entry has been made in the appropriate crates

[thomaseizinger]

Thanks!

A few minor suggestions.

[thomaseizinger]

Can we put this with the other tests at the bottom please in a mod tests?

[rkuhn]

ah, I looked at some tests.rs but found it irrelevant, so placed the test next to the thing; recently I began doubting the dogma of “mod tests at the bottom” for such things because they serve to clearly document the intended behaviour right where people read the code

[thomaseizinger]

I don't mind much where the tests are but I want them to be feature-gated on cfg(test) so we don't compile them into binaries of our users.

[rkuhn]

ah, good point: we have a deal :-)

[rkuhn]

Wow, that was interesting: I checked what was needed, and indeed #[test] alone already hides the function in normal builds. This is the expansion:

    extern crate test;
    #[cfg(test)]
    #[rustc_test_marker = "upgrade::protocol_name_display"]
    pub const protocol_name_display: test::TestDescAndFn = test::TestDescAndFn {
        desc: test::TestDesc {
            name: test::StaticTestName("upgrade::protocol_name_display"),
            ignore: false,
            ignore_message: ::core::option::Option::None,
            compile_fail: false,
            no_run: false,
            should_panic: test::ShouldPanic::No,
            test_type: test::TestType::UnitTest,
        },
        testfn: test::StaticTestFn(|| test::assert_test_result(protocol_name_display())),
    };
    fn protocol_name_display() {
        ...
    }

So thanks to our exchange I learnt that #[cfg(test)] is only needed for hiding test-related support functions and infrastructure.
(EDIT: fn protocol_name_display is elided from the .rlib as dead code)

[thomaseizinger]

Are you sure extern crate test is not being dragged in?

[rkuhn]

Hmm, after lunch I followed this rabbit hole for a little while longer and compared the liblibp2p_core.rlib for three cases:

1. without the test (commented out)
2. test with only the #[test] attribute (120 bytes size increase, caused by a 16 byte increase and other changes in lib.rmeta)
3. with additional #[cfg(test)] attribute (106 bytes size increase, caused by a 104 byte increase in lib.rmeta)

As the metadata format is somewhat obscure, I decided to stop here. To my knowledge, extern crate test only brings a declared dependency explicitly into scope, which has been unnecessary since the 2015 edition (IIRC). Judging by the absence of the string protocol_name_display in the rlib, I’d leave the code as is, unless you (or others) have a strong opinion.

[thomaseizinger]

I am leaning towards adding a mod tests block:

1. Based on your investigation (thanks for doing that!), it seems to reduce code size.
2. It is consistent across the codebase.

I don't have a strong opinion on where the mod tests block sits although we tend to put it at the bottom of the file.

The argument that it should be next to the function is definitely valid, however I think the more common case is that you want to read the production code, not the test code.

If you want to actually co-locate it, you could make it a rustdoc test :)

[rkuhn]

That is a brilliant idea, in particular, because it found a usability bug (no public constructor).

[rkuhn]

The failures in earlier commits are related to semver, which doesn’t seem to be caused by this PR, so I consider this ready now.

[mxinden]

Oh wonderful. Just 3 days ago I was debugging an issue and wished I had this patch in place. Thanks @rkuhn for the improvement.

[mxinden]

A stream upgrade involves various I/O operations on many layers. I don't think a heap allocated 32 byte vector have a significant performance impact.

Thus, unless the performance improvement is proven through a benchmark, I suggest allocating on the heap here.

Suggested change

	name: SmallVec<[u8; 32]>,
	name: Vec<u8>,

[rkuhn]

Given that all protocol names I’m aware of are quite small, I see no reason to unconditionally allocate on the heap — why should that be the default that needs no reason? I could reduce the inline capacity to keep size_of equal to that of a Vec<u8>, if you want.

[thomaseizinger]

I am with @rkuhn here. I think it is good to avoid allocations for the majority of the cases. I don't see the use of a different type as too much complexity.

[mxinden]

I see no reason to unconditionally allocate on the heap — why should that be the default that needs no reason?

Reason for me to not use SmallVec by default is that it adds noise, additional compile time and increases the attack vector in our dependency supply chain. Though the last one might be a lost fight in the first place.

I wrote a benchmark to try to replicate a performance benefit using SmallVec here. I have not been able thus far. Please take a look at Actyx#95. Maybe I can nerd-snipe either of you into proving me wrong @rkuhn and @thomaseizinger.

I am sorry in case this comes across as nit-picky. I am not trying to start an argument. I am genuinely interested in performance optimizations in rust-libp2p. I am curious in which cases we could optimize through stack allocation. I don't think this is one of those cases.

On a more general note, again out of curiosity, is either of you aware of a case where heap allocation is faster than stack allocation? I can not come up with a real world case where the heap would be faster than the stack.

[rkuhn]

To me this is foremost a question of using the most appropriate data structure for the job. SmallVec was already in the dependencies, and it is better suited than Vec due to usage characteristics, so I used it.

---

Regarding the benchmark: memory management cannot be benchmarked in this fashion. In general, microbenchmarks like yours are very rarely meaningful and even then they require careful interpretation of the result. The reason is that most of the time you are looking at a huge machine doing a tiny task, with all sorts of optimisations kicking in. And when you run a relevant task instead, different optimisations will completely change the picture. It is quite obvious that a stack allocation takes less than one CPU cycle and that a heap allocation can in general not be this fast. If your microbenchmark finds them to be equally fast, then your heap usage allows the malloc implementation to optimise down to a single pointer subtraction — which is a very likely thread-local optimisation to make for malloc().

But all of this theory is irrelevant in my opinion because we’re not optimising for the last percent of performance (as far as I’m aware we’re nowhere close to getting there at this point). So I just propose usage of the most appropriate data structure at hand.

[thomaseizinger]

I think it is reasonable to trust in CS knowledge like "stack allocations are faster than heap", even if you can't produce a micro benchmark that proves it.

Soon, this will be replaced by Cow so I am happy either way. If @mxinden feels strongly, let's go with Vec.

[rkuhn]

BTW: this discussion uses “heap” and “stack”, but “stack” doesn’t actually enter the picture in the code in question since we’re talking about a memory slot in a generator, which will end up spawned onto a thread pool, so allocated on the heap in any case.

[thomaseizinger]

Right, what would be the right terminology then (out of curiosity?). "local variable"?

[rkuhn]

That sounds appropriate to me — it’ll end up being stored in a compiler-generated enum variant if it lives across an .await point.

[mxinden]

Thanks for expanding here. I think the points above are valid. That said, I haven't yet formed a good guiding principle for rust-libp2p.

As said above, the concrete instance is not relevant. Let's get this merged. Looking forward to the easier debugging of protocol upgrades on streams.

[thomaseizinger]

One more thought! I'll let @mxinden decide regarding Vec vs SmallVec.

[thomaseizinger]

LGTM, thanks!

[mxinden]

Thanks @rkuhn!

Approvals have been dismissed because the PR was updated after the send-it label was applied.