fix(profiling): restart the profiler on uwsgi fork (#2295) (#2302)

In uWSGI, the current code starts in the forked process the ProfilerInstance
that has been created in the master process. That actually works fine, except
all Events are discarded by the Recorder because its `pid` attribute is not
updated: it is still the pid of the master process.

Using the `_restart_on_fork` method makes sure that the `ProfilerInstance` gets
a new `Recorder` object with the correct PID.

The test is updated to not test only for file presence, but making sure that
there is at least one sample included.

This removes test_call_script_pprof_output_interval as it is flaky by
construction and fails with the new extended test.

Co-authored-by: mergify[bot] <37929162+mergify[bot]@users.noreply.github.com>
(cherry picked from commit ea5992b)

Co-authored-by: Julien Danjou <[email protected]>
Co-authored-by: Kyle Verhoog <[email protected]>

Author: 3 people

ddtrace/profiling/profiler.py

@@ -73,7 +73,7 @@ def start(self, stop_on_exit=True, profile_children=True):
 
         if profile_children:
             try:
-                uwsgi.check_uwsgi(self.start, atexit=self.stop if stop_on_exit else None)
+                uwsgi.check_uwsgi(self._restart_on_fork, atexit=self.stop if stop_on_exit else None)
             except uwsgi.uWSGIMasterProcess:
                 # Do nothing, the start() method will be called in each worker subprocess
                 return

releasenotes/notes/profiling-fix-uwsgi-empty-profiles-7dbd5fdd93dea47f.yaml

@@ -0,0 +1,6 @@
+---
+fixes:
+  - |
+    In certain circumstances, the profiles generated in a uWSGI application
+    could have been empty. This is now fixed and the profiler records correctly
+    the generated events.

tests/profiling/exporter/test_file.py

@@ -2,12 +2,12 @@
 
 from ddtrace.profiling.exporter import file
 
-from .. import test_main
+from .. import utils
 from ..exporter import test_pprof
 
 
 def test_export(tmp_path):
     filename = str(tmp_path / "pprof")
     exp = file.PprofFileExporter(filename)
     exp.export(test_pprof.TEST_EVENTS, 0, 1)
-    test_main.check_pprof_file(filename + "." + str(os.getpid()) + ".1")
+    utils.check_pprof_file(filename + "." + str(os.getpid()) + ".1")

tests/profiling/test_main.py

@@ -1,10 +1,9 @@
-import gzip
 import os
 import subprocess
 
 import pytest
 
-from ddtrace.profiling.exporter import pprof_pb2
+from . import utils
 
 
 def call_program(*args):
@@ -38,15 +37,6 @@ def test_call_script_gevent(monkeypatch):
     assert exitcode == 0
 
 
-def check_pprof_file(filename):
-    with gzip.open(filename, "rb") as f:
-        content = f.read()
-    p = pprof_pb2.Profile()
-    p.ParseFromString(content)
-    assert len(p.sample_type) == 11
-    assert p.string_table[p.sample_type[0].type] == "cpu-samples"
-
-
 def test_call_script_pprof_output(tmp_path, monkeypatch):
     """This checks if the pprof output and atexit register work correctly.
 
@@ -58,17 +48,10 @@ def test_call_script_pprof_output(tmp_path, monkeypatch):
     monkeypatch.setenv("DD_PROFILING_ENABLED", "1")
     _, _, exitcode, pid = call_program("ddtrace-run", os.path.join(os.path.dirname(__file__), "simple_program.py"))
     assert exitcode == 42
-    check_pprof_file(filename + "." + str(pid) + ".1")
+    utils.check_pprof_file(filename + "." + str(pid) + ".1")
     return filename, pid
 
 
-def test_call_script_pprof_output_interval(tmp_path, monkeypatch):
-    monkeypatch.setenv("DD_PROFILING_UPLOAD_INTERVAL", "0.1")
-    filename, pid = test_call_script_pprof_output(tmp_path, monkeypatch)
-    for i in (2, 3):
-        check_pprof_file(filename + "." + str(pid) + (".%d" % i))
-
-
 def test_fork(tmp_path, monkeypatch):
     filename = str(tmp_path / "pprof")
     monkeypatch.setenv("DD_PROFILING_API_TIMEOUT", "0.1")
@@ -79,8 +62,8 @@ def test_fork(tmp_path, monkeypatch):
     )
     assert exitcode == 0
     child_pid = stdout.decode().strip()
-    check_pprof_file(filename + "." + str(pid) + ".1")
-    check_pprof_file(filename + "." + str(child_pid) + ".1")
+    utils.check_pprof_file(filename + "." + str(pid) + ".1")
+    utils.check_pprof_file(filename + "." + str(child_pid) + ".1")
 
 
 @pytest.mark.skipif(not os.getenv("DD_PROFILE_TEST_GEVENT", False), reason="Not testing gevent")

tests/profiling/test_uwsgi.py

@@ -10,12 +10,16 @@
 
 from tests.contrib.uwsgi import run_uwsgi
 
+from . import utils
+
 
 uwsgi_app = os.path.join(os.path.dirname(__file__), "uwsgi-app.py")
 
 
 @pytest.fixture
-def uwsgi():
+def uwsgi(monkeypatch):
+    # Do not ignore profiler so we have samples in the output pprof
+    monkeypatch.setenv("DD_PROFILING_IGNORE_PROFILER", "0")
     # Do not use pytest tmpdir fixtures which generate directories longer than allowed for a socket file name
     socket_name = tempfile.mktemp()
     cmd = ["uwsgi", "--need-app", "--die-on-term", "--socket", socket_name, "--wsgi-file", uwsgi_app]
@@ -43,7 +47,7 @@ def test_uwsgi_threads_enabled(uwsgi, tmp_path, monkeypatch):
     proc.terminate()
     assert proc.wait() == 30
     for pid in worker_pids:
-        assert os.path.exists("%s.%d.1" % (filename, pid))
+        utils.check_pprof_file("%s.%d.1" % (filename, pid))
 
 
 def test_uwsgi_threads_processes_no_master(uwsgi, monkeypatch):
@@ -85,7 +89,7 @@ def test_uwsgi_threads_processes_master(uwsgi, tmp_path, monkeypatch):
     proc.terminate()
     assert proc.wait() == 0
     for pid in worker_pids:
-        assert os.path.exists("%s.%d.1" % (filename, pid))
+        utils.check_pprof_file("%s.%d.1" % (filename, pid))
 
 
 def test_uwsgi_threads_processes_master_lazy_apps(uwsgi, tmp_path, monkeypatch):
@@ -98,7 +102,7 @@ def test_uwsgi_threads_processes_master_lazy_apps(uwsgi, tmp_path, monkeypatch):
     proc.terminate()
     assert proc.wait() == 0
     for pid in worker_pids:
-        assert os.path.exists("%s.%d.1" % (filename, pid))
+        utils.check_pprof_file("%s.%d.1" % (filename, pid))
 
 
 # For whatever reason this crashes easily on Python 2.7 with a segfault, and hangs on Python before 3.7.
@@ -154,4 +158,4 @@ def test_uwsgi_threads_processes_no_master_lazy_apps(uwsgi, tmp_path, monkeypatc
             except OSError:
                 break
     for pid in worker_pids:
-        assert os.path.exists("%s.%d.1" % (filename, pid))
+        utils.check_pprof_file("%s.%d.1" % (filename, pid))

tests/profiling/utils.py

@@ -0,0 +1,16 @@
+import gzip
+
+from ddtrace.profiling.exporter import pprof_pb2
+
+
+def check_pprof_file(
+    filename,  # type: str
+):
+    # type: (...) -> None
+    with gzip.open(filename, "rb") as f:
+        content = f.read()
+    p = pprof_pb2.Profile()
+    p.ParseFromString(content)
+    assert len(p.sample_type) == 11
+    assert p.string_table[p.sample_type[0].type] == "cpu-samples"
+    assert len(p.sample) >= 1