# HG changeset patch # User Christian Brabandt # Date 1693660506 -7200 # Node ID bede81965821b2e62f9af1db702fd8ac0b3244d0 # Parent 67f506069462076b444fcac9a75d3c3c76ff82be patch 9.0.1842: Need more accurate profiling Commit: https://github.com/vim/vim/commit/21d3212361f687704acb52cad7c1b9228e7c83f0 Author: Ernie Rael Date: Sat Sep 2 15:09:18 2023 +0200 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 Co-authored-by: Ernie Rael diff --git a/src/debugger.c b/src/debugger.c --- 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 --- 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 --- 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 --- 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 --- 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 --- a/src/version.c +++ b/src/version.c @@ -700,6 +700,8 @@ static char *(features[]) = static int included_patches[] = { /* Add new patch number below this line */ /**/ + 1842, +/**/ 1841, /**/ 1840, diff --git a/src/vim9class.c b/src/vim9class.c --- 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 --- 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;