Performance

- Added Timer class to display high resolution timing information.
- Found terrible bug in Table::optimize that was taking up 99.7%,
  on average, of the Table::rendering time, including sorting.  This
  fix naturally causes a 187-fold speedup of rendering.
- Changed report.cpp in handleCustomReport to only load pending tasks,
  instead of all pending tasks.  Subtle, but important difference.
This commit is contained in:
Paul Beckingham
2009-03-08 20:49:33 -04:00
parent 4fa4c5f532
commit 0362b41f3b
11 changed files with 765 additions and 20 deletions

View File

@@ -1,2 +1,2 @@
bin_PROGRAMS = task
task_SOURCES = Config.cpp Date.cpp T.cpp TDB.cpp Table.cpp Grid.cpp color.cpp parse.cpp task.cpp command.cpp report.cpp util.cpp text.cpp rules.cpp Config.h Date.h T.h TDB.h Table.h Grid.h color.h task.h
task_SOURCES = Config.cpp Date.cpp T.cpp TDB.cpp Table.cpp Grid.cpp Timer.cpp color.cpp parse.cpp task.cpp command.cpp report.cpp util.cpp text.cpp rules.cpp Config.h Date.h T.h TDB.h Table.h Grid.h Timer.h color.h task.h

View File

@@ -44,9 +44,10 @@ am__installdirs = "$(DESTDIR)$(bindir)"
binPROGRAMS_INSTALL = $(INSTALL_PROGRAM)
PROGRAMS = $(bin_PROGRAMS)
am_task_OBJECTS = Config.$(OBJEXT) Date.$(OBJEXT) T.$(OBJEXT) \
TDB.$(OBJEXT) Table.$(OBJEXT) Grid.$(OBJEXT) color.$(OBJEXT) \
parse.$(OBJEXT) task.$(OBJEXT) command.$(OBJEXT) \
report.$(OBJEXT) util.$(OBJEXT) text.$(OBJEXT) rules.$(OBJEXT)
TDB.$(OBJEXT) Table.$(OBJEXT) Grid.$(OBJEXT) Timer.$(OBJEXT) \
color.$(OBJEXT) parse.$(OBJEXT) task.$(OBJEXT) \
command.$(OBJEXT) report.$(OBJEXT) util.$(OBJEXT) \
text.$(OBJEXT) rules.$(OBJEXT)
task_OBJECTS = $(am_task_OBJECTS)
task_LDADD = $(LDADD)
DEFAULT_INCLUDES = -I. -I$(top_builddir)@am__isrc@
@@ -154,7 +155,7 @@ sysconfdir = @sysconfdir@
target_alias = @target_alias@
top_builddir = @top_builddir@
top_srcdir = @top_srcdir@
task_SOURCES = Config.cpp Date.cpp T.cpp TDB.cpp Table.cpp Grid.cpp color.cpp parse.cpp task.cpp command.cpp report.cpp util.cpp text.cpp rules.cpp Config.h Date.h T.h TDB.h Table.h Grid.h color.h task.h
task_SOURCES = Config.cpp Date.cpp T.cpp TDB.cpp Table.cpp Grid.cpp Timer.cpp color.cpp parse.cpp task.cpp command.cpp report.cpp util.cpp text.cpp rules.cpp Config.h Date.h T.h TDB.h Table.h Grid.h Timer.h color.h task.h
all: all-am
.SUFFIXES:
@@ -227,6 +228,7 @@ distclean-compile:
@AMDEP_TRUE@@am__include@ @am__quote@./$(DEPDIR)/T.Po@am__quote@
@AMDEP_TRUE@@am__include@ @am__quote@./$(DEPDIR)/TDB.Po@am__quote@
@AMDEP_TRUE@@am__include@ @am__quote@./$(DEPDIR)/Table.Po@am__quote@
@AMDEP_TRUE@@am__include@ @am__quote@./$(DEPDIR)/Timer.Po@am__quote@
@AMDEP_TRUE@@am__include@ @am__quote@./$(DEPDIR)/color.Po@am__quote@
@AMDEP_TRUE@@am__include@ @am__quote@./$(DEPDIR)/command.Po@am__quote@
@AMDEP_TRUE@@am__include@ @am__quote@./$(DEPDIR)/parse.Po@am__quote@

View File

@@ -749,12 +749,50 @@ void Table::optimize (std::string& output)
*/
// \s\n -> \n
/*
Well, how about that!
The benchmark.t unit test adds a 1000 tasks, fiddles with some of them, then
runs a series of reports. The results are timed, and look like this:
1000 tasks added in 3 seconds
600 tasks altered in 32 seconds
'task ls' in 26 seconds
'task list' in 17 seconds
'task list pri:H' in 19 seconds
'task list +tag' in 0 seconds
'task list project_A' in 0 seconds
'task long' in 29 seconds
'task completed' in 2 seconds
'task history' in 0 seconds
'task ghistory' in 0 seconds
This performance is terrible. To identify the worst offender, Various Timer
objects were added in Table::render, assuming that table sorting is the major
bottleneck. But no, it is Table::optimize that is the problem. After
commenting out the code below, the results are now:
1000 tasks added in 3 seconds
600 tasks altered in 29 seconds
'task ls' in 0 seconds
'task list' in 0 seconds
'task list pri:H' in 1 seconds
'task list +tag' in 0 seconds
'task list project_A' in 0 seconds
'task long' in 0 seconds
'task completed' in 0 seconds
'task history' in 0 seconds
'task ghistory' in 0 seconds
Much better. Table::optimize is currently disabled.
size_t i = 0;
while ((i = output.find (" \n")) != std::string::npos)
{
output = output.substr (0, i) +
output.substr (i + 1, std::string::npos);
output.substr (i + 2, std::string::npos);
}
*/
/*
std::cout << int ((100 * (start - output.length ()) / start))

56
src/Timer.cpp Normal file
View File

@@ -0,0 +1,56 @@
////////////////////////////////////////////////////////////////////////////////
// task - a command line task list manager.
//
// Copyright 2006 - 2009, Paul Beckingham.
// All rights reserved.
//
// This program is free software; you can redistribute it and/or modify it under
// the terms of the GNU General Public License as published by the Free Software
// Foundation; either version 2 of the License, or (at your option) any later
// version.
//
// This program is distributed in the hope that it will be useful, but WITHOUT
// ANY WARRANTY; without even the implied warranty of MERCHANTABILITY or FITNESS
// FOR A PARTICULAR PURPOSE. See the GNU General Public License for more
// details.
//
// You should have received a copy of the GNU General Public License along with
// this program; if not, write to the
//
// Free Software Foundation, Inc.,
// 51 Franklin Street, Fifth Floor,
// Boston, MA
// 02110-1301
// USA
//
////////////////////////////////////////////////////////////////////////////////
#include <iostream>
#include <iomanip>
#include <Timer.h>
////////////////////////////////////////////////////////////////////////////////
// Timer starts when the object is constructed.
Timer::Timer (const std::string& description)
: mDescription (description)
{
::gettimeofday (&mStart, NULL);
}
////////////////////////////////////////////////////////////////////////////////
// Timer stops when the object is desctructed.
Timer::~Timer ()
{
struct timeval end;
::gettimeofday (&end, NULL);
std::cout << "Timer "
<< mDescription
<< " "
<< std::setprecision (6)
<< ((end.tv_sec - mStart.tv_sec) +
((end.tv_usec - mStart.tv_usec ) / 1000000.0))
<< std::endl;
}
////////////////////////////////////////////////////////////////////////////////

46
src/Timer.h Normal file
View File

@@ -0,0 +1,46 @@
////////////////////////////////////////////////////////////////////////////////
// task - a command line task list manager.
//
// Copyright 2006 - 2009, Paul Beckingham.
// All rights reserved.
//
// This program is free software; you can redistribute it and/or modify it under
// the terms of the GNU General Public License as published by the Free Software
// Foundation; either version 2 of the License, or (at your option) any later
// version.
//
// This program is distributed in the hope that it will be useful, but WITHOUT
// ANY WARRANTY; without even the implied warranty of MERCHANTABILITY or FITNESS
// FOR A PARTICULAR PURPOSE. See the GNU General Public License for more
// details.
//
// You should have received a copy of the GNU General Public License along with
// this program; if not, write to the
//
// Free Software Foundation, Inc.,
// 51 Franklin Street, Fifth Floor,
// Boston, MA
// 02110-1301
// USA
//
////////////////////////////////////////////////////////////////////////////////
#ifndef INCLUDED_TIMER
#define INCLUDED_TIMER
#include <string>
#include <sys/time.h>
class Timer
{
public:
Timer (const std::string&);
~Timer ();
private:
std::string mDescription;
struct timeval mStart;
};
#endif
////////////////////////////////////////////////////////////////////////////////

View File

@@ -2262,7 +2262,7 @@ std::string handleCustomReport (
// Load all pending tasks.
std::vector <T> tasks;
tdb.allPendingT (tasks);
tdb.pendingT (tasks);
handleRecurrence (tdb, tasks);
// Apply filters.

View File

@@ -48,6 +48,7 @@ my $description = 'This is a medium-sized description with no special characters
# Start the clock.
my $start = time ();
my $cursor = $start;
diag ("start=$start");
# Make a mess.
@@ -59,23 +60,29 @@ for my $i (1 .. 1000)
qx{../task rc:bench.rc add project:$project priority:$priority +$tag $i $description};
}
diag ("1000 tasks added");
diag ("1000 tasks added in " . (time () - $cursor) . " seconds");
$cursor = time ();
qx{../task rc:bench.rc /with/WITH/} for 1 .. 200;
qx{../task rc:bench.rc done $_} for 201 .. 400;
qx{../task rc:bench.rc start $_} for 401 .. 600;
diag ("600 tasks altered");
diag ("600 tasks altered in " . (time () - $cursor) . " seconds");
$cursor = time ();
# Report it all.
qx{../task rc:bench.rc ls};
qx{../task rc:bench.rc list};
qx{../task rc:bench.rc list priority:H};
qx{../task rc:bench.rc list +tag};
qx{../task rc:bench.rc list project_A};
qx{../task rc:bench.rc long};
qx{../task rc:bench.rc completed};
qx{../task rc:bench.rc history};
qx{../task rc:bench.rc ghistory};
# Report it all. Note that all Timer information is displayed.
for (1 .. 100)
{
diag (grep {/^Timer /} qx{../task rc:bench.rc ls});
diag (grep {/^Timer /} qx{../task rc:bench.rc list});
diag (grep {/^Timer /} qx{../task rc:bench.rc list priority:H});
diag (grep {/^Timer /} qx{../task rc:bench.rc list +tag});
diag (grep {/^Timer /} qx{../task rc:bench.rc list project_A});
diag (grep {/^Timer /} qx{../task rc:bench.rc long});
diag (grep {/^Timer /} qx{../task rc:bench.rc completed});
diag (grep {/^Timer /} qx{../task rc:bench.rc history});
diag (grep {/^Timer /} qx{../task rc:bench.rc ghistory});
}
# Stop the clock.
my $stop = time ();