Performance Timing

- Change the was performance measurements are taken.  This in preparation
  to automated daily perf charts, leading to efforts to speed up certain
  operations.

src/Context.cpp

@@ -27,6 +27,7 @@
 
 #include <iostream>
 #include <fstream>
+#include <sstream>
 #include <algorithm>
 #include <pwd.h>
 #include <stdlib.h>
@@ -35,12 +36,14 @@
 #include <Context.h>
 #include <Directory.h>
 #include <File.h>
-#include <Timer.h>
 #include <text.h>
 #include <util.h>
 #include <main.h>
 #include <i18n.h>
-#include <../cmake.h>
+#include <cmake.h>
+#ifdef HAVE_COMMIT
+#include <commit.h>
+#endif
 
 ////////////////////////////////////////////////////////////////////////////////
 Context::Context ()
@@ -67,7 +70,7 @@ Context::~Context ()
 ////////////////////////////////////////////////////////////////////////////////
 int Context::initialize (int argc, const char** argv)
 {
-  Timer t ("Context::initialize");
+  timer_init.start ();
   int rc = 0;
 
   try
@@ -202,6 +205,8 @@ int Context::initialize (int argc, const char** argv)
       else
         std::cout << *f << "\n";
   }
+
+  timer_init.stop ();
   return rc;
 }
 
@@ -214,6 +219,37 @@ int Context::run ()
   try
   {
     rc = dispatch (output);
+
+    std::stringstream s;
+    s << "Perf "
+      << PACKAGE_STRING
+      << " "
+#ifdef HAVE_COMMIT
+      << COMMIT
+#else
+      << "-"
+#endif
+      << " "
+      << Date ().toISO ()
+
+      << " init:"   << timer_init.total ()
+      << " load:"   << timer_load.total ()
+      << " synch:"  << timer_synch.total ()
+      << " gc:"     << timer_gc.total ()
+      << " filter:" << timer_filter.total ()
+      << " commit:" << timer_commit.total ()
+      << " sort:"   << timer_sort.total ()
+      << " render:" << timer_render.total ()
+      << " total:"  << (timer_init.total ()   +
+                        timer_load.total ()   +
+                        timer_synch.total ()  +
+                        timer_gc.total ()     +
+                        timer_filter.total () +
+                        timer_commit.total () +
+                        timer_sort.total ()   +
+                        timer_render.total ())
+      << "\n";
+    debug (s.str ());
   }
 
   catch (const std::string& error)
@@ -273,8 +309,6 @@ int Context::run ()
 // with the earliest argument.
 int Context::dispatch (std::string &out)
 {
-  Timer t ("Context::dispatch");
-
   // Autocomplete args against keywords.
   std::string command;
   if (a3.find_command (command))

src/Context.h

@@ -40,6 +40,7 @@
 #include <File.h>
 #include <Directory.h>
 #include <A3.h>
+#include <Timer.h>
 
 class Context
 {
@@ -112,6 +113,15 @@ public:
 
   int                                 terminal_width;
   int                                 terminal_height;
+
+  Timer                               timer_init;
+  Timer                               timer_load;
+  Timer                               timer_synch;
+  Timer                               timer_gc;
+  Timer                               timer_filter;
+  Timer                               timer_commit;
+  Timer                               timer_sort;
+  Timer                               timer_render;
 };
 
 #endif

src/TDB.cpp

@@ -41,7 +41,6 @@
 #include <Directory.h>
 #include <File.h>
 #include <ViewText.h>
-#include <Timer.h>
 #include <Color.h>
 #include <main.h>
 
@@ -275,8 +274,6 @@ int TDB::load (std::vector <Task>& tasks)
 //       multiple files.
 int TDB::loadPending (std::vector <Task>& tasks)
 {
-  Timer t ("TDB::loadPending");
-
   std::string file;
   int line_number = 1;
 
@@ -346,8 +343,6 @@ int TDB::loadPending (std::vector <Task>& tasks)
 //       multiple files.
 int TDB::loadCompleted (std::vector <Task>& tasks)
 {
-  Timer t ("TDB::loadCompleted");
-
   std::string file;
   int line_number = 1;
 
@@ -456,7 +451,7 @@ void TDB::update (const Task& task)
 // only modified by TDB::gc.
 int TDB::commit ()
 {
-  Timer t ("TDB::commit");
+  context.timer_gc.start ();
 
   int quantity = mNew.size () + mModified.size ();
 
@@ -542,6 +537,7 @@ int TDB::commit ()
     mNew.clear ();
   }
 
+  context.timer_gc.stop ();
   return quantity;
 }
 
@@ -552,11 +548,14 @@ int TDB::commit ()
 // Now cleans up dangling dependencies.
 int TDB::gc ()
 {
-  Timer t ("TDB::gc");
+  context.timer_gc.start ();
 
   // Allowed as a temporary override.
   if (!context.config.getBoolean ("gc"))
+  {
+    context.timer_gc.stop ();
     return 0;
+  }
 
   int count_pending_changes = 0;
   int count_completed_changes = 0;
@@ -662,6 +661,8 @@ int TDB::gc ()
   std::stringstream s;
   s << "gc " << (count_pending_changes + count_completed_changes) << " tasks";
   context.debug (s.str ());
+
+  context.timer_gc.stop ();
   return count_pending_changes + count_completed_changes;
 }
 

src/TDB2.cpp

@@ -27,7 +27,6 @@
 
 //#include <iostream> // TODO Remove.
 #include <Context.h>
-#include <Timer.h>
 #include <text.h>
 #include <TDB2.h>
 
@@ -62,7 +61,6 @@ void TF2::target (const std::string& f)
 const std::vector <Task>& TF2::get_tasks ()
 {
 //  std::cout << "# TF2::get_tasks " << _file.data << "\n";
-  Timer timer ("TF2::get_tasks " + _file.data);
 
   if (! _loaded_tasks)
     load_tasks ();
@@ -242,6 +240,7 @@ void TF2::commit ()
 void TF2::load_tasks ()
 {
 //  std::cout << "# TF2::load_tasks " << _file.data << "\n";
+  context.timer_load.start ();
 
   if (! _loaded_lines)
     load_lines ();
@@ -281,6 +280,8 @@ void TF2::load_tasks ()
   {
     throw e + format (" in {1} at line {2}", _file.data, line_number);
   }
+
+  context.timer_load.stop ();
 }
 
 ////////////////////////////////////////////////////////////////////////////////
@@ -413,15 +414,28 @@ void TDB2::modify (const Task& task)
 void TDB2::commit ()
 {
   dump ();
-  Timer timer ("TDB2::commit");
+
+  context.timer_gc.start ();
+
   pending.commit ();
   completed.commit ();
   undo.commit ();
   backlog.commit ();
   synch_key.commit ();
+
+  context.timer_gc.stop ();
+
   dump ();
 }
 
+////////////////////////////////////////////////////////////////////////////////
+void TDB2::synch ()
+{
+  context.timer_synch.start ();
+
+  context.timer_synch.stop ();
+}
+
 ////////////////////////////////////////////////////////////////////////////////
 // Scans the pending tasks for any that are completed or deleted, and if so,
 // moves them to the completed.data file.  Returns a count of tasks moved.
@@ -429,7 +443,11 @@ void TDB2::commit ()
 // Now cleans up dangling dependencies.
 int TDB2::gc ()
 {
-  Timer timer ("TDB2::gc");
+  context.timer_gc.start ();
+
+  // Allowed as a temporary override.
+  if (context.config.getBoolean ("gc"))
+  {
 /*
     pending.load_tasks
     completed.load_tasks
@@ -450,7 +468,9 @@ int TDB2::gc ()
 
     // TODO Remove dangling dependencies
     // TODO Wake up expired waiting tasks
+  }
 
+  context.timer_gc.stop ();
   return 0;
 }
 

src/TDB2.h

@@ -92,6 +92,7 @@ public:
   void add (const Task&);
   void modify (const Task&);
   void commit ();
+  void synch ();
   int  gc ();
   int  next_id ();
 

src/Timer.cpp

@@ -37,36 +37,72 @@ extern Context context;
 
 ////////////////////////////////////////////////////////////////////////////////
 // Timer starts when the object is constructed.
-Timer::Timer (const std::string& description)
-: mDescription (description)
+Timer::Timer ()
+: _description ("-")
+, _running (false)
+, _total (0)
 {
-  gettimeofday (&mStart, NULL);
+}
+
+////////////////////////////////////////////////////////////////////////////////
+// Timer starts when the object is constructed with a description.
+Timer::Timer (const std::string& description)
+: _description (description)
+, _running (false)
+, _total (0)
+{
+  start ();
 }
 
 ////////////////////////////////////////////////////////////////////////////////
 // Timer stops when the object is destructed.
 Timer::~Timer ()
 {
-  struct timeval end;
-  gettimeofday (&end, NULL);
+  stop ();
 
   std::stringstream s;
   s << "Timer " // No i18n
-    << mDescription
+    << _description
     << " "
     << std::setprecision (6)
-
 #ifndef HAIKU
     // Haiku fails on this - don't know why.
     << std::fixed
 #endif
-
-    << ((end.tv_sec - mStart.tv_sec) + ((end.tv_usec - mStart.tv_usec )
-       / 1000000.0))
+    << _total / 1000000.0
     << " sec";
 
   context.debug (s.str ());
 }
 
 ////////////////////////////////////////////////////////////////////////////////
+void Timer::start ()
+{
+  if (!_running)
+  {
+    gettimeofday (&_start, NULL);
+    _running = true;
+  }
+}
+
+////////////////////////////////////////////////////////////////////////////////
+void Timer::stop ()
+{
+  if (_running)
+  {
+    struct timeval end;
+    gettimeofday (&end, NULL);
+    _running = false;
+    _total += (end.tv_sec - _start.tv_sec) * 1000000.0
+            + (end.tv_usec - _start.tv_usec);
+  }
+}
+
+////////////////////////////////////////////////////////////////////////////////
+unsigned long Timer::total () const
+{
+  return _total;
+}
+
+////////////////////////////////////////////////////////////////////////////////
 

src/Timer.h

@@ -34,14 +34,21 @@
 class Timer
 {
 public:
+  Timer ();
   Timer (const std::string&);
   ~Timer ();
   Timer (const Timer&);
   Timer& operator= (const Timer&);
 
+  void start ();
+  void stop ();
+  unsigned long total () const;
+
 private:
-  std::string mDescription;
-  struct timeval mStart;
+  std::string    _description;
+  bool           _running;
+  struct timeval _start;
+  unsigned long  _total;
 };
 
 #endif

src/ViewTask.cpp

@@ -101,7 +101,7 @@ ViewTask::ViewTask ()
 //
 std::string ViewTask::render (std::vector <Task>& data, std::vector <int>& sequence)
 {
-  Timer timer ("ViewTask::render");
+  context.timer_render.start ();
 
   // Determine minimal, ideal column widths.
   std::vector <int> minimal;
@@ -228,8 +228,11 @@ std::string ViewTask::render (std::vector <Task>& data, std::vector <int>& seque
 
     // Stop if the line limit is exceeded.
     if (++_lines >= _truncate_lines && _truncate_lines != 0)
+    {
+      context.timer_render.stop ();
       return out;
     }
+  }
 
   // Compose, render columns, in sequence.
   _rows = 0;
@@ -289,16 +292,23 @@ std::string ViewTask::render (std::vector <Task>& data, std::vector <int>& seque
 
       // Stop if the line limit is exceeded.
       if (++_lines >= _truncate_lines && _truncate_lines != 0)
+      {
+        context.timer_render.stop ();
         return out;
       }
+    }
 
     cells.clear ();
 
     // Stop if the row limit is exceeded.
     if (++_rows >= _truncate_rows && _truncate_rows != 0)
+    {
+      context.timer_render.stop ();
       return out;
     }
+  }
 
+  context.timer_render.stop ();
   return out;
 }
 

src/commands/Command.cpp

@@ -31,7 +31,6 @@
 #include <vector>
 #include <stdlib.h>
 #include <E9.h>
-#include <Timer.h>
 #include <text.h>
 #include <i18n.h>
 #include <Command.h>
@@ -270,7 +269,7 @@ bool Command::displays_id () const
 // Filter a specific list of tasks.
 void Command::filter (std::vector <Task>& input, std::vector <Task>& output)
 {
-  Timer timer ("Command::filter");
+  context.timer_filter.start ();
 
   A3 filt = context.a3.extract_filter ();
   filt.dump ("extract_filter");
@@ -286,32 +285,38 @@ void Command::filter (std::vector <Task>& input, std::vector <Task>& output)
   }
   else
     output = input;
+
+  context.timer_filter.stop ();
 }
 
 ////////////////////////////////////////////////////////////////////////////////
 // Filter all tasks.
 void Command::filter (std::vector <Task>& output)
 {
+  context.timer_filter.start ();
   A3 filt = context.a3.extract_filter ();
   filt.dump ("extract_filter");
 
   if (filt.size ())
   {
+    context.timer_filter.stop ();
     const std::vector <Task>& pending = context.tdb2.pending.get_tasks ();
+    context.timer_filter.start ();
     E9 e (filt);
 
     output.clear ();
     std::vector <Task>::const_iterator task;
 
-    Timer timer ("Command::filter");
     for (task = pending.begin (); task != pending.end (); ++task)
       if (e.evalFilter (*task))
         output.push_back (*task);
 
     if (! filter_shortcut (filt))
     {
+      context.timer_filter.stop ();
       const std::vector <Task>& completed = context.tdb2.completed.get_tasks (); // TODO Optional
-      Timer timer ("Command::filter");
+      context.timer_filter.start ();
+
       for (task = completed.begin (); task != completed.end (); ++task)
         if (e.evalFilter (*task))
           output.push_back (*task);
@@ -321,8 +326,10 @@ void Command::filter (std::vector <Task>& output)
   }
   else
   {
+    context.timer_filter.stop ();
     const std::vector <Task>& pending   = context.tdb2.pending.get_tasks ();
     const std::vector <Task>& completed = context.tdb2.completed.get_tasks ();
+    context.timer_filter.start ();
 
     std::vector <Task>::const_iterator task;
     for (task = pending.begin (); task != pending.end (); ++task)
@@ -331,6 +338,8 @@ void Command::filter (std::vector <Task>& output)
     for (task = completed.begin (); task != completed.end (); ++task)
       output.push_back (*task);
   }
+
+  context.timer_filter.stop ();
 }
 
 ////////////////////////////////////////////////////////////////////////////////

src/sort.cpp

@@ -33,7 +33,6 @@
 #include <Context.h>
 #include <Duration.h>
 #include <Task.h>
-#include <Timer.h>
 #include <text.h>
 
 extern Context context;
@@ -48,7 +47,7 @@ void sort_tasks (
   std::vector <int>& order,
   const std::string& keys)
 {
-  Timer t ("Sort");
+  context.timer_sort.start ();
 
   global_data = &data;
 
@@ -59,6 +58,8 @@ void sort_tasks (
   // Only sort if necessary.
   if (order.size ())
     std::stable_sort (order.begin (), order.end (), sort_compare);
+
+  context.timer_sort.stop ();
 }
 
 ////////////////////////////////////////////////////////////////////////////////

test/benchmark.t

@@ -63,7 +63,7 @@ for my $i (1 .. 1000)
 diag ("1000 tasks added in " . (time () - $cursor) . " seconds");
 $cursor = time ();
 
-qx{../src/task rc:bench.rc modify /with/WITH/}  for   1 .. 200;
+qx{../src/task rc:bench.rc $_ modify /with/WITH/} for   1 .. 200;
 qx{../src/task rc:bench.rc $_ done}               for 201 .. 400;
 qx{../src/task rc:bench.rc $_ start}              for 401 .. 600;
 diag ("600 tasks altered in " . (time () - $cursor) . " seconds");