记一次刻骨铭心的debug

上个星期遇到了一个非常棘手的bug。我花了一个星期的时间，到昨天已经绝望，谁知柳暗花明醍醐灌顶，今天终于将其攻克，感觉有50%概率这会是我这辈子中印象最深的一次debug。

这次的bug有以下几个特点：

• 是第三方库的bug。所以必须要去看第三方库的源代码，搞清楚别人的代码是干什么的，然后自己hack，自己编译。
• 是一个Higgs-Bugson。只存在于日志中，通过生产环境复现。这一个特性有两个结果，都对debug十分不利：
  • 枪毙了基于断点的debug方法，因为事先不知道bug会在什么时候发生。
  • 第三方库的开发人员不可能有效参与debug过程。
• 最最重要的是：debug情节曲折离奇；结局出人意料，又在情理之中。
• debug过程使我掌握了一个内存调度算法，收获了一些debug技巧，加深了对程序语言的特性的认识。

楔子

最近在开发一个Python数值计算的库，其中与GPU交互的部分选择了cupy作为接口。代码写好了之后，跑简单的测试没问题，一跑长时间的任务就会出现这样的错误：

  File "cupy/cuda/memory.pyx", line 521, in cupy.cuda.memory.alloc
  File "cupy/cuda/memory.pyx", line 1098, in cupy.cuda.memory.MemoryPool.malloc
  File "cupy/cuda/memory.pyx", line 1119, in cupy.cuda.memory.MemoryPool.malloc
  File "cupy/cuda/memory.pyx", line 933, in cupy.cuda.memory.SingleDeviceMemoryPool.malloc
  File "cupy/cuda/memory.pyx", line 949, in cupy.cuda.memory.SingleDeviceMemoryPool._malloc
  File "cupy/cuda/memory.pyx", line 698, in cupy.cuda.memory._get_chunk
  File "cupy/cuda/memory.pyx", line 224, in cupy.cuda.memory._Chunk.split
AssertionError

这是Traceback的下半部分。上半部分基本上是我写的数值计算代码，每次的调用堆栈都不一样，显然和这个bug没有直接关系。这个Traceback提供的信息非常有限，只能大概确定这个bug和cupy的GPU内存调度算法失效有关。

首先上Github查issue，发现没有任何信息。然后尝试多个不同的环境，比如不同GPU，CUDA版本，cupy版本等等，发现时间一长这个错误都会出现。短的可能十分钟，长的要十几个小时。与此同时简单研究了一下文档，发现可以手动关闭cupy的内存调度，每次创建数组直接调用cudaMalloc，绕开这一部分代码。在关闭了cupy内存调度之后这个bug果然消失了，代价是计算速度慢了3到4倍，这对于一个数值计算库来说显然是不可接受的。于是咬咬牙准备好好查一查bug的来源。

以下所有cupy代码适用但不限于5.2.0和5.3.0版本。

cupy的GPU内存调度算法

从AssertionError的调用堆栈上来看，是在分配内存的时候发生的错误，最后调用的split函数如下（Cython）：

cpdef _Chunk split(self, size_t size):
    """Split contiguous block of a larger allocation"""
    cdef _Chunk remaining
    assert self.size >= size
    if self.size == size:
        return None
    remaining = _Chunk.__new__(_Chunk)
    remaining._init(self.mem, self.offset + size, self.size - size,
                    self.stream_ptr)
    self.size = size

    if self.next is not None:
        remaining.next = self.next
        remaining.next.prev = remaining
    self.next = remaining
    remaining.prev = self
    return remaining

其中的的assert self.size >= size就是直接引起AssertionError的代码了。这个assert保护了下面的代码不会出现溢出之类的异常，但本身并没有为debug提供什么有用信息。再往上一层的_get_chunk就显得更有趣一些：

cdef object _get_chunk(SingleDeviceMemoryPool pool, size_t size,
                       size_t stream_ptr):
    # need self._free_lock
    cdef set free_list
    cdef size_t i, index, length
    cdef _Chunk chunk
    cdef size_t bin_index = _bin_index_from_size(size)
    cdef list arena = pool._arena(stream_ptr)
    a_index = pool._arena_index(stream_ptr)
    a_flag = pool._arena_flag(stream_ptr)
    index = <size_t>(
        algorithm.lower_bound(a_index.begin(), a_index.end(), bin_index)
        - a_index.begin())
    length = a_index.size()
    for i in range(index, length):
        if a_flag.at(i) == 0:
            continue
        free_list = arena[i]
        chunk = free_list.pop()
        if len(free_list) == 0:
            dereference(a_flag)[i] = 0
            arena[i] = None
        if i - index >= _index_compaction_threshold:
            _compact_index(pool, stream_ptr, False)
        remaining = chunk.split(size)
        if remaining is not None:
            _append_to_free_list(arena, a_index, a_flag, remaining)
        assert chunk.stream_ptr == stream_ptr
        return chunk
    return None

这个函数包含了丰富的逻辑，在调用chunk.split(size)时如果该chunk的大小没有达到size的要求，就会引起错误。那什么情况下chunk的大小会小于预期呢？这就必须对cupy的内存调度算法有所了解，搞明白各个变量的不变量是什么才可以。

cupy的GPU内存管理算法叫做best-fit with coalescing，简称BFC，与tensorflow相同。原理也简单，所有内存被组织为一个双向链表，链表的每个结点即称为chunk。每个chunk的大小规定为某个数值（比如本例中512 Bytes）的整数倍。相邻的结点如果都没有被使用可以合并，大的节点可以随时被split成两个相邻的小结点供使用。为了加快内存分配，额外维护一个向量，起字典的作用，将所需的内存大小直接映射为可用chunk的集合。

cupy的内存分配代码在2015年刚写的时候还是很简洁漂亮的，后来因为要有新的feature以及要做优化变得丑陋了一些，但总的来说不难理解。就拿我们这里的_get_chunk函数的若干个重要变量来说吧:

• pool表示当前设备的内存池
• size表示所需的chunk的大小
• stream_ptr可以认为是GPU流式计算的线程ID。在我的应用中只有一个流即所谓的NULL流，stream_ptr也一直是0，没有什么作用。
• 从pool中结合stream_ptr取出了三个重要参数arena，a_index和a_flag。
  • arena是一个Python的list，元素为set，每个set中包含了大小为某个值的所有可用chunk。
  • a_index是一个vector<size_t>的指针，大小和arena相同。它的每个元素指出了arena中相同位置的元素（即set）所包含的chunk的大小。如{0,3}表示arena中第一个set的大小是512 Bytes, 第二个是2048 Bytes。
  • a_flag是一个vector<int8_t>的指针，大小也和arena相同，元素取值0或1，指出了a_index的有效性。当特定大小的chunk被耗尽时，原则上应该立刻把arena和a_index中相应的条目删除，但这些对于数组类型的数据结构来说是\(\mathcal{O}(N)\)级别的操作，十分昂贵。为了减小这部分开销引入了a_flag，当特定大小的chunk被耗尽时，只需对a_flag中相应的条目置0即可。这比起判断arena中的set是否为空要快上非常多。当a_flag变得十分稀疏，影响效率时，对其进行一次压缩操作（_compact_index），使删除元素的分摊复杂度大约为\(\mathcal{O}(1)\)。
• 以上三个数组原则上可以是无序的，但是维持它们有序可以更快地进行查找，因此a_index是一个单调上升的数组，arena中每个set包含的chunk的大小也单调增加。

理解了这些数据结构，_get_chunk的逻辑也就变得清晰了。_get_chunk函数将首先试图从当前内存池中找到大小（chunk.size）大于等于size要求的chunk。如果成功将这个chunk分成两份一份给调用者使用一份扔回内存池中。如果失败则返回None，由调用者请求GPU再分配内存。其中，“找到大小大于等于size要求的chunk”分为两步：

1. 调用STL的lower_bound函数从有序数组a_index中进行二分查找找到大小足够的chunk的索引的下界。arena中大于该索引的所有set原则上都可以使用。
2. 从小到大遍历这些set，跳过被a_flag标为无效的部分，找到一个最小的。

显然，如果这个算法正常运行，chunk.split(size)一定会成功。单从肉眼看的话_get_chunk的逻辑没有问题，是骡子是马debug一下才能知道。

稳步推进

由于我面对的是一个Higgs-Bugson，内存分配在发生bug之前可能被执行数百万次，在_get_chunk中打个断点然后一步一步慢慢看是行不通的，只能基于日志debug：

1. 首先写打印SingleDeviceMemoryPool和_Chunk的函数
2. 在_get_chunk中对拿到的chunk进行判断，如果发现大小不满足要求，打印当前的pool和chunk
3. 运行程序并做别的事情

过程其实颇类似于钓鱼。在“做别的事情”时，我也不是没有想过稳定重现这个bug。如果成功，debug会方便很多，打个比方的话相当于时间开销从线性量级变成常数量级。于是我给cupy的内存调度模块写了一些压力测试，结果都完美pass。“记录所有的内存分配、释放然后重放”也是一个主意，但接下来的进展让我打消了这些想法。

_get_chunk模块很快就证明了自身的清白，在打印出的日志中，a_index不再是单调上升的，而是会在中间出现一个峰：

这意味着基于有序数组的lower_bound函数将不能保证在其返回的迭代器之后只有大于size的元素，找到的chunk自然就有可能小于size的要求，引起AssertionError。

尽管a_index不再有序，其它要求arena、a_flag与a_index符合的不变量，如长度相等、arena中的chunk的大小与a_index中对应等都得到满足。所以问题应该出在操作a_index的函数里而不在_get_chunk中。

问题虽然变得复杂化了，但取得了确定的进展，总的来说是个好消息。而且在_get_chunk中有一个_compact_index函数调用，很像是bug的源头：

• _compact_index显然是一个操作a_index的函数
• 该逻辑只有在i - index >= _index_compaction_threshold或者说a_flag变得足够稀疏时才会执行，这就解释了Higgs-Bugson的存在

我按照这个线索追了一阵，由于最后确实不是_compact_index的原因就不细说了，总之没有什么进展，所以还是按老办法继续debug：

1. 写检查a_index有序的函数
2. 在各个对a_index进行操作的函数返回之前检查a_index是否有序，如果不再有序则打印pool及其他感兴趣的局部变量
3. 运行程序并做别的事情

经过对日志的分析，确定_append_to_free_list函数最可疑。在这个函数返回时，a_index变得无序的日志第一次出现，而进入这个函数时a_index仍然是有序的。因此可以有把握地说：_append_to_free_list中的某些操作导致了a_index变得无序。这个函数讲道理不长，逻辑也不复杂：

• 函数的目的是将新创建的chunk放入arena中合理的位置，同时更新a_index和a_flag维持不变量。
• 唯一的一个分支，是对arena中是否有大小与新创建的chunk大小相同的chunk集合做判断。如果有，则直接将chunk放入该集合即可。如果没有，则在arene中创建一个集合，并在a_index和a_flag中创建相应的条目。

cdef _append_to_free_list(list arena, vector.vector[size_t]* a_index,
                          vector.vector[int8_t]* a_flag, _Chunk chunk):
    # need self._free_lock
    cdef size_t index, bin_index
    cdef set free_list
    bin_index = _bin_index_from_size(chunk.size)
    index = <size_t>(
        algorithm.lower_bound(a_index.begin(), a_index.end(), bin_index)
        - a_index.begin())
    if index < a_index.size() and a_index.at(index) == bin_index:
        free_list = arena[index]
        if free_list is None:
            arena[index] = free_list = set()
    else:
        free_list = set()
        a_index.insert(a_index.begin() + index, bin_index)
        a_flag.insert(a_flag.begin() + index, 0)
        arena.insert(index, free_list)
    free_list.add(chunk)
    dereference(a_flag)[index] = 1

既然确定bug就在这几行里，Cython又是静态类型，肉眼看一看应该就能发现错误了吧。然而我对着这段代码盯了半天，死活找不到可能的错误。而且这段代码如果有逻辑错误的话，之前执行了1000000次都没错，为什么第1000001次就错了呢？

疑云渐起

没办法，接着做日志debug吧：在函数返回之前（函数最后一行dereference(a_flag)[index] = 1之后），若a_index不再有序，除了打印a_index之外，打印更多的debug信息，如bin_index，index等等。然而结果却让我大惑不解：

从图中可以看出，chunk被准确地插入到了index所标志的位置，然而问题是index所标志的位置（90）是不正确的，正确的位置是132。也就是说，下面这段STL函数调用：

index = <size_t>(
    algorithm.lower_bound(a_index.begin(), a_index.end(), bin_index)
    - a_index.begin())

本来应该返回132，实际中却返回了90，导致chunk被插入到了错误的位置，使a_index失去有序性。

至此，我开始有了走入死胡同的感觉。明明把敌人逼到了墙角，却变得看不见摸不着。STL调用出问题的概率小于我现在直接被雷劈死，检查Cython编译生成的cpp文件也没有问题，在STL调用后插入debug代码记录的index值也与函数返回时的index值相同。我在这里无头苍蝇一样乱撞了很久，获得了许多非常难以解释的日志信息。比如说下面这段插入了debug代码，试图记录分支执行轨迹的_append_to_free_list：

cdef _append_to_free_list(list arena, vector.vector[size_t]* a_index,
                          vector.vector[int8_t]* a_flag, _Chunk chunk):
    # need self._free_lock
    cdef size_t index, bin_index
    cdef set free_list
    bin_index = _bin_index_from_size(chunk.size)
    index = <size_t>(
        algorithm.lower_bound(a_index.begin(), a_index.end(), bin_index)
        - a_index.begin())
    #XXXXXX debug XXXXXXX
    cdef int path = 0
    #XXXXXX debug XXXXXXX
    if index < a_index.size() and a_index.at(index) == bin_index:
        #XXXXXX debug XXXXXXX
        path = 1
        #XXXXXX debug XXXXXXX
        free_list = arena[index]
        if free_list is None:
            #XXXXXX debug XXXXXXX
            path = 2
            print(index)
            #XXXXXX debug XXXXXXX
            arena[index] = free_list = set()
    else:
        free_list = set()
        a_index.insert(a_index.begin() + index, bin_index)
        a_flag.insert(a_flag.begin() + index, 0)
        arena.insert(index, free_list)
    free_list.add(chunk)
    dereference(a_flag)[index] = 1
    #XXXXXX debug XXXXXXX
    print("---append log---")
    print(path, index)
    #XXXXXX debug XXXXXXX

每次调用时，正常的输出应该类似于这样（[ ... ]表示省略）：

[ ... ]
---append log---
0, 100
---append log---
1, 80
130
---append log---
2, 130
[ ... ]  # 正常日志

而在出错日志之前，可以见到这样的输出：

[ ... ]
---append log---
0, 100
---append log---
1, 80
---append log---
2, 130
[ ... ]  # 出错日志

即尽管path = 2的分支确定无疑被执行了，与path = 2对应的那一条print信息却找不到了！另一个很诡异的现象是出错之前的path除了2以外有时还会是0。在排除了所有不可能的选项后，我不情愿地接受了一个现实：这些异常行为只能用未经正确同步互斥的并行执行解释：STL调用返回的index是正确的，但是在插入之前别的线程已经对a_index以及arena等数据结构做了修改，导致最后插入的位置不对。cupy曾经遇到过多线程的问题，后来加了可重入锁解决，现在看来这个锁还有缺陷。这个猜想能够解释目前观察到的所有现象，而且也是Gihub上一个类似issue的原因。我之所以不愿意接受，原因很简单，能debug单线程代码的话谁愿意debug并行代码呢？

单线程程序的上下文切换？context switch in single thread?

要验证这个猜想，可以在进入_append_to_free_list时对a_index做一个局部的拷贝，发现异常时打印出来即可。好消息是，结果符合预期：

可见进入函数体时，lower_bound找到了正确的index，而从进入函数体到函数体结束，a_index确实被别的程序修改了，最后导致插入位置错误。现在的问题是，什么程序修改了a_index？我自己写的数值计算部分没有与并行执行有关的内容，查阅cupy的文档和源代码也没有并行执行的部分。而_append_to_free_list中使用Python的threading.active_count()结果始终为1。

不得已拿strace和gdb强行看了一下，发现除了主线程之外，有三个新线程生成：

(gdb) info threads
  Id   Target Id         Frame 
* 1    Thread 0x7f1dc9917700 (LWP 5688) "python" 0x000056269f2ff411 in PyObject_GetAttr () at /tmp/build/80754af9/python_1546130271559/work/Objects/object.c:918
  2    Thread 0x7f1d9fa78700 (LWP 5690) "python" 0x00007f1dc92338c8 in accept4 (fd=9, addr=..., addr_len=0x7f1d9fa77e58, flags=524288) at ../sysdeps/unix/sysv/linux/accept4.c:40
  3    Thread 0x7f1d9f277700 (LWP 5691) "python" 0x00007f1dc922674d in poll () at ../sysdeps/unix/syscall-template.S:84
  4    Thread 0x7f1d9ea76700 (LWP 5692) "python" pthread_cond_timedwait@@GLIBC_2.3.2 () at ../sysdeps/unix/sysv/linux/x86_64/pthread_cond_timedwait.S:225

然而仔细一研究发现这三个线程好像都是用来给CUDA服务的，并不涉及用户层（cupy）的代码。无法，还是老老实实打印日志看，抄了一个查看当前tid的工具函数：

cdef extern from "<sys/syscall.h>" nogil:
    int __NR_gettid
    long syscall(long number, ...)

def gettid():
    return syscall(__NR_gettid)

在每个操作a_index的函数中都加了打印当前tid的代码。结果让我大跌眼镜：所有的日志都显示了同样的tid，所有操作都是同一个线程在执行，即使是那些出错日志之前的修改a_index的操作！当时我的感觉只有一个那就是见了鬼了。单线程程序有上下文切换吗？我不禁思考起了宇宙和人生。

Python原罪

在我决定向别人求助，开始准备材料和措辞时，突然想到：会不会是在执行_append_to_free_list时存在某种递归呢？我想起了在写Python的C/C++扩展时一个原则：当你减少一个对象的引用计数时，牢记此时任何代码都可能被执行。如果_append_to_free_list中存在减少引用计数的代码，然后引起了chunk的回收并引发一系列其他的维护内存池的代码，就有可能产生递归并导致a_index指针指向的数组被修改。如此就产生了单线程上下文切换的假象，而这种假象是通过程序员没有意识到的函数调用营造的。

为此我又细细查看了一遍Cython编译的cpp文件，发现并没有对任何有意义的Python对象减少引用计数的代码。要想拿到实锤，还是得看traceback。对于Python的栈帧来说traceback很容易看，但是Cython的traceback就只能用gdb来看了。于是我用一个全局变量来探测递归，并在发现递归时打印提示信息、进入死循环，接着运行程序，在见到提示信息后gdb切进去，bt一看，真相大白！

(gdb) bt
#0  0x00007f1b3b1fc957 in __pyx_f_4cupy_4cuda_6memory__append_to_free_list (__pyx_v_arena=__pyx_v_arena@entry=0x7f1b36ba3a88, __pyx_v_a_index=__pyx_v_a_index@entry=0x559d6f9417d8, 
    __pyx_v_a_flag=__pyx_v_a_flag@entry=0x559d6f911238, __pyx_v_chunk=__pyx_v_chunk@entry=0x7f1b15dee528) at cupy/cuda/memory.cpp:15413
#1  0x00007f1b3b1fdc0b in __pyx_f_4cupy_4cuda_6memory_22SingleDeviceMemoryPool_free (__pyx_v_self=__pyx_v_self@entry=0x7f1b36c0b2b8, __pyx_v_ptr=__pyx_v_ptr@entry=30141793792, __pyx_v_size=__pyx_v_size@entry=37376, 
    __pyx_skip_dispatch=__pyx_skip_dispatch@entry=0) at cupy/cuda/memory.cpp:19349
#2  0x00007f1b3b1ff6f3 in __pyx_f_4cupy_4cuda_6memory_12PooledMemory_free (__pyx_v_self=__pyx_v_self@entry=0x7f1b13b64880, __pyx_skip_dispatch=__pyx_skip_dispatch@entry=0) at cupy/cuda/memory.cpp:12025
#3  0x00007f1b3b20100a in __pyx_pf_4cupy_4cuda_6memory_12PooledMemory_4__dealloc__ (__pyx_v_self=0x7f1b13b64880) at cupy/cuda/memory.cpp:12482
#4  __pyx_pw_4cupy_4cuda_6memory_12PooledMemory_5__dealloc__ (__pyx_v_self=0x7f1b13b64880) at cupy/cuda/memory.cpp:12435
#5  __pyx_tp_dealloc_4cupy_4cuda_6memory_PooledMemory (o=0x7f1b13b64880) at cupy/cuda/memory.cpp:31215
#6  0x00007f1b3b1ccaf7 in __pyx_tp_dealloc_4cupy_4cuda_6memory_MemoryPointer (o=0x7f1b300bd2d0) at cupy/cuda/memory.cpp:30252
#7  0x00007f1b58d561b7 in __pyx_tp_dealloc_4cupy_4core_4core_ndarray (o=0x7f1b13baf0d8) at cupy/core/core.cpp:43849
#8  0x0000559d6e2cdcaa in dict_dealloc (mp=0x7f1b13d99ca8) at /tmp/build/80754af9/python_1546130271559/work/Objects/dictobject.c:2017
#9  subtype_clear (self=<optimized out>) at /tmp/build/80754af9/python_1546130271559/work/Objects/typeobject.c:1067
#10 delete_garbage (old=<optimized out>, collectable=<optimized out>) at /tmp/build/80754af9/python_1546130271559/work/Modules/gcmodule.c:864
#11 collect () at /tmp/build/80754af9/python_1546130271559/work/Modules/gcmodule.c:1016
#12 0x0000559d6e34237d in collect_with_callback () at /tmp/build/80754af9/python_1546130271559/work/Modules/gcmodule.c:1128
#13 0x0000559d6e342430 in collect_generations () at /tmp/build/80754af9/python_1546130271559/work/Modules/gcmodule.c:1151
#14 0x0000559d6e29f3a4 in _PyObject_GC_Alloc (basicsize=basicsize@entry=139754271587664, use_calloc=0) at /tmp/build/80754af9/python_1546130271559/work/Modules/gcmodule.c:1729
#15 _PyObject_GC_Malloc () at /tmp/build/80754af9/python_1546130271559/work/Modules/gcmodule.c:1739
#16 0x0000559d6e2f42c5 in PyType_GenericAlloc.localalias.299 () at /tmp/build/80754af9/python_1546130271559/work/Objects/typeobject.c:936
#17 0x0000559d6e2bad68 in make_new_set (iterable=0x0, type=0x559d6e45bfe0 <PySet_Type>) at /tmp/build/80754af9/python_1546130271559/work/Objects/setobject.c:1046
#18 PySet_New () at /tmp/build/80754af9/python_1546130271559/work/Objects/setobject.c:2280
#19 0x00007f1b3b1fcc46 in __pyx_f_4cupy_4cuda_6memory__append_to_free_list (__pyx_v_arena=__pyx_v_arena@entry=0x7f1b36ba3a88, __pyx_v_a_index=__pyx_v_a_index@entry=0x559d6f9417d8, 
    __pyx_v_a_flag=__pyx_v_a_flag@entry=0x559d6f911238, __pyx_v_chunk=__pyx_v_chunk@entry=0x7f1b3011a948) at cupy/cuda/memory.cpp:15697
[ ... ]

在_append_to_free_list中有两处创建了新的set，而在Python中，某些对象的创建会调用_PyObject_GC_Malloc函数，可能引起垃圾回收：

static PyObject *
_PyObject_GC_Alloc(int use_calloc, size_t basicsize)
{           
    PyObject *op;
    PyGC_Head *g;
    size_t size;
    if (basicsize > PY_SSIZE_T_MAX - sizeof(PyGC_Head))
        return PyErr_NoMemory();
    size = sizeof(PyGC_Head) + basicsize;
    if (use_calloc)
        g = (PyGC_Head *)PyObject_Calloc(1, size);
    else
        g = (PyGC_Head *)PyObject_Malloc(size);
    if (g == NULL)
        return PyErr_NoMemory();
    assert(((uintptr_t)g & 3) == 0);  // g must be aligned 4bytes boundary
    g->_gc_next = 0;
    g->_gc_prev = 0;
    _PyRuntime.gc.generations[0].count++; /* number of allocated GC objects */
    if (_PyRuntime.gc.generations[0].count > _PyRuntime.gc.generations[0].threshold &&
        _PyRuntime.gc.enabled &&
        _PyRuntime.gc.generations[0].threshold &&
        !_PyRuntime.gc.collecting &&
        !PyErr_Occurred()) {
        _PyRuntime.gc.collecting = 1;
        collect_generations();
        _PyRuntime.gc.collecting = 0;
    }
    op = FROM_GC(g);
    return op;
}

该函数中，首先分配了对象所需的内存，紧接着就视情况进行垃圾回收。这一回收不得了，调用了Memory类的析构函数:

def __dealloc__(self):
    if self.ptr:
        runtime.free(self.ptr)

这个析构函数会修改当前的内存池，自然导致了a_index的变化。等到垃圾回收完毕，set被创建，洞中才一日，世上已千年，a_index早就不是那个当年那个a_index了。

我被这个bug困住一个星期之久，根本原因就在于我不清楚Python在创建对象时可能进行GC，想不到一个简单的set()可能意味着执行这么多代码。这个道理说穿了也简单，大家一看就懂，但其实折射出Python一个很严重的问题：学习曲线太长太长了。Python漂亮地隐藏了很多细节，使人可以快速上手构建大型项目，但随着时间推进这些细节会一个一个蹦出来困扰用户，达到精通非常困难。

解决方案

只需要两行代码：一行在开始进行内存调度时禁用GC，另一行在结束时开启即可。

感想

最重要的一些感想：

• 最大的lesson：使用垃圾收集的语言一定要小心析构函数的随时执行
• traceback对于debug很重要。Python程序异常处理过程自然地带有traceback，debug时也很容易查看。C/C++虽然没有原生traceback，但是gdb等一系列工具太方便太强大了，因此不成问题。而Cython以及其它一些先编译为C/C++再编译为二进制的语言存在没有traceback而gdb又不好用的问题，有点坑爹。
• 专家的价值不可估量。我相信对于一个专家来说，看一看_append_to_free_list的代码然后发现问题所在是可能的，工作效率保守估计比我高50倍。很可惜看来这样的专家比较少，至少cupy的几个核心贡献者没有达到这样的水平。

其它一些不很重要的感想：

• debug一个Higgs-Bugson太困难了，没有趁手的工具，盲人摸象，很容易跑偏。
• Python呀好是好，坑起人来也是真狠。我日常被Python坑的实在太多，近一阵在酝酿一个《Python的N宗罪》的文章，N未定。等再积累积累素材再写也未可知。