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.

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();
             });
         }
     }