add profile module, and use it in snax

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
 

lualib-src/lua-profile.c

@@ -0,0 +1,184 @@
+#include <lua.h>
+#include <lauxlib.h>
+
+
+#include <time.h>
+
+#if defined(__APPLE__)
+#include <mach/task.h>
+#include <mach/mach.h>
+#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;
+}

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()

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)

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)