add skynet.trace()

lualib-src/lua-skynet.c

@@ -11,6 +11,29 @@
 #include <stdlib.h>
 #include <string.h>
 #include <assert.h>
+#include <inttypes.h>
+
+#include <time.h>
+
+#if defined(__APPLE__)
+#include <sys/time.h>
+#endif
+
+#include "skynet.h"
+
+// return nsec
+static int64_t
+get_time() {
+#if !defined(__APPLE__) || defined(AVAILABLE_MAC_OS_X_VERSION_10_12_AND_LATER)
+	struct timespec ti;
+	clock_gettime(CLOCK_MONOTONIC, &ti);
+	return (int64_t)1000000000 * ti.tv_sec + ti.tv_nsec;
+#else
+	struct timeval tv;
+	gettimeofday(&tv, NULL);
+	return (int64_t)1000000000 * tv.tv_sec + tv.tv_usec * 1000;
+#endif
+}
 
 struct snlua {
 	lua_State * L;
@@ -378,6 +401,40 @@ lnow(lua_State *L) {
 	return 1;
 }
 
+static int
+lhpc(lua_State *L) {
+	lua_pushinteger(L, get_time());
+	return 1;
+}
+
+/*
+	string tag
+	string userstring
+	thread co (default nil)
+	integer level (default is 3)
+ */
+static int
+ltrace(lua_State *L) {
+	struct skynet_context * context = lua_touserdata(L, lua_upvalueindex(1));
+	const char * tag = luaL_checkstring(L, 1);
+	const char * user = luaL_checkstring(L, 2);
+	if (lua_isthread(L, 3)) {
+		lua_State * co = lua_tothread (L, 3);
+		lua_Debug d;
+		int level = luaL_optinteger(L, 4, 3);
+		do {
+			if (!lua_getstack(co, level, &d))
+				break;
+			lua_getinfo(co, "Sl", &d);
+			level++;
+		} while (d.currentline < 0);
+		skynet_error(context, "<TRACE %s> %" PRId64 " %s : %s:%d", tag, get_time(), user, d.short_src, d.currentline);
+		return 0;
+	}
+	skynet_error(context, "<TRACE %s> %" PRId64 " %s", tag, get_time(), user);
+	return 0;
+}
+
 LUAMOD_API int
 luaopen_skynet_core(lua_State *L) {
 	luaL_checkversion(L);
@@ -390,18 +447,25 @@ luaopen_skynet_core(lua_State *L) {
 		{ "intcommand", lintcommand },
 		{ "addresscommand", laddresscommand },
 		{ "error", lerror },
-		{ "tostring", ltostring },
 		{ "harbor", lharbor },
+		{ "callback", lcallback },
+		{ "trace", ltrace },
+		{ NULL, NULL },
+	};
+
+	// functions without skynet_context
+	luaL_Reg l2[] = {
+		{ "tostring", ltostring },
 		{ "pack", luaseri_pack },
 		{ "unpack", luaseri_unpack },
 		{ "packstring", lpackstring },
 		{ "trash" , ltrash },
-		{ "callback", lcallback },
 		{ "now", lnow },
+		{ "hpc", lhpc },	// getHPCounter
 		{ NULL, NULL },
 	};
 
-	luaL_newlibtable(L, l);
+	lua_createtable(L, 0, sizeof(l)/sizeof(l[0]) + sizeof(l2)/sizeof(l2[0]) -2);
 
 	lua_getfield(L, LUA_REGISTRYINDEX, "skynet_context");
 	struct skynet_context *ctx = lua_touserdata(L,-1);
@@ -409,7 +473,10 @@ luaopen_skynet_core(lua_State *L) {
 		return luaL_error(L, "Init skynet context first");
 	}
 
+
 	luaL_setfuncs(L,l,1);
 
+	luaL_setfuncs(L,l2,0);
+
 	return 1;
 }

lualib/skynet.lua

@@ -28,6 +28,7 @@ local skynet = {
 	PTYPE_DEBUG = 9,
 	PTYPE_LUA = 10,
 	PTYPE_SNAX = 11,
+	PTYPE_TRACE = 12,	-- use for debug trace
 }
 
 -- code cache
@@ -45,6 +46,7 @@ end
 local session_id_coroutine = {}
 local session_coroutine_id = {}
 local session_coroutine_address = {}
+local session_coroutine_tracetag = {}
 local unresponse = {}
 
 local wakeup_queue = {}
@@ -151,28 +153,37 @@ end
 
 -- suspend is local function
 function suspend(co, result, command, param, param2)
+	local tag = session_coroutine_tracetag[co]
 	if not result then
 		local session = session_coroutine_id[co]
 		if session then -- coroutine may fork by others (session is nil)
 			local addr = session_coroutine_address[co]
 			if session ~= 0 then
 				-- only call response error
+				if tag then c.trace(tag, "error", co) end
 				c.send(addr, skynet.PTYPE_ERROR, session, "")
 			end
 			session_coroutine_id[co] = nil
 			session_coroutine_address[co] = nil
+			session_coroutine_tracetag[co] = nil
 		end
 		error(debug.traceback(co,tostring(command)))
 	end
 	if command == "CALL" then
+		if tag then
+			c.trace(tag, "call", co)
+			c.send(param2, skynet.PTYPE_TRACE, 0, tag)
+		end
 		session_id_coroutine[param] = co
 	elseif command == "SLEEP" then
+		if tag then c.trace(tag, "sleep", co) end
 		session_id_coroutine[param] = co
 		if sleep_session[param2] then
 			error(debug.traceback(co, "token duplicative"))
 		end
 		sleep_session[param2] = param
 	elseif command == "RETURN" then
+		if tag then c.trace(tag, "response") end
 		local co_session = session_coroutine_id[co]
 		session_coroutine_id[co] = nil
 		if co_session == 0 then
@@ -254,6 +265,7 @@ function suspend(co, result, command, param, param2)
 			release_watching(address)
 			session_coroutine_id[co] = nil
 			session_coroutine_address[co] = nil
+			session_coroutine_tracetag[co] = nil
 		end
 	elseif command == "QUIT" then
 		-- service exit
@@ -265,6 +277,10 @@ function suspend(co, result, command, param, param2)
 		-- We use session for other uses
 		session_coroutine_id[co] = nil
 		return suspend(co, coroutine_resume(co))
+	elseif command == "TRACE" then
+		session_coroutine_tracetag[co] = param
+		c.trace(param, "trace")
+		return suspend(co, coroutine_resume(co))
 	elseif command == nil then
 		-- debug trace
 		return
@@ -320,6 +336,13 @@ function skynet.localname(name)
 end
 
 skynet.now = c.now
+skynet.hpc = c.hpc	-- high performance counter
+
+local traceid = 0
+function skynet.trace()
+	traceid = traceid + 1
+	coroutine_yield("TRACE", string.format(":%08x-%d",skynet.self(), traceid))
+end
 
 local starttime
 
@@ -393,7 +416,7 @@ skynet.trash = assert(c.trash)
 
 local function yield_call(service, session)
 	watching_session[session] = service
-	local succ, msg, sz = coroutine_yield("CALL", session)
+	local succ, msg, sz = coroutine_yield("CALL", session, service)
 	watching_session[session] = nil
 	if not succ then
 		error "call failed"
@@ -483,6 +506,8 @@ function skynet.fork(func,...)
 	return co
 end
 
+local trace_source = {}
+
 local function raw_dispatch_message(prototype, msg, sz, session, source)
 	-- skynet.PTYPE_RESPONSE = 1, read skynet.h
 	if prototype == 1 then
@@ -492,13 +517,27 @@ local function raw_dispatch_message(prototype, msg, sz, session, source)
 		elseif co == nil then
 			unknown_response(session, source, msg, sz)
 		else
+			local tag = session_coroutine_tracetag[co]
+			if tag then c.trace(tag, "resume") end
 			session_id_coroutine[session] = nil
 			suspend(co, coroutine_resume(co, true, msg, sz))
 		end
 	else
+		local tag = trace_source[source]
+		if tag then
+			if session ~= 0 then
+				c.trace(tag, "request")
+				trace_source[source] = nil
+			else
+				tag = nil
+			end
+		end
 		local p = proto[prototype]
 		if p == nil then
-			if session ~= 0 then
+			if prototype == skynet.PTYPE_TRACE then
+				-- trace next request
+				trace_source[source] = c.tostring(msg,sz)
+			elseif session ~= 0 then
 				c.send(source, skynet.PTYPE_ERROR, session, "")
 			else
 				unknown_request(session, source, msg, sz, prototype)
@@ -516,6 +555,7 @@ local function raw_dispatch_message(prototype, msg, sz, session, source)
 			local co = co_create(f)
 			session_coroutine_id[co] = session
 			session_coroutine_address[co] = source
+			session_coroutine_tracetag[co] = tag
 			suspend(co, coroutine_resume(co, session,source, p.unpack(msg,sz)))
 		elseif session ~= 0 then
 			c.send(source, skynet.PTYPE_ERROR, session, "")

test/testping.lua

@@ -2,6 +2,7 @@ local skynet = require "skynet"
 local snax = require "skynet.snax"
 
 skynet.start(function()
+	skynet.trace()
 	local ps = snax.newservice ("pingserver", "hello world")
 	print(ps.req.ping("foobar"))
 	print(ps.post.hello())