2 * This is the High Performance Python Profiler portion of HotShot.
8 #include "frameobject.h"
9 #include "structmember.h"
12 * Which timer to use should be made more configurable, but that should not
13 * be difficult. This will do for now.
19 #include <direct.h> /* for getcwd() */
22 typedef __int64 hs_time
;
23 #define GETTIMEOFDAY(P_HS_TIME) \
24 { LARGE_INTEGER _temp; \
25 QueryPerformanceCounter(&_temp); \
26 *(P_HS_TIME) = _temp.QuadPart; }
30 #ifndef HAVE_GETTIMEOFDAY
31 #error "This module requires gettimeofday() on non-Windows platforms!"
33 #if (defined(PYOS_OS2) && defined(PYCC_GCC)) || defined(__QNX__)
36 #include <sys/resource.h>
37 #include <sys/times.h>
39 typedef struct timeval hs_time
;
42 #if !defined(__cplusplus) && !defined(inline)
44 #define inline __inline
52 #define BUFFERSIZE 10240
54 #if defined(PYOS_OS2) && defined(PYCC_GCC)
58 #if defined(__sgi) && _COMPILER_VERSION>700 && !defined(PATH_MAX)
59 /* fix PATH_MAX not being defined with MIPSPro 7.x
60 if mode is ANSI C (default) */
66 # define PATH_MAX MAX_PATH
67 # elif defined (_POSIX_PATH_MAX)
68 # define PATH_MAX _POSIX_PATH_MAX
70 # error "Need a defn. for PATH_MAX in _hotshot.c"
77 PyObject
*logfilename
;
79 unsigned char buffer
[BUFFERSIZE
];
87 hs_time prev_timeofday
;
98 static PyObject
* ProfilerError
= NULL
;
102 #ifdef GETTIMEOFDAY_NO_TZ
103 #define GETTIMEOFDAY(ptv) gettimeofday((ptv))
105 #define GETTIMEOFDAY(ptv) gettimeofday((ptv), (struct timezone *)NULL)
110 /* The log reader... */
112 PyDoc_STRVAR(logreader_close__doc__
,
114 "Close the log file, preventing additional records from being read.");
117 logreader_close(LogReaderObject
*self
, PyObject
*args
)
119 if (self
->logfp
!= NULL
) {
128 PyDoc_STRVAR(logreader_fileno__doc__
,
129 "fileno() -> file descriptor\n"
130 "Returns the file descriptor for the log file, if open.\n"
131 "Raises ValueError if the log file is closed.");
134 logreader_fileno(LogReaderObject
*self
)
136 if (self
->logfp
== NULL
) {
137 PyErr_SetString(PyExc_ValueError
,
138 "logreader's file object already closed");
141 return PyInt_FromLong(fileno(self
->logfp
));
148 * The log file consists of a sequence of variable-length records.
149 * Each record is identified with a record type identifier in two
150 * bits of the first byte. The two bits are the "least significant"
153 * Low bits: Opcode: Meaning:
154 * 0x00 ENTER enter a frame
155 * 0x01 EXIT exit a frame
156 * 0x02 LINENO execution moved onto a different line
157 * 0x03 OTHER more bits are needed to deecode
159 * If the type is OTHER, the record is not packed so tightly, and the
160 * remaining bits are used to disambiguate the record type. These
161 * records are not used as frequently so compaction is not an issue.
162 * Each of the first three record types has a highly tailored
163 * structure that allows it to be packed tightly.
165 * The OTHER records have the following identifiers:
167 * First byte: Opcode: Meaning:
168 * 0x13 ADD_INFO define a key/value pair
169 * 0x23 DEFINE_FILE define an int->filename mapping
170 * 0x33 LINE_TIMES indicates if LINENO events have tdeltas
171 * 0x43 DEFINE_FUNC define a (fileno,lineno)->funcname mapping
172 * 0x53 FRAME_TIMES indicates if ENTER/EXIT events have tdeltas
176 * "Packed integers" are non-negative integer values encoded as a
177 * sequence of bytes. Each byte is encoded such that the most
178 * significant bit is set if the next byte is also part of the
179 * integer. Each byte provides bits to the least-significant end of
180 * the result; the accumulated value must be shifted up to place the
181 * new bits into the result.
183 * "Modified packed integers" are packed integers where only a portion
184 * of the first byte is used. In the rest of the specification, these
185 * are referred to as "MPI(n,name)", where "n" is the number of bits
186 * discarded from the least-signicant positions of the byte, and
187 * "name" is a name being given to those "discarded" bits, since they
188 * are a field themselves.
192 * MPI(2,type) fileno -- type is 0x00
194 * PI tdelta -- iff frame times are enabled
198 * MPI(2,type) tdelta -- type is 0x01; tdelta will be 0
199 * if frame times are disabled
203 * MPI(2,type) lineno -- type is 0x02
204 * PI tdelta -- iff LINENO includes it
208 * BYTE type -- always 0x13
209 * PI len1 -- length of first string
210 * BYTE string1[len1] -- len1 bytes of string data
211 * PI len2 -- length of second string
212 * BYTE string2[len2] -- len2 bytes of string data
214 * DEFINE_FILE records
216 * BYTE type -- always 0x23
218 * PI len -- length of filename
219 * BYTE filename[len] -- len bytes of string data
221 * DEFINE_FUNC records
223 * BYTE type -- always 0x43
226 * PI len -- length of funcname
227 * BYTE funcname[len] -- len bytes of string data
231 * This record can be used only before the start of ENTER/EXIT/LINENO
232 * records. If have_tdelta is true, LINENO records will include the
233 * tdelta field, otherwise it will be omitted. If this record is not
234 * given, LINENO records will not contain the tdelta field.
236 * BYTE type -- always 0x33
237 * BYTE have_tdelta -- 0 if LINENO does *not* have
239 * FRAME_TIMES records
241 * This record can be used only before the start of ENTER/EXIT/LINENO
242 * records. If have_tdelta is true, ENTER and EXIT records will
243 * include the tdelta field, otherwise it will be omitted. If this
244 * record is not given, ENTER and EXIT records will contain the tdelta
247 * BYTE type -- always 0x53
248 * BYTE have_tdelta -- 0 if ENTER/EXIT do *not* have
252 #define WHAT_ENTER 0x00
253 #define WHAT_EXIT 0x01
254 #define WHAT_LINENO 0x02
255 #define WHAT_OTHER 0x03 /* only used in decoding */
256 #define WHAT_ADD_INFO 0x13
257 #define WHAT_DEFINE_FILE 0x23
258 #define WHAT_LINE_TIMES 0x33
259 #define WHAT_DEFINE_FUNC 0x43
260 #define WHAT_FRAME_TIMES 0x53
264 #define ERR_EXCEPTION -2
265 #define ERR_BAD_RECTYPE -3
267 #define PISIZE (sizeof(int) + 1)
268 #define MPISIZE (PISIZE + 1)
270 /* Maximum size of "normal" events -- nothing that contains string data */
271 #define MAXEVENTSIZE (MPISIZE + PISIZE*2)
274 /* Unpack a packed integer; if "discard" is non-zero, unpack a modified
275 * packed integer with "discard" discarded bits.
278 unpack_packed_int(LogReaderObject
*self
, int *pvalue
, int discard
)
287 if ((c
= fgetc(self
->logfp
)) == EOF
)
289 accum
|= ((c
& 0x7F) >> discard
) << bits
;
290 bits
+= (7 - discard
);
300 /* Unpack a string, which is encoded as a packed integer giving the
301 * length of the string, followed by the string data.
304 unpack_string(LogReaderObject
*self
, PyObject
**pvalue
)
312 if ((err
= unpack_packed_int(self
, &len
, 0)))
315 buf
= (char *)malloc(len
);
318 return ERR_EXCEPTION
;
321 for (i
=0; i
< len
; i
++) {
322 ch
= fgetc(self
->logfp
);
329 *pvalue
= PyString_FromStringAndSize(buf
, len
);
331 if (*pvalue
== NULL
) {
332 return ERR_EXCEPTION
;
339 unpack_add_info(LogReaderObject
*self
)
342 PyObject
*value
= NULL
;
345 err
= unpack_string(self
, &key
);
347 err
= unpack_string(self
, &value
);
351 PyObject
*list
= PyDict_GetItem(self
->info
, key
);
353 list
= PyList_New(0);
358 if (PyDict_SetItem(self
->info
, key
, list
)) {
365 if (PyList_Append(list
, value
))
377 eof_error(LogReaderObject
*self
)
381 PyErr_SetString(PyExc_EOFError
,
382 "end of file with incomplete profile record");
386 logreader_tp_iternext(LogReaderObject
*self
)
394 PyObject
*s1
= NULL
, *s2
= NULL
;
395 PyObject
*result
= NULL
;
397 unsigned char b0
, b1
;
400 if (self
->logfp
== NULL
) {
401 PyErr_SetString(ProfilerError
,
402 "cannot iterate over closed LogReader object");
407 /* decode the record type */
408 if ((c
= fgetc(self
->logfp
)) == EOF
) {
413 what
= c
& WHAT_OTHER
;
414 if (what
== WHAT_OTHER
)
415 what
= c
; /* need all the bits for type */
417 ungetc(c
, self
->logfp
); /* type byte includes packed int */
421 err
= unpack_packed_int(self
, &fileno
, 2);
423 err
= unpack_packed_int(self
, &lineno
, 0);
424 if (self
->frametimings
&& !err
)
425 err
= unpack_packed_int(self
, &tdelta
, 0);
429 err
= unpack_packed_int(self
, &tdelta
, 2);
432 err
= unpack_packed_int(self
, &lineno
, 2);
433 if (self
->linetimings
&& !err
)
434 err
= unpack_packed_int(self
, &tdelta
, 0);
437 err
= unpack_add_info(self
);
439 case WHAT_DEFINE_FILE
:
440 err
= unpack_packed_int(self
, &fileno
, 0);
442 err
= unpack_string(self
, &s1
);
449 case WHAT_DEFINE_FUNC
:
450 err
= unpack_packed_int(self
, &fileno
, 0);
452 err
= unpack_packed_int(self
, &lineno
, 0);
454 err
= unpack_string(self
, &s1
);
457 case WHAT_LINE_TIMES
:
458 if ((c
= fgetc(self
->logfp
)) == EOF
)
461 self
->linetimings
= c
? 1 : 0;
465 case WHAT_FRAME_TIMES
:
466 if ((c
= fgetc(self
->logfp
)) == EOF
)
469 self
->frametimings
= c
? 1 : 0;
474 err
= ERR_BAD_RECTYPE
;
476 if (err
== ERR_BAD_RECTYPE
) {
477 PyErr_SetString(PyExc_ValueError
,
478 "unknown record type in log file");
480 else if (err
== ERR_EOF
) {
484 result
= PyTuple_New(4);
487 PyTuple_SET_ITEM(result
, 0, PyInt_FromLong(what
));
488 PyTuple_SET_ITEM(result
, 2, PyInt_FromLong(fileno
));
490 PyTuple_SET_ITEM(result
, 1, PyInt_FromLong(tdelta
));
492 PyTuple_SET_ITEM(result
, 1, s1
);
494 PyTuple_SET_ITEM(result
, 3, PyInt_FromLong(lineno
));
496 PyTuple_SET_ITEM(result
, 3, s2
);
498 /* The only other case is err == ERR_EXCEPTION, in which case the
499 * exception is already set.
502 b0
= self
->buffer
[self
->index
];
503 b1
= self
->buffer
[self
->index
+ 1];
505 /* This is a line-number event. */
507 lineno
= ((b0
& ~1) << 7) + b1
;
511 what
= (b0
& 0x0E) >> 1;
512 tdelta
= ((b0
& 0xF0) << 4) + b1
;
513 if (what
== PyTrace_CALL
) {
514 /* we know there's a 2-byte file ID & 2-byte line number */
515 fileno
= ((self
->buffer
[self
->index
+ 2] << 8)
516 + self
->buffer
[self
->index
+ 3]);
517 lineno
= ((self
->buffer
[self
->index
+ 4] << 8)
518 + self
->buffer
[self
->index
+ 5]);
529 logreader_dealloc(LogReaderObject
*self
)
531 if (self
->logfp
!= NULL
) {
535 Py_XDECREF(self
->info
);
540 logreader_sq_item(LogReaderObject
*self
, Py_ssize_t index
)
542 PyObject
*result
= logreader_tp_iternext(self
);
543 if (result
== NULL
&& !PyErr_Occurred()) {
544 PyErr_SetString(PyExc_IndexError
, "no more events in log");
551 do_stop(ProfilerObject
*self
);
554 flush_data(ProfilerObject
*self
)
556 /* Need to dump data to the log file... */
557 size_t written
= fwrite(self
->buffer
, 1, self
->index
, self
->logfp
);
558 if (written
== (size_t)self
->index
)
561 memmove(self
->buffer
, &self
->buffer
[written
],
562 self
->index
- written
);
563 self
->index
-= written
;
565 char *s
= PyString_AsString(self
->logfilename
);
566 PyErr_SetFromErrnoWithFilename(PyExc_IOError
, s
);
572 if (fflush(self
->logfp
)) {
573 char *s
= PyString_AsString(self
->logfilename
);
574 PyErr_SetFromErrnoWithFilename(PyExc_IOError
, s
);
583 pack_packed_int(ProfilerObject
*self
, int value
)
585 unsigned char partial
;
588 partial
= value
& 0x7F;
592 self
->buffer
[self
->index
] = partial
;
598 /* Encode a modified packed integer, with a subfield of modsize bits
599 * containing the value "subfield". The value of subfield is not
600 * checked to ensure it actually fits in modsize bits.
603 pack_modified_packed_int(ProfilerObject
*self
, int value
,
604 int modsize
, int subfield
)
606 const int maxvalues
[] = {-1, 1, 3, 7, 15, 31, 63, 127};
608 int bits
= 7 - modsize
;
609 int partial
= value
& maxvalues
[bits
];
610 unsigned char b
= subfield
| (partial
<< modsize
);
612 if (partial
!= value
) {
614 self
->buffer
[self
->index
] = b
;
616 return pack_packed_int(self
, value
>> bits
);
618 self
->buffer
[self
->index
] = b
;
624 pack_string(ProfilerObject
*self
, const char *s
, Py_ssize_t len
)
626 if (len
+ PISIZE
+ self
->index
>= BUFFERSIZE
) {
627 if (flush_data(self
) < 0)
630 assert(len
< INT_MAX
);
631 if (pack_packed_int(self
, (int)len
) < 0)
633 memcpy(self
->buffer
+ self
->index
, s
, len
);
639 pack_add_info(ProfilerObject
*self
, const char *s1
, const char *s2
)
641 Py_ssize_t len1
= strlen(s1
);
642 Py_ssize_t len2
= strlen(s2
);
644 if (len1
+ len2
+ PISIZE
*2 + 1 + self
->index
>= BUFFERSIZE
) {
645 if (flush_data(self
) < 0)
648 self
->buffer
[self
->index
] = WHAT_ADD_INFO
;
650 if (pack_string(self
, s1
, len1
) < 0)
652 return pack_string(self
, s2
, len2
);
656 pack_define_file(ProfilerObject
*self
, int fileno
, const char *filename
)
658 Py_ssize_t len
= strlen(filename
);
660 if (len
+ PISIZE
*2 + 1 + self
->index
>= BUFFERSIZE
) {
661 if (flush_data(self
) < 0)
664 self
->buffer
[self
->index
] = WHAT_DEFINE_FILE
;
666 if (pack_packed_int(self
, fileno
) < 0)
668 return pack_string(self
, filename
, len
);
672 pack_define_func(ProfilerObject
*self
, int fileno
, int lineno
,
673 const char *funcname
)
675 Py_ssize_t len
= strlen(funcname
);
677 if (len
+ PISIZE
*3 + 1 + self
->index
>= BUFFERSIZE
) {
678 if (flush_data(self
) < 0)
681 self
->buffer
[self
->index
] = WHAT_DEFINE_FUNC
;
683 if (pack_packed_int(self
, fileno
) < 0)
685 if (pack_packed_int(self
, lineno
) < 0)
687 return pack_string(self
, funcname
, len
);
691 pack_line_times(ProfilerObject
*self
)
693 if (2 + self
->index
>= BUFFERSIZE
) {
694 if (flush_data(self
) < 0)
697 self
->buffer
[self
->index
] = WHAT_LINE_TIMES
;
698 self
->buffer
[self
->index
+ 1] = self
->linetimings
? 1 : 0;
704 pack_frame_times(ProfilerObject
*self
)
706 if (2 + self
->index
>= BUFFERSIZE
) {
707 if (flush_data(self
) < 0)
710 self
->buffer
[self
->index
] = WHAT_FRAME_TIMES
;
711 self
->buffer
[self
->index
+ 1] = self
->frametimings
? 1 : 0;
717 pack_enter(ProfilerObject
*self
, int fileno
, int tdelta
, int lineno
)
719 if (MPISIZE
+ PISIZE
*2 + self
->index
>= BUFFERSIZE
) {
720 if (flush_data(self
) < 0)
723 pack_modified_packed_int(self
, fileno
, 2, WHAT_ENTER
);
724 pack_packed_int(self
, lineno
);
725 if (self
->frametimings
)
726 return pack_packed_int(self
, tdelta
);
732 pack_exit(ProfilerObject
*self
, int tdelta
)
734 if (MPISIZE
+ self
->index
>= BUFFERSIZE
) {
735 if (flush_data(self
) < 0)
738 if (self
->frametimings
)
739 return pack_modified_packed_int(self
, tdelta
, 2, WHAT_EXIT
);
740 self
->buffer
[self
->index
] = WHAT_EXIT
;
746 pack_lineno(ProfilerObject
*self
, int lineno
)
748 if (MPISIZE
+ self
->index
>= BUFFERSIZE
) {
749 if (flush_data(self
) < 0)
752 return pack_modified_packed_int(self
, lineno
, 2, WHAT_LINENO
);
756 pack_lineno_tdelta(ProfilerObject
*self
, int lineno
, int tdelta
)
758 if (MPISIZE
+ PISIZE
+ self
->index
>= BUFFERSIZE
) {
759 if (flush_data(self
) < 0)
762 if (pack_modified_packed_int(self
, lineno
, 2, WHAT_LINENO
) < 0)
764 return pack_packed_int(self
, tdelta
);
768 get_fileno(ProfilerObject
*self
, PyCodeObject
*fcode
)
770 /* This is only used for ENTER events. */
776 obj
= PyDict_GetItem(self
->filemap
, fcode
->co_filename
);
778 /* first sighting of this file */
783 fileno
= self
->next_fileno
;
784 obj
= Py_BuildValue("iN", fileno
, dict
);
788 if (PyDict_SetItem(self
->filemap
, fcode
->co_filename
, obj
)) {
794 if (pack_define_file(self
, fileno
,
795 PyString_AS_STRING(fcode
->co_filename
)) < 0)
799 /* already know this ID */
800 fileno
= PyInt_AS_LONG(PyTuple_GET_ITEM(obj
, 0));
801 dict
= PyTuple_GET_ITEM(obj
, 1);
803 /* make sure we save a function name for this (fileno, lineno) */
804 obj
= PyInt_FromLong(fcode
->co_firstlineno
);
806 /* We just won't have it saved; too bad. */
810 PyObject
*name
= PyDict_GetItem(dict
, obj
);
812 if (pack_define_func(self
, fileno
, fcode
->co_firstlineno
,
813 PyString_AS_STRING(fcode
->co_name
)) < 0) {
817 if (PyDict_SetItem(dict
, obj
, fcode
->co_name
)) {
828 get_tdelta(ProfilerObject
*self
)
836 diff
= tv
- self
->prev_timeofday
;
843 tdelta
= tv
.tv_usec
- self
->prev_timeofday
.tv_usec
;
844 if (tv
.tv_sec
!= self
->prev_timeofday
.tv_sec
)
845 tdelta
+= (tv
.tv_sec
- self
->prev_timeofday
.tv_sec
) * 1000000;
847 /* time can go backwards on some multiprocessor systems or by NTP */
851 self
->prev_timeofday
= tv
;
856 /* The workhorse: the profiler callback function. */
859 tracer_callback(ProfilerObject
*self
, PyFrameObject
*frame
, int what
,
866 fileno
= get_fileno(self
, frame
->f_code
);
869 return pack_enter(self
, fileno
,
870 self
->frametimings
? get_tdelta(self
) : -1,
871 frame
->f_code
->co_firstlineno
);
874 return pack_exit(self
, get_tdelta(self
));
876 case PyTrace_LINE
: /* we only get these events if we asked for them */
877 if (self
->linetimings
)
878 return pack_lineno_tdelta(self
, frame
->f_lineno
,
881 return pack_lineno(self
, frame
->f_lineno
);
884 /* ignore PyTrace_EXCEPTION */
891 /* A couple of useful helper functions. */
894 static LARGE_INTEGER frequency
= {0, 0};
897 static unsigned long timeofday_diff
= 0;
898 static unsigned long rusage_diff
= 0;
907 QueryPerformanceFrequency(&frequency
);
916 timeofday_diff
= (unsigned long)diff
;
920 if (tv1
.tv_sec
!= tv2
.tv_sec
|| tv1
.tv_usec
!= tv2
.tv_usec
) {
921 if (tv1
.tv_sec
== tv2
.tv_sec
)
922 timeofday_diff
= tv2
.tv_usec
- tv1
.tv_usec
;
924 timeofday_diff
= (1000000 - tv1
.tv_usec
) + tv2
.tv_usec
;
929 #if defined(MS_WINDOWS) || defined(PYOS_OS2) || \
930 defined(__VMS) || defined (__QNX__)
934 struct rusage ru1
, ru2
;
936 getrusage(RUSAGE_SELF
, &ru1
);
938 getrusage(RUSAGE_SELF
, &ru2
);
939 if (ru1
.ru_utime
.tv_sec
!= ru2
.ru_utime
.tv_sec
) {
940 rusage_diff
= ((1000000 - ru1
.ru_utime
.tv_usec
)
941 + ru2
.ru_utime
.tv_usec
);
944 else if (ru1
.ru_utime
.tv_usec
!= ru2
.ru_utime
.tv_usec
) {
945 rusage_diff
= ru2
.ru_utime
.tv_usec
- ru1
.ru_utime
.tv_usec
;
948 else if (ru1
.ru_stime
.tv_sec
!= ru2
.ru_stime
.tv_sec
) {
949 rusage_diff
= ((1000000 - ru1
.ru_stime
.tv_usec
)
950 + ru2
.ru_stime
.tv_usec
);
953 else if (ru1
.ru_stime
.tv_usec
!= ru2
.ru_stime
.tv_usec
) {
954 rusage_diff
= ru2
.ru_stime
.tv_usec
- ru1
.ru_stime
.tv_usec
;
963 do_start(ProfilerObject
*self
)
966 GETTIMEOFDAY(&self
->prev_timeofday
);
967 if (self
->lineevents
)
968 PyEval_SetTrace((Py_tracefunc
) tracer_callback
, (PyObject
*)self
);
970 PyEval_SetProfile((Py_tracefunc
) tracer_callback
, (PyObject
*)self
);
974 do_stop(ProfilerObject
*self
)
978 if (self
->lineevents
)
979 PyEval_SetTrace(NULL
, NULL
);
981 PyEval_SetProfile(NULL
, NULL
);
983 if (self
->index
> 0) {
984 /* Best effort to dump out any remaining data. */
990 is_available(ProfilerObject
*self
)
993 PyErr_SetString(ProfilerError
, "profiler already active");
996 if (self
->logfp
== NULL
) {
997 PyErr_SetString(ProfilerError
, "profiler already closed");
1004 /* Profiler object interface methods. */
1006 PyDoc_STRVAR(addinfo__doc__
,
1007 "addinfo(key, value)\n"
1008 "Insert an ADD_INFO record into the log.");
1011 profiler_addinfo(ProfilerObject
*self
, PyObject
*args
)
1013 PyObject
*result
= NULL
;
1016 if (PyArg_ParseTuple(args
, "ss:addinfo", &key
, &value
)) {
1017 if (self
->logfp
== NULL
)
1018 PyErr_SetString(ProfilerError
, "profiler already closed");
1020 if (pack_add_info(self
, key
, value
) == 0) {
1029 PyDoc_STRVAR(close__doc__
,
1031 "Shut down this profiler and close the log files, even if its active.");
1034 profiler_close(ProfilerObject
*self
)
1037 if (self
->logfp
!= NULL
) {
1038 fclose(self
->logfp
);
1045 #define fileno__doc__ logreader_fileno__doc__
1048 profiler_fileno(ProfilerObject
*self
)
1050 if (self
->logfp
== NULL
) {
1051 PyErr_SetString(PyExc_ValueError
,
1052 "profiler's file object already closed");
1055 return PyInt_FromLong(fileno(self
->logfp
));
1058 PyDoc_STRVAR(runcall__doc__
,
1059 "runcall(callable[, args[, kw]]) -> callable()\n"
1060 "Profile a specific function call, returning the result of that call.");
1063 profiler_runcall(ProfilerObject
*self
, PyObject
*args
)
1065 PyObject
*result
= NULL
;
1066 PyObject
*callargs
= NULL
;
1067 PyObject
*callkw
= NULL
;
1070 if (PyArg_UnpackTuple(args
, "runcall", 1, 3,
1071 &callable
, &callargs
, &callkw
)) {
1072 if (is_available(self
)) {
1074 result
= PyEval_CallObjectWithKeywords(callable
, callargs
, callkw
);
1081 PyDoc_STRVAR(runcode__doc__
,
1082 "runcode(code, globals[, locals])\n"
1083 "Execute a code object while collecting profile data. If locals is\n"
1084 "omitted, globals is used for the locals as well.");
1087 profiler_runcode(ProfilerObject
*self
, PyObject
*args
)
1089 PyObject
*result
= NULL
;
1092 PyObject
*locals
= NULL
;
1094 if (PyArg_ParseTuple(args
, "O!O!|O:runcode",
1095 &PyCode_Type
, &code
,
1096 &PyDict_Type
, &globals
,
1098 if (is_available(self
)) {
1099 if (locals
== NULL
|| locals
== Py_None
)
1101 else if (!PyDict_Check(locals
)) {
1102 PyErr_SetString(PyExc_TypeError
,
1103 "locals must be a dictionary or None");
1107 result
= PyEval_EvalCode(code
, globals
, locals
);
1110 if (!PyErr_Occurred()) {
1120 PyDoc_STRVAR(start__doc__
,
1122 "Install this profiler for the current thread.");
1125 profiler_start(ProfilerObject
*self
, PyObject
*args
)
1127 PyObject
*result
= NULL
;
1129 if (is_available(self
)) {
1137 PyDoc_STRVAR(stop__doc__
,
1139 "Remove this profiler from the current thread.");
1142 profiler_stop(ProfilerObject
*self
, PyObject
*args
)
1144 PyObject
*result
= NULL
;
1147 PyErr_SetString(ProfilerError
, "profiler not active");
1157 /* Python API support. */
1160 profiler_dealloc(ProfilerObject
*self
)
1163 if (self
->logfp
!= NULL
)
1164 fclose(self
->logfp
);
1165 Py_XDECREF(self
->filemap
);
1166 Py_XDECREF(self
->logfilename
);
1167 PyObject_Del((PyObject
*)self
);
1170 static PyMethodDef profiler_methods
[] = {
1171 {"addinfo", (PyCFunction
)profiler_addinfo
, METH_VARARGS
, addinfo__doc__
},
1172 {"close", (PyCFunction
)profiler_close
, METH_NOARGS
, close__doc__
},
1173 {"fileno", (PyCFunction
)profiler_fileno
, METH_NOARGS
, fileno__doc__
},
1174 {"runcall", (PyCFunction
)profiler_runcall
, METH_VARARGS
, runcall__doc__
},
1175 {"runcode", (PyCFunction
)profiler_runcode
, METH_VARARGS
, runcode__doc__
},
1176 {"start", (PyCFunction
)profiler_start
, METH_NOARGS
, start__doc__
},
1177 {"stop", (PyCFunction
)profiler_stop
, METH_NOARGS
, stop__doc__
},
1181 static PyMemberDef profiler_members
[] = {
1182 {"frametimings", T_LONG
, offsetof(ProfilerObject
, linetimings
), READONLY
},
1183 {"lineevents", T_LONG
, offsetof(ProfilerObject
, lineevents
), READONLY
},
1184 {"linetimings", T_LONG
, offsetof(ProfilerObject
, linetimings
), READONLY
},
1189 profiler_get_closed(ProfilerObject
*self
, void *closure
)
1191 PyObject
*result
= (self
->logfp
== NULL
) ? Py_True
: Py_False
;
1196 static PyGetSetDef profiler_getsets
[] = {
1197 {"closed", (getter
)profiler_get_closed
, NULL
,
1198 PyDoc_STR("True if the profiler's output file has already been closed.")},
1203 PyDoc_STRVAR(profiler_object__doc__
,
1204 "High-performance profiler object.\n"
1208 "close(): Stop the profiler and close the log files.\n"
1209 "fileno(): Returns the file descriptor of the log file.\n"
1210 "runcall(): Run a single function call with profiling enabled.\n"
1211 "runcode(): Execute a code object with profiling enabled.\n"
1212 "start(): Install the profiler and return.\n"
1213 "stop(): Remove the profiler.\n"
1215 "Attributes (read-only):\n"
1217 "closed: True if the profiler has already been closed.\n"
1218 "frametimings: True if ENTER/EXIT events collect timing information.\n"
1219 "lineevents: True if line events are reported to the profiler.\n"
1220 "linetimings: True if line events collect timing information.");
1222 static PyTypeObject ProfilerType
= {
1223 PyObject_HEAD_INIT(NULL
)
1225 "_hotshot.ProfilerType", /* tp_name */
1226 (int) sizeof(ProfilerObject
), /* tp_basicsize */
1227 0, /* tp_itemsize */
1228 (destructor
)profiler_dealloc
, /* tp_dealloc */
1234 0, /* tp_as_number */
1235 0, /* tp_as_sequence */
1236 0, /* tp_as_mapping */
1240 PyObject_GenericGetAttr
, /* tp_getattro */
1241 0, /* tp_setattro */
1242 0, /* tp_as_buffer */
1243 Py_TPFLAGS_DEFAULT
, /* tp_flags */
1244 profiler_object__doc__
, /* tp_doc */
1245 0, /* tp_traverse */
1247 0, /* tp_richcompare */
1248 0, /* tp_weaklistoffset */
1250 0, /* tp_iternext */
1251 profiler_methods
, /* tp_methods */
1252 profiler_members
, /* tp_members */
1253 profiler_getsets
, /* tp_getset */
1256 0, /* tp_descr_get */
1257 0, /* tp_descr_set */
1261 static PyMethodDef logreader_methods
[] = {
1262 {"close", (PyCFunction
)logreader_close
, METH_NOARGS
,
1263 logreader_close__doc__
},
1264 {"fileno", (PyCFunction
)logreader_fileno
, METH_NOARGS
,
1265 logreader_fileno__doc__
},
1269 static PyMemberDef logreader_members
[] = {
1270 {"info", T_OBJECT
, offsetof(LogReaderObject
, info
), RO
,
1271 PyDoc_STR("Dictionary mapping informational keys to lists of values.")},
1276 PyDoc_STRVAR(logreader__doc__
,
1277 "logreader(filename) --> log-iterator\n\
1278 Create a log-reader for the timing information file.");
1280 static PySequenceMethods logreader_as_sequence
= {
1284 (ssizeargfunc
)logreader_sq_item
, /* sq_item */
1286 0, /* sq_ass_item */
1287 0, /* sq_ass_slice */
1288 0, /* sq_contains */
1289 0, /* sq_inplace_concat */
1290 0, /* sq_inplace_repeat */
1294 logreader_get_closed(LogReaderObject
*self
, void *closure
)
1296 PyObject
*result
= (self
->logfp
== NULL
) ? Py_True
: Py_False
;
1301 static PyGetSetDef logreader_getsets
[] = {
1302 {"closed", (getter
)logreader_get_closed
, NULL
,
1303 PyDoc_STR("True if the logreader's input file has already been closed.")},
1307 static PyTypeObject LogReaderType
= {
1308 PyObject_HEAD_INIT(NULL
)
1310 "_hotshot.LogReaderType", /* tp_name */
1311 (int) sizeof(LogReaderObject
), /* tp_basicsize */
1312 0, /* tp_itemsize */
1313 (destructor
)logreader_dealloc
, /* tp_dealloc */
1319 0, /* tp_as_number */
1320 &logreader_as_sequence
, /* tp_as_sequence */
1321 0, /* tp_as_mapping */
1325 PyObject_GenericGetAttr
, /* tp_getattro */
1326 0, /* tp_setattro */
1327 0, /* tp_as_buffer */
1328 Py_TPFLAGS_DEFAULT
, /* tp_flags */
1329 logreader__doc__
, /* tp_doc */
1330 0, /* tp_traverse */
1332 0, /* tp_richcompare */
1333 0, /* tp_weaklistoffset */
1334 PyObject_SelfIter
, /* tp_iter */
1335 (iternextfunc
)logreader_tp_iternext
,/* tp_iternext */
1336 logreader_methods
, /* tp_methods */
1337 logreader_members
, /* tp_members */
1338 logreader_getsets
, /* tp_getset */
1341 0, /* tp_descr_get */
1342 0, /* tp_descr_set */
1346 hotshot_logreader(PyObject
*unused
, PyObject
*args
)
1348 LogReaderObject
*self
= NULL
;
1353 if (PyArg_ParseTuple(args
, "s:logreader", &filename
)) {
1354 self
= PyObject_New(LogReaderObject
, &LogReaderType
);
1356 self
->frametimings
= 1;
1357 self
->linetimings
= 0;
1359 self
->logfp
= fopen(filename
, "rb");
1360 if (self
->logfp
== NULL
) {
1361 PyErr_SetFromErrnoWithFilename(PyExc_IOError
, filename
);
1366 self
->info
= PyDict_New();
1367 if (self
->info
== NULL
) {
1371 /* read initial info */
1373 if ((c
= fgetc(self
->logfp
)) == EOF
) {
1377 if (c
!= WHAT_ADD_INFO
) {
1378 ungetc(c
, self
->logfp
);
1381 err
= unpack_add_info(self
);
1386 PyErr_SetString(PyExc_RuntimeError
,
1387 "unexpected error");
1394 return (PyObject
*) self
;
1398 /* Return a Python string that represents the version number without the
1399 * extra cruft added by revision control, even if the right options were
1400 * given to the "cvs export" command to make it not include the extra
1404 get_version_string(void)
1406 static char *rcsid
= "$Revision$";
1411 while (*rev
&& !isdigit(Py_CHARMASK(*rev
)))
1413 while (rev
[i
] != ' ' && rev
[i
] != '\0')
1415 buffer
= (char *)malloc(i
+ 1);
1416 if (buffer
!= NULL
) {
1417 memmove(buffer
, rev
, i
);
1423 /* Write out a RFC 822-style header with various useful bits of
1424 * information to make the output easier to manage.
1427 write_header(ProfilerObject
*self
)
1430 char cwdbuffer
[PATH_MAX
];
1434 buffer
= get_version_string();
1435 if (buffer
== NULL
) {
1439 pack_add_info(self
, "hotshot-version", buffer
);
1440 pack_add_info(self
, "requested-frame-timings",
1441 (self
->frametimings
? "yes" : "no"));
1442 pack_add_info(self
, "requested-line-events",
1443 (self
->lineevents
? "yes" : "no"));
1444 pack_add_info(self
, "requested-line-timings",
1445 (self
->linetimings
? "yes" : "no"));
1446 pack_add_info(self
, "platform", Py_GetPlatform());
1447 pack_add_info(self
, "executable", Py_GetProgramFullPath());
1449 buffer
= (char *) Py_GetVersion();
1453 pack_add_info(self
, "executable-version", buffer
);
1456 PyOS_snprintf(cwdbuffer
, sizeof(cwdbuffer
), "%I64d", frequency
.QuadPart
);
1457 pack_add_info(self
, "reported-performance-frequency", cwdbuffer
);
1459 PyOS_snprintf(cwdbuffer
, sizeof(cwdbuffer
), "%lu", rusage_diff
);
1460 pack_add_info(self
, "observed-interval-getrusage", cwdbuffer
);
1461 PyOS_snprintf(cwdbuffer
, sizeof(cwdbuffer
), "%lu", timeofday_diff
);
1462 pack_add_info(self
, "observed-interval-gettimeofday", cwdbuffer
);
1465 pack_add_info(self
, "current-directory",
1466 getcwd(cwdbuffer
, sizeof cwdbuffer
));
1468 temp
= PySys_GetObject("path");
1469 if (temp
== NULL
|| !PyList_Check(temp
)) {
1470 PyErr_SetString(PyExc_RuntimeError
, "sys.path must be a list");
1473 len
= PyList_GET_SIZE(temp
);
1474 for (i
= 0; i
< len
; ++i
) {
1475 PyObject
*item
= PyList_GET_ITEM(temp
, i
);
1476 buffer
= PyString_AsString(item
);
1477 if (buffer
== NULL
) {
1478 pack_add_info(self
, "sys-path-entry", "<non-string-path-entry>");
1482 pack_add_info(self
, "sys-path-entry", buffer
);
1485 pack_frame_times(self
);
1486 pack_line_times(self
);
1491 PyDoc_STRVAR(profiler__doc__
,
1492 "profiler(logfilename[, lineevents[, linetimes]]) -> profiler\n\
1493 Create a new profiler object.");
1496 hotshot_profiler(PyObject
*unused
, PyObject
*args
)
1499 ProfilerObject
*self
= NULL
;
1501 int linetimings
= 1;
1503 if (PyArg_ParseTuple(args
, "s|ii:profiler", &logfilename
,
1504 &lineevents
, &linetimings
)) {
1505 self
= PyObject_New(ProfilerObject
, &ProfilerType
);
1508 self
->frametimings
= 1;
1509 self
->lineevents
= lineevents
? 1 : 0;
1510 self
->linetimings
= (lineevents
&& linetimings
) ? 1 : 0;
1513 self
->next_fileno
= 0;
1515 self
->logfilename
= PyTuple_GET_ITEM(args
, 0);
1516 Py_INCREF(self
->logfilename
);
1517 self
->filemap
= PyDict_New();
1518 if (self
->filemap
== NULL
) {
1522 self
->logfp
= fopen(logfilename
, "wb");
1523 if (self
->logfp
== NULL
) {
1525 PyErr_SetFromErrnoWithFilename(PyExc_IOError
, logfilename
);
1528 if (timeofday_diff
== 0) {
1529 /* Run this several times since sometimes the first
1530 * doesn't give the lowest values, and we're really trying
1531 * to determine the lowest.
1537 if (write_header(self
)) {
1538 /* some error occurred, exception has been set */
1543 return (PyObject
*) self
;
1546 PyDoc_STRVAR(coverage__doc__
,
1547 "coverage(logfilename) -> profiler\n\
1548 Returns a profiler that doesn't collect any timing information, which is\n\
1549 useful in building a coverage analysis tool.");
1552 hotshot_coverage(PyObject
*unused
, PyObject
*args
)
1555 PyObject
*result
= NULL
;
1557 if (PyArg_ParseTuple(args
, "s:coverage", &logfilename
)) {
1558 result
= hotshot_profiler(unused
, args
);
1559 if (result
!= NULL
) {
1560 ProfilerObject
*self
= (ProfilerObject
*) result
;
1561 self
->frametimings
= 0;
1562 self
->linetimings
= 0;
1563 self
->lineevents
= 1;
1569 PyDoc_VAR(resolution__doc__
) =
1572 "resolution() -> (performance-counter-ticks, update-frequency)\n"
1573 "Return the resolution of the timer provided by the QueryPerformanceCounter()\n"
1574 "function. The first value is the smallest observed change, and the second\n"
1575 "is the result of QueryPerformanceFrequency()."
1579 "resolution() -> (gettimeofday-usecs, getrusage-usecs)\n"
1580 "Return the resolution of the timers provided by the gettimeofday() and\n"
1581 "getrusage() system calls, or -1 if the call is not supported."
1587 hotshot_resolution(PyObject
*self
, PyObject
*unused
)
1589 if (timeofday_diff
== 0) {
1595 return Py_BuildValue("ii", timeofday_diff
, frequency
.LowPart
);
1597 return Py_BuildValue("ii", timeofday_diff
, rusage_diff
);
1602 static PyMethodDef functions
[] = {
1603 {"coverage", hotshot_coverage
, METH_VARARGS
, coverage__doc__
},
1604 {"profiler", hotshot_profiler
, METH_VARARGS
, profiler__doc__
},
1605 {"logreader", hotshot_logreader
, METH_VARARGS
, logreader__doc__
},
1606 {"resolution", hotshot_resolution
, METH_NOARGS
, resolution__doc__
},
1616 LogReaderType
.ob_type
= &PyType_Type
;
1617 ProfilerType
.ob_type
= &PyType_Type
;
1618 module
= Py_InitModule("_hotshot", functions
);
1619 if (module
!= NULL
) {
1620 char *s
= get_version_string();
1622 PyModule_AddStringConstant(module
, "__version__", s
);
1624 Py_INCREF(&LogReaderType
);
1625 PyModule_AddObject(module
, "LogReaderType",
1626 (PyObject
*)&LogReaderType
);
1627 Py_INCREF(&ProfilerType
);
1628 PyModule_AddObject(module
, "ProfilerType",
1629 (PyObject
*)&ProfilerType
);
1631 if (ProfilerError
== NULL
)
1632 ProfilerError
= PyErr_NewException("hotshot.ProfilerError",
1634 if (ProfilerError
!= NULL
) {
1635 Py_INCREF(ProfilerError
);
1636 PyModule_AddObject(module
, "ProfilerError", ProfilerError
);
1638 PyModule_AddIntConstant(module
, "WHAT_ENTER", WHAT_ENTER
);
1639 PyModule_AddIntConstant(module
, "WHAT_EXIT", WHAT_EXIT
);
1640 PyModule_AddIntConstant(module
, "WHAT_LINENO", WHAT_LINENO
);
1641 PyModule_AddIntConstant(module
, "WHAT_OTHER", WHAT_OTHER
);
1642 PyModule_AddIntConstant(module
, "WHAT_ADD_INFO", WHAT_ADD_INFO
);
1643 PyModule_AddIntConstant(module
, "WHAT_DEFINE_FILE", WHAT_DEFINE_FILE
);
1644 PyModule_AddIntConstant(module
, "WHAT_DEFINE_FUNC", WHAT_DEFINE_FUNC
);
1645 PyModule_AddIntConstant(module
, "WHAT_LINE_TIMES", WHAT_LINE_TIMES
);