Try C++ implementation of profiler hook (#26)

* Try C++ implementation of profiler hook
* refactor the event profiler

_doc/examples/README.txt

@@ -1,3 +1,3 @@
 
-Examples
-========
+Gallery of Examples
+===================

_doc/examples/plot_profiling.py

@@ -19,7 +19,10 @@
 """
 
 import time
-from cpyquickhelper.profiling import EventProfiler, WithEventProfiler
+import inspect
+from cpyquickhelper.profiling import (
+    EventProfiler, WithEventProfiler)
+from cpyquickhelper.profiling.event_profiler import EventProfilerDebug
 
 
 def f1(t):
@@ -93,3 +96,39 @@ def clean_name(name):
     f4()
 
 wev.report
+
+##########################################
+# Profiling cost
+# ++++++++++++++
+#
+# Logging an events takes a few microseconds so
+# A class not profiling but still logging is available
+# to measure the cost of the profiling.
+
+
+def measure_implementation(impl):
+    N = 100000
+    ev = EventProfilerDebug(impl=impl)
+    ev.start()
+    begin = time.perf_counter()
+
+    if impl == 'python':
+        for _ in range(N):
+            ev.log_event(inspect.currentframe(), 'call', None)
+            ev.log_event(inspect.currentframe(), 'return', None)
+    else:
+        for _ in range(N):
+            ev._buffer.c_log_event(
+                inspect.currentframe(), 'call', None)
+            ev._buffer.c_log_event(
+                inspect.currentframe(), 'return', None)
+
+    end = time.perf_counter()
+    ev.stop()
+    duration = end - begin
+    msg = "%s: %1.6f microsecond" % (impl, duration / N * 1e6)
+    return msg
+
+
+print(measure_implementation('python'))
+print(measure_implementation('pybind11'))

_unittests/ut_profiling/test_event_profiler.py

@@ -2,15 +2,19 @@
 @brief      test log(time=3s)
 """
 import unittest
-from time import sleep
+import inspect
+import logging
+from time import sleep, perf_counter
 from pyquickhelper.pycode import ExtTestCase
-from cpyquickhelper.profiling import EventProfiler, WithEventProfiler
+from cpyquickhelper.profiling import (
+    EventProfiler, WithEventProfiler)
+from cpyquickhelper.profiling.event_profiler import EventProfilerDebug
 
 
 class TestEventProfiler(ExtTestCase):
 
     def test_profiling_exc(self):
-        ev = EventProfiler()
+        ev = EventProfiler(impl='python')
         self.assertRaise(lambda: ev.stop(), RuntimeError)
         ev.start()
         self.assertRaise(lambda: ev.start(), RuntimeError)
@@ -34,7 +38,7 @@ def f4():
             f2()
             f3()
 
-        ev = EventProfiler()
+        ev = EventProfiler(impl='python')
         ev.start()
         f4()
         ev.stop()
@@ -64,7 +68,7 @@ def f4():
             f2()
             f3()
 
-        ev = EventProfiler(20)
+        ev = EventProfiler(size=30, impl='python')
         ev.start()
         f4()
         ev.stop()
@@ -90,7 +94,7 @@ def catch_exc():
             except RuntimeError as e:
                 return str(e)
 
-        ev = EventProfiler()
+        ev = EventProfiler(impl='python')
         ev.start()
         catch_exc()
         ev.stop()
@@ -104,7 +108,7 @@ def test_with_sleep(self):
         def fsleep():
             sleep(0.1)
 
-        prof = WithEventProfiler()
+        prof = WithEventProfiler(impl='python')
         with prof:
             fsleep()
         df = prof.report
@@ -117,12 +121,128 @@ def fraise():
             raise RuntimeError("TESTISSUE")
 
         try:
-            prof = WithEventProfiler()
+            prof = WithEventProfiler(impl='python')
             with prof:
                 fraise()
         except RuntimeError as e:
             self.assertEqual(str(e), 'TESTISSUE')
 
+    def test_debug(self):
+        N = 100000
+        ev = EventProfilerDebug(impl='python')
+        ev.start()
+        begin = perf_counter()
+        for _ in range(N):
+            ev.log_event(inspect.currentframe(), 'call', None)
+            ev.log_event(inspect.currentframe(), 'return', None)
+        end = perf_counter()
+        ev.stop()
+        duration = end - begin
+        msg = "evpy: %1.6f microsecond" % (duration / N * 1e6)
+        self.assertNotEmpty(msg)
+        if __name__ == "__main__":
+            print(msg)
+
+    def test_debug_c(self):
+        N = 100000
+        ev = EventProfilerDebug(impl='pybind11', size=10000000)
+        ev.start()
+        begin = perf_counter()
+        for _ in range(N):
+            ev._buffer.c_log_event(  # pylint: disable=W0212
+                inspect.currentframe(), 'call', None)
+            ev._buffer.c_log_event(  # pylint: disable=W0212
+                inspect.currentframe(), 'return', None)
+        end = perf_counter()
+        ev.stop()
+        duration = end - begin
+        msg = "evc+: %1.6f microsecond" % (duration / N * 1e6)
+        self.assertNotEmpty(msg)
+        if __name__ == "__main__":
+            print(msg)
+
+    def test_debug_logging(self):
+        N = 100
+        logger = logging.getLogger('cpyquickhelper-ut')
+        logger.setLevel(logging.INFO)
+        ev = EventProfilerDebug(impl='pybind11', size=10000000)
+        ev.start()
+        begin = perf_counter()
+        for _ in range(N):
+            logger.info("call %d", inspect.currentframe().f_lineno)
+            logger.info("return %d", inspect.currentframe().f_lineno)
+        end = perf_counter()
+        ev.stop()
+        duration = end - begin
+        msg = "logg: %1.6f microsecond" % (duration / N * 1e6)
+        self.assertNotEmpty(msg)
+        if __name__ == "__main__":
+            print(msg)
+
+    def test_profiling_c(self):
+
+        def f1(t):
+            sleep(t)
+
+        def f2():
+            f1(0.1)
+
+        def f3():
+            li = [0 for i in range(0, 10000)]
+            f1(0.2)
+            return li
+
+        def f4():
+            f2()
+            f3()
+
+        ev = EventProfiler(impl='pybind11')
+        ev.start()
+        f4()
+        ev.stop()
+        res = ev.retrieve_raw_results()
+        self.assertEqual(res.shape[1], ev.n_columns)
+        df = ev.retrieve_results(False)
+        self.assertEqual(df.shape, (res.shape[0], 10))
+        expected = ['time', 'value1', 'value2', 'event',
+                    'name', 'mod', 'lineno', 'from_name',
+                    'from_mod', 'from_line']
+        self.assertEqual(list(df.columns), expected)
+        self.assertIn('sleep', set(df['name']))
+        self.assertIn('time', set(df['mod']))
+
+    def test_profiling_c_20(self):
+
+        def f1(t):
+            sleep(t)
+
+        def f2():
+            f1(0.1)
+
+        def f3():
+            li = [0 for i in range(0, 10000)]
+            f1(0.2)
+            return li
+
+        def f4():
+            f2()
+            f3()
+
+        ev = EventProfiler(impl='pybind11', size=220)
+        ev.start()
+        f4()
+        ev.stop()
+        res = ev.retrieve_raw_results()
+        self.assertEqual(res.shape[1], ev.n_columns)
+        df = ev.retrieve_results(False)
+        self.assertEqual(df.shape, (res.shape[0], 10))
+        expected = ['time', 'value1', 'value2', 'event',
+                    'name', 'mod', 'lineno', 'from_name',
+                    'from_mod', 'from_line']
+        self.assertEqual(list(df.columns), expected)
+        self.assertIn('sleep', set(df['name']))
+        self.assertIn('time', set(df['mod']))
+
 
 if __name__ == "__main__":
     unittest.main()

bin/build.bat

@@ -6,13 +6,7 @@ cd %root%
 @echo Compile
 @echo running %root%\setup.py build_ext --inplace
 @echo ##################
-set pythonexe="c:\Python372_x64\python.exe"
-if not exist %pythonexe% set pythonexe="c:\Python370_x64\python.exe"
-if not exist %pythonexe% set pythonexe="c:\Python366_x64\python.exe"
-if not exist %pythonexe% set pythonexe="c:\Python365_x64\python.exe"
-if not exist %pythonexe% set pythonexe="c:\Python364_x64\python.exe"
-if not exist %pythonexe% set pythonexe="c:\Python363_x64\python.exe"
-if not exist %pythonexe% set pythonexe="c:\Python36_x64\python.exe"
+set pythonexe=python
 %pythonexe% -u %root%\setup.py build_ext --inplace
 if %errorlevel% neq 0 exit /b %errorlevel%
 @echo Done Compile.

cpyquickhelper/profiling/_event_profiler.cpp

@@ -7,7 +7,6 @@
 #include <iostream>
 #include <cstring>
 
-
 std::string CEventProfilerEvent::to_string() const {
     char buf[50];
     sprintf(buf, "%lld,%lld,%lld,%lld,%lld,%lld",
@@ -16,6 +15,43 @@ std::string CEventProfilerEvent::to_string() const {
 }
 
 
+std::unordered_map<std::string, int64_t> CEventProfiler::_get_mapping() {
+    std::unordered_map<std::string, int64_t> ev;
+    ev["call"] = 1;
+    ev["return"] = 2;
+    ev["c_call"] = 3;
+    ev["c_return"] = 4;
+    ev["exception"] = 5;
+    ev["c_exception"] = 6;
+    ev["profiler_call"] = 10;
+    ev["profiler_return"] = 11;
+    ev["profiler_start"] = 100;
+    ev["profiler_sort"] = 101;
+    ev["malloc"] = 1000;
+    ev["calloc"] = 1001;
+    ev["realloc"] = 1002;
+    ev["free"] = 1003;
+    ev["realloc_free"] = 1004;
+    return ev;
+}
+
+
+void CEventProfiler::delete_pyobj() {
+    _mtx.lock();
+    _mem_frame.clear();
+    _mem_arg.clear();
+    _mtx.unlock();
+}
+
+
+CEventProfiler::~CEventProfiler() {
+    if (_mem_frame.size() > 0 || _mem_arg.size() > 0)
+        throw std::runtime_error(MakeString(
+            "Method delete must be called explicitely. There are ",
+            _mem_frame.size(), " remaining python objects to free."));
+}
+
+
 std::string CEventProfiler::__str__() const {
     char buf[100];
     sprintf(buf, "CEventProfiler(%d)", (int)_buffer.size());
@@ -30,14 +66,18 @@ std::string CEventProfiler::__repr__() const {
 }
 
 
-int64_t CEventProfiler::dump(int64_t* buffer, int64_t size, bool lock) {
+int64_t CEventProfiler::dump_and_clear(int64_t* buffer, int64_t size, bool lock) {
     if (lock)
         _mtx.lock();
     int64_t cpy_size = sizeof(CEventProfilerEvent) * _last_position;
     if (size * (int64_t)sizeof(int64_t) < cpy_size)
-        throw std::runtime_error("Buffer is not big enough.");
+        throw std::runtime_error(MakeString(
+            "Buffer is not big enough: ", size * (int64_t)sizeof(int64_t),
+            " >= ", cpy_size, " (copy buffer size)."));
     memcpy(buffer, _buffer.data(), cpy_size);
+    int64_t ret = _last_position;
+    _last_position = 0;
     if (lock)
         _mtx.unlock();
-    return cpy_size;
+    return ret;
 }