Don't print profiling information twice

It's important to `.clear` the messages so that we don't print them
again for the next "profiling session". It might be argued that really
we should have a single "profiling session" for Cargo, but we don't at
the moment.

And, while we are at it, let's lock stdout as well, so that we won't
get confused when Cargo becomes multi-threaded and prints profiling info
from several threads simultaneously.

diff --git a/src/cargo/util/profile.rs b/src/cargo/util/profile.rs
index 7d32adc3f6012cdbc5c83341411463359b2a6155..ce49eee26cccaf110b65f3643c0b524121ceb2ab 100644 (file)
--- a/src/cargo/util/profile.rs
+++ b/src/cargo/util/profile.rs
@@ -4,6 +4,7 @@ use std::mem;
 use std::time;
 use std::iter::repeat;
 use std::cell::RefCell;
+use std::io::{stdout, StdoutLock, Write};
 
 thread_local!(static PROFILE_STACK: RefCell<Vec<time::Instant>> = RefCell::new(Vec::new()));
 thread_local!(static MESSAGES: RefCell<Vec<Message>> = RefCell::new(Vec::new()));
@@ -39,14 +40,24 @@ impl Drop for Profiler {
             None => return,
         };
 
-        let start = PROFILE_STACK.with(|stack| stack.borrow_mut().pop().unwrap());
+        let (start, stack_len) = PROFILE_STACK.with(|stack| {
+            let mut stack = stack.borrow_mut();
+            let start = stack.pop().unwrap();
+            (start, stack.len())
+        });
         let duration = start.elapsed();
         let duration_ms =
             duration.as_secs() * 1000 + u64::from(duration.subsec_nanos() / 1_000_000);
 
-        let stack_len = PROFILE_STACK.with(|stack| stack.borrow().len());
+        let msg = (
+            stack_len,
+            duration_ms,
+            mem::replace(&mut self.desc, String::new()),
+        );
+        MESSAGES.with(|msgs| msgs.borrow_mut().push(msg));
+
         if stack_len == 0 {
-            fn print(lvl: usize, msgs: &[Message], enabled: usize) {
+            fn print(lvl: usize, msgs: &[Message], enabled: usize, stdout: &mut StdoutLock) {
                 if lvl > enabled {
                     return;
                 }
@@ -55,26 +66,23 @@ impl Drop for Profiler {
                     if l != lvl {
                         continue;
                     }
-                    println!(
+                    writeln!(
+                        stdout,
                         "{} {:6}ms - {}",
                         repeat("    ").take(lvl + 1).collect::<String>(),
                         time,
                         msg
-                    );
+                    ).expect("printing profiling info to stdout");
 
-                    print(lvl + 1, &msgs[last..i], enabled);
+                    print(lvl + 1, &msgs[last..i], enabled, stdout);
                     last = i;
                 }
             }
-            MESSAGES.with(|msgs_rc| {
-                let mut msgs = msgs_rc.borrow_mut();
-                msgs.push((0, duration_ms, mem::replace(&mut self.desc, String::new())));
-                print(0, &msgs, enabled);
-            });
-        } else {
+            let stdout = stdout();
             MESSAGES.with(|msgs| {
-                let msg = mem::replace(&mut self.desc, String::new());
-                msgs.borrow_mut().push((stack_len, duration_ms, msg));
+                let mut msgs = msgs.borrow_mut();
+                print(0, &msgs, enabled, &mut stdout.lock());
+                msgs.clear();
             });
         }
     }