From c69ebe8d50529eae281275c841428eb9b375a442 Mon Sep 17 00:00:00 2001 From: Nicholas Bastin Date: Wed, 24 Mar 2004 21:57:10 +0000 Subject: Enable the profiling of C functions (builtins and extensions) --- Doc/api/init.tex | 28 ++++++++++++++++++++---- Doc/lib/libpdb.tex | 15 +++++++++++-- Include/pystate.h | 3 +++ Lib/bdb.py | 6 +++++ Lib/profile.py | 31 +++++++++++++++++++++++++- Lib/test/output/test_profile | 5 ++++- Lib/test/test_profilehooks.py | 11 +++++++++- Misc/NEWS | 3 +++ Python/ceval.c | 51 ++++++++++++++++++++++++++++++++++++++++--- Python/sysmodule.c | 7 +++--- 10 files changed, 145 insertions(+), 15 deletions(-) diff --git a/Doc/api/init.tex b/Doc/api/init.tex index 2f21168..7949690 100644 --- a/Doc/api/init.tex +++ b/Doc/api/init.tex @@ -726,16 +726,21 @@ previous versions. The first parameter is the object passed to the registration function as \var{obj}, \var{frame} is the frame object to which the event pertains, \var{what} is one of the constants - \constant{PyTrace_CALL}, \constant{PyTrace_EXCEPT}, - \constant{PyTrace_LINE} or \constant{PyTrace_RETURN}, and \var{arg} + \constant{PyTrace_CALL}, \constant{PyTrace_EXCEPTION}, + \constant{PyTrace_LINE}, \constant{PyTrace_RETURN}, + \constant{PyTrace_C_CALL}, \constant{PyTrace_C_EXCEPTION}, + or \constant{PyTrace_C_RETURN}, and \var{arg} depends on the value of \var{what}: \begin{tableii}{l|l}{constant}{Value of \var{what}}{Meaning of \var{arg}} \lineii{PyTrace_CALL}{Always \NULL.} - \lineii{PyTrace_EXCEPT}{Exception information as returned by + \lineii{PyTrace_EXCEPTION}{Exception information as returned by \function{sys.exc_info()}.} \lineii{PyTrace_LINE}{Always \NULL.} \lineii{PyTrace_RETURN}{Value being returned to the caller.} + \lineii{PyTrace_C_CALL}{Name of function being called.} + \lineii{PyTrace_C_EXCEPTION}{Always \NULL.} + \lineii{PyTrace_C_RETURN}{Always \NULL.} \end{tableii} \end{ctypedesc} @@ -747,7 +752,7 @@ previous versions. control transfer to the Python bytecode in the corresponding frame. \end{cvardesc} -\begin{cvardesc}{int}{PyTrace_EXCEPT} +\begin{cvardesc}{int}{PyTrace_EXCEPTION} The value of the \var{what} parameter to a \ctype{Py_tracefunc} function when an exception has been raised. The callback function is called with this value for \var{what} when after any bytecode is @@ -770,6 +775,21 @@ previous versions. functions when a call is returning without propagating an exception. \end{cvardesc} +\begin{cvardesc}{int}{PyTrace_C_CALL} + The value for the \var{what} parameter to \ctype{Py_tracefunc} + functions when a C function is about to be called. +\end{cvardesc} + +\begin{cvardesc}{int}{PyTrace_C_EXCEPTION} + The value for the \var{what} parameter to \ctype{Py_tracefunc} + functions when a C function has thrown an exception. +\end{cvardesc} + +\begin{cvardesc}{int}{PyTrace_C_RETURN} + The value for the \var{what} parameter to \ctype{Py_tracefunc} + functions when a C function has returned. +\end{cvardesc} + \begin{cfuncdesc}{void}{PyEval_SetProfile}{Py_tracefunc func, PyObject *obj} Set the profiler function to \var{func}. The \var{obj} parameter is passed to the function as its first parameter, and may be any Python diff --git a/Doc/lib/libpdb.tex b/Doc/lib/libpdb.tex index ee9ab91..2229dc8 100644 --- a/Doc/lib/libpdb.tex +++ b/Doc/lib/libpdb.tex @@ -350,8 +350,9 @@ Some changes were made to the interpreter: Trace functions have three arguments: \var{frame}, \var{event}, and \var{arg}. \var{frame} is the current stack frame. \var{event} is a -string: \code{'call'}, \code{'line'}, \code{'return'} or -\code{'exception'}. \var{arg} depends on the event type. +string: \code{'call'}, \code{'line'}, \code{'return'}, \code{'exception'}, + \code{'c_call'}, \code{'c_return'}, or \code{'c_exception'}. \var{arg} + depends on the event type. The global trace function is invoked (with \var{event} set to \code{'call'}) whenever a new local scope is entered; it should return @@ -390,6 +391,16 @@ An exception has occurred. The local trace function is called; \var{traceback})}; the return value specifies the new local trace function. +\item[\code{'c_call'}] +A C function is about to be called. This may be an extension function +or a builtin. \var{arg} is the C function name. + +\item[\code{'c_return'}] +A C function has returned. \var{arg} is \code{None}. + +\item[\code{'c_exception'}] +A C function has thrown an exception. \var{arg} is \code{None}. + \end{description} Note that as an exception is propagated down the chain of callers, an diff --git a/Include/pystate.h b/Include/pystate.h index ff35969..353a102 100644 --- a/Include/pystate.h +++ b/Include/pystate.h @@ -45,6 +45,9 @@ typedef int (*Py_tracefunc)(PyObject *, struct _frame *, int, PyObject *); #define PyTrace_EXCEPTION 1 #define PyTrace_LINE 2 #define PyTrace_RETURN 3 +#define PyTrace_C_CALL 4 +#define PyTrace_C_EXCEPTION 5 +#define PyTrace_C_RETURN 6 typedef struct _ts { diff --git a/Lib/bdb.py b/Lib/bdb.py index 11ed212..19a9722 100644 --- a/Lib/bdb.py +++ b/Lib/bdb.py @@ -52,6 +52,12 @@ class Bdb: return self.dispatch_return(frame, arg) if event == 'exception': return self.dispatch_exception(frame, arg) + if event == 'c_call': + return self.trace_dispatch + if event == 'c_exception': + return self.trace_dispatch + if event == 'c_return': + return self.trace_dispatch print 'bdb.Bdb.dispatch: unknown debugging event:', repr(event) return self.trace_dispatch diff --git a/Lib/profile.py b/Lib/profile.py index cf22377..99a5b62 100755 --- a/Lib/profile.py +++ b/Lib/profile.py @@ -163,6 +163,7 @@ class Profile: self.timings = {} self.cur = None self.cmd = "" + self.c_func_name = "" if bias is None: bias = self.bias @@ -214,6 +215,9 @@ class Profile: t = timer() t = t[0] + t[1] - self.t - self.bias + if event == "c_call": + self.c_func_name = arg + if self.dispatch[event](self, frame,t): t = timer() self.t = t[0] + t[1] @@ -227,7 +231,11 @@ class Profile: def trace_dispatch_i(self, frame, event, arg): timer = self.timer t = timer() - self.t - self.bias - if self.dispatch[event](self, frame,t): + + if event == "c_call": + self.c_func_name = arg + + if self.dispatch[event](self, frame, t): self.t = timer() else: self.t = timer() - t # put back unrecorded delta @@ -238,6 +246,10 @@ class Profile: def trace_dispatch_mac(self, frame, event, arg): timer = self.timer t = timer()/60.0 - self.t - self.bias + + if event == "c_call": + self.c_func_name = arg + if self.dispatch[event](self, frame, t): self.t = timer()/60.0 else: @@ -249,6 +261,9 @@ class Profile: get_time = self.get_time t = get_time() - self.t - self.bias + if event == "c_call": + self.c_func_name = arg + if self.dispatch[event](self, frame, t): self.t = get_time() else: @@ -291,6 +306,17 @@ class Profile: timings[fn] = 0, 0, 0, 0, {} return 1 + def trace_dispatch_c_call (self, frame, t): + fn = ("", 0, self.c_func_name) + self.cur = (t, 0, 0, fn, frame, self.cur) + timings = self.timings + if timings.has_key(fn): + cc, ns, tt, ct, callers = timings[fn] + timings[fn] = cc, ns+1, tt, ct, callers + else: + timings[fn] = 0, 0, 0, 0, {} + return 1 + def trace_dispatch_return(self, frame, t): if frame is not self.cur[-2]: assert frame is self.cur[-2].f_back, ("Bad return", self.cur[-3]) @@ -333,6 +359,9 @@ class Profile: "call": trace_dispatch_call, "exception": trace_dispatch_exception, "return": trace_dispatch_return, + "c_call": trace_dispatch_c_call, + "c_exception": trace_dispatch_exception, + "c_return": trace_dispatch_return, } diff --git a/Lib/test/output/test_profile b/Lib/test/output/test_profile index 917a18e..b46bb6a 100644 --- a/Lib/test/output/test_profile +++ b/Lib/test/output/test_profile @@ -1,9 +1,12 @@ test_profile - 53 function calls in 1.000 CPU seconds + 74 function calls in 1.000 CPU seconds Ordered by: standard name ncalls tottime percall cumtime percall filename:lineno(function) + 12 0.000 0.000 0.012 0.001 :0(hasattr) + 8 0.000 0.000 0.000 0.000 :0(range) + 1 0.000 0.000 0.000 0.000 :0(setprofile) 1 0.000 0.000 1.000 1.000 :1(?) 0 0.000 0.000 profile:0(profiler) 1 0.000 0.000 1.000 1.000 profile:0(testfunc()) diff --git a/Lib/test/test_profilehooks.py b/Lib/test/test_profilehooks.py index ac8ebd8..53f882a 100644 --- a/Lib/test/test_profilehooks.py +++ b/Lib/test/test_profilehooks.py @@ -11,7 +11,10 @@ class HookWatcher: self.events = [] def callback(self, frame, event, arg): - self.add_event(event, frame) + if (event == "call" + or event == "return" + or event == "exception"): + self.add_event(event, frame) def add_event(self, event, frame=None): """Add an event to the log.""" @@ -56,10 +59,16 @@ class ProfileSimulator(HookWatcher): self.testcase.fail( "the profiler should never receive exception events") + def trace_pass(self, frame): + pass + dispatch = { 'call': trace_call, 'exception': trace_exception, 'return': trace_return, + 'c_call': trace_pass, + 'c_return': trace_pass, + 'c_exception': trace_pass, } diff --git a/Misc/NEWS b/Misc/NEWS index afd8ea6..724ccab 100644 --- a/Misc/NEWS +++ b/Misc/NEWS @@ -12,6 +12,9 @@ What's New in Python 2.4 alpha 1? Core and builtins ----------------- +- Enabled the profiling of C extension functions (and builtins) - check + new documentation and modified profiler and bdb modules for more details + - Set file.name to the object passed to open (instead of a new string) - Moved tracebackobject into traceback.h and renamed to PyTracebackObject diff --git a/Python/ceval.c b/Python/ceval.c index b48e042..e136cb0 100644 --- a/Python/ceval.c +++ b/Python/ceval.c @@ -536,9 +536,7 @@ _Py_CheckRecursiveCall(char *where) return 0; } - /* Status code for main loop (reason for stack unwind) */ - enum why_code { WHY_NOT, /* No error */ WHY_EXCEPTION, /* Exception occurred */ @@ -3425,6 +3423,42 @@ err_args(PyObject *func, int flags, int nargs) nargs); } +#define BEGIN_C_TRACE \ +if (tstate->use_tracing) { \ + if (tstate->c_profilefunc != NULL) { \ + PyObject *func_name = \ + PyString_FromString (((PyCFunctionObject *) \ + func)->m_ml->ml_name); \ + are_tracing = 1; \ + if (call_trace(tstate->c_profilefunc, \ + tstate->c_profileobj, \ + tstate->frame, PyTrace_C_CALL, \ + func_name)) \ + { return NULL; } \ + Py_DECREF (func_name); \ + } \ + } + +#define END_C_TRACE \ + if (tstate->use_tracing && are_tracing) { \ + if (tstate->c_profilefunc != NULL) { \ + if (x == NULL) { \ + if (call_trace (tstate->c_profilefunc, \ + tstate->c_profileobj, \ + tstate->frame, PyTrace_C_EXCEPTION, \ + NULL)) \ + { return NULL; } \ + } else { \ + if (call_trace(tstate->c_profilefunc, \ + tstate->c_profileobj, \ + tstate->frame, PyTrace_C_RETURN, \ + NULL)) \ + { return NULL; } \ + } \ + } \ + } + + static PyObject * call_function(PyObject ***pp_stack, int oparg) { @@ -3435,6 +3469,10 @@ call_function(PyObject ***pp_stack, int oparg) PyObject *func = *pfunc; PyObject *x, *w; + int are_tracing = 0; + + PyThreadState *tstate = PyThreadState_GET(); + /* Always dispatch PyCFunction first, because these are presumed to be the most frequent callable object. */ @@ -3444,11 +3482,16 @@ call_function(PyObject ***pp_stack, int oparg) if (flags & (METH_NOARGS | METH_O)) { PyCFunction meth = PyCFunction_GET_FUNCTION(func); PyObject *self = PyCFunction_GET_SELF(func); - if (flags & METH_NOARGS && na == 0) + if (flags & METH_NOARGS && na == 0) { + BEGIN_C_TRACE x = (*meth)(self, NULL); + END_C_TRACE + } else if (flags & METH_O && na == 1) { PyObject *arg = EXT_POP(*pp_stack); + BEGIN_C_TRACE x = (*meth)(self, arg); + END_C_TRACE Py_DECREF(arg); } else { @@ -3459,7 +3502,9 @@ call_function(PyObject ***pp_stack, int oparg) else { PyObject *callargs; callargs = load_args(pp_stack, na); + BEGIN_C_TRACE x = PyCFunction_Call(func, callargs, NULL); + END_C_TRACE Py_XDECREF(callargs); } } else { diff --git a/Python/sysmodule.c b/Python/sysmodule.c index c98e9f1..4e7035a 100644 --- a/Python/sysmodule.c +++ b/Python/sysmodule.c @@ -272,15 +272,16 @@ operating system filenames." * Cached interned string objects used for calling the profile and * trace functions. Initialized by trace_init(). */ -static PyObject *whatstrings[4] = {NULL, NULL, NULL, NULL}; +static PyObject *whatstrings[7] = {NULL, NULL, NULL, NULL, NULL, NULL, NULL}; static int trace_init(void) { - static char *whatnames[4] = {"call", "exception", "line", "return"}; + static char *whatnames[7] = {"call", "exception", "line", "return", + "c_call", "c_exception", "c_return"}; PyObject *name; int i; - for (i = 0; i < 4; ++i) { + for (i = 0; i < 7; ++i) { if (whatstrings[i] == NULL) { name = PyString_InternFromString(whatnames[i]); if (name == NULL) -- cgit v0.12