Beat the timing and tracing code into shape.

main.cc

@@ -42,9 +42,9 @@ static int read_and_report(report_t * report, int argc, char * argv[],
 
   // Process the environment settings
 
-  TRACE(1, "Processing options and environment settings");
+  TRACE_START(environment, 1, "Processed environment variables");
-
   process_environment(const_cast<const char **>(envp), "LEDGER_", report);
+  TRACE_FINISH(environment, 1);
 
   const char * p = std::getenv("HOME");
   string home = p ? p : "";
@@ -68,7 +68,7 @@ static int read_and_report(report_t * report, int argc, char * argv[],
   TRACE(1, "Main journal is " << session.data_file);
 
   if (! session.use_cache)
-    INFO("The binary cache mechanism will not be used");
+    INFO("Binary cache mechanism will not be used");
 
   // Read the command word and create a command object based on it
 
@@ -168,9 +168,14 @@ static int read_and_report(report_t * report, int argc, char * argv[],
 
   session.read_init();
 
-  std::cout << "Reading journal ..." << std::endl;
+  INFO_START(journal, "Read journal file");
   journal_t * journal = session.read_data(report->account);
-  std::cout << "Generating report ..." << std::endl;
+  INFO_FINISH(journal);
+
+  TRACE_FINISH(entry_date, 2);
+  TRACE_FINISH(entry_details, 2);
+  TRACE_FINISH(entry_xacts, 2);
+  TRACE_FINISH(parsing_total, 2);
 
   // Configure the output stream
 
@@ -323,16 +328,20 @@ static int read_and_report(report_t * report, int argc, char * argv[],
 #endif
   }
 
+  INFO_START(transforms, "Applied transforms");
   report->apply_transforms(journal->document);
+  INFO_FINISH(transforms);
 
+  INFO_START(command, "Did user command '" << verb << "'");
   value_t temp;
   (*command)(temp, locals.get());
+  INFO_FINISH(command);
 
   // Write out the binary cache, if need be
 
   if (session.use_cache && session.cache_dirty &&
       ! session.cache_file.empty()) {
-    TRACE_START(binary_cache, 1, "Writing journal file");
+    TRACE_START(binary_cache, 1, "Wrote binary journal file");
 
     std::ofstream stream(session.cache_file.c_str());
 #if 0
@@ -345,12 +354,8 @@ static int read_and_report(report_t * report, int argc, char * argv[],
 #if defined(FREE_MEMORY)
   // Cleanup memory -- if this is a beta or development build.
 
-  TRACE_START(cleanup, 1, "Cleaning up allocated memory");
-
   if (! report->output_file.empty())
     delete out;
-
-  TRACE_STOP(cleanup, 1);
 #endif
 
   // If the user specified a pager, wait for it to exit now
@@ -374,12 +379,8 @@ int main(int argc, char * argv[], char * envp[])
 {
   int status = 1;
 
-#if defined(FULL_DEBUG)
-  ledger::verify_enabled = true;
-#endif
-
   for (int i = 1; i < argc; i++)
-    if (argv[i][0] == '-' && argv[i][1] == '-') {
+    if (argv[i][0] == '-') {
 #if defined(VERIFY_ON)
       if (std::strcmp(argv[i], "--verify") == 0)
 	ledger::verify_enabled = true;

session.cc

@@ -216,7 +216,7 @@ void shutdown()
   amount_t::shutdown();
 
   IF_VERIFY() {
-    TRACE(1, "Shutting down memory trace");
+    INFO("Ledger shutdown (Boost and libstdc++ may hold memory)");
     shutdown_memory_tracing();
   }
 }

session.h

@@ -165,6 +165,7 @@ class session_t : public xml::xpath_t::scope_t
   void option_debug(value_t&, xml::xpath_t::scope_t * locals) {}
 
   void option_verbose(value_t&) {
+    if (_log_level < LOG_INFO)
       _log_level = LOG_INFO;
   }
 

textual.cc

@@ -412,7 +412,7 @@ entry_t * parse_entry(std::istream& in, char * line, journal_t * journal,
 
   // Parse the date
 
-  TRACE_START(entry_date, 2, "Parsing entry date");
+  TRACE_START(entry_date, 2, "Time spent parsing entry dates:");
 
   curr->_date = parse_datetime(date);
 
@@ -423,7 +423,7 @@ entry_t * parse_entry(std::istream& in, char * line, journal_t * journal,
 
   // Parse the optional cleared flag: *
 
-  TRACE_START(entry_details, 2, "Parsing entry details");
+  TRACE_START(entry_details, 2, "Time spent parsing entry details:");
 
   transaction_t::state_t state = transaction_t::UNCLEARED;
   if (statep) {
@@ -451,7 +451,7 @@ entry_t * parse_entry(std::istream& in, char * line, journal_t * journal,
 
   // Parse all of the transactions associated with this entry
 
-  TRACE_START(entry_xacts, 2, "Parsing entry transactions");
+  TRACE_START(entry_xacts, 2, "Time spent parsing transactions:");
 
   unsigned long end_pos;
   unsigned long beg_line = linenum;
@@ -620,7 +620,7 @@ unsigned int textual_parser_t::parse(std::istream&	 in,
   unsigned int count  = 0;
   unsigned int errors = 0;
 
-  TRACE_START(parsing_total, 2, "Parsing textual file");
+  TRACE_START(parsing_total, 2, "Total time spent parsing text:");
 
   std::list<account_t *> account_stack;
 

utils.cc

@@ -33,11 +33,7 @@ void debug_assert(const string& reason,
 
 namespace ledger {
 
-#if defined(FULL_DEBUG)
-bool verify_enabled = true;
-#else
 bool verify_enabled = false;
-#endif
 
 typedef std::pair<std::string, std::size_t>     allocation_pair;
 typedef std::map<void *, allocation_pair>       live_memory_map;
@@ -79,11 +75,15 @@ void shutdown_memory_tracing()
 {
   memory_tracing_active = false;
 
+  if (live_objects) {
     IF_DEBUG_("memory.counts")
       report_memory(std::cerr, true);
     else
       IF_DEBUG_("memory.counts.live")
 	report_memory(std::cerr);
+    else if (live_objects->size() > 0)
+      report_memory(std::cerr);
+  }
 
   delete live_memory;        live_memory	= NULL;
   delete live_memory_count;  live_memory_count	= NULL;
@@ -431,9 +431,7 @@ bool logger_func(log_level_t level)
   if (! logger_has_run) {
     logger_has_run = true;
     IF_VERIFY()
-      *_log_stream << "  TIME  OBJSZ  MEMSZ  LEVEL  MESSAGE" << std::endl;
+      *_log_stream << "  TIME  OBJSZ  MEMSZ" << std::endl;
-    else
-      *_log_stream << "  TIME  LEVEL  MESSAGE" << std::endl;
   }
 
   *_log_stream << std::right << std::setw(6)
@@ -469,6 +467,8 @@ bool logger_func(log_level_t level)
   *_log_stream << ' ' << _log_buffer.str() << std::endl;
 
   _log_buffer.str("");
+
+  return true;
 }
 
 } // namespace ledger
@@ -484,26 +484,86 @@ bool logger_func(log_level_t level)
 
 namespace ledger {
 
-void start_timer(const char * name)
+struct timer_t {
+  log_level_t  level;
+  std::clock_t begin;
+  std::clock_t spent;
+  std::string  description;
+  bool	       active;
+
+  timer_t(log_level_t _level, std::string _description)
+    : level(_level), begin(std::clock()), spent(0),
+      description(_description), active(true) {}
+};
+
+typedef std::map<std::string, timer_t>  timer_map;
+typedef std::pair<std::string, timer_t> timer_pair;
+
+static timer_map timers;
+
+void start_timer(const char * name, log_level_t lvl)
 {
-#if 0
+#if defined(VERIFY_ON)
-  begin = std::clock();
+  memory_tracing_active = false;
+#endif
+
+  timer_map::iterator i = timers.find(name);
+  if (i == timers.end()) {
+    timers.insert(timer_pair(name, timer_t(lvl, _log_buffer.str())));
+  } else {
+    assert((*i).second.description == _log_buffer.str());
+    (*i).second.begin  = std::clock();
+    (*i).second.active = true;
+  }
+  _log_buffer.str("");
+
+#if defined(VERIFY_ON)
+  memory_tracing_active = true;
 #endif
 }
 
 void stop_timer(const char * name)
 {
-#if 0
+#if defined(VERIFY_ON)
-  cumulative += std::clock() - begin;
+  memory_tracing_active = false;
+#endif
+
+  timer_map::iterator i = timers.find(name);
+  assert(i != timers.end());
+
+  (*i).second.spent += std::clock() - (*i).second.begin;
+  (*i).second.active = false;
+
+#if defined(VERIFY_ON)
+  memory_tracing_active = true;
 #endif
 }
 
 void finish_timer(const char * name)
 {
-#if 0
+#if defined(VERIFY_ON)
-  DEBUG_(cls.c_str(), file << ":" << line << ": "
+  memory_tracing_active = false;
-	 << category << " = "
+#endif
-	 << (double(cumulative) / double(CLOCKS_PER_SEC)) << "s");
+
+  timer_map::iterator i = timers.find(name);
+  if (i == timers.end())
+    return;
+
+  std::clock_t spent = (*i).second.spent;
+  if ((*i).second.active) {
+    spent = std::clock() - (*i).second.begin;
+    (*i).second.active = false;
+  }
+
+  _log_buffer << (*i).second.description << " ("
+	      << (double(spent) / double(CLOCKS_PER_SEC)) << "s"
+	      << ')';
+  logger_func((*i).second.level);
+
+  timers.erase(i);
+
+#if defined(VERIFY_ON)
+  memory_tracing_active = true;
 #endif
 }
 

utils.h

@@ -298,21 +298,14 @@ inline bool category_matches(const char * cat) {
 
 namespace ledger {
 
-struct timer_t {
+void start_timer(const char * name, log_level_t lvl);
-  std::clock_t count;
-  std::string  message;
-};
-
-typedef std::map<std::string, timer_t> timing_map;
-typedef timing_map::value_type         timing_pair;
-
-void start_timer(const char * name);
 void stop_timer(const char * name);
 void finish_timer(const char * name);
 
 #if defined(TRACING_ON)
 #define TRACE_START(name, lvl, msg)					\
-  (TRACE(lvl, msg) ? start_timer(#name) : ((void)0))
+  (SHOW_TRACE(lvl) ?							\
+   ((_log_buffer << msg), start_timer(#name, LOG_TRACE)) : ((void)0))
 #define TRACE_STOP(name, lvl) \
   (SHOW_TRACE(lvl) ? stop_timer(#name) : ((void)0))
 #define TRACE_FINISH(name, lvl) \
@@ -325,7 +318,8 @@ void finish_timer(const char * name);
 
 #if defined(DEBUG_ON)
 #define DEBUG_START_(name, cat, msg)					\
-  (DEBUG_(cat, msg) ? start_timer(#name) : ((void)0))
+  (SHOW_DEBUG_(cat) ?							\
+   ((_log_buffer << msg), start_timer(#name, LOG_DEBUG)) : ((void)0))
 #define DEBUG_START(name, msg) \
   DEBUG_START_(name, _this_category, msg)
 #define DEBUG_STOP_(name, cat) \
@@ -344,7 +338,8 @@ void finish_timer(const char * name);
 #endif
 
 #define INFO_START(name, msg)						\
-  (INFO(msg) && start_timer(#name))
+  (SHOW_INFO() ?							\
+   ((_log_buffer << msg), start_timer(#name, LOG_INFO)) : ((void)0))
 #define INFO_STOP(name) \
   (SHOW_INFO() ? stop_timer(#name) : ((void)0))
 #define INFO_FINISH(name) \
@@ -364,7 +359,6 @@ void finish_timer(const char * name);
 #define DEBUG_FINISH(name)
 
 #define INFO_START(name, msg)
-#define INFO_START_(name, cat, msg)
 #define INFO_STOP(name)
 #define INFO_FINISH(name)