Possible ref counting bug (<refcnt 0 at ...>)

[Valcortez]

Hi,

I'm having a issue with a parameter of a function passed using partial being replaced by a tuple with a single value which prints as <refcnt 0 at ...>. I believe this happens when a second thread is the only one keeping a ref to the partial function. Lemme first describe my code. The following version of the code does work fine:

cdef object _log_callback = None
cdef int log_level = AV_LOG_WARNING

cdef void gil_call_callback(char *line, int level):
    cdef object callback
    callback = _log_callback
    if callback is None:
        return
    callback(tcode(line), _loglevel_inverse[level])

cdef void call_callback(char *line, int level) nogil:
    with gil:
        gil_call_callback(line, level)

cdef void _log_callback_func(void* ptr, int level, const char* fmt, va_list vl) nogil:
    if fmt == NULL or level > log_level:
        return
    do_stuff...
    call_callback(line, level)

The reason for this 3 function deep structure is that I want _log_callback_func to exit quickly if fmt == NULL or level > log_level. But if in this function I acquire the gil then upon the function call the gil is synced which I believe will slow down the call even if we never actually acquire the gil when we return early (see the cleaned generated c code all the way at the end to see what I mean about the additional gil stuff added when the gil is acquired anywhere in the func).

Anyway, here's a short version of the callback that gets set to _log_callback:

def _dshow_log_callback(log, message, level):
    log.append((message.encode('utf8'), level))

cdef int list_dshow_opts(list log):
    global _log_callback
    _log_callback = partial(_dshow_log_callback, log)

Quite often what happens is that _log_callback_func or its called functions is the only place that holds a reference to the generated partial callback because during a _log_callback_func call the global _log_callback maybe be replaced.

Anyway, so far the code works. The problem arises with the following version of the above code:

cdef void gil_call_callback(object callback, char *line, int level) nogil:
    with gil:
        callback(tcode(line), _loglevel_inverse[level])

cdef void call_callback(object callback, char *line, int level) nogil:
    if callback is None or level > log_level:
        return
    gil_call_callback(callback, line, level)

cdef void _log_callback_func(void* ptr, int level, const char* fmt, va_list vl) nogil:
    do_stuff...
    call_callback(_log_callback, line, level)

You'll notice, the difference here is that _log_callback gets captured by _log_callback_func as a parameter without having the gil. The reason for writing the code this way is not completely sane, but mainly I was trying to get the _log_callback value without the gil so I can check whether it's None and exit early quickly in that case.

The problem is that the line log.append((message.encode('utf8'), level)) raises an exception: tuple doesn't have a append method and when inspecting what the value of log is, instead of being a list it prints as (<refcnt 0 at ...>, ). I think this happens only when _log_callback_func is the only place that still has access to the callback.

I wonder whether it's an oversight that the compiler doesn't complain about capturing a global as a function param without the gil? For instance, if I did:

cdef ... nogil:
    cdef object callback
    with gil:
        callback = _log_callback

It complains about python temporaries without gil. In either case, getting the global _log_callback without the gil seems to make the partial function parameter  that is not held elsewhere die too early.

Thanks,
Matt




Here's the generated c code of the working version from above of the functions showing how as long as there is a with gil statement in the function, even if the gil is not acquired and we return before that, gil sync stuff still happens (e.g. PyGILState_Ensure):

static void __pyx_f_10ffpyplayer_5tools_call_callback(char *__pyx_v_line, int __pyx_v_level) {
  __Pyx_RefNannyDeclarations
  #ifdef WITH_THREAD
  PyGILState_STATE __pyx_gilstate_save;
  #endif
  __Pyx_RefNannySetupContext("call_callback", 1);

  {
    {
        #ifdef WITH_THREAD
        PyGILState_STATE __pyx_gilstate_save = PyGILState_Ensure();
        #endif
          __pyx_f_10ffpyplayer_5tools_gil_call_callback(__pyx_v_line, __pyx_v_level);
        }
        /*finally:*/ {
          /*normal exit:*/{
            #ifdef WITH_THREAD
            PyGILState_Release(__pyx_gilstate_save);
            #endif
            goto __pyx_L8;
          }
          __pyx_L8:;
        }
    }
  }
  /*finally:*/ {
    /*normal exit:*/{
      #ifdef WITH_THREAD
      __pyx_gilstate_save = PyGILState_Ensure();
      #endif
      goto __pyx_L5;
    }
    __pyx_L5:;
  }

  /* function exit code */
  #ifdef WITH_THREAD
  PyGILState_Release(__pyx_gilstate_save);
  #endif
}

static void __pyx_f_10ffpyplayer_5tools__log_callback_func(void *__pyx_v_ptr, int __pyx_v_level, char const *__pyx_v_fmt, va_list __pyx_v_vl) {
  int __pyx_t_1;
  int __pyx_t_2;
  __pyx_t_2 = ((__pyx_v_fmt == NULL) != 0);
  if (!__pyx_t_2) {
  } else {
    __pyx_t_1 = __pyx_t_2;
    goto __pyx_L4_bool_binop_done;
  }
  __pyx_t_2 = ((__pyx_v_level > __pyx_v_10ffpyplayer_5tools_log_level) != 0);
  __pyx_t_1 = __pyx_t_2;
  __pyx_L4_bool_binop_done:;
  if (__pyx_t_1) {
    goto __pyx_L0;
  }
  __pyx_f_10ffpyplayer_5tools_call_callback(__pyx_v_line, __pyx_v_level);
  __pyx_L0:;
}

[Valcortez]

Here's a standalone minimal example reproducing the issue:

$ cython -V
Cython version 0.23.4

from functools import partial

cdef object _log_callback = None

def log_callback(log, message):
    print(log, message)

cdef void call_callback(object callback) nogil:
    global _log_callback
    with gil:
        _log_callback = None
        callback(55)

def call_log():
    global _log_callback
    _log_callback = partial(log_callback, [])
    with nogil:
        call_callback(_log_callback)

Then we get:

$ python
Python 2.7.10 (default, May 23 2015, 09:40:32) [MSC v.1500 32 bit (Intel)] on win32
Type "help", "copyright", "credits" or "license" for more information.
>>> from src.cyplayground import call_log
>>> call_log()
((<nil>,), 55)

Notice the nil. However, if we change the example and always have the gil, e.g.

cdef void call_callback(object callback):
    global _log_callback
    _log_callback = None
    callback(55)

def call_log():
    global _log_callback
    _log_callback = partial(log_callback, [])
    call_callback(_log_callback)

Then we get:

>>> from src.cyplayground import call_log
>>> call_log()
([], 55)

Thanks,
Matt