Merge pull request #1190 from gevent/cython-tracer

Compile the monitor greenlet tracer with Cython

.gitignore

@@ -15,6 +15,7 @@ src/gevent/_imap.c
 src/gevent/event.c
 src/gevent/_hub_local.c
 src/gevent/_waiter.c
+src/gevent/_tracer.c
 src/gevent/queue.c
 src/gevent/_hub_primitives.c
 src/gevent/_greenlet_primitives.c

benchmarks/bench_tracer.py

+# -*- coding: utf-8 -*-
+"""
+Benchmarks for gevent.queue
+
+"""
+from __future__ import absolute_import
+from __future__ import division
+from __future__ import print_function
+
+import contextlib
+
+import perf
+
+import greenlet
+import gevent
+from gevent import _tracer as monitor
+
+N = 1000
+
+@contextlib.contextmanager
+def tracer(cls, *args):
+    inst = cls(*args)
+    try:
+        yield
+    finally:
+        inst.kill()
+
+def _run(loops):
+
+    duration = 0
+
+    for _ in range(loops):
+
+        g1 = None
+        def switch():
+            parent = gevent.getcurrent().parent
+            for _ in range(N):
+                parent.switch()
+
+        g1 = gevent.Greenlet(switch)
+        g1.parent = gevent.getcurrent()
+
+        t1 = perf.perf_counter()
+        for _ in range(N):
+            g1.switch()
+
+        t2 = perf.perf_counter()
+
+        duration += t2 - t1
+    return duration
+
+
+def bench_no_trace(loops):
+    return _run(loops)
+
+def bench_trivial_tracer(loops):
+
+    def trivial(_event, _args):
+        return
+
+    greenlet.settrace(trivial)
+    try:
+        return _run(loops)
+    finally:
+        greenlet.settrace(None)
+
+
+def bench_monitor_tracer(loops):
+    with tracer(monitor.GreenletTracer):
+        return _run(loops)
+
+
+def bench_hub_switch_tracer(loops):
+    # use current as the hub, since tracer fires
+    # when we switch into that greenlet
+    with tracer(monitor.HubSwitchTracer, gevent.getcurrent(), 1):
+        return _run(loops)
+
+def bench_max_switch_tracer(loops):
+    # use object() as the hub, since tracer fires
+    # when switch into something that's *not* the hub
+    with tracer(monitor.MaxSwitchTracer, object, 1):
+        return _run(loops)
+
+def main():
+    runner = perf.Runner()
+
+    runner.bench_time_func(
+        "no tracer",
+        bench_no_trace,
+        inner_loops=N
+    )
+
+    runner.bench_time_func(
+        "trivial tracer",
+        bench_trivial_tracer,
+        inner_loops=N
+    )
+
+    runner.bench_time_func(
+        "monitor tracer",
+        bench_monitor_tracer,
+        inner_loops=N
+    )
+
+    runner.bench_time_func(
+        "max switch tracer",
+        bench_max_switch_tracer,
+        inner_loops=N
+    )
+
+    runner.bench_time_func(
+        "hub switch tracer",
+        bench_hub_switch_tracer,
+        inner_loops=N
+    )
+
+
+if __name__ == '__main__':
+    main()

setup.py

@@ -129,6 +129,10 @@ GLT_PRIMITIVES = Extension(name="gevent.__greenlet_primitives",
                            depends=['src/gevent/__greenlet_primitives.pxd'],
                            include_dirs=include_dirs)
 
+TRACER = Extension(name="gevent.__tracer",
+                   sources=["src/gevent/_tracer.py"],
+                   depends=['src/gevent/__tracer.pxd'],
+                   include_dirs=include_dirs)
 
 
 _to_cythonize = [
@@ -137,6 +141,7 @@ _to_cythonize = [
     HUB_LOCAL,
     WAITER,
     GREENLET,
+    TRACER,
 
     SEMAPHORE,
     LOCAL,
@@ -161,6 +166,7 @@ EXT_MODULES = [
     WAITER,
     HUB_PRIMITIVES,
     GLT_PRIMITIVES,
+    TRACER,
 ]
 
 LIBEV_CFFI_MODULE = 'src/gevent/libev/_corecffi_build.py:ffi'
@@ -254,9 +260,13 @@ if PYPY:
 
     EXT_MODULES.remove(GLT_PRIMITIVES)
     _to_cythonize.remove(GLT_PRIMITIVES)
+
     EXT_MODULES.remove(HUB_PRIMITIVES)
     _to_cythonize.remove(HUB_PRIMITIVES)
 
+    EXT_MODULES.remove(TRACER)
+    _to_cythonize.remove(TRACER)
+
 
 for mod in _to_cythonize:
     EXT_MODULES.remove(mod)

src/gevent/__tracer.pxd

+cimport cython
+
+cdef sys
+cdef traceback
+
+cdef settrace
+cdef getcurrent
+
+cdef format_run_info
+
+cdef perf_counter
+cdef gmctime
+
+
+cdef class GreenletTracer:
+    cpdef readonly object active_greenlet
+    cpdef readonly object previous_trace_function
+    cpdef readonly Py_ssize_t greenlet_switch_counter
+
+    cdef bint _killed
+
+    cpdef _trace(self, str event, tuple args)
+
+    @cython.locals(did_switch=bint)
+    cpdef did_block_hub(self, hub)
+
+    cpdef kill(self)
+
+@cython.internal
+cdef class _HubTracer(GreenletTracer):
+    cpdef readonly object hub
+    cpdef readonly double max_blocking_time
+
+
+cdef class HubSwitchTracer(_HubTracer):
+    cpdef readonly double last_entered_hub
+
+cdef class MaxSwitchTracer(_HubTracer):
+    cpdef readonly double max_blocking
+    cpdef readonly double last_switch
+
+    @cython.locals(switched_at=double)
+    cpdef _trace(self, str event, tuple args)

src/gevent/_monitor.py

@@ -3,16 +3,13 @@ from __future__ import print_function, absolute_import, division
 
 import os
 import sys
-import traceback
 
 from weakref import ref as wref
 
-from greenlet import settrace
 from greenlet import getcurrent
 
 from gevent import config as GEVENT_CONFIG
 from gevent.monkey import get_original
-from gevent.util import format_run_info
 from gevent.events import notify
 from gevent.events import EventLoopBlocked
 from gevent.events import MemoryUsageThresholdExceeded
@@ -20,9 +17,10 @@ from gevent.events import MemoryUsageUnderThreshold
 from gevent.events import IPeriodicMonitorThread
 from gevent.events import implementer
 
+from gevent._tracer import GreenletTracer
 from gevent._compat import thread_mod_name
 from gevent._compat import perf_counter
-from gevent._util import gmctime
+
 
 
 __all__ = [
@@ -39,148 +37,6 @@ class MonitorWarning(RuntimeWarning):
     """The type of warnings we emit."""
 
 
-class GreenletTracer(object):
-
-    # A counter, incremented by the greenlet trace function
-    # we install on every greenlet switch. This is reset when the
-    # periodic monitoring thread runs.
-    greenlet_switch_counter = 0
-
-    # The greenlet last switched to.
-    active_greenlet = None
-
-    # The trace function that was previously installed,
-    # if any.
-    previous_trace_function = None
-
-    def __init__(self):
-        prev_trace = settrace(self)
-        self.previous_trace_function = prev_trace
-
-    def kill(self): #  pylint:disable=method-hidden
-        # Must be called in the monitored thread.
-        settrace(self.previous_trace_function)
-        self.previous_trace_function = None
-        # Become a no-op
-        self.kill = lambda: None
-
-    def __call__(self, event, args):
-        # This function runs in the thread we are monitoring.
-        self.greenlet_switch_counter += 1
-        if event in ('switch', 'throw'):
-            # args is (origin, target). This is the only defined
-            # case
-            self.active_greenlet = args[1]
-        else:
-            self.active_greenlet = None
-        if self.previous_trace_function is not None:
-            self.previous_trace_function(event, args)
-
-    def did_block_hub(self, hub):
-        # Check to see if we have blocked since the last call to this
-        # method. Returns a true value if we blocked (not in the hub),
-        # a false value if everything is fine.
-
-        # This may be called in the same thread being traced or a
-        # different thread; if a different thread, there is a race
-        # condition with this being incremented in the thread we're
-        # monitoring, but probably not often enough to lead to
-        # annoying false positives.
-
-        active_greenlet = self.active_greenlet
-        did_switch = self.greenlet_switch_counter != 0
-        self.greenlet_switch_counter = 0
-
-        if did_switch or active_greenlet is None or active_greenlet is hub:
-            # Either we switched, or nothing is running (we got a
-            # trace event we don't know about or were requested to
-            # ignore), or we spent the whole time in the hub, blocked
-            # for IO. Nothing to report.
-            return False
-        return True, active_greenlet
-
-    def ignore_current_greenlet_blocking(self):
-        # Don't pay attention to the current greenlet.
-        self.active_greenlet = None
-
-    def monitor_current_greenlet_blocking(self):
-        self.active_greenlet = getcurrent()
-
-    def did_block_hub_report(self, hub, active_greenlet, format_kwargs):
-        report = ['=' * 80,
-                  '\n%s : Greenlet %s appears to be blocked' %
-                  (gmctime(), active_greenlet)]
-        report.append("    Reported by %s" % (self,))
-        try:
-            frame = sys._current_frames()[hub.thread_ident]
-        except KeyError:
-            # The thread holding the hub has died. Perhaps we shouldn't
-            # even report this?
-            stack = ["Unknown: No thread found for hub %r\n" % (hub,)]
-        else:
-            stack = traceback.format_stack(frame)
-        report.append('Blocked Stack (for thread id %s):' % (hex(hub.thread_ident),))
-        report.append(''.join(stack))
-        report.append("Info:")
-        report.extend(format_run_info(**format_kwargs))
-
-        return report
-
-class _HubTracer(GreenletTracer):
-    def __init__(self, hub, max_blocking_time):
-        GreenletTracer.__init__(self)
-        self.max_blocking_time = max_blocking_time
-        self.hub = hub
-
-    def kill(self): # pylint:disable=method-hidden
-        self.hub = None
-        GreenletTracer.kill(self)
-
-
-class HubSwitchTracer(_HubTracer):
-    # A greenlet tracer that records the last time we switched *into* the hub.
-
-    last_entered_hub = 0
-
-    def __call__(self, event, args):
-        GreenletTracer.__call__(self, event, args)
-        if self.active_greenlet is self.hub:
-            self.last_entered_hub = perf_counter()
-
-    def did_block_hub(self, hub):
-        if perf_counter() - self.last_entered_hub > self.max_blocking_time:
-            return True, self.active_greenlet
-
-
-class MaxSwitchTracer(_HubTracer):
-    # A greenlet tracer that records the maximum time between switches,
-    # not including time spent in the hub.
-
-    max_blocking = 0
-
-    def __init__(self, hub, max_blocking_time):
-        _HubTracer.__init__(self, hub, max_blocking_time)
-        self.last_switch = perf_counter()
-
-    def __call__(self, event, args):
-        old_active = self.active_greenlet
-        GreenletTracer.__call__(self, event, args)
-        if old_active is not self.hub and old_active is not None:
-            # If we're switching out of the hub, the blocking
-            # time doesn't count.
-            switched_at = perf_counter()
-            self.max_blocking = max(self.max_blocking,
-                                    switched_at - self.last_switch)
-
-    def did_block_hub(self, hub):
-        if self.max_blocking == 0:
-            # We never switched. Check the time now
-            self.max_blocking = perf_counter() - self.last_switch
-
-        if self.max_blocking > self.max_blocking_time:
-            return True, self.active_greenlet
-
-
 class _MonitorEntry(object):
 
     __slots__ = ('function', 'period', 'last_run_time')

src/gevent/_tracer.py

+# Copyright (c) 2018 gevent. See LICENSE for details.
+# cython: auto_pickle=False,embedsignature=True,always_allow_keywords=False
+from __future__ import print_function, absolute_import, division
+
+import sys
+import traceback
+
+from greenlet import settrace
+from greenlet import getcurrent
+
+from gevent.util import format_run_info
+
+from gevent._compat import perf_counter
+from gevent._util import gmctime
+
+
+__all__ = [
+    'GreenletTracer',
+    'HubSwitchTracer',
+    'MaxSwitchTracer',
+]
+
+# Recall these classes are cython compiled, so
+# class variable declarations are bad.
+
+
+class GreenletTracer(object):
+    def __init__(self):
+        # A counter, incremented by the greenlet trace function
+        # we install on every greenlet switch. This is reset when the
+        # periodic monitoring thread runs.
+
+        self.greenlet_switch_counter = 0
+
+        # The greenlet last switched to.
+        self.active_greenlet = None
+
+        # The trace function that was previously installed,
+        # if any.
+        # NOTE: Calling a class instance is cheaper than
+        # calling a bound method (at least when compiled with cython)
+        # even when it redirects to another function.
+        prev_trace = settrace(self)
+
+        self.previous_trace_function = prev_trace
+
+        self._killed = False
+
+    def kill(self):
+        # Must be called in the monitored thread.
+        if not self._killed:
+            self._killed = True
+            settrace(self.previous_trace_function)
+            self.previous_trace_function = None
+
+    def _trace(self, event, args):
+        # This function runs in the thread we are monitoring.
+        self.greenlet_switch_counter += 1
+        if event in ('switch', 'throw'):
+            # args is (origin, target). This is the only defined
+            # case
+            self.active_greenlet = args[1]
+        else:
+            self.active_greenlet = None
+        if self.previous_trace_function is not None:
+            self.previous_trace_function(event, args)
+
+    def __call__(self, event, args):
+        return self._trace(event, args)
+
+    def did_block_hub(self, hub):
+        # Check to see if we have blocked since the last call to this
+        # method. Returns a true value if we blocked (not in the hub),
+        # a false value if everything is fine.
+
+        # This may be called in the same thread being traced or a
+        # different thread; if a different thread, there is a race
+        # condition with this being incremented in the thread we're
+        # monitoring, but probably not often enough to lead to
+        # annoying false positives.
+
+        active_greenlet = self.active_greenlet
+        did_switch = self.greenlet_switch_counter != 0
+        self.greenlet_switch_counter = 0
+
+        if did_switch or active_greenlet is None or active_greenlet is hub:
+            # Either we switched, or nothing is running (we got a
+            # trace event we don't know about or were requested to
+            # ignore), or we spent the whole time in the hub, blocked
+            # for IO. Nothing to report.
+            return False
+        return True, active_greenlet
+
+    def ignore_current_greenlet_blocking(self):
+        # Don't pay attention to the current greenlet.
+        self.active_greenlet = None
+
+    def monitor_current_greenlet_blocking(self):
+        self.active_greenlet = getcurrent()
+
+    def did_block_hub_report(self, hub, active_greenlet, format_kwargs):
+        report = ['=' * 80,
+                  '\n%s : Greenlet %s appears to be blocked' %
+                  (gmctime(), active_greenlet)]
+        report.append("    Reported by %s" % (self,))
+        try:
+            frame = sys._current_frames()[hub.thread_ident]
+        except KeyError:
+            # The thread holding the hub has died. Perhaps we shouldn't
+            # even report this?
+            stack = ["Unknown: No thread found for hub %r\n" % (hub,)]
+        else:
+            stack = traceback.format_stack(frame)
+        report.append('Blocked Stack (for thread id %s):' % (hex(hub.thread_ident),))
+        report.append(''.join(stack))
+        report.append("Info:")
+        report.extend(format_run_info(**format_kwargs))
+
+        return report
+
+
+class _HubTracer(GreenletTracer):
+    def __init__(self, hub, max_blocking_time):
+        GreenletTracer.__init__(self)
+        self.max_blocking_time = max_blocking_time
+        self.hub = hub
+
+    def kill(self):
+        self.hub = None
+        GreenletTracer.kill(self)
+
+
+class HubSwitchTracer(_HubTracer):
+    # A greenlet tracer that records the last time we switched *into* the hub.
+
+    def __init__(self, hub, max_blocking_time):
+        _HubTracer.__init__(self, hub, max_blocking_time)
+        self.last_entered_hub = 0
+
+    def _trace(self, event, args):
+        GreenletTracer._trace(self, event, args)
+        if self.active_greenlet is self.hub:
+            self.last_entered_hub = perf_counter()
+
+    def did_block_hub(self, hub):
+        if perf_counter() - self.last_entered_hub > self.max_blocking_time:
+            return True, self.active_greenlet
+
+
+class MaxSwitchTracer(_HubTracer):
+    # A greenlet tracer that records the maximum time between switches,
+    # not including time spent in the hub.
+
+    def __init__(self, hub, max_blocking_time):
+        _HubTracer.__init__(self, hub, max_blocking_time)
+        self.last_switch = perf_counter()
+        self.max_blocking = 0
+
+    def _trace(self, event, args):
+        old_active = self.active_greenlet
+        GreenletTracer._trace(self, event, args)
+        if old_active is not self.hub and old_active is not None:
+            # If we're switching out of the hub, the blocking
+            # time doesn't count.
+            switched_at = perf_counter()
+            self.max_blocking = max(self.max_blocking,
+                                    switched_at - self.last_switch)
+
+    def did_block_hub(self, hub):
+        if self.max_blocking == 0:
+            # We never switched. Check the time now
+            self.max_blocking = perf_counter() - self.last_switch
+
+        if self.max_blocking > self.max_blocking_time:
+            return True, self.active_greenlet
+
+
+from gevent._util import import_c_accel
+import_c_accel(globals(), 'gevent.__tracer')

src/gevent/util.py

@@ -557,7 +557,7 @@ class assert_switches(object):
 
     def __enter__(self):
         from gevent import get_hub
-        from gevent import _monitor
+        from gevent import _tracer
 
         self.hub = hub = get_hub()
 
@@ -565,11 +565,11 @@ class assert_switches(object):
         # installed by the monitoring thread, if there is one.
         # As it is, we will chain trace calls back to it.
         if not self.max_blocking_time:
-            self.tracer = _monitor.GreenletTracer()
+            self.tracer = _tracer.GreenletTracer()
         elif self.hub_only:
-            self.tracer = _monitor.HubSwitchTracer(hub, self.max_blocking_time)
+            self.tracer = _tracer.HubSwitchTracer(hub, self.max_blocking_time)
         else:
-            self.tracer = _monitor.MaxSwitchTracer(hub, self.max_blocking_time)
+            self.tracer = _tracer.MaxSwitchTracer(hub, self.max_blocking_time)
 
         self.tracer.monitor_current_greenlet_blocking()
         return self

src/greentest/test___monitor.py

@@ -217,9 +217,9 @@ class TestPeriodicMonitorBlocking(_AbstractTestPeriodicMonitoringThread,
         self.assertEqual(gettrace(), self.pmt._greenlet_tracer)
         self.assertIs(self.pmt._greenlet_tracer.previous_trace_function, f)
 
-        self.pmt._greenlet_tracer('event', 'args')
+        self.pmt._greenlet_tracer('event', ('args',))
 
-        self.assertEqual([('event', 'args')], called)
+        self.assertEqual([('event', ('args',))], called)
 
     def test__greenlet_tracer(self):
         self.assertEqual(0, self.pmt._greenlet_tracer.greenlet_switch_counter)
@@ -236,7 +236,7 @@ class TestPeriodicMonitorBlocking(_AbstractTestPeriodicMonitoringThread,
         self.assertIs(target, self.pmt._greenlet_tracer.active_greenlet)
 
         # Unknown event removes active greenlet
-        self.pmt._greenlet_tracer('unknown', self)
+        self.pmt._greenlet_tracer('unknown', ())
         self.assertEqual(3, self.pmt._greenlet_tracer.greenlet_switch_counter)
         self.assertIsNone(self.pmt._greenlet_tracer.active_greenlet)