diff --git a/NEWS b/NEWS index 8cb302c9e..446769524 100644 --- a/NEWS +++ b/NEWS @@ -6,6 +6,12 @@ New in spot 2.1.2.dev (not yet released) LTL over finite words) model checking to LTL model checking. This is based on a transformation by De Giacomo & Vardi (IJCAI'13). + * autfilt, dstar2tgba, ltl2tgba, ltlcross, ltldo learned to time any + task in a more precise way thanks to %R, %[LETTER]R option. User time, + system time or children processing time or ... (see --help) can be + measured separately. A typical use-case is to exclude time spent + inside ltldo by keeping only time spent in each executed tool. + Library: * from_ltlf() is a new function implementing the --from-ltlf diff --git a/bin/autfilt.cc b/bin/autfilt.cc index 848f9f189..4abab6196 100644 --- a/bin/autfilt.cc +++ b/bin/autfilt.cc @@ -963,8 +963,8 @@ namespace process_automaton(const spot::const_parsed_aut_ptr& haut, const char* filename) { - spot::stopwatch sw; - sw.start(); + process_timer timer; + timer.start(); // If --stats or --name is used, duplicate the automaton so we // never modify the original automaton (e.g. with @@ -1183,8 +1183,7 @@ namespace run->project(aut)->highlight(word_aut.second); } - const double conversion_time = sw.stop(); - + timer.stop(); if (opt->uniq) { auto tmp = @@ -1197,8 +1196,7 @@ namespace ++match_count; - printer.print(aut, nullptr, filename, -1, conversion_time, haut, - prefix, suffix); + printer.print(aut, timer, nullptr, filename, -1, haut, prefix, suffix); if (opt_max_count >= 0 && match_count >= opt_max_count) abort_run = true; diff --git a/bin/common_aoutput.cc b/bin/common_aoutput.cc index d2c37b15e..db3f4363a 100644 --- a/bin/common_aoutput.cc +++ b/bin/common_aoutput.cc @@ -20,20 +20,19 @@ #include "common_sys.hh" #include "error.h" #include "argmatch.h" - #include "common_aoutput.hh" #include "common_post.hh" #include "common_cout.hh" +#include #include - #include -#include #include -#include -#include #include +#include +#include #include +#include automaton_format_t automaton_format = Hoa; static const char* automaton_format_opt = nullptr; @@ -173,6 +172,11 @@ static const argp_option io_options[] = "using the following LETTERS, possibly concatenated: (a) accepting, " "(r) rejecting, (v) trivial, (t) terminal, (w) weak, " "(iw) inherently weak. Use uppercase letters to negate them.", 0 }, + { "%R, %[LETTERS]R", 0, nullptr, + OPTION_DOC | OPTION_NO_USAGE, + "CPU time (excluding parsing), in seconds; Add LETTERS to restrict to" + "(u) user time, (s) system time or to omit (p) parent processes, " + "(c) children processes.", 0 }, { "%N, %n", 0, nullptr, OPTION_DOC | OPTION_NO_USAGE, "number of nondeterministic states", 0 }, { "%D, %d", 0, nullptr, OPTION_DOC | OPTION_NO_USAGE, @@ -180,7 +184,7 @@ static const argp_option io_options[] = { "%P, %p", 0, nullptr, OPTION_DOC | OPTION_NO_USAGE, "1 if the automaton is complete, 0 otherwise", 0 }, { "%r", 0, nullptr, OPTION_DOC | OPTION_NO_USAGE, - "processing time (excluding parsing) in seconds", 0 }, + "wall-clock time elapsed in seconds (excluding parsing)", 0 }, { "%W, %w", 0, nullptr, OPTION_DOC | OPTION_NO_USAGE, "one word accepted by the automaton", 0 }, { "%%", 0, nullptr, OPTION_DOC | OPTION_NO_USAGE, @@ -225,6 +229,11 @@ static const argp_option o_options[] = "using the following LETTERS, possibly concatenated: (a) accepting, " "(r) rejecting, (v) trivial, (t) terminal, (w) weak, " "(iw) inherently weak. Use uppercase letters to negate them.", 0 }, + { "%R, %[LETTERS]R", 0, nullptr, + OPTION_DOC | OPTION_NO_USAGE, + "CPU time (excluding parsing), in seconds; Add LETTERS to restrict to" + "(u) user time, (s) system time or to omit (p) parent processes, " + "(c) children processes.", 0 }, { "%n", 0, nullptr, OPTION_DOC | OPTION_NO_USAGE, "number of nondeterministic states in output", 0 }, { "%d", 0, nullptr, OPTION_DOC | OPTION_NO_USAGE, @@ -232,7 +241,7 @@ static const argp_option o_options[] = { "%p", 0, nullptr, OPTION_DOC | OPTION_NO_USAGE, "1 if the output is complete, 0 otherwise", 0 }, { "%r", 0, nullptr, OPTION_DOC | OPTION_NO_USAGE, - "processing time (excluding parsing) in seconds", 0 }, + "wall-clock time elapsed in seconds (excluding parsing)", 0 }, { "%w", 0, nullptr, OPTION_DOC | OPTION_NO_USAGE, "one word accepted by the output automaton", 0 }, { "%%", 0, nullptr, OPTION_DOC | OPTION_NO_USAGE, @@ -351,6 +360,7 @@ hoa_stat_printer::hoa_stat_printer(std::ostream& os, const char* format, declare('>', &csv_suffix_); declare('F', &filename_); declare('L', &location_); + declare('R', &timer_); if (input != ltl_input) declare('f', &filename_); // Override the formula printer. declare('h', &output_aut_); @@ -362,9 +372,12 @@ std::ostream& hoa_stat_printer::print(const spot::const_parsed_aut_ptr& haut, const spot::const_twa_graph_ptr& aut, spot::formula f, - const char* filename, int loc, double run_time, + const char* filename, int loc, process_timer& ptimer, const char* csv_prefix, const char* csv_suffix) { + timer_ = ptimer.dt; + double run_time = ptimer.get_lap_sw(); + filename_ = filename ? filename : ""; csv_prefix_ = csv_prefix ? csv_prefix : ""; csv_suffix_ = csv_suffix ? csv_suffix : ""; @@ -494,12 +507,13 @@ automaton_printer::automaton_printer(stat_style input) void automaton_printer::print(const spot::twa_graph_ptr& aut, + // Time for statistics + process_timer& ptimer, spot::formula f, // Input location for errors and statistics. const char* filename, int loc, - // Time and input automaton for statistics - double time, + // input automaton for statistics const spot::const_parsed_aut_ptr& haut, const char* csv_prefix, const char* csv_suffix) @@ -518,7 +532,7 @@ automaton_printer::print(const spot::twa_graph_ptr& aut, if (opt_name) { name.str(""); - namer.print(haut, aut, f, filename, loc, time, csv_prefix, csv_suffix); + namer.print(haut, aut, f, filename, loc, ptimer, csv_prefix, csv_suffix); aut->set_named_prop("automaton-name", new std::string(name.str())); } @@ -526,7 +540,7 @@ automaton_printer::print(const spot::twa_graph_ptr& aut, if (opt_output) { outputname.str(""); - outputnamer.print(haut, aut, f, filename, loc, time, + outputnamer.print(haut, aut, f, filename, loc, ptimer, csv_prefix, csv_suffix); std::string fname = outputname.str(); auto p = outputfiles.emplace(fname, nullptr); @@ -556,7 +570,7 @@ automaton_printer::print(const spot::twa_graph_ptr& aut, break; case Stats: statistics.set_output(*out); - statistics.print(haut, aut, f, filename, loc, time, + statistics.print(haut, aut, f, filename, loc, ptimer, csv_prefix, csv_suffix) << '\n'; break; } @@ -590,3 +604,70 @@ void printable_automaton::print(std::ostream& os, const char* pos) const } print_hoa(os, val_, options.c_str()); } + +void printable_timer::print(std::ostream& os, const char* pos) const +{ + double res = 0; + + if (*pos != '[') + { + res = val_.get_uscp(true, true, true, true); + os << res / sysconf(_SC_CLK_TCK); + return; + } + + bool user = false; + bool system = false; + bool parent = false; + bool children = false; + + const char* beg = pos; + auto error = [&](std::string str) + { + std::ostringstream tmp; + const char* end = std::strchr(pos, ']'); + tmp << "unknown option '" << str << "' in '%" << std::string(beg, end + 2) + << '\''; + throw std::runtime_error(tmp.str()); + }; + + do + { + ++pos; + switch (*pos) + { + case 'u': + user = true; + break; + case 's': + system = true; + break; + case 'p': + parent = true; + break; + case 'c': + children = true; + break; + case ' ': + case '\t': + case '\n': + case ',': + case ']': + break; + default: + error(std::string(pos, pos + 1)); + } + } while (*pos != ']'); + + if (user && !parent && !children) + parent = children = true; + if (system && !parent && !children) + parent = children = true; + if (parent && !user && !system) + user = system = true; + if (children && !user && !system) + user = system = true; + + res = val_.get_uscp(user, system, children, parent); + os << res / sysconf(_SC_CLK_TCK); +} diff --git a/bin/common_aoutput.hh b/bin/common_aoutput.hh index 008fc9c09..9a10b0745 100644 --- a/bin/common_aoutput.hh +++ b/bin/common_aoutput.hh @@ -20,18 +20,17 @@ #pragma once #include "common_sys.hh" +#include "common_file.hh" #include #include - +#include #include - -#include -#include #include -#include #include -#include "common_file.hh" +#include +#include +#include // Format for automaton output @@ -74,6 +73,40 @@ struct printable_automaton final: void print(std::ostream& os, const char* pos) const override; }; + +struct process_timer +{ + void start() + { + sw.start(); + dt.start(); + } + + void stop() + { + // sw.stop() --> It always returns the duration since the last call to + // start(). Therefore, it wont't stop timing, moreover, it can be called + // multiple times. + sw_lap_ = sw.stop(); + dt.stop(); + } + double get_lap_sw() + { + return sw_lap_; + } + + spot::timer dt; + spot::stopwatch sw; + double sw_lap_ = 0; +}; + +struct printable_timer final: + public spot::printable_value +{ + using spot::printable_value::operator=; + void print(std::ostream& os, const char* pos) const override; +}; + /// \brief prints various statistics about a TGBA /// /// This object can be configured to display various statistics @@ -83,7 +116,7 @@ class hoa_stat_printer: protected spot::stat_printer { public: hoa_stat_printer(std::ostream& os, const char* format, - stat_style input = no_input); + stat_style input = no_input); using spot::formater::declare; using spot::formater::set_output; @@ -93,10 +126,10 @@ public: /// The \a f argument is not needed if the Formula does not need /// to be output. std::ostream& - print(const spot::const_parsed_aut_ptr& haut, + print(const spot::const_parsed_aut_ptr& haut, const spot::const_twa_graph_ptr& aut, spot::formula f, - const char* filename, int loc, double run_time, + const char* filename, int loc, process_timer& ptimer, const char* csv_prefix, const char* csv_suffix); private: @@ -117,6 +150,7 @@ private: spot::printable_value haut_complete_; spot::printable_value csv_prefix_; spot::printable_value csv_suffix_; + printable_timer timer_; printable_automaton input_aut_; printable_automaton output_aut_; }; @@ -132,18 +166,17 @@ class automaton_printer std::map> outputfiles; public: - automaton_printer(stat_style input = no_input); ~automaton_printer(); void print(const spot::twa_graph_ptr& aut, + process_timer& ptimer, spot::formula f = nullptr, // Input location for errors and statistics. const char* filename = nullptr, int loc = -1, // Time and input automaton for statistics - double time = 0.0, const spot::const_parsed_aut_ptr& haut = nullptr, const char* csv_prefix = nullptr, const char* csv_suffix = nullptr); diff --git a/bin/dstar2tgba.cc b/bin/dstar2tgba.cc index 7df42b64b..505e6b303 100644 --- a/bin/dstar2tgba.cc +++ b/bin/dstar2tgba.cc @@ -213,13 +213,12 @@ namespace process_automaton(const spot::const_parsed_aut_ptr& haut, const char* filename) { - spot::stopwatch sw; - sw.start(); + process_timer timer; + timer.start(); auto nba = spot::to_generalized_buchi(haut->aut); auto aut = post.run(nba, nullptr); - const double conversion_time = sw.stop(); - - printer.print(aut, nullptr, filename, -1, conversion_time, haut); + timer.stop(); + printer.print(aut, timer, nullptr, filename, -1, haut); flush_cout(); return 0; } diff --git a/bin/ltl2tgba.cc b/bin/ltl2tgba.cc index d1c1992ab..41beae20d 100644 --- a/bin/ltl2tgba.cc +++ b/bin/ltl2tgba.cc @@ -139,12 +139,12 @@ namespace s.c_str()); } - spot::stopwatch sw; - sw.start(); + process_timer timer; + timer.start(); auto aut = trans.run(&f); - const double translation_time = sw.stop(); + timer.stop(); - printer.print(aut, f, filename, linenum, translation_time, nullptr, + printer.print(aut, timer, f, filename, linenum, nullptr, prefix, suffix); return 0; } diff --git a/bin/ltlcross.cc b/bin/ltlcross.cc index fe171a284..f93804c56 100644 --- a/bin/ltlcross.cc +++ b/bin/ltlcross.cc @@ -39,6 +39,7 @@ #include "common_file.hh" #include "common_finput.hh" #include "common_hoaread.hh" +#include "common_aoutput.hh" #include #include #include @@ -534,11 +535,10 @@ namespace std::string cmd = command.str(); std::cerr << "Running [" << l << translator_num << "]: " << cmd << std::endl; - spot::stopwatch sw; - sw.start(); + process_timer timer; + timer.start(); int es = exec_with_timeout(cmd.c_str()); - double duration = sw.stop(); - + timer.stop(); const char* status_str = nullptr; spot::twa_graph_ptr res = nullptr; @@ -619,7 +619,7 @@ namespace statistics* st = &(*fstats)[translator_num]; st->status_str = status_str; st->status_code = es; - st->time = duration; + st->time = timer.get_lap_sw(); // Compute statistics. if (res) diff --git a/bin/ltldo.cc b/bin/ltldo.cc index c9e69776f..81cc3da33 100644 --- a/bin/ltldo.cc +++ b/bin/ltldo.cc @@ -168,7 +168,7 @@ namespace } spot::twa_graph_ptr - translate(unsigned int translator_num, bool& problem, double& duration) + translate(unsigned int translator_num, bool& problem, process_timer& timer) { output.reset(translator_num); @@ -178,10 +178,9 @@ namespace std::string cmd = command.str(); //std::cerr << "Running [" << l << translator_num << "]: " // << cmd << std::endl; - spot::stopwatch sw; - sw.start(); + timer.start(); int es = exec_with_timeout(cmd.c_str()); - duration = sw.stop(); + timer.stop(); spot::twa_graph_ptr res = nullptr; problem = false; @@ -316,8 +315,8 @@ namespace for (unsigned t = 0; t < ts; ++t) { bool problem; - double translation_time; - auto aut = runner.translate(t, problem, translation_time); + process_timer timer; + auto aut = runner.translate(t, problem, timer); if (problem) { if (errors_opt == errors_abort) @@ -333,7 +332,7 @@ namespace aut = post.run(aut, f); cmdname = translators[t].name; roundval = round; - printer.print(aut, f, filename, linenum, translation_time, + printer.print(aut, timer, f, filename, linenum, nullptr, prefix, suffix); }; } diff --git a/bin/randaut.cc b/bin/randaut.cc index ac65ac2e7..971f4664b 100644 --- a/bin/randaut.cc +++ b/bin/randaut.cc @@ -341,8 +341,8 @@ main(int argc, char** argv) for (;;) { - spot::stopwatch sw; - sw.start(); + process_timer timer; + timer.start(); if (ap_count_given.max > 0 && ap_count_given.min != ap_count_given.max) @@ -395,10 +395,10 @@ main(int argc, char** argv) trials = max_trials; } - auto runtime = sw.stop(); + timer.stop(); - printer.print(aut, nullptr, - opt_seed_str, automaton_num, runtime, nullptr); + printer.print(aut, timer, nullptr, + opt_seed_str, automaton_num, nullptr); ++automaton_num; if (opt_automata > 0 && automaton_num >= opt_automata) diff --git a/spot/misc/formater.hh b/spot/misc/formater.hh index d1edc985a..879cbebd0 100644 --- a/spot/misc/formater.hh +++ b/spot/misc/formater.hh @@ -20,10 +20,13 @@ #pragma once #include +#include #include #include #include +#define UNUSED(expr) do { (void)(expr); } while (0) + namespace spot { class printable @@ -85,6 +88,15 @@ namespace spot } }; + // This function was defined to avoid compilation error when + // instantiating function spot::printable_value::print + // because of: os << val_; + std::ostream& operator<<(std::ostream& os, const timer& dt) + { + UNUSED(dt); + return os; + } + /// The default callback simply writes "%c". class printable_id: public printable { diff --git a/spot/misc/timer.cc b/spot/misc/timer.cc index e1e98c74d..649f59884 100644 --- a/spot/misc/timer.cc +++ b/spot/misc/timer.cc @@ -27,6 +27,15 @@ namespace spot { + /* + std::ostream& operator<<(std::ostream& os, const timer& dt) + { + os << "utime<" << dt.utime() << ">, cutime<" << dt.cutime() + << ">, stime<" << dt.stime() << ">, cstime<" << dt.cstime() << '>'; + return os; + } + */ + std::ostream& timer_map::print(std::ostream& os) const @@ -39,8 +48,11 @@ namespace spot { total.utime += i->second.first.utime(); total.stime += i->second.first.stime(); + total.cutime += i->second.first.cutime(); + total.cstime += i->second.first.cstime(); } - clock_t grand_total = total.utime + total.stime; + clock_t grand_total = total.utime + total.cutime + + total.stime + total.cstime; os << std::setw(23) << "" << "| user time | sys. time | total |" @@ -61,18 +73,21 @@ namespace spot const char* sep = t.is_running() ? "+|" : " |"; os << std::setw(22) << name << sep - << std::setw(6) << t.utime() << ' ' + << std::setw(6) << t.utime() + t.cutime() << ' ' << std::setw(8) << (total.utime ? - 100.0 * t.utime() / total.utime : 0.) + 100.0 * (t.utime() + t.cutime()) + / (total.utime + total.cutime) : 0.) << sep - << std::setw(6) << t.stime() << ' ' + << std::setw(6) << t.stime() + t.cstime() << ' ' << std::setw(8) << (total.stime ? - 100.0 * t.stime() / total.stime : 0.) + 100.0 * (t.stime() +t.cstime()) + / (total.stime + total.cstime) : 0.) << sep - << std::setw(6) << t.utime() + t.stime() << ' ' + << std::setw(6) << t.utime() + t.cutime() + t.stime() + + t.cstime() << ' ' << std::setw(8) << (grand_total ? - (100.0 * (t.utime() + t.stime()) / - grand_total) : 0.) + (100.0 * (t.utime() + t.cutime() + t.stime() + + t.cstime()) / grand_total) : 0.) << sep << std::setw(4) << i->second.second << std::endl; @@ -80,10 +95,10 @@ namespace spot os << std::setw(79) << std::setfill('-') << "" << std::setfill(' ') << std::endl << std::setw(22) << "TOTAL" << " |" - << std::setw(6) << total.utime << ' ' + << std::setw(6) << total.utime + total.cutime << ' ' << std::setw(8) << 100. << " |" - << std::setw(6) << total.stime << ' ' + << std::setw(6) << total.stime + total.cstime << ' ' << std::setw(8) << 100. << " |" << std::setw(6) << grand_total << ' ' diff --git a/spot/misc/timer.hh b/spot/misc/timer.hh index 107c8b846..9b933e0e2 100644 --- a/spot/misc/timer.hh +++ b/spot/misc/timer.hh @@ -66,19 +66,22 @@ namespace spot } }; - /// A structure to record elapsed time in clock ticks. struct time_info { time_info() - : utime(0), stime(0) + : utime(0), stime(0), cutime(0), cstime(0) { } clock_t utime; clock_t stime; + clock_t cutime; + clock_t cstime; }; - /// A timekeeper that accumulate interval of time. + /// A timekeeper that accumulate interval of time in a more detailed way. + /// For instance, you can get the time spent with or without children + /// processes. class timer { public: @@ -96,8 +99,10 @@ namespace spot #ifdef SPOT_HAVE_TIMES struct tms tmp; times(&tmp); - start_.utime = tmp.tms_utime + tmp.tms_cutime; - start_.stime = tmp.tms_stime + tmp.tms_cstime; + start_.utime = tmp.tms_utime; + start_.cutime = tmp.tms_cutime; + start_.stime = tmp.tms_stime; + start_.cstime = tmp.tms_cstime; #else start_.utime = clock(); #endif @@ -110,8 +115,10 @@ namespace spot #ifdef SPOT_HAVE_TIMES struct tms tmp; times(&tmp); - total_.utime += tmp.tms_utime + tmp.tms_cutime - start_.utime; - total_.stime += tmp.tms_stime + tmp.tms_cstime - start_.stime; + total_.utime += tmp.tms_utime - start_.utime; + total_.cutime += tmp.tms_cutime - start_.cutime; + total_.stime += tmp.tms_stime - start_.stime; + total_.cstime += tmp.tms_cstime - start_.cstime; #else total_.utime += clock() - start_.utime; #endif @@ -119,7 +126,8 @@ namespace spot running = false; } - /// \brief Return the user time of all accumulated interval. + /// \brief Return the user time of the current process (without children) + /// of all accumulated interval. /// /// Any time interval that has been start()ed but not stop()ed /// will not be accounted for. @@ -129,7 +137,18 @@ namespace spot return total_.utime; } - /// \brief Return the system time of all accumulated interval. + /// \brief Return the user time of children of all accumulated interval. + /// + /// Any time interval that has been start()ed but not stop()ed + /// will not be accounted for. + clock_t + cutime() const + { + return total_.cutime; + } + + /// \brief Return the system time of the current process (whithout children) + /// of all accumulated interval. /// /// Any time interval that has been start()ed but not stop()ed /// will not be accounted for. @@ -139,6 +158,34 @@ namespace spot return total_.stime; } + /// \brief Return the system time of children of all accumulated interval. + /// + /// Any time interval that has been start()ed but not stop()ed + /// will not be accounted for. + clock_t + cstime() const + { + return total_.cstime; + } + + clock_t get_uscp(bool user, bool system, bool children, bool parent) const + { + clock_t res = 0; + + if (user && parent) + res += utime(); + + if (user && children) + res += cutime(); + + if (system && parent) + res += stime(); + + if (system && children) + res += cstime(); + + return res; + } /// \brief Whether the timer is running. bool @@ -153,6 +200,10 @@ namespace spot bool running; }; + // This function declared here must be implemented in each file + // that includes this header, well, only if this operator is needed! + inline std::ostream& operator<<(std::ostream& os, const timer& dt); + /// \brief A map of timer, where each timer has a name. /// /// Timer_map also keeps track of the number of measures each timer diff --git a/spot/twaalgos/dtbasat.cc b/spot/twaalgos/dtbasat.cc index 70036eff5..0f250fa9c 100644 --- a/spot/twaalgos/dtbasat.cc +++ b/spot/twaalgos/dtbasat.cc @@ -794,8 +794,10 @@ namespace spot } out << ',' << s.first << ',' << s.second << ',' - << te.utime() << ',' << te.stime() << ',' - << ts.utime() << ',' << ts.stime() << '\n'; + << te.utime() + te.cutime() << ',' + << te.stime() + te.cstime() << ',' + << ts.utime() + ts.cutime() << ',' + << ts.stime() + ts.cstime() << '\n'; } static bool show = getenv("SPOT_SATSHOW"); if (show && res) diff --git a/spot/twaalgos/dtwasat.cc b/spot/twaalgos/dtwasat.cc index 6da958dae..c9b01f236 100644 --- a/spot/twaalgos/dtwasat.cc +++ b/spot/twaalgos/dtwasat.cc @@ -1173,8 +1173,10 @@ namespace spot } out << ',' << s.first << ',' << s.second << ',' - << te.utime() << ',' << te.stime() << ',' - << ts.utime() << ',' << ts.stime() << '\n'; + << te.utime() + te.cutime() << ',' + << te.stime() + te.cstime() << ',' + << ts.utime() + ts.cutime() << ',' + << ts.stime() + ts.cstime() << '\n'; } static bool show = getenv("SPOT_SATSHOW"); if (show && res)