maybe in an endless loop又出现了 #1737

ericzhanchina · 2023-04-10T05:27:20Z

ericzhanchina
Apr 10, 2023

之前就开贴讨论过这种情况，原来的帖子，那时候以为是日志的问题，所以把原来自己的lua日志服务替换成skynet.error的日志输出了，昨天又发生了这种maybe in an endless loop 的情况。

情况描述是一旦出现这个情况，服务器会卡死大概10几分钟，随后恢复。我看后台的日志输出如下：

09/04/23 21:45:42.29 [:0000000e] DEBUG [     gated]: dGVzdF93eF9valBSOXdlbmp5TXRldENqRG9TVFlaQzMxSXo0@Z2FtZQ==#MjI=>>5001
09/04/23 21:45:42.29 [:00000072] INFO  [  msgagent]: >>[5001][SyncRolePos] userid = 1117461982866444288
09/04/23 21:45:42.29 [:00000072] INFO  [  msgagent]: client req = {
	["x"] = 3899,
	["y"] = 1474,
	["userid"] = 1117461982866444288,
	["mapId"] = 1009,
	["cost"] = 0,
}
09/04/23 21:45:42.29 [:00000072] DEBUG [  msgagent]: father is 1009,userdata.user[tok_game.t_user.mapid] is 1009
09/04/23 21:45:42.29 [:0000001b] DEBUG [   dbredis]: redis parameter is {
	--这里是输出的参数，我省略了，是一个pipeline
}
09/04/23 22:01:57.94 [:0000000e] DEBUG [     gated]: dGVzdF9xcV83NTExQzgxRkIwQjBERjRGMTI3NDJBOEVERjlBNzIwMQ==@Z2FtZQ==#NjQ=>>5001
09/04/23 22:01:57.94 [:00000000] A message from [ :0000001e ] to [ :0000001b ] maybe in an endless loop (version = 301267)
09/04/23 22:01:57.94 [:00000000] A message from [ :00000000 ] to [ :0000000e ] maybe in an endless loop (version = 306427)
09/04/23 22:01:57.97 [:00000000] A message from [ :0000001e ] to [ :0000001b ] maybe in an endless loop (version = 301267)
09/04/23 22:01:57.97 [:00000000] A message from [ :00000000 ] to [ :0000000e ] maybe in an endless loop (version = 306427)
09/04/23 22:01:57.97 [:00000000] A message from [ :0000001e ] to [ :0000001b ] maybe in an endless loop (version = 301267)
09/04/23 22:01:58.22 [:0000001b] INFO  [   dbredis]: call pipeline of .mainredis.slave[3] from 114 cost 975652 ms
09/04/23 22:01:58.22 [:0000000e] DEBUG [     gated]: dGVzdF9xcV9BQzBBQUMwNEJDNEJGNTgzMzgwNDRCQTRGQzlGNEE4Mg==@Z2FtZQ==#ODA=>>7001
09/04/23 22:01:58.22 [:0000000e] DEBUG [     gated]: dGVzdF9xcV83NTExQzgxRkIwQjBERjRGMTI3NDJBOEVERjlBNzIwMQ==@Z2FtZQ==#NjQ=>>5001
09/04/23 22:01:58.22 [:0000017d] INFO  [  msgagent]: >>[7001][pvefight] userid = 1117233598890643456

从日志看SyncRolePos这个协议卡死了，我的玩家数据存储在内存，变更的部分我会先写入到redis里面，然后定期写回MySQL里面。21:45的这个请求，到了redis服务，也是可以正常执行的，但是看redis打印的执行时间是900多秒。

dbredis是一个主服务，四个从服务处理redis的读写

    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
    )

从代码看21:45输出了redis parameter is，然后就卡死了，知道22点才出来log.info的内容，也就是执行时间，这900秒貌似只执行了一个util.millisecond()方法，这个是一个C函数获得系统的毫秒时间。不应该是这个函数出问题吧。

困扰我很久了，有点儿头疼，请求帮助。
0000000e 是gate，
0000001b，是redis的主服务
0000001e，是redis的从服务，负责读写的。

cloudwu · 2023-04-10T08:00:02Z

cloudwu
Apr 10, 2023
Maintainer

你的消息是从 1e 到 1b 卡住的，如果 1e 指的是 skynet.call(slave[index], "lua", cmd, ...) 这里调用的服务，那么这意味着是 1e 回应的那个消息处理的时间过长。

因为你的 log 显示 cost 975652 ms 是包含了 call 以及 log.debug 以及 util.millisecond 的时间，而两条 log.debug 和 log.info 的时间戳是 22:01:58.22 - 21:45:42.29 ，这就意味着 log 服务收到这两条 log 的时间差为 975.9s 。这和 log 中写的 975652 ms 是一致的。

这倒不是说时间花在 call 对象的处理时间上，因为前面还发生了 5 条 maybe in an endless loop 信息，所以很可能是 call 的回应消息已经放到了 1b 的消息队列，但是 1b 服务由于别的原因一直没有处理这条消息。监控线程是每 5 秒检测一次的，900 秒应该检测了 100 次以上。这个消息数量明显偏少。所以卡住的不仅是工作线程，连监测线程恐怕也卡住了。

除了应该查 1b 服务内是否有别的因素占据 cpu 外。还可以查看是否 skynet 的工作线程数目超过了机器能提供的物理线程数量。

13 replies

cloudwu Apr 10, 2023
Maintainer

如果你想确定是不是特定服务抢占了所有的 cpu 时间，可以考虑在 https://github.com/cloudwu/skynet/blob/master/skynet-src/skynet_server.c#L284 增加和 https://github.com/cloudwu/skynet/blob/master/skynet-src/skynet_server.c#L268-L270 类似的 log 。

然后通过 debug console 单独打开对应服务的 log ，记录每条消息的开始时间和结束时间（目前没有记录结束时间）。不过目前记录了 ctx->cpu_cost ，显然你给出的数据里并没有超过 900s 的 cpu_cost 。

ericzhanchina Apr 10, 2023
Author

今天早上发现问题就在debug console里面用stat查看了，没有超过900s的，有没有可能是发生在出问题的那个协议的msgagent里面，那个msgagent如果出了死循环，应该就会大量占用cpu，但是玩家退出后msgagent也就销毁了，我们也看不到了。但是从日志来看，是进入到0000001b这个服务才出的问题，好像又跟msgagent没有关系。

ericzhanchina Apr 12, 2023
Author

如果你想确定是不是特定服务抢占了所有的 cpu 时间，可以考虑在 https://github.com/cloudwu/skynet/blob/master/skynet-src/skynet_server.c#L284 增加和 https://github.com/cloudwu/skynet/blob/master/skynet-src/skynet_server.c#L268-L270 类似的 log 。

然后通过 debug console 单独打开对应服务的 log ，记录每条消息的开始时间和结束时间（目前没有记录结束时间）。不过目前记录了 ctx->cpu_cost ，显然你给出的数据里并没有超过 900s 的 cpu_cost 。

还请云风给看看问题，这次我加了skynet.trace()，这个出现问题的服务器的配置是2CPU 8G内存，上面跑了login服，gate服，擂台服三个skynet进程，每个进程的thread设置为1了，同时这个服务器上还在跑redis，mysql，nginx和两个springboot程序，CPU一直都是20%左右，内存占用2-4G，都很少。

11/04/23 22:02:40.09 [:0000105a] TRACE nil
11/04/23 22:02:40.09 [:0000105a] <TRACE :0000105a-73> 1242794215475928 trace
11/04/23 22:02:40.09 [:0000105a] INFO  [  msgagent]: >>[5800][task_tosection] userid = 1117992244855574528
11/04/23 22:02:40.09 [:0000105a] INFO  [  msgagent]: client req = {
	["selectsection"] = "section2",
	["npcid"] = 20504002,
	["taskid"] = 40101001,
	["storyid"] = 40101001,
}
11/04/23 22:02:40.09 [:0000105a] <TRACE :0000105a-73> 1242794215561120 call : @./game/globalmgr.lua:751 @./service/msgagent.lua:643 @./skynet/lualib/skynet.lua:280
11/04/23 22:02:40.09 [:00000019] <TRACE :0000105a-73> 1242794215593113 request
11/04/23 22:02:40.09 [:00000019] <TRACE :0000105a-73> 1242794215602190 response
11/04/23 22:02:40.09 [:00000019] <TRACE :0000105a-73> 1242794215603765 end
11/04/23 22:02:40.09 [:0000105a] <TRACE :0000105a-73> 1242794215612871 resume
11/04/23 22:02:40.09 [:0000105a] INFO  [  msgagent]: commands = {
	[1] = {
		["talking"] = "",
		["parameter"] = {
			[1] = "20504002",
		},
		["command"] = "npc_kill",
	},
}
11/04/23 22:02:40.09 [:0000105a] DEBUG [  msgagent]: cmd is npc_kill
11/04/23 22:02:40.09 [:0000105a] DEBUG [  msgagent]: npc_kill(20504002) is called 
11/04/23 22:02:40.09 [:0000105a] INFO  [  msgagent]: results = {
	["update"] = {
		["monsters"] = {
			[1] = {
				["t"] = 1681221760,
				["d"] = 1,
				["id"] = 20504002,
			},
		},
	},
	["delete"] = {
	},
	["code"] = 0,
	["insert"] = {
	},
	["attach"] = {
		["nextsection"] = "section3",
	},
}
11/04/23 22:02:40.09 [:0000105a] <TRACE :0000105a-73> 1242794216005716 call : @./game/monitor.lua:210 @./game/globalmgr.lua:833 @./service/msgagent.lua:643
11/04/23 22:02:40.09 [:0000001b] <TRACE :0000105a-73> 1242794216053114 request
11/04/23 22:02:40.09 [:0000001b] <TRACE :0000105a-73> 1242794216084432 call : @./service/dbredis.lua:68 @./skynet/lualib/skynet.lua:280
11/04/23 22:02:40.09 [:0000001e] <TRACE :0000105a-73> 1242794216124707 request
11/04/23 22:02:40.09 [:0000001e] <TRACE :0000105a-73> 1242794216210675 sleep : @./skynet/lualib/skynet.lua:416 @./skynet/lualib/skynet/socketchannel.lua:458 @./service/dbredis.lua:475
11/04/23 22:02:40.09 [:0000001e] <TRACE :0000105a-73> 1242794216347342 resume
11/04/23 22:18:27.13 [:0000001e] <TRACE :0000105a-73> 1242794216354601 response
11/04/23 22:18:27.13 [:0000001e] <TRACE :0000105a-73> 1242794216356319 end
11/04/23 22:18:27.14 [:0000001b] <TRACE :0000105a-73> 1242794216367333 resume
11/04/23 22:18:27.14 [:0000001b] DEBUG [   dbredis]: redis parameter is {
	这里是参数，我省略了
}
11/04/23 22:18:27.14 [:00000000] A message from [ :0000001e ] to [ :0000001b ] maybe in an endless loop (version = 68899575)
11/04/23 22:18:27.15 [:00000000] A message from [ :0000001e ] to [ :0000001b ] maybe in an endless loop (version = 68899575)
11/04/23 22:18:27.15 [:00000000] A message from [ :0000001e ] to [ :0000001b ] maybe in an endless loop (version = 68899575)
11/04/23 22:18:27.15 [:00000000] A message from [ :0000001e ] to [ :0000001b ] maybe in an endless loop (version = 68899575)
11/04/23 22:18:27.15 [:00000000] A message from [ :0000001e ] to [ :0000001b ] maybe in an endless loop (version = 68899575)
11/04/23 22:18:27.15 [:00000000] A message from [ :0000001e ] to [ :0000001b ] maybe in an endless loop (version = 68899575)
11/04/23 22:18:27.15 [:00000000] A message from [ :0000001e ] to [ :0000001b ] maybe in an endless loop (version = 68899575)
11/04/23 22:18:27.15 [:00000000] A message from [ :0000001e ] to [ :0000001b ] maybe in an endless loop (version = 68899575)
这里有一共189个endless loop的输出
11/04/23 22:18:27.26 [:0000001b] INFO  [   dbredis]: [362] call pipeline of .mainredis.slave[3] from 4186 cost 947039 ms
11/04/23 22:18:27.26 [:0000001b] <TRACE :0000105a-73> 1243741255971488 response
11/04/23 22:18:27.26 [:0000001b] <TRACE :0000105a-73> 1243741255979665 end
11/04/23 22:18:27.26 [:0000000e] DEBUG [     gated]: dGVzdF9xcV84RDgwRERFMEVBRUMzMzVFMTQ2QjYwQzdEQTM3NDk5Qg==@Z2FtZQ==#MjIxNA==>>5001
11/04/23 22:18:27.26 [:0000000e] DEBUG [     gated]: dGVzdF9xcV9BNTE3RTlCQ0VBMTU5QkUxMkNFRjIyODQ0QUJCMDkyRg==@Z2FtZQ==#MjE0OA==>>6
11/04/23 22:18:27.26 [:0000000e] DEBUG [     gated]: dGVzdF9xcV9CMTRFODY5MUI1MUI0NEFGQkU1OTUxNzAyNDk4NjhEQg==@Z2FtZQ==#MjI0Mg==>>5001
11/04/23 22:18:27.27 [:0000000e] DEBUG [     gated]: dGVzdF9xcV9FMTdGOUVFRUYyNERGODc0RkNFQzUzNzg4NEFEMUI2Rg==@Z2FtZQ==#MjIzNQ==>>5001

从trace可以看出，执行完log.debug，再到log.info，就被卡住了，下面是dbredis的代码，这个是一个服务，0000001b会转发redis的请求给他的slave服务0000001e，

    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 h1 = skynet.hpc()
                        local ret = skynet.call(slave[index], "lua", cmd, ...)
                        local t = { ... }
                        log.debug("redis parameter is %s",util.dump(t))
                        -- local t2 = util.millisecond()
                        local h2 = skynet.hpc()
                        log.info("[%d] call %s of %s.slave[%d] from %d cost %d ms",session, cmd, name, index, source, math.floor((h2-h1)/1000000))
                        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
    )

cloudwu Apr 12, 2023
Maintainer

我认为硬要在同一个机器上运行多个 skynet 进程，不排除掉相关因素，非要去分析原因是在浪费时间。

而且把三个 skynet 进程内的服务放在同一个 skynet 进程内运行应该也只是举手之劳的工作。这差不多等价于：本来你可以在一个虚拟机内运行三个进程的，但偏要在同一台机器上开三个虚拟机，每个运行一个进程。

ericzhanchina Apr 12, 2023
Author

收到，那我分开部署一下再看看有没有问题。

其实我主要是想不明白为啥从log.debug到log.info，中间只是执行了一个local h2 = skynet.hpc()，为啥时间就差了十几分钟。

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

maybe in an endless loop又出现了 #1737

{{title}}

Replies: 1 comment 13 replies

{{title}}

{{title}}

{{title}}

{{title}}

{{title}}

{{editor}}'s edit

{{editor}}'s edit

{{title}}

Select a reply

maybe in an endless loop又出现了 #1737

ericzhanchina Apr 10, 2023

Replies: 1 comment · 13 replies

cloudwu Apr 10, 2023 Maintainer

cloudwu Apr 10, 2023 Maintainer

ericzhanchina Apr 10, 2023 Author

ericzhanchina Apr 12, 2023 Author

cloudwu Apr 12, 2023 Maintainer

ericzhanchina Apr 12, 2023 Author

ericzhanchina
Apr 10, 2023

Replies: 1 comment 13 replies

cloudwu
Apr 10, 2023
Maintainer

cloudwu Apr 10, 2023
Maintainer

ericzhanchina Apr 10, 2023
Author

ericzhanchina Apr 12, 2023
Author

cloudwu Apr 12, 2023
Maintainer

ericzhanchina Apr 12, 2023
Author