core::rt: Begin recording scheduler metrics

Author: brson

src/libstd/rt/comm.rs

@@ -119,16 +119,26 @@ impl<T> ChanOne<T> {
             match oldstate {
                 STATE_BOTH => {
                     // Port is not waiting yet. Nothing to do
+                    do Local::borrow::<Scheduler> |sched| {
+                        rtdebug!("non-rendezvous send");
+                        sched.metrics.non_rendezvous_sends += 1;
+                    }
                 }
                 STATE_ONE => {
+                    do Local::borrow::<Scheduler> |sched| {
+                        rtdebug!("rendezvous send");
+                        sched.metrics.rendezvous_sends += 1;
+                    }
                     // Port has closed. Need to clean up.
                     let _packet: ~Packet<T> = cast::transmute(this.inner.void_packet);
                     recvr_active = false;
                 }
                 task_as_state => {
                     // Port is blocked. Wake it up.
                     let recvr: ~Coroutine = cast::transmute(task_as_state);
-                    let sched = Local::take::<Scheduler>();
+                    let mut sched = Local::take::<Scheduler>();
+                    rtdebug!("rendezvous send");
+                    sched.metrics.rendezvous_sends += 1;
                     sched.schedule_task(recvr);
                 }
             }
@@ -170,18 +180,19 @@ impl<T> PortOne<T> {
                 match oldstate {
                     STATE_BOTH => {
                         // Data has not been sent. Now we're blocked.
+                        rtdebug!("non-rendezvous recv");
+                        sched.metrics.non_rendezvous_recvs += 1;
                     }
                     STATE_ONE => {
+                        rtdebug!("rendezvous recv");
+                        sched.metrics.rendezvous_recvs += 1;
+
                         // Channel is closed. Switch back and check the data.
                         // NB: We have to drop back into the scheduler event loop here
                         // instead of switching immediately back or we could end up
                         // triggering infinite recursion on the scheduler's stack.
                         let task: ~Coroutine = cast::transmute(task_as_state);
-                        let task = Cell(task);
-                        do sched.event_loop.callback {
-                            let sched = Local::take::<Scheduler>();
-                            sched.resume_task_immediately(task.take());
-                        }
+                        sched.enqueue_task(task);
                     }
                     _ => util::unreachable()
                 }

src/libstd/rt/metrics.rs

@@ -0,0 +1,88 @@
+// Copyright 2013 The Rust Project Developers. See the COPYRIGHT
+// file at the top-level directory of this distribution and at
+// http://rust-lang.org/COPYRIGHT.
+//
+// Licensed under the Apache License, Version 2.0 <LICENSE-APACHE or
+// http://www.apache.org/licenses/LICENSE-2.0> or the MIT license
+// <LICENSE-MIT or http://opensource.org/licenses/MIT>, at your
+// option. This file may not be copied, modified, or distributed
+// except according to those terms.
+
+use to_str::ToStr;
+
+pub struct SchedMetrics {
+    // The number of times executing `run_sched_once`.
+    turns: uint,
+    // The number of turns that received a message.
+    messages_received: uint,
+    // The number of turns that ran a task from the queue.
+    tasks_resumed_from_queue: uint,
+    // The number of turns that found no work to perform.
+    wasted_turns: uint,
+    // The number of times the scheduler went to sleep.
+    sleepy_times: uint,
+    // Context switches from the scheduler into a task.
+    context_switches_sched_to_task: uint,
+    // Context switches from a task into the scheduler.
+    context_switches_task_to_sched: uint,
+    // Context switches from a task to a task.
+    context_switches_task_to_task: uint,
+    // Message sends that unblock the receiver
+    rendezvous_sends: uint,
+    // Message sends that do not unblock the receiver
+    non_rendezvous_sends: uint,
+    // Message receives that do not block the receiver
+    rendezvous_recvs: uint,
+    // Message receives that block the receiver
+    non_rendezvous_recvs: uint
+}
+
+impl SchedMetrics {
+    pub fn new() -> SchedMetrics {
+        SchedMetrics {
+            turns: 0,
+            messages_received: 0,
+            tasks_resumed_from_queue: 0,
+            wasted_turns: 0,
+            sleepy_times: 0,
+            context_switches_sched_to_task: 0,
+            context_switches_task_to_sched: 0,
+            context_switches_task_to_task: 0,
+            rendezvous_sends: 0,
+            non_rendezvous_sends: 0,
+            rendezvous_recvs: 0,
+            non_rendezvous_recvs: 0
+        }
+    }
+}
+
+impl ToStr for SchedMetrics {
+    fn to_str(&self) -> ~str {
+        fmt!("turns: %u\n\
+              messages_received: %u\n\
+              tasks_resumed_from_queue: %u\n\
+              wasted_turns: %u\n\
+              sleepy_times: %u\n\
+              context_switches_sched_to_task: %u\n\
+              context_switches_task_to_sched: %u\n\
+              context_switches_task_to_task: %u\n\
+              rendezvous_sends: %u\n\
+              non_rendezvous_sends: %u\n\
+              rendezvous_recvs: %u\n\
+              non_rendezvous_recvs: %u\n\
+              ",
+             self.turns,
+             self.messages_received,
+             self.tasks_resumed_from_queue,
+             self.wasted_turns,
+             self.sleepy_times,
+             self.context_switches_sched_to_task,
+             self.context_switches_task_to_sched,
+             self.context_switches_task_to_task,
+             self.rendezvous_sends,
+             self.non_rendezvous_sends,
+             self.rendezvous_recvs,
+             self.non_rendezvous_recvs
+        )
+    }
+}

src/libstd/rt/mod.rs

@@ -130,6 +130,8 @@ pub mod local_ptr;
 /// Bindings to pthread/windows thread-local storage.
 pub mod thread_local_storage;
 
+pub mod metrics;
+
 
 /// Set up a default runtime configuration, given compiler-supplied arguments.
 ///

src/libstd/rt/sched.rs

@@ -13,6 +13,7 @@ use sys;
 use cast::transmute;
 use cell::Cell;
 use clone::Clone;
+use to_str::ToStr;
 
 use super::sleeper_list::SleeperList;
 use super::work_queue::WorkQueue;
@@ -24,6 +25,7 @@ use super::message_queue::MessageQueue;
 use rt::local_ptr;
 use rt::local::Local;
 use rt::rtio::{IoFactoryObject, RemoteCallback};
+use rt::metrics::SchedMetrics;
 
 /// The Scheduler is responsible for coordinating execution of Coroutines
 /// on a single thread. When the scheduler is running it is owned by
@@ -63,7 +65,8 @@ pub struct Scheduler {
     current_task: Option<~Coroutine>,
     /// An action performed after a context switch on behalf of the
     /// code running before the context switch
-    priv cleanup_job: Option<CleanupJob>
+    priv cleanup_job: Option<CleanupJob>,
+    metrics: SchedMetrics
 }
 
 pub struct SchedHandle {
@@ -115,6 +118,7 @@ pub impl Scheduler {
             saved_context: Context::empty(),
             current_task: None,
             cleanup_job: None,
+            metrics: SchedMetrics::new()
         }
     }
 
@@ -141,20 +145,24 @@ pub impl Scheduler {
 
         let sched = Local::take::<Scheduler>();
         assert!(sched.work_queue.is_empty());
+        rtdebug!("scheduler metrics: %s\n", sched.metrics.to_str());
         return sched;
     }
 
     fn run_sched_once() {
 
+        let mut sched = Local::take::<Scheduler>();
+        sched.metrics.turns += 1;
+
         // First, check the message queue for instructions.
         // XXX: perf. Check for messages without atomics.
         // It's ok if we miss messages occasionally, as long as
         // we sync and check again before sleeping.
-        let sched = Local::take::<Scheduler>();
         if sched.interpret_message_queue() {
             // We performed a scheduling action. There may be other work
             // to do yet, so let's try again later.
             let mut sched = Local::take::<Scheduler>();
+            sched.metrics.messages_received += 1;
             sched.event_loop.callback(Scheduler::run_sched_once);
             Local::put(sched);
             return;
@@ -166,6 +174,7 @@ pub impl Scheduler {
             // We performed a scheduling action. There may be other work
             // to do yet, so let's try again later.
             let mut sched = Local::take::<Scheduler>();
+            sched.metrics.tasks_resumed_from_queue += 1;
             sched.event_loop.callback(Scheduler::run_sched_once);
             Local::put(sched);
             return;
@@ -176,8 +185,10 @@ pub impl Scheduler {
         // somebody can wake us up later.
         rtdebug!("no work to do");
         let mut sched = Local::take::<Scheduler>();
+        sched.metrics.wasted_turns += 1;
         if !sched.sleepy && !sched.no_sleep {
             rtdebug!("sleeping");
+            sched.metrics.sleepy_times += 1;
             sched.sleepy = true;
             let handle = sched.make_handle();
             sched.sleeper_list.push(handle);
@@ -327,6 +338,7 @@ pub impl Scheduler {
         assert!(!this.in_task_context());
 
         rtdebug!("scheduling a task");
+        this.metrics.context_switches_sched_to_task += 1;
 
         // Store the task in the scheduler so it can be grabbed later
         this.current_task = Some(task);
@@ -369,6 +381,7 @@ pub impl Scheduler {
         assert!(this.in_task_context());
 
         rtdebug!("blocking task");
+        this.metrics.context_switches_task_to_sched += 1;
 
         unsafe {
             let blocked_task = this.current_task.swap_unwrap();
@@ -401,6 +414,7 @@ pub impl Scheduler {
         assert!(this.in_task_context());
 
         rtdebug!("switching tasks");
+        this.metrics.context_switches_task_to_task += 1;
 
         let old_running_task = this.current_task.swap_unwrap();
         let f_fake_region = unsafe {