Tracking a memory leak in C extension - interpreting the output of PYTHONMALLOCSTATS

Tue Jul 24 06:09:51 EDT 2018

2018-07-23 21:51 GMT+02:00 Thomas Jollans <tjol at tjol.eu>:
> On 23/07/18 20:02, Bartosz Golaszewski wrote:
>> Hi!
>
> Hey!
>
>> A user recently reported a memory leak in python bindings (C extension
>> module) to a C library[1] I wrote. I've been trying to fix it since
>> but so far without success. Since I'm probably dealing with a space
>> leak rather than actual memory leak, valgrind didn't help much even
>> when using malloc as allocator. I'm now trying to use
>> PYTHONMALLOCSTATS but need some help on how to interpret the output
>> emitted it's enabled.
>
> Oh dear.
>
>>
>> [snip]
>>
>> The number of pools in arena 53 continuously grows. Its size column
>> says: 432. I couldn't find any documentation on what it means but I
>> assume it's an allocation of 432 bytes. [...]
>
> I had a quick look at the code (because what else does one do for fun);
> I don't understand much, but what I can tell you is that
>  (a) yes, that is an allocation size in bytes, and
>  (b) as you can see, it uses intervals of 8. This means that pool 53
>      is used for allocations of 424 < nbytes <= 432 bytes. Maybe your
>      breakpoint needs tweaking.
>  (c) Try breaking on _PyObject_Malloc or pymalloc_alloc. I think they're
>      called by both PyMem_Malloc and PyObject_Malloc.
>
> int _PyObject_DebugMallocStats(FILE *out)
>
> https://github.com/python/cpython/blob/b18f8bc1a77193c372d79afa79b284028a2842d7/Objects/obmalloc.c#L2435
>
> static int pymalloc_alloc(void *ctx, void **ptr_p, size_t nbytes)
>
> https://github.com/python/cpython/blob/b18f8bc1a77193c372d79afa79b284028a2842d7/Objects/obmalloc.c#L1327
>
>
> Have fun debugging!
>
> -- Thomas
>
>
>>
>> How do I use the info produced by PYTHONMALLOCSTATS do get to the
>> culprit of the leak? Is there anything wrong in my reasoning here?
>>
>> Best regards,
>> Bartosz Golaszewski
>>
>> [1] https://git.kernel.org/pub/scm/libs/libgpiod/libgpiod.git/
>>
>
> --
> https://mail.python.org/mailman/listinfo/python-list

Thanks for the hints!

I've been able to pinpoint the allocation in question to this line:

    https://git.kernel.org/pub/scm/libs/libgpiod/libgpiod.git/tree/bindings/python/gpiodmodule.c?h=next#n1238

with the following stack trace:

#0  _PyObject_Malloc (ctx=0x0, nbytes=432) at Objects/obmalloc.c:1523
#1  0x0000555555614c38 in _PyMem_DebugRawAlloc (ctx=0x555555a3c340
<_PyMem_Debug+96>, nbytes=400, use_calloc=0) at
Objects/obmalloc.c:1998
#2  0x00005555556238c5 in PyType_GenericAlloc (type=0x7ffff6e06820
<gpiod_LineBulkType>, nitems=0) at Objects/typeobject.c:972
#3  0x0000555555627ba5 in type_call (type=0x7ffff6e06820
<gpiod_LineBulkType>, args=0x7ffff6e21910, kwds=0x0) at
Objects/typeobject.c:929
#4  0x00005555555cc666 in PyObject_Call (kwargs=0x0, args=<optimized
out>, callable=0x7ffff6e06820 <gpiod_LineBulkType>)
    at Objects/call.c:245
#5  PyEval_CallObjectWithKeywords (kwargs=0x0, args=<optimized out>,
callable=0x7ffff6e06820 <gpiod_LineBulkType>) at Objects/call.c:826
#6  PyObject_CallObject (callable=0x7ffff6e06820 <gpiod_LineBulkType>,
args=<optimized out>) at Objects/call.c:834
#7  0x00007ffff6c008dd in gpiod_LineToLineBulk
(line=line at entry=0x7ffff5bbd240) at gpiodmodule.c:1238
#8  0x00007ffff6c009af in gpiod_Line_set_value (self=0x7ffff5bbd240,
args=<optimized out>) at gpiodmodule.c:442
#9  0x00005555555c9ef8 in _PyMethodDef_RawFastCallKeywords
(method=0x7ffff6e06280 <gpiod_Line_methods+384>,
    self=self at entry=0x7ffff5bbd240, args=args at entry=0x555555b15e18,
nargs=nargs at entry=1, kwnames=kwnames at entry=0x0) at Objects/call.c:694
#10 0x0000555555754db9 in _PyMethodDescr_FastCallKeywords
(descrobj=0x7ffff6e344d0, args=args at entry=0x555555b15e10,
nargs=nargs at entry=2,
    kwnames=kwnames at entry=0x0) at Objects/descrobject.c:288
#11 0x00005555555b7fcd in call_function (kwnames=0x0, oparg=2,
pp_stack=<synthetic pointer>) at Python/ceval.c:4581
#12 _PyEval_EvalFrameDefault (f=<optimized out>, throwflag=<optimized
out>) at Python/ceval.c:3176
#13 0x0000555555683b7c in PyEval_EvalFrameEx (throwflag=0,
f=0x555555b15ca0) at Python/ceval.c:536
#14 _PyEval_EvalCodeWithName (_co=_co at entry=0x7ffff7e50460,
globals=globals at entry=0x7ffff7f550e8,
locals=locals at entry=0x7ffff7e50460,
    args=args at entry=0x0, argcount=argcount at entry=0,
kwnames=kwnames at entry=0x0, kwargs=0x0, kwcount=0, kwstep=2, defs=0x0,
defcount=0,
    kwdefs=0x0, closure=0x0, name=0x0, qualname=0x0) at Python/ceval.c:3941
#15 0x0000555555683ca3 in PyEval_EvalCodeEx (closure=0x0, kwdefs=0x0,
defcount=0, defs=0x0, kwcount=0, kws=0x0, argcount=0, args=0x0,
    locals=locals at entry=0x7ffff7e50460,
globals=globals at entry=0x7ffff7f550e8, _co=_co at entry=0x7ffff7e50460) at
Python/ceval.c:3970
#16 PyEval_EvalCode (co=co at entry=0x7ffff7e50460,
globals=globals at entry=0x7ffff7efcc50,
locals=locals at entry=0x7ffff7efcc50)
    at Python/ceval.c:513
#17 0x00005555556bb099 in run_mod (arena=0x7ffff7f550e8,
flags=0x7fffffffe1a0, locals=0x7ffff7efcc50, globals=0x7ffff7efcc50,
    filename=0x7ffff7e5b4c0, mod=0x555555afc2f8) at Python/pythonrun.c:1035
#18 PyRun_FileExFlags (fp=0x555555b26010, filename_str=<optimized
out>, start=<optimized out>, globals=0x7ffff7efcc50,
    locals=0x7ffff7efcc50, closeit=1, flags=0x7fffffffe1a0) at
Python/pythonrun.c:988
#19 0x00005555556bb2b5 in PyRun_SimpleFileExFlags (fp=0x555555b26010,
filename=<optimized out>, closeit=1, flags=0x7fffffffe1a0)
    at Python/pythonrun.c:429
#20 0x00005555555bd5ff in pymain_run_file (p_cf=0x7fffffffe1a0,
filename=0x555555ab7380 L"./gpio_leak.py", fp=0x555555b26010)
    at Modules/main.c:426
#21 pymain_run_filename (cf=0x7fffffffe1a0, pymain=0x7fffffffe2a0) at
Modules/main.c:1521
#22 pymain_run_python (pymain=0x7fffffffe2a0) at Modules/main.c:2570
#23 pymain_main (pymain=pymain at entry=0x7fffffffe2a0) at Modules/main.c:2712
#24 0x00005555555bda3a in _Py_UnixMain (argc=<optimized out>,
argv=<optimized out>) at Modules/main.c:2747
#25 0x00007ffff71322e1 in __libc_start_main (main=0x5555555ae8a0
<main>, argc=2, argv=0x7fffffffe4d8, init=<optimized out>,
    fini=<optimized out>, rtld_fini=<optimized out>,
stack_end=0x7fffffffe4c8) at ../csu/libc-start.c:291
#26 0x00005555555b8dea in _start ()

Except that I can also see in gdb that the object created here is freed find at

    https://git.kernel.org/pub/scm/libs/libgpiod/libgpiod.git/tree/bindings/python/gpiodmodule.c?h=next#n454

#0  _PyObject_Free (ctx=0x0, p=0x7ffff6e32d78) at Objects/obmalloc.c:1780
#1  0x00007ffff6c00a6f in gpiod_Line_set_value (self=<optimized out>,
args=<optimized out>) at gpiodmodule.c:454
#2  0x00005555555c9ef8 in _PyMethodDef_RawFastCallKeywords
(method=0x7ffff6e06280 <gpiod_Line_methods+384>,
    self=self at entry=0x7ffff5bbd240, args=args at entry=0x555555b15e18,
nargs=nargs at entry=1, kwnames=kwnames at entry=0x0) at Objects/call.c:694
#3  0x0000555555754db9 in _PyMethodDescr_FastCallKeywords
(descrobj=0x7ffff6e344d0, args=args at entry=0x555555b15e10,
nargs=nargs at entry=2,
    kwnames=kwnames at entry=0x0) at Objects/descrobject.c:288
#4  0x00005555555b7fcd in call_function (kwnames=0x0, oparg=2,
pp_stack=<synthetic pointer>) at Python/ceval.c:4581
#5  _PyEval_EvalFrameDefault (f=<optimized out>, throwflag=<optimized
out>) at Python/ceval.c:3176
#6  0x0000555555683b7c in PyEval_EvalFrameEx (throwflag=0,
f=0x555555b15ca0) at Python/ceval.c:536
#7  _PyEval_EvalCodeWithName (_co=_co at entry=0x7ffff7e50460,
globals=globals at entry=0x7ffff7f550e8,
locals=locals at entry=0x7ffff7e50460,
    args=args at entry=0x0, argcount=argcount at entry=0,
kwnames=kwnames at entry=0x0, kwargs=0x0, kwcount=0, kwstep=2, defs=0x0,
defcount=0,
    kwdefs=0x0, closure=0x0, name=0x0, qualname=0x0) at Python/ceval.c:3941
#8  0x0000555555683ca3 in PyEval_EvalCodeEx (closure=0x0, kwdefs=0x0,
defcount=0, defs=0x0, kwcount=0, kws=0x0, argcount=0, args=0x0,
    locals=locals at entry=0x7ffff7e50460,
globals=globals at entry=0x7ffff7f550e8, _co=_co at entry=0x7ffff7e50460) at
Python/ceval.c:3970
#9  PyEval_EvalCode (co=co at entry=0x7ffff7e50460,
globals=globals at entry=0x7ffff7efcc50,
locals=locals at entry=0x7ffff7efcc50)
    at Python/ceval.c:513
#10 0x00005555556bb099 in run_mod (arena=0x7ffff7f550e8,
flags=0x7fffffffe1a0, locals=0x7ffff7efcc50, globals=0x7ffff7efcc50,
    filename=0x7ffff7e5b4c0, mod=0x555555afc2f8) at Python/pythonrun.c:1035
#11 PyRun_FileExFlags (fp=0x555555b26010, filename_str=<optimized
out>, start=<optimized out>, globals=0x7ffff7efcc50,
    locals=0x7ffff7efcc50, closeit=1, flags=0x7fffffffe1a0) at
Python/pythonrun.c:988
#12 0x00005555556bb2b5 in PyRun_SimpleFileExFlags (fp=0x555555b26010,
filename=<optimized out>, closeit=1, flags=0x7fffffffe1a0)
    at Python/pythonrun.c:429
#13 0x00005555555bd5ff in pymain_run_file (p_cf=0x7fffffffe1a0,
filename=0x555555ab7380 L"./gpio_leak.py", fp=0x555555b26010)
    at Modules/main.c:426
#14 pymain_run_filename (cf=0x7fffffffe1a0, pymain=0x7fffffffe2a0) at
Modules/main.c:1521
#15 pymain_run_python (pymain=0x7fffffffe2a0) at Modules/main.c:2570
#16 pymain_main (pymain=pymain at entry=0x7fffffffe2a0) at Modules/main.c:2712
#17 0x00005555555bda3a in _Py_UnixMain (argc=<optimized out>,
argv=<optimized out>) at Modules/main.c:2747
#18 0x00007ffff71322e1 in __libc_start_main (main=0x5555555ae8a0
<main>, argc=2, argv=0x7fffffffe4d8, init=<optimized out>,
    fini=<optimized out>, rtld_fini=<optimized out>,
stack_end=0x7fffffffe4c8) at ../csu/libc-start.c:291
#19 0x00005555555b8dea in _start ()

I don't see any other allocation of this size. Can this be some bug in
the interpreter?

Bart