wallet: for draw calls add a trace_id used to correlate draw() trace!() logs

bin/darkwallet/src/ui/button.rs

@@ -78,7 +78,7 @@ impl UIObject for Button {
         self.priority.get()
     }
 
-    async fn draw(&self, parent_rect: Rectangle) -> Option<DrawUpdate> {
+    async fn draw(&self, parent_rect: Rectangle, trace_id: u32) -> Option<DrawUpdate> {
         let _ = self.rect.eval(&parent_rect);
         None
     }

bin/darkwallet/src/ui/chatedit.rs

@@ -680,7 +680,7 @@ impl ChatEdit {
     }
 
     /// Called whenever the text or any text property changes.
-    fn regen_text_mesh(&self) -> GfxDrawMesh {
+    fn regen_text_mesh(&self, trace_id: u32) -> GfxDrawMesh {
         let is_focused = self.is_focused.get();
         let text = self.text.get();
         let font_size = self.font_size.get();
@@ -734,15 +734,13 @@ impl ChatEdit {
         );
 
         let mut clip = self.rect.get();
-        //debug!(target: "ui::chatedit", "Rendering text '{text}' rect={clip:?} width={width}");
+        t!("Rendering text '{text}' rect={clip:?} width={width} [trace_id={trace_id}]");
         clip.x = 0.;
         clip.y = 0.;
 
         let mut mesh = MeshBuilder::with_clip(clip.clone());
         let mut curr_y = -scroll;
 
-        //debug!(target: "ui::chatedit", "regen_text_mesh() selections={selections:?}");
-
         for (line_idx, wrap_line) in wrapped_lines.lines.iter().enumerate() {
             // Instead of bools, maybe we should have a GlyphStyle enum
             let select_marks = self.mark_selected_glyphs(&wrap_line, &selections);
@@ -1710,9 +1708,10 @@ impl ChatEdit {
     }
 
     async fn redraw(&self) {
+        let trace_id = rand::random();
         let timest = unixtime();
         t!("redraw()");
-        let Some(draw_update) = self.make_draw_calls() else {
+        let Some(draw_update) = self.make_draw_calls(trace_id) else {
             error!(target: "ui::chatedit", "Text failed to draw");
             return;
         };
@@ -1762,8 +1761,8 @@ impl ChatEdit {
         cursor_instrs
     }
 
-    fn make_draw_calls(&self) -> Option<DrawUpdate> {
-        let text_mesh = self.regen_text_mesh();
+    fn make_draw_calls(&self, trace_id: u32) -> Option<DrawUpdate> {
+        let text_mesh = self.regen_text_mesh(trace_id);
         let cursor_instrs = self.get_cursor_instrs();
 
         let rect = self.rect.get();
@@ -1942,11 +1941,11 @@ impl UIObject for ChatEdit {
         self.tasks.set(tasks);
     }
 
-    async fn draw(&self, parent_rect: Rectangle) -> Option<DrawUpdate> {
-        t!("ChatEdit::draw({:?})", self.node.upgrade().unwrap());
+    async fn draw(&self, parent_rect: Rectangle, trace_id: u32) -> Option<DrawUpdate> {
+        t!("ChatEdit::draw({:?}, {trace_id})", self.node.upgrade().unwrap());
         *self.parent_rect.lock() = Some(parent_rect);
 
-        self.make_draw_calls()
+        self.make_draw_calls(trace_id)
     }
 
     async fn handle_char(&self, key: char, mods: KeyMods, repeat: bool) -> bool {

bin/darkwallet/src/ui/chatview/mod.rs

@@ -350,6 +350,8 @@ impl ChatView {
 
     /// Mark line as selected
     async fn select_line(&self, mut y: f32) {
+        let trace_id = rand::random();
+        t!("select_line({y}) [trace_id={trace_id}]");
         // The cursor is inside the rect. We just have to find which line it clicked.
         let rect = self.rect.get();
 
@@ -363,7 +365,7 @@ impl ChatView {
         let mut msgbuf = self.msgbuf.lock().await;
         msgbuf.select_line(y).await;
 
-        self.redraw_cached(&mut msgbuf).await;
+        self.redraw_cached(&mut msgbuf, trace_id).await;
     }
 
     fn end_touch_phase(&self, touch_y: f32) {
@@ -434,7 +436,8 @@ impl ChatView {
         nick: String,
         text: String,
     ) {
-        t!("handle_insert_line({timest}, {msg_id}, {nick}, {text})");
+        let trace_id = rand::random();
+        t!("handle_insert_line({timest}, {msg_id}, {nick}, {text}) [trace_id={trace_id}]");
 
         // Lock message buffer so background loader doesn't load the message as soon as it's
         // inserted into the DB.
@@ -460,7 +463,7 @@ impl ChatView {
             }
         }
 
-        self.redraw_cached(&mut msgbuf).await;
+        self.redraw_cached(&mut msgbuf, trace_id).await;
         self.bgload_cv.notify();
     }
     async fn handle_insert_unconf_line(
@@ -470,7 +473,8 @@ impl ChatView {
         nick: String,
         text: String,
     ) {
-        t!("handle_insert_unconf_line({timest}, {msg_id}, {nick}, {text})");
+        let trace_id = rand::random();
+        t!("handle_insert_unconf_line({timest}, {msg_id}, {nick}, {text}) [trace_id={trace_id}]");
 
         // We don't add unconfirmed lines to the db. Maybe we should?
 
@@ -478,7 +482,7 @@ impl ChatView {
         let mut msgbuf = self.msgbuf.lock().await;
         let Some(privmsg) = msgbuf.insert_privmsg(timest, msg_id, nick, text) else { return };
         privmsg.confirmed = false;
-        self.redraw_cached(&mut msgbuf).await;
+        self.redraw_cached(&mut msgbuf, trace_id).await;
         self.bgload_cv.notify();
     }
 
@@ -527,7 +531,8 @@ impl ChatView {
     }
 
     async fn handle_bgload(&self) {
-        t!("ChatView::handle_bgload()");
+        let trace_id = rand::random();
+        t!("ChatView::handle_bgload() [trace_id={trace_id}]");
         // Do we need to load some more?
         let scroll = self.scroll.get();
         let rect = self.rect.get();
@@ -540,20 +545,20 @@ impl ChatView {
         let total_height = msgbuf.calc_total_height().await;
         if total_height > top + preload_height {
             // Nothing to do here
-            t!("bgloader: buffer is sufficient");
+            t!("bgloader: buffer is sufficient [trace_id={trace_id}]");
             return
         }
 
         // Keep loading until this is below 0
         let mut remaining_load_height = top + preload_height - total_height;
         let mut remaining_visible = top - total_height;
-        t!("bgloader: remaining px = {remaining_load_height}, remaining_visible={remaining_visible}");
+        t!("bgloader: remaining px = {remaining_load_height}, remaining_visible={remaining_visible} [trace_id={trace_id}]");
 
         // Get the current earliest timestamp
         let iter = match msgbuf.oldest_timestamp() {
             Some(oldest_timest) => {
                 // iterate from there
-                t!("preloading from {oldest_timest}");
+                t!("preloading from {oldest_timest} [trace_id={trace_id}]");
                 let timest = (oldest_timest - 1).to_be_bytes();
                 let mut key = [0u8; 8 + 32];
                 key[..8].clone_from_slice(&timest);
@@ -562,7 +567,7 @@ impl ChatView {
                 iter
             }
             None => {
-                t!("initial load");
+                t!("initial load [trace_id={trace_id}]");
                 self.tree.iter().rev()
             }
         };
@@ -576,7 +581,7 @@ impl ChatView {
             let timest = Timestamp::from_be_bytes(timest_bytes);
             let chatmsg: ChatMsg = deserialize(&v).unwrap();
 
-            t!("{timest:?} {chatmsg:?}");
+            t!("{timest:?} {chatmsg:?} [trace_id={trace_id}]");
             let msg_height = msgbuf.push_privmsg(timest, msg_id, chatmsg.nick, chatmsg.text);
 
             remaining_load_height -= msg_height;
@@ -590,14 +595,15 @@ impl ChatView {
             }
             remaining_visible -= msg_height;
         }
-        t!("do_redraw = {do_redraw}");
+        t!("do_redraw = {do_redraw} [trace_id={trace_id}]");
         if do_redraw {
-            self.redraw_cached(&mut msgbuf).await;
+            self.redraw_cached(&mut msgbuf, trace_id).await;
         }
     }
 
     async fn scrollview(&self, mut scroll: f32) -> f32 {
-        t!("scrollview()");
+        let trace_id = rand::random();
+        t!("scrollview({scroll}) [trace_id={trace_id}]");
         let old_scroll = self.scroll.get();
 
         let rect = self.rect.get();
@@ -610,7 +616,7 @@ impl ChatView {
         }
 
         // 2/3 of time spent here  ~3.3ms
-        self.redraw_cached(&mut msgbuf).await;
+        self.redraw_cached(&mut msgbuf, trace_id).await;
 
         self.scroll.set(scroll);
         self.bgload_cv.notify();
@@ -683,8 +689,8 @@ impl ChatView {
         instrs
     }
 
-    async fn redraw_cached(&self, msgbuf: &mut MessageBuffer) {
-        t!("ChatView::redraw_cached()");
+    async fn redraw_cached(&self, msgbuf: &mut MessageBuffer, trace_id: u32) {
+        t!("ChatView::redraw_cached() [trace_id={trace_id}]");
         let timest = unixtime();
         let rect = self.rect.get();
 
@@ -697,20 +703,21 @@ impl ChatView {
             vec![(self.dc_key, GfxDrawCall { instrs, dcs: vec![], z_index: self.z_index.get() })];
 
         self.render_api.replace_draw_calls(timest, draw_calls);
-        t!("ChatView::redraw_cached() DONE");
+        t!("ChatView::redraw_cached() DONE [trace_id={trace_id}]");
     }
 
     /// Invalidates cache and redraws everything
     async fn redraw_all(&self) {
-        t!("ChatView::redraw_all()");
+        let trace_id = rand::random();
+        t!("ChatView::redraw_all() [trace_id={trace_id}]");
         let parent_rect = self.parent_rect.lock().unwrap().unwrap().clone();
         self.rect.eval(&parent_rect).expect("unable to eval rect");
 
         let mut msgbuf = self.msgbuf.lock().await;
         msgbuf.adjust_params();
         msgbuf.clear_meshes();
-        self.redraw_cached(&mut msgbuf).await;
-        t!("ChatView::redraw_all() DONE");
+        self.redraw_cached(&mut msgbuf, trace_id).await;
+        t!("ChatView::redraw_all() DONE [trace_id={trace_id}]");
     }
 }
 
@@ -800,8 +807,8 @@ impl UIObject for ChatView {
         self.tasks.set(tasks);
     }
 
-    async fn draw(&self, parent_rect: Rectangle) -> Option<DrawUpdate> {
-        t!("ChatView::draw({:?})", self.node.upgrade().unwrap());
+    async fn draw(&self, parent_rect: Rectangle, trace_id: u32) -> Option<DrawUpdate> {
+        t!("ChatView::draw({:?}, {trace_id})", self.node.upgrade().unwrap());
 
         *self.parent_rect.lock().unwrap() = Some(parent_rect.clone());
         self.rect.eval(&parent_rect).ok()?;

bin/darkwallet/src/ui/editbox/mod.rs

@@ -1330,8 +1330,8 @@ impl UIObject for EditBox {
         self.tasks.set(tasks);
     }
 
-    async fn draw(&self, parent_rect: Rectangle) -> Option<DrawUpdate> {
-        t!("EditBox::draw()");
+    async fn draw(&self, parent_rect: Rectangle, trace_id: u32) -> Option<DrawUpdate> {
+        t!("EditBox::draw() [trace_id={trace_id}]");
         *self.parent_rect.lock().unwrap() = Some(parent_rect);
         self.rect.eval(&parent_rect).ok()?;
 

bin/darkwallet/src/ui/emoji_picker/mod.rs

@@ -247,10 +247,11 @@ impl EmojiPicker {
     }
 
     fn redraw(&self) {
+        let trace_id = rand::random();
         let timest = unixtime();
         let Some(parent_rect) = self.parent_rect.lock().unwrap().clone() else { return };
 
-        let Some(draw_update) = self.get_draw_calls(parent_rect) else {
+        let Some(draw_update) = self.get_draw_calls(parent_rect, trace_id) else {
             error!(target: "ui::emoji_picker", "Emoji picker failed to draw");
             return;
         };
@@ -258,7 +259,7 @@ impl EmojiPicker {
         t!("replace draw calls done");
     }
 
-    fn get_draw_calls(&self, parent_rect: Rectangle) -> Option<DrawUpdate> {
+    fn get_draw_calls(&self, parent_rect: Rectangle, trace_id: u32) -> Option<DrawUpdate> {
         if let Err(e) = self.rect.eval(&parent_rect) {
             warn!(target: "ui::emoji_picker", "Rect eval failed: {e}");
             return None
@@ -330,10 +331,10 @@ impl UIObject for EmojiPicker {
         self.tasks.set(on_modify.tasks);
     }
 
-    async fn draw(&self, parent_rect: Rectangle) -> Option<DrawUpdate> {
-        t!("EmojiPicker::draw()");
+    async fn draw(&self, parent_rect: Rectangle, trace_id: u32) -> Option<DrawUpdate> {
+        t!("EmojiPicker::draw({parent_rect:?}, {trace_id})");
         *self.parent_rect.lock().unwrap() = Some(parent_rect);
-        self.get_draw_calls(parent_rect)
+        self.get_draw_calls(parent_rect, trace_id)
     }
 
     async fn handle_mouse_move(&self, mut mouse_pos: Point) -> bool {

bin/darkwallet/src/ui/image.rs

@@ -131,15 +131,17 @@ impl Image {
     }
 
     async fn redraw(self: Arc<Self>) {
+        let trace_id = rand::random();
         let timest = unixtime();
+        t!("redraw({:?}) [trace_id={trace_id}]", self.node.upgrade().unwrap());
         let Some(parent_rect) = self.parent_rect.lock().unwrap().clone() else { return };
 
-        let Some(draw_update) = self.get_draw_calls(parent_rect).await else {
+        let Some(draw_update) = self.get_draw_calls(parent_rect, trace_id).await else {
             error!(target: "ui::image", "Image failed to draw");
             return;
         };
         self.render_api.replace_draw_calls(timest, draw_update.draw_calls);
-        t!("replace draw calls done");
+        t!("redraw() DONE [trace_id={trace_id}]");
     }
 
     /// Called whenever any property changes.
@@ -152,7 +154,7 @@ impl Image {
         mesh.alloc(&self.render_api)
     }
 
-    async fn get_draw_calls(&self, parent_rect: Rectangle) -> Option<DrawUpdate> {
+    async fn get_draw_calls(&self, parent_rect: Rectangle, _: u32) -> Option<DrawUpdate> {
         self.rect.eval(&parent_rect).ok()?;
         let rect = self.rect.get();
         self.uv.eval(&rect).ok()?;
@@ -202,10 +204,10 @@ impl UIObject for Image {
         self.tasks.set(on_modify.tasks);
     }
 
-    async fn draw(&self, parent_rect: Rectangle) -> Option<DrawUpdate> {
-        t!("Image::draw()");
+    async fn draw(&self, parent_rect: Rectangle, trace_id: u32) -> Option<DrawUpdate> {
+        t!("Image::draw() [trace_id={trace_id}]");
         *self.parent_rect.lock().unwrap() = Some(parent_rect);
-        self.get_draw_calls(parent_rect).await
+        self.get_draw_calls(parent_rect, trace_id).await
     }
 }
 

bin/darkwallet/src/ui/layer.rs

@@ -89,22 +89,23 @@ impl Layer {
     }
 
     async fn redraw(self: Arc<Self>) {
+        let trace_id = rand::random();
         let timest = unixtime();
-        t!("Layer::redraw({:?})", self.node.upgrade().unwrap());
+        t!("Layer::redraw({:?}) [trace_id={trace_id}]", self.node.upgrade().unwrap());
         let Some(parent_rect) = self.parent_rect.lock().unwrap().clone() else { return };
 
-        let Some(draw_update) = self.get_draw_calls(parent_rect).await else {
-            error!(target: "ui::layer", "Layer failed to draw");
+        let Some(draw_update) = self.get_draw_calls(parent_rect, trace_id).await else {
+            error!(target: "ui::layer", "Layer failed to draw [trace_id={trace_id}]");
             return;
         };
         self.render_api.replace_draw_calls(timest, draw_update.draw_calls);
-        t!("Layer::redraw({:?}) DONE [timest={timest}]", self.node.upgrade().unwrap());
+        t!("Layer::redraw({:?}) DONE [timest={timest}, trace_id={trace_id}]", self.node.upgrade().unwrap());
     }
 
-    async fn get_draw_calls(&self, parent_rect: Rectangle) -> Option<DrawUpdate> {
+    async fn get_draw_calls(&self, parent_rect: Rectangle, trace_id: u32) -> Option<DrawUpdate> {
         self.rect.eval(&parent_rect).ok()?;
         let rect = self.rect.get();
-        t!("Layer::get_draw_calls() [rect={rect:?}, dc={}]", self.dc_key);
+        t!("Layer::get_draw_calls() [rect={rect:?}, dc={}, trace_id={trace_id}]", self.dc_key);
 
         // Apply viewport
 
@@ -116,8 +117,8 @@ impl Layer {
         if self.is_visible.get() {
             for child in self.get_children() {
                 let obj = get_ui_object3(&child);
-                let Some(mut draw_update) = obj.draw(rect).await else {
-                    t!("Skipped draw for {child:?}");
+                let Some(mut draw_update) = obj.draw(rect, trace_id).await else {
+                    t!("Skipped draw for {child:?} [trace_id={trace_id}]");
                     continue
                 };
 
@@ -158,8 +159,8 @@ impl UIObject for Layer {
         }
     }
 
-    async fn draw(&self, parent_rect: Rectangle) -> Option<DrawUpdate> {
-        t!("Layer::draw({:?})", self.node.upgrade().unwrap());
+    async fn draw(&self, parent_rect: Rectangle, trace_id: u32) -> Option<DrawUpdate> {
+        t!("Layer::draw({:?}) [trace_id={trace_id}]", self.node.upgrade().unwrap());
         *self.parent_rect.lock().unwrap() = Some(parent_rect);
 
         /*
@@ -173,8 +174,8 @@ impl UIObject for Layer {
         }
         */
 
-        let update = self.get_draw_calls(parent_rect).await;
-        t!("Layer::draw({:?}) DONE", self.node.upgrade().unwrap());
+        let update = self.get_draw_calls(parent_rect, trace_id).await;
+        t!("Layer::draw({:?}) DONE [trace_id={trace_id}]", self.node.upgrade().unwrap());
         update
     }
 

bin/darkwallet/src/ui/mod.rs

@@ -69,7 +69,7 @@ pub trait UIObject: Sync {
 
     async fn start(self: Arc<Self>, ex: ExecutorPtr) {}
 
-    async fn draw(&self, parent_rect: Rectangle) -> Option<DrawUpdate> {
+    async fn draw(&self, parent_rect: Rectangle, trace_id: u32) -> Option<DrawUpdate> {
         None
     }
 

bin/darkwallet/src/ui/text.rs

@@ -157,19 +157,20 @@ impl Text {
     }
 
     async fn redraw(self: Arc<Self>) {
+        let trace_id = rand::random();
         let timest = unixtime();
-        t!("Text::redraw({:?})", self.node.upgrade().unwrap());
+        t!("Text::redraw({:?}) [trace_id={trace_id}]", self.node.upgrade().unwrap());
         let Some(parent_rect) = self.parent_rect.lock().unwrap().clone() else { return };
 
-        let Some(draw_update) = self.get_draw_calls(parent_rect).await else {
-            error!(target: "ui::text", "Text failed to draw");
+        let Some(draw_update) = self.get_draw_calls(parent_rect, trace_id).await else {
+            error!(target: "ui::text", "Text failed to draw [trace_id={trace_id}]");
             return;
         };
         self.render_api.replace_draw_calls(timest, draw_update.draw_calls);
-        t!("replace draw calls done");
+        t!("Text::redraw() DONE [trace_id={trace_id}]");
     }
 
-    async fn get_draw_calls(&self, parent_rect: Rectangle) -> Option<DrawUpdate> {
+    async fn get_draw_calls(&self, parent_rect: Rectangle, trace_id: u32) -> Option<DrawUpdate> {
         self.rect.eval(&parent_rect).ok()?;
         let rect = self.rect.get();
 
@@ -220,10 +221,10 @@ impl UIObject for Text {
         self.tasks.set(on_modify.tasks);
     }
 
-    async fn draw(&self, parent_rect: Rectangle) -> Option<DrawUpdate> {
-        t!("Text::draw({:?})", self.node.upgrade().unwrap());
+    async fn draw(&self, parent_rect: Rectangle, trace_id: u32) -> Option<DrawUpdate> {
+        t!("Text::draw({:?}) [trace_id={trace_id}]", self.node.upgrade().unwrap());
         *self.parent_rect.lock().unwrap() = Some(parent_rect);
-        self.get_draw_calls(parent_rect).await
+        self.get_draw_calls(parent_rect, trace_id).await
     }
 }
 

bin/darkwallet/src/ui/vector_art/mod.rs

@@ -101,12 +101,13 @@ impl VectorArt {
     }
 
     async fn redraw(self: Arc<Self>) {
+        let trace_id = rand::random();
         let timest = unixtime();
-        trace!(target: "ui::vector_art", "VectorArt::redraw({})", self.node_path());
+        trace!(target: "ui::vector_art", "VectorArt::redraw({}) [trace_id={trace_id}]", self.node_path());
         let Some(parent_rect) = self.parent_rect.lock().unwrap().clone() else { return };
 
-        let Some(draw_update) = self.get_draw_calls(parent_rect).await else {
-            error!(target: "ui::vector_art", "Mesh failed to draw");
+        let Some(draw_update) = self.get_draw_calls(parent_rect, trace_id).await else {
+            error!(target: "ui::vector_art", "Mesh failed to draw [trace_id={trace_id}]");
             return;
         };
         self.render_api.replace_draw_calls(timest, draw_update.draw_calls);
@@ -134,9 +135,9 @@ impl VectorArt {
         vec![GfxDrawInstruction::Move(rect.pos()), GfxDrawInstruction::Draw(mesh)]
     }
 
-    async fn get_draw_calls(&self, parent_rect: Rectangle) -> Option<DrawUpdate> {
+    async fn get_draw_calls(&self, parent_rect: Rectangle, trace_id: u32) -> Option<DrawUpdate> {
         if let Err(e) = self.rect.eval(&parent_rect) {
-            warn!(target: "ui::vector_art", "Rect eval failure: {e}");
+            warn!(target: "ui::vector_art", "Rect eval failure: {e} [trace_id={trace_id}]");
             return None
         }
         let instrs = self.get_draw_instrs();
@@ -167,10 +168,10 @@ impl UIObject for VectorArt {
         self.tasks.set(on_modify.tasks);
     }
 
-    async fn draw(&self, parent_rect: Rectangle) -> Option<DrawUpdate> {
-        t!("VectorArt::draw({})", self.node_path());
+    async fn draw(&self, parent_rect: Rectangle, trace_id: u32) -> Option<DrawUpdate> {
+        t!("VectorArt::draw({}) [trace_id={trace_id}]", self.node_path());
         *self.parent_rect.lock().unwrap() = Some(parent_rect);
-        self.get_draw_calls(parent_rect).await
+        self.get_draw_calls(parent_rect, trace_id).await
     }
 }
 

bin/darkwallet/src/ui/win.rs

@@ -439,19 +439,20 @@ impl Window {
     }
 
     pub async fn draw(&self) {
+        let trace_id = rand::random();
         let timest = unixtime();
 
         let local = self.screen_size.get() / self.scale.get();
         let rect = Rectangle::from([0., 0., local.w, local.h]);
-        t!("Window::draw({rect:?})");
+        t!("Window::draw({rect:?}) [timest={timest}, trace_id={trace_id}]");
 
         let mut draw_calls = vec![];
         let mut child_calls = vec![];
 
         for child in self.get_children() {
             let obj = get_ui_object3(&child);
-            let Some(mut draw_update) = obj.draw(rect).await else {
-                error!(target: "ui::layer", "draw() of {child:?} failed");
+            let Some(mut draw_update) = obj.draw(rect, trace_id).await else {
+                error!(target: "ui::layer", "draw() of {child:?} failed [trace_id={trace_id}]");
                 continue
             };
 
@@ -469,6 +470,6 @@ impl Window {
 
         self.render_api.replace_draw_calls(timest, draw_calls);
 
-        t!("Window::draw() - replaced draw call [timest={timest}]");
+        t!("Window::draw() - replaced draw call [timest={timest}, trace_id={trace_id}]");
     }
 }