added timing debug code

3 files changed, 90 insertions, 7 deletions

diff --git a/main.cc b/main.cc
index 17008cae..c08b71b1 100644
--- a/main.cc
+++ b/main.cc
@@ -427,6 +427,14 @@ OPT_BEGIN(weighted_trend, "Z", false) {
 } OPT_END(weighted_trend);
 
 
+TIMER_DEF(write_cache,	  "writing cache file");
+TIMER_DEF(report_gen,	  "generation of final report");
+TIMER_DEF(handle_options, "configuring based on options");
+TIMER_DEF(parse_files,	  "parsing ledger files");
+TIMER_DEF(process_env,	  "processing environment");
+TIMER_DEF(process_args,   "processing command-line arguments");
+TIMER_DEF(read_cache,	  "reading cache file");
+
 int main(int argc, char * argv[], char * envp[])
 {
 #ifdef DEBUG_ENABLED
@@ -438,7 +446,7 @@ int main(int argc, char * argv[], char * envp[])
 
   // A ledger data file must be specified
 
-  TIMER_START(read_cache, "reading cache file");
+  TIMER_START(read_cache);
 
   // jww (2004-08-13): use LEDGER_FILE
   use_cache = std::getenv("LEDGER") != NULL;
@@ -474,7 +482,7 @@ int main(int argc, char * argv[], char * envp[])
 
   // Parse the command-line options
 
-  TIMER_START(process_args, "processing command-line arguments");
+  TIMER_START(process_args);
 
   std::list<std::string> args;
 
@@ -490,7 +498,7 @@ int main(int argc, char * argv[], char * envp[])
 
   // Process options from the environment
 
-  TIMER_START(process_env, "processing environment");
+  TIMER_START(process_env);
 
   process_environment(envp, "LEDGER_");
 
@@ -503,7 +511,7 @@ int main(int argc, char * argv[], char * envp[])
 
   // Read the ledger file, unless we already read it from the cache
 
-  TIMER_START(parse_files, "parsing ledger files");
+  TIMER_START(parse_files);
 
   if (! use_cache || cache_dirty) {
     int entry_count = 0;
@@ -552,7 +560,7 @@ int main(int argc, char * argv[], char * envp[])
 
   std::string command = *arg++;
 
-  TIMER_START(handle_options, "configuring based on options");
+  TIMER_START(handle_options);
 
   if (command == "balance" || command == "bal" || command == "b")
     command = "b";
@@ -708,7 +716,7 @@ int main(int argc, char * argv[], char * envp[])
 
   // Walk the entries based on the report type and the options
 
-  TIMER_START(report_gen, "generation of final report");
+  TIMER_START(report_gen);
 
   if (command == "b") {
     std::auto_ptr<item_handler<transaction_t> > formatter;
@@ -834,7 +842,7 @@ int main(int argc, char * argv[], char * envp[])
 
   // Save the cache, if need be
 
-  TIMER_START(write_cache, "writing cache file");
+  TIMER_START(write_cache);
 
   if (use_cache && cache_dirty) {
     std::string cache_file = ledger_cache_file();
diff --git a/textual.cc b/textual.cc
index 9b252248..07fb428d 100644
--- a/textual.cc
+++ b/textual.cc
@@ -3,6 +3,7 @@
 #include "valexpr.h"
 #include "error.h"
 #include "option.h"
+#include "timing.h"
 
 #include <fstream>
 #include <sstream>
@@ -222,6 +223,11 @@ bool finalize_entry(entry_t * entry)
   return ! balance;
 }
 
+TIMER_DEF(entry_finish,  "finalizing entry");
+TIMER_DEF(entry_xacts,   "parsing transactions");
+TIMER_DEF(entry_details, "parsing entry details");
+TIMER_DEF(entry_date,    "parsing entry date");
+
 entry_t * parse_entry(std::istream& in, account_t * master)
 {
   entry_t * curr = new entry_t;
@@ -232,13 +238,19 @@ entry_t * parse_entry(std::istream& in, account_t * master)
 
   // Parse the date
 
+  TIMER_START(entry_date);
+
   char * next = next_element(line);
 
   if (! quick_parse_date(line, &curr->date))
     throw parse_error(path, linenum, "Failed to parse date");
 
+  TIMER_STOP(entry_date);
+
   // Parse the optional cleared flag: *
 
+  TIMER_START(entry_details);
+
   if (*next == '*') {
     curr->state = entry_t::CLEARED;
     next = skip_ws(++next);
@@ -258,19 +270,29 @@ entry_t * parse_entry(std::istream& in, account_t * master)
 
   curr->payee = next;
 
+  TIMER_STOP(entry_details);
+
   // Parse all of the transactions associated with this entry
 
+  TIMER_START(entry_xacts);
+
   while (! in.eof() && (in.peek() == ' ' || in.peek() == '\t'))
     if (transaction_t * xact = parse_transaction(in, master, curr))
       curr->add_transaction(xact);
 
+  TIMER_STOP(entry_xacts);
+
   // If there were no transactions, throw away the entry
 
+  TIMER_START(entry_finish);
+
   if (curr->transactions.empty() || ! finalize_entry(curr)) {
     delete curr;
     return NULL;
   }
 
+  TIMER_STOP(entry_finish);
+
   return curr;
 }
 
diff --git a/timing.h b/timing.h
new file mode 100644
index 00000000..bb36d99d
--- /dev/null
+++ b/timing.h
@@ -0,0 +1,53 @@
+#ifndef _TIMING_H
+#define _TIMING_H
+
+#include "debug.h"
+
+#include <ctime>
+
+namespace ledger {
+
+class timing_t
+{
+ public:
+  std::clock_t	begin;
+  std::clock_t	cumulative;
+  std::string	file;
+  unsigned long line;
+  std::string	symbol;
+  std::string	category;
+
+  timing_t(const std::string& _symbol, const std::string& _category)
+    : begin(0), cumulative(0), symbol(_symbol), category(_category) {}
+
+  ~timing_t() {
+    std::string cls = "timing.results.";
+    cls += symbol;
+    DEBUG_PRINT(cls.c_str(), file << ":" << line << ": "
+		<< category << " = "
+		<< (double(cumulative) / double(CLOCKS_PER_SEC)) << "s");
+  }
+
+  void start(const std::string& _file, unsigned long _line) {
+    file  = _file;
+    line  = _line;
+    begin = std::clock();
+  }
+
+  void stop() {
+    cumulative += std::clock() - begin;
+  }
+};
+
+#ifdef DEBUG_ENABLED
+#define TIMER_DEF(sym, cat) static timing_t sym(#sym, cat)
+#define TIMER_START(sym) sym.start(__FILE__, __LINE__)
+#define TIMER_STOP(sym) sym.stop()
+#else
+#define TIMER_START(sym, cat)
+#define TIMER_STOP(sym)
+#endif
+
+} // namespace ledger
+
+#endif // _TIMING_H