diff --git a/common.cpp b/common.cpp index d20040b87..f2240b53c 100644 --- a/common.cpp +++ b/common.cpp @@ -83,7 +83,7 @@ static bool thread_assertions_configured_for_testing = false; wchar_t ellipsis_char; wchar_t omitted_newline_char; -char *profile=0; +bool g_profiling_active = false; const wchar_t *program_name; diff --git a/common.h b/common.h index 3e9be1063..33fbb0e5e 100644 --- a/common.h +++ b/common.h @@ -149,7 +149,7 @@ extern int debug_level; /** Profiling flag. True if commands should be profiled. */ -extern char *profile; +extern bool g_profiling_active; /** Name of the current program. Should be set at startup. Used by the diff --git a/fish.cpp b/fish.cpp index bf6470f8a..f1c5b898a 100644 --- a/fish.cpp +++ b/fish.cpp @@ -73,6 +73,9 @@ Foundation, Inc., 51 Franklin Street, Fifth Floor, Boston, MA 02110-1301, USA */ #define GETOPT_STRING "+hilnvc:p:d:" +/* If we are doing profiling, the filename to output to */ +static const char *s_profiling_output_filename = NULL; + static bool has_suffix(const std::string &path, const char *suffix, bool ignore_case) { size_t pathlen = path.size(), suffixlen = strlen(suffix); @@ -245,7 +248,6 @@ static int read_init(const struct config_paths_t &paths) return 1; } - /** Parse the argument list, return the index of the first non-switch arguments. @@ -346,7 +348,8 @@ static int fish_parse_opt(int argc, char **argv, std::vector *out_c case 'p': { - profile = optarg; + s_profiling_output_filename = optarg; + g_profiling_active = true; break; } @@ -521,11 +524,16 @@ int main(int argc, char **argv) restore_term_mode(); restore_term_foreground_process_group(); + + if (g_profiling_active) + { + parser.emit_profiling(s_profiling_output_filename); + } + history_destroy(); proc_destroy(); builtin_destroy(); reader_destroy(); - parser.destroy(); wutil_destroy(); event_destroy(); diff --git a/parse_execution.cpp b/parse_execution.cpp index d0d8336b3..08f222ed7 100644 --- a/parse_execution.cpp +++ b/parse_execution.cpp @@ -27,7 +27,30 @@ static bool specific_statement_type_is_redirectable_block(const parse_node_t &no } -parse_execution_context_t::parse_execution_context_t(const parse_node_tree_t &t, const wcstring &s, parser_t *p) : tree(t), src(s), parser(p), eval_level(0) +/* Get the name of a redirectable block, for profiling purposes */ +static wcstring profiling_cmd_name_for_redirectable_block(const parse_node_t &node, const parse_node_tree_t &tree, const wcstring &src) +{ + assert(specific_statement_type_is_redirectable_block(node)); + assert(node.has_source()); + + /* Get the source for the block, and cut it at the next statement terminator. */ + const size_t src_start = node.source_start; + size_t src_len = node.source_length; + + const parse_node_tree_t::parse_node_list_t statement_terminator_nodes = tree.find_nodes(node, parse_token_type_end, 1); + if (! statement_terminator_nodes.empty()) + { + const parse_node_t *term = statement_terminator_nodes.at(0); + assert(term->source_start >= src_start); + src_len = term->source_start - src_start; + } + + wcstring result = wcstring(src, src_start, src_len); + result.append(L"..."); + return result; +} + +parse_execution_context_t::parse_execution_context_t(const parse_node_tree_t &t, const wcstring &s, parser_t *p, int initial_eval_level) : tree(t), src(s), parser(p), eval_level(initial_eval_level) { } @@ -1270,6 +1293,14 @@ parse_execution_result_t parse_execution_context_t::run_1_job(const parse_node_t /* Increment the eval_level for the duration of this command */ scoped_push saved_eval_level(&eval_level, eval_level + 1); + /* 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 != NULL) + { + start_time = get_time(); + } + /* When we encounter a block construct (e.g. while loop) in the general case, we create a "block process" that has a pointer to its source. This allows us to handle block-level redirections. However, if there are no redirections, then we can just jump into the block directly, which is significantly faster. */ if (job_is_simple_block(job_node)) { @@ -1279,31 +1310,35 @@ parse_execution_result_t parse_execution_context_t::run_1_job(const parse_node_t switch (specific_statement.type) { case symbol_block_statement: - return this->run_block_statement(specific_statement); + result = this->run_block_statement(specific_statement); + break; case symbol_if_statement: - return this->run_if_statement(specific_statement); + result = this->run_if_statement(specific_statement); + break; case symbol_switch_statement: - return this->run_switch_statement(specific_statement); + result = this->run_switch_statement(specific_statement); + break; default: /* Other types should be impossible due to the specific_statement_type_is_redirectable_block check */ PARSER_DIE(); break; } - } - - /* Profiling support */ - long long start_time = 0, parse_time = 0, exec_time = 0; - const bool do_profile = profile; - profile_item_t *profile_item = NULL; - if (do_profile) - { - profile_item = new profile_item_t(); - profile_item->skipped = 1; - profile_items.push_back(profile_item); - start_time = get_time(); + + if (profile_item != NULL) + { + /* 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->level=eval_level; + profile_item->parse = 0; + profile_item->exec=(int)(exec_time-start_time); + profile_item->cmd = profiling_cmd_name_for_redirectable_block(specific_statement, this->tree, this->src); + profile_item->skipped = result != parse_execution_success; + } + + return result; } job_t *j = new job_t(acquire_job_id(), block_io); @@ -1336,11 +1371,9 @@ parse_execution_result_t parse_execution_context_t::run_1_job(const parse_node_t /* Store time it took to 'parse' the command */ - if (do_profile) + if (profile_item != NULL) { parse_time = get_time(); - profile_item->cmd = j->command(); - profile_item->skipped=parser->current_block()->skip; } if (populated_job) @@ -1370,20 +1403,22 @@ parse_execution_result_t parse_execution_context_t::run_1_job(const parse_node_t } } + if (profile_item != NULL) + { + exec_time = get_time(); + profile_item->level=eval_level; + profile_item->parse = (int)(parse_time-start_time); + profile_item->exec=(int)(exec_time-parse_time); + profile_item->cmd = j ? j->command() : wcstring(); + profile_item->skipped = ! populated_job || result != parse_execution_success; + } + /* If the job was skipped, we pretend it ran anyways */ if (result == parse_execution_skipped) { result = parse_execution_success; } - if (do_profile) - { - exec_time = get_time(); - profile_item->level=eval_level; - profile_item->parse = (int)(parse_time-start_time); - profile_item->exec=(int)(exec_time-parse_time); - profile_item->skipped = ! populated_job; - } /* Clean up jobs. */ job_reap(0); diff --git a/parse_execution.h b/parse_execution.h index 89565d753..8ab5c5d6e 100644 --- a/parse_execution.h +++ b/parse_execution.h @@ -12,7 +12,6 @@ #include "proc.h" class job_t; -struct profile_item_t; struct block_t; enum parse_execution_result_t @@ -40,7 +39,6 @@ private: //parse_error_list_t errors; int eval_level; - std::vector profile_items; /* No copying allowed */ parse_execution_context_t(const parse_execution_context_t&); @@ -66,7 +64,7 @@ private: /* Command not found support */ void handle_command_not_found(const wcstring &cmd, const parse_node_t &statement_node, int err_code); - + /* Utilities */ wcstring get_source(const parse_node_t &node) const; const parse_node_t *get_child(const parse_node_t &parent, node_offset_t which, parse_token_type_t expected_type = token_type_invalid) const; @@ -103,7 +101,10 @@ private: parse_execution_result_t populate_job_from_job_node(job_t *j, const parse_node_t &job_node, const block_t *associated_block); public: - parse_execution_context_t(const parse_node_tree_t &t, const wcstring &s, parser_t *p); + parse_execution_context_t(const parse_node_tree_t &t, const wcstring &s, parser_t *p, int initial_eval_level); + + /* Returns the current eval level */ + int current_eval_level() const { return eval_level; } /* Start executing at the given node offset. Returns 0 if there was no error, 1 if there was an error */ parse_execution_result_t eval_node_at_offset(node_offset_t offset, const block_t *associated_block, const io_chain_t &io); diff --git a/parser.cpp b/parser.cpp index 4badfff83..7a75911bd 100644 --- a/parser.cpp +++ b/parser.cpp @@ -568,8 +568,7 @@ void parser_t::error(int ec, size_t p, const wchar_t *str, ...) static void print_profile(const std::vector &items, FILE *out) { - size_t pos; - for (pos = 0; pos < items.size(); pos++) + for (size_t pos = 0; pos < items.size(); pos++) { const profile_item_t *me, *prev; size_t i; @@ -626,47 +625,38 @@ static void print_profile(const std::vector &items, } } - delete me; } } } -void parser_t::destroy() +void parser_t::emit_profiling(const char *path) const { - if (profile) + /* Save profiling information. OK to not use CLO_EXEC here because this is called while fish is dying (and hence will not fork) */ + FILE *f = fopen(path, "w"); + if (!f) { - /* Save profiling information. OK to not use CLO_EXEC here because this is called while fish is dying (and hence will not fork) */ - FILE *f = fopen(profile, "w"); - if (!f) + debug(1, + _(L"Could not write profiling information to file '%s'"), + path); + } + else + { + if (fwprintf(f, + _(L"Time\tSum\tCommand\n"), + profile_items.size()) < 0) { - debug(1, - _(L"Could not write profiling information to file '%s'"), - profile); + wperror(L"fwprintf"); } else { - if (fwprintf(f, - _(L"Time\tSum\tCommand\n"), - profile_items.size()) < 0) - { - wperror(L"fwprintf"); - } - else - { - print_profile(profile_items, f); - } + print_profile(profile_items, f); + } - if (fclose(f)) - { - wperror(L"fclose"); - } + if (fclose(f)) + { + wperror(L"fclose"); } } - - lineinfo.clear(); - - forbidden_function.clear(); - } /** @@ -1225,6 +1215,17 @@ job_t *parser_t::job_get_from_pid(int pid) return 0; } +profile_item_t *parser_t::create_profile_item() +{ + profile_item_t *result = NULL; + if (g_profiling_active) + { + result = new profile_item_t(); + profile_items.push_back(result); + } + return result; +} + /** Parse options for the specified job @@ -2329,16 +2330,14 @@ void parser_t::eval_job(tokenizer_t *tok) long long t1=0, t2=0, t3=0; - profile_item_t *profile_item = NULL; bool skip = false; int job_begin_pos; - const bool do_profile = profile; + profile_item_t *profile_item = create_profile_item(); + const bool do_profile = (profile_item != NULL); if (do_profile) { - profile_item = new profile_item_t(); profile_item->skipped = 1; - profile_items.push_back(profile_item); t1 = get_time(); } @@ -2572,8 +2571,12 @@ int parser_t::eval_new_parser(const wcstring &cmd, const io_chain_t &io, enum bl return 1; } + + /* Determine the initial eval level. If this is the first context, it's -1; otherwise it's the eval level of the top context. This is sort of wonky because we're stitching together a global notion of eval level from these separate objects. A better approach would be some profile object that all contexts share, and that tracks the eval levels on its own. */ + int exec_eval_level = (execution_contexts.empty() ? -1 : execution_contexts.back()->current_eval_level()); + /* Append to the execution context stack */ - parse_execution_context_t *ctx = new parse_execution_context_t(tree, cmd, this); + parse_execution_context_t *ctx = new parse_execution_context_t(tree, cmd, this, exec_eval_level); execution_contexts.push_back(ctx); /* Execute the first node */ @@ -2593,7 +2596,8 @@ int parser_t::eval_new_parser(const wcstring &cmd, const io_chain_t &io, enum bl int parser_t::eval_block_node(node_offset_t node_idx, const io_chain_t &io, enum block_type_t block_type) { - // Paranoia. It's a little frightening that we're given only a node_idx and we interpret this in the topmost execution context's tree. What happens if these were to be interleaved? Fortunately that cannot happen. + /* Paranoia. It's a little frightening that we're given only a node_idx and we interpret this in the topmost execution context's tree. What happens if two trees were to be interleaved? Fortunately that cannot happen (yet); in the future we probably want some sort of reference counted trees. + */ parse_execution_context_t *ctx = execution_contexts.back(); assert(ctx != NULL); diff --git a/parser.h b/parser.h index 6e43c8da0..491e569f5 100644 --- a/parser.h +++ b/parser.h @@ -247,25 +247,19 @@ enum parser_type_t struct profile_item_t { - /** - Time spent executing the specified command, including parse time for nested blocks. - */ + /** 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. - */ + + /** 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 increase the block level. - */ + + /** The block level of the specified command. nested blocks and command substitutions both increase the block level. */ size_t level; - /** - If the execution of this command was skipped. - */ - int skipped; - /** - The command string. - */ + + /** If the execution of this command was skipped. */ + bool skipped; + + /** The command string. */ wcstring cmd; }; @@ -477,6 +471,9 @@ public: /** Returns the job with the given pid */ job_t *job_get_from_pid(int pid); + + /* Returns a new profile item if profiling is active. The caller should fill it in. The parser_t will clean it up. */ + profile_item_t *create_profile_item(); /** Test if the specified string can be parsed, or if more bytes need @@ -517,9 +514,9 @@ public: void init(); /** - Destroy static parser data + Output profiling data to the given filename */ - void destroy(); + void emit_profiling(const char *path) const; /** This function checks if the specified string is a help option.