Mercurial > vim
view src/profiler.c @ 32936:c517845bd10e v9.0.1776
patch 9.0.1776: No support for stable Python 3 ABI
Commit: https://github.com/vim/vim/commit/c13b3d1350b60b94fe87f0761ea31c0e7fb6ebf3
Author: Yee Cheng Chin <ychin.git@gmail.com>
Date: Sun Aug 20 21:18:38 2023 +0200
patch 9.0.1776: No support for stable Python 3 ABI
Problem: No support for stable Python 3 ABI
Solution: Support Python 3 stable ABI
Commits:
1) Support Python 3 stable ABI to allow mixed version interoperatbility
Vim currently supports embedding Python for use with plugins, and the
"dynamic" linking option allows the user to specify a locally installed
version of Python by setting `pythonthreedll`. However, one caveat is
that the Python 3 libs are not binary compatible across minor versions,
and mixing versions can potentially be dangerous (e.g. let's say Vim was
linked against the Python 3.10 SDK, but the user sets `pythonthreedll`
to a 3.11 lib). Usually, nothing bad happens, but in theory this could
lead to crashes, memory corruption, and other unpredictable behaviors.
It's also difficult for the user to tell something is wrong because Vim
has no way of reporting what Python 3 version Vim was linked with.
For Vim installed via a package manager, this usually isn't an issue
because all the dependencies would already be figured out. For prebuilt
Vim binaries like MacVim (my motivation for working on this), AppImage,
and Win32 installer this could potentially be an issue as usually a
single binary is distributed. This is more tricky when a new Python
version is released, as there's a chicken-and-egg issue with deciding
what Python version to build against and hard to keep in sync when a new
Python version just drops and we have a mix of users of different Python
versions, and a user just blindly upgrading to a new Python could lead to
bad interactions with Vim.
Python 3 does have a solution for this problem: stable ABI / limited API
(see https://docs.python.org/3/c-api/stable.html). The C SDK limits the
API to a set of functions that are promised to be stable across
versions. This pull request adds an ifdef config that allows us to turn
it on when building Vim. Vim binaries built with this option should be
safe to freely link with any Python 3 libraies without having the
constraint of having to use the same minor version.
Note: Python 2 has no such concept and this doesn't change how Python 2
integration works (not that there is going to be a new version of Python
2 that would cause compatibility issues in the future anyway).
---
Technical details:
======
The stable ABI can be accessed when we compile with the Python 3 limited
API (by defining `Py_LIMITED_API`). The Python 3 code (in `if_python3.c`
and `if_py_both.h`) would now handle this and switch to limited API
mode. Without it set, Vim will still use the full API as before so this
is an opt-in change.
The main difference is that `PyType_Object` is now an opaque struct that
we can't directly create "static types" out of, and we have to create
type objects as "heap types" instead. This is because the struct is not
stable and changes from version to version (e.g. 3.8 added a
`tp_vectorcall` field to it). I had to change all the types to be
allocated on the heap instead with just a pointer to them.
Other functions are also simply missing in limited API, or they are
introduced too late (e.g. `PyUnicode_AsUTF8AndSize` in 3.10) to it that
we need some other ways to do the same thing, so I had to abstract a few
things into macros, and sometimes re-implement functions like
`PyObject_NEW`.
One caveat is that in limited API, `OutputType` (used for replacing
`sys.stdout`) no longer inherits from `PyStdPrinter_Type` which I don't
think has any real issue other than minor differences in how they
convert to a string and missing a couple functions like `mode()` and
`fileno()`.
Also fixed an existing bug where `tp_basicsize` was set incorrectly for
`BufferObject`, `TabListObject, `WinListObject`.
Technically, there could be a small performance drop, there is a little
more indirection with accessing type objects, and some APIs like
`PyUnicode_AsUTF8AndSize` are missing, but in practice I didn't see any
difference, and any well-written Python plugin should try to avoid
excessing callbacks to the `vim` module in Python anyway.
I only tested limited API mode down to Python 3.7, which seemes to
compile and work fine. I haven't tried earlier Python versions.
2) Fix PyIter_Check on older Python vers / type##Ptr unused warning
For PyIter_Check, older versions exposed them as either macros (used in
full API), or a function (for use in limited API). A previous change
exposed PyIter_Check to the dynamic build because Python just moved it
to function-only in 3.10 anyway. Because of that, just make sure we
always grab the function in dynamic builds in earlier versions since
that's what Python eventually did anyway.
3) Move Py_LIMITED_API define to configure script
Can now use --with-python-stable-abi flag to customize what stable ABI
version to target. Can also use an env var to do so as well.
4) Show +python/dyn-stable in :version, and allow has() feature query
Not sure if the "/dyn-stable" suffix would break things, or whether we
should do it another way. Or just don't show it in version and rely on
has() feature checking.
5) Documentation first draft. Still need to implement v:python3_version
6) Fix PyIter_Check build breaks when compiling against Python 3.8
7) Add CI coverage stable ABI on Linux/Windows / make configurable on Windows
This adds configurable options for Windows make files (both MinGW and
MSVC). CI will also now exercise both traditional full API and stable
ABI for Linux and Windows in the matrix for coverage.
Also added a "dynamic" option to Linux matrix as a drive-by change to
make other scripting languages like Ruby / Perl testable under both
static and dynamic builds.
8) Fix inaccuracy in Windows docs
Python's own docs are confusing but you don't actually want to use
`python3.dll` for the dynamic linkage.
9) Add generated autoconf file
10) Add v:python3_version support
This variable indicates the version of Python3 that Vim was built
against (PY_VERSION_HEX), and will be useful to check whether the Python
library you are loading in dynamically actually fits it. When built with
stable ABI, it will be the limited ABI version instead
(`Py_LIMITED_API`), which indicates the minimum version of Python 3 the
user should have, rather than the exact match. When stable ABI is used,
we won't be exposing PY_VERSION_HEX in this var because it just doesn't
seem necessary to do so (the whole point of stable ABI is the promise
that it will work across versions), and I don't want to confuse the user
with too many variables.
Also, cleaned up some documentation, and added help tags.
11) Fix Python 3.7 compat issues
Fix a couple issues when using limited API < 3.8
- Crash on exit: In Python 3.7, if a heap-allocated type is destroyed
before all instances are, it would cause a crash later. This happens
when we destroyed `OptionsType` before calling `Py_Finalize` when
using the limited API. To make it worse, later versions changed the
semantics and now each instance has a strong reference to its own type
and the recommendation has changed to have each instance de-ref its
own type and have its type in GC traversal. To avoid dealing with
these cross-version variations, we just don't free the heap type. They
are static types in non-limited-API anyway and are designed to last
through the entirety of the app, and we also don't restart the Python
runtime and therefore do not need it to have absolutely 0 leaks.
See:
- https://docs.python.org/3/whatsnew/3.8.html#changes-in-the-c-api
- https://docs.python.org/3/whatsnew/3.9.html#changes-in-the-c-api
- PyIter_Check: This function is not provided in limited APIs older than
3.8. Previously I was trying to mock it out using manual
PyType_GetSlot() but it was brittle and also does not actually work
properly for static types (it will generate a Python error). Just
return false. It does mean using limited API < 3.8 is not recommended
as you lose the functionality to handle iterators, but from playing
with plugins I couldn't find it to be an issue.
- Fix loading of PyIter_Check so it will be done when limited API < 3.8.
Otherwise loading a 3.7 Python lib will fail even if limited API was
specified to use it.
12) Make sure to only load `PyUnicode_AsUTF8AndSize` in needed in limited API
We don't use this function unless limited API >= 3.10, but we were
loading it regardless. Usually it's ok in Unix-like systems where Python
just has a single lib that we load from, but in Windows where there is a
separate python3.dll this would not work as the symbol would not have
been exposed in this more limited DLL file. This makes it much clearer
under what condition is this function needed.
closes: #12032
Signed-off-by: Christian Brabandt <cb@256bit.org>
Co-authored-by: Yee Cheng Chin <ychin.git@gmail.com>
author | Christian Brabandt <cb@256bit.org> |
---|---|
date | Sun, 20 Aug 2023 21:30:04 +0200 |
parents | 695b50472e85 |
children | bede81965821 |
line wrap: on
line source
/* vi:set ts=8 sts=4 sw=4 noet: * * VIM - Vi IMproved by Bram Moolenaar * * Do ":help uganda" in Vim to read copying and usage conditions. * Do ":help credits" in Vim to see a list of people who contributed. * See README.txt for an overview of the Vim source code. */ /* * profiler.c: vim script profiler */ #include "vim.h" #if defined(FEAT_EVAL) || defined(PROTO) # if defined(FEAT_PROFILE) || defined(FEAT_RELTIME) || defined(PROTO) /* * Store the current time in "tm". */ void profile_start(proftime_T *tm) { # ifdef MSWIN QueryPerformanceCounter(tm); # else PROF_GET_TIME(tm); # endif } /* * Compute the elapsed time from "tm" till now and store in "tm". */ void profile_end(proftime_T *tm) { proftime_T now; # ifdef MSWIN QueryPerformanceCounter(&now); tm->QuadPart = now.QuadPart - tm->QuadPart; # else PROF_GET_TIME(&now); tm->tv_fsec = now.tv_fsec - tm->tv_fsec; tm->tv_sec = now.tv_sec - tm->tv_sec; if (tm->tv_fsec < 0) { tm->tv_fsec += TV_FSEC_SEC; --tm->tv_sec; } # endif } /* * Subtract the time "tm2" from "tm". */ void profile_sub(proftime_T *tm, proftime_T *tm2) { # ifdef MSWIN tm->QuadPart -= tm2->QuadPart; # else tm->tv_fsec -= tm2->tv_fsec; tm->tv_sec -= tm2->tv_sec; if (tm->tv_fsec < 0) { tm->tv_fsec += TV_FSEC_SEC; --tm->tv_sec; } # endif } /* * Return a string that represents the time in "tm". * Uses a static buffer! */ char * profile_msg(proftime_T *tm) { static char buf[50]; # ifdef MSWIN LARGE_INTEGER fr; QueryPerformanceFrequency(&fr); sprintf(buf, "%10.6lf", (double)tm->QuadPart / (double)fr.QuadPart); # else sprintf(buf, PROF_TIME_FORMAT, (long)tm->tv_sec, (long)tm->tv_fsec); # endif return buf; } /* * Return a float that represents the time in "tm". */ float_T profile_float(proftime_T *tm) { # ifdef MSWIN LARGE_INTEGER fr; QueryPerformanceFrequency(&fr); return (float_T)tm->QuadPart / (float_T)fr.QuadPart; # else return (float_T)tm->tv_sec + (float_T)tm->tv_fsec / (float_T)TV_FSEC_SEC; # endif } /* * Put the time "msec" past now in "tm". */ void profile_setlimit(long msec, proftime_T *tm) { if (msec <= 0) // no limit profile_zero(tm); else { # ifdef MSWIN LARGE_INTEGER fr; QueryPerformanceCounter(tm); QueryPerformanceFrequency(&fr); tm->QuadPart += (LONGLONG)((double)msec / 1000.0 * (double)fr.QuadPart); # else varnumber_T fsec; // this should be 64 bit if possible PROF_GET_TIME(tm); fsec = (varnumber_T)tm->tv_fsec + (varnumber_T)msec * (varnumber_T)(TV_FSEC_SEC / 1000); tm->tv_fsec = fsec % (long)TV_FSEC_SEC; tm->tv_sec += fsec / (long)TV_FSEC_SEC; # endif } } /* * Return TRUE if the current time is past "tm". */ int profile_passed_limit(proftime_T *tm) { proftime_T now; # ifdef MSWIN if (tm->QuadPart == 0) // timer was not set return FALSE; QueryPerformanceCounter(&now); return (now.QuadPart > tm->QuadPart); # else if (tm->tv_sec == 0) // timer was not set return FALSE; PROF_GET_TIME(&now); return (now.tv_sec > tm->tv_sec || (now.tv_sec == tm->tv_sec && now.tv_fsec > tm->tv_fsec)); # endif } /* * Set the time in "tm" to zero. */ void profile_zero(proftime_T *tm) { # ifdef MSWIN tm->QuadPart = 0; # else tm->tv_fsec = 0; tm->tv_sec = 0; # endif } # endif // FEAT_PROFILE || FEAT_RELTIME #if defined(FEAT_SYN_HL) && defined(FEAT_RELTIME) && defined(FEAT_PROFILE) # if defined(HAVE_MATH_H) # include <math.h> # endif /* * Divide the time "tm" by "count" and store in "tm2". */ void profile_divide(proftime_T *tm, int count, proftime_T *tm2) { if (count == 0) profile_zero(tm2); else { # ifdef MSWIN tm2->QuadPart = tm->QuadPart / count; # else double fsec = (tm->tv_sec * (float_T)TV_FSEC_SEC + tm->tv_fsec) / count; tm2->tv_sec = floor(fsec / (float_T)TV_FSEC_SEC); tm2->tv_fsec = vim_round(fsec - (tm2->tv_sec * (float_T)TV_FSEC_SEC)); # endif } } #endif # if defined(FEAT_PROFILE) || defined(PROTO) /* * Functions for profiling. */ static proftime_T prof_wait_time; /* * Add the time "tm2" to "tm". */ void profile_add(proftime_T *tm, proftime_T *tm2) { # ifdef MSWIN tm->QuadPart += tm2->QuadPart; # else tm->tv_fsec += tm2->tv_fsec; tm->tv_sec += tm2->tv_sec; if (tm->tv_fsec >= TV_FSEC_SEC) { tm->tv_fsec -= TV_FSEC_SEC; ++tm->tv_sec; } # endif } /* * Add the "self" time from the total time and the children's time. */ void profile_self(proftime_T *self, proftime_T *total, proftime_T *children) { // Check that the result won't be negative. Can happen with recursive // calls. #ifdef MSWIN if (total->QuadPart <= children->QuadPart) return; #else if (total->tv_sec < children->tv_sec || (total->tv_sec == children->tv_sec && total->tv_fsec <= children->tv_fsec)) return; #endif profile_add(self, total); profile_sub(self, children); } /* * Get the current waittime. */ static void profile_get_wait(proftime_T *tm) { *tm = prof_wait_time; } /* * Subtract the passed waittime since "tm" from "tma". */ void profile_sub_wait(proftime_T *tm, proftime_T *tma) { proftime_T tm3 = prof_wait_time; profile_sub(&tm3, tm); profile_sub(tma, &tm3); } /* * Return TRUE if "tm1" and "tm2" are equal. */ static int profile_equal(proftime_T *tm1, proftime_T *tm2) { # ifdef MSWIN return (tm1->QuadPart == tm2->QuadPart); # else return (tm1->tv_fsec == tm2->tv_fsec && tm1->tv_sec == tm2->tv_sec); # endif } /* * Return <0, 0 or >0 if "tm1" < "tm2", "tm1" == "tm2" or "tm1" > "tm2" */ int profile_cmp(const proftime_T *tm1, const proftime_T *tm2) { # ifdef MSWIN return (int)(tm2->QuadPart - tm1->QuadPart); # else if (tm1->tv_sec == tm2->tv_sec) return tm2->tv_fsec - tm1->tv_fsec; return tm2->tv_sec - tm1->tv_sec; # endif } static char_u *profile_fname = NULL; static proftime_T pause_time; /* * Reset all profiling information. */ static void profile_reset(void) { int id; int todo; hashtab_T *functbl; hashitem_T *hi; // Reset sourced files. for (id = 1; id <= script_items.ga_len; id++) { scriptitem_T *si = SCRIPT_ITEM(id); if (si->sn_prof_on) { si->sn_prof_on = FALSE; si->sn_pr_force = FALSE; profile_zero(&si->sn_pr_child); si->sn_pr_nest = 0; si->sn_pr_count = 0; profile_zero(&si->sn_pr_total); profile_zero(&si->sn_pr_self); profile_zero(&si->sn_pr_start); profile_zero(&si->sn_pr_children); ga_clear(&si->sn_prl_ga); profile_zero(&si->sn_prl_start); profile_zero(&si->sn_prl_children); profile_zero(&si->sn_prl_wait); si->sn_prl_idx = -1; si->sn_prl_execed = 0; } } // Reset functions. functbl = func_tbl_get(); todo = (int)functbl->ht_used; FOR_ALL_HASHTAB_ITEMS(functbl, hi, todo) { ufunc_T *fp; int i; if (HASHITEM_EMPTY(hi)) continue; todo--; fp = HI2UF(hi); if (fp->uf_prof_initialized) { fp->uf_profiling = 0; fp->uf_prof_initialized = FALSE; fp->uf_tm_count = 0; profile_zero(&fp->uf_tm_total); profile_zero(&fp->uf_tm_self); profile_zero(&fp->uf_tm_children); for (i = 0; i < fp->uf_lines.ga_len; i++) { fp->uf_tml_count[i] = 0; profile_zero(&fp->uf_tml_total[i]); profile_zero(&fp->uf_tml_self[i]); } profile_zero(&fp->uf_tml_start); profile_zero(&fp->uf_tml_children); profile_zero(&fp->uf_tml_wait); fp->uf_tml_idx = -1; fp->uf_tml_execed = 0; } } VIM_CLEAR(profile_fname); } /* * ":profile cmd args" */ void ex_profile(exarg_T *eap) { char_u *e; int len; e = skiptowhite(eap->arg); len = (int)(e - eap->arg); e = skipwhite(e); if (len == 5 && STRNCMP(eap->arg, "start", 5) == 0 && *e != NUL) { VIM_CLEAR(profile_fname); profile_fname = expand_env_save_opt(e, TRUE); do_profiling = PROF_YES; profile_zero(&prof_wait_time); set_vim_var_nr(VV_PROFILING, 1L); } else if (do_profiling == PROF_NONE) emsg(_(e_first_use_profile_start_fname)); else if (STRCMP(eap->arg, "stop") == 0) { profile_dump(); do_profiling = PROF_NONE; set_vim_var_nr(VV_PROFILING, 0L); profile_reset(); } else if (STRCMP(eap->arg, "pause") == 0) { if (do_profiling == PROF_YES) profile_start(&pause_time); do_profiling = PROF_PAUSED; } else if (STRCMP(eap->arg, "continue") == 0) { if (do_profiling == PROF_PAUSED) { profile_end(&pause_time); profile_add(&prof_wait_time, &pause_time); } do_profiling = PROF_YES; } else if (STRCMP(eap->arg, "dump") == 0) profile_dump(); else { // The rest is similar to ":breakadd". ex_breakadd(eap); } } // Command line expansion for :profile. static enum { PEXP_SUBCMD, // expand :profile sub-commands PEXP_FUNC // expand :profile func {funcname} } pexpand_what; static char *pexpand_cmds[] = { "start", "stop", "pause", "continue", "func", "file", "dump", NULL }; /* * Function given to ExpandGeneric() to obtain the profile command * specific expansion. */ char_u * get_profile_name(expand_T *xp UNUSED, int idx) { switch (pexpand_what) { case PEXP_SUBCMD: return (char_u *)pexpand_cmds[idx]; default: return NULL; } } /* * Handle command line completion for :profile command. */ void set_context_in_profile_cmd(expand_T *xp, char_u *arg) { char_u *end_subcmd; // Default: expand subcommands. xp->xp_context = EXPAND_PROFILE; pexpand_what = PEXP_SUBCMD; xp->xp_pattern = arg; end_subcmd = skiptowhite(arg); if (*end_subcmd == NUL) return; if ((end_subcmd - arg == 5 && STRNCMP(arg, "start", 5) == 0) || (end_subcmd - arg == 4 && STRNCMP(arg, "file", 4) == 0)) { xp->xp_context = EXPAND_FILES; xp->xp_pattern = skipwhite(end_subcmd); return; } else if (end_subcmd - arg == 4 && STRNCMP(arg, "func", 4) == 0) { xp->xp_context = EXPAND_USER_FUNC; xp->xp_pattern = skipwhite(end_subcmd); return; } xp->xp_context = EXPAND_NOTHING; } static proftime_T inchar_time; /* * Called when starting to wait for the user to type a character. */ void prof_inchar_enter(void) { profile_start(&inchar_time); } /* * Called when finished waiting for the user to type a character. */ void prof_inchar_exit(void) { profile_end(&inchar_time); profile_add(&prof_wait_time, &inchar_time); } /* * Return TRUE when a function defined in the current script should be * profiled. */ int prof_def_func(void) { if (current_sctx.sc_sid > 0) return SCRIPT_ITEM(current_sctx.sc_sid)->sn_pr_force; return FALSE; } /* * Print the count and times for one function or function line. */ static void prof_func_line( FILE *fd, int count, proftime_T *total, proftime_T *self, int prefer_self) // when equal print only self time { if (count > 0) { fprintf(fd, "%5d ", count); if (prefer_self && profile_equal(total, self)) fprintf(fd, PROF_TIME_BLANK); else fprintf(fd, "%s ", profile_msg(total)); if (!prefer_self && profile_equal(total, self)) fprintf(fd, PROF_TIME_BLANK); else fprintf(fd, "%s ", profile_msg(self)); } else fprintf(fd, " %s%s", PROF_TIME_BLANK, PROF_TIME_BLANK); } static void prof_sort_list( FILE *fd, ufunc_T **sorttab, int st_len, char *title, int prefer_self) // when equal print only self time { int i; ufunc_T *fp; fprintf(fd, "FUNCTIONS SORTED ON %s TIME\n", title); fprintf(fd, "%s function\n", PROF_TOTALS_HEADER); for (i = 0; i < 20 && i < st_len; ++i) { fp = sorttab[i]; prof_func_line(fd, fp->uf_tm_count, &fp->uf_tm_total, &fp->uf_tm_self, prefer_self); if (fp->uf_name[0] == K_SPECIAL) fprintf(fd, " <SNR>%s()\n", fp->uf_name + 3); else fprintf(fd, " %s()\n", fp->uf_name); } fprintf(fd, "\n"); } /* * Compare function for total time sorting. */ static int prof_total_cmp(const void *s1, const void *s2) { ufunc_T *p1, *p2; p1 = *(ufunc_T **)s1; p2 = *(ufunc_T **)s2; return profile_cmp(&p1->uf_tm_total, &p2->uf_tm_total); } /* * Compare function for self time sorting. */ static int prof_self_cmp(const void *s1, const void *s2) { ufunc_T *p1, *p2; p1 = *(ufunc_T **)s1; p2 = *(ufunc_T **)s2; return profile_cmp(&p1->uf_tm_self, &p2->uf_tm_self); } /* * Start profiling function "fp". */ void func_do_profile(ufunc_T *fp) { int len = fp->uf_lines.ga_len; if (!fp->uf_prof_initialized) { if (len == 0) len = 1; // avoid getting error for allocating zero bytes fp->uf_tm_count = 0; profile_zero(&fp->uf_tm_self); profile_zero(&fp->uf_tm_total); if (fp->uf_tml_count == NULL) fp->uf_tml_count = ALLOC_CLEAR_MULT(int, len); if (fp->uf_tml_total == NULL) fp->uf_tml_total = ALLOC_CLEAR_MULT(proftime_T, len); if (fp->uf_tml_self == NULL) fp->uf_tml_self = ALLOC_CLEAR_MULT(proftime_T, len); fp->uf_tml_idx = -1; if (fp->uf_tml_count == NULL || fp->uf_tml_total == NULL || fp->uf_tml_self == NULL) return; // out of memory fp->uf_prof_initialized = TRUE; } fp->uf_profiling = TRUE; } /* * Save time when starting to invoke another script or function. */ static void script_prof_save( proftime_T *tm) // place to store wait time { scriptitem_T *si; if (SCRIPT_ID_VALID(current_sctx.sc_sid)) { si = SCRIPT_ITEM(current_sctx.sc_sid); if (si->sn_prof_on && si->sn_pr_nest++ == 0) profile_start(&si->sn_pr_child); } profile_get_wait(tm); } /* * When calling a function: may initialize for profiling. */ 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)) { info->pi_started_profiling = TRUE; func_do_profile(fp); } if (fp->uf_profiling || (caller != NULL && caller->uf_profiling)) { ++fp->uf_tm_count; profile_start(&info->pi_call_start); profile_zero(&fp->uf_tm_children); } script_prof_save(&info->pi_wait_start); } /* * After calling a function: may handle profiling. profile_may_start_func() * must have been called previously. */ void profile_may_end_func(profinfo_T *info, ufunc_T *fp, ufunc_T *caller) { profile_end(&info->pi_call_start); profile_sub_wait(&info->pi_wait_start, &info->pi_call_start); profile_add(&fp->uf_tm_total, &info->pi_call_start); profile_self(&fp->uf_tm_self, &info->pi_call_start, &fp->uf_tm_children); if (caller != NULL && caller->uf_profiling) { profile_add(&caller->uf_tm_children, &info->pi_call_start); profile_add(&caller->uf_tml_children, &info->pi_call_start); } if (info->pi_started_profiling) // make a ":profdel func" stop profiling the function fp->uf_profiling = FALSE; } /* * Prepare profiling for entering a child or something else that is not * counted for the script/function itself. * Should always be called in pair with prof_child_exit(). */ void prof_child_enter( proftime_T *tm) // place to store waittime { funccall_T *fc = get_current_funccal(); if (fc != NULL && fc->fc_func->uf_profiling) profile_start(&fc->fc_prof_child); script_prof_save(tm); } /* * Take care of time spent in a child. * Should always be called after prof_child_enter(). */ void prof_child_exit( proftime_T *tm) // where waittime was stored { funccall_T *fc = get_current_funccal(); if (fc != NULL && fc->fc_func->uf_profiling) { profile_end(&fc->fc_prof_child); profile_sub_wait(tm, &fc->fc_prof_child); // don't count waiting time profile_add(&fc->fc_func->uf_tm_children, &fc->fc_prof_child); profile_add(&fc->fc_func->uf_tml_children, &fc->fc_prof_child); } script_prof_restore(tm); } /* * Called when starting to read a function line. * "sourcing_lnum" must be correct! * When skipping lines it may not actually be executed, but we won't find out * until later and we need to store the time now. */ void func_line_start(void *cookie, long lnum) { funccall_T *fcp = (funccall_T *)cookie; ufunc_T *fp = fcp->fc_func; if (fp->uf_profiling && lnum >= 1 && lnum <= fp->uf_lines.ga_len) { fp->uf_tml_idx = lnum - 1; // Skip continuation lines. while (fp->uf_tml_idx > 0 && FUNCLINE(fp, fp->uf_tml_idx) == NULL) --fp->uf_tml_idx; fp->uf_tml_execed = FALSE; profile_start(&fp->uf_tml_start); profile_zero(&fp->uf_tml_children); profile_get_wait(&fp->uf_tml_wait); } } /* * Called when actually executing a function line. */ void func_line_exec(void *cookie) { funccall_T *fcp = (funccall_T *)cookie; ufunc_T *fp = fcp->fc_func; if (fp->uf_profiling && fp->uf_tml_idx >= 0) fp->uf_tml_execed = TRUE; } /* * Called when done with a function line. */ void func_line_end(void *cookie) { funccall_T *fcp = (funccall_T *)cookie; ufunc_T *fp = fcp->fc_func; if (fp->uf_profiling && fp->uf_tml_idx >= 0) { if (fp->uf_tml_execed) { ++fp->uf_tml_count[fp->uf_tml_idx]; profile_end(&fp->uf_tml_start); profile_sub_wait(&fp->uf_tml_wait, &fp->uf_tml_start); profile_add(&fp->uf_tml_total[fp->uf_tml_idx], &fp->uf_tml_start); profile_self(&fp->uf_tml_self[fp->uf_tml_idx], &fp->uf_tml_start, &fp->uf_tml_children); } fp->uf_tml_idx = -1; } } /* * Dump the profiling results for all functions in file "fd". */ static void func_dump_profile(FILE *fd) { hashtab_T *functbl; hashitem_T *hi; int todo; ufunc_T *fp; int i; ufunc_T **sorttab; int st_len = 0; char_u *p; functbl = func_tbl_get(); todo = (int)functbl->ht_used; if (todo == 0) return; // nothing to dump sorttab = ALLOC_MULT(ufunc_T *, todo); FOR_ALL_HASHTAB_ITEMS(functbl, hi, todo) { if (!HASHITEM_EMPTY(hi)) { --todo; fp = HI2UF(hi); if (fp->uf_prof_initialized) { if (sorttab != NULL) sorttab[st_len++] = fp; if (fp->uf_name[0] == K_SPECIAL) fprintf(fd, "FUNCTION <SNR>%s()\n", fp->uf_name + 3); else fprintf(fd, "FUNCTION %s()\n", fp->uf_name); if (fp->uf_script_ctx.sc_sid > 0) { p = home_replace_save(NULL, get_scriptname(fp->uf_script_ctx.sc_sid)); if (p != NULL) { fprintf(fd, " Defined: %s:%ld\n", p, (long)fp->uf_script_ctx.sc_lnum); vim_free(p); } } if (fp->uf_tm_count == 1) fprintf(fd, "Called 1 time\n"); else fprintf(fd, "Called %d times\n", fp->uf_tm_count); fprintf(fd, "Total time: %s\n", profile_msg(&fp->uf_tm_total)); fprintf(fd, " Self time: %s\n", profile_msg(&fp->uf_tm_self)); fprintf(fd, "\n"); fprintf(fd, "%s\n", PROF_TOTALS_HEADER); for (i = 0; i < fp->uf_lines.ga_len; ++i) { if (FUNCLINE(fp, i) == NULL) continue; prof_func_line(fd, fp->uf_tml_count[i], &fp->uf_tml_total[i], &fp->uf_tml_self[i], TRUE); fprintf(fd, "%s\n", FUNCLINE(fp, i)); } fprintf(fd, "\n"); } } } if (sorttab != NULL && st_len > 0) { qsort((void *)sorttab, (size_t)st_len, sizeof(ufunc_T *), prof_total_cmp); prof_sort_list(fd, sorttab, st_len, "TOTAL", FALSE); qsort((void *)sorttab, (size_t)st_len, sizeof(ufunc_T *), prof_self_cmp); prof_sort_list(fd, sorttab, st_len, "SELF", TRUE); } vim_free(sorttab); } /* * Start profiling script "fp". */ void script_do_profile(scriptitem_T *si) { si->sn_pr_count = 0; profile_zero(&si->sn_pr_total); profile_zero(&si->sn_pr_self); ga_init2(&si->sn_prl_ga, sizeof(sn_prl_T), 100); si->sn_prl_idx = -1; si->sn_prof_on = TRUE; si->sn_pr_nest = 0; } /* * Count time spent in children after invoking another script or function. */ void script_prof_restore(proftime_T *tm) { scriptitem_T *si; if (!SCRIPT_ID_VALID(current_sctx.sc_sid)) return; si = SCRIPT_ITEM(current_sctx.sc_sid); if (si->sn_prof_on && --si->sn_pr_nest == 0) { profile_end(&si->sn_pr_child); profile_sub_wait(tm, &si->sn_pr_child); // don't count wait time profile_add(&si->sn_pr_children, &si->sn_pr_child); profile_add(&si->sn_prl_children, &si->sn_pr_child); } } /* * Dump the profiling results for all scripts in file "fd". */ static void script_dump_profile(FILE *fd) { int id; scriptitem_T *si; int i; FILE *sfd; sn_prl_T *pp; for (id = 1; id <= script_items.ga_len; ++id) { si = SCRIPT_ITEM(id); if (si->sn_prof_on) { fprintf(fd, "SCRIPT %s\n", si->sn_name); if (si->sn_pr_count == 1) fprintf(fd, "Sourced 1 time\n"); else fprintf(fd, "Sourced %d times\n", si->sn_pr_count); fprintf(fd, "Total time: %s\n", profile_msg(&si->sn_pr_total)); fprintf(fd, " Self time: %s\n", profile_msg(&si->sn_pr_self)); fprintf(fd, "\n"); fprintf(fd, "%s\n", PROF_TOTALS_HEADER); sfd = mch_fopen((char *)si->sn_name, "r"); if (sfd == NULL) fprintf(fd, "Cannot open file!\n"); else { // Keep going till the end of file, so that trailing // continuation lines are listed. for (i = 0; ; ++i) { if (vim_fgets(IObuff, IOSIZE, sfd)) break; // When a line has been truncated, append NL, taking care // of multi-byte characters . if (IObuff[IOSIZE - 2] != NUL && IObuff[IOSIZE - 2] != NL) { int n = IOSIZE - 2; if (enc_utf8) { // Move to the first byte of this char. // utf_head_off() doesn't work, because it checks // for a truncated character. while (n > 0 && (IObuff[n] & 0xc0) == 0x80) --n; } else if (has_mbyte) n -= mb_head_off(IObuff, IObuff + n); IObuff[n] = NL; IObuff[n + 1] = NUL; } if (i < si->sn_prl_ga.ga_len && (pp = &PRL_ITEM(si, i))->snp_count > 0) { fprintf(fd, "%5d ", pp->snp_count); if (profile_equal(&pp->sn_prl_total, &pp->sn_prl_self)) fprintf(fd, " "); else fprintf(fd, "%s ", profile_msg(&pp->sn_prl_total)); fprintf(fd, "%s ", profile_msg(&pp->sn_prl_self)); } else fprintf(fd, " "); fprintf(fd, "%s", IObuff); } fclose(sfd); } fprintf(fd, "\n"); } } } /* * Dump the profiling info. */ void profile_dump(void) { FILE *fd; if (profile_fname == NULL) return; fd = mch_fopen((char *)profile_fname, "w"); if (fd == NULL) semsg(_(e_cant_open_file_str), profile_fname); else { script_dump_profile(fd); func_dump_profile(fd); fclose(fd); } } /* * Called when starting to read a script line. * "sourcing_lnum" must be correct! * When skipping lines it may not actually be executed, but we won't find out * until later and we need to store the time now. */ void script_line_start(void) { scriptitem_T *si; sn_prl_T *pp; if (!SCRIPT_ID_VALID(current_sctx.sc_sid)) return; si = SCRIPT_ITEM(current_sctx.sc_sid); if (si->sn_prof_on && SOURCING_LNUM >= 1) { // Grow the array before starting the timer, so that the time spent // here isn't counted. (void)ga_grow(&si->sn_prl_ga, (int)(SOURCING_LNUM - si->sn_prl_ga.ga_len)); si->sn_prl_idx = SOURCING_LNUM - 1; while (si->sn_prl_ga.ga_len <= si->sn_prl_idx && si->sn_prl_ga.ga_len < si->sn_prl_ga.ga_maxlen) { // Zero counters for a line that was not used before. pp = &PRL_ITEM(si, si->sn_prl_ga.ga_len); pp->snp_count = 0; profile_zero(&pp->sn_prl_total); profile_zero(&pp->sn_prl_self); ++si->sn_prl_ga.ga_len; } si->sn_prl_execed = FALSE; profile_start(&si->sn_prl_start); profile_zero(&si->sn_prl_children); profile_get_wait(&si->sn_prl_wait); } } /* * Called when actually executing a function line. */ void script_line_exec(void) { scriptitem_T *si; if (!SCRIPT_ID_VALID(current_sctx.sc_sid)) return; si = SCRIPT_ITEM(current_sctx.sc_sid); if (si->sn_prof_on && si->sn_prl_idx >= 0) si->sn_prl_execed = TRUE; } /* * Called when done with a script line. */ void script_line_end(void) { scriptitem_T *si; sn_prl_T *pp; if (!SCRIPT_ID_VALID(current_sctx.sc_sid)) return; si = SCRIPT_ITEM(current_sctx.sc_sid); if (si->sn_prof_on && si->sn_prl_idx >= 0 && si->sn_prl_idx < si->sn_prl_ga.ga_len) { if (si->sn_prl_execed) { pp = &PRL_ITEM(si, si->sn_prl_idx); ++pp->snp_count; profile_end(&si->sn_prl_start); profile_sub_wait(&si->sn_prl_wait, &si->sn_prl_start); profile_add(&pp->sn_prl_total, &si->sn_prl_start); profile_self(&pp->sn_prl_self, &si->sn_prl_start, &si->sn_prl_children); } si->sn_prl_idx = -1; } } # endif // FEAT_PROFILE #endif