patch 9.0.1842: Need more accurate profiling

Problem:  Need more accurate profiling
Solution: Improve profiling results

closes: #12192

Reduce overhead of checking if a function should be profiled,
by caching results of checking (which are done with regexp).

Cache uf_hash for uf_name in ufunc_T.

Cache cleared when regexps are changed.

Break at first match for has_profiling lookup.

Signed-off-by: Christian Brabandt <cb@256bit.org>
Co-authored-by: Ernie Rael <errael@raelity.com>

diff --git a/src/debugger.c b/src/debugger.c
index 393e11e414fb4106c7c127136e0fd7ecc86feb77..66647ab4649183b1a50a0a55e14746c1a6b1862f 100644 (file)
--- a/src/debugger.c
+++ b/src/debugger.c
@@ -528,6 +528,35 @@ static int has_expr_breakpoint = FALSE;
 #ifdef FEAT_PROFILE
 // Profiling uses file and func names similar to breakpoints.
 static garray_T prof_ga = {0, 0, sizeof(struct debuggy), 4, NULL};
+
+// Profiling caches results of regexp lookups for function/script name.
+#define N_PROF_HTAB 2
+static hashtab_T prof_cache[N_PROF_HTAB];
+#define PROF_HTAB_FUNCS 0
+#define PROF_HTAB_FILES 1
+static int prof_cache_initialized;
+typedef struct profentry_S
+{
+    char    pen_flags; // cache data booleans: profiling, forceit
+    char_u  pen_name[1]; // actually longer
+} profentry_T;
+#define PEN_FLAG_PROFILING 1
+#define PEN_FLAG_FORCEIT 2
+#define PEN_SET_PROFILING(pe) ((pe)->pen_flags |= PEN_FLAG_PROFILING)
+#define PEN_SET_FORCEIT(pe) ((pe)->pen_flags |= PEN_FLAG_FORCEIT)
+#define PEN_IS_PROFILING(pe) (((pe)->pen_flags & PEN_FLAG_PROFILING) != 0)
+#define PEN_IS_FORCEIT(pe) (((pe)->pen_flags & PEN_FLAG_FORCEIT) != 0)
+
+#define PE2HIKEY(pe)   ((pe)->pen_name)
+#define HIKEY2PE(p)    ((profentry_T *)((p) - (offsetof(profentry_T, pen_name))))
+#define HI2PE(hi)      HIKEY2PE((hi)->hi_key)
+
+static void prof_clear_cache(void);
+#define PROF_CLEAR_CACHE(gap) do {if ((gap) == &prof_ga) prof_clear_cache();} while (0)
+// Can enable to get some info about profile caching
+// #define PROF_CACHE_LOG
+#else
+#define PROF_CLEAR_CACHE(gap) do {} while (0)
 #endif
 #define DBG_FUNC       1
 #define DBG_FILE       2
@@ -708,6 +737,7 @@ ex_breakadd(exarg_T *eap)
                ++debug_tick;
            }
            ++gap->ga_len;
+           PROF_CLEAR_CACHE(gap);
        }
     }
     else
@@ -845,6 +875,7 @@ ex_breakdel(exarg_T *eap)
        if (!del_all)
            break;
     }
+    PROF_CLEAR_CACHE(gap);
 
     // If all breakpoints were removed clear the array.
     if (gap->ga_len == 0)
@@ -899,17 +930,102 @@ dbg_find_breakpoint(
 }
 
 #if defined(FEAT_PROFILE) || defined(PROTO)
+#if defined(PROF_CACHE_LOG)
+static int count_lookups[2];
+#endif
 /*
  * Return TRUE if profiling is on for a function or sourced file.
+ * Cache the results of debuggy_find().
+ * Cache is cleared whenever prof_ga.ga_len is changed.
  */
     int
 has_profiling(
     int                file,       // TRUE for a file, FALSE for a function
     char_u     *fname,     // file or function name
-    int                *fp)        // return: forceit
+    int                *fp,        // return: forceit
+    hash_T     *hashp)     // use/return fname hash, may be NULL
 {
-    return (debuggy_find(file, fname, (linenr_T)0, &prof_ga, fp)
-                                                             != (linenr_T)0);
+    if (prof_ga.ga_len == 0 || !prof_cache_initialized)
+       return debuggy_find(file, fname, (linenr_T)0, &prof_ga, fp)
+                                                            != (linenr_T)0;
+
+    hash_T hash;
+    if (hashp != NULL)
+    {
+       hash = *hashp;
+       if (hash == 0)
+       {
+           hash = hash_hash(fname);
+           *hashp = hash;
+       }
+    }
+    else
+       hash = hash_hash(fname);
+
+    hashtab_T *ht = &prof_cache[file ? PROF_HTAB_FILES : PROF_HTAB_FUNCS];
+    hashitem_T *hi = hash_lookup(ht, fname, hash);
+    profentry_T *pe;
+    if (HASHITEM_EMPTY(hi))
+    {
+       pe = alloc(offsetof(profentry_T, pen_name) + STRLEN(fname) + 1);
+       if (pe == NULL)
+           return FALSE;
+       STRCPY(pe->pen_name, fname);
+       pe->pen_flags = 0;
+       // run debuggy_find and capture return and forceit
+       int f;
+       int lnum = debuggy_find(file, fname, (linenr_T)0, &prof_ga, &f);
+       if (lnum)
+       {
+           PEN_SET_PROFILING(pe);
+           if (f)
+               PEN_SET_FORCEIT(pe);
+       }
+       hash_add_item(ht, hi, pe->pen_name, hash);
+#if defined(PROF_CACHE_LOG)
+       ch_log(NULL, "has_profiling: %s %s forceit %s, profile %s",
+              file ? "file" : "func", fname,
+              PEN_IS_FORCEIT(pe) ? "true" : "false",
+              PEN_IS_PROFILING(pe) ? "true" : "false");
+#endif
+    }
+    else
+       pe = HI2PE(hi);
+    if (fp)
+       *fp = PEN_IS_FORCEIT(pe);
+#if defined(PROF_CACHE_LOG)
+    count_lookups[file ? PROF_HTAB_FILES : PROF_HTAB_FUNCS]++;
+#endif
+    return PEN_IS_PROFILING(pe);
+}
+
+    static void
+prof_clear_cache()
+{
+    if (!prof_cache_initialized)
+    {
+       hash_init(&prof_cache[PROF_HTAB_FUNCS]);
+       hash_init(&prof_cache[PROF_HTAB_FILES]);
+       prof_cache_initialized = TRUE;
+    }
+
+    hashtab_T *ht;
+    for (ht = &prof_cache[0]; ht < &prof_cache[N_PROF_HTAB]; ht++)
+    {
+       if (ht->ht_used > 0)
+       {
+#if defined(PROF_CACHE_LOG)
+           int idx = ht == &prof_cache[PROF_HTAB_FUNCS]
+                     ? PROF_HTAB_FUNCS : PROF_HTAB_FILES;
+           ch_log(NULL, "prof_clear_cache: %s, used: %ld, lookups: %d",
+                  idx == PROF_HTAB_FUNCS ? "function" : "script",
+                  ht->ht_used, count_lookups[idx]);
+           count_lookups[idx] = 0;
+#endif
+           hash_clear_all(ht, offsetof(profentry_T, pen_name));
+           hash_init(ht);
+       }
+    }
 }
 #endif
 
@@ -979,6 +1095,10 @@ debuggy_find(
                    *fp = bp->dbg_forceit;
            }
            got_int |= prev_got_int;
+#ifdef FEAT_PROFILE
+           if (lnum && gap == &prof_ga)
+               break;
+#endif
        }
 #ifdef FEAT_EVAL
        else if (bp->dbg_type == DBG_EXPR)

diff --git a/src/profiler.c b/src/profiler.c
index e101067ce8ab438008a575e0c2e791374deef2d2..780b958a918d437efb773b88f5ac2cbd11abda63 100644 (file)
--- a/src/profiler.c
+++ b/src/profiler.c
@@ -664,7 +664,8 @@ script_prof_save(
     void
 profile_may_start_func(profinfo_T *info, ufunc_T *fp, ufunc_T *caller)
 {
-    if (!fp->uf_profiling && has_profiling(FALSE, fp->uf_name, NULL))
+    if (!fp->uf_profiling && has_profiling(FALSE, fp->uf_name, NULL,
+                                                               &fp->uf_hash))
     {
        info->pi_started_profiling = TRUE;
        func_do_profile(fp);

diff --git a/src/proto/debugger.pro b/src/proto/debugger.pro
index d80ecf5019598f75a3e0ef09a7abba1727512807..b20f36dfd944c34f98cb43bb4b57e5f3030a57b8 100644 (file)
--- a/src/proto/debugger.pro
+++ b/src/proto/debugger.pro
@@ -10,6 +10,6 @@ int debug_has_expr_breakpoint(void);
 void ex_breakdel(exarg_T *eap);
 void ex_breaklist(exarg_T *eap);
 linenr_T dbg_find_breakpoint(int file, char_u *fname, linenr_T after);
-int has_profiling(int file, char_u *fname, int *fp);
+int has_profiling(int file, char_u *fname, int *fp, hash_T *hash);
 void dbg_breakpoint(char_u *name, linenr_T lnum);
 /* vim: set ft=c : */

diff --git a/src/scriptfile.c b/src/scriptfile.c
index aff964e4ec6faadfadd65cc7094ab0539333774a..e9c124e9fedfde842c5561154e36fa0c73fa5c8e 100644 (file)
--- a/src/scriptfile.c
+++ b/src/scriptfile.c
@@ -1721,7 +1721,7 @@ do_source_ext(
        int     forceit;
 
        // Check if we do profiling for this script.
-       if (!si->sn_prof_on && has_profiling(TRUE, si->sn_name, &forceit))
+       if (!si->sn_prof_on && has_profiling(TRUE, si->sn_name, &forceit, NULL))
        {
            script_do_profile(si);
            si->sn_pr_force = forceit;

diff --git a/src/structs.h b/src/structs.h
index 949031f1d3d5bdd2edfdf8db7307e0074232da53..6e9e90168625ac158e395f4cddf402312899e74b 100644 (file)
--- a/src/structs.h
+++ b/src/structs.h
@@ -1823,6 +1823,7 @@ struct ufunc_S
 # ifdef FEAT_PROFILE
     int                uf_profiling;   // TRUE when func is being profiled
     int                uf_prof_initialized;
+    hash_T     uf_hash;        // hash for uf_name when profiling
     // profiling the function as a whole
     int                uf_tm_count;    // nr of calls
     proftime_T uf_tm_total;    // time spent in function + children

diff --git a/src/version.c b/src/version.c
index 7fd2ebcac1996a3d02f2fa56d5206b219e1a7147..a09c725138ef827a4e79e7084d38bba96eabfabe 100644 (file)
--- a/src/version.c
+++ b/src/version.c
@@ -699,6 +699,8 @@ static char *(features[]) =
 
 static int included_patches[] =
 {   /* Add new patch number below this line */
+/**/
+    1842,
 /**/
     1841,
 /**/

diff --git a/src/vim9class.c b/src/vim9class.c
index 9c7badccb241ffae177bc876d5e489dc7d66bd62..165c3297f72a2bd467ae142ccf6381fef774a4d6 100644 (file)
--- a/src/vim9class.c
+++ b/src/vim9class.c
@@ -1475,6 +1475,7 @@ early_ret:
 
        // Add the class to the script-local variables.
        // TODO: handle other context, e.g. in a function
+       // TODO: does uf_hash need to be cleared?
        typval_T tv;
        tv.v_type = VAR_CLASS;
        tv.vval.v_class = cl;

diff --git a/src/vim9compile.c b/src/vim9compile.c
index 62528e957007f48ccfff75e6f8b93a9c620937b1..2786026ce6e5f849dda6c4490b89b8925cbd5fd5 100644 (file)
--- a/src/vim9compile.c
+++ b/src/vim9compile.c
@@ -2983,7 +2983,8 @@ get_compile_type(ufunc_T *ufunc)
 #ifdef FEAT_PROFILE
     if (do_profiling == PROF_YES)
     {
-       if (!ufunc->uf_profiling && has_profiling(FALSE, ufunc->uf_name, NULL))
+       if (!ufunc->uf_profiling && has_profiling(FALSE, ufunc->uf_name, NULL,
+                                                           &ufunc->uf_hash))
            func_do_profile(ufunc);
        if (ufunc->uf_profiling)
            return CT_PROFILE;