From ac9d1f3bfad85ef32d01503d4490fcc1fc539c3f Mon Sep 17 00:00:00 2001 From: Paul Beckingham Date: Mon, 15 Aug 2011 21:53:01 -0400 Subject: [PATCH] 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 | 44 ++++++++++++++++++++++++++---- src/Context.h | 10 +++++++ src/TDB.cpp | 15 ++++++----- src/TDB2.cpp | 58 +++++++++++++++++++++++++++------------- src/TDB2.h | 1 + src/Timer.cpp | 56 +++++++++++++++++++++++++++++++------- src/Timer.h | 11 ++++++-- src/ViewTask.cpp | 12 ++++++++- src/commands/Command.cpp | 17 +++++++++--- src/sort.cpp | 5 ++-- test/benchmark.t | 6 ++--- 11 files changed, 182 insertions(+), 53 deletions(-) diff --git a/src/Context.cpp b/src/Context.cpp index 2d36823c8..1380e7b35 100644 --- a/src/Context.cpp +++ b/src/Context.cpp @@ -27,6 +27,7 @@ #include #include +#include #include #include #include @@ -35,12 +36,14 @@ #include #include #include -#include #include #include #include #include -#include <../cmake.h> +#include +#ifdef HAVE_COMMIT +#include +#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)) diff --git a/src/Context.h b/src/Context.h index 46bbb8831..698582f49 100644 --- a/src/Context.h +++ b/src/Context.h @@ -40,6 +40,7 @@ #include #include #include +#include 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 diff --git a/src/TDB.cpp b/src/TDB.cpp index fe2ee39f4..81d8ad9f0 100644 --- a/src/TDB.cpp +++ b/src/TDB.cpp @@ -41,7 +41,6 @@ #include #include #include -#include #include #include @@ -275,8 +274,6 @@ int TDB::load (std::vector & tasks) // multiple files. int TDB::loadPending (std::vector & tasks) { - Timer t ("TDB::loadPending"); - std::string file; int line_number = 1; @@ -346,8 +343,6 @@ int TDB::loadPending (std::vector & tasks) // multiple files. int TDB::loadCompleted (std::vector & 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; } diff --git a/src/TDB2.cpp b/src/TDB2.cpp index d9c2942c8..48a418705 100644 --- a/src/TDB2.cpp +++ b/src/TDB2.cpp @@ -27,7 +27,6 @@ //#include // TODO Remove. #include -#include #include #include @@ -62,7 +61,6 @@ void TF2::target (const std::string& f) const std::vector & 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,28 +443,34 @@ 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 + pending.load_tasks + completed.load_tasks - for each pending - if status == completed || status == deleted - pending.remove - completed.add - if status == waiting && wait < now - status = pending - wait.clear + for each pending + if status == completed || status == deleted + pending.remove + completed.add + if status == waiting && wait < now + status = pending + wait.clear - for each completed - if status == pending || status == waiting - completed.remove - pending.add + for each completed + if status == pending || status == waiting + completed.remove + pending.add */ - // TODO Remove dangling dependencies - // TODO Wake up expired waiting tasks + // TODO Remove dangling dependencies + // TODO Wake up expired waiting tasks + } + context.timer_gc.stop (); return 0; } diff --git a/src/TDB2.h b/src/TDB2.h index e8aa43402..967ca6f43 100644 --- a/src/TDB2.h +++ b/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 (); diff --git a/src/Timer.cpp b/src/Timer.cpp index 224bb1e0c..475c3f384 100644 --- a/src/Timer.cpp +++ b/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; +} + +//////////////////////////////////////////////////////////////////////////////// diff --git a/src/Timer.h b/src/Timer.h index 8f0badbfa..b8f12b6f6 100644 --- a/src/Timer.h +++ b/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 diff --git a/src/ViewTask.cpp b/src/ViewTask.cpp index 8229cabb8..d59f5c15f 100644 --- a/src/ViewTask.cpp +++ b/src/ViewTask.cpp @@ -101,7 +101,7 @@ ViewTask::ViewTask () // std::string ViewTask::render (std::vector & data, std::vector & sequence) { - Timer timer ("ViewTask::render"); + context.timer_render.start (); // Determine minimal, ideal column widths. std::vector minimal; @@ -228,7 +228,10 @@ std::string ViewTask::render (std::vector & data, std::vector & 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. @@ -289,16 +292,23 @@ std::string ViewTask::render (std::vector & data, std::vector & 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; } diff --git a/src/commands/Command.cpp b/src/commands/Command.cpp index d3c247865..279204901 100644 --- a/src/commands/Command.cpp +++ b/src/commands/Command.cpp @@ -31,7 +31,6 @@ #include #include #include -#include #include #include #include @@ -270,7 +269,7 @@ bool Command::displays_id () const // Filter a specific list of tasks. void Command::filter (std::vector & input, std::vector & 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 & input, std::vector & output) } else output = input; + + context.timer_filter.stop (); } //////////////////////////////////////////////////////////////////////////////// // Filter all tasks. void Command::filter (std::vector & 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 & pending = context.tdb2.pending.get_tasks (); + context.timer_filter.start (); E9 e (filt); output.clear (); std::vector ::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 & 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 & output) } else { + context.timer_filter.stop (); const std::vector & pending = context.tdb2.pending.get_tasks (); const std::vector & completed = context.tdb2.completed.get_tasks (); + context.timer_filter.start (); std::vector ::const_iterator task; for (task = pending.begin (); task != pending.end (); ++task) @@ -331,6 +338,8 @@ void Command::filter (std::vector & output) for (task = completed.begin (); task != completed.end (); ++task) output.push_back (*task); } + + context.timer_filter.stop (); } //////////////////////////////////////////////////////////////////////////////// diff --git a/src/sort.cpp b/src/sort.cpp index 4277584f7..dbeee35ca 100644 --- a/src/sort.cpp +++ b/src/sort.cpp @@ -33,7 +33,6 @@ #include #include #include -#include #include extern Context context; @@ -48,7 +47,7 @@ void sort_tasks ( std::vector & 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 (); } //////////////////////////////////////////////////////////////////////////////// diff --git a/test/benchmark.t b/test/benchmark.t index 837bf903f..7a3065ff6 100755 --- a/test/benchmark.t +++ b/test/benchmark.t @@ -63,9 +63,9 @@ 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 $_ done} for 201 .. 400; -qx{../src/task rc:bench.rc $_ start} for 401 .. 600; +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"); $cursor = time ();