Add support for tracing execution

Cc: @DavideAllavena Example output: ``` 5 is writable: call ./neubot_runtime/connector.py:36:handle_write() call ./neubot_runtime/poller.py:78:unset_writable() call ./neubot_runtime/connector.py:33:fileno() return ./neubot_runtime/connector.py:34:fileno() return ./neubot_runtime/poller.py:82:unset_writable() call ./neubot_runtime/utils_net.py:169:isconnected() call ./neubot_runtime/utils_net.py:16:format_epnt() return ./neubot_runtime/utils_net.py:23:format_epnt() call ./neubot_runtime/utils_net.py:216:getpeername() call ./neubot_runtime/utils_net.py:201:__strip_ipv4mapped_prefix() call ./neubot_runtime/utils_net.py:206:__strip_ipv4mapped_prefix1() return ./neubot_runtime/utils_net.py:214:__strip_ipv4mapped_prefix1() return ./neubot_runtime/utils_net.py:204:__strip_ipv4mapped_prefix() return ./neubot_runtime/utils_net.py:218:getpeername() return ./neubot_runtime/utils_net.py:184:isconnected() call ./neubot_runtime/utils.py:95:ticks() return ./neubot_runtime/utils.py:101:ticks() call ./neubot_runtime/http_client.py:51:connection_made() call ./neubot_runtime/utils.py:69:time_formatter() return ./neubot_runtime/utils.py:75:time_formatter() call ./neubot_runtime/http_client_stream.py:20:__init__() call ./neubot_runtime/http_stream.py:42:__init__() call ./neubot_runtime/stream.py:24:__init__() call ./neubot_runtime/pollable.py:18:__init__() call ./neubot_runtime/utils.py:95:ticks() return ./neubot_runtime/utils.py:101:ticks() return ./neubot_runtime/pollable.py:20:__init__() call ./neubot_runtime/utils_net.py:220:getsockname() call ./neubot_runtime/utils_net.py:201:__strip_ipv4mapped_prefix() call ./neubot_runtime/utils_net.py:206:__strip_ipv4mapped_prefix1() return ./neubot_runtime/utils_net.py:214:__strip_ipv4mapped_prefix1() return ./neubot_runtime/utils_net.py:204:__strip_ipv4mapped_prefix() return ./neubot_runtime/utils_net.py:222:getsockname() call ./neubot_runtime/utils_net.py:216:getpeername() call ./neubot_runtime/utils_net.py:201:__strip_ipv4mapped_prefix() call ./neubot_runtime/utils_net.py:206:__strip_ipv4mapped_prefix1() return ./neubot_runtime/utils_net.py:214:__strip_ipv4mapped_prefix1() return ./neubot_runtime/utils_net.py:204:__strip_ipv4mapped_prefix() return ./neubot_runtime/utils_net.py:218:getpeername() return ./neubot_runtime/stream.py:48:__init__() return ./neubot_runtime/http_stream.py:47:__init__() return ./neubot_runtime/http_client_stream.py:22:__init__() call ./neubot_runtime/http_stream.py:49:connection_made() call ./neubot_runtime/stream.py:109:start_recv() call ./neubot_runtime/poller.py:64:set_readable() call ./neubot_runtime/stream.py:53:fileno() return ./neubot_runtime/stream.py:54:fileno() return ./neubot_runtime/poller.py:66:set_readable() return ./neubot_runtime/stream.py:116:start_recv() return ./neubot_runtime/http_stream.py:51:connection_made() call ./neubot_runtime/http_message.py:33:__init__() return ./neubot_runtime/http_message.py:53:__init__() call ./neubot_runtime/http_message.py:144:compose() call ./neubot_runtime/http_misc.py:15:urlsplit() return ./neubot_runtime/http_misc.py:52:urlsplit() call ./neubot_runtime/http_message.py:123:__setitem__() return ./neubot_runtime/http_message.py:128:__setitem__() call ./neubot_runtime/http_message.py:123:__setitem__() return ./neubot_runtime/http_message.py:128:__setitem__() call ./neubot_runtime/http_message.py:123:__setitem__() return ./neubot_runtime/http_message.py:128:__setitem__() call ./neubot_runtime/http_message.py:123:__setitem__() return ./neubot_runtime/http_message.py:128:__setitem__() call ./neubot_runtime/http_message.py:123:__setitem__() return ./neubot_runtime/http_message.py:128:__setitem__() call ./neubot_runtime/http_message.py:123:__setitem__() return ./neubot_runtime/http_message.py:128:__setitem__() return ./neubot_runtime/http_message.py:228:compose() call ./neubot_runtime/http_message.py:33:__init__() return ./neubot_runtime/http_message.py:53:__init__() call ./neubot_runtime/http_client_stream.py:24:send_request() call ./neubot_runtime/http_stream.py:59:send_message() call ./neubot_runtime/http_message.py:64:serialize_headers() return ./neubot_runtime/http_message.py:105:serialize_headers() call ./neubot_runtime/http_message.py:107:serialize_body() call ./neubot_runtime/http_message.py:241:prettyprintbody() return ./neubot_runtime/http_message.py:241:prettyprintbody() return ./neubot_runtime/http_message.py:110:serialize_body() call ./neubot_runtime/http_stream.py:83:_flush() call ./neubot_runtime/stream.py:149:start_send() call ./neubot_runtime/poller.py:68:set_writable() call ./neubot_runtime/stream.py:53:fileno() return ./neubot_runtime/stream.py:54:fileno() return ./neubot_runtime/poller.py:70:set_writable() return ./neubot_runtime/stream.py:157:start_send() return ./neubot_runtime/http_stream.py:98:_flush() return ./neubot_runtime/http_stream.py:76:send_message() return ./neubot_runtime/http_client_stream.py:30:send_request() return ./neubot_runtime/http_client.py:61:connection_made() return ./neubot_runtime/connector.py:44:handle_write() 5 is writable: call ./neubot_runtime/stream.py:159:handle_write() call ./neubot_runtime/poller.py:78:unset_writable() call ./neubot_runtime/stream.py:53:fileno() return ./neubot_runtime/stream.py:54:fileno() return ./neubot_runtime/poller.py:82:unset_writable() call ./neubot_runtime/http_stream.py:78:send_complete() call ./neubot_runtime/http_stream.py:83:_flush() return ./neubot_runtime/http_stream.py:98:_flush() return ./neubot_runtime/http_stream.py:81:send_complete() return ./neubot_runtime/stream.py:187:handle_write() 5 is readable: call ./neubot_runtime/stream.py:118:handle_read() call ./neubot_runtime/poller.py:72:unset_readable() call ./neubot_runtime/stream.py:53:fileno() return ./neubot_runtime/stream.py:54:fileno() return ./neubot_runtime/poller.py:76:unset_readable() call ./neubot_runtime/http_stream.py:100:recv_complete() call ./neubot_runtime/third_party/six.py:184:find_module() return ./neubot_runtime/third_party/six.py:187:find_module() call ./neubot_runtime/http_stream.py:161:_got_line() call ./neubot_runtime/http_client_stream.py:32:got_first_line() return ./neubot_runtime/http_client_stream.py:38:got_first_line() return ./neubot_runtime/http_stream.py:222:_got_line() call ./neubot_runtime/http_stream.py:161:_got_line() call ./neubot_runtime/http_client_stream.py:40:got_header() call ./neubot_runtime/http_message.py:123:__setitem__() return ./neubot_runtime/http_message.py:128:__setitem__() return ./neubot_runtime/http_client_stream.py:42:got_header() return ./neubot_runtime/http_stream.py:222:_got_line() call ./neubot_runtime/http_stream.py:161:_got_line() call ./neubot_runtime/http_client_stream.py:40:got_header() call ./neubot_runtime/http_message.py:123:__setitem__() return ./neubot_runtime/http_message.py:128:__setitem__() return ./neubot_runtime/http_client_stream.py:42:got_header() return ./neubot_runtime/http_stream.py:222:_got_line() call ./neubot_runtime/http_stream.py:161:_got_line() call ./neubot_runtime/http_client_stream.py:40:got_header() call ./neubot_runtime/http_message.py:123:__setitem__() return ./neubot_runtime/http_message.py:128:__setitem__() return ./neubot_runtime/http_client_stream.py:42:got_header() return ./neubot_runtime/http_stream.py:222:_got_line() call ./neubot_runtime/http_stream.py:161:_got_line() call ./neubot_runtime/http_client_stream.py:40:got_header() call ./neubot_runtime/http_message.py:123:__setitem__() return ./neubot_runtime/http_message.py:128:__setitem__() return ./neubot_runtime/http_client_stream.py:42:got_header() return ./neubot_runtime/http_stream.py:222:_got_line() call ./neubot_runtime/http_stream.py:161:_got_line() call ./neubot_runtime/http_client_stream.py:40:got_header() call ./neubot_runtime/http_message.py:123:__setitem__() return ./neubot_runtime/http_message.py:128:__setitem__() return ./neubot_runtime/http_client_stream.py:42:got_header() return ./neubot_runtime/http_stream.py:222:_got_line() call ./neubot_runtime/http_stream.py:161:_got_line() call ./neubot_runtime/http_client_stream.py:40:got_header() call ./neubot_runtime/http_message.py:123:__setitem__() return ./neubot_runtime/http_message.py:128:__setitem__() return ./neubot_runtime/http_client_stream.py:42:got_header() return ./neubot_runtime/http_stream.py:222:_got_line() call ./neubot_runtime/http_stream.py:161:_got_line() call ./neubot_runtime/http_client_stream.py:40:got_header() call ./neubot_runtime/http_message.py:123:__setitem__() return ./neubot_runtime/http_message.py:128:__setitem__() return ./neubot_runtime/http_client_stream.py:42:got_header() return ./neubot_runtime/http_stream.py:222:_got_line() call ./neubot_runtime/http_stream.py:161:_got_line() call ./neubot_runtime/http_client_stream.py:44:got_end_of_headers() call ./neubot_runtime/http_client.py:41:got_response_headers() return ./neubot_runtime/http_client.py:43:got_response_headers() call ./neubot_runtime/http_misc.py:87:nextstate() call ./neubot_runtime/http_message.py:119:__getitem__() return ./neubot_runtime/http_message.py:121:__getitem__() call ./neubot_runtime/http_message.py:119:__getitem__() return ./neubot_runtime/http_message.py:121:__getitem__() call ./neubot_runtime/http_misc.py:72:_parselength() call ./neubot_runtime/http_message.py:119:__getitem__() return ./neubot_runtime/http_message.py:121:__getitem__() return ./neubot_runtime/http_misc.py:85:_parselength() return ./neubot_runtime/http_misc.py:103:nextstate() return ./neubot_runtime/http_client_stream.py:49:got_end_of_headers() return ./neubot_runtime/http_stream.py:222:_got_line() call ./neubot_runtime/compat23.py:26:buff() return ./neubot_runtime/compat23.py:29:buff() call ./neubot_runtime/http_stream.py:224:_got_piece() call ./neubot_runtime/http_client_stream.py:51:got_piece() return ./neubot_runtime/http_client_stream.py:53:got_piece() call ./neubot_runtime/http_client_stream.py:55:got_end_of_body() call ./neubot_runtime/utils.py:14:safe_seek() return ./neubot_runtime/utils.py:30:safe_seek() call ./neubot_runtime/http_message.py:241:prettyprintbody() return ./neubot_runtime/http_message.py:241:prettyprintbody() call ./neubot_runtime/http_client.py:48:got_response() return ./neubot_runtime/http_client.py:48:got_response() call ./neubot_runtime/http_message.py:119:__getitem__() return ./neubot_runtime/http_message.py:121:__getitem__() call ./neubot_runtime/stream.py:73:close() call ./neubot_runtime/poller.py:84:close() call ./neubot_runtime/poller.py:72:unset_readable() call ./neubot_runtime/stream.py:53:fileno() return ./neubot_runtime/stream.py:54:fileno() return ./neubot_runtime/poller.py:76:unset_readable() call ./neubot_runtime/poller.py:78:unset_writable() call ./neubot_runtime/stream.py:53:fileno() return ./neubot_runtime/stream.py:54:fileno() return ./neubot_runtime/poller.py:82:unset_writable() call ./neubot_runtime/stream.py:83:handle_close() call ./neubot_runtime/http_stream.py:53:connection_lost() return ./neubot_runtime/http_stream.py:57:connection_lost() call ./neubot_runtime/stream_handler.py:55:connection_lost() return ./neubot_runtime/stream_handler.py:55:connection_lost() return ./neubot_runtime/stream.py:107:handle_close() return ./neubot_runtime/poller.py:93:close() return ./neubot_runtime/stream.py:81:close() return ./neubot_runtime/http_client_stream.py:63:got_end_of_body() return ./neubot_runtime/http_stream.py:246:_got_piece() return ./neubot_runtime/http_stream.py:149:recv_complete() return ./neubot_runtime/stream.py:141:handle_read() ```
neubot · Jan 20, 2016 · 3c2c502 · 3c2c502
1 parent 0daf25b
commit 3c2c502
Show file tree

Hide file tree

Showing 2 changed files with 102 additions and 0 deletions.
diff --git a/neubot_runtime/poller.py b/neubot_runtime/poller.py
@@ -10,6 +10,7 @@
 import sched
 import sys
 
+from .profiler import PROFILER
 from .utils import ticks
 from .utils import timestamp
 
@@ -108,6 +109,8 @@ def _call_handle_read(self, fileno):
         if fileno in self._readset:
             stream = self._readset[fileno]
             try:
+                sys.stderr.write("\n\n%d is readable:\n" % fileno)
+                sys.setprofile(PROFILER.notify_event)
                 stream.handle_read()
             except (KeyboardInterrupt, SystemExit):
                 raise
@@ -120,6 +123,8 @@ def _call_handle_write(self, fileno):
         if fileno in self._writeset:
             stream = self._writeset[fileno]
             try:
+                sys.stderr.write("\n\n%d is writable:\n" % fileno)
+                sys.setprofile(PROFILER.notify_event)
                 stream.handle_write()
             except (KeyboardInterrupt, SystemExit):
                 raise
@@ -171,6 +176,7 @@ def _poll(self, timeout):
             # No error?  Fire readable and writable events
             for fileno in res[0]:
                 self._call_handle_read(fileno)
+
             for fileno in res[1]:
                 self._call_handle_write(fileno)
 

diff --git a/neubot_runtime/profiler.py b/neubot_runtime/profiler.py
@@ -0,0 +1,96 @@
+# neubot/debug/__init__.py
+
+#
+# Copyright (c) 2010-2011 Simone Basso <bassosimone@gmail.com>,
+#  NEXA Center for Internet & Society at Politecnico di Torino
+#
+# This file is part of Neubot <http://www.neubot.org/>.
+#
+# Neubot is free software: you can redistribute it and/or modify
+# it under the terms of the GNU General Public License as published by
+# the Free Software Foundation, either version 3 of the License, or
+# (at your option) any later version.
+#
+# Neubot is distributed in the hope that it will be useful,
+# but WITHOUT ANY WARRANTY; without even the implied warranty of
+# MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the
+# GNU General Public License for more details.
+#
+# You should have received a copy of the GNU General Public License
+# along with Neubot.  If not, see <http://www.gnu.org/licenses/>.
+#
+
+import sys
+
+class Profiler(object):
+
+    def __init__(self):
+        self.enabled = True
+        self.frameno = 0
+        self.depth = 0
+
+    def _getfilename(self, frame):
+        if frame.f_globals.has_key("__file__"):
+
+            name = frame.f_globals["__file__"]
+            if not name:
+                # XXX this is quite unexpected
+                name = "???"
+
+            if name.endswith(".pyc") or name.endswith(".pyo"):
+                name = name[:-1]
+            for pattern in ["neubot/", "python2.5/", "python2.6/", "python/"]:
+                index = name.find(pattern)
+                if index > 0:
+                    name = name[index+len(pattern):]
+                    break
+
+        else:
+            name = "???"
+
+        return name
+
+    #
+    # We stop tracing when we exit from the frame number zero.
+    # This happens because we start tracing when the Python program
+    # is already running, and so _our_ zero is actually a positive
+    # frame number in Python's stack.
+    # This is not a problem because usually we're interested in
+    # tracing just a subset of the script.
+    #
+    # We also avoid diving into the logging module because this module
+    # invokes loads of other functions of the standard python library,
+    # and we are not actually interested on those functions.
+    #
+
+    def notify_event(self, frame, event, arg):
+        if event in ["call", "return"]:
+
+            fname = self._getfilename(frame)
+            func = frame.f_code.co_name
+
+            if not fname.startswith("./neubot"):
+                return
+
+            if event == "return":
+                self.frameno -= 1
+                if not self.enabled and self.frameno == self.depth:
+                    self.enabled = True
+                if self.frameno < 0:
+                    self.frameno = 0
+                    sys.setprofile(None)
+                    return
+
+            if self.enabled:
+                lineno = frame.f_lineno
+                prefix  = "\t" * (self.frameno + 1)
+                buff = "%s%s %s:%d:%s()\n" % (prefix,event,fname,lineno,func)
+                sys.stderr.write(buff)
+
+            if event == "call":
+                if self.enabled and fname.startswith("logging/"):
+                    self.enabled = False
+                    self.depth = self.frameno
+                self.frameno += 1
+
+PROFILER = Profiler()