diff --git a/minecraft-entities-derive/examples/main.rs b/minecraft-entities-derive/examples/main.rs index c20ef6f4..d42f5e76 100644 --- a/minecraft-entities-derive/examples/main.rs +++ b/minecraft-entities-derive/examples/main.rs @@ -17,6 +17,7 @@ enum AnyEntity { Cow(Cow), } +#[derive(Debug)] pub struct Handler { uuid: Eid, world: Arc>, diff --git a/minecraft-server/Cargo.toml b/minecraft-server/Cargo.toml index 2c37ee16..b3fc1e4c 100644 --- a/minecraft-server/Cargo.toml +++ b/minecraft-server/Cargo.toml @@ -7,10 +7,18 @@ edition = "2021" [dependencies] env_logger = "0.10.0" -log = "0.4.20" tokio = { version = "1.33.0", features = ["full"] } futures = "0.3.29" minecraft-protocol = { path="../minecraft-protocol" } minecraft-positions = { path="../minecraft-positions" } minecraft-entities-derive = { path="../minecraft-entities-derive" } rand = "0.8.4" +tracy-client = { version = "0.16.4", features = ["enable"], optional = true} +tracing-tracy = { version = "0.10.4", features = ["enable", "system-tracing"], optional = true} +tracing-subscriber = "0.3.18" +log = "0.4.17" +tracing = { version = "0.1", features = ["attributes"] } + +[features] +default = [] +tracing = ["tracy-client", "tracing-tracy"] diff --git a/minecraft-server/src/entities/entity.rs b/minecraft-server/src/entities/entity.rs index 59da82ac..c62726c9 100644 --- a/minecraft-server/src/entities/entity.rs +++ b/minecraft-server/src/entities/entity.rs @@ -7,6 +7,8 @@ use super::*; init(self, server_msg_rcvr: BroadcastReceiver); } )] + +#[derive(Debug)] pub struct Entity { pub position: Position, pub velocity: Translation, @@ -29,6 +31,7 @@ pub struct Entity { } impl Handler { + #[instrument(skip_all)] pub async fn init(self, server_msg_rcvr: BroadcastReceiver) { self.insert_task("newton", tokio::spawn(newton_task(self.clone(), server_msg_rcvr))).await; } diff --git a/minecraft-server/src/entities/player.rs b/minecraft-server/src/entities/player.rs index 0e10449d..22cb3e44 100644 --- a/minecraft-server/src/entities/player.rs +++ b/minecraft-server/src/entities/player.rs @@ -87,6 +87,7 @@ impl Player { } impl Handler { + #[instrument(skip_all)] async fn update_center_chunk(self) { let Some((old_center_chunk, new_center_chunk, render_distance)) = self.mutate(|player| { let old_center_chunk = player.center_chunk.clone(); @@ -150,6 +151,7 @@ impl Handler { } } + #[instrument(skip_all)] async fn send_packet<'a>(&self, packet: PlayClientbound<'a>) { let packet = packet.serialize_minecraft_packet().unwrap(); let packets_sent = self.mutate(|player| { @@ -163,6 +165,7 @@ impl Handler { packet_sender.send(packet).await.unwrap(); } + #[instrument(skip_all)] async fn send_raw_packet(&self, packet: Vec) { let packets_sent = self.mutate(|player| { player.packets_sent += 1; @@ -179,6 +182,11 @@ impl Handler { use ServerMessage::*; match message { Tick(tick_id) => { + #[cfg(feature = "tracing")] { + let span = info_span!("player tick"); + let _enter: tracing::span::Entered<'_> = span.enter(); + } + if tick_id % (20*10) == 0 { self.send_packet(PlayClientbound::KeepAlive { keep_alive_id: tick_id as u64 }).await; } @@ -191,6 +199,7 @@ impl Handler { } } + #[instrument(skip_all)] async fn on_world_change(self, change: WorldChange) { match change { WorldChange::Block(position, block) => { @@ -283,6 +292,7 @@ impl Handler { } } + #[instrument(skip_all)] async fn on_packet<'a>(mut self, packet: PlayServerbound<'a>) { use PlayServerbound::*; match packet { @@ -357,6 +367,7 @@ impl Handler { } } +#[instrument(skip_all)] async fn handle_player(h: Handler, uuid: UUID, stream: TcpStream, packet_receiver: MpscReceiver>, server_msg_rcvr: BroadcastReceiver, change_receiver: MpscReceiver) { let r = handle_player_inner(h.clone(), stream, packet_receiver, server_msg_rcvr, change_receiver).await; match r { @@ -366,6 +377,7 @@ async fn handle_player(h: Handler, uuid: UUID, stream: TcpStream, packet h.world.remove_loader(uuid).await; } +#[instrument(skip_all)] async fn handle_player_inner(h: Handler, stream: TcpStream, mut packet_receiver: MpscReceiver>, mut server_msg_rcvr: BroadcastReceiver, mut change_receiver: MpscReceiver) -> Result<(), ()> { let (mut reader_stream, mut writer_stream) = stream.into_split(); diff --git a/minecraft-server/src/main.rs b/minecraft-server/src/main.rs index 9667ad48..d0f414d7 100644 --- a/minecraft-server/src/main.rs +++ b/minecraft-server/src/main.rs @@ -23,6 +23,22 @@ impl std::future::Future for ServerFuture { #[tokio::main] async fn main() { + #[cfg(feature = "tracing")] + #[global_allocator] + static GLOBAL: tracy_client::ProfiledAllocator = + tracy_client::ProfiledAllocator::new(std::alloc::System, 100); + + use tracing_subscriber::{fmt, layer::SubscriberExt, Registry}; + + let subscriber = Registry::default() + .with(fmt::layer()); + #[cfg(feature = "tracing")] + let subscriber = subscriber + .with(tracing_tracy::TracyLayer::new()); + + tracing::subscriber::set_global_default(subscriber) + .expect("setting up tracing"); + env_logger::init(); let server = ServerBehavior::init().await; diff --git a/minecraft-server/src/player_handler/connect.rs b/minecraft-server/src/player_handler/connect.rs index 87692566..3b206068 100644 --- a/minecraft-server/src/player_handler/connect.rs +++ b/minecraft-server/src/player_handler/connect.rs @@ -1,5 +1,7 @@ use super::*; + +#[instrument(skip_all)] pub async fn handle_connection( mut stream: TcpStream, addr: SocketAddr, diff --git a/minecraft-server/src/player_handler/handshake.rs b/minecraft-server/src/player_handler/handshake.rs index b5c30bcd..59366e35 100644 --- a/minecraft-server/src/player_handler/handshake.rs +++ b/minecraft-server/src/player_handler/handshake.rs @@ -14,6 +14,8 @@ pub struct PlayerInfo { pub allow_server_listing: bool, } + +#[instrument(skip_all)] pub async fn handshake(stream: &mut TcpStream, logged_in_player_info: LoggedInPlayerInfo, world: &'static World) -> Result<(PlayerInfo, MpscReceiver), ()> { // Receive client informations let packet = receive_packet(stream).await?; diff --git a/minecraft-server/src/player_handler/login.rs b/minecraft-server/src/player_handler/login.rs index 043ced41..1a78f4cd 100644 --- a/minecraft-server/src/player_handler/login.rs +++ b/minecraft-server/src/player_handler/login.rs @@ -6,6 +6,7 @@ pub struct LoggedInPlayerInfo { pub(super) uuid: u128, } +#[instrument(skip_all)] pub async fn login(stream: &mut TcpStream, addr: SocketAddr) -> Result { // Receive login start let packet = receive_packet(stream).await?; diff --git a/minecraft-server/src/player_handler/network.rs b/minecraft-server/src/player_handler/network.rs index 0b9e7227..eb723853 100644 --- a/minecraft-server/src/player_handler/network.rs +++ b/minecraft-server/src/player_handler/network.rs @@ -48,6 +48,7 @@ pub async fn receive_packet_split(stream: &mut OwnedReadHalf) -> Result, Ok(data) } +#[instrument] pub async fn send_packet_raw(stream: &mut TcpStream, packet: &[u8]) { let length = VarInt::from(packet.len()); stream.write_all(length.serialize_minecraft_packet().unwrap().as_slice()).await.unwrap(); @@ -55,6 +56,7 @@ pub async fn send_packet_raw(stream: &mut TcpStream, packet: &[u8]) { stream.flush().await.unwrap(); } +#[instrument] pub async fn send_packet_raw_split(stream: &mut OwnedWriteHalf, packet: &[u8]) { let length = VarInt::from(packet.len()); stream.write_all(length.serialize_minecraft_packet().unwrap().as_slice()).await.unwrap(); @@ -62,6 +64,7 @@ pub async fn send_packet_raw_split(stream: &mut OwnedWriteHalf, packet: &[u8]) { stream.flush().await.unwrap(); } +#[instrument(skip_all)] pub async fn send_packet<'a, P: MinecraftPacketPart<'a>>(stream: &mut TcpStream, packet: P) { let packet = packet.serialize_minecraft_packet().unwrap(); send_packet_raw(stream, packet.as_slice()).await; diff --git a/minecraft-server/src/player_handler/status.rs b/minecraft-server/src/player_handler/status.rs index aa2f724c..0e6dd654 100644 --- a/minecraft-server/src/player_handler/status.rs +++ b/minecraft-server/src/player_handler/status.rs @@ -1,5 +1,6 @@ use super::*; +#[instrument(skip_all)] pub async fn status(stream: &mut TcpStream) -> Result<(), ()> { loop { let packet = receive_packet(stream).await?; diff --git a/minecraft-server/src/prelude.rs b/minecraft-server/src/prelude.rs index 9018ac95..46568f95 100644 --- a/minecraft-server/src/prelude.rs +++ b/minecraft-server/src/prelude.rs @@ -1,6 +1,6 @@ pub use crate::{entities::*, player_handler::*, server_behavior::*, world::*}; pub use futures::FutureExt; -pub use log::{debug, error, info, trace, warn}; +pub use tracing::{debug, error, info, trace, warn, instrument, info_span}; pub use minecraft_protocol::{ components::{ chat::ChatMode, diff --git a/minecraft-server/src/world/ecs.rs b/minecraft-server/src/world/ecs.rs index eb20c8b0..9c40c7f9 100644 --- a/minecraft-server/src/world/ecs.rs +++ b/minecraft-server/src/world/ecs.rs @@ -6,6 +6,7 @@ use tokio::sync::RwLock; pub type EntityTask = Pin + Send + Sync + 'static>>; pub type EntityTaskHandle = tokio::task::JoinHandle<()>; + pub struct Entities { eid_counter: std::sync::atomic::AtomicU32, uuid_counter: std::sync::atomic::AtomicU64, @@ -30,12 +31,14 @@ impl Entities { } /// Observe an entity through a closure + #[instrument(skip_all)] pub(super) async fn observe_entity(&self, eid: Eid, observer: impl FnOnce(&AnyEntity) -> R) -> Option { self.entities.read().await.get(&eid).map(observer) } /// Observe entities in a chunk through a closure /// That closure will be applied to each entity, and the results will be returned in a vector + #[instrument(skip_all)] pub(super) async fn observe_entities(&self, chunk: ChunkColumnPosition, mut observer: impl FnMut(&AnyEntity) -> Option) -> Vec { let entities = self.entities.read().await; let chunks = self.chunks.read().await; @@ -52,6 +55,7 @@ impl Entities { } /// Mutate an entity through a closure + #[instrument(skip_all)] pub(super) async fn mutate_entity(&self, eid: Eid, mutator: impl FnOnce(&mut AnyEntity) -> (R, EntityChanges)) -> Option<(R, EntityChanges)> { let mut entities = self.entities.write().await; @@ -72,6 +76,7 @@ impl Entities { } } + #[instrument(skip_all)] pub(super) async fn spawn_entity(&self, entity: AnyEntity, world: &'static World, receiver: BroadcastReceiver) -> (Eid, UUID) where AnyEntity: TryAsEntityRef, Handler: EntityExt { @@ -90,7 +95,8 @@ impl Entities { h.init(receiver).await; (eid, uuid) } - + + #[instrument(skip_all)] pub(super) async fn insert_entity_task(&self, eid: Eid, name: &'static str, handle: EntityTaskHandle) { let mut entity_tasks = self.entity_tasks.write().await; let old = entity_tasks.entry(eid).or_insert(HashMap::new()).insert(name, handle); @@ -100,6 +106,7 @@ impl Entities { } /// Remove an entity + #[instrument(skip_all)] pub(super) async fn remove_entity(&self, eid: Eid) -> Option { let entity = self.entities.write().await.remove(&eid); let mut chunks = self.chunks.write().await; diff --git a/minecraft-server/src/world/loading_manager.rs b/minecraft-server/src/world/loading_manager.rs index 3a5d2178..b00e1259 100644 --- a/minecraft-server/src/world/loading_manager.rs +++ b/minecraft-server/src/world/loading_manager.rs @@ -1,12 +1,13 @@ use crate::prelude::*; -#[derive(Default)] +#[derive(Default, Debug)] pub(super) struct WorldLoadingManager { loaded_chunks: HashMap>, loader_entities: HashMap>, } impl WorldLoadingManager { + #[instrument(skip_all)] pub(super) fn update_loaded_chunks(&mut self, uuid: UUID, loaded_chunks: HashSet) { let loaded_before = self.loaded_chunks.entry(uuid).or_default(); for just_unloaded in loaded_before.difference(&loaded_chunks) { diff --git a/minecraft-server/src/world/map.rs b/minecraft-server/src/world/map.rs index 8939b907..2894a46b 100644 --- a/minecraft-server/src/world/map.rs +++ b/minecraft-server/src/world/map.rs @@ -54,6 +54,7 @@ impl Chunk { &self.data } + #[instrument(skip_all)] fn get_block(&self, position: BlockPositionInChunk) -> BlockWithState { match &self.data.blocks { PalettedData::Paletted { palette, indexed } => { @@ -74,6 +75,7 @@ impl Chunk { } // TODO edit block_count in data + #[instrument(skip_all)] fn set_block(&mut self, position: BlockPositionInChunk, block: BlockWithState) { let block_state_id = block.block_state_id().unwrap_or_else(|| { error!("Tried to set block with invalid state {block:?}. Placing air"); 0 @@ -448,6 +450,7 @@ impl WorldMap { } } + #[instrument(skip_all)] pub async fn get_block(&self, position: BlockPosition) -> BlockWithState { async fn inner_get_block(s: &WorldMap, position: BlockPosition) -> Option { let chunk_position = position.chunk(); @@ -466,6 +469,7 @@ impl WorldMap { self.shards[shard].clone().write_owned().await } + #[instrument(skip_all)] pub async fn get_network_chunk_column_data(&self, position: ChunkColumnPosition) -> Option> { let shard = position.shard(self.shard_count); let shard = self.shards[shard].read().await; @@ -508,6 +512,7 @@ impl WorldMap { LightManager::update_light(self, position, block).await; } + #[instrument(skip_all)] pub async fn get_skylight(&self, position: BlockPosition) -> u8 { async fn inner_get_skylight(s: &WorldMap, position: BlockPosition) -> Option { let chunk_position = position.chunk(); @@ -551,6 +556,7 @@ impl WorldMap { movement.clone() // Would be more logic if it returned validated, but this way we avoid precision errors } + #[instrument(skip_all)] pub async fn load(&'static self, position: ChunkColumnPosition) { let chunk = ChunkColumn::flat(); // TODO: load from disk let shard = position.shard(self.shard_count); diff --git a/tools/tracy-p64 b/tools/tracy-p64 new file mode 100755 index 00000000..e81feee2 Binary files /dev/null and b/tools/tracy-p64 differ