Partially rework profiling. Fix profiling crash with new parser. Fixes

1295

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;
 

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

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

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<int> 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;
         }
+        
+        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;
         }
         
-    /* Profiling support */
+        return result;
-    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();
     }
 
     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);

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_item_t*> profile_items;
 
     /* No copying allowed */
     parse_execution_context_t(const parse_execution_context_t&);
@@ -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);

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<profile_item_t*> &items,
                           FILE *out)
 {
-    size_t pos;
+    for (size_t pos = 0; pos < items.size(); pos++)
-    for (pos = 0; pos < items.size(); pos++)
     {
         const profile_item_t *me, *prev;
         size_t i;
@@ -626,22 +625,19 @@ static void print_profile(const std::vector<profile_item_t*> &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(profile, "w");
+    FILE *f = fopen(path, "w");
     if (!f)
     {
         debug(1,
               _(L"Could not write profiling information to file '%s'"),
-                  profile);
+              path);
     }
     else
     {
@@ -661,12 +657,6 @@ void parser_t::destroy()
             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);
 

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.
+    /** If the execution of this command was skipped. */
-    */
+    bool skipped;
-    int skipped;
+
-    /**
+    /** The command string. */
-       The command string.
-    */
     wcstring cmd;
 };
 
@@ -478,6 +472,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
        to be read first. The result will have the PARSER_TEST_ERROR bit
@@ -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.