No string in slog (#2017)

## Issue Addressed

Following slog's documentation, this should help a bit with string allocations. I left it run for two days and mem usage is lower. This is of course anecdotal, but shouldn't harm anyway 

## Proposed Changes

remove `String` creation in logs when possible
This commit is contained in:
divma
2020-11-30 10:33:00 +00:00
parent 3f036fd193
commit 8fcd22992c
22 changed files with 160 additions and 158 deletions

View File

@@ -206,7 +206,7 @@ impl<T: BeaconChainTypes> AttestationService<T> {
// This will subscribe to long-lived random subnets if required.
trace!(self.log,
"Validator subscription";
"subscription" => format!("{:?}", subscription),
"subscription" => ?subscription,
);
self.add_known_validator(subscription.validator_index);
@@ -220,7 +220,7 @@ impl<T: BeaconChainTypes> AttestationService<T> {
Err(e) => {
warn!(self.log,
"Failed to compute subnet id for validator subscription";
"error" => format!("{:?}", e),
"error" => ?e,
"validator_index" => subscription.validator_index
);
continue;
@@ -257,7 +257,7 @@ impl<T: BeaconChainTypes> AttestationService<T> {
} else {
trace!(self.log,
"Subscribed to subnet for aggregator duties";
"exact_subnet" => format!("{:?}", exact_subnet),
"exact_subnet" => ?exact_subnet,
"validator_index" => subscription.validator_index
);
}
@@ -339,7 +339,7 @@ impl<T: BeaconChainTypes> AttestationService<T> {
// peer before they can be removed.
warn!(self.log,
"Not enough time for a discovery search";
"subnet_id" => format!("{:?}", exact_subnet)
"subnet_id" => ?exact_subnet
);
None
}

View File

@@ -961,7 +961,7 @@ impl Drop for SendOnDrop {
self.log,
"Unable to free worker";
"msg" => "did not free worker, shutdown may be underway",
"error" => e.to_string()
"error" => %e
)
}
}

View File

@@ -212,7 +212,7 @@ impl<T: BeaconChainTypes> Worker<T> {
self.log,
"New block received";
"slot" => verified_block.block.slot(),
"hash" => verified_block.block_root.to_string()
"hash" => %verified_block.block_root
);
self.propagate_validation_result(
message_id,
@@ -232,7 +232,7 @@ impl<T: BeaconChainTypes> Worker<T> {
| Err(e @ BlockError::NotFinalizedDescendant { .. })
| Err(e @ BlockError::BeaconChainError(_)) => {
debug!(self.log, "Could not verify block for gossip, ignoring the block";
"error" => e.to_string());
"error" => %e);
// Prevent recurring behaviour by penalizing the peer slightly.
self.penalize_peer(peer_id.clone(), PeerAction::HighToleranceError);
self.propagate_validation_result(message_id, peer_id, MessageAcceptance::Ignore);
@@ -252,7 +252,7 @@ impl<T: BeaconChainTypes> Worker<T> {
| Err(e @ BlockError::WeakSubjectivityConflict)
| Err(e @ BlockError::GenesisBlock) => {
warn!(self.log, "Could not verify block for gossip, rejecting the block";
"error" => e.to_string());
"error" => %e);
self.propagate_validation_result(
message_id,
peer_id.clone(),
@@ -307,15 +307,15 @@ impl<T: BeaconChainTypes> Worker<T> {
debug!(
self.log,
"Invalid gossip beacon block";
"outcome" => format!("{:?}", other),
"block root" => format!("{}", block.canonical_root()),
"outcome" => ?other,
"block root" => %block.canonical_root(),
"block slot" => block.slot()
);
self.penalize_peer(peer_id, PeerAction::MidToleranceError);
trace!(
self.log,
"Invalid gossip beacon block ssz";
"ssz" => format!("0x{}", hex::encode(block.as_ssz_bytes())),
"ssz" => format_args!("0x{}", hex::encode(block.as_ssz_bytes())),
);
}
};
@@ -787,8 +787,8 @@ impl<T: BeaconChainTypes> Worker<T> {
debug!(
self.log,
"Received attestation on incorrect subnet";
"expected" => format!("{:?}", expected),
"received" => format!("{:?}", received),
"expected" => ?expected,
"received" => ?received,
);
self.propagate_validation_result(
message_id,

View File

@@ -225,14 +225,14 @@ impl<T: BeaconChainTypes> Router<T> {
self.processor.on_block_gossip(id, peer_id, block);
}
PubsubMessage::VoluntaryExit(exit) => {
debug!(self.log, "Received a voluntary exit"; "peer_id" => format!("{}", peer_id));
debug!(self.log, "Received a voluntary exit"; "peer_id" => %peer_id);
self.processor.on_voluntary_exit_gossip(id, peer_id, exit);
}
PubsubMessage::ProposerSlashing(proposer_slashing) => {
debug!(
self.log,
"Received a proposer slashing";
"peer_id" => format!("{}", peer_id)
"peer_id" => %peer_id
);
self.processor
.on_proposer_slashing_gossip(id, peer_id, proposer_slashing);
@@ -241,7 +241,7 @@ impl<T: BeaconChainTypes> Router<T> {
debug!(
self.log,
"Received a attester slashing";
"peer_id" => format!("{}", peer_id)
"peer_id" => %peer_id
);
self.processor
.on_attester_slashing_gossip(id, peer_id, attester_slashing);

View File

@@ -179,7 +179,7 @@ impl<T: BeaconChainTypes> Processor<T> {
trace!(
self.log,
"Received BlocksByRange Response";
"peer" => peer_id.to_string(),
"peer" => %peer_id,
);
if let RequestId::Sync(id) = request_id {
@@ -206,7 +206,7 @@ impl<T: BeaconChainTypes> Processor<T> {
trace!(
self.log,
"Received BlocksByRoot Response";
"peer" => peer_id.to_string(),
"peer" => %peer_id,
);
if let RequestId::Sync(id) = request_id {
@@ -356,10 +356,9 @@ impl<T: EthSpec> HandlerNetworkContext<T> {
/// Sends a message to the network task.
fn inform_network(&mut self, msg: NetworkMessage<T>) {
let msg_r = &format!("{:?}", msg);
self.network_send
.send(msg)
.unwrap_or_else(|e| warn!(self.log, "Could not send message to the network service"; "error" => %e, "message" => msg_r))
self.network_send.send(msg).unwrap_or_else(
|e| warn!(self.log, "Could not send message to the network service"; "error" => %e),
)
}
/// Disconnects and ban's a peer, sending a Goodbye request with the associated reason.

View File

@@ -241,13 +241,13 @@ fn spawn_service<T: BeaconChainTypes>(
debug!(
service.log,
"Persisting DHT to store";
"Number of peers" => format!("{}", enrs.len()),
"Number of peers" => enrs.len(),
);
match persist_dht::<T::EthSpec, T::HotStore, T::ColdStore>(service.store.clone(), enrs) {
Err(e) => error!(
service.log,
"Failed to persist DHT on drop";
"error" => format!("{:?}", e)
"error" => ?e
),
Ok(_) => info!(
service.log,
@@ -354,9 +354,9 @@ fn spawn_service<T: BeaconChainTypes>(
validation_result,
} => {
trace!(service.log, "Propagating gossipsub message";
"propagation_peer" => format!("{:?}", propagation_source),
"message_id" => message_id.to_string(),
"validation_result" => format!("{:?}", validation_result)
"propagation_peer" => ?propagation_source,
"message_id" => %message_id,
"validation_result" => ?validation_result
);
service
.libp2p
@@ -376,7 +376,7 @@ fn spawn_service<T: BeaconChainTypes>(
service.log,
"Sending pubsub messages";
"count" => messages.len(),
"topics" => format!("{:?}", topic_kinds)
"topics" => ?topic_kinds
);
metrics::expose_publish_metrics(&messages);
service.libp2p.swarm.publish(messages);
@@ -398,7 +398,7 @@ fn spawn_service<T: BeaconChainTypes>(
if service.libp2p.swarm.subscribe_kind(topic_kind.clone()) {
subscribed_topics.push(topic_kind.clone());
} else {
warn!(service.log, "Could not subscribe to topic"; "topic" => format!("{}",topic_kind));
warn!(service.log, "Could not subscribe to topic"; "topic" => %topic_kind);
}
}
@@ -412,13 +412,13 @@ fn spawn_service<T: BeaconChainTypes>(
service.libp2p.swarm.update_enr_subnet(subnet_id, true);
subscribed_topics.push(topic_kind.clone());
} else {
warn!(service.log, "Could not subscribe to topic"; "topic" => format!("{}",topic_kind));
warn!(service.log, "Could not subscribe to topic"; "topic" => %topic_kind);
}
}
}
if !subscribed_topics.is_empty() {
info!(service.log, "Subscribed to topics"; "topics" => format!("{:?}", subscribed_topics));
info!(service.log, "Subscribed to topics"; "topics" => ?subscribed_topics);
}
}
}
@@ -545,7 +545,7 @@ fn spawn_service<T: BeaconChainTypes>(
}
Libp2pEvent::ZeroListeners => {
let _ = shutdown_sender.send("All listeners are closed. Unable to listen").await.map_err(|e| {
warn!(service.log, "failed to send a shutdown signal"; "error" => e.to_string()
warn!(service.log, "failed to send a shutdown signal"; "error" => %e
)
});
}

View File

@@ -611,7 +611,7 @@ impl<T: BeaconChainTypes> SyncManager<T> {
if let Some(peer_info) = self.network_globals.peers.write().peer_info_mut(peer_id) {
let new_state = sync_type.as_sync_status(remote_sync_info);
let rpr = new_state.to_string();
let rpr = new_state.as_str();
let was_updated = peer_info.sync_status.update(new_state);
if was_updated {
debug!(self.log, "Peer transitioned sync state"; "peer_id" => %peer_id, "new_state" => rpr,

View File

@@ -125,7 +125,7 @@ impl<T: EthSpec> SyncNetworkContext<T> {
"Sending BlocksByRoot Request";
"method" => "BlocksByRoot",
"count" => request.block_roots.len(),
"peer" => format!("{:?}", peer_id)
"peer" => %peer_id
);
self.send_rpc_request(peer_id, Request::BlocksByRoot(request))
}
@@ -139,11 +139,11 @@ impl<T: EthSpec> SyncNetworkContext<T> {
}
pub fn report_peer(&mut self, peer_id: PeerId, action: PeerAction) {
debug!(self.log, "Sync reporting peer"; "peer_id" => peer_id.to_string(), "action" => action.to_string());
debug!(self.log, "Sync reporting peer"; "peer_id" => %peer_id, "action" => %action);
self.network_send
.send(NetworkMessage::ReportPeer { peer_id, action })
.unwrap_or_else(|e| {
warn!(self.log, "Could not report peer, channel failed"; "error"=> e.to_string());
warn!(self.log, "Could not report peer, channel failed"; "error"=> %e);
});
}
@@ -166,7 +166,7 @@ impl<T: EthSpec> SyncNetworkContext<T> {
self.network_send
.send(NetworkMessage::SubscribeCoreTopics)
.unwrap_or_else(|e| {
warn!(self.log, "Could not subscribe to core topics."; "error" => e.to_string());
warn!(self.log, "Could not subscribe to core topics."; "error" => %e);
});
}

View File

@@ -391,7 +391,7 @@ impl<T: EthSpec> slog::KV for BatchInfo<T> {
)?;
serializer.emit_usize("downloaded", self.failed_download_attempts.len())?;
serializer.emit_usize("processed", self.failed_processing_attempts.len())?;
serializer.emit_str("state", &format!("{:?}", self.state))?;
serializer.emit_arguments("state", &format_args!("{:?}", self.state))?;
slog::Result::Ok(())
}
}

View File

@@ -513,7 +513,7 @@ impl<T: BeaconChainTypes> SyncingChain<T> {
// This should be unlikely, so we tolerate these errors, but not often.
let action = PeerAction::LowToleranceError;
warn!(self.log, "Batch failed to download. Dropping chain scoring peers";
"score_adjustment" => action.to_string(),
"score_adjustment" => %action,
"batch_epoch"=> batch_id);
for (peer, _) in self.peers.drain() {
network.report_peer(peer, action);
@@ -1028,7 +1028,7 @@ impl<T: BeaconChainTypes> slog::KV for SyncingChain<T> {
"to",
serializer,
)?;
serializer.emit_str("end_root", &self.target_head_root.to_string())?;
serializer.emit_arguments("end_root", &format_args!("{}", self.target_head_root))?;
Value::serialize(
&self.processing_target,
record,

View File

@@ -215,13 +215,15 @@ impl<T: BeaconChainTypes> ChainCollection<T> {
}
}
pub fn state(&self) -> Result<Option<(RangeSyncType, Slot /* from */, Slot /* to */)>, String> {
pub fn state(
&self,
) -> Result<Option<(RangeSyncType, Slot /* from */, Slot /* to */)>, &'static str> {
match self.state {
RangeSyncState::Finalized(ref syncing_id) => {
let chain = self
.finalized_chains
.get(syncing_id)
.ok_or(format!("Finalized syncing chain not found: {}", syncing_id))?;
.ok_or("Finalized syncing chain not found")?;
Ok(Some((
RangeSyncType::Finalized,
chain.start_epoch.start_slot(T::EthSpec::slots_per_epoch()),
@@ -234,7 +236,7 @@ impl<T: BeaconChainTypes> ChainCollection<T> {
let chain = self
.head_chains
.get(id)
.ok_or(format!("Head syncing chain not found: {}", id))?;
.ok_or("Head syncing chain not found")?;
let start = chain.start_epoch.start_slot(T::EthSpec::slots_per_epoch());
let target = chain.target_head_slot;
@@ -242,8 +244,7 @@ impl<T: BeaconChainTypes> ChainCollection<T> {
.map(|(min_start, max_slot)| (min_start.min(start), max_slot.max(target)))
.or(Some((start, target)));
}
let (start_slot, target_slot) =
range.ok_or_else(|| "Syncing head with empty head ids".to_string())?;
let (start_slot, target_slot) = range.ok_or("Syncing head with empty head ids")?;
Ok(Some((RangeSyncType::Head, start_slot, target_slot)))
}
RangeSyncState::Idle => Ok(None),

View File

@@ -88,7 +88,9 @@ impl<T: BeaconChainTypes> RangeSync<T> {
}
}
pub fn state(&self) -> Result<Option<(RangeSyncType, Slot /* from */, Slot /* to */)>, String> {
pub fn state(
&self,
) -> Result<Option<(RangeSyncType, Slot /* from */, Slot /* to */)>, &'static str> {
self.chains.state()
}