6 files changed, 106 insertions, 2 deletions

diff --git a/DAnCE/dance/LocalityManager/Scheduler/Deployment_Completion.h b/DAnCE/dance/LocalityManager/Scheduler/Deployment_Completion.h
index 0381bf53e5b..25f4944597d 100644
--- a/DAnCE/dance/LocalityManager/Scheduler/Deployment_Completion.h
+++ b/DAnCE/dance/LocalityManager/Scheduler/Deployment_Completion.h
@@ -14,6 +14,7 @@
 
 #include "ace/Condition_T.h"
 #include "ace/Future.h"
+#include "ace/Time_Value.h"
 #include "Completion/Completion_Counter_Base.h"
 #include "dance/LocalityManager/Scheduler/Deployment_Event.h"
 #include "dance/LocalityManager/Scheduler/Deployment_Scheduler.h"
diff --git a/DAnCE/dance/NodeApplication/NodeApplication_Impl.cpp b/DAnCE/dance/NodeApplication/NodeApplication_Impl.cpp
index d85b82d4162..6b61a7621a8 100644
--- a/DAnCE/dance/NodeApplication/NodeApplication_Impl.cpp
+++ b/DAnCE/dance/NodeApplication/NodeApplication_Impl.cpp
@@ -56,11 +56,18 @@ NodeApplication_Impl::NodeApplication_Impl (CORBA::ORB_ptr orb,
   // @Todo:  We can probably move this up into the NodeManager and
   // share the thread pool among several node applications.
   this->scheduler_.activate_scheduler (0);
+  
+  timer_out_.open (node_name_.c_str (), 
+                   std::ios_base::out & std::ios_base::trunc);
+  timer_.reset ();
+  timer_.start ();
 }
 
 NodeApplication_Impl::~NodeApplication_Impl()
 {
   DANCE_TRACE( "NodeApplication_Impl::~NodeApplication_Impl()");
+  timer_.stop ();
+  timer_out_.close ();
   this->scheduler_.terminate_scheduler ();
 }
 
@@ -68,11 +75,15 @@ void
 NodeApplication_Impl::prepare_instances (const LocalitySplitter::TSubPlans& plans)
 {
   DANCE_TRACE ("NodeApplication_Impl::prepare_instances");
+  
+  ACE_hrtime_t time (0);
+  timer_.elapsed_microseconds (time);
+  timer_out_ << "prepare_instances start:" << time << '\n';
 
   CORBA::ULong plan (0);
   std::list < Event_Future > prepared_instances;
   Deployment_Completion completion (this->scheduler_);
-
+  
   // for each sub plan
   LocalitySplitter::TSubPlanConstIterator plans_end (plans, 1);
   for (LocalitySplitter::TSubPlanConstIterator i (plans);
@@ -201,6 +212,9 @@ NodeApplication_Impl::prepare_instances (const LocalitySplitter::TSubPlans& plan
                     ACE_TEXT ("Successfully executed preparePlan on locality %C\n"),
                     event.id_.c_str ()));
     }
+  
+  timer_.elapsed_microseconds (time);
+  timer_out_ << "prepare_instances end:" << time << '\n';
 }
 
 void
@@ -224,7 +238,7 @@ NodeApplication_Impl::prepare_instance (const char *name,
     {
       DANCE_ERROR (DANCE_LOG_TERMINAL_ERROR, (LM_ERROR, DLINFO
                        ACE_TEXT ("NodeApplication_Impl::prepare_instance - ")
-                       ACE_TEXT ("Caugt unexpected CORBA exception while invoking preparePlan %C\n"),
+                       ACE_TEXT ("Caught unexpected CORBA exception while invoking preparePlan %C\n"),
                        ex._info ().c_str ()));
     }
   // @@ TODO:  Ouch! We're swallowing exceptions here!
@@ -248,6 +262,10 @@ void
 NodeApplication_Impl::start_launch_instances (const Deployment::Properties &prop,
                                               Deployment::Connections_out providedReference)
 {
+  ACE_hrtime_t time (0);
+  timer_.elapsed_microseconds (time);
+  timer_out_ << "start_launch_instances start:" << time << '\n';
+
   DANCE_TRACE ("NodeApplication_Impl::start_launch_instances");
   Deployment::Connections *tmp (0);
 
@@ -313,12 +331,19 @@ NodeApplication_Impl::start_launch_instances (const Deployment::Properties &prop
           throw;
         }
     }
+
+  timer_.elapsed_microseconds (time);
+  timer_out_ << "start_launch_instances end:" << time << '\n';
 }
 
 void
 NodeApplication_Impl::finishLaunch (const ::Deployment::Connections & providedReference,
                                     ::CORBA::Boolean start)
 {
+  ACE_hrtime_t time (0);
+  timer_.elapsed_microseconds (time);
+  timer_out_ << "finishLaunch start:" << time << '\n';
+
   DANCE_TRACE ("NodeApplication_Impl::finishLaunch");
 
 
@@ -346,11 +371,18 @@ NodeApplication_Impl::finishLaunch (const ::Deployment::Connections & providedRe
           throw;
         }
     }
+  
+  timer_.elapsed_microseconds (time);
+  timer_out_ << "finishLaunch end:" << time << '\n';
 }
 
 void
 NodeApplication_Impl::start ()
 {
+  ACE_hrtime_t time (0);
+  timer_.elapsed_microseconds (time);
+  timer_out_ << "start start:" << time << '\n';
+
   DANCE_TRACE( "NodeApplication_Impl::start");
 
   for (LOCALITY_MAP::const_iterator i = this->localities_.begin ();
@@ -376,6 +408,8 @@ NodeApplication_Impl::start ()
           throw;
         }
     }
+  timer_.elapsed_microseconds (time);
+  timer_out_ << "start end:" << time << '\n';
 }
 
 void
diff --git a/DAnCE/dance/NodeApplication/NodeApplication_Impl.h b/DAnCE/dance/NodeApplication/NodeApplication_Impl.h
index c9d9aa2b4ec..22a5f49f134 100644
--- a/DAnCE/dance/NodeApplication/NodeApplication_Impl.h
+++ b/DAnCE/dance/NodeApplication/NodeApplication_Impl.h
@@ -34,6 +34,9 @@
 #include <map>
 #include <vector>
 
+#include "ace/High_Res_Timer.h"
+#include <ostream>
+
 using namespace DAnCE::Utility;
 
 namespace DAnCE
@@ -92,6 +95,10 @@ namespace DAnCE
     PLAN_MAP sub_plans_;
 
     CORBA::ULong spawn_delay_;
+    
+    ACE_High_Res_Timer timer_;
+    
+    std::ofstream timer_out_;
   };
 }
 #endif /*NODEAPPLICATION_IMPL_H_*/
diff --git a/DAnCE/dance/Plan_Launcher/Plan_Launcher_Base.h b/DAnCE/dance/Plan_Launcher/Plan_Launcher_Base.h
index ccad13bd487..e0a00edee7b 100644
--- a/DAnCE/dance/Plan_Launcher/Plan_Launcher_Base.h
+++ b/DAnCE/dance/Plan_Launcher/Plan_Launcher_Base.h
@@ -10,6 +10,9 @@
 #ifndef DANCE_PLAN_LAUNCHER_BASE
 #define DANCE_PLAN_LAUNCHER_BASE
 
+#include "ace/High_Res_Timer.h"
+#include <ostream>
+
 #include "dance/Deployment/Deployment_DeploymentPlanC.h"
 #include "dance/Deployment/Deployment_ConnectionC.h"
 #include "dance/Plan_Launcher/Plan_Launcher_Export.h"
@@ -52,6 +55,12 @@ namespace DAnCE
     /// Instructs the Manager to destroy the ApplicationManager.
     virtual void destroy_app_manager (CORBA::Object_ptr app_mgr) = 0;
 
+  private:
+     
+  private:
+    ACE_High_Res_Timer timer_;
+    std::ofstream outfile_;
+    
   };
 }
 
diff --git a/DAnCE/dance/Plan_Launcher/Plan_Launcher_Base_Impl_T.cpp b/DAnCE/dance/Plan_Launcher/Plan_Launcher_Base_Impl_T.cpp
index 8e24e856421..302910656f5 100644
--- a/DAnCE/dance/Plan_Launcher/Plan_Launcher_Base_Impl_T.cpp
+++ b/DAnCE/dance/Plan_Launcher/Plan_Launcher_Base_Impl_T.cpp
@@ -75,8 +75,18 @@ namespace DAnCE
 
   try
     {
+      timer_.reset ();
+      timer_.start ();
+
       ::Deployment::ApplicationManager_var l_manager =
         this->manager_->preparePlan (plan, 0);
+
+      timer_.stop ();
+
+      ACE_hrtime_t elapsed (0);
+      timer_.elapsed_microseconds (elapsed);
+      outfile_ << "PreparePlan time: " << elapsed << '\n';
+
       app_manager = app_manager = AppManager::_narrow (l_manager.in ());
     }
   catch (::Deployment::PlanError &ex)
@@ -174,7 +184,18 @@ Plan_Launcher_Base_Impl< Manager, AppManager, Application>
                    (LM_DEBUG, DLINFO
                     ACE_TEXT("Plan_Launcher_Base_Impl::start_launch - ")
                     ACE_TEXT("before startLaunch...\n")));
+
+      timer_.reset ();
+      timer_.start ();
+
       da = app_manager->startLaunch (properties, connections);
+
+      timer_.stop ();
+
+      ACE_hrtime_t elapsed (0);
+      timer_.elapsed_microseconds (elapsed);
+      outfile_ << "PreparePlan time: " << elapsed << '\n';
+
       DANCE_DEBUG (DANCE_LOG_EVENT_TRACE,
                    (LM_DEBUG, DLINFO
                     ACE_TEXT("Plan_Launcher_Base_Impl::start_launch - ")
@@ -323,8 +344,17 @@ Plan_Launcher_Base_Impl< Manager, AppManager, Application>
                    (LM_DEBUG, DLINFO
                     ACE_TEXT("Plan_Launcher_Base_Impl::launch_plan - ")
                     ACE_TEXT("before finishLaunch\n")));
+
+      timer_.reset ();
+      timer_.start ();
+
       application->finishLaunch (provided_connections,
                                  start);
+
+      ACE_hrtime_t elapsed (0);
+      timer_.elapsed_microseconds (elapsed);
+      outfile_ << "PreparePlan time: " << elapsed << '\n';
+
       DANCE_DEBUG (DANCE_LOG_EVENT_TRACE,
                    (LM_DEBUG, DLINFO
                     ACE_TEXT("Plan_Launcher_Base_Impl::launch_plan - ")
@@ -455,6 +485,14 @@ Plan_Launcher_Base_Impl< Manager, AppManager, Application>
 
   try
     {
+      std::string filename = plan.UUID.in ();
+      filename += ".timing";
+      outfile_.open (filename.c_str ());
+      
+      ACE_High_Res_Timer timer;
+      timer.reset ();
+      timer.start ();
+ 
       CORBA::Object_var app_mgr = this->prepare_plan (plan);
 
       ::Deployment::Connections_var conns;
@@ -469,6 +507,15 @@ Plan_Launcher_Base_Impl< Manager, AppManager, Application>
 
       this->start (app.in ());
 
+         
+      timer.stop ();
+      
+      ACE_hrtime_t elapsed (0);
+      timer.elapsed_microseconds (elapsed);
+      outfile_ << "Total plan deployment time: " << elapsed << '\n';
+      
+      outfile_.close ();
+
       DANCE_DEBUG (DANCE_LOG_MAJOR_EVENT,
                    (LM_DEBUG, DLINFO
                     ACE_TEXT ("Plan_Launcher_Base_Impl::launch_plan - ")
diff --git a/DAnCE/dance/Plan_Launcher/Plan_Launcher_Base_Impl_T.h b/DAnCE/dance/Plan_Launcher/Plan_Launcher_Base_Impl_T.h
index a5b412e8550..9b8bbb0abf4 100644
--- a/DAnCE/dance/Plan_Launcher/Plan_Launcher_Base_Impl_T.h
+++ b/DAnCE/dance/Plan_Launcher/Plan_Launcher_Base_Impl_T.h
@@ -15,6 +15,9 @@
 
 #include "Plan_Launcher_Base.h"
 
+#include "ace/High_Res_Timer.h"
+#include <ostream>
+
 namespace DAnCE
 {
   /**
@@ -75,6 +78,9 @@ namespace DAnCE
 
     /// Object reference of the Manager
     Manager_var manager_;
+    
+    ACE_High_Res_Timer timer_;
+    std::ofstream outfile_;
   }; // class Plan_Launcher_Impl
 
 }