From 878e9cb9ba3dedcf6c9c22883e1131daa79f9a40 Mon Sep 17 00:00:00 2001
From: "roberto@precise64" <roberto@precise64>
Date: Sat, 31 Mar 2012 15:48:22 +0200
Subject: [PATCH] reports microseconds in python profilers

---
 plugins/python/profiler.c      | 39 ++++++++++++++++++++++++++++++++--
 plugins/python/python_plugin.c |  3 +++
 plugins/python/uwsgi_python.h  |  1 +
 utils.c                        |  6 ++++++
 uwsgi.h                        |  2 ++
 5 files changed, 49 insertions(+), 2 deletions(-)

diff --git a/plugins/python/profiler.c b/plugins/python/profiler.c
index c374ca6a..774204ea 100644
--- a/plugins/python/profiler.c
+++ b/plugins/python/profiler.c
@@ -15,16 +15,28 @@ int PyFrame_GetLineNumber(PyFrameObject *frame) {
 
 int uwsgi_python_profiler_call(PyObject *obj, PyFrameObject *frame, int what, PyObject *arg) {
 
+	static uint64_t last_ts = 0;
+        uint64_t now = uwsgi_micros();
+        uint64_t delta = 0;
+
 #ifndef UWSGI_PYPY
 	switch(what) {
 		case PyTrace_CALL:
-			uwsgi_log("[uWSGI Python profiler] CALL: %s (line %d) -> %s %d args, stacksize %d\n",
+			if (last_ts == 0) delta = 0;
+                	else delta = now - last_ts;
+                	last_ts = now;
+			uwsgi_log("[uWSGI Python profiler %llu] CALL: %s (line %d) -> %s %d args, stacksize %d\n",
+				(unsigned long long) delta,
 				PyString_AsString(frame->f_code->co_filename),
 				PyFrame_GetLineNumber(frame),
 				PyString_AsString(frame->f_code->co_name), frame->f_code->co_argcount, frame->f_code->co_stacksize);
 			break;
 		case PyTrace_C_CALL:
-			uwsgi_log("[uWSGI Python profiler] C CALL: %s (line %d) -> %s %d args, stacksize %d\n",
+			if (last_ts == 0) delta = 0;
+                	else delta = now - last_ts;
+                	last_ts = now;
+			uwsgi_log("[uWSGI Python profiler %llu] C CALL: %s (line %d) -> %s %d args, stacksize %d\n",
+				(unsigned long long) delta,
 				PyString_AsString(frame->f_code->co_filename),
 				PyFrame_GetLineNumber(frame),
 				PyEval_GetFuncName(arg), frame->f_code->co_argcount, frame->f_code->co_stacksize);
@@ -34,3 +46,26 @@ int uwsgi_python_profiler_call(PyObject *obj, PyFrameObject *frame, int what, Py
 
 	return 0;
 }
+
+int uwsgi_python_tracer(PyObject *obj, PyFrameObject *frame, int what, PyObject *arg) {
+
+	static uint64_t last_ts = 0;
+	uint64_t now = uwsgi_micros();
+	uint64_t delta = 0;
+
+#ifndef UWSGI_PYPY
+	if (what == PyTrace_LINE) {
+		if (last_ts == 0) {
+			delta = 0;
+		}
+		else {
+			delta = now - last_ts;
+		}
+		last_ts = now;
+		uwsgi_log("[uWSGI Python profiler %llu] file %s line %d: %s argc:%d\n", (unsigned long long)delta,  PyString_AsString(frame->f_code->co_filename), PyFrame_GetLineNumber(frame), PyString_AsString(frame->f_code->co_name), frame->f_code->co_argcount);
+	}
+#endif
+
+        return 0;
+}
+
diff --git a/plugins/python/python_plugin.c b/plugins/python/python_plugin.c
index b0672d15..ca1dd770 100644
--- a/plugins/python/python_plugin.c
+++ b/plugins/python/python_plugin.c
@@ -1081,6 +1081,9 @@ next:
 		if (!strcmp(uwsgi.profiler, "pycall")) {
 			PyEval_SetProfile(uwsgi_python_profiler_call, NULL);
 		}
+		else if (!strcmp(uwsgi.profiler, "pyline")) {
+			PyEval_SetTrace(uwsgi_python_tracer, NULL);
+		}
 	}
 #endif
 
diff --git a/plugins/python/uwsgi_python.h b/plugins/python/uwsgi_python.h
index 8939372b..119af4f3 100644
--- a/plugins/python/uwsgi_python.h
+++ b/plugins/python/uwsgi_python.h
@@ -248,6 +248,7 @@ void simple_reset_ts(struct wsgi_request *, struct uwsgi_app *);
 void simple_threaded_reset_ts(struct wsgi_request *, struct uwsgi_app *);
 
 int uwsgi_python_profiler_call(PyObject *, PyFrameObject *, int, PyObject *);
+int uwsgi_python_tracer(PyObject *, PyFrameObject *, int, PyObject *);
 
 void uwsgi_python_reset_random_seed(void);
 
diff --git a/utils.c b/utils.c
index e3daae0d..abe00e15 100644
--- a/utils.c
+++ b/utils.c
@@ -4149,6 +4149,12 @@ time_t uwsgi_now() {
 	return time(NULL);
 }
 
+uint64_t uwsgi_micros() {
+	struct timeval tv;
+	gettimeofday(&tv, NULL);
+	return (tv.tv_sec * 1000000) + tv.tv_usec;
+}
+
 void uwsgi_write_pidfile(char *pidfile_name) {
 	uwsgi_log("writing pidfile to %s\n", pidfile_name);
         FILE *pidfile = fopen(pidfile_name, "w");
diff --git a/uwsgi.h b/uwsgi.h
index d68fa8eb..acccc475 100644
--- a/uwsgi.h
+++ b/uwsgi.h
@@ -2772,6 +2772,8 @@ int uwsgi_socket_is_already_bound(char *name);
 
 char *uwsgi_expand_path(char *, int, char *);
 
+uint64_t uwsgi_micros(void);
+
 #ifdef UWSGI_AS_SHARED_LIBRARY
 int uwsgi_init(int, char **, char **);
 #endif