Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

feat(core): Log protocol upgrades on trace #3128

Merged
merged 9 commits into from
Dec 14, 2022
Merged

feat(core): Log protocol upgrades on trace #3128

Show file tree
Hide file tree
Changes from 1 commit
Commits
Show all changes
9 commits
Select commit Hold shift + click to select a range
fe1dabb
core: improve logging of libp2p_core::upgrade::apply
rkuhn Nov 16, 2022
18002ff
Apply suggestions from code review
rkuhn Nov 17, 2022
4ccd17c
more PR review
rkuhn Nov 17, 2022
1fb088a
replace test with doctest
rkuhn Nov 24, 2022
e38213c
Update core/src/upgrade.rs
rkuhn Nov 24, 2022
579d86e
test all the bytes
rkuhn Dec 5, 2022
90ab1ed
move DisplayProtocolName to apply.rs and make pub(crate)
rkuhn Dec 9, 2022
249cb42
Merge branch 'master' into rku/improve-upgrade-apply-logging
mxinden Dec 14, 2022
26a39d2
Merge branch 'master' into rku/improve-upgrade-apply-logging
mergify[bot] Dec 14, 2022
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
21 changes: 21 additions & 0 deletions core/src/upgrade.rs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -86,6 +86,7 @@ pub use self::{
};
pub use crate::Negotiated;
pub use multistream_select::{NegotiatedComplete, NegotiationError, ProtocolError, Version};
use std::fmt::{Display, Write};

/// Types serving as protocol names.
///
Expand Down Expand Up @@ -134,6 +135,26 @@ impl<T: AsRef<[u8]>> ProtocolName for T {
}
}

pub struct DisplayProtocolName<N>(N);
impl<N: ProtocolName> Display for DisplayProtocolName<N> {
fn fmt(&self, f: &mut std::fmt::Formatter<'_>) -> std::fmt::Result {
for byte in self.0.protocol_name() {
if (b' '..=b'~').contains(byte) {
f.write_char(char::from(*byte))?;
} else {
write!(f, "<{:02X}>", byte)?;
thomaseizinger marked this conversation as resolved.
Show resolved Hide resolved
}
}
Ok(())
}
}
rkuhn marked this conversation as resolved.
Show resolved Hide resolved

#[test]
fn protocol_name_display() {
assert_eq!(DisplayProtocolName("hello").to_string(), "hello");
assert_eq!(DisplayProtocolName("hellö/").to_string(), "hell<C3><B6>/");
}
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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.

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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

Copy link
Contributor Author

@rkuhn rkuhn Nov 17, 2022 •
edited
Loading

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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)

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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.

Copy link
Contributor

@thomaseizinger thomaseizinger Nov 22, 2022 •
edited
Loading

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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 :)

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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


/// Common trait for upgrades that can be applied on inbound substreams, outbound substreams,
/// or both.
pub trait UpgradeInfo {
Expand Down
39 changes: 30 additions & 9 deletions core/src/upgrade/apply.rs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -18,14 +18,17 @@
// FROM, OUT OF OR IN CONNECTION WITH THE SOFTWARE OR THE USE OR OTHER
// DEALINGS IN THE SOFTWARE.

use crate::upgrade::{InboundUpgrade, OutboundUpgrade, ProtocolName, UpgradeError};
use crate::upgrade::{
DisplayProtocolName, InboundUpgrade, OutboundUpgrade, ProtocolName, UpgradeError,
};
use crate::{connection::ConnectedPoint, Negotiated};
use futures::{future::Either, prelude::*};
use log::debug;
use multistream_select::{self, DialerSelectFuture, ListenerSelectFuture};
use std::{iter, mem, pin::Pin, task::Context, task::Poll};

pub use multistream_select::Version;
use smallvec::SmallVec;

// TODO: Still needed?
/// Applies an upgrade to the inbound and outbound direction of a connection or substream.
Expand Down Expand Up @@ -105,6 +108,7 @@ where
},
Upgrade {
future: Pin<Box<U::Future>>,
name: SmallVec<[u8; 32]>,
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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>,

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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.

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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.

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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.

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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.

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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.

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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.

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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.

},
Undefined,
}
Expand Down Expand Up @@ -137,22 +141,30 @@ where
return Poll::Pending;
}
};
let name = SmallVec::from_slice(info.protocol_name());
self.inner = InboundUpgradeApplyState::Upgrade {
future: Box::pin(upgrade.upgrade_inbound(io, info.0)),
name,
};
}
InboundUpgradeApplyState::Upgrade { mut future } => {
InboundUpgradeApplyState::Upgrade { mut future, name } => {
match Future::poll(Pin::new(&mut future), cx) {
Poll::Pending => {
self.inner = InboundUpgradeApplyState::Upgrade { future };
self.inner = InboundUpgradeApplyState::Upgrade { future, name };
return Poll::Pending;
}
Poll::Ready(Ok(x)) => {
debug!("Successfully applied negotiated protocol");
log::trace!(
"Successfully applied negotiated inbound protocol {}",
rkuhn marked this conversation as resolved.
Show resolved Hide resolved
DisplayProtocolName(name)
);
return Poll::Ready(Ok(x));
}
Poll::Ready(Err(e)) => {
debug!("Failed to apply negotiated protocol");
debug!(
"Failed to apply negotiated inbound protocol {}",
rkuhn marked this conversation as resolved.
Show resolved Hide resolved
DisplayProtocolName(name)
);
return Poll::Ready(Err(UpgradeError::Apply(e)));
}
}
Expand Down Expand Up @@ -185,6 +197,7 @@ where
},
Upgrade {
future: Pin<Box<U::Future>>,
name: SmallVec<[u8; 32]>,
},
Undefined,
}
Expand Down Expand Up @@ -217,22 +230,30 @@ where
return Poll::Pending;
}
};
let name = SmallVec::from_slice(info.protocol_name());
self.inner = OutboundUpgradeApplyState::Upgrade {
future: Box::pin(upgrade.upgrade_outbound(connection, info.0)),
name,
};
}
OutboundUpgradeApplyState::Upgrade { mut future } => {
OutboundUpgradeApplyState::Upgrade { mut future, name } => {
match Future::poll(Pin::new(&mut future), cx) {
Poll::Pending => {
self.inner = OutboundUpgradeApplyState::Upgrade { future };
self.inner = OutboundUpgradeApplyState::Upgrade { future, name };
return Poll::Pending;
}
Poll::Ready(Ok(x)) => {
debug!("Successfully applied negotiated protocol");
log::trace!(
"Successfully applied negotiated outbound protocol {}",
DisplayProtocolName(name)
);
return Poll::Ready(Ok(x));
}
Poll::Ready(Err(e)) => {
debug!("Failed to apply negotiated protocol");
debug!(
"Failed to apply negotiated outbound protocol {}",
DisplayProtocolName(name)
);
return Poll::Ready(Err(UpgradeError::Apply(e)));
}
}
Expand Down