From 42141b3aa317eea1a59ca9b797b6b68d8670123b Mon Sep 17 00:00:00 2001 From: =?UTF-8?q?Marcel=20M=C3=A4rtens?= Date: Tue, 18 Aug 2020 18:42:02 +0200 Subject: [PATCH] remove some `trace!` in network which a) was only spam and b) could be replaced by a metric way better. added a span for disconnecting on the gameserver side. also added more debug! tracing there Just keeping a trace! all 10000ms active to have a keep alive feeling. --- network/src/metrics.rs | 10 ++++++++++ network/src/participant.rs | 8 +++++--- network/src/prios.rs | 15 +++++---------- server/src/events/player.rs | 11 ++++++----- server/src/sys/message.rs | 26 +++++++++++++------------- 5 files changed, 39 insertions(+), 31 deletions(-) diff --git a/network/src/metrics.rs b/network/src/metrics.rs index 4436a8ce7f..02940acd40 100644 --- a/network/src/metrics.rs +++ b/network/src/metrics.rs @@ -34,6 +34,8 @@ pub struct NetworkMetrics { pub message_out_total: IntCounterVec, // send(prio) Messages throughput, seperated by STREAM AND PARTICIPANT, pub message_out_throughput: IntCounterVec, + // flushed(prio) stream count, seperated by PARTICIPANT, + pub streams_flushed: IntCounterVec, // TODO: queued Messages, seperated by STREAM (add PART, CHANNEL), // queued Messages, seperated by PARTICIPANT pub queued_count: IntGaugeVec, @@ -167,6 +169,13 @@ impl NetworkMetrics { ), &["participant", "stream"], )?; + let streams_flushed = IntCounterVec::new( + Opts::new( + "stream_flushed", + "Number of flushed streams requested to PrioManager at participant level", + ), + &["participant"], + )?; let queued_count = IntGaugeVec::new( Opts::new( "queued_count", @@ -207,6 +216,7 @@ impl NetworkMetrics { wire_in_throughput, message_out_total, message_out_throughput, + streams_flushed, queued_count, queued_bytes, participants_ping, diff --git a/network/src/participant.rs b/network/src/participant.rs index b05701ff50..eca9945931 100644 --- a/network/src/participant.rs +++ b/network/src/participant.rs @@ -206,13 +206,11 @@ impl BParticipant { #[cfg(feature = "metrics")] let mut send_cache = PidCidFrameCache::new(self.metrics.frames_out_total.clone(), self.remote_pid); + let mut i: u64 = 0; loop { let mut frames = VecDeque::new(); prios.fill_frames(FRAMES_PER_TICK, &mut frames).await; let len = frames.len(); - if len > 0 { - trace!("Tick {}", len); - } for (_, frame) in frames { self.send_frame( frame, @@ -226,6 +224,10 @@ impl BParticipant { .await .unwrap(); async_std::task::sleep(TICK_TIME).await; + i += 1; + if i.rem_euclid(1000) == 0 { + trace!("Did 1000 ticks"); + } //shutdown after all msg are send! if closing_up && (len == 0) { break; diff --git a/network/src/prios.rs b/network/src/prios.rs index 4e5971a32e..1026b5f581 100644 --- a/network/src/prios.rs +++ b/network/src/prios.rs @@ -16,8 +16,6 @@ use futures::channel::oneshot; use std::collections::{HashMap, HashSet, VecDeque}; #[cfg(feature = "metrics")] use std::sync::Arc; -use tracing::*; - const PRIO_MAX: usize = 64; #[derive(Default)] @@ -148,11 +146,8 @@ impl PrioManager { async fn tick(&mut self) { // Check Range - let mut messages = 0; - let mut closed = 0; for (prio, sid, msg) in self.messages_rx.try_iter() { debug_assert!(prio as usize <= PRIO_MAX); - messages += 1; #[cfg(feature = "metrics")] { let sid_string = sid.to_string(); @@ -173,7 +168,11 @@ impl PrioManager { } //this must be AFTER messages for (sid, return_sender) in self.sid_flushed_rx.try_iter() { - closed += 1; + #[cfg(feature = "metrics")] + self.metrics + .streams_flushed + .with_label_values(&[&self.pid]) + .inc(); if let Some(cnt) = self.sid_owned.get_mut(&sid) { // register sender cnt.empty_notify = Some(return_sender); @@ -182,9 +181,6 @@ impl PrioManager { return_sender.send(()).unwrap(); } } - if messages > 0 || closed > 0 { - trace!(?messages, ?closed, "tick"); - } } //if None returned, we are empty! @@ -256,7 +252,6 @@ impl PrioManager { } } } else { - trace!(?msg.mid, "Repush message"); self.messages[prio as usize].push_front((sid, msg)); } }, diff --git a/server/src/events/player.rs b/server/src/events/player.rs index bc05196f66..8b5ea37dfe 100644 --- a/server/src/events/player.rs +++ b/server/src/events/player.rs @@ -79,18 +79,19 @@ pub fn handle_exit_ingame(server: &mut Server, entity: EcsEntity) { pub fn handle_client_disconnect(server: &mut Server, entity: EcsEntity) -> Event { if let Some(client) = server.state().read_storage::().get(entity) { - trace!("Closing participant of client"); let participant = match client.participant.try_lock() { Ok(mut p) => p.take().unwrap(), Err(e) => { - error!(?e, "coudln't lock participant for removal"); + error!(?e, ?entity, "coudln't lock participant for removal"); return Event::ClientDisconnected { entity }; }, }; - std::thread::spawn(|| { - let pid = participant.remote_pid(); + let pid = participant.remote_pid(); + std::thread::spawn(move || { + let span = tracing::span!(tracing::Level::DEBUG, "client_disconnect", ?pid, ?entity); + let _enter = span.enter(); let now = std::time::Instant::now(); - trace!(?pid, "start disconnect"); + debug!(?pid, ?entity, "Start handle disconnect of client"); if let Err(e) = block_on(participant.disconnect()) { debug!( ?e, diff --git a/server/src/sys/message.rs b/server/src/sys/message.rs index 234f6c0a86..415f9d4727 100644 --- a/server/src/sys/message.rs +++ b/server/src/sys/message.rs @@ -25,6 +25,7 @@ use hashbrown::HashMap; use specs::{ Entities, Join, Read, ReadExpect, ReadStorage, System, Write, WriteExpect, WriteStorage, }; +use tracing::{debug, error, info, warn}; impl Sys { ///We needed to move this to a async fn, if we would use a async closures @@ -267,17 +268,13 @@ impl Sys { let msg = mode.new_message(*from, message); new_chat_msgs.push((Some(entity), msg)); } else { - tracing::error!("Could not send message. Missing player uid"); + error!("Could not send message. Missing player uid"); } }, Err(ChatMsgValidationError::TooLong) => { let max = MAX_BYTES_CHAT_MSG; let len = message.len(); - tracing::warn!( - ?len, - ?max, - "Recieved a chat message that's too long" - ) + warn!(?len, ?max, "Recieved a chat message that's too long") }, } }, @@ -342,7 +339,9 @@ impl Sys { client.notify(ServerMsg::Disconnect); }, ClientMsg::Terminate => { + debug!(?entity, "Client send message to termitate session"); server_emitter.emit(ServerEvent::ClientDisconnect(entity)); + break Ok(()); }, ClientMsg::RequestCharacterList => { if let Some(player) = players.get(entity) { @@ -351,11 +350,7 @@ impl Sys { }, ClientMsg::CreateCharacter { alias, tool, body } => { if let Err(error) = alias_validator.validate(&alias) { - tracing::debug!( - ?error, - ?alias, - "denied alias as it contained a banned word" - ); + debug!(?error, ?alias, "denied alias as it contained a banned word"); client.notify(ServerMsg::CharacterActionError(error.to_string())); } else if let Some(player) = players.get(entity) { character_loader.create_character( @@ -522,10 +517,15 @@ impl<'a> System<'a> for Sys { // Update client ping. if cnt > 0 { client.last_ping = time.0 - } else if time.0 - client.last_ping > CLIENT_TIMEOUT // Timeout - || network_err.is_err() + } else if time.0 - client.last_ping > CLIENT_TIMEOUT + // Timeout + { + info!(?entity, "timeout error with client, disconnecting"); + server_emitter.emit(ServerEvent::ClientDisconnect(entity)); + } else if network_err.is_err() // Postbox error { + debug!(?entity, "postbox error with client, disconnecting"); server_emitter.emit(ServerEvent::ClientDisconnect(entity)); } else if time.0 - client.last_ping > CLIENT_TIMEOUT * 0.5 { // Try pinging the client if the timeout is nearing.