diff options
| -rw-r--r-- | main.cc | 31 | ||||
| -rw-r--r-- | session.cc | 2 | ||||
| -rw-r--r-- | session.h | 3 | ||||
| -rw-r--r-- | textual.cc | 8 | ||||
| -rw-r--r-- | utils.cc | 100 | ||||
| -rw-r--r-- | utils.h | 26 |
6 files changed, 113 insertions, 57 deletions
@@ -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; @@ -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(); } } @@ -165,7 +165,8 @@ 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&) { - _log_level = LOG_INFO; + if (_log_level < LOG_INFO) + _log_level = LOG_INFO; } // @@ -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; @@ -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_DEBUG_("memory.counts") - report_memory(std::cerr, true); - else - IF_DEBUG_("memory.counts.live") + 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; - else - *_log_stream << " TIME LEVEL MESSAGE" << std::endl; + *_log_stream << " TIME OBJSZ MEMSZ" << 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 - begin = std::clock(); +#if defined(VERIFY_ON) + 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 - cumulative += std::clock() - begin; +#if defined(VERIFY_ON) + 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 - DEBUG_(cls.c_str(), file << ":" << line << ": " - << category << " = " - << (double(cumulative) / double(CLOCKS_PER_SEC)) << "s"); +#if defined(VERIFY_ON) + memory_tracing_active = false; +#endif + + 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 } @@ -298,21 +298,14 @@ inline bool category_matches(const char * cat) { namespace ledger { -struct timer_t { - 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 start_timer(const char * name, log_level_t lvl); 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)) +#define TRACE_START(name, lvl, msg) \ + (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) \ @@ -324,8 +317,9 @@ void finish_timer(const char * name); #endif #if defined(DEBUG_ON) -#define DEBUG_START_(name, cat, msg) \ - (DEBUG_(cat, msg) ? start_timer(#name) : ((void)0)) +#define DEBUG_START_(name, cat, msg) \ + (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) \ @@ -343,8 +337,9 @@ void finish_timer(const char * name); #define DEBUG_FINISH(name) #endif -#define INFO_START(name, msg) \ - (INFO(msg) && start_timer(#name)) +#define INFO_START(name, msg) \ + (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) |