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

@@ -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<std::string> 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<long long>(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();

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_statement_t>()->if_clause.condition.source_range().end();
+            src_end = node.as<if_statement_t>()->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<const ast::job_t *> 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<int>(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<int>(parse_time - start_time);
-        profile_item->exec = static_cast<int>(exec_time - parse_time);
         profile_item->cmd = job ? job->command() : wcstring();
         profile_item->skipped = (pop_result != end_execution_reason_t::ok);
     }

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<std::unique_ptr<profile_item_t>> &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<profile_item_t> &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<std::unique_ptr<profile_item_t>> &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<profile_item_t>());
-        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,

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<parser_t> {
     /// 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<std::unique_ptr<profile_item_t>> profile_items;
+    /// to profile_items). deque does not move items on reallocation.
+    std::deque<profile_item_t> profile_items;
 
     // No copying allowed.
     parser_t(const parser_t &);
@@ -371,16 +377,17 @@ class parser_t : public std::enable_shared_from_this<parser_t> {
     /// 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.