Tracing

minecraft-entities-derive/examples/main.rs

@@ -17,6 +17,7 @@ enum AnyEntity {
     Cow(Cow),
 }
 
+#[derive(Debug)]
 pub struct Handler<T> {
     uuid: Eid,
     world: Arc<Mutex<()>>,

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"]

minecraft-server/src/entities/entity.rs

@@ -7,6 +7,8 @@ use super::*;
         init(self, server_msg_rcvr: BroadcastReceiver<ServerMessage>);
     }
 )]
+
+#[derive(Debug)]
 pub struct Entity {
     pub position: Position,
     pub velocity: Translation,
@@ -29,6 +31,7 @@ pub struct Entity {
 }
 
 impl Handler<Entity> {
+    #[instrument(skip_all)]
     pub async fn init(self, server_msg_rcvr: BroadcastReceiver<ServerMessage>) {
         self.insert_task("newton", tokio::spawn(newton_task(self.clone(), server_msg_rcvr))).await;
     }

minecraft-server/src/entities/player.rs

@@ -87,6 +87,7 @@ impl Player {
 }
 
 impl Handler<Player> {
+    #[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();
@@ -172,6 +173,7 @@ impl Handler<Player> {
         }
     }
 
+    #[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| {
@@ -185,10 +187,16 @@ impl Handler<Player> {
         packet_sender.send(packet).await.unwrap();
     }
 
+    #[instrument(skip_all)]
     async fn on_server_message(self, message: ServerMessage) {
         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;
                 }
@@ -201,6 +209,7 @@ impl Handler<Player> {
         }
     }
 
+    #[instrument(skip_all)]
     async fn on_world_change(self, change: WorldChange) {
         match change {
             WorldChange::Block(position, block) => {
@@ -293,6 +302,7 @@ impl Handler<Player> {
         }
     }
 
+    #[instrument(skip_all)]
     async fn on_packet<'a>(mut self, packet: PlayServerbound<'a>) {
         use PlayServerbound::*;
         match packet {
@@ -367,6 +377,7 @@ impl Handler<Player> {
     }
 }
 
+#[instrument(skip_all)]
 async fn handle_player(h: Handler<Player>, uuid: UUID, stream: TcpStream, packet_receiver: MpscReceiver<Vec<u8>>, server_msg_rcvr: BroadcastReceiver<ServerMessage>, change_receiver: MpscReceiver<WorldChange>) {
     let r = handle_player_inner(h.clone(), stream, packet_receiver, server_msg_rcvr, change_receiver).await;
     match r {
@@ -376,6 +387,7 @@ async fn handle_player(h: Handler<Player>, uuid: UUID, stream: TcpStream, packet
     h.world.remove_loader(uuid).await;
 }
 
+#[instrument(skip_all)]
 async fn handle_player_inner(h: Handler<Player>, stream: TcpStream, mut packet_receiver: MpscReceiver<Vec<u8>>, mut server_msg_rcvr: BroadcastReceiver<ServerMessage>, mut change_receiver: MpscReceiver<WorldChange>) -> Result<(), ()> {
     let (mut reader_stream, mut writer_stream) = stream.into_split();
 

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<std::alloc::System> =
+        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;

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,

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<WorldChange>), ()> {
     // Receive client informations
     let packet = receive_packet(stream).await?;

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<LoggedInPlayerInfo, ()> {
     // Receive login start
     let packet = receive_packet(stream).await?;

minecraft-server/src/player_handler/network.rs

@@ -48,20 +48,23 @@ pub async fn receive_packet_split(stream: &mut OwnedReadHalf) -> Result<Vec<u8>,
     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();
     stream.write_all(packet).await.unwrap();
     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();
     stream.write_all(packet).await.unwrap();
     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;

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?;

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,

minecraft-server/src/world/ecs.rs

@@ -6,6 +6,7 @@ use tokio::sync::RwLock;
 pub type EntityTask = Pin<Box<dyn Future<Output = ()> + 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<R>(&self, eid: Eid, observer: impl FnOnce(&AnyEntity) -> R) -> Option<R> {
         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<R>(&self, chunk: ChunkColumnPosition, mut observer: impl FnMut(&AnyEntity) -> Option<R>) -> Vec<R> {
         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<R>(&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<E>(&self, entity: AnyEntity, world: &'static World, receiver: BroadcastReceiver<ServerMessage>) -> (Eid, UUID)
         where AnyEntity: TryAsEntityRef<E>, Handler<E>: 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<AnyEntity> {
         let entity = self.entities.write().await.remove(&eid);
         let mut chunks = self.chunks.write().await;

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<UUID, HashSet<ChunkColumnPosition>>,
     loader_entities: HashMap<ChunkColumnPosition, HashSet<UUID>>,
 }
 
 impl WorldLoadingManager {
+    #[instrument(skip_all)]
     pub(super) fn update_loaded_chunks(&mut self, uuid: UUID, loaded_chunks: HashSet<ChunkColumnPosition>) {
         let loaded_before = self.loaded_chunks.entry(uuid).or_default();
         for just_unloaded in loaded_before.difference(&loaded_chunks) {

minecraft-server/src/world/map.rs

@@ -52,6 +52,7 @@ impl Chunk {
         &self.data
     }
 
+    #[instrument(skip_all)]
     fn get_block(&self, position: BlockPositionInChunk) -> BlockWithState {
         match &self.data.blocks {
             PalettedData::Paletted { palette, indexed } => {
@@ -72,6 +73,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
@@ -230,6 +232,7 @@ impl WorldMap {
         WorldMap { shard_count, shards }
     }
 
+    #[instrument(skip_all)]
     pub async fn get_block(&self, position: BlockPosition) -> BlockWithState {
         async fn inner_get_block(s: &WorldMap, position: BlockPosition) -> Option<BlockWithState> {
             let chunk_position = position.chunk();
@@ -256,6 +259,7 @@ impl WorldMap {
         Some(chunk.as_network_chunk().clone())
     }
 
+    #[instrument(skip_all)]
     pub async fn set_block(&self, position: BlockPosition, block: BlockWithState) {
         async fn inner_get_block(s: &WorldMap, position: BlockPosition, block: BlockWithState) -> Option<()> {
             let chunk_position = position.chunk();
@@ -271,6 +275,7 @@ impl WorldMap {
         inner_get_block(self, position, block).await;
     }
 
+    #[instrument(skip_all)]
     pub async fn try_move(&self, object: &CollisionShape, movement: &Translation) -> Translation {
         // TODO(perf): Optimize Map.try_move by preventing block double-checking
         // Also lock the map only once
@@ -288,6 +293,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(&self, position: ChunkColumnPosition) {
         let chunk = ChunkColumn::flat(); // TODO: load from disk
         let shard = position.shard(self.shard_count);