diff --git a/Makefile b/Makefile index a93f1789a..d87450750 100644 --- a/Makefile +++ b/Makefile @@ -38,7 +38,7 @@ jemalloc : $(JEMALLOC_STATICLIB) # skynet CSERVICE = snlua logger gate master harbor -LUA_CLIB = skynet socketdriver int64 bson mongo md5 netpack cjson clientsocket memory +LUA_CLIB = skynet socketdriver int64 bson mongo md5 netpack cjson clientsocket memory profile SKYNET_SRC = skynet_main.c skynet_handle.c skynet_module.c skynet_mq.c \ skynet_server.c skynet_start.c skynet_timer.c skynet_error.c \ @@ -96,6 +96,9 @@ $(LUA_CLIB_PATH)/clientsocket.so : lualib-src/lua-clientsocket.c | $(LUA_CLIB_PA $(LUA_CLIB_PATH)/memory.so : lualib-src/lua-memory.c | $(LUA_CLIB_PATH) $(CC) $(CFLAGS) $(SHARED) -Iskynet-src $^ -o $@ +$(LUA_CLIB_PATH)/profile.so : lualib-src/lua-profile.c | $(LUA_CLIB_PATH) + $(CC) $(CFLAGS) $(SHARED) $^ -o $@ + clean : rm -f $(SKYNET_BUILD_PATH)/skynet $(CSERVICE_PATH)/*.so $(LUA_CLIB_PATH)/*.so diff --git a/lualib-src/lua-profile.c b/lualib-src/lua-profile.c new file mode 100644 index 000000000..39a13b836 --- /dev/null +++ b/lualib-src/lua-profile.c @@ -0,0 +1,184 @@ +#include +#include + + +#include + +#if defined(__APPLE__) +#include +#include +#endif + +#define NANOSEC 1000000000 + +static double +get_time() { +#if !defined(__APPLE__) + struct timespec ti; + clock_gettime(CLOCK_THREAD_CPUTIME_ID, &ti); + + int sec = ti.tv_sec & 0xffff; + int nsec = ti.tv_nsec; + + return (double)sec + (double)nsec / 1000000000; +#else + struct task_thread_times_info aTaskInfo; + mach_msg_type_number_t aTaskInfoCount = TASK_THREAD_TIMES_INFO_COUNT; + assert(KERN_SUCCESS == task_info(mach_task_self(), TASK_THREAD_TIMES_INFO, (task_info_t )&aTaskInfo, &aTaskInfoCount)); + + int sec = aTaskInfo.user_time.seconds & 0xffff; + int msec = aTaskInfo.user_time.microseconds; + + return (double)sec + (double)msec / 1000000; +#endif +} + +static inline double +diff_time(double start) { + double now = get_time(); + if (now < start) { + return now + 0x10000 - start; + } else { + return now - start; + } +} + +static int +lstart(lua_State *L) { + lua_pushthread(L); + lua_rawget(L, lua_upvalueindex(2)); + if (!lua_isnil(L, -1)) { + return luaL_error(L, "Thread %p start profile more than once", lua_topointer(L, 1)); + } + lua_pushthread(L); + lua_pushnumber(L, 0); + lua_rawset(L, lua_upvalueindex(2)); + + lua_pushthread(L); + lua_pushnumber(L, get_time()); + lua_rawset(L, lua_upvalueindex(1)); + + return 0; +} + +static int +lstop(lua_State *L) { + lua_pushthread(L); + lua_rawget(L, lua_upvalueindex(1)); + luaL_checktype(L, -1, LUA_TNUMBER); + double ti = diff_time(lua_tonumber(L, -1)); + lua_pushthread(L); + lua_rawget(L, lua_upvalueindex(2)); + double total_time = lua_tonumber(L, -1); + + lua_pushthread(L); + lua_pushnil(L); + lua_rawset(L, lua_upvalueindex(1)); + + lua_pushthread(L); + lua_pushnil(L); + lua_rawset(L, lua_upvalueindex(2)); + + lua_pushnumber(L, ti + total_time); + + return 1; +} + +static int +lresume(lua_State *L) { + lua_pushvalue(L,1); + lua_rawget(L, lua_upvalueindex(2)); + if (lua_isnil(L, -1)) { // check total time + lua_pop(L,1); + } else { + lua_pop(L,1); + lua_pushvalue(L,1); + lua_pushnumber(L, get_time()); + lua_rawset(L, lua_upvalueindex(1)); // set start time + } + + lua_CFunction co_resume = lua_tocfunction(L, lua_upvalueindex(3)); + + return co_resume(L); +} + +static int +lyield(lua_State *L) { + lua_pushthread(L); + lua_rawget(L, lua_upvalueindex(2)); // check total time + if (lua_isnil(L, -1)) { + lua_pop(L,1); + } else { + double ti = lua_tonumber(L, -1); + lua_pop(L,1); + + lua_pushthread(L); + lua_rawget(L, lua_upvalueindex(1)); + double starttime = lua_tonumber(L, -1); + lua_pop(L,1); + + ti += diff_time(starttime); + + lua_pushthread(L); + lua_pushnumber(L, ti); + lua_rawset(L, lua_upvalueindex(1)); + } + + lua_CFunction co_yield = lua_tocfunction(L, lua_upvalueindex(3)); + + return co_yield(L); +} + +int +luaopen_profile(lua_State *L) { + luaL_checkversion(L); + luaL_Reg l[] = { + { "start", lstart }, + { "stop", lstop }, + { "resume", lresume }, + { "yield", lyield }, + { NULL, NULL }, + }; + luaL_newlibtable(L,l); + lua_newtable(L); // table thread->start time + lua_newtable(L); // table thread->total time + + lua_newtable(L); // weak table + lua_pushliteral(L, "kv"); + lua_setfield(L, -2, "__mode"); + + lua_pushvalue(L, -1); + lua_setmetatable(L, -3); + lua_setmetatable(L, -3); + + lua_pushnil(L); + luaL_setfuncs(L,l,3); + + int libtable = lua_gettop(L); + + lua_getglobal(L, "coroutine"); + lua_getfield(L, -1, "resume"); + + lua_CFunction co_resume = lua_tocfunction(L, -1); + if (co_resume == NULL) + return luaL_error(L, "Can't get coroutine.resume"); + lua_pop(L,1); + lua_getfield(L, libtable, "resume"); + lua_pushcfunction(L, co_resume); + lua_setupvalue(L, -2, 3); + lua_pop(L,1); + + lua_getfield(L, -1, "yield"); + + lua_CFunction co_yield = lua_tocfunction(L, -1); + if (co_yield == NULL) + return luaL_error(L, "Can't get coroutine.yield"); + lua_pop(L,1); + lua_getfield(L, libtable, "yield"); + lua_pushcfunction(L, co_yield); + lua_setupvalue(L, -2, 3); + + lua_settop(L, libtable); + + return 1; +} diff --git a/lualib/skynet.lua b/lualib/skynet.lua index 6e72f4ad4..3d3135db7 100644 --- a/lualib/skynet.lua +++ b/lualib/skynet.lua @@ -6,6 +6,11 @@ local assert = assert local pairs = pairs local pcall = pcall +local profile = require "profile" + +coroutine.resume = profile.resume +coroutine.yield = profile.yield + local proto = {} local skynet = { -- read skynet.h @@ -476,6 +481,12 @@ end ----- debug +local internal_info_func + +function skynet.info_func(func) + internal_info_func = func +end + local dbgcmd = {} function dbgcmd.MEM() diff --git a/service/snaxd.lua b/service/snaxd.lua index d19c8b420..626a39113 100644 --- a/service/snaxd.lua +++ b/service/snaxd.lua @@ -1,12 +1,24 @@ local skynet = require "skynet" local c = require "skynet.c" local snax_interface = require "snax_interface" +local profile = require "profile" local func = snax_interface(tostring(...), _ENV) local mode local thread_id local message_queue = {} local init = false +local profile_table = {} + +local function update_stat(name, ti) + local t = profile_table[name] + if t == nil then + t = { count = 0, time = 0 } + profile_table[name] = t + end + t.count = t.count + 1 + t.time = t.time + ti +end local function do_func(f, msg) return pcall(f, table.unpack(msg)) @@ -33,7 +45,10 @@ local function message_dispatch() print(string.format("Error on [:%x] to [:%x] %s", msg.source, skynet.self(), tostring(data))) end else + profile.start() local ok, data, size = pcall(dispatch, f, table.unpack(msg)) + local ti = profile.stop() + update_stat(method[3], ti) if ok then -- skynet.PTYPE_RESPONSE == 1 c.send(msg.source, 1, msg.session, data, size) @@ -61,6 +76,24 @@ local function queue( session, source, method, ...) end end +local function return_f(f, ...) + return skynet.ret(skynet.pack(f(...))) +end + +local function timing( method, ... ) + local err, msg + profile.start() + if method[2] == "accept" then + -- no return + err,msg = pcall(method[4], ...) + else + err,msg = pcall(return_f, method[4], ...) + end + local ti = profile.stop() + update_stat(method[3], ti) + assert(err,msg) +end + skynet.start(function() skynet.dispatch("lua", function ( session , source , id, ...) local method = func[id] @@ -78,6 +111,9 @@ skynet.start(function() skynet.fork(message_dispatch) end skynet.ret() + skynet.info_func(function() + return profile_table + end) init = true elseif mode == "queue" then queue( session, source, method , ...) @@ -94,11 +130,8 @@ skynet.start(function() assert(init, "Init first") if mode == "queue" then queue(session, source, method , ...) - elseif method[2] == "accept" then - -- no return - method[4](...) else - skynet.ret(skynet.pack(method[4](...))) + timing(method, ...) end end end) diff --git a/test/testping.lua b/test/testping.lua index 06746705c..61a82bc0d 100644 --- a/test/testping.lua +++ b/test/testping.lua @@ -24,6 +24,13 @@ end ]])) print(ps.post.hello()) + + local info = skynet.call(ps.handle, "debug", "INFO") + + for name,v in pairs(info) do + print(string.format("%s\tcount:%d time:%f", name, v.count, v.time)) + end + print(snax.kill(ps,"exit")) skynet.exit() end)