Enable the profiling of C functions (builtins and extensions)
This commit is contained in:
Nicholas Bastin
parent
a1dde13389
commit
c69ebe8d50
|
|
@ -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
|
||||
|
|
|
|||
|
|
@ -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
|
||||
|
|
|
|||
|
|
@ -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 {
|
||||
|
||||
|
|
|
|||
|
|
@ -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
|
||||
|
||||
|
|
|
|||
|
|
@ -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,
|
||||
}
|
||||
|
||||
|
||||
|
|
|
|||
|
|
@ -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 <string>:1(?)
|
||||
0 0.000 0.000 profile:0(profiler)
|
||||
1 0.000 0.000 1.000 1.000 profile:0(testfunc())
|
||||
|
|
|
|||
|
|
@ -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,
|
||||
}
|
||||
|
||||
|
||||
|
|
|
|||
|
|
@ -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
|
||||
|
|
|
|||
|
|
@ -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 {
|
||||
|
|
|
|||
|
|
@ -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)
|
||||
|
|
|
|||
Loading…
Reference in New Issue