endless loop的问题请教 #1742

ericzhanchina · 2023-04-17T03:11:15Z

ericzhanchina
Apr 17, 2023

服务器四台，login的2cpu 8G，安装了nginx,redis,mysql,还跑两个springboot程序，skynet的login服务主要跑这个服务器上；game服两个，每个都是1CPU 2G，分别部署了两个game服，主要处理玩家的协议，一个arena服，主要处理擂台相关的协议，game转发给arena，也是1CPU 2G。

测试阶段玩家在线只有100左右。
昨天大概21:54 到 10:10左右，两个Game服都卡住了，玩家无法登录，无法操作，10:10之后恢复正常，没有做任何操作自己恢复了。看日志两个服务都是在同一个时间点卡住的，难道跟redis有关系吗，下面是日志，请大佬帮忙给分析一下。

dbredis是一个master-slave的服务器，1b会转发给四个slave，四个slave每个与redis建立连接，处理redis相关的请求。

redis的日志，我看了一些，感觉出问题的时候，redis就没有什么请求了。

245414:C 16 Apr 2023 21:49:14.463 * DB saved on disk
245414:C 16 Apr 2023 21:49:14.465 * Fork CoW for RDB: current 1 MB, peak 1 MB, average 1 MB
879:M 16 Apr 2023 21:49:14.507 * Background saving terminated with success
879:M 16 Apr 2023 21:52:44.344 * 10000 changes in 60 seconds. Saving...
879:M 16 Apr 2023 21:52:44.346 * Background saving started by pid 245436
245436:C 16 Apr 2023 21:52:44.513 * DB saved on disk
245436:C 16 Apr 2023 21:52:44.514 * Fork CoW for RDB: current 1 MB, peak 1 MB, average 1 MB
879:M 16 Apr 2023 21:52:44.547 * Background saving terminated with success
879:M 16 Apr 2023 21:57:45.052 * 100 changes in 300 seconds. Saving...
879:M 16 Apr 2023 21:57:45.053 * Background saving started by pid 245464
245464:C 16 Apr 2023 21:57:45.230 * DB saved on disk
245464:C 16 Apr 2023 21:57:45.231 * Fork CoW for RDB: current 1 MB, peak 1 MB, average 1 MB
879:M 16 Apr 2023 21:57:45.254 * Background saving terminated with success
879:M 16 Apr 2023 22:02:46.033 * 100 changes in 300 seconds. Saving...
879:M 16 Apr 2023 22:02:46.034 * Background saving started by pid 245499
245499:C 16 Apr 2023 22:02:46.207 * DB saved on disk
245499:C 16 Apr 2023 22:02:46.209 * Fork CoW for RDB: current 1 MB, peak 1 MB, average 1 MB
879:M 16 Apr 2023 22:02:46.234 * Background saving terminated with success
879:M 16 Apr 2023 22:10:00.182 * 100 changes in 300 seconds. Saving...
879:M 16 Apr 2023 22:10:00.183 * Background saving started by pid 245547
245547:C 16 Apr 2023 22:10:00.369 * DB saved on disk
245547:C 16 Apr 2023 22:10:00.370 * Fork CoW for RDB: current 1 MB, peak 1 MB, average 1 MB
879:M 16 Apr 2023 22:10:00.385 * Background saving terminated with success
879:M 16 Apr 2023 22:15:01.043 * 100 changes in 300 seconds. Saving...
879:M 16 Apr 2023 22:15:01.044 * Background saving started by pid 245586
245586:C 16 Apr 2023 22:15:01.221 * DB saved on disk
245586:C 16 Apr 2023 22:15:01.222 * Fork CoW for RDB: current 1 MB, peak 1 MB, average 1 MB
879:M 16 Apr 2023 22:15:01.245 * Background saving terminated with success
879:M 16 Apr 2023 22:19:47.407 * 10000 changes in 60 seconds. Saving...
879:M 16 Apr 2023 22:19:47.408 * Background saving started by pid 245619
245619:C 16 Apr 2023 22:19:47.567 * DB saved on disk
245619:C 16 Apr 2023 22:19:47.568 * Fork CoW for RDB: current 1 MB, peak 1 MB, average 1 MB
879:M 16 Apr 2023 22:19:47.609 * Background saving terminated with success
879:M 16 Apr 2023 22:24:14.614 * 10000 changes in 60 seconds. Saving...

game1的卡住的日志，我分析日志是不是game的1d这个redis的进程卡住了，一直没有能回应给1b

16/04/23 21:54:07.23 [:000009d5] TRACE nil
16/04/23 21:54:07.23 [:000009d5] <TRACE :000009d5-1225> 9765504271425188 trace
16/04/23 21:54:07.23 [:000009d5] INFO  [  msgagent]: >>[5001][SyncRolePos] userid = 1117188201673527296
16/04/23 21:54:07.23 [:000009d5] INFO  [  msgagent]: client req = {
	["mapId"] = 2010,
	["x"] = -601,
	["cost"] = 0,
	["y"] = 1484,
	["userid"] = 1117188201673527296,
}
16/04/23 21:54:07.23 [:000009d5] DEBUG [  msgagent]: father is 2010,userdata.user[tok_game.t_user.mapid] is 2010
16/04/23 21:54:07.23 [:000009d5] <TRACE :000009d5-1225> 9765504271746310 call : @./game/monitor.lua:210 @./game/globalmgr.lua:511 @./service/msgagent.lua:656
16/04/23 21:54:07.23 [:0000001b] <TRACE :000009d5-1225> 9765504271801934 request
16/04/23 21:54:07.23 [:0000001b] <TRACE :000009d5-1225> 9765504271820626 call : @./service/dbredis.lua:68 @./skynet/lualib/skynet.lua:280
16/04/23 21:54:07.23 [:0000001d] <TRACE :000009d5-1225> 9765504271855255 request
16/04/23 21:54:07.23 [:0000001d] <TRACE :000009d5-1225> 9765504271973661 sleep : @./skynet/lualib/skynet.lua:416 @./skynet/lualib/skynet/socketchannel.lua:458 @./service/dbredis.lua:475
16/04/23 21:54:07.23 [:0000001d] <TRACE :000009d5-1225> 9765504272356111 resume
16/04/23 22:10:17.76 [:0000001d] <TRACE :000009d5-1225> 9765504272381439 response
16/04/23 22:10:17.76 [:0000001d] <TRACE :000009d5-1225> 9765504272383686 end
16/04/23 22:10:17.76 [:0000001b] <TRACE :000009d5-1225> 9765504272407043 resume
16/04/23 22:10:17.77 [:0000001b] DEBUG [   dbredis]: redis parameter is {
	[1] = {
		[1] = {
			[1] = "hset",
			[2] = "main:userdata:1117188201673527296",
			[3] = "t_user",
			[4] = "{\"id\":1117188201673527296,\"cooper\":65042,\"experience\":678423,\"lv\":45,\"updatetime\":\"2023-04-16 21:54:07\",\"exp\":26312298}",
		},
下面省略了一些redis的pipeline的参数
16/04/23 22:10:17.77 [:00000000] A message from [ :0000001d ] to [ :0000001b ] maybe in an endless loop (version = 54222369)
16/04/23 22:10:17.77 [:00000000] A message from [ :0000001d ] to [ :0000001b ] maybe in an endless loop (version = 54222369)
16/04/23 22:10:17.77 [:00000000] A message from [ :0000001d ] to [ :0000001b ] maybe in an endless loop (version = 54222369)
16/04/23 22:10:17.77 [:00000000] A message from [ :0000001d ] to [ :0000001b ] maybe in an endless loop (version = 54222369)
16/04/23 22:10:17.77 [:00000000] A message from [ :0000001d ] to [ :0000001b ] maybe in an endless loop (version = 54222369)
16/04/23 22:10:17.77 [:00000000] A message from [ :0000001d ] to [ :0000001b ] maybe in an endless loop (version = 54222369)
16/04/23 22:10:17.77 [:00000000] A message from [ :0000001d ] to [ :0000001b ] maybe in an endless loop (version = 54222369)
16/04/23 22:10:17.77 [:00000000] A message from [ :0000001d ] to [ :0000001b ] maybe in an endless loop (version = 54222369)
16/04/23 22:10:17.77 [:00000000] A message from [ :0000001d ] to [ :0000001b ] maybe in an endless loop (version = 54222369)
16/04/23 22:10:17.77 [:00000000] A message from [ :0000001d ] to [ :0000001b ] maybe in an endless loop (version = 54222369)
16/04/23 22:10:17.77 [:00000000] A message from [ :0000001d ] to [ :0000001b ] maybe in an endless loop (version = 54222369)
16/04/23 22:10:17.77 [:00000000] A message from [ :0000001d ] to [ :0000001b ] maybe in an endless loop (version = 54222369)
16/04/23 22:10:17.77 [:00000000] A message from [ :0000001d ] to [ :0000001b ] maybe in an endless loop (version = 54222369)
16/04/23 22:10:17.77 [:00000000] A message from [ :0000001d ] to [ :0000001b ] maybe in an endless loop (version = 54222369)
这里有190个输出，我省略了。
16/04/23 22:10:17.83 [:0000001b] INFO  [   dbredis]: [3618] call pipeline of .mainredis.slave[2] from 2517 cost 970530 ms
16/04/23 22:10:17.83 [:0000001b] <TRACE :000009d5-1225> 9766474802864061 response
16/04/23 22:10:17.83 [:0000001b] <TRACE :000009d5-1225> 9766474802869951 end

后面从22:10:17之后恢复正常了。

game2卡住的日志

16/04/23 21:54:08.50 [:0000001b] INFO  [   dbredis]: [1556] call pipeline of .mainredis.slave[2] from 2481 cost 3 ms
16/04/23 21:54:08.50 [:0000001b] <TRACE :000009b1-389> 2357097567421531 response
16/04/23 21:54:08.50 [:0000001b] <TRACE :000009b1-389> 2357097567426256 end
16/04/23 21:54:08.50 [:0000000e] DEBUG [     gated]: dGVzdF9xcV8yMzdGNzQ1MzgwMkFBQzIzREJDMUNFNDhFOTA2N0FCNQ==@Z2FtZTI=#MTQwNQ==>>5001
16/04/23 21:54:08.51 [:000009b1] <TRACE :000009b1-389> 2357097567571812 resume
16/04/23 21:54:08.51 [:000009b1] <TRACE :000009b1-389> 2357097567620665 response
16/04/23 21:54:08.51 [:000009b1] INFO  [  msgagent]: <<SUCCESS,[5800][task_tosection] cost = 6 ms size = 90 byte userid = 1118129635062845440
16/04/23 22:10:19.21 [:000009b1] <TRACE :000009b1-389> 2357097567660295 end
16/04/23 22:10:19.21 [:000009c7] TRACE nil
16/04/23 22:10:19.22 [:000009c7] <TRACE :000009c7-255> 2357097567690554 trace
16/04/23 22:10:19.22 [:000009c7] INFO  [  msgagent]: >>[5001][SyncRolePos] userid = 1122898324211503104
16/04/23 22:10:19.23 [:000009c7] INFO  [  msgagent]: client req = {
	["y"] = 2496,
	["x"] = -577,
	["cost"] = 0,
	["mapId"] = 1010,
	["userid"] = 1122898324211503104,
}

16/04/23 22:10:19.26 [:00000000] A message from [ :0000001f ] to [ :0000001b ] maybe in an endless loop (version = 50877499)
16/04/23 22:10:19.26 [:00000000] A message from [ :0000001f ] to [ :0000001b ] maybe in an endless loop (version = 50877499)
16/04/23 22:10:19.26 [:00000000] A message from [ :0000001f ] to [ :0000001b ] maybe in an endless loop (version = 50877499)
16/04/23 22:10:19.26 [:00000000] A message from [ :0000001f ] to [ :0000001b ] maybe in an endless loop (version = 50877499)
16/04/23 22:10:19.26 [:00000000] A message from [ :0000001f ] to [ :0000001b ] maybe in an endless loop (version = 50877499)
16/04/23 22:10:19.26 [:00000000] A message from [ :0000001f ] to [ :0000001b ] maybe in an endless loop (version = 50877499)
16/04/23 22:10:19.26 [:00000000] A message from [ :0000001f ] to [ :0000001b ] maybe in an endless loop (version = 50877499)
16/04/23 22:10:19.26 [:00000000] A message from [ :0000001f ] to [ :0000001b ] maybe in an endless loop (version = 50877499)
16/04/23 22:10:19.26 [:00000000] A message from [ :0000001f ] to [ :0000001b ] maybe in an endless loop (version = 50877499)
16/04/23 22:10:19.27 [:00000000] A message from [ :0000001f ] to [ :0000001b ] maybe in an endless loop (version = 50877499)
16/04/23 22:10:19.27 [:00000000] A message from [ :0000001f ] to [ :0000001b ] maybe in an endless loop (version = 50877499)
16/04/23 22:10:19.27 [:00000000] A message from [ :0000001f ] to [ :0000001b ] maybe in an endless loop (version = 50877499)
省略了一些日志，接着就是190个左右的endless loop日志
16/04/23 22:10:19.37 [:0000001b] INFO  [   dbredis]: [883] call pipeline of .mainredis.slave[4] from 2503 cost 970703 ms
16/04/23 22:10:19.37 [:0000001b] <TRACE :000009c7-256> 2358068274098778 response
16/04/23 22:10:19.37 [:0000001b] <TRACE :000009c7-256> 2358068274110801 end
后面就都恢复正常了。

不知道是不是dbredis的代码写的有问题，我把dbredis的也发出来，lua用了一年，可能水平还比较低，请大佬给把把关。

local function master()
    local slave = {}

    local COMMAND = {}

    function COMMAND.define( ... )
        config.reload_tokdefine()
        log.info("tok_define is reloaded in dbredis master")        
    end

    function COMMAND.init(dbconf)
        for i = 1, #slave do
            local conf = {
                host = dbconf.host,
                port = dbconf.port,
                db = dbconf.db,
                auth = dbconf.auth
            }
            skynet.call(
                slave[i],
                "lua",
                "connect",
                conf
            )
        end
        log.info("the %s service initialize %d salve service successfully",name,#slave)
        skynet.ret(skynet.pack(true))
    end

    local function ping()
        while true do
            local r = math.random(#slave)
            local ok = skynet.call(slave[r], "lua", "ping", "time of key")
            log.debug("call %s of slave[%d] from %d", "ping", r, skynet.self())
            skynet.sleep(100 * 60 * 2)
        end
    end

    skynet.start(
        function()
            for i = 1, balance do
                local s = skynet.newservice(SERVICE_NAME, "slave")
                table.insert(slave, s)
            end

            local index = 0
            skynet.dispatch(
                "lua",
                function(session, source, cmd, ...)
                    if COMMAND[cmd] then
                        COMMAND[cmd](...)
                    else
                        -- msgagent always call the dbredis in the same connection
                        index = source % balance + 1
                        local t1 = util.millisecond()
                        local ret = skynet.call(slave[index], "lua", cmd, ...)
                        local t = { ... }
                        log.debug("redis parameter is %s",util.dump(t))
                        local t2 = util.millisecond()
                        log.info("call %s of %s.slave[%d] from %d cost %d ms", cmd, name, index, source, t2 - t1)
                        skynet.ret(skynet.pack(ret))
                    end
                end
            )
            skynet.register(name)
            log.info("the %s service has been started with %d slaves", name, balance)
            skynet.timeout(1000,ping)
        end
    )
end

if mode == "slave" then
    local db

    local CMD = {}

    local function func(f)
        -- local status, err =
        -- xpcall(
        --     f,
        --     function(err)
        --         log.error(debug.traceback())
        --     end
        -- )
        -- if status then
        --     return err
        -- else
        --     return false
        -- end
        return f()
    end

   

    function CMD.disconnect()
        db:disconnect()
    end

    function CMD.connect(conf)
        db = redis.connect(conf)
        log.info("connect to redis at %s:%d", conf.host, conf.port)
        if db then
            return true
        end
    end

    function CMD.pipeline(cmds)
        return func(
            function()
                return db:pipeline(cmds, {})
            end
        )
    end

  

    skynet.start(
        function()
            skynet.dispatch(
                "lua",
                function(session, source, cmd, ...)
                    local f = assert(CMD[cmd])
                    skynet.ret(skynet.pack(f(...)))
                end
            )
        end
    )
else
    master()
end

cloudwu · 2023-04-17T03:43:37Z

cloudwu
Apr 17, 2023
Maintainer

从你的 log 看，卡住的是 1b 不是 1d ，这行 log 是在发给 1b 的消息超时没能被处理时输出的。这种情况只发生在 1b 在干别的事情，无法结束上一次的消息处理，而新消息进来也无法再处理了。

或者是另外一种相当罕见的情况：工作线程忙于做其它的事情，1b 无法被调度器调度。

16 replies

cloudwu Apr 18, 2023
Maintainer

另外一个比较简单的调试方法是，如果现场发现卡住，立刻 gdb attach 进去看工作线程在干什么。如果 worker 为 1 ，那么卡住的时候应该是没有 log 的，等到 endless loop 的 log 出来应该已经不卡了。

ericzhanchina Apr 20, 2023
Author

云风大佬，在1CPU的服务器上，将工作线程数写成2，目前跑了两天没有再出现endless loop，还需要再观察一段时间。

ericzhanchina May 3, 2023
Author

另外一个比较简单的调试方法是，如果现场发现卡住，立刻 gdb attach 进去看工作线程在干什么。如果 worker 为 1 ，那么卡住的时候应该是没有 log 的，等到 endless loop 的 log 出来应该已经不卡了。

跑了一段时间没出现endless loop，然后今天又出现了，十五分钟左右自动恢复，在一台2cpu 4G内存，独享型得阿里云ECS上面，已经按照云风得指导，部署了一个skynet进程，工作线程开了两个。下面是日志，跟之前的不一样了，现在感觉像是整个skynet进程不再执行了。出问题的时候，我telnet无法连接到debug_console。还请云风帮忙看看，我从哪里进一步处理一下会有效果，另外，26日出了问题之后，到5.3日，又没有出过问题了。

26/04/23 11:45:30.17 [:0000001b] <TRACE :00000059-30> 3184579237095383 response
26/04/23 11:45:30.17 [:0000001b] <TRACE :00000059-30> 3184579237097795 end
26/04/23 11:45:30.17 [:00000059] <TRACE :00000059-30> 3184579237111233 resume
26/04/23 11:45:30.17 [:00000059] <TRACE :00000059-30> 3184579237144223 response
26/04/23 11:45:30.17 [:00000059] INFO  [  msgagent]: <<SUCCESS,[5001][SyncRolePos] cost = 2 ms size = 44 byte userid = 1121191326566715392
26/04/23 11:45:30.17 [:00000059] <TRACE :00000059-30> 3184579237159272 end
26/04/23 11:45:30.36 [:0000000e] DEBUG [     gated]: dGVzdF9xcV8xQ0FFRjg4M0JFNEQ3MUVBRTUyMENFRkUwNzlFOUI0MQ==@Z2FtZTI=#MTI=>>5001
26/04/23 11:45:30.36 [:00000059] TRACE nil
26/04/23 11:45:30.36 [:00000059] <TRACE :00000059-31> 3184579422528264 trace
26/04/23 11:45:30.36 [:00000059] INFO  [  msgagent]: >>[5001][SyncRolePos] userid = 1121191326566715392
26/04/23 11:45:30.36 [:00000059] INFO  [  msgagent]: client req = {
	["userid"] = 1121191326566715392,
	["mapId"] = 1001,
	["x"] = 3008,
	["cost"] = 0,
	["y"] = 561,
}
26/04/23 11:45:30.36 [:00000059] DEBUG [  msgagent]: father is 1001,userdata.user[tok_game.t_user.mapid] is 1001
26/04/23 11:45:30.36 [:00000059] <TRACE :00000059-31> 3184579422721746 call : @./game/monitor.lua:210 @./game/globalmgr.lua:565 @./service/msgagent.lua:657
26/04/23 11:45:30.36 [:0000001b] <TRACE :00000059-31> 3184579422759703 request
26/04/23 11:45:30.36 [:0000001b] DEBUG [   dbredis]: redis parameter = {
	[1] = {
		[1] = {
			[1] = "hset",
			[2] = "main:userdata:1121191326566715392",
			[3] = "t_user",
			[4] = "{\"id\":1121191326566715392,\"cooper\":198,\"experience\":230,\"updatetime\":\"2023-04-26 11:45:30\",\"exp\":783,\"lv\":2}",
		},

这里省略了一些redis的参数输出。接下来就没有日志了，一直到15分钟后出现endless loop，这里省略了部分endless的日志，总共是374条。

26/04/23 12:01:08.55 [:0000000e] DEBUG [     gated]: dGVzdF9xcV8xQ0FFRjg4M0JFNEQ3MUVBRTUyMENFRkUwNzlFOUI0MQ==@Z2FtZTI=#MTI=>>5001
26/04/23 12:01:08.55 [:00000000] A message from [ :00000059 ] to [ :0000001b ] maybe in an endless loop (version = 56757)
26/04/23 12:01:08.55 [:00000000] A message from [ :00000000 ] to [ :0000000e ] maybe in an endless loop (version = 58925)
26/04/23 12:01:08.55 [:00000000] A message from [ :00000059 ] to [ :0000001b ] maybe in an endless loop (version = 56757)
26/04/23 12:01:08.55 [:00000000] A message from [ :00000000 ] to [ :0000000e ] maybe in an endless loop (version = 58925)

26/04/23 12:01:08.57 [:00000000] A message from [ :00000000 ] to [ :0000000e ] maybe in an endless loop (version = 58925)
26/04/23 12:01:08.57 [:0000001b] 3185517615802923 sleep : @./skynet/lualib/skynet.lua:416 @./skynet/lualib/skynet/socketchannel.lua:458 @./service/dbredis.lua:16
26/04/23 12:01:08.57 [:00000059] DEBUG [ msgagent]: monster refresh rate = 0.95,rt = 342.0
26/04/23 12:01:08.57 [:0000005a] DEBUG [ msgagent]: monster refresh rate = 0.9,rt = 324.0
26/04/23 12:01:08.57 [:0000005a] DEBUG [ msgagent]: monster refresh rate = 0.9,rt = 324.0
26/04/23 12:01:08.57 [:0000005a] DEBUG [ msgagent]: monster refresh rate = 0.9,rt = 324.0
26/04/23 12:01:08.57 [:0000000e] DEBUG [ gated]: dGVzdF9xcV8xQ0FFRjg4M0JFNEQ3MUVBRTUyMENFRkUwNzlFOUI0MQ==@Z2FtZTI=#MTI=>>5001
26/04/23 12:01:08.57 [:0000000e] DEBUG [ gated]: dGVzdF9xcV8xQ0FFRjg4M0JFNEQ3MUVBRTUyMENFRkUwNzlFOUI0MQ==@Z2FtZTI=#MTI=>>5001
26/04/23 12:01:08.57 [:00000059] TRACE nil
26/04/23 12:01:08.57 [:00000059] 3185517616812594 trace
26/04/23 12:01:08.57 [:00000059] INFO [ msgagent]: >>[5001][SyncRolePos] userid = 1121191326566715392
26/04/23 12:01:08.57 [:00000059] INFO [ msgagent]: client req = {
["userid"] = 1121191326566715392,
["mapId"] = 1001,
["x"] = 3008,
["cost"] = 0,
["y"] = 692,
}
这里省略了一些日志，主要为了追踪显示TRACE :00000059-31，可以看到TRACE :00000059-31整个日志被skynet挂起过程给打断了，但是从日志输出的时间来看，记录的访问redis的时间都是极短的，说明redis的处理是没有问题的。这个也是跟我之前只有一个worker线程不同的日志，之前一个worker，日志服务就不会记录了，等写出来的时候，会提示redis的处理时间有15分钟的时间。

看日志，好像是后面的一些日志其实都已经是之前已经处理完了的，只不过是skynet恢复之后，陆续写到了文件系统上，所以时间都是12：01这个时间段的。

26/04/23 12:01:08.57 [:0000001b] <TRACE :00000059-49> 3185517625786666 sleep : @./skynet/lualib/skynet.lua:416 @./skynet/lualib/skynet/socketchannel.lua:458 @./service/dbredis.lua:16
26/04/23 12:01:08.57 [:0000000e] DEBUG [     gated]: dGVzdF9xcV8xQ0FFRjg4M0JFNEQ3MUVBRTUyMENFRkUwNzlFOUI0MQ==@Z2FtZTI=#MTI=>>6
26/04/23 12:01:08.57 [:0000001b] <TRACE :00000059-31> 3185517625853974 resume
26/04/23 12:01:08.57 [:0000001b] INFO  [   dbredis]: call [pipeline] of .mainredis from 89 cost 10 ms
26/04/23 12:01:08.57 [:0000001b] <TRACE :00000059-31> 3185517625863692 response
26/04/23 12:01:08.57 [:0000001b] <TRACE :00000059-31> 3185517625870809 end
26/04/23 12:01:08.57 [:0000001b] <TRACE :00000059-32> 3185517625872584 resume
26/04/23 12:01:08.57 [:0000001b] INFO  [   dbredis]: call [pipeline] of .mainredis from 89 cost 8 ms
26/04/23 12:01:08.57 [:0000001b] <TRACE :00000059-32> 3185517625879530 response
26/04/23 12:01:08.57 [:0000001b] <TRACE :00000059-32> 3185517625880671 end
26/04/23 12:01:08.57 [:0000001b] <TRACE :00000059-33> 3185517625961902 resume
26/04/23 12:01:08.57 [:0000001b] INFO  [   dbredis]: call [pipeline] of .mainredis from 89 cost 8 ms
26/04/23 12:01:08.57 [:0000001b] <TRACE :00000059-33> 3185517625970081 response
26/04/23 12:01:08.57 [:0000001b] <TRACE :00000059-33> 3185517625971290 end
26/04/23 12:01:08.57 [:0000001b] <TRACE :00000059-34> 3185517625972676 resume
26/04/23 12:01:08.57 [:0000001b] INFO  [   dbredis]: call [pipeline] of .mainredis from 89 cost 8 ms
26/04/23 12:01:08.57 [:0000001b] <TRACE :00000059-34> 3185517625979173 response
26/04/23 12:01:08.57 [:0000001b] <TRACE :00000059-34> 3185517625980245 end
26/04/23 12:01:08.57 [:0000001b] <TRACE :00000059-35> 3185517625981690 resume
26/04/23 12:01:08.57 [:0000001b] INFO  [   dbredis]: call [pipeline] of .mainredis from 89 cost 7 ms
26/04/23 12:01:08.57 [:0000001b] <TRACE :00000059-35> 3185517625987529 response
26/04/23 12:01:08.57 [:0000001b] <TRACE :00000059-35> 3185517625988441 end
26/04/23 12:01:08.57 [:0000001b] <TRACE :00000059-36> 3185517625989688 resume
26/04/23 12:01:08.57 [:0000001b] INFO  [   dbredis]: call [pipeline] of .mainredis from 89 cost 7 ms
26/04/23 12:01:08.57 [:0000001b] <TRACE :00000059-36> 3185517625995715 response
26/04/23 12:01:08.57 [:0000001b] <TRACE :00000059-36> 3185517625996615 end
26/04/23 12:01:08.57 [:0000001b] <TRACE :00000059-37> 3185517625997606 resume
26/04/23 12:01:08.57 [:0000001b] INFO  [   dbredis]: call [pipeline] of .mainredis from 89 cost 6 ms
26/04/23 12:01:08.57 [:0000001b] <TRACE :00000059-37> 3185517626003644 response
26/04/23 12:01:08.57 [:0000001b] <TRACE :00000059-37> 3185517626004522 end
26/04/23 12:01:08.57 [:0000001b] <TRACE :00000059-38> 3185517626005513 resume
26/04/23 12:01:08.57 [:0000001b] INFO  [   dbredis]: call [pipeline] of .mainredis from 89 cost 6 ms
26/04/23 12:01:08.57 [:0000001b] <TRACE :00000059-38> 3185517626011436 response
26/04/23 12:01:08.57 [:0000001b] <TRACE :00000059-38> 3185517626012235 end
26/04/23 12:01:08.57 [:0000001b] <TRACE :00000059-39> 3185517626077157 resume
26/04/23 12:01:08.57 [:0000001b] INFO  [   dbredis]: call [pipeline] of .mainredis from 89 cost 7 ms
26/04/23 12:01:08.57 [:0000001b] <TRACE :00000059-39> 3185517626084679 response
26/04/23 12:01:08.57 [:0000001b] <TRACE :00000059-39> 3185517626085699 end
26/04/23 12:01:08.57 [:0000001b] <TRACE :00000059-40> 3185517626086739 resume
26/04/23 12:01:08.57 [:0000001b] INFO  [   dbredis]: call [pipeline] of .mainredis from 89 cost 6 ms
26/04/23 12:01:08.57 [:0000001b] <TRACE :00000059-40> 3185517626092510 response
26/04/23 12:01:08.57 [:0000001b] <TRACE :00000059-40> 3185517626095497 end
26/04/23 12:01:08.57 [:0000001b] <TRACE :00000059-41> 3185517626145995 resume
26/04/23 12:01:08.57 [:0000001b] INFO  [   dbredis]: call [pipeline] of .mainredis from 89 cost 6 ms
26/04/23 12:01:08.57 [:0000001b] <TRACE :00000059-41> 3185517626153443 response
26/04/23 12:01:08.57 [:0000001b] <TRACE :00000059-41> 3185517626154458 end
26/04/23 12:01:08.57 [:0000000e] INFO  [     gated]: [2]gate try to kick test_qq_DB8C71C36181F6F11BC1729461DA5488
26/04/23 12:01:08.57 [:0000001b] <TRACE :00000059-42> 3185517626190694 resume
26/04/23 12:01:08.57 [:0000001b] INFO  [   dbredis]: call [pipeline] of .mainredis from 89 cost 6 ms
26/04/23 12:01:08.57 [:0000001b] <TRACE :00000059-42> 3185517626197154 response
26/04/23 12:01:08.57 [:0000001b] <TRACE :00000059-42> 3185517626198148 end
26/04/23 12:01:08.57 [:00000047] INFO  [  msgagent]: [3]test_qq_DB8C71C36181F6F11BC1729461DA5488 is going to logout
26/04/23 12:01:08.57 [:0000000e] INFO  [     gated]: [2]gate try to kick test_qq_3BF528AC456A4EE6FF3330617B41EE2D
26/04/23 12:01:08.57 [:0000002e] DEBUG [   dbmysql]: call [exec] of dbmysql from 71 cost 6 ms result = true
26/04/23 12:01:08.57 [:0000005a] INFO  [  msgagent]: [3]test_qq_3BF528AC456A4EE6FF3330617B41EE2D is going to logout
26/04/23 12:01:08.57 [:00000059] <TRACE :00000059-50> 3185517620319420 trace
26/04/23 12:01:08.57 [:00000059] INFO  [  msgagent]: >>[5001][SyncRolePos] userid = 1121191326566715392
26/04/23 12:01:08.57 [:00000059] INFO  [  msgagent]: client req = {
	["userid"] = 1121191326566715392,
	["mapId"] = 1001,
	["x"] = 2492,
	["cost"] = 0,
	["y"] = 1277,
}
26/04/23 12:01:08.57 [:00000059] DEBUG [  msgagent]: father is 1001,userdata.user[tok_game.t_user.mapid] is 1001
26/04/23 12:01:08.57 [:00000059] <TRACE :00000059-50> 3185517626827876 call : @./game/monitor.lua:210 @./game/globalmgr.lua:565 @./service/msgagent.lua:657
26/04/23 12:01:08.57 [:0000000e] INFO  [     gated]: default_default_airssux995 try to login game@gamed with secret = 82286d5c0a89b458
26/04/23 12:01:08.57 [:0000000e] INFO  [     gated]: [ZGVmYXVsdF9kZWZhdWx0X2FpcnNzdXg5OTU=@Z2FtZTI=#MTM=] try to login game server which node = game2
26/04/23 12:01:08.57 [:0000000e] INFO  [     gated]: get a agent from pool
26/04/23 12:01:08.57 [:0000000e] INFO  [     gated]: agent pool size =27
26/04/23 12:01:08.57 [:0000001b] <TRACE :00000047-259> 3185517626883515 request
26/04/23 12:01:08.57 [:0000001b] DEBUG [   dbredis]: redis parameter = {
	
}
26/04/23 12:01:08.57 [:0000001b] <TRACE :00000047-259> 3185517627263220 sleep : @./skynet/lualib/skynet.lua:416 @./skynet/lualib/skynet/socketchannel.lua:458 @./service/dbredis.lua:16
26/04/23 12:01:08.57 [:00000059] TRACE nil
26/04/23 12:01:08.57 [:00000059] <TRACE :00000059-51> 3185517627317789 trace
26/04/23 12:01:08.57 [:00000059] INFO  [  msgagent]: >>[5001][SyncRolePos] userid = 1121191326566715392
26/04/23 12:01:08.57 [:00000059] INFO  [  msgagent]: client req = {
	["userid"] = 1121191326566715392,
	["mapId"] = 1001,
	["x"] = 2868,
	["cost"] = 0,
	["y"] = 1402,
}
26/04/23 12:01:08.57 [:00000059] DEBUG [  msgagent]: father is 1001,userdata.user[tok_game.t_user.mapid] is 1001
26/04/23 12:01:08.57 [:00000059] <TRACE :00000059-51> 3185517627405804 call : @./game/monitor.lua:210 @./game/globalmgr.lua:565 @./service/msgagent.lua:657
26/04/23 12:01:08.57 [:00000058] INFO  [  msgagent]: default_default_airssux995 login to game server
26/04/23 12:01:08.57 [:0000001b] DEBUG [   dbredis]: redis parameter = {
}
26/04/23 12:01:08.57 [:0000001b] <TRACE :00000059-43> 3185517627624903 resume
26/04/23 12:01:08.57 [:0000001b] INFO  [   dbredis]: call [pipeline] of .mainredis from 89 cost 3 ms
26/04/23 12:01:08.57 [:0000001b] <TRACE :00000059-43> 3185517627634878 response
26/04/23 12:01:08.57 [:0000001b] <TRACE :00000059-43> 3185517627636311 end
26/04/23 12:01:08.57 [:00000059] TRACE nil
26/04/23 12:01:08.57 [:00000059] <TRACE :00000059-52> 3185517627667582 trace
26/04/23 12:01:08.57 [:00000059] INFO  [  msgagent]: >>[6][account_heart] userid = 1121191326566715392
26/04/23 12:01:08.57 [:00000059] INFO  [  msgagent]: client req = {
	["index"] = 1,
}
26/04/23 12:01:08.57 [:00000059] DEBUG [  msgagent]: receive heartbreak session= 1
26/04/23 12:01:08.57 [:00000059] <TRACE :00000059-52> 3185517627711493 response
26/04/23 12:01:08.57 [:00000059] INFO  [  msgagent]: <<SUCCESS,[6][account_heart] cost = 0 ms size = 4 byte userid = 1121191326566715392
26/04/23 12:01:08.57 [:00000059] <TRACE :00000059-52> 3185517627748543 end
26/04/23 12:01:08.57 [:0000001b] <TRACE :00000059-44> 3185517627778501 resume
26/04/23 12:01:08.57 [:0000001b] INFO  [   dbredis]: call [pipeline] of .mainredis from 89 cost 3 ms
26/04/23 12:01:08.57 [:0000001b] <TRACE :00000059-44> 3185517627790070 response
26/04/23 12:01:08.57 [:0000001b] <TRACE :00000059-44> 3185517627791395 end
26/04/23 12:01:08.57 [:00000059] TRACE nil
26/04/23 12:01:08.57 [:00000059] <TRACE :00000059-53> 3185517627827234 trace
26/04/23 12:01:08.57 [:00000059] INFO  [  msgagent]: >>[6][account_heart] userid = 1121191326566715392
26/04/23 12:01:08.57 [:00000059] INFO  [  msgagent]: client req = {
	["index"] = 2,
}
26/04/23 12:01:08.57 [:00000059] DEBUG [  msgagent]: receive heartbreak session= 2
26/04/23 12:01:08.57 [:00000059] <TRACE :00000059-53> 3185517627852329 response
26/04/23 12:01:08.57 [:00000059] INFO  [  msgagent]: <<SUCCESS,[6][account_heart] cost = 0 ms size = 4 byte userid = 1121191326566715392
26/04/23 12:01:08.57 [:00000059] <TRACE :00000059-53> 3185517627857656 end
26/04/23 12:01:08.57 [:00000059] TRACE nil
26/04/23 12:01:08.57 [:00000059] <TRACE :00000059-54> 3185517627892097 trace
26/04/23 12:01:08.57 [:00000059] INFO  [  msgagent]: >>[6][account_heart] userid = 1121191326566715392
26/04/23 12:01:08.57 [:00000059] INFO  [  msgagent]: client req = {
	["index"] = 3,
}
26/04/23 12:01:08.57 [:00000059] DEBUG [  msgagent]: receive heartbreak session= 3
26/04/23 12:01:08.57 [:00000059] <TRACE :00000059-54> 3185517627916656 response
26/04/23 12:01:08.57 [:00000059] INFO  [  msgagent]: <<SUCCESS,[6][account_heart] cost = 0 ms size = 4 byte userid = 1121191326566715392
26/04/23 12:01:08.57 [:00000059] <TRACE :00000059-54> 3185517627921904 end
26/04/23 12:01:08.57 [:0000001b] <TRACE :0000005a-89> 3185517627926657 request
26/04/23 12:01:08.57 [:0000001b] DEBUG [   dbredis]: redis parameter = {
	[1] = "main:monster:2023-04-26",
	[2] = 1114616915952799744,
}
26/04/23 12:01:08.57 [:0000001b] <TRACE :0000005a-89> 3185517627958600 sleep : @./skynet/lualib/skynet.lua:416 @./skynet/lualib/skynet/socketchannel.lua:458 @./service/dbredis.lua:16
26/04/23 12:01:08.57 [:0000002e] DEBUG [   dbmysql]: call [exec] of dbmysql from 71 cost 0 ms result = true
26/04/23 12:01:08.57 [:00000059] TRACE nil
26/04/23 12:01:08.57 [:00000059] <TRACE :00000059-55> 3185517628018938 trace
26/04/23 12:01:08.57 [:00000059] INFO  [  msgagent]: >>[6][account_heart] userid = 1121191326566715392
26/04/23 12:01:08.57 [:00000059] INFO  [  msgagent]: client req = {
	["index"] = 4,
}
26/04/23 12:01:08.57 [:00000059] DEBUG [  msgagent]: receive heartbreak session= 4
26/04/23 12:01:08.57 [:00000059] <TRACE :00000059-55> 3185517628040101 response
26/04/23 12:01:08.57 [:00000059] INFO  [  msgagent]: <<SUCCESS,[6][account_heart] cost = 0 ms size = 4 byte userid = 1121191326566715392
26/04/23 12:01:08.57 [:00000059] <TRACE :00000059-55> 3185517628045177 end
26/04/23 12:01:08.57 [:0000001b] <TRACE :00000059-45> 3185517628070516 resume
26/04/23 12:01:08.57 [:0000001b] INFO  [   dbredis]: call [pipeline] of .mainredis from 89 cost 4 ms
26/04/23 12:01:08.57 [:0000001b] <TRACE :00000059-45> 3185517628078473 response
26/04/23 12:01:08.57 [:0000001b] <TRACE :00000059-45> 3185517628079725 end
26/04/23 12:01:08.57 [:00000059] TRACE nil
26/04/23 12:01:08.57 [:00000059] <TRACE :00000059-56> 3185517628117184 trace
26/04/23 12:01:08.57 [:00000059] INFO  [  msgagent]: >>[6][account_heart] userid = 1121191326566715392
26/04/23 12:01:08.57 [:00000059] INFO  [  msgagent]: client req = {
	["index"] = 5,
}
26/04/23 12:01:08.57 [:00000059] DEBUG [  msgagent]: receive heartbreak session= 5
26/04/23 12:01:08.57 [:00000059] <TRACE :00000059-56> 3185517628143123 response
26/04/23 12:01:08.57 [:00000059] INFO  [  msgagent]: <<SUCCESS,[6][account_heart] cost = 0 ms size = 4 byte userid = 1121191326566715392
26/04/23 12:01:08.57 [:00000059] <TRACE :00000059-56> 3185517628148057 end
26/04/23 12:01:08.57 [:0000001b] <TRACE :00000059-46> 3185517628165557 resume
26/04/23 12:01:08.57 [:0000001b] INFO  [   dbredis]: call [pipeline] of .mainredis from 89 cost 3 ms
26/04/23 12:01:08.57 [:00000059] TRACE nil
26/04/23 12:01:08.57 [:00000059] <TRACE :00000059-57> 3185517628213335 trace
26/04/23 12:01:08.57 [:00000059] INFO  [  msgagent]: >>[6][account_heart] userid = 1121191326566715392
26/04/23 12:01:08.57 [:00000059] INFO  [  msgagent]: client req = {
	["index"] = 6,
}
26/04/23 12:01:08.57 [:0000001b] <TRACE :00000059-46> 3185517628172769 response
26/04/23 12:01:08.57 [:0000001b] <TRACE :00000059-46> 3185517628239204 end
26/04/23 12:01:08.57 [:00000059] DEBUG [  msgagent]: receive heartbreak session= 6
26/04/23 12:01:08.57 [:00000059] <TRACE :00000059-57> 3185517628278887 response
26/04/23 12:01:08.57 [:00000059] INFO  [  msgagent]: <<SUCCESS,[6][account_heart] cost = 0 ms size = 4 byte userid = 1121191326566715392
26/04/23 12:01:08.57 [:00000059] <TRACE :00000059-57> 3185517628284666 end
26/04/23 12:01:08.57 [:0000001b] <TRACE :00000059-47> 3185517628311153 resume
26/04/23 12:01:08.57 [:0000001b] INFO  [   dbredis]: call [pipeline] of .mainredis from 89 cost 3 ms
26/04/23 12:01:08.57 [:0000001b] <TRACE :00000059-47> 3185517628408354 response
26/04/23 12:01:08.57 [:0000001b] <TRACE :00000059-47> 3185517628409860 end
26/04/23 12:01:08.57 [:00000059] TRACE nil
26/04/23 12:01:08.57 [:00000059] <TRACE :00000059-58> 3185517628418086 trace
26/04/23 12:01:08.57 [:00000059] INFO  [  msgagent]: >>[6][account_heart] userid = 1121191326566715392
26/04/23 12:01:08.57 [:00000059] INFO  [  msgagent]: client req = {
	["index"] = 7,
}
26/04/23 12:01:08.57 [:00000059] DEBUG [  msgagent]: receive heartbreak session= 7
26/04/23 12:01:08.57 [:00000059] <TRACE :00000059-58> 3185517628442499 response
26/04/23 12:01:08.57 [:00000059] INFO  [  msgagent]: <<SUCCESS,[6][account_heart] cost = 0 ms size = 4 byte userid = 1121191326566715392
26/04/23 12:01:08.57 [:00000059] <TRACE :00000059-58> 3185517628447172 end
26/04/23 12:01:08.57 [:0000001b] <TRACE :00000059-48> 3185517628471953 resume
26/04/23 12:01:08.57 [:0000001b] INFO  [   dbredis]: call [pipeline] of .mainredis from 89 cost 3 ms
26/04/23 12:01:08.57 [:0000001b] <TRACE :00000059-48> 3185517628478863 response
26/04/23 12:01:08.57 [:0000001b] <TRACE :00000059-48> 3185517628480069 end
26/04/23 12:01:08.57 [:00000059] TRACE nil
26/04/23 12:01:08.57 [:00000059] <TRACE :00000059-59> 3185517628487388 trace
26/04/23 12:01:08.57 [:00000059] INFO  [  msgagent]: >>[6][account_heart] userid = 1121191326566715392
26/04/23 12:01:08.57 [:00000059] INFO  [  msgagent]: client req = {
	["index"] = 8,
}
26/04/23 12:01:08.57 [:00000059] DEBUG [  msgagent]: receive heartbreak session= 8
26/04/23 12:01:08.57 [:00000059] <TRACE :00000059-59> 3185517628506456 response
26/04/23 12:01:08.57 [:00000059] INFO  [  msgagent]: <<SUCCESS,[6][account_heart] cost = 0 ms size = 4 byte userid = 1121191326566715392
26/04/23 12:01:08.57 [:00000059] <TRACE :00000059-59> 3185517628511037 end
26/04/23 12:01:08.57 [:0000001b] <TRACE :00000059-49> 3185517628531800 resume
26/04/23 12:01:08.57 [:0000001b] INFO  [   dbredis]: call [pipeline] of .mainredis from 89 cost 3 ms
26/04/23 12:01:08.57 [:00000059] TRACE nil
26/04/23 12:01:08.57 [:00000059] <TRACE :00000059-60> 3185517628649829 trace
26/04/23 12:01:08.57 [:00000059] INFO  [  msgagent]: >>[6][account_heart] userid = 1121191326566715392
26/04/23 12:01:08.57 [:00000059] INFO  [  msgagent]: client req = {
	["index"] = 9,
}
26/04/23 12:01:08.57 [:00000059] DEBUG [  msgagent]: receive heartbreak session= 9
26/04/23 12:01:08.57 [:00000059] <TRACE :00000059-60> 3185517628672755 response
26/04/23 12:01:08.57 [:00000059] INFO  [  msgagent]: <<SUCCESS,[6][account_heart] cost = 0 ms size = 4 byte userid = 1121191326566715392
26/04/23 12:01:08.57 [:00000059] <TRACE :00000059-60> 3185517628677688 end
26/04/23 12:01:08.57 [:0000001b] <TRACE :00000059-49> 3185517628720120 response
26/04/23 12:01:08.57 [:0000001b] <TRACE :00000059-49> 3185517628721728 end
26/04/23 12:01:08.57 [:00000059] TRACE nil
26/04/23 12:01:08.57 [:00000059] <TRACE :00000059-61> 3185517628730463 trace
26/04/23 12:01:08.57 [:00000059] INFO  [  msgagent]: >>[6][account_heart] userid = 1121191326566715392
26/04/23 12:01:08.57 [:00000059] INFO  [  msgagent]: client req = {
	["index"] = 10,
}
26/04/23 12:01:08.57 [:00000059] DEBUG [  msgagent]: receive heartbreak session= 10
26/04/23 12:01:08.57 [:00000059] <TRACE :00000059-61> 3185517628750290 response
26/04/23 12:01:08.57 [:00000059] INFO  [  msgagent]: <<SUCCESS,[6][account_heart] cost = 0 ms size = 4 byte userid = 1121191326566715392
26/04/23 12:01:08.57 [:00000059] <TRACE :00000059-61> 3185517628754859 end
26/04/23 12:01:08.57 [:00000059] <TRACE :00000059-31> 3185517628766713 resume
26/04/23 12:01:08.57 [:00000059] <TRACE :00000059-31> 3185517628795800 response
26/04/23 12:01:08.57 [:00000059] INFO  [  msgagent]: <<SUCCESS,[5001][SyncRolePos] cost = 938206 ms size = 44 byte userid = 1121191326566715392
26/04/23 12:01:08.57 [:00000059] <TRACE :00000059-31> 3185517628802044 end

cloudwu May 10, 2023
Maintainer

我觉得如果完全卡死，你需要 gdb attach 进去看卡在哪里，光靠 log 无法分析。

ericzhanchina May 11, 2023
Author

我觉得如果完全卡死，你需要 gdb attach 进去看卡在哪里，光靠 log 无法分析。

收到，这个问题也是很奇葩，已经10天没有发生了

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

endless loop的问题请教 #1742

{{title}}

Replies: 1 comment 16 replies

{{title}}

{{title}}

{{title}}

{{title}}

{{title}}

{{title}}

Select a reply

endless loop的问题请教 #1742

ericzhanchina Apr 17, 2023

Replies: 1 comment · 16 replies

cloudwu Apr 17, 2023 Maintainer

cloudwu Apr 18, 2023 Maintainer

ericzhanchina Apr 20, 2023 Author

ericzhanchina May 3, 2023 Author

cloudwu May 10, 2023 Maintainer

ericzhanchina May 11, 2023 Author

ericzhanchina
Apr 17, 2023

Replies: 1 comment 16 replies

cloudwu
Apr 17, 2023
Maintainer

cloudwu Apr 18, 2023
Maintainer

ericzhanchina Apr 20, 2023
Author

ericzhanchina May 3, 2023
Author

cloudwu May 10, 2023
Maintainer

ericzhanchina May 11, 2023
Author