From a2494dd21870c856b7bc7a009b70b56c791242c5 Mon Sep 17 00:00:00 2001
From: Maximilian Ammann <max@maxammann.org>
Date: Fri, 1 Apr 2022 18:34:57 +0200
Subject: [PATCH] Add tracing crate

---
 ..._desktop.xml => Run_desktop__tracing_.xml} |   4 +-
 Cargo.lock                                    | 230 +++++++++++++++++-
 Cargo.toml                                    |   8 +
 src/coords.rs                                 |   1 +
 src/io/scheduler.rs                           |   7 +
 src/main_loop.rs                              |  32 +++
 src/render/buffer_pool.rs                     |   1 +
 src/render/camera.rs                          |   1 +
 src/render/render_state.rs                    |  40 ++-
 9 files changed, 304 insertions(+), 20 deletions(-)
 rename .idea/runConfigurations/{Run_desktop.xml => Run_desktop__tracing_.xml} (75%)

diff --git a/.idea/runConfigurations/Run_desktop.xml b/.idea/runConfigurations/Run_desktop__tracing_.xml
similarity index 75%
rename from .idea/runConfigurations/Run_desktop.xml
rename to .idea/runConfigurations/Run_desktop__tracing_.xml
index 1c4d575e..5415d7f7 100644
--- a/.idea/runConfigurations/Run_desktop.xml
+++ b/.idea/runConfigurations/Run_desktop__tracing_.xml
@@ -1,6 +1,6 @@
 <component name="ProjectRunConfigurationManager">
-  <configuration default="false" name="Run desktop" type="CargoCommandRunConfiguration" factoryName="Cargo Command">
-    <option name="command" value="run --example  desktop" />
+  <configuration default="false" name="Run desktop (tracing)" type="CargoCommandRunConfiguration" factoryName="Cargo Command">
+    <option name="command" value="run --example  desktop --features enable-tracing" />
     <option name="workingDirectory" value="file://$PROJECT_DIR$" />
     <option name="channel" value="DEFAULT" />
     <option name="requiredFeatures" value="true" />
diff --git a/Cargo.lock b/Cargo.lock
index 47e72be4..ce346601 100644
--- a/Cargo.lock
+++ b/Cargo.lock
@@ -28,6 +28,15 @@ dependencies = [
  "memchr",
 ]
 
+[[package]]
+name = "ansi_term"
+version = "0.12.1"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "d52a9bb7ec0cf484c551830a7ce27bd20d67eac647e1befb56b0be4ee39a55d2"
+dependencies = [
+ "winapi",
+]
+
 [[package]]
 name = "anyhow"
 version = "1.0.55"
@@ -1580,6 +1589,12 @@ dependencies = [
  "web-sys",
 ]
 
+[[package]]
+name = "integer-encoding"
+version = "3.0.3"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "0e85a1509a128c855368e135cffcde7eac17d8e1083f41e2b98c58bc1a5074be"
+
 [[package]]
 name = "ipnet"
 version = "2.3.1"
@@ -1772,6 +1787,8 @@ dependencies = [
  "lyon",
  "mbtiles",
  "ndk-glue",
+ "opentelemetry",
+ "opentelemetry-jaeger",
  "prost",
  "reqwest",
  "reqwest-middleware",
@@ -1781,6 +1798,9 @@ dependencies = [
  "test-env-log",
  "tilejson-spec",
  "tokio",
+ "tracing",
+ "tracing-opentelemetry",
+ "tracing-subscriber",
  "vector-tile",
  "wasm-bindgen",
  "wasm-bindgen-futures",
@@ -2111,6 +2131,57 @@ version = "0.3.0"
 source = "registry+https://github.com/rust-lang/crates.io-index"
 checksum = "624a8340c38c1b80fd549087862da4ba43e08858af025b236e509b6649fc13d5"
 
+[[package]]
+name = "opentelemetry"
+version = "0.17.0"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "6105e89802af13fdf48c49d7646d3b533a70e536d818aae7e78ba0433d01acb8"
+dependencies = [
+ "async-trait",
+ "crossbeam-channel",
+ "futures-channel",
+ "futures-executor",
+ "futures-util",
+ "js-sys",
+ "lazy_static",
+ "percent-encoding",
+ "pin-project",
+ "rand 0.8.5",
+ "thiserror",
+]
+
+[[package]]
+name = "opentelemetry-jaeger"
+version = "0.16.0"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "f8c0b12cd9e3f9b35b52f6e0dac66866c519b26f424f4bbf96e3fe8bfbdc5229"
+dependencies = [
+ "async-trait",
+ "lazy_static",
+ "opentelemetry",
+ "opentelemetry-semantic-conventions",
+ "thiserror",
+ "thrift",
+]
+
+[[package]]
+name = "opentelemetry-semantic-conventions"
+version = "0.9.0"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "985cc35d832d412224b2cffe2f9194b1b89b6aa5d0bef76d080dce09d90e62bd"
+dependencies = [
+ "opentelemetry",
+]
+
+[[package]]
+name = "ordered-float"
+version = "1.1.1"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "3305af35278dd29f46fcdd139e0b1fbfae2153f0e5928b39b035542dd31e37b7"
+dependencies = [
+ "num-traits",
+]
+
 [[package]]
 name = "parking"
 version = "2.0.0"
@@ -2205,7 +2276,7 @@ source = "registry+https://github.com/rust-lang/crates.io-index"
 checksum = "17367f0cc86f2d25802b2c26ee58a7b23faeccf78a396094c13dced0d0182526"
 dependencies = [
  "phf_shared",
- "rand",
+ "rand 0.7.3",
 ]
 
 [[package]]
@@ -2231,6 +2302,26 @@ dependencies = [
  "siphasher",
 ]
 
+[[package]]
+name = "pin-project"
+version = "1.0.10"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "58ad3879ad3baf4e44784bc6a718a8698867bb991f8ce24d1bcbe2cfb4c3a75e"
+dependencies = [
+ "pin-project-internal",
+]
+
+[[package]]
+name = "pin-project-internal"
+version = "1.0.10"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "744b6f092ba29c3650faf274db506afd39944f48420f6c86b17cfe0ee1cb36bb"
+dependencies = [
+ "proc-macro2",
+ "quote",
+ "syn",
+]
+
 [[package]]
 name = "pin-project-lite"
 version = "0.2.8"
@@ -2422,12 +2513,23 @@ checksum = "6a6b1679d49b24bbfe0c803429aa1874472f50d9b363131f0e89fc356b544d03"
 dependencies = [
  "getrandom 0.1.16",
  "libc",
- "rand_chacha",
- "rand_core",
+ "rand_chacha 0.2.2",
+ "rand_core 0.5.1",
  "rand_hc",
  "rand_pcg",
 ]
 
+[[package]]
+name = "rand"
+version = "0.8.5"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "34af8d1a0e25924bc5b7c43c079c942339d8f0a8b57c39049bef581b46327404"
+dependencies = [
+ "libc",
+ "rand_chacha 0.3.1",
+ "rand_core 0.6.3",
+]
+
 [[package]]
 name = "rand_chacha"
 version = "0.2.2"
@@ -2435,7 +2537,17 @@ source = "registry+https://github.com/rust-lang/crates.io-index"
 checksum = "f4c8ed856279c9737206bf725bf36935d8666ead7aa69b52be55af369d193402"
 dependencies = [
  "ppv-lite86",
- "rand_core",
+ "rand_core 0.5.1",
+]
+
+[[package]]
+name = "rand_chacha"
+version = "0.3.1"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "e6c10a63a0fa32252be49d21e7709d4d4baf8d231c2dbce1eaa8141b9b127d88"
+dependencies = [
+ "ppv-lite86",
+ "rand_core 0.6.3",
 ]
 
 [[package]]
@@ -2447,13 +2559,22 @@ dependencies = [
  "getrandom 0.1.16",
 ]
 
+[[package]]
+name = "rand_core"
+version = "0.6.3"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "d34f1408f55294453790c48b2f1ebbb1c5b4b7563eb1f418bcfcfdbb06ebb4e7"
+dependencies = [
+ "getrandom 0.2.5",
+]
+
 [[package]]
 name = "rand_hc"
 version = "0.2.0"
 source = "registry+https://github.com/rust-lang/crates.io-index"
 checksum = "ca3129af7b92a17112d59ad498c6f81eaf463253766b90396d39ea7a39d6613c"
 dependencies = [
- "rand_core",
+ "rand_core 0.5.1",
 ]
 
 [[package]]
@@ -2462,7 +2583,7 @@ version = "0.2.1"
 source = "registry+https://github.com/rust-lang/crates.io-index"
 checksum = "16abd0c1b639e9eb4d7c50c0b8100b0d0f849be2349829c740fe8e6eb4816429"
 dependencies = [
- "rand_core",
+ "rand_core 0.5.1",
 ]
 
 [[package]]
@@ -2910,6 +3031,15 @@ dependencies = [
  "opaque-debug 0.3.0",
 ]
 
+[[package]]
+name = "sharded-slab"
+version = "0.1.4"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "900fba806f70c630b0a382d0d825e17a0f19fcd059a2ade1ff237bcddf446b31"
+dependencies = [
+ "lazy_static",
+]
+
 [[package]]
 name = "sid"
 version = "0.6.1"
@@ -3181,6 +3311,37 @@ dependencies = [
  "syn",
 ]
 
+[[package]]
+name = "thread_local"
+version = "1.1.4"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "5516c27b78311c50bf42c071425c560ac799b11c30b31f87e3081965fe5e0180"
+dependencies = [
+ "once_cell",
+]
+
+[[package]]
+name = "threadpool"
+version = "1.8.1"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "d050e60b33d41c19108b32cea32164033a9013fe3b46cbd4457559bfbf77afaa"
+dependencies = [
+ "num_cpus",
+]
+
+[[package]]
+name = "thrift"
+version = "0.15.0"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "b82ca8f46f95b3ce96081fe3dd89160fdea970c254bb72925255d1b62aae692e"
+dependencies = [
+ "byteorder",
+ "integer-encoding",
+ "log",
+ "ordered-float",
+ "threadpool",
+]
+
 [[package]]
 name = "tile-grid"
 version = "0.3.0"
@@ -3299,9 +3460,21 @@ checksum = "f6c650a8ef0cd2dd93736f033d21cbd1224c5a967aa0c258d00fcf7dafef9b9f"
 dependencies = [
  "cfg-if 1.0.0",
  "pin-project-lite",
+ "tracing-attributes",
  "tracing-core",
 ]
 
+[[package]]
+name = "tracing-attributes"
+version = "0.1.20"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "2e65ce065b4b5c53e73bb28912318cb8c9e9ad3921f1d669eb0e68b4c8143a2b"
+dependencies = [
+ "proc-macro2",
+ "quote",
+ "syn",
+]
+
 [[package]]
 name = "tracing-core"
 version = "0.1.22"
@@ -3309,6 +3482,45 @@ source = "registry+https://github.com/rust-lang/crates.io-index"
 checksum = "03cfcb51380632a72d3111cb8d3447a8d908e577d31beeac006f836383d29a23"
 dependencies = [
  "lazy_static",
+ "valuable",
+]
+
+[[package]]
+name = "tracing-log"
+version = "0.1.2"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "a6923477a48e41c1951f1999ef8bb5a3023eb723ceadafe78ffb65dc366761e3"
+dependencies = [
+ "lazy_static",
+ "log",
+ "tracing-core",
+]
+
+[[package]]
+name = "tracing-opentelemetry"
+version = "0.17.2"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "1f9378e96a9361190ae297e7f3a8ff644aacd2897f244b1ff81f381669196fa6"
+dependencies = [
+ "opentelemetry",
+ "tracing",
+ "tracing-core",
+ "tracing-log",
+ "tracing-subscriber",
+]
+
+[[package]]
+name = "tracing-subscriber"
+version = "0.3.9"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "9e0ab7bdc962035a87fba73f3acca9b8a8d0034c2e6f60b84aeaaddddc155dce"
+dependencies = [
+ "ansi_term",
+ "sharded-slab",
+ "smallvec",
+ "thread_local",
+ "tracing-core",
+ "tracing-log",
 ]
 
 [[package]]
@@ -3384,6 +3596,12 @@ dependencies = [
  "serde",
 ]
 
+[[package]]
+name = "valuable"
+version = "0.1.0"
+source = "registry+https://github.com/rust-lang/crates.io-index"
+checksum = "830b7e5d4d90034032940e4ace0d9a9a057e7a45cd94e6c007832e39edb82f6d"
+
 [[package]]
 name = "value-bag"
 version = "1.0.0-alpha.8"
diff --git a/Cargo.toml b/Cargo.toml
index f26d3b20..71a858d7 100644
--- a/Cargo.toml
+++ b/Cargo.toml
@@ -31,6 +31,8 @@ debug = true
 
 [features]
 web-webgl = ["wgpu/webgl"]
+enable-tracing = [ "tracing-opentelemetry", "opentelemetry", "tracing-subscriber", "opentelemetry-jaeger"]
+default = []
 
 [target.'cfg(target_arch = "wasm32")'.dependencies]
 console_error_panic_hook = "0.1"
@@ -66,6 +68,12 @@ winit = { version = "0.26", default-features = false, features = ["x11", "waylan
 [dependencies]
 winit = { version = "0.26", default-features = false }
 
+tracing = { version = "0.1" }
+tracing-opentelemetry = { version = "0.17", optional = true }
+opentelemetry = { version = "0.17", optional = true }
+tracing-subscriber = { version = "0.3", optional = true }
+opentelemetry-jaeger = { version = "0.16", optional = true }
+
 # Vector riles
 vector-tile = { path = "./libs/vector_tile" }
 style-spec = { path = "./libs/style_spec" }
diff --git a/src/coords.rs b/src/coords.rs
index 28483bc3..e07b0134 100644
--- a/src/coords.rs
+++ b/src/coords.rs
@@ -361,6 +361,7 @@ impl From<Point3<f64>> for WorldCoords {
     }
 }
 
+#[derive(Debug)]
 pub struct ViewRegion {
     min_tile: WorldTileCoords,
     max_tile: WorldTileCoords,
diff --git a/src/io/scheduler.rs b/src/io/scheduler.rs
index 732f9b16..7b43637b 100644
--- a/src/io/scheduler.rs
+++ b/src/io/scheduler.rs
@@ -1,4 +1,5 @@
 use std::collections::{HashMap, HashSet};
+use std::fmt;
 
 use geozero::mvt::Tile;
 use geozero::GeozeroDatasource;
@@ -239,6 +240,12 @@ pub struct IOScheduler {
     schedule_method: ScheduleMethod,
 }
 
+impl fmt::Debug for IOScheduler {
+    fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result {
+        write!(f, "IOScheduler")
+    }
+}
+
 const _: () = {
     fn assert_send<T: Send>() {}
 
diff --git a/src/main_loop.rs b/src/main_loop.rs
index ec1a4767..c62baad1 100644
--- a/src/main_loop.rs
+++ b/src/main_loop.rs
@@ -14,6 +14,30 @@ use crate::io::scheduler::IOScheduler;
 use crate::platform::Instant;
 use crate::render::render_state::RenderState;
 
+#[cfg(feature = "enable-tracing")]
+fn enable_tracing() {
+    use opentelemetry::sdk::export::trace::stdout;
+    use opentelemetry_jaeger;
+    use tracing::{error, span};
+    use tracing_subscriber::layer::SubscriberExt;
+    use tracing_subscriber::Registry;
+
+    // Install a new OpenTelemetry trace pipeline
+    /*let tracer = stdout::new_pipeline().install_simple();*/
+    let tracer = opentelemetry_jaeger::new_pipeline()
+        .with_service_name("mapr")
+        .install_simple()
+        .unwrap();
+
+    // Create a tracing layer with the configured tracer
+    let telemetry = tracing_opentelemetry::layer().with_tracer(tracer);
+
+    // Use the tracing subscriber `Registry`, or any other subscriber
+    // that impls `LookupSpan`
+    let subscriber = Registry::default().with(telemetry);
+    tracing::subscriber::set_global_default(subscriber).expect("setting default subscriber failed");
+}
+
 pub async fn run(
     window: winit::window::Window,
     event_loop: EventLoop<()>,
@@ -21,6 +45,13 @@ pub async fn run(
     style: Box<Style>,
     max_frames: Option<u64>,
 ) {
+    #[cfg(feature = "enable-tracing")]
+    enable_tracing();
+    #[cfg(feature = "enable-tracing")]
+    let root = tracing::span!(tracing::Level::TRACE, "app_start", work_units = 2);
+    #[cfg(feature = "enable-tracing")]
+    let _enter = root.enter();
+
     let mut input = InputController::new(0.2, 100.0, 0.1);
     let mut maybe_state: Option<RenderState> = {
         #[cfg(target_os = "android")]
@@ -91,6 +122,7 @@ pub async fn run(
                     }
                 }
                 Event::RedrawRequested(_) => {
+                    let _span_ = tracing::span!(tracing::Level::TRACE, "redraw requested").entered();
                     let now = Instant::now();
                     let dt = now - last_render_time;
                     last_render_time = now;
diff --git a/src/render/buffer_pool.rs b/src/render/buffer_pool.rs
index e23ec2e4..d3918cb1 100644
--- a/src/render/buffer_pool.rs
+++ b/src/render/buffer_pool.rs
@@ -147,6 +147,7 @@ impl<Q: Queue<B>, B, V: bytemuck::Pod, I: bytemuck::Pod, TM: bytemuck::Pod, FM:
     /// * `layer_metadata` and
     /// * `feature_metadata` for a layer. This function is able to dynamically evict layers if there
     /// is not enough space available.
+    #[tracing::instrument(skip_all)]
     pub fn allocate_layer_geometry(
         &mut self,
         queue: &Q,
diff --git a/src/render/camera.rs b/src/render/camera.rs
index 0699601f..b5756554 100644
--- a/src/render/camera.rs
+++ b/src/render/camera.rs
@@ -20,6 +20,7 @@ pub const FLIP_Y: cgmath::Matrix4<f64> = cgmath::Matrix4::new(
     0.0, 0.0, 0.0, 1.0,
 );
 
+#[derive(Debug)]
 pub struct ViewProjection(Matrix4<f64>);
 
 impl ViewProjection {
diff --git a/src/render/render_state.rs b/src/render/render_state.rs
index de2df94d..a04b29d3 100644
--- a/src/render/render_state.rs
+++ b/src/render/render_state.rs
@@ -1,7 +1,8 @@
 use cgmath::{Matrix4, Vector4};
 use std::collections::HashSet;
 use std::default::Default;
-use std::{cmp, iter};
+use std::fmt::Formatter;
+use std::{cmp, fmt, iter};
 
 use crate::coords::{ViewRegion, TILE_SIZE};
 
@@ -31,6 +32,8 @@ use super::shaders;
 use super::shaders::*;
 use super::texture::Texture;
 
+use tracing;
+
 pub struct RenderState {
     instance: wgpu::Instance,
 
@@ -351,8 +354,9 @@ impl RenderState {
         self.zoom.floor() as u8
     }
 
-    ///         Fetch tiles which are currently in view
-    fn fetch_tiles_in_view(&self, view_region: &ViewRegion, scheduler: &mut IOScheduler) {
+    /// Request tiles which are currently in view
+    #[tracing::instrument]
+    fn request_tiles_in_view(&self, view_region: &ViewRegion, scheduler: &mut IOScheduler) {
         let source_layers: HashSet<String> = self
             .style
             .layers
@@ -371,6 +375,7 @@ impl RenderState {
     /// Update tile metadata for all required tiles on the GPU according to current zoom, camera and perspective
     /// We perform the update before uploading new tessellated tiles, such that each
     /// tile metadata in the the `buffer_pool` gets updated exactly once and not twice.
+    #[tracing::instrument]
     fn update_metadata(&self, view_proj: &ViewProjection) {
         for entries in self.buffer_pool.index().iter() {
             for entry in entries {
@@ -399,6 +404,7 @@ impl RenderState {
         }
     }
 
+    #[tracing::instrument]
     fn upload_tile_geometry(
         &mut self,
         view_proj: &ViewProjection,
@@ -487,6 +493,7 @@ impl RenderState {
         }
     }
 
+    #[tracing::instrument]
     pub fn prepare_render_data(&mut self, scheduler: &mut IOScheduler) {
         let visible_z = self.visible_z();
 
@@ -501,7 +508,7 @@ impl RenderState {
 
         if let Some(view_region) = &view_region {
             self.upload_tile_geometry(&view_proj, &view_region, scheduler);
-            self.fetch_tiles_in_view(view_region, scheduler);
+            self.request_tiles_in_view(view_region, scheduler);
         }
 
         // TODO: Could we draw inspiration from StagingBelt (https://docs.rs/wgpu/latest/wgpu/util/struct.StagingBelt.html)?
@@ -517,6 +524,7 @@ impl RenderState {
         );
     }
 
+    #[tracing::instrument]
     pub fn render(&mut self) -> Result<(), wgpu::SurfaceError> {
         let frame = self.surface.get_current_texture()?;
         let frame_view = frame
@@ -569,6 +577,8 @@ impl RenderState {
             pass.set_bind_group(0, &self.bind_group, &[]);
 
             {
+                let _span_ = tracing::span!(tracing::Level::TRACE, "render pass").entered();
+
                 let visible_z = self.visible_z();
                 let inverted_view_proj = self.camera.calc_view_proj(&self.perspective).invert();
                 let view_region = self
@@ -578,11 +588,9 @@ impl RenderState {
 
                 let index = self.buffer_pool.index();
 
-                /* println!("Render pass start");*/
-
                 if let Some(view_region) = &view_region {
                     for world_coords in view_region.iter() {
-                        /*  println!("Render coordinate {:?}", world_coords);*/
+                        tracing::trace!("Drawing tile at {world_coords}");
 
                         if let Some(entries) = index.get_layers_fallback(&world_coords) {
                             let mut to_render: Vec<&IndexEntry> = Vec::from_iter(entries);
@@ -593,11 +601,11 @@ impl RenderState {
                                 .stencil_reference_value(&world_coords)
                                 as u32;
 
-                            /* println!("Render mask");*/
-
                             // Draw mask
                             if let Some(mask_entry) = entries.front() {
                                 {
+                                    tracing::trace!("Drawing mask {}", &mask_entry.coords);
+
                                     pass.set_pipeline(&self.mask_pipeline);
                                     pass.set_stencil_reference(reference);
                                     pass.set_vertex_buffer(
@@ -613,7 +621,11 @@ impl RenderState {
                             for entry in to_render {
                                 // Draw tile
                                 {
-                                    /* println!("Render tile");*/
+                                    tracing::trace!(
+                                        "Drawing layer {:?} at {}",
+                                        entry.style_layer.source_layer,
+                                        &entry.coords
+                                    );
 
                                     pass.set_pipeline(&self.render_pipeline);
                                     pass.set_stencil_reference(reference);
@@ -647,8 +659,6 @@ impl RenderState {
                         }
                     }
                 }
-
-                /*      println!("Render pass end");*/
             }
         }
 
@@ -667,3 +677,9 @@ impl RenderState {
         self.suspended = false;
     }
 }
+
+impl fmt::Debug for RenderState {
+    fn fmt(&self, f: &mut fmt::Formatter<'_>) -> fmt::Result {
+        write!(f, "RenderState")
+    }
+}