add profile.elapsed

service-src/service_snlua.c

@@ -121,8 +121,9 @@ get_time() {
 }
 
 static inline double
-diff_time(double start) {
+diff_time(double start, double *pnow) {
 	double now = get_time();
+	if (pnow) *pnow = now;
 	if (now < start) {
 		return now + 0x10000 - start;
 	} else {
@@ -199,7 +200,7 @@ timing_resume(lua_State *L, int co_index, int n) {
 
 	if (timing_enable(L, co_index, &start_time)) {
 		double total_time = timing_total(L, co_index);
-		double diff = diff_time(start_time);
+		double diff = diff_time(start_time, NULL);
 		total_time += diff;
 #ifdef DEBUG_LOG
 		fprintf(stderr, "PROFILE [%p] yield (%lf/%lf)\n", co, diff, total_time);
@@ -293,8 +294,8 @@ lstart(lua_State *L) {
 	return 0;
 }
 
-static int
-lstop(lua_State *L) {
+static double
+timing_elapsed(lua_State *L, int stop) {
 	if (lua_gettop(L) != 0) {
 		lua_settop(L,1);
 		luaL_checktype(L, 1, LUA_TTHREAD);
@@ -303,32 +304,54 @@ lstop(lua_State *L) {
 	}
 	lua_Number start_time = 0;
 	if (!timing_enable(L, 1, &start_time)) {
-		return luaL_error(L, "Call profile.start() before profile.stop()");
+		return luaL_error(L, "Call profile.start() first, stop:%d", stop);
 	}
-	double ti = diff_time(start_time);
+	double now;
+	double ti = diff_time(start_time, &now);
 	double total_time = timing_total(L,1);
-
-	lua_pushvalue(L, 1);	// push coroutine
-	lua_pushnil(L);
-	lua_rawset(L, lua_upvalueindex(1));
-
-	lua_pushvalue(L, 1);	// push coroutine
-	lua_pushnil(L);
-	lua_rawset(L, lua_upvalueindex(2));
-
 	total_time += ti;
-	lua_pushnumber(L, total_time);
+	if (stop) {
+		lua_pushvalue(L, 1);	// push coroutine
+		lua_pushnil(L);
+		lua_rawset(L, lua_upvalueindex(1));
+
+		lua_pushvalue(L, 1);	// push coroutine
+		lua_pushnil(L);
+		lua_rawset(L, lua_upvalueindex(2));
+	} else {
+		lua_pushvalue(L, 1);
+		lua_pushnumber(L, now);
+		lua_rawset(L, lua_upvalueindex(1));	// set start time
+
+		lua_pushvalue(L, 1);
+		lua_pushnumber(L, total_time);
+		lua_rawset(L, lua_upvalueindex(2));
+	}
 #ifdef DEBUG_LOG
-	fprintf(stderr, "PROFILE [%p] stop (%lf/%lf)\n", lua_tothread(L,1), ti, total_time);
+	fprintf(stderr, "profile [%p] stop: %d (%lf/%lf)\n", lua_tothread(L,1), stop, ti, total_time);
 #endif
+	return total_time;
+}
+
+static int
+lelapsed(lua_State *L) {
+	double total_time = timing_elapsed(L, 0);
+	lua_pushnumber(L, total_time);
+	return 1;
+}
 
+static int
+lstop(lua_State *L) {
+	double total_time = timing_elapsed(L, 1);
+	lua_pushnumber(L, total_time);
 	return 1;
 }
 
 static int
 init_profile(lua_State *L) {
 	luaL_Reg l[] = {
 		{ "start", lstart },
+		{ "elapsed", lelapsed },
 		{ "stop", lstop },
 		{ "resume", luaB_coresume },
 		{ "wrap", luaB_cowrap },

test/testprofile.lua

@@ -0,0 +1,148 @@
+local skynet = require "skynet"
+local profile = require "skynet.profile"
+local tinsert = table.insert
+
+
+----------------------------------------------------
+-- simple call tree profiler
+
+local profiler = {}
+local calltree
+local currnode
+
+local function newnode(info)
+	return {
+		func = info.func,
+		name = info.name,
+		what = info.what,
+		start = profile.elapsed(),
+		time = 0,
+		count = 1,
+		parent = nil,
+		children = {},
+	}
+end
+
+local function hook(ev)
+	if ev == "call" then
+		local info = debug.getinfo(2, "nSf")
+		local node
+		if currnode then
+			for _, nd in ipairs(currnode.children) do
+				if nd.func == info.func then
+					node = nd
+					break
+				end
+			end
+			if node then
+				node.count = node.count + 1
+				node.start = profile.elapsed()
+			else
+				node = newnode(info)
+				tinsert(currnode.children, node)
+			end
+			node.parent = currnode
+		else
+			node = newnode(info)
+			tinsert(calltree.children, node)
+		end
+		currnode = node
+	elseif ev == "return" then
+		if not currnode then
+			return
+		end
+		local elapsed = profile.elapsed() - currnode.start
+		currnode.time = currnode.time + elapsed
+		currnode = currnode.parent
+	end
+end
+
+function profiler.start()
+	currnode = nil
+	calltree = {
+		children = {},
+	}
+	profile.start()
+	debug.sethook(hook, "cr")
+end
+
+function profiler.stop()
+	debug.sethook()
+	profile.stop()
+end
+
+function profiler.print(level)
+	print(string.format("%-30s%15s%15s%15s%30s%15s", "name", "time", "time self", "count", "func", "what"))
+	print(string.rep("-", 130))
+
+	local function calc_timeself(node)
+		local ti = node.time
+		for _, child in ipairs(node.children) do
+			ti = ti - child.time
+		end
+		return ti
+	end
+
+	local function print_nodes(nodes, indent)
+		for _, node in ipairs(nodes) do
+			local name = string.format("%s%s", string.rep(" ", indent*2), node.name)
+			local timeself = calc_timeself(node)
+			print(string.format("%-30s%15s%15s%15s%30s%15s", name, node.time, timeself, node.count, node.func, node.what))
+			if indent < level then
+				print_nodes(node.children, indent + 1)
+			end
+		end
+	end
+
+	level = level or 3
+	print_nodes(calltree.children, 0)
+end
+
+----------------------------------------------------
+-- test
+
+local function insert(a, v)
+	for i = #a, 1, -1 do
+		a[i+1] = a[i]
+	end
+	a[1] = tostring(v)
+end
+
+local function concat(a)
+	local s = ""
+	for i = 1, #a do
+		s = s ..a[i]
+	end
+end
+
+local function test1()
+	local a = {}
+	for i = 1, 10000 do
+		insert(a, i)
+	end
+	skynet.sleep(100)
+	concat(a)
+end
+
+local function test2()
+	local function fibonacci(n)
+		if n == 1 or n == 2 then
+			return 1
+		else
+			return fibonacci(n - 1) + fibonacci(n - 2)
+		end
+	end
+	fibonacci(26)
+end
+
+skynet.start(function()
+	skynet.timeout(0, function()
+		local t = skynet.time()
+		profiler.start()
+		test1()
+		test2()
+		profiler.stop()
+		print("skynet.time", skynet.time() - t)
+		profiler.print(6)
+	end)
+end)