ref: e6b4528626528c2bf11f760bfc660375195e6055
dir: /sys/src/cmd/python/Modules/_hotshot.c/
/*
* This is the High Performance Python Profiler portion of HotShot.
*/
#include "Python.h"
#include "code.h"
#include "eval.h"
#include "frameobject.h"
#include "structmember.h"
/*
* Which timer to use should be made more configurable, but that should not
* be difficult. This will do for now.
*/
#ifdef MS_WINDOWS
#include <windows.h>
#ifdef HAVE_DIRECT_H
#include <direct.h> /* for getcwd() */
#endif
typedef __int64 hs_time;
#define GETTIMEOFDAY(P_HS_TIME) \
{ LARGE_INTEGER _temp; \
QueryPerformanceCounter(&_temp); \
*(P_HS_TIME) = _temp.QuadPart; }
#else
#ifndef HAVE_GETTIMEOFDAY
#error "This module requires gettimeofday() on non-Windows platforms!"
#endif
#if (defined(PYOS_OS2) && defined(PYCC_GCC)) || defined(__QNX__)
#include <sys/time.h>
#else
#include <sys/resource.h>
#include <sys/times.h>
#endif
typedef struct timeval hs_time;
#endif
#if !defined(__cplusplus) && !defined(inline)
#ifdef __GNUC__
#define inline __inline
#endif
#endif
#ifndef inline
#define inline
#endif
#define BUFFERSIZE 10240
#if defined(PYOS_OS2) && defined(PYCC_GCC)
#define PATH_MAX 260
#endif
#if defined(__sgi) && _COMPILER_VERSION>700 && !defined(PATH_MAX)
/* fix PATH_MAX not being defined with MIPSPro 7.x
if mode is ANSI C (default) */
#define PATH_MAX 1024
#endif
#ifndef PATH_MAX
# ifdef MAX_PATH
# define PATH_MAX MAX_PATH
# elif defined (_POSIX_PATH_MAX)
# define PATH_MAX _POSIX_PATH_MAX
# else
# error "Need a defn. for PATH_MAX in _hotshot.c"
# endif
#endif
typedef struct {
PyObject_HEAD
PyObject *filemap;
PyObject *logfilename;
Py_ssize_t index;
unsigned char buffer[BUFFERSIZE];
FILE *logfp;
int lineevents;
int linetimings;
int frametimings;
/* size_t filled; */
int active;
int next_fileno;
hs_time prev_timeofday;
} ProfilerObject;
typedef struct {
PyObject_HEAD
PyObject *info;
FILE *logfp;
int linetimings;
int frametimings;
} LogReaderObject;
static PyObject * ProfilerError = NULL;
#ifndef MS_WINDOWS
#ifdef GETTIMEOFDAY_NO_TZ
#define GETTIMEOFDAY(ptv) gettimeofday((ptv))
#else
#define GETTIMEOFDAY(ptv) gettimeofday((ptv), (struct timezone *)NULL)
#endif
#endif
/* The log reader... */
PyDoc_STRVAR(logreader_close__doc__,
"close()\n"
"Close the log file, preventing additional records from being read.");
static PyObject *
logreader_close(LogReaderObject *self, PyObject *args)
{
if (self->logfp != NULL) {
fclose(self->logfp);
self->logfp = NULL;
}
Py_INCREF(Py_None);
return Py_None;
}
PyDoc_STRVAR(logreader_fileno__doc__,
"fileno() -> file descriptor\n"
"Returns the file descriptor for the log file, if open.\n"
"Raises ValueError if the log file is closed.");
static PyObject *
logreader_fileno(LogReaderObject *self)
{
if (self->logfp == NULL) {
PyErr_SetString(PyExc_ValueError,
"logreader's file object already closed");
return NULL;
}
return PyInt_FromLong(fileno(self->logfp));
}
/* Log File Format
* ---------------
*
* The log file consists of a sequence of variable-length records.
* Each record is identified with a record type identifier in two
* bits of the first byte. The two bits are the "least significant"
* bits of the byte.
*
* Low bits: Opcode: Meaning:
* 0x00 ENTER enter a frame
* 0x01 EXIT exit a frame
* 0x02 LINENO execution moved onto a different line
* 0x03 OTHER more bits are needed to deecode
*
* If the type is OTHER, the record is not packed so tightly, and the
* remaining bits are used to disambiguate the record type. These
* records are not used as frequently so compaction is not an issue.
* Each of the first three record types has a highly tailored
* structure that allows it to be packed tightly.
*
* The OTHER records have the following identifiers:
*
* First byte: Opcode: Meaning:
* 0x13 ADD_INFO define a key/value pair
* 0x23 DEFINE_FILE define an int->filename mapping
* 0x33 LINE_TIMES indicates if LINENO events have tdeltas
* 0x43 DEFINE_FUNC define a (fileno,lineno)->funcname mapping
* 0x53 FRAME_TIMES indicates if ENTER/EXIT events have tdeltas
*
* Packed Integers
*
* "Packed integers" are non-negative integer values encoded as a
* sequence of bytes. Each byte is encoded such that the most
* significant bit is set if the next byte is also part of the
* integer. Each byte provides bits to the least-significant end of
* the result; the accumulated value must be shifted up to place the
* new bits into the result.
*
* "Modified packed integers" are packed integers where only a portion
* of the first byte is used. In the rest of the specification, these
* are referred to as "MPI(n,name)", where "n" is the number of bits
* discarded from the least-signicant positions of the byte, and
* "name" is a name being given to those "discarded" bits, since they
* are a field themselves.
*
* ENTER records:
*
* MPI(2,type) fileno -- type is 0x00
* PI lineno
* PI tdelta -- iff frame times are enabled
*
* EXIT records
*
* MPI(2,type) tdelta -- type is 0x01; tdelta will be 0
* if frame times are disabled
*
* LINENO records
*
* MPI(2,type) lineno -- type is 0x02
* PI tdelta -- iff LINENO includes it
*
* ADD_INFO records
*
* BYTE type -- always 0x13
* PI len1 -- length of first string
* BYTE string1[len1] -- len1 bytes of string data
* PI len2 -- length of second string
* BYTE string2[len2] -- len2 bytes of string data
*
* DEFINE_FILE records
*
* BYTE type -- always 0x23
* PI fileno
* PI len -- length of filename
* BYTE filename[len] -- len bytes of string data
*
* DEFINE_FUNC records
*
* BYTE type -- always 0x43
* PI fileno
* PI lineno
* PI len -- length of funcname
* BYTE funcname[len] -- len bytes of string data
*
* LINE_TIMES records
*
* This record can be used only before the start of ENTER/EXIT/LINENO
* records. If have_tdelta is true, LINENO records will include the
* tdelta field, otherwise it will be omitted. If this record is not
* given, LINENO records will not contain the tdelta field.
*
* BYTE type -- always 0x33
* BYTE have_tdelta -- 0 if LINENO does *not* have
* timing information
* FRAME_TIMES records
*
* This record can be used only before the start of ENTER/EXIT/LINENO
* records. If have_tdelta is true, ENTER and EXIT records will
* include the tdelta field, otherwise it will be omitted. If this
* record is not given, ENTER and EXIT records will contain the tdelta
* field.
*
* BYTE type -- always 0x53
* BYTE have_tdelta -- 0 if ENTER/EXIT do *not* have
* timing information
*/
#define WHAT_ENTER 0x00
#define WHAT_EXIT 0x01
#define WHAT_LINENO 0x02
#define WHAT_OTHER 0x03 /* only used in decoding */
#define WHAT_ADD_INFO 0x13
#define WHAT_DEFINE_FILE 0x23
#define WHAT_LINE_TIMES 0x33
#define WHAT_DEFINE_FUNC 0x43
#define WHAT_FRAME_TIMES 0x53
#define ERR_NONE 0
#define ERR_EOF -1
#define ERR_EXCEPTION -2
#define ERR_BAD_RECTYPE -3
#define PISIZE (sizeof(int) + 1)
#define MPISIZE (PISIZE + 1)
/* Maximum size of "normal" events -- nothing that contains string data */
#define MAXEVENTSIZE (MPISIZE + PISIZE*2)
/* Unpack a packed integer; if "discard" is non-zero, unpack a modified
* packed integer with "discard" discarded bits.
*/
static int
unpack_packed_int(LogReaderObject *self, int *pvalue, int discard)
{
int c;
int accum = 0;
int bits = 0;
int cont;
do {
/* read byte */
if ((c = fgetc(self->logfp)) == EOF)
return ERR_EOF;
accum |= ((c & 0x7F) >> discard) << bits;
bits += (7 - discard);
cont = c & 0x80;
discard = 0;
} while (cont);
*pvalue = accum;
return 0;
}
/* Unpack a string, which is encoded as a packed integer giving the
* length of the string, followed by the string data.
*/
static int
unpack_string(LogReaderObject *self, PyObject **pvalue)
{
int i;
int len;
int err;
int ch;
char *buf;
if ((err = unpack_packed_int(self, &len, 0)))
return err;
buf = (char *)malloc(len);
if (!buf) {
PyErr_NoMemory();
return ERR_EXCEPTION;
}
for (i=0; i < len; i++) {
ch = fgetc(self->logfp);
buf[i] = ch;
if (ch == EOF) {
free(buf);
return ERR_EOF;
}
}
*pvalue = PyString_FromStringAndSize(buf, len);
free(buf);
if (*pvalue == NULL) {
return ERR_EXCEPTION;
}
return 0;
}
static int
unpack_add_info(LogReaderObject *self)
{
PyObject *key;
PyObject *value = NULL;
int err;
err = unpack_string(self, &key);
if (!err) {
err = unpack_string(self, &value);
if (err)
Py_DECREF(key);
else {
PyObject *list = PyDict_GetItem(self->info, key);
if (list == NULL) {
list = PyList_New(0);
if (list == NULL) {
err = ERR_EXCEPTION;
goto finally;
}
if (PyDict_SetItem(self->info, key, list)) {
Py_DECREF(list);
err = ERR_EXCEPTION;
goto finally;
}
Py_DECREF(list);
}
if (PyList_Append(list, value))
err = ERR_EXCEPTION;
}
}
finally:
Py_XDECREF(key);
Py_XDECREF(value);
return err;
}
static void
eof_error(LogReaderObject *self)
{
fclose(self->logfp);
self->logfp = NULL;
PyErr_SetString(PyExc_EOFError,
"end of file with incomplete profile record");
}
static PyObject *
logreader_tp_iternext(LogReaderObject *self)
{
int c;
int what;
int err = ERR_NONE;
int lineno = -1;
int fileno = -1;
int tdelta = -1;
PyObject *s1 = NULL, *s2 = NULL;
PyObject *result = NULL;
#if 0
unsigned char b0, b1;
#endif
if (self->logfp == NULL) {
PyErr_SetString(ProfilerError,
"cannot iterate over closed LogReader object");
return NULL;
}
restart:
/* decode the record type */
if ((c = fgetc(self->logfp)) == EOF) {
fclose(self->logfp);
self->logfp = NULL;
return NULL;
}
what = c & WHAT_OTHER;
if (what == WHAT_OTHER)
what = c; /* need all the bits for type */
else
ungetc(c, self->logfp); /* type byte includes packed int */
switch (what) {
case WHAT_ENTER:
err = unpack_packed_int(self, &fileno, 2);
if (!err) {
err = unpack_packed_int(self, &lineno, 0);
if (self->frametimings && !err)
err = unpack_packed_int(self, &tdelta, 0);
}
break;
case WHAT_EXIT:
err = unpack_packed_int(self, &tdelta, 2);
break;
case WHAT_LINENO:
err = unpack_packed_int(self, &lineno, 2);
if (self->linetimings && !err)
err = unpack_packed_int(self, &tdelta, 0);
break;
case WHAT_ADD_INFO:
err = unpack_add_info(self);
break;
case WHAT_DEFINE_FILE:
err = unpack_packed_int(self, &fileno, 0);
if (!err) {
err = unpack_string(self, &s1);
if (!err) {
Py_INCREF(Py_None);
s2 = Py_None;
}
}
break;
case WHAT_DEFINE_FUNC:
err = unpack_packed_int(self, &fileno, 0);
if (!err) {
err = unpack_packed_int(self, &lineno, 0);
if (!err)
err = unpack_string(self, &s1);
}
break;
case WHAT_LINE_TIMES:
if ((c = fgetc(self->logfp)) == EOF)
err = ERR_EOF;
else {
self->linetimings = c ? 1 : 0;
goto restart;
}
break;
case WHAT_FRAME_TIMES:
if ((c = fgetc(self->logfp)) == EOF)
err = ERR_EOF;
else {
self->frametimings = c ? 1 : 0;
goto restart;
}
break;
default:
err = ERR_BAD_RECTYPE;
}
if (err == ERR_BAD_RECTYPE) {
PyErr_SetString(PyExc_ValueError,
"unknown record type in log file");
}
else if (err == ERR_EOF) {
eof_error(self);
}
else if (!err) {
result = PyTuple_New(4);
if (result == NULL)
return NULL;
PyTuple_SET_ITEM(result, 0, PyInt_FromLong(what));
PyTuple_SET_ITEM(result, 2, PyInt_FromLong(fileno));
if (s1 == NULL)
PyTuple_SET_ITEM(result, 1, PyInt_FromLong(tdelta));
else
PyTuple_SET_ITEM(result, 1, s1);
if (s2 == NULL)
PyTuple_SET_ITEM(result, 3, PyInt_FromLong(lineno));
else
PyTuple_SET_ITEM(result, 3, s2);
}
/* The only other case is err == ERR_EXCEPTION, in which case the
* exception is already set.
*/
#if 0
b0 = self->buffer[self->index];
b1 = self->buffer[self->index + 1];
if (b0 & 1) {
/* This is a line-number event. */
what = PyTrace_LINE;
lineno = ((b0 & ~1) << 7) + b1;
self->index += 2;
}
else {
what = (b0 & 0x0E) >> 1;
tdelta = ((b0 & 0xF0) << 4) + b1;
if (what == PyTrace_CALL) {
/* we know there's a 2-byte file ID & 2-byte line number */
fileno = ((self->buffer[self->index + 2] << 8)
+ self->buffer[self->index + 3]);
lineno = ((self->buffer[self->index + 4] << 8)
+ self->buffer[self->index + 5]);
self->index += 6;
}
else
self->index += 2;
}
#endif
return result;
}
static void
logreader_dealloc(LogReaderObject *self)
{
if (self->logfp != NULL) {
fclose(self->logfp);
self->logfp = NULL;
}
Py_XDECREF(self->info);
PyObject_Del(self);
}
static PyObject *
logreader_sq_item(LogReaderObject *self, Py_ssize_t index)
{
PyObject *result = logreader_tp_iternext(self);
if (result == NULL && !PyErr_Occurred()) {
PyErr_SetString(PyExc_IndexError, "no more events in log");
return NULL;
}
return result;
}
static void
do_stop(ProfilerObject *self);
static int
flush_data(ProfilerObject *self)
{
/* Need to dump data to the log file... */
size_t written = fwrite(self->buffer, 1, self->index, self->logfp);
if (written == (size_t)self->index)
self->index = 0;
else {
memmove(self->buffer, &self->buffer[written],
self->index - written);
self->index -= written;
if (written == 0) {
char *s = PyString_AsString(self->logfilename);
PyErr_SetFromErrnoWithFilename(PyExc_IOError, s);
do_stop(self);
return -1;
}
}
if (written > 0) {
if (fflush(self->logfp)) {
char *s = PyString_AsString(self->logfilename);
PyErr_SetFromErrnoWithFilename(PyExc_IOError, s);
do_stop(self);
return -1;
}
}
return 0;
}
static inline int
pack_packed_int(ProfilerObject *self, int value)
{
unsigned char partial;
do {
partial = value & 0x7F;
value >>= 7;
if (value)
partial |= 0x80;
self->buffer[self->index] = partial;
self->index++;
} while (value);
return 0;
}
/* Encode a modified packed integer, with a subfield of modsize bits
* containing the value "subfield". The value of subfield is not
* checked to ensure it actually fits in modsize bits.
*/
static inline int
pack_modified_packed_int(ProfilerObject *self, int value,
int modsize, int subfield)
{
const int maxvalues[] = {-1, 1, 3, 7, 15, 31, 63, 127};
int bits = 7 - modsize;
int partial = value & maxvalues[bits];
unsigned char b = subfield | (partial << modsize);
if (partial != value) {
b |= 0x80;
self->buffer[self->index] = b;
self->index++;
return pack_packed_int(self, value >> bits);
}
self->buffer[self->index] = b;
self->index++;
return 0;
}
static int
pack_string(ProfilerObject *self, const char *s, Py_ssize_t len)
{
if (len + PISIZE + self->index >= BUFFERSIZE) {
if (flush_data(self) < 0)
return -1;
}
assert(len < INT_MAX);
if (pack_packed_int(self, (int)len) < 0)
return -1;
memcpy(self->buffer + self->index, s, len);
self->index += len;
return 0;
}
static int
pack_add_info(ProfilerObject *self, const char *s1, const char *s2)
{
Py_ssize_t len1 = strlen(s1);
Py_ssize_t len2 = strlen(s2);
if (len1 + len2 + PISIZE*2 + 1 + self->index >= BUFFERSIZE) {
if (flush_data(self) < 0)
return -1;
}
self->buffer[self->index] = WHAT_ADD_INFO;
self->index++;
if (pack_string(self, s1, len1) < 0)
return -1;
return pack_string(self, s2, len2);
}
static int
pack_define_file(ProfilerObject *self, int fileno, const char *filename)
{
Py_ssize_t len = strlen(filename);
if (len + PISIZE*2 + 1 + self->index >= BUFFERSIZE) {
if (flush_data(self) < 0)
return -1;
}
self->buffer[self->index] = WHAT_DEFINE_FILE;
self->index++;
if (pack_packed_int(self, fileno) < 0)
return -1;
return pack_string(self, filename, len);
}
static int
pack_define_func(ProfilerObject *self, int fileno, int lineno,
const char *funcname)
{
Py_ssize_t len = strlen(funcname);
if (len + PISIZE*3 + 1 + self->index >= BUFFERSIZE) {
if (flush_data(self) < 0)
return -1;
}
self->buffer[self->index] = WHAT_DEFINE_FUNC;
self->index++;
if (pack_packed_int(self, fileno) < 0)
return -1;
if (pack_packed_int(self, lineno) < 0)
return -1;
return pack_string(self, funcname, len);
}
static int
pack_line_times(ProfilerObject *self)
{
if (2 + self->index >= BUFFERSIZE) {
if (flush_data(self) < 0)
return -1;
}
self->buffer[self->index] = WHAT_LINE_TIMES;
self->buffer[self->index + 1] = self->linetimings ? 1 : 0;
self->index += 2;
return 0;
}
static int
pack_frame_times(ProfilerObject *self)
{
if (2 + self->index >= BUFFERSIZE) {
if (flush_data(self) < 0)
return -1;
}
self->buffer[self->index] = WHAT_FRAME_TIMES;
self->buffer[self->index + 1] = self->frametimings ? 1 : 0;
self->index += 2;
return 0;
}
static inline int
pack_enter(ProfilerObject *self, int fileno, int tdelta, int lineno)
{
if (MPISIZE + PISIZE*2 + self->index >= BUFFERSIZE) {
if (flush_data(self) < 0)
return -1;
}
pack_modified_packed_int(self, fileno, 2, WHAT_ENTER);
pack_packed_int(self, lineno);
if (self->frametimings)
return pack_packed_int(self, tdelta);
else
return 0;
}
static inline int
pack_exit(ProfilerObject *self, int tdelta)
{
if (MPISIZE + self->index >= BUFFERSIZE) {
if (flush_data(self) < 0)
return -1;
}
if (self->frametimings)
return pack_modified_packed_int(self, tdelta, 2, WHAT_EXIT);
self->buffer[self->index] = WHAT_EXIT;
self->index++;
return 0;
}
static inline int
pack_lineno(ProfilerObject *self, int lineno)
{
if (MPISIZE + self->index >= BUFFERSIZE) {
if (flush_data(self) < 0)
return -1;
}
return pack_modified_packed_int(self, lineno, 2, WHAT_LINENO);
}
static inline int
pack_lineno_tdelta(ProfilerObject *self, int lineno, int tdelta)
{
if (MPISIZE + PISIZE + self->index >= BUFFERSIZE) {
if (flush_data(self) < 0)
return 0;
}
if (pack_modified_packed_int(self, lineno, 2, WHAT_LINENO) < 0)
return -1;
return pack_packed_int(self, tdelta);
}
static inline int
get_fileno(ProfilerObject *self, PyCodeObject *fcode)
{
/* This is only used for ENTER events. */
PyObject *obj;
PyObject *dict;
int fileno;
obj = PyDict_GetItem(self->filemap, fcode->co_filename);
if (obj == NULL) {
/* first sighting of this file */
dict = PyDict_New();
if (dict == NULL) {
return -1;
}
fileno = self->next_fileno;
obj = Py_BuildValue("iN", fileno, dict);
if (obj == NULL) {
return -1;
}
if (PyDict_SetItem(self->filemap, fcode->co_filename, obj)) {
Py_DECREF(obj);
return -1;
}
self->next_fileno++;
Py_DECREF(obj);
if (pack_define_file(self, fileno,
PyString_AS_STRING(fcode->co_filename)) < 0)
return -1;
}
else {
/* already know this ID */
fileno = PyInt_AS_LONG(PyTuple_GET_ITEM(obj, 0));
dict = PyTuple_GET_ITEM(obj, 1);
}
/* make sure we save a function name for this (fileno, lineno) */
obj = PyInt_FromLong(fcode->co_firstlineno);
if (obj == NULL) {
/* We just won't have it saved; too bad. */
PyErr_Clear();
}
else {
PyObject *name = PyDict_GetItem(dict, obj);
if (name == NULL) {
if (pack_define_func(self, fileno, fcode->co_firstlineno,
PyString_AS_STRING(fcode->co_name)) < 0) {
Py_DECREF(obj);
return -1;
}
if (PyDict_SetItem(dict, obj, fcode->co_name)) {
Py_DECREF(obj);
return -1;
}
}
Py_DECREF(obj);
}
return fileno;
}
static inline int
get_tdelta(ProfilerObject *self)
{
int tdelta;
#ifdef MS_WINDOWS
hs_time tv;
hs_time diff;
GETTIMEOFDAY(&tv);
diff = tv - self->prev_timeofday;
tdelta = (int)diff;
#else
struct timeval tv;
GETTIMEOFDAY(&tv);
tdelta = tv.tv_usec - self->prev_timeofday.tv_usec;
if (tv.tv_sec != self->prev_timeofday.tv_sec)
tdelta += (tv.tv_sec - self->prev_timeofday.tv_sec) * 1000000;
#endif
/* time can go backwards on some multiprocessor systems or by NTP */
if (tdelta < 0)
return 0;
self->prev_timeofday = tv;
return tdelta;
}
/* The workhorse: the profiler callback function. */
static int
tracer_callback(ProfilerObject *self, PyFrameObject *frame, int what,
PyObject *arg)
{
int fileno;
switch (what) {
case PyTrace_CALL:
fileno = get_fileno(self, frame->f_code);
if (fileno < 0)
return -1;
return pack_enter(self, fileno,
self->frametimings ? get_tdelta(self) : -1,
frame->f_code->co_firstlineno);
case PyTrace_RETURN:
return pack_exit(self, get_tdelta(self));
case PyTrace_LINE: /* we only get these events if we asked for them */
if (self->linetimings)
return pack_lineno_tdelta(self, frame->f_lineno,
get_tdelta(self));
else
return pack_lineno(self, frame->f_lineno);
default:
/* ignore PyTrace_EXCEPTION */
break;
}
return 0;
}
/* A couple of useful helper functions. */
#ifdef MS_WINDOWS
static LARGE_INTEGER frequency = {0, 0};
#endif
static unsigned long timeofday_diff = 0;
static unsigned long rusage_diff = 0;
static void
calibrate(void)
{
hs_time tv1, tv2;
#ifdef MS_WINDOWS
hs_time diff;
QueryPerformanceFrequency(&frequency);
#endif
GETTIMEOFDAY(&tv1);
while (1) {
GETTIMEOFDAY(&tv2);
#ifdef MS_WINDOWS
diff = tv2 - tv1;
if (diff != 0) {
timeofday_diff = (unsigned long)diff;
break;
}
#else
if (tv1.tv_sec != tv2.tv_sec || tv1.tv_usec != tv2.tv_usec) {
if (tv1.tv_sec == tv2.tv_sec)
timeofday_diff = tv2.tv_usec - tv1.tv_usec;
else
timeofday_diff = (1000000 - tv1.tv_usec) + tv2.tv_usec;
break;
}
#endif
}
#if defined(MS_WINDOWS) || defined(PYOS_OS2) || \
defined(__VMS) || defined (__QNX__)
rusage_diff = -1;
#else
{
struct rusage ru1, ru2;
getrusage(RUSAGE_SELF, &ru1);
while (1) {
getrusage(RUSAGE_SELF, &ru2);
if (ru1.ru_utime.tv_sec != ru2.ru_utime.tv_sec) {
rusage_diff = ((1000000 - ru1.ru_utime.tv_usec)
+ ru2.ru_utime.tv_usec);
break;
}
else if (ru1.ru_utime.tv_usec != ru2.ru_utime.tv_usec) {
rusage_diff = ru2.ru_utime.tv_usec - ru1.ru_utime.tv_usec;
break;
}
else if (ru1.ru_stime.tv_sec != ru2.ru_stime.tv_sec) {
rusage_diff = ((1000000 - ru1.ru_stime.tv_usec)
+ ru2.ru_stime.tv_usec);
break;
}
else if (ru1.ru_stime.tv_usec != ru2.ru_stime.tv_usec) {
rusage_diff = ru2.ru_stime.tv_usec - ru1.ru_stime.tv_usec;
break;
}
}
}
#endif
}
static void
do_start(ProfilerObject *self)
{
self->active = 1;
GETTIMEOFDAY(&self->prev_timeofday);
if (self->lineevents)
PyEval_SetTrace((Py_tracefunc) tracer_callback, (PyObject *)self);
else
PyEval_SetProfile((Py_tracefunc) tracer_callback, (PyObject *)self);
}
static void
do_stop(ProfilerObject *self)
{
if (self->active) {
self->active = 0;
if (self->lineevents)
PyEval_SetTrace(NULL, NULL);
else
PyEval_SetProfile(NULL, NULL);
}
if (self->index > 0) {
/* Best effort to dump out any remaining data. */
flush_data(self);
}
}
static int
is_available(ProfilerObject *self)
{
if (self->active) {
PyErr_SetString(ProfilerError, "profiler already active");
return 0;
}
if (self->logfp == NULL) {
PyErr_SetString(ProfilerError, "profiler already closed");
return 0;
}
return 1;
}
/* Profiler object interface methods. */
PyDoc_STRVAR(addinfo__doc__,
"addinfo(key, value)\n"
"Insert an ADD_INFO record into the log.");
static PyObject *
profiler_addinfo(ProfilerObject *self, PyObject *args)
{
PyObject *result = NULL;
char *key, *value;
if (PyArg_ParseTuple(args, "ss:addinfo", &key, &value)) {
if (self->logfp == NULL)
PyErr_SetString(ProfilerError, "profiler already closed");
else {
if (pack_add_info(self, key, value) == 0) {
result = Py_None;
Py_INCREF(result);
}
}
}
return result;
}
PyDoc_STRVAR(close__doc__,
"close()\n"
"Shut down this profiler and close the log files, even if its active.");
static PyObject *
profiler_close(ProfilerObject *self)
{
do_stop(self);
if (self->logfp != NULL) {
fclose(self->logfp);
self->logfp = NULL;
}
Py_INCREF(Py_None);
return Py_None;
}
#define fileno__doc__ logreader_fileno__doc__
static PyObject *
profiler_fileno(ProfilerObject *self)
{
if (self->logfp == NULL) {
PyErr_SetString(PyExc_ValueError,
"profiler's file object already closed");
return NULL;
}
return PyInt_FromLong(fileno(self->logfp));
}
PyDoc_STRVAR(runcall__doc__,
"runcall(callable[, args[, kw]]) -> callable()\n"
"Profile a specific function call, returning the result of that call.");
static PyObject *
profiler_runcall(ProfilerObject *self, PyObject *args)
{
PyObject *result = NULL;
PyObject *callargs = NULL;
PyObject *callkw = NULL;
PyObject *callable;
if (PyArg_UnpackTuple(args, "runcall", 1, 3,
&callable, &callargs, &callkw)) {
if (is_available(self)) {
do_start(self);
result = PyEval_CallObjectWithKeywords(callable, callargs, callkw);
do_stop(self);
}
}
return result;
}
PyDoc_STRVAR(runcode__doc__,
"runcode(code, globals[, locals])\n"
"Execute a code object while collecting profile data. If locals is\n"
"omitted, globals is used for the locals as well.");
static PyObject *
profiler_runcode(ProfilerObject *self, PyObject *args)
{
PyObject *result = NULL;
PyCodeObject *code;
PyObject *globals;
PyObject *locals = NULL;
if (PyArg_ParseTuple(args, "O!O!|O:runcode",
&PyCode_Type, &code,
&PyDict_Type, &globals,
&locals)) {
if (is_available(self)) {
if (locals == NULL || locals == Py_None)
locals = globals;
else if (!PyDict_Check(locals)) {
PyErr_SetString(PyExc_TypeError,
"locals must be a dictionary or None");
return NULL;
}
do_start(self);
result = PyEval_EvalCode(code, globals, locals);
do_stop(self);
#if 0
if (!PyErr_Occurred()) {
result = Py_None;
Py_INCREF(result);
}
#endif
}
}
return result;
}
PyDoc_STRVAR(start__doc__,
"start()\n"
"Install this profiler for the current thread.");
static PyObject *
profiler_start(ProfilerObject *self, PyObject *args)
{
PyObject *result = NULL;
if (is_available(self)) {
do_start(self);
result = Py_None;
Py_INCREF(result);
}
return result;
}
PyDoc_STRVAR(stop__doc__,
"stop()\n"
"Remove this profiler from the current thread.");
static PyObject *
profiler_stop(ProfilerObject *self, PyObject *args)
{
PyObject *result = NULL;
if (!self->active)
PyErr_SetString(ProfilerError, "profiler not active");
else {
do_stop(self);
result = Py_None;
Py_INCREF(result);
}
return result;
}
/* Python API support. */
static void
profiler_dealloc(ProfilerObject *self)
{
do_stop(self);
if (self->logfp != NULL)
fclose(self->logfp);
Py_XDECREF(self->filemap);
Py_XDECREF(self->logfilename);
PyObject_Del((PyObject *)self);
}
static PyMethodDef profiler_methods[] = {
{"addinfo", (PyCFunction)profiler_addinfo, METH_VARARGS, addinfo__doc__},
{"close", (PyCFunction)profiler_close, METH_NOARGS, close__doc__},
{"fileno", (PyCFunction)profiler_fileno, METH_NOARGS, fileno__doc__},
{"runcall", (PyCFunction)profiler_runcall, METH_VARARGS, runcall__doc__},
{"runcode", (PyCFunction)profiler_runcode, METH_VARARGS, runcode__doc__},
{"start", (PyCFunction)profiler_start, METH_NOARGS, start__doc__},
{"stop", (PyCFunction)profiler_stop, METH_NOARGS, stop__doc__},
{NULL, NULL}
};
static PyMemberDef profiler_members[] = {
{"frametimings", T_LONG, offsetof(ProfilerObject, linetimings), READONLY},
{"lineevents", T_LONG, offsetof(ProfilerObject, lineevents), READONLY},
{"linetimings", T_LONG, offsetof(ProfilerObject, linetimings), READONLY},
{NULL}
};
static PyObject *
profiler_get_closed(ProfilerObject *self, void *closure)
{
PyObject *result = (self->logfp == NULL) ? Py_True : Py_False;
Py_INCREF(result);
return result;
}
static PyGetSetDef profiler_getsets[] = {
{"closed", (getter)profiler_get_closed, NULL,
PyDoc_STR("True if the profiler's output file has already been closed.")},
{NULL}
};
PyDoc_STRVAR(profiler_object__doc__,
"High-performance profiler object.\n"
"\n"
"Methods:\n"
"\n"
"close(): Stop the profiler and close the log files.\n"
"fileno(): Returns the file descriptor of the log file.\n"
"runcall(): Run a single function call with profiling enabled.\n"
"runcode(): Execute a code object with profiling enabled.\n"
"start(): Install the profiler and return.\n"
"stop(): Remove the profiler.\n"
"\n"
"Attributes (read-only):\n"
"\n"
"closed: True if the profiler has already been closed.\n"
"frametimings: True if ENTER/EXIT events collect timing information.\n"
"lineevents: True if line events are reported to the profiler.\n"
"linetimings: True if line events collect timing information.");
static PyTypeObject ProfilerType = {
PyObject_HEAD_INIT(NULL)
0, /* ob_size */
"_hotshot.ProfilerType", /* tp_name */
(int) sizeof(ProfilerObject), /* tp_basicsize */
0, /* tp_itemsize */
(destructor)profiler_dealloc, /* tp_dealloc */
0, /* tp_print */
0, /* tp_getattr */
0, /* tp_setattr */
0, /* tp_compare */
0, /* tp_repr */
0, /* tp_as_number */
0, /* tp_as_sequence */
0, /* tp_as_mapping */
0, /* tp_hash */
0, /* tp_call */
0, /* tp_str */
PyObject_GenericGetAttr, /* tp_getattro */
0, /* tp_setattro */
0, /* tp_as_buffer */
Py_TPFLAGS_DEFAULT, /* tp_flags */
profiler_object__doc__, /* tp_doc */
0, /* tp_traverse */
0, /* tp_clear */
0, /* tp_richcompare */
0, /* tp_weaklistoffset */
0, /* tp_iter */
0, /* tp_iternext */
profiler_methods, /* tp_methods */
profiler_members, /* tp_members */
profiler_getsets, /* tp_getset */
0, /* tp_base */
0, /* tp_dict */
0, /* tp_descr_get */
0, /* tp_descr_set */
};
static PyMethodDef logreader_methods[] = {
{"close", (PyCFunction)logreader_close, METH_NOARGS,
logreader_close__doc__},
{"fileno", (PyCFunction)logreader_fileno, METH_NOARGS,
logreader_fileno__doc__},
{NULL, NULL}
};
static PyMemberDef logreader_members[] = {
{"info", T_OBJECT, offsetof(LogReaderObject, info), RO,
PyDoc_STR("Dictionary mapping informational keys to lists of values.")},
{NULL}
};
PyDoc_STRVAR(logreader__doc__,
"logreader(filename) --> log-iterator\n\
Create a log-reader for the timing information file.");
static PySequenceMethods logreader_as_sequence = {
0, /* sq_length */
0, /* sq_concat */
0, /* sq_repeat */
(ssizeargfunc)logreader_sq_item, /* sq_item */
0, /* sq_slice */
0, /* sq_ass_item */
0, /* sq_ass_slice */
0, /* sq_contains */
0, /* sq_inplace_concat */
0, /* sq_inplace_repeat */
};
static PyObject *
logreader_get_closed(LogReaderObject *self, void *closure)
{
PyObject *result = (self->logfp == NULL) ? Py_True : Py_False;
Py_INCREF(result);
return result;
}
static PyGetSetDef logreader_getsets[] = {
{"closed", (getter)logreader_get_closed, NULL,
PyDoc_STR("True if the logreader's input file has already been closed.")},
{NULL}
};
static PyTypeObject LogReaderType = {
PyObject_HEAD_INIT(NULL)
0, /* ob_size */
"_hotshot.LogReaderType", /* tp_name */
(int) sizeof(LogReaderObject), /* tp_basicsize */
0, /* tp_itemsize */
(destructor)logreader_dealloc, /* tp_dealloc */
0, /* tp_print */
0, /* tp_getattr */
0, /* tp_setattr */
0, /* tp_compare */
0, /* tp_repr */
0, /* tp_as_number */
&logreader_as_sequence, /* tp_as_sequence */
0, /* tp_as_mapping */
0, /* tp_hash */
0, /* tp_call */
0, /* tp_str */
PyObject_GenericGetAttr, /* tp_getattro */
0, /* tp_setattro */
0, /* tp_as_buffer */
Py_TPFLAGS_DEFAULT, /* tp_flags */
logreader__doc__, /* tp_doc */
0, /* tp_traverse */
0, /* tp_clear */
0, /* tp_richcompare */
0, /* tp_weaklistoffset */
PyObject_SelfIter, /* tp_iter */
(iternextfunc)logreader_tp_iternext,/* tp_iternext */
logreader_methods, /* tp_methods */
logreader_members, /* tp_members */
logreader_getsets, /* tp_getset */
0, /* tp_base */
0, /* tp_dict */
0, /* tp_descr_get */
0, /* tp_descr_set */
};
static PyObject *
hotshot_logreader(PyObject *unused, PyObject *args)
{
LogReaderObject *self = NULL;
char *filename;
int c;
int err = 0;
if (PyArg_ParseTuple(args, "s:logreader", &filename)) {
self = PyObject_New(LogReaderObject, &LogReaderType);
if (self != NULL) {
self->frametimings = 1;
self->linetimings = 0;
self->info = NULL;
self->logfp = fopen(filename, "rb");
if (self->logfp == NULL) {
PyErr_SetFromErrnoWithFilename(PyExc_IOError, filename);
Py_DECREF(self);
self = NULL;
goto finally;
}
self->info = PyDict_New();
if (self->info == NULL) {
Py_DECREF(self);
goto finally;
}
/* read initial info */
for (;;) {
if ((c = fgetc(self->logfp)) == EOF) {
eof_error(self);
break;
}
if (c != WHAT_ADD_INFO) {
ungetc(c, self->logfp);
break;
}
err = unpack_add_info(self);
if (err) {
if (err == ERR_EOF)
eof_error(self);
else
PyErr_SetString(PyExc_RuntimeError,
"unexpected error");
break;
}
}
}
}
finally:
return (PyObject *) self;
}
/* Return a Python string that represents the version number without the
* extra cruft added by revision control, even if the right options were
* given to the "cvs export" command to make it not include the extra
* cruft.
*/
static char *
get_version_string(void)
{
static char *rcsid = "$Revision: 51218 $";
char *rev = rcsid;
char *buffer;
int i = 0;
while (*rev && !isdigit(Py_CHARMASK(*rev)))
++rev;
while (rev[i] != ' ' && rev[i] != '\0')
++i;
buffer = (char *)malloc(i + 1);
if (buffer != NULL) {
memmove(buffer, rev, i);
buffer[i] = '\0';
}
return buffer;
}
/* Write out a RFC 822-style header with various useful bits of
* information to make the output easier to manage.
*/
static int
write_header(ProfilerObject *self)
{
char *buffer;
char cwdbuffer[PATH_MAX];
PyObject *temp;
Py_ssize_t i, len;
buffer = get_version_string();
if (buffer == NULL) {
PyErr_NoMemory();
return -1;
}
pack_add_info(self, "hotshot-version", buffer);
pack_add_info(self, "requested-frame-timings",
(self->frametimings ? "yes" : "no"));
pack_add_info(self, "requested-line-events",
(self->lineevents ? "yes" : "no"));
pack_add_info(self, "requested-line-timings",
(self->linetimings ? "yes" : "no"));
pack_add_info(self, "platform", Py_GetPlatform());
pack_add_info(self, "executable", Py_GetProgramFullPath());
free(buffer);
buffer = (char *) Py_GetVersion();
if (buffer == NULL)
PyErr_Clear();
else
pack_add_info(self, "executable-version", buffer);
#ifdef MS_WINDOWS
PyOS_snprintf(cwdbuffer, sizeof(cwdbuffer), "%I64d", frequency.QuadPart);
pack_add_info(self, "reported-performance-frequency", cwdbuffer);
#else
PyOS_snprintf(cwdbuffer, sizeof(cwdbuffer), "%lu", rusage_diff);
pack_add_info(self, "observed-interval-getrusage", cwdbuffer);
PyOS_snprintf(cwdbuffer, sizeof(cwdbuffer), "%lu", timeofday_diff);
pack_add_info(self, "observed-interval-gettimeofday", cwdbuffer);
#endif
pack_add_info(self, "current-directory",
getcwd(cwdbuffer, sizeof cwdbuffer));
temp = PySys_GetObject("path");
if (temp == NULL || !PyList_Check(temp)) {
PyErr_SetString(PyExc_RuntimeError, "sys.path must be a list");
return -1;
}
len = PyList_GET_SIZE(temp);
for (i = 0; i < len; ++i) {
PyObject *item = PyList_GET_ITEM(temp, i);
buffer = PyString_AsString(item);
if (buffer == NULL) {
pack_add_info(self, "sys-path-entry", "<non-string-path-entry>");
PyErr_Clear();
}
else {
pack_add_info(self, "sys-path-entry", buffer);
}
}
pack_frame_times(self);
pack_line_times(self);
return 0;
}
PyDoc_STRVAR(profiler__doc__,
"profiler(logfilename[, lineevents[, linetimes]]) -> profiler\n\
Create a new profiler object.");
static PyObject *
hotshot_profiler(PyObject *unused, PyObject *args)
{
char *logfilename;
ProfilerObject *self = NULL;
int lineevents = 0;
int linetimings = 1;
if (PyArg_ParseTuple(args, "s|ii:profiler", &logfilename,
&lineevents, &linetimings)) {
self = PyObject_New(ProfilerObject, &ProfilerType);
if (self == NULL)
return NULL;
self->frametimings = 1;
self->lineevents = lineevents ? 1 : 0;
self->linetimings = (lineevents && linetimings) ? 1 : 0;
self->index = 0;
self->active = 0;
self->next_fileno = 0;
self->logfp = NULL;
self->logfilename = PyTuple_GET_ITEM(args, 0);
Py_INCREF(self->logfilename);
self->filemap = PyDict_New();
if (self->filemap == NULL) {
Py_DECREF(self);
return NULL;
}
self->logfp = fopen(logfilename, "wb");
if (self->logfp == NULL) {
Py_DECREF(self);
PyErr_SetFromErrnoWithFilename(PyExc_IOError, logfilename);
return NULL;
}
if (timeofday_diff == 0) {
/* Run this several times since sometimes the first
* doesn't give the lowest values, and we're really trying
* to determine the lowest.
*/
calibrate();
calibrate();
calibrate();
}
if (write_header(self)) {
/* some error occurred, exception has been set */
Py_DECREF(self);
self = NULL;
}
}
return (PyObject *) self;
}
PyDoc_STRVAR(coverage__doc__,
"coverage(logfilename) -> profiler\n\
Returns a profiler that doesn't collect any timing information, which is\n\
useful in building a coverage analysis tool.");
static PyObject *
hotshot_coverage(PyObject *unused, PyObject *args)
{
char *logfilename;
PyObject *result = NULL;
if (PyArg_ParseTuple(args, "s:coverage", &logfilename)) {
result = hotshot_profiler(unused, args);
if (result != NULL) {
ProfilerObject *self = (ProfilerObject *) result;
self->frametimings = 0;
self->linetimings = 0;
self->lineevents = 1;
}
}
return result;
}
PyDoc_VAR(resolution__doc__) =
#ifdef MS_WINDOWS
PyDoc_STR(
"resolution() -> (performance-counter-ticks, update-frequency)\n"
"Return the resolution of the timer provided by the QueryPerformanceCounter()\n"
"function. The first value is the smallest observed change, and the second\n"
"is the result of QueryPerformanceFrequency()."
)
#else
PyDoc_STR(
"resolution() -> (gettimeofday-usecs, getrusage-usecs)\n"
"Return the resolution of the timers provided by the gettimeofday() and\n"
"getrusage() system calls, or -1 if the call is not supported."
)
#endif
;
static PyObject *
hotshot_resolution(PyObject *self, PyObject *unused)
{
if (timeofday_diff == 0) {
calibrate();
calibrate();
calibrate();
}
#ifdef MS_WINDOWS
return Py_BuildValue("ii", timeofday_diff, frequency.LowPart);
#else
return Py_BuildValue("ii", timeofday_diff, rusage_diff);
#endif
}
static PyMethodDef functions[] = {
{"coverage", hotshot_coverage, METH_VARARGS, coverage__doc__},
{"profiler", hotshot_profiler, METH_VARARGS, profiler__doc__},
{"logreader", hotshot_logreader, METH_VARARGS, logreader__doc__},
{"resolution", hotshot_resolution, METH_NOARGS, resolution__doc__},
{NULL, NULL}
};
void
init_hotshot(void)
{
PyObject *module;
LogReaderType.ob_type = &PyType_Type;
ProfilerType.ob_type = &PyType_Type;
module = Py_InitModule("_hotshot", functions);
if (module != NULL) {
char *s = get_version_string();
PyModule_AddStringConstant(module, "__version__", s);
free(s);
Py_INCREF(&LogReaderType);
PyModule_AddObject(module, "LogReaderType",
(PyObject *)&LogReaderType);
Py_INCREF(&ProfilerType);
PyModule_AddObject(module, "ProfilerType",
(PyObject *)&ProfilerType);
if (ProfilerError == NULL)
ProfilerError = PyErr_NewException("hotshot.ProfilerError",
NULL, NULL);
if (ProfilerError != NULL) {
Py_INCREF(ProfilerError);
PyModule_AddObject(module, "ProfilerError", ProfilerError);
}
PyModule_AddIntConstant(module, "WHAT_ENTER", WHAT_ENTER);
PyModule_AddIntConstant(module, "WHAT_EXIT", WHAT_EXIT);
PyModule_AddIntConstant(module, "WHAT_LINENO", WHAT_LINENO);
PyModule_AddIntConstant(module, "WHAT_OTHER", WHAT_OTHER);
PyModule_AddIntConstant(module, "WHAT_ADD_INFO", WHAT_ADD_INFO);
PyModule_AddIntConstant(module, "WHAT_DEFINE_FILE", WHAT_DEFINE_FILE);
PyModule_AddIntConstant(module, "WHAT_DEFINE_FUNC", WHAT_DEFINE_FUNC);
PyModule_AddIntConstant(module, "WHAT_LINE_TIMES", WHAT_LINE_TIMES);
}
}