From 45898e35f7c5426d2266c1818cd9a1fa9cf6d7e8 Mon Sep 17 00:00:00 2001 From: colin <124654806@qq.com> Date: Thu, 23 Sep 2021 21:38:48 +0800 Subject: [PATCH] add profile.elapsed --- service-src/service_snlua.c | 57 +++++++++----- test/testprofile.lua | 148 ++++++++++++++++++++++++++++++++++++ 2 files changed, 188 insertions(+), 17 deletions(-) create mode 100644 test/testprofile.lua diff --git a/service-src/service_snlua.c b/service-src/service_snlua.c index 4e9381ce8..238c54c4b 100644 --- a/service-src/service_snlua.c +++ b/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,25 +304,46 @@ 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; } @@ -329,6 +351,7 @@ static int init_profile(lua_State *L) { luaL_Reg l[] = { { "start", lstart }, + { "elapsed", lelapsed }, { "stop", lstop }, { "resume", luaB_coresume }, { "wrap", luaB_cowrap }, diff --git a/test/testprofile.lua b/test/testprofile.lua new file mode 100644 index 000000000..a6239a62b --- /dev/null +++ b/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)