task output

direct/src/task/TaskNew.py

@@ -235,3 +235,6 @@ class TaskManager:
     def stop(self):
         # Set a flag so we will stop before beginning next frame
         self.running = False
+
+    def __repr__(self):
+        return str(self.mgr)

panda/src/event/asyncTask.I

@@ -13,29 +13,6 @@
 ////////////////////////////////////////////////////////////////////
 
 
-////////////////////////////////////////////////////////////////////
-//     Function: AsyncTask::Constructor
-//       Access: Public
-//  Description: 
-////////////////////////////////////////////////////////////////////
-INLINE AsyncTask::
-AsyncTask(const string &name) : 
-  Namable(name),
-  _delay(0.0),
-  _has_delay(false),
-  _wake_time(0.0),
-  _sort(0),
-  _priority(0),
-  _state(S_inactive),
-  _servicing_thread(NULL),
-  _manager(NULL),
-  _chain(NULL)
-{
-#ifdef HAVE_PYTHON
-  _python_object = NULL;
-#endif  // HAVE_PYTHON
-}
-
 ////////////////////////////////////////////////////////////////////
 //     Function: AsyncTask::get_state
 //       Access: Published
@@ -256,3 +233,39 @@ get_python_object() const {
 }
 #endif  // HAVE_PYTHON
 
+////////////////////////////////////////////////////////////////////
+//     Function: AsyncTask::get_dt
+//       Access: Published
+//  Description: Returns the amount of time elapsed during the task's
+//               previous run cycle, in seconds.
+////////////////////////////////////////////////////////////////////
+INLINE double AsyncTask::
+get_dt() const {
+  return _dt;
+}
+
+////////////////////////////////////////////////////////////////////
+//     Function: AsyncTask::get_max_dt
+//       Access: Published
+//  Description: Returns the maximum amount of time elapsed during any
+//               one of the task's previous run cycles, in seconds.
+////////////////////////////////////////////////////////////////////
+INLINE double AsyncTask::
+get_max_dt() const {
+  return _max_dt;
+}
+
+////////////////////////////////////////////////////////////////////
+//     Function: AsyncTask::get_average_dt
+//       Access: Published
+//  Description: Returns the average amount of time elapsed during
+//               each of the task's previous run cycles, in seconds.
+////////////////////////////////////////////////////////////////////
+INLINE double AsyncTask::
+get_average_dt() const {
+  if (_num_frames == 0) {
+    return 0.0;
+  } else {
+    return _total_dt / _num_frames;
+  }
+}

panda/src/event/asyncTask.cxx

@@ -18,6 +18,33 @@
 
 TypeHandle AsyncTask::_type_handle;
 
+////////////////////////////////////////////////////////////////////
+//     Function: AsyncTask::Constructor
+//       Access: Public
+//  Description: 
+////////////////////////////////////////////////////////////////////
+AsyncTask::
+AsyncTask(const string &name) : 
+  Namable(name),
+  _delay(0.0),
+  _has_delay(false),
+  _wake_time(0.0),
+  _sort(0),
+  _priority(0),
+  _state(S_inactive),
+  _servicing_thread(NULL),
+  _manager(NULL),
+  _chain(NULL),
+  _dt(0.0),
+  _max_dt(0.0),
+  _total_dt(0.0),
+  _num_frames(0)
+{
+#ifdef HAVE_PYTHON
+  _python_object = NULL;
+#endif  // HAVE_PYTHON
+}
+
 ////////////////////////////////////////////////////////////////////
 //     Function: AsyncTask::Destructor
 //       Access: Public, Virtual
@@ -47,7 +74,7 @@ remove() {
 //     Function: AsyncTask::get_elapsed_time
 //       Access: Published
 //  Description: Returns the amount of time that has elapsed since
-//               task was started, according to the task manager's
+//               the task was started, according to the task manager's
 //               clock.
 //
 //               It is only valid to call this if the task's status is
@@ -224,6 +251,36 @@ output(ostream &out) const {
   }
 }
 
+////////////////////////////////////////////////////////////////////
+//     Function: AsyncTask::unlock_and_do_task
+//       Access: Protected
+//  Description: Called by the AsyncTaskManager to actually run the
+//               task.  Assumes the lock is held.  See do_task().
+////////////////////////////////////////////////////////////////////
+AsyncTask::DoneStatus AsyncTask::
+unlock_and_do_task() {
+  nassertr(_manager != (AsyncTaskManager *)NULL, DS_done);
+  PT(ClockObject) clock = _manager->get_clock();
+
+  // It's important to release the lock while the task is being
+  // serviced.
+  _manager->_lock.release();
+  
+  double start = clock->get_real_time();
+  DoneStatus status = do_task();
+  double end = clock->get_real_time();
+
+  // Now reacquire the lock (so we can return with the lock held).
+  _manager->_lock.lock();
+
+  _dt = end - start;
+  _max_dt = max(_dt, _max_dt);
+  _total_dt += _dt;
+  ++_num_frames;
+
+  return status;
+}
+
 ////////////////////////////////////////////////////////////////////
 //     Function: AsyncTask::do_task
 //       Access: Protected, Virtual
@@ -241,6 +298,8 @@ output(ostream &out) const {
 //
 //               DS_abort: abort the task, and interrupt the whole
 //               AsyncTaskManager.
+//
+//               This function is called with the lock *not* held.
 ////////////////////////////////////////////////////////////////////
 AsyncTask::DoneStatus AsyncTask::
 do_task() {

panda/src/event/asyncTask.h

@@ -42,7 +42,7 @@ class AsyncTaskChain;
 ////////////////////////////////////////////////////////////////////
 class EXPCL_PANDA_EVENT AsyncTask : public TypedReferenceCount, public Namable {
 public:
-  INLINE AsyncTask(const string &name = string());
+  AsyncTask(const string &name = string());
   virtual ~AsyncTask();
   ALLOC_DELETED_CHAIN(AsyncTask);
 
@@ -96,9 +96,14 @@ PUBLISHED:
   INLINE PyObject *get_python_object() const;
 #endif  // HAVE_PYTHON
 
+  INLINE double get_dt() const;
+  INLINE double get_max_dt() const;
+  INLINE double get_average_dt() const;
+
   virtual void output(ostream &out) const;
 
 protected:
+  DoneStatus unlock_and_do_task();
   virtual DoneStatus do_task();
 
 protected:
@@ -115,6 +120,11 @@ protected:
   AsyncTaskManager *_manager;
   AsyncTaskChain *_chain;
 
+  double _dt;
+  double _max_dt;
+  double _total_dt;
+  int _num_frames;
+
 private:
 #ifdef HAVE_PYTHON
   PyObject *_python_object;

panda/src/event/asyncTaskChain.cxx

@@ -24,6 +24,7 @@
 #include "pStatTimer.h"
 #include "clockObject.h"
 #include <algorithm>
+#include <stdio.h>  // For sprintf/snprintf
 
 TypeHandle AsyncTaskChain::_type_handle;
 
@@ -507,15 +508,7 @@ service_one_task(AsyncTaskChain::AsyncTaskChainThread *thread) {
     task->_state = AsyncTask::S_servicing;
     task->_servicing_thread = thread;
 
-    // Now release the chain lock while we actually service the
+    AsyncTask::DoneStatus ds = task->unlock_and_do_task();
-    // task.
-    _manager->_lock.release();
-    AsyncTask::DoneStatus ds = task->do_task();
-
-    // Now we have to re-acquire the chain lock, so we can put the
-    // task back on the queue (and so we can return with the lock
-    // still held).
-    _manager->_lock.lock();
 
     if (thread != (AsyncTaskChain::AsyncTaskChainThread *)NULL) {
       thread->_servicing = NULL;
@@ -801,8 +794,28 @@ do_poll() {
 ////////////////////////////////////////////////////////////////////
 void AsyncTaskChain::
 do_write(ostream &out, int indent_level) const {
-  indent(out, indent_level)
+  if (has_name()) {
-    << get_type() << " " << get_name() << "\n";
+    indent(out, indent_level)
+      << get_name() << "\n";
+  }
+
+  static const size_t buffer_size = 1024;
+  char buffer[buffer_size];
+  sprintf(buffer, " %-32s %8s %8s %8s %8s %6s",
+          "Task", 
+          "sleep(s)",
+          "dt(ms)", "avg", "max",
+          "sort");
+  nassertv(strlen(buffer) < buffer_size);
+
+  indent(out, indent_level) 
+    << buffer << "\n";
+
+  indent(out, indent_level);
+  for (int i = 0; i < 32+8+8+8+8+6+7; ++i) {
+    out << '-';
+  }
+  out << "\n";
 
   // Collect a list of all active tasks, then sort them into order for
   // output.
@@ -818,55 +831,78 @@ do_write(ostream &out, int indent_level) const {
     }
   }
 
-  if (!tasks.empty()) {
+  sort(tasks.begin(), tasks.end(), AsyncTaskSortPriority());
-    indent(out, indent_level + 2)
-      << "Active tasks:\n";
 
-    sort(tasks.begin(), tasks.end(), AsyncTaskSortPriority());
+  double now = _manager->_clock->get_frame_time();
 
-    // Since AsyncTaskSortPriority() sorts backwards (because of STL's
+  // Since AsyncTaskSortPriority() sorts backwards (because of STL's
-    // push_heap semantics), we go through the task list in reverse
+  // push_heap semantics), we go through the task list in reverse
-    // order to print them forwards.
+  // order to print them forwards.
-    TaskHeap::reverse_iterator ti;
+  TaskHeap::reverse_iterator ti;
-    int current_sort = tasks.back()->get_sort() - 1;
+  int current_sort = tasks.back()->get_sort() - 1;
-    for (ti = tasks.rbegin(); ti != tasks.rend(); ++ti) {
+  for (ti = tasks.rbegin(); ti != tasks.rend(); ++ti) {
-      AsyncTask *task = (*ti);
+    AsyncTask *task = (*ti);
-      if (task->get_sort() != current_sort) {
+    write_task_line(out, indent_level, task, now);
-        current_sort = task->get_sort();
-        indent(out, indent_level + 2)
-          << "sort = " << current_sort << "\n";
-      }
-      if (task->_state == AsyncTask::S_servicing) {
-        indent(out, indent_level + 3)
-          << "*" << *task << "\n";
-      } else {
-        indent(out, indent_level + 4)
-          << *task << "\n";
-      }
-    }
   }
 
-  if (!_sleeping.empty()) {
+  // Instead of iterating through the _sleeping list in heap order,
-    indent(out, indent_level + 2)
+  // copy it and then use repeated pops to get it out in sorted
-      << "Sleeping tasks:\n";
+  // order, for the user's satisfaction.
-    double now = _manager->_clock->get_frame_time();
+  TaskHeap sleeping = _sleeping;
-
+  while (!sleeping.empty()) {
-    // Instead of iterating through the _sleeping list in heap order,
+    PT(AsyncTask) task = sleeping.front();
-    // copy it and then use repeated pops to get it out in sorted
+    pop_heap(sleeping.begin(), sleeping.end(), AsyncTaskSortWakeTime());
-    // order, for the user's satisfaction.
+    sleeping.pop_back();
-    TaskHeap sleeping = _sleeping;
+    
-    while (!sleeping.empty()) {
+    write_task_line(out, indent_level, task, now);
-      PT(AsyncTask) task = sleeping.front();
-      pop_heap(sleeping.begin(), sleeping.end(), AsyncTaskSortWakeTime());
-      sleeping.pop_back();
-
-      indent(out, indent_level + 4)
-        << task->get_wake_time() - now << "s: "
-        << *task << "\n";
-    }
   }
 }
 
+////////////////////////////////////////////////////////////////////
+//     Function: AsyncTaskChain::write_task_line
+//       Access: Protected
+//  Description: Writes a single line for a task in the report
+//               generated by do_write().  Assumes the lock is already
+//               held.
+////////////////////////////////////////////////////////////////////
+void AsyncTaskChain::
+write_task_line(ostream &out, int indent_level, AsyncTask *task, double now) const {
+  char servicing_flag = ' ';
+  if (task->_state == AsyncTask::S_servicing) {
+    servicing_flag = '*';
+  } else if (task->_state == AsyncTask::S_servicing_removed) {
+    servicing_flag = '-';
+  }
+
+  static const size_t buffer_size = 1024;
+  char buffer[buffer_size];
+
+  if (task->_state == AsyncTask::S_sleeping) {
+    // For sleeping tasks, include the wake time, as an elapsed time
+    // in seconds.
+    string name = task->get_name().substr(0, 32);
+    sprintf(buffer, "%c%-32s %8.1f %8.1f %8.1f %8.1f %6d",
+            servicing_flag, name.c_str(),
+            task->_wake_time - now,
+            task->_dt * 1000.0, task->get_average_dt() * 1000.0,
+            task->_max_dt * 1000.0, 
+            task->_sort);
+  } else {
+    // For active tasks, don't include a wake time.  This means we
+    // have more space for the name.
+    string name = task->get_name().substr(0, 41);
+    sprintf(buffer, "%c%-41s %8.1f %8.1f %8.1f %6d",
+            servicing_flag, name.c_str(),
+            task->_dt * 1000.0, task->get_average_dt() * 1000.0,
+            task->_max_dt * 1000.0, 
+            task->_sort);
+  }
+  nassertv(strlen(buffer) < buffer_size);
+
+  indent(out, indent_level) 
+    << buffer << "\n";
+}
+
 ////////////////////////////////////////////////////////////////////
 //     Function: AsyncTaskChain::AsyncTaskChainThread::Constructor
 //       Access: Public

panda/src/event/asyncTaskChain.h

@@ -108,6 +108,8 @@ protected:
   void do_poll();
   void do_write(ostream &out, int indent_level) const;
 
+  void write_task_line(ostream &out, int indent_level, AsyncTask *task, double now) const;
+
 protected:
   class AsyncTaskChainThread : public Thread {
   public:

panda/src/event/asyncTaskManager.cxx

@@ -37,6 +37,8 @@ AsyncTaskManager(const string &name) :
   Namable(name),
   _clock(ClockObject::get_global_clock())
 {
+  // Make a default task chain.
+  do_make_task_chain("");
 }
 
 ////////////////////////////////////////////////////////////////////