Issue python#26588: add debug traces

Try to debug random failure on buildbots.

Author: vstinner

Lib/test/test_tracemalloc.py

@@ -88,13 +88,18 @@ def traceback_filename(filename):
 
 class TestTracemallocEnabled(unittest.TestCase):
     def setUp(self):
+        if _testcapi:
+            _testcapi.tracemalloc_set_debug(True)
+
         if tracemalloc.is_tracing():
             self.skipTest("tracemalloc must be stopped before the test")
 
         tracemalloc.start(1)
 
     def tearDown(self):
         tracemalloc.stop()
+        if _testcapi:
+            _testcapi.tracemalloc_set_debug(False)
 
     def test_get_tracemalloc_memory(self):
         data = [allocate_bytes(123) for count in range(1000)]
@@ -877,6 +882,9 @@ class TestCAPI(unittest.TestCase):
     maxDiff = 80 * 20
 
     def setUp(self):
+        if _testcapi:
+            _testcapi.tracemalloc_set_debug(True)
+
         if tracemalloc.is_tracing():
             self.skipTest("tracemalloc must be stopped before the test")
 
@@ -890,6 +898,8 @@ def setUp(self):
 
     def tearDown(self):
         tracemalloc.stop()
+        if _testcapi:
+            _testcapi.tracemalloc_set_debug(False)
 
     def get_traceback(self):
         frames = _testcapi.tracemalloc_get_traceback(self.domain, self.ptr)

Modules/_testcapimodule.c

@@ -3747,6 +3747,19 @@ tracemalloc_get_traceback(PyObject *self, PyObject *args)
     return _PyTraceMalloc_GetTraceback(domain, (Py_uintptr_t)ptr);
 }
 
+PyObject*
+tracemalloc_set_debug(PyObject *self, PyObject *args)
+{
+    int debug;
+    extern int tracemalloc_debug;
+
+    if (!PyArg_ParseTuple(args, "i", &debug))
+        return NULL;
+
+    tracemalloc_debug = debug;
+    Py_RETURN_NONE;
+}
+
 
 static PyMethodDef TestMethods[] = {
     {"raise_exception",         raise_exception,                 METH_VARARGS},
@@ -3936,6 +3949,7 @@ static PyMethodDef TestMethods[] = {
     {"tracemalloc_track", tracemalloc_track, METH_VARARGS},
     {"tracemalloc_untrack", tracemalloc_untrack, METH_VARARGS},
     {"tracemalloc_get_traceback", tracemalloc_get_traceback, METH_VARARGS},
+    {"tracemalloc_set_debug", tracemalloc_set_debug, METH_VARARGS},
     {NULL, NULL} /* sentinel */
 };
 

Modules/_tracemalloc.c

@@ -45,6 +45,8 @@ static struct {
     int use_domain;
 } tracemalloc_config = {TRACEMALLOC_NOT_INITIALIZED, 0, 1, 1};
 
+int tracemalloc_debug = 0;
+
 #if defined(TRACE_RAW_MALLOC) && defined(WITH_THREAD)
 /* This lock is needed because tracemalloc_free() is called without
    the GIL held from PyMem_RawFree(). It cannot acquire the lock because it
@@ -891,18 +893,24 @@ tracemalloc_clear_traces(void)
     _Py_hashtable_clear(tracemalloc_filenames);
 }
 
+#define DEBUG(MSG) \
+    if (tracemalloc_debug) { fprintf(stderr, "[pid %li, tid %li] " MSG "\n", (long)getpid(), PyThread_get_thread_ident()); fflush(stderr); }
+
 
 static int
 tracemalloc_init(void)
 {
+DEBUG("tracemalloc_init()");
     if (tracemalloc_config.initialized == TRACEMALLOC_FINALIZED) {
         PyErr_SetString(PyExc_RuntimeError,
                         "the tracemalloc module has been unloaded");
         return -1;
     }
 
-    if (tracemalloc_config.initialized == TRACEMALLOC_INITIALIZED)
+    if (tracemalloc_config.initialized == TRACEMALLOC_INITIALIZED) {
+DEBUG("tracemalloc_init(): exit (already initialized)");
         return 0;
+    }
 
     PyMem_GetAllocator(PYMEM_DOMAIN_RAW, &allocators.raw);
 
@@ -969,18 +977,23 @@ tracemalloc_init(void)
     /* Disable tracing allocations until hooks are installed. Set
        also the reentrant flag to detect bugs: fail with an assertion error
        if set_reentrant(1) is called while tracing is disabled. */
+DEBUG("tracemalloc_init(): set_reentrant(1)");
     set_reentrant(1);
 
     tracemalloc_config.initialized = TRACEMALLOC_INITIALIZED;
+DEBUG("tracemalloc_init(): done");
     return 0;
 }
 
 
 static void
 tracemalloc_deinit(void)
 {
-    if (tracemalloc_config.initialized != TRACEMALLOC_INITIALIZED)
+DEBUG("tracemalloc_deinit()");
+    if (tracemalloc_config.initialized != TRACEMALLOC_INITIALIZED) {
+DEBUG("tracemalloc_deinit(): exit (not initialized)");
         return;
+    }
     tracemalloc_config.initialized = TRACEMALLOC_FINALIZED;
 
     tracemalloc_stop();
@@ -997,11 +1010,13 @@ tracemalloc_deinit(void)
     }
 #endif
 
+DEBUG("tracemalloc_deinit(): delete reentrant key");
 #ifdef REENTRANT_THREADLOCAL
     PyThread_delete_key(tracemalloc_reentrant_key);
 #endif
 
     Py_XDECREF(unknown_filename);
+DEBUG("tracemalloc_deinit(): done");
 }
 
 
@@ -1011,11 +1026,15 @@ tracemalloc_start(int max_nframe)
     PyMemAllocatorEx alloc;
     size_t size;
 
-    if (tracemalloc_init() < 0)
+DEBUG("tracemalloc_start()");
+    if (tracemalloc_init() < 0) {
+DEBUG("tracemalloc_start(): ERROR! init failed!");
         return -1;
+    }
 
     if (tracemalloc_config.tracing) {
         /* hook already installed: do nothing */
+DEBUG("tracemalloc_start(): exit (already tracing)");
         return 0;
     }
 
@@ -1057,23 +1076,30 @@ tracemalloc_start(int max_nframe)
 
     /* everything is ready: start tracing Python memory allocations */
     tracemalloc_config.tracing = 1;
+
+DEBUG("tracemalloc_start(): set_reentrant(0)");
     set_reentrant(0);
 
+DEBUG("tracemalloc_start(): done");
     return 0;
 }
 
 
 static void
 tracemalloc_stop(void)
 {
-    if (!tracemalloc_config.tracing)
+DEBUG("tracemalloc_stop()");
+    if (!tracemalloc_config.tracing) {
+DEBUG("tracemalloc_stop(): exit (not tracing)");
         return;
+    }
 
     /* stop tracing Python memory allocations */
     tracemalloc_config.tracing = 0;
 
     /* set the reentrant flag to detect bugs: fail with an assertion error if
        set_reentrant(1) is called while tracing is disabled. */
+DEBUG("tracemalloc_stop(): set_reentrant(1)");
     set_reentrant(1);
 
     /* unregister the hook on memory allocators */
@@ -1088,6 +1114,7 @@ tracemalloc_stop(void)
     /* release memory */
     raw_free(tracemalloc_traceback);
     tracemalloc_traceback = NULL;
+DEBUG("tracemalloc_stop(): done");
 }
 
 PyDoc_STRVAR(tracemalloc_is_tracing_doc,
@@ -1455,8 +1482,11 @@ py_tracemalloc_start(PyObject *self, PyObject *args)
     }
     nframe_int = Py_SAFE_DOWNCAST(nframe, Py_ssize_t, int);
 
-    if (tracemalloc_start(nframe_int) < 0)
+    if (tracemalloc_start(nframe_int) < 0) {
+DEBUG("start(): ERROR!");
         return NULL;
+    }
+DEBUG("start(): done");
 
     Py_RETURN_NONE;
 }