rwlock_rlock中死循环问题

[YuuFish]

最近将版本同步更新到目前master版本，测试时偶现进程CPU100%问题，看表现上是在rwlock_rlock中发生了死循环，gdb attach查看信息如下，麻烦帮忙看看什么情况：

• 编译器版本：gcc (GCC) 4.8.5 20150623 (Red Hat 4.8.5-39)
• 系统：CentOS Linux release 7.2.1511
• 编译选项：添加了CFLAGS += -D__STDC_NO_ATOMICS__，其它的和master中一样的默认选项

1. top查看线程cpu使用情况[PID 88073 cpu占用99.7%]

   PID USER      PR  NI    VIRT    RES    SHR S %CPU %MEM     TIME+ COMMAND
 88073 dev       20   0  519584  88272   3824 R 99.7  1.1   4:56.46 skynet
 88070 dev       20   0  519584  88272   3824 S  0.7  1.1   0:01.41 skynet
 88072 dev       20   0  519584  88272   3824 S  0.3  1.1   0:04.40 skynet
 88061 dev       20   0  519584  88272   3824 S  0.0  1.1   0:00.01 skynet
 88069 dev       20   0  519584  88272   3824 S  0.0  1.1   0:00.00 skynet
 88071 dev       20   0  519584  88272   3824 S  0.0  1.1   0:00.03 skynet
 88102 dev       20   0  519584  88272   3824 S  0.0  1.1   0:00.09 rdk:main
 88103 dev       20   0  519584  88272   3824 S  0.0  1.1   0:00.00 rdk:broker-1
 88104 dev       20   0  519584  88272   3824 S  0.0  1.1   0:00.01 rdk:broker-1
 88105 dev       20   0  519584  88272   3824 S  0.0  1.1   0:00.00 skynet
 88106 dev       20   0  519584  88272   3824 S  0.0  1.1   0:00.00 rdk:broker0

2. gdb查看信息

(gdb) info thread
  Id   Target Id         Frame
  11   Thread 0x7f66d13f7700 (LWP 88069) "skynet" 0x00007f66d326585d in nanosleep () from /lib64/libc.so.6
  10   Thread 0x7f66d0bf6700 (LWP 88070) "skynet" 0x00007f66d326585d in nanosleep () from /lib64/libc.so.6
  9    Thread 0x7f66d03f5700 (LWP 88071) "skynet" 0x00007f66d329eeb3 in epoll_wait () from /lib64/libc.so.6
  8    Thread 0x7f66cfbf4700 (LWP 88072) "skynet" 0x00007f66d3e9da35 in pthread_cond_wait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
  7    Thread 0x7f66cf3f3700 (LWP 88073) "skynet" 0x000000000040bd13 in skynet_handle_grab (handle=handle@entry=1) at skynet-src/skynet_handle.c:153
  6    Thread 0x7f66c97fa700 (LWP 88102) "rdk:main" 0x00007f66d3e9dde2 in pthread_cond_timedwait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
  5    Thread 0x7f66c8cf9700 (LWP 88103) "rdk:broker-1" 0x00007f66d3e9dde2 in pthread_cond_timedwait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
  4    Thread 0x7f66c84f8700 (LWP 88104) "rdk:broker-1" 0x00007f66d3293c3d in poll () from /lib64/libc.so.6
  3    Thread 0x7f66c73ff700 (LWP 88105) "skynet" 0x00007f66d3ea075d in read () from /lib64/libpthread.so.0
  2    Thread 0x7f66c69fe700 (LWP 88106) "rdk:broker0" 0x00007f66d3e9dde2 in pthread_cond_timedwait@@GLIBC_2.3.2 () from /lib64/libpthread.so.0
* 1    Thread 0x7f66d42b3f80 (LWP 88061) "skynet" 0x00007f66d3e9b017 in pthread_join () from /lib64/libpthread.so.0
(gdb) thread 7
[Switching to thread 7 (Thread 0x7f66cf3f3700 (LWP 88073))]
#0  0x000000000040bd13 in skynet_handle_grab (handle=handle@entry=1) at skynet-src/skynet_handle.c:153
153     skynet-src/skynet_handle.c: Permission denied.
(gdb) bt
#0  0x000000000040bd13 in skynet_handle_grab (handle=handle@entry=1) at skynet-src/skynet_handle.c:153
#1  0x000000000040d703 in skynet_context_message_dispatch (sm=sm@entry=0x7f66d2c090e0, q=q@entry=0x7f66d2c14200, weight=weight@entry=-1) at skynet-src/skynet_server.c:308
#2  0x000000000040df2d in thread_worker (p=<optimized out>) at skynet-src/skynet_start.c:163
#3  0x00007f66d3e99ea5 in start_thread () from /lib64/libpthread.so.0
#4  0x00007f66d329e8dd in clone () from /lib64/libc.so.6
(gdb) p result
$1 = (struct skynet_context *) 0x0
(gdb) p hash
$2 = <optimized out>
(gdb) p *s
$3 = {lock = {write = 0, read = 0}, harbor = 0, handle_index = 70, slot_size = 128, slot = 0x7f66c59db900, name_cap = 4, name_count = 4, name = 0x7f66ce6310f0}

[cloudwu]

几个问题：

1. 怎样看出是在 rwlock_rlock 死循环的？从 gdb 信息看， lock = { write = 0, read = 0 } 锁处于开状态。如果加了写锁， write 应该是 1 ，如果加了读锁， read 为非 0 。
2. 线程上看，并没有另一个线程处于锁状态。而读锁本身不应该死循环。https://github.com/cloudwu/skynet/blob/master/skynet-src/rwlock.h#L19-L30 这里，只要 write 为 0 ，就不没有可能进入循环。

最近修改原子操作，是在 #1317 。如果怀疑 rwlock 修改后的实现引入了 bug ，那么是否可以尝试单独把 rwlock.h 单个文件回滚到之前的版本 ( https://github.com/cloudwu/skynet/blob/bf8f9b8654fe5764b5249766b9f7611adb6e8dd0/skynet-src/rwlock.h ) 比较一下？

或者，可以定义 USE_PTHREAD_LOCK 改用 pthread 带的读写锁，避开这里的实现。

btw, 这个问题看起来和 #1353 有点类似，是否会是同一个问题？

[YuuFish]

几个问题：

1. 怎样看出是在 rwlock_rlock 死循环的？从 gdb 信息看， lock = { write = 0, read = 0 } 锁处于开状态。如果加了写锁， write 应该是 1 ，如果加了读锁， read 为非 0 。
2. 线程上看，并没有另一个线程处于锁状态。而读锁本身不应该死循环。https://github.com/cloudwu/skynet/blob/master/skynet-src/rwlock.h#L19-L30 这里，只要 write 为 0 ，就不没有可能进入循环。

最近修改原子操作，是在 #1317 。如果怀疑 rwlock 修改后的实现引入了 bug ，那么是否可以尝试单独把 rwlock.h 单个文件回滚到之前的版本 ( https://github.com/cloudwu/skynet/blob/bf8f9b8654fe5764b5249766b9f7611adb6e8dd0/skynet-src/rwlock.h ) 比较一下？

或者，可以定义 USE_PTHREAD_LOCK 改用 pthread 带的读写锁，避开这里的实现。

btw, 这个问题看起来和 #1353 有点类似，是否会是同一个问题？

[YuuFish]

几个问题：

1. 怎样看出是在 rwlock_rlock 死循环的？从 gdb 信息看， lock = { write = 0, read = 0 } 锁处于开状态。如果加了写锁， write 应该是 1 ，如果加了读锁， read 为非 0 。
2. 线程上看，并没有另一个线程处于锁状态。而读锁本身不应该死循环。https://github.com/cloudwu/skynet/blob/master/skynet-src/rwlock.h#L19-L30 这里，只要 write 为 0 ，就不没有可能进入循环。

最近修改原子操作，是在 #1317 。如果怀疑 rwlock 修改后的实现引入了 bug ，那么是否可以尝试单独把 rwlock.h 单个文件回滚到之前的版本 ( https://github.com/cloudwu/skynet/blob/bf8f9b8654fe5764b5249766b9f7611adb6e8dd0/skynet-src/rwlock.h ) 比较一下？
或者，可以定义 USE_PTHREAD_LOCK 改用 pthread 带的读写锁，避开这里的实现。
btw, 这个问题看起来和 #1353 有点类似，是否会是同一个问题？

1，判断是在rwlock_rlock中死循环的原因是gdb看rwlock_rlock调用前后的两个值情况如下，rwlock_rlock调用后的hash的赋值还没有，不知道这样判断是否正确：

-- skynet_handle_grab的实现
struct skynet_context *
skynet_handle_grab(uint32_t handle) {
    struct handle_storage *s = H;
    struct skynet_context * result = NULL;

    rwlock_rlock(&s->lock);

    uint32_t hash = handle & (s->slot_size-1);
    struct skynet_context * ctx = s->slot[hash];
    if (ctx && skynet_context_handle(ctx) == handle) {
        result = ctx;
        skynet_context_grab(result);
    }

    rwlock_runlock(&s->lock);

    return result;
}

-- gdb中查看rwlock_rlock调用的前后的变量的值
(gdb) p result
$1 = (struct skynet_context *) 0x0
(gdb) p hash
$2 = <optimized out>

[cloudwu]

我觉得想判断是否是 rwlock 实现的 bug ，最简单的方法是定义 -DUSE_PTHREAD_LOCK 比较一下。这样方便确定问题。

[YuuFish]

好的，谢谢云大，我先修改为-DUSE_PTHREAD_LOCK再观察下

[iwifigame]

大概率重现步骤：

1. 修改examples/main.lua

	-- skynet.newservice("simpledb")
    for i = 1, 100 do
        skynet.newservice("simple_service")
    end

2. 创建simple_service.lua服务文件，就是为了模拟多线程来注册handle。

local skynet = require "skynet"

skynet.start(function()
    for i = 1, 100 do
        skynet.newservice("simple_service2")
    end
end)

3. 创建simple_service2.lua服务文件。

local skynet = require "skynet"

skynet.start(function()
end)

4. 启动skynet。
   ./skynet ./examples/config

原因应该是 atomic.h中，如果定义了__STDC_NO_ATOMICS__。下面的宏定义不是原子操作的。
#define ATOM_LOAD(ptr) ((ptr))
#define ATOM_STORE(ptr, v) ((ptr) = v)

[iwifigame]

采用这个实现可以解决。但不知道还有没有更好的方法。
#define ATOM_LOAD(ptr) __sync_val_compare_and_swap(ptr, *ptr, *ptr)
#define ATOM_STORE(ptr, v) __sync_bool_compare_and_swap(ptr, *ptr, v)

[YuuFish]

这样是ATOM_INIT也要对应改成ATOM_STORE的宏定义不？

[cloudwu]

1. 改成 cas 做读写并不等价。

2. 直接读写字长的变量 ，cpu 可以保证原子性。

3. 如果是编译器的优化导致没有每次都从内存读取（看生成代码），可以通过给指针加 volatile 解决。

4. 在使用 stdatomic 之前，代码中并没有 load save 宏，都是直接读写，并没有人报告问题。

[cloudwu]

这样是ATOM_INIT也要对应改成ATOM_STORE的宏定义不？

我认为可以尝试把 #define ATOM_INT int改成 #define ATOM_INT volatile int 试试。

[YuuFish]

好的，我将#define ATOM_INT int改成 #define ATOM_INT volatile int试试。之前为了得到更多debug信息，修改过编译选项为-g -O0，修改后观察了7天左右，那期间没出现过这种高CPU的情况，确实是有可能编译器优化导致

[iwifigame]

1. 改成 cas 做读写并不等价。
2. 直接读写字长的变量 ，cpu 可以保证原子性。
3. 如果是编译器的优化导致没有每次都从内存读取（看生成代码），可以通过给指针加 volatile 解决。
4. 在使用 stdatomic 之前，代码中并没有 load save 宏，都是直接读写，并没有人报告问题。

lua-bson.c 有ATOM_STORE(&oid_counter, c);是static ATOM_ULONG oid_counter;会出现问题吧。

[cloudwu]

lua-bson.c 那里不想对初始化做严格的原子处理，因为这里即使同时初始化两次也没有关系。object id 本质上是产生一个随机数，是什么都无所谓（已有的算法也无法严格保证 id 不重复）。

[cloudwu]

@iwifigame 目前 master 版本，我使用了你给的测试案例，无法重现问题。

[iwifigame]

@iwifigame 目前 master 版本，我使用了你给的测试案例，无法重现问题。

新的代码，我测试了，暂时是没有再出现了

[YuuFish]

按照volatile的方案修改之后，目前观察了3天，暂时没出现CPU占用100%问题