From bae64f8a8a1bb0d0d781e0339947938b5b2bf48c Mon Sep 17 00:00:00 2001 From: ridiculousfish Date: Wed, 22 Jul 2020 15:35:14 -0700 Subject: [PATCH] Modest cleanup of profiling This is a set of miscellaneous cleanup for profiling. An errant newline has been removed from 'if' statement output, which got introduced with the new ast. Switch from storing unique_ptr to a deque, which allocates less. Collapse "parse" and "exec" times into just a single value "duration". The "parse" time no longer makes sense, as we now parse ahead of time. --- src/fish.cpp | 9 +++--- src/parse_execution.cpp | 22 +++------------ src/parser.cpp | 61 +++++++++++++++++------------------------ src/parser.h | 43 +++++++++++++++++------------ 4 files changed, 58 insertions(+), 77 deletions(-) diff --git a/src/fish.cpp b/src/fish.cpp index a44de6e04..5ec6a7713 100644 --- a/src/fish.cpp +++ b/src/fish.cpp @@ -65,6 +65,8 @@ class fish_cmd_opts_t { wcstring features; // File path for debug output. std::string debug_output; + // File path for profiling output, or empty for none. + std::string profile_output; // Commands to be executed in place of interactive shell. std::vector batch_cmds; // Commands to execute after the shell's config has been read. @@ -81,9 +83,6 @@ class fish_cmd_opts_t { bool enable_private_mode{false}; }; -/// If we are doing profiling, the filename to output to. -static const char *s_profiling_output_filename = nullptr; - /// \return a timeval converted to milliseconds. long long tv_to_msec(const struct timeval &tv) { long long msec = static_cast(tv.tv_sec) * 1000; // milliseconds per second @@ -353,7 +352,7 @@ static int fish_parse_opt(int argc, char **argv, fish_cmd_opts_t *opts) { exit(0); } case 'p': { - s_profiling_output_filename = optarg; + opts->profile_output = optarg; g_profiling_active = true; break; } @@ -531,7 +530,7 @@ int main(int argc, char **argv) { restore_term_foreground_process_group_for_exit(); if (g_profiling_active) { - parser.emit_profiling(s_profiling_output_filename); + parser.emit_profiling(opts.profile_output.c_str()); } history_save_all(); diff --git a/src/parse_execution.cpp b/src/parse_execution.cpp index 273ad39bd..cdc3495e0 100644 --- a/src/parse_execution.cpp +++ b/src/parse_execution.cpp @@ -91,7 +91,7 @@ static wcstring profiling_cmd_name_for_redirectable_block(const ast::node_t &nod } break; case type_t::if_statement: - src_end = node.as()->if_clause.condition.source_range().end(); + src_end = node.as()->if_clause.condition.job.source_range().end(); break; case type_t::switch_statement: @@ -1225,11 +1225,8 @@ end_execution_reason_t parse_execution_context_t::run_1_job(const ast::job_t &jo scoped_push saved_node(&executing_job_node, &job_node); // Profiling support. - long long start_time = 0, parse_time = 0, exec_time = 0; profile_item_t *profile_item = this->parser->create_profile_item(); - if (profile_item != nullptr) { - start_time = get_time(); - } + const auto start_time = profile_item ? profile_item_t::now() : 0; // When we encounter a block construct (e.g. while loop) in the general case, we create a "block // process" containing its node. This allows us to handle block-level redirections. @@ -1275,12 +1272,8 @@ end_execution_reason_t parse_execution_context_t::run_1_job(const ast::job_t &jo } if (profile_item != nullptr) { - // Block-types profile a little weird. They have no 'parse' time, and their command is - // just the block type. - exec_time = get_time(); + profile_item->duration = profile_item_t::now() - start_time; profile_item->level = parser->eval_level; - profile_item->parse = 0; - profile_item->exec = static_cast(exec_time - start_time); profile_item->cmd = profiling_cmd_name_for_redirectable_block(*specific_statement, *this->pstree); profile_item->skipped = false; @@ -1317,11 +1310,6 @@ end_execution_reason_t parse_execution_context_t::run_1_job(const ast::job_t &jo this->populate_job_from_job_node(job.get(), job_node, associated_block); caller_id.restore(); - // Store time it took to 'parse' the command. - if (profile_item != nullptr) { - parse_time = get_time(); - } - // Clean up the job on failure or cancellation. if (pop_result == end_execution_reason_t::ok) { // Set the pgroup assignment mode and job group, now that the job is populated. @@ -1353,10 +1341,8 @@ end_execution_reason_t parse_execution_context_t::run_1_job(const ast::job_t &jo } if (profile_item != nullptr) { - exec_time = get_time(); + profile_item->duration = profile_item_t::now() - start_time; profile_item->level = parser->eval_level; - profile_item->parse = static_cast(parse_time - start_time); - profile_item->exec = static_cast(exec_time - parse_time); profile_item->cmd = job ? job->command() : wcstring(); profile_item->skipped = (pop_result != end_execution_reason_t::ok); } diff --git a/src/parser.cpp b/src/parser.cpp index e22ca7a24..506565623 100644 --- a/src/parser.cpp +++ b/src/parser.cpp @@ -252,50 +252,40 @@ block_t *parser_t::block_at_index(size_t idx) { block_t *parser_t::current_block() { return block_at_index(0); } /// Print profiling information to the specified stream. -static void print_profile(const std::vector> &items, FILE *out) { - for (size_t pos = 0; pos < items.size(); pos++) { - const profile_item_t *me, *prev; - size_t i; - int my_time; +static void print_profile(const std::deque &items, FILE *out) { + for (size_t idx = 0; idx < items.size(); idx++) { + const profile_item_t &item = items.at(idx); + if (item.skipped || item.cmd.empty()) continue; - me = items.at(pos).get(); - if (me->skipped) { - continue; + long long total_time = item.duration; + + // Compute the self time as the total time, minus the total time consumed by subsequent + // items exactly one eval level deeper. + long long self_time = item.duration; + for (size_t i = idx + 1; i < items.size(); i++) { + const profile_item_t &nested_item = items.at(i); + if (nested_item.skipped) continue; + + // If the eval level is not larger, then we have exhausted nested items. + if (nested_item.level <= item.level) break; + + // If the eval level is exactly one more than our level, it is a directly nested item. + if (nested_item.level == item.level + 1) self_time -= nested_item.duration; } - my_time = me->parse + me->exec; - for (i = pos + 1; i < items.size(); i++) { - prev = items.at(i).get(); - if (prev->skipped) { - continue; - } - if (prev->level <= me->level) { - break; - } - if (prev->level > me->level + 1) { - continue; - } - - my_time -= prev->parse + prev->exec; - } - - if (me->cmd.empty()) { - continue; - } - - if (std::fwprintf(out, L"%d\t%d\t", my_time, me->parse + me->exec) < 0) { + if (std::fwprintf(out, L"%lld\t%lld\t", self_time, total_time) < 0) { wperror(L"fwprintf"); return; } - for (i = 0; i < me->level; i++) { + for (size_t i = 0; i < item.level; i++) { if (std::fwprintf(out, L"-") < 0) { wperror(L"fwprintf"); return; } } - if (std::fwprintf(out, L"> %ls\n", me->cmd.c_str()) < 0) { + if (std::fwprintf(out, L"> %ls\n", item.cmd.c_str()) < 0) { wperror(L"fwprintf"); return; } @@ -304,7 +294,7 @@ static void print_profile(const std::vector> &it void parser_t::emit_profiling(const char *path) const { // Save profiling information. OK to not use CLO_EXEC here because this is called while fish is - // dying (and hence will not fork). + // exiting (and hence will not fork). FILE *f = fopen(path, "w"); if (!f) { FLOGF(warning, _(L"Could not write profiling information to file '%s'"), path); @@ -620,12 +610,11 @@ job_t *parser_t::job_get_from_pid(pid_t pid) const { } profile_item_t *parser_t::create_profile_item() { - profile_item_t *result = nullptr; if (g_profiling_active) { - profile_items.push_back(make_unique()); - result = profile_items.back().get(); + profile_items.emplace_back(); + return &profile_items.back(); } - return result; + return nullptr; } eval_res_t parser_t::eval(const wcstring &cmd, const io_chain_t &io, diff --git a/src/parser.h b/src/parser.h index db42b69f4..356f2d177 100644 --- a/src/parser.h +++ b/src/parser.h @@ -19,6 +19,7 @@ #include "parse_execution.h" #include "parse_tree.h" #include "proc.h" +#include "util.h" class io_chain_t; @@ -113,18 +114,23 @@ class block_t { }; struct profile_item_t { - /// Time spent executing the specified command, including parse time for nested blocks. - int exec; - /// Time spent parsing the specified command, including execution time for command - /// substitutions. - int parse; - /// The block level of the specified command. nested blocks and command substitutions both + using microseconds_t = long long; + + /// Time spent executing the command, including nested blocks. + microseconds_t duration{}; + + /// The block level of the specified command. Nested blocks and command substitutions both /// increase the block level. - size_t level; + size_t level{}; + /// If the execution of this command was skipped. - bool skipped; + bool skipped{}; + /// The command string. - wcstring cmd; + wcstring cmd{}; + + /// \return the current time as a microsecond timestamp since the epoch. + static microseconds_t now() { return get_time(); } }; class parse_execution_context_t; @@ -238,11 +244,11 @@ class parser_t : public std::enable_shared_from_this { /// Miscellaneous library data. library_data_t library_data{}; - /// List of profile items - /// These are pointers because we return pointers to them to callers, + /// List of profile items. + /// This must be a deque because we return pointers to them to callers, /// who may hold them across blocks (which would cause reallocations internal - /// to profile_items) - std::vector> profile_items; + /// to profile_items). deque does not move items on reallocation. + std::deque profile_items; // No copying allowed. parser_t(const parser_t &); @@ -371,16 +377,17 @@ class parser_t : public std::enable_shared_from_this { /// Returns the job with the given pid. job_t *job_get_from_pid(pid_t pid) const; - /// Returns a new profile item if profiling is active. The caller should fill it in. The - /// parser_t will clean it up. + /// Returns a new profile item if profiling is active. The caller should fill it in. + /// The parser_t will deallocate it. + /// If profiling is not active, this returns nullptr. profile_item_t *create_profile_item(); - void get_backtrace(const wcstring &src, const parse_error_list_t &errors, - wcstring &output) const; - /// Output profiling data to the given filename. void emit_profiling(const char *path) const; + void get_backtrace(const wcstring &src, const parse_error_list_t &errors, + wcstring &output) const; + /// Returns the file currently evaluated by the parser. This can be different than /// reader_current_filename, e.g. if we are evaluating a function defined in a different file /// than the one curently read.