关于profile.start()调用报错问题

[253980289]

我这边在函数开始和结束时分别调用了profile.start()和profile.stop()，但偶发性会报以下错误，是否因为该函数调用中涉及到skynet.timer引发了协程切换导致？
profile.lua:60: Thread 0x7d7ca7c499a8 start profile more than once

skynet.dispatch(...
...
gdata.dlog("nnprofile.start", name)
nnprofile.start(name)
if "string" == type(cmd) and gdata.hook_fun[cmd] then
	gdata.hook_fun[cmd](subcmd, ...)
else
	func(session, source, cmd, subcmd, ...)
end
gdata.dlog("nnprofile.stop", name)
nnprofile.stop(name)

[Jian0326]

调用nnprofile.start(name)后没有调用nnprofile.stop(name)又调用了nnprofile.start(name)

[253980289]

调用nnprofile.start(name)后没有调用nnprofile.stop(name)又调用了nnprofile.start(name)

我也是这么想的，但关键是怎么会出现这个情况的。我是在skynet.dispatch里调的start和stop，如果这之间因阻塞导致协和切换，那么在处理其他消息时，又会重复使用前一协程吗？

[Jian0326]

会不会是因为程序报错了。下面代码实际并没有执行

[253980289]

会不会是因为程序报错了。下面代码实际并没有执行

日志显示并没有其它报错，只有这个start报错。

[253980289]

我简单看了skynet的协程池代码，按理这个任务未完成时，这个协程不会被回收用作其他代码执行，所以没明白发生的原因。

[253980289]

我把这个出错的协程日志专门抽取出来了，感觉不正常，就算start和stop之间有阻塞调用，但此任务未完成，这个协程不应该被作干别的事了。

[0][dbg][2024-10-30 18:09:49.95][0x708e7124cb68][0309][ghttpserver1-gcommon-(no_name)f->try_call->xpcall(-1)]	nnprofile.start	new_service_notify[mqlen:2][2024-10-30 18:09:49.95]-log_mqlen:6

[0][dbg][2024-10-30 18:09:49.95][0x708e7124cb68][0314][ghttpserver1-gcommon-(no_name)f->try_call->xpcall(-1)]	nnprofile.stop	new_service_notify[mqlen:0][2024-10-30 18:09:49.95]-log_mqlen:1

[0][flo][2024-10-30 18:09:49.95][0x708e7124cb68][0203][ghttpserver1-gcommon-log_dispatch(203)]	dispatch_end[mqlen:0][2024-10-30 18:09:49.95]-log_mqlen:0

[0][flo][2024-10-30 18:09:49.99][0x708e7124cb68][0201][ghttpserver1-gcommon-log_dispatch(201)]	dispatch_begin:	0	:0000002f	new_service_notify	{
  ["ip_port"]  =  "127.0.0.1:1410",
  ["gate_msg_route"]  =  {
    ["msg_list"]  =  {
      [1]  =  10003,
    },
  },
  ["name"]  =  "gloginserver",
  ["id"]  =  1,
}	nil	nil[mqlen:0][2024-10-30 18:09:49.99]-log_mqlen:17


[0][dbg][2024-10-30 18:09:49.99][0x708e7124cb68][0309][ghttpserver1-gcommon-(no_name)f->try_call->xpcall(-1)]	nnprofile.start	new_service_notify[mqlen:0][2024-10-30 18:09:49.99]-log_mqlen:15

[0][err][2024-10-30 18:09:49.99][0x708e7124cb68][0324][ghttpserver1-gcommon-(no_name)xpcall->start->clock_start->start(-1)]	err:

[0][flo][2024-10-30 18:09:50.42][0x708e7124cb68][0201][ghttpserver1-gcommon-log_dispatch(201)]	dispatch_begin:	0	:0000002f	new_service_notify	{
  ["monitor_user_online_state"]  =  true,
  ["ip_port"]  =  "127.0.0.1:1650",
  ["gate_msg_route"]  =  {
    ["msg_list"]  =  {
      [1]  =  13001,
      [2]  =  13003,
      [3]  =  13005,
    },
    ["uid_range"]  =  {
      ["from"]  =  100001,
      ["range"]  =  10000,
    },
  },
  ["name"]  =  "ghome",
  ["id"]  =  1,
}	nil	nil[mqlen:0][2024-10-30 18:09:50.43]-log_mqlen:11

[0][dbg][2024-10-30 18:09:50.42][0x708e7124cb68][0309][ghttpserver1-gcommon-(no_name)f->try_call->xpcall(-1)]	nnprofile.start	new_service_notify[mqlen:0][2024-10-30 18:09:50.43]-log_mqlen:10

[0][err][2024-10-30 18:09:50.42][0x708e7124cb68][0324][ghttpserver1-gcommon-(no_name)xpcall->start->clock_start->start(-1)]	err:

[0][flo][2024-10-30 18:09:50.51][0x708e7124cb68][0201][ghttpserver1-gcommon-log_dispatch(201)]	dispatch_begin:	0	:0000002f	new_service_notify	{
  ["ip_port"]  =  "127.0.0.1:1211",
  ["name"]  =  "ggateserver",
  ["id"]  =  2,
}	nil	nil[mqlen:0][2024-10-30 18:09:50.51]-log_mqlen:18

[0][dbg][2024-10-30 18:09:50.51][0x708e7124cb68][0309][ghttpserver1-gcommon-(no_name)f->try_call->xpcall(-1)]	nnprofile.start	new_service_notify[mqlen:0][2024-10-30 18:09:50.51]-log_mqlen:17

[0][err][2024-10-30 18:09:50.51][0x708e7124cb68][0324][ghttpserver1-gcommon-(no_name)xpcall->start->clock_start->start(-1)]	err:

[253980289]

或者是不是可以理解为，在skynet.dispatch注册的消息处理函数中，如果有阻塞调用，那么就不能使用profile的start和stop来统计执行时间了？

[253980289]

应该是在阻塞时被不同协程重复调用了start，而没有传入当前协程参数导致

[253980289]

static int
lstart(lua_State *L) {
	if (lua_gettop(L) != 0) {
		lua_settop(L,1);
		luaL_checktype(L, 1, LUA_TTHREAD);
	} else {
		lua_pushthread(L);
	}
	lua_Number start_time = 0;
	if (timing_enable(L, 1, &start_time)) {
		return luaL_error(L, "Thread %p start profile more than once", lua_topointer(L, 1));
	}

[253980289]

skynet wiki(https://github.com/cloudwu/skynet/wiki/Profile)上说：

使用 skynet 内置的 profile 记时而不用系统带的 os.time 是因为 profile 可以剔除阻塞调用的时间，准确统计出当前 coroutine 真正的开销。

那我想问的是，profile和os.clock的区别是什么？

[hanxi]

因为使用os.clock没法减去阻塞调用的时间？

[253980289]

因为使用os.clock没法减去阻塞调用的时间？

我测试好像不是这样。

[changlongH]

注：profile.start() 和 profile.stop() 必须在 skynet 线程中调用（记录当前线程），如果在 skynet Coroutine 中调用的话，请传入指定的 skynet 线程对象，通常可通过 skynet.coroutine.thread() 获得

业务中有什么情况会导致 dispatch不在skynet线程中调用吗？

[changlongH]

或者每次都传入 skynet.coroutine.thread() 看看

[253980289]

注：profile.start() 和 profile.stop() 必须在 skynet 线程中调用（记录当前线程），如果在 skynet Coroutine 中调用的话，请传入指定的 skynet 线程对象，通常可通过 skynet.coroutine.thread() 获得

业务中有什么情况会导致 dispatch不在skynet线程中调用吗？

我的理解是自己通过lua原生协程生成的线程。

[253980289]

我这边测试下来profile.start好像不太好用，虽然传入skynet.coroutine.thread()可以解决不同协程间冲突问题，但在用作客户端压测代码按socket分组而非协程分组时，就没法用了。
而且经初步测试，也没发现os.clock代替方案的劣势。