pybind / pybind/pybind11

[BUG]: Missing calls from a cProfile profile when calling into a pybind11 extension

Open
#5,600 2 comments 2 reactions 0 assignees View on GitHub

Nobody has claimed this yet.

triage
Dominant language
C++
Stars
18k
Forks
2.3k
Avg merge
5d 17h
Merged PRs (30d)
10

Description

Required prerequisites
What version (or hash if on master) of pybind11 are you using?

tried with both 2.13.6 and master

Problem description

Consider the following Python code using cProfile:

import cProfile
import sys

import ext

def call_me() -> None:
    obj = ext.CppClass()
    for _ in range(10):
        obj.call_me()

def main() -> None:
    print("Profiling...\n\n")
    cProfile.run("call_me()")

if __name__ == "__main__":
    main()

where ext is the following pybind11 extension:

#include <pybind11/pybind11.h>

namespace myspace {
class CppClass {};
} // namespace myspace

namespace py = pybind11;

PYBIND11_MODULE(ext, m) {
  m.doc() = "Simple C++ Python extension using pybind11";

  m.def("return_zero", []() { return 0; });

  py::class_<myspace::CppClass>(m, "CppClass")
      .def(py::init<>())
      .def("call_me", [](myspace::CppClass& self) {
        printf("hello!\n");
        return 0;
      });
}

Running this under Python 3.12.8 produces the following output:

Profiling...


hello!
hello!
hello!
hello!
hello!
hello!
hello!
hello!
hello!
hello!
         1 function calls in 0.000 seconds

   Ordered by: standard name

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        1    0.000    0.000    0.000    0.000 {method 'disable' of '_lsprof.Profiler' objects}

Notably, the resulting profile doesn't include anything about the Python call to call_me(), nor the 10 calls to the pybind11 call_me() method on the obj instance. We can see from the "hello" prints in the output that the method was indeed called.

Interestingly, when changing the call inside the loop to ext.return_zero() instead, the profile produced is as expected:

Profiling...


         14 function calls in 0.000 seconds

   Ordered by: standard name

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        1    0.000    0.000    0.000    0.000 <string>:1(<module>)
        1    0.000    0.000    0.000    0.000 repro.py:11(call_me)
        1    0.000    0.000    0.000    0.000 {built-in method builtins.exec}
       10    0.000    0.000    0.000    0.000 {built-in method ext.return_zero}
        1    0.000    0.000    0.000    0.000 {method 'disable' of '_lsprof.Profiler' objects}

Using Python 3.10 instead of 3.12, the second profile is identical, while the first one is still missing some calls, but it's not missing the initial Python call_me() call:

Profiling...


hello!
hello!
hello!
hello!
hello!
hello!
hello!
hello!
hello!
hello!
         4 function calls in 0.000 seconds

   Ordered by: standard name

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        1    0.000    0.000    0.000    0.000 <string>:1(<module>)
        1    0.000    0.000    0.000    0.000 repro.py:11(call_me)
        1    0.000    0.000    0.000    0.000 {built-in method builtins.exec}
        1    0.000    0.000    0.000    0.000 {method 'disable' of '_lsprof.Profiler' objects}

I think this is likely pybind11-specific, because I tried reproducing this with an equivalent C++ extension using hand crafted C-API, and couldn't observe the issue.

Reproducible example code

Is this a regression? Put the last known working version here if it is.

Not a regression

Contributor guide

Open the contributing guide

First steps

  1. Read the whole issue, then the project's contributing guide.
  2. Comment on the issue to say you are picking it up — it saves two people doing the same work.
  3. Fork the repository and make your change on a branch.
  4. Open a pull request that references the issue number.

Research direction

Start with the Python cProfile example and the pybind11 extension definitions for CppClass.call_me and ext.return_zero, comparing their profiles on Python 3.10 and 3.12. Trace the pybind11 call path against the hand-crafted C-API comparison mentioned in the issue. Done means calls to call_me and its surrounding Python function appear correctly in the generated profile.

Written by the indexing model from the issue text.

Assessment

Tech stack
cpp, python
Domain
backend
Issue type
Bug
Difficulty
4/5
Estimated time
3-5 days
Activity status
Stale
Clarity
Mostly clear
Newbie friendliness
35/100

Get new issues in your inbox

A short digest of beginner-friendly GitHub issues.