From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: Received: from smtp45.i.mail.ru (smtp45.i.mail.ru [94.100.177.105]) (using TLSv1.2 with cipher ECDHE-RSA-AES256-GCM-SHA384 (256/256 bits)) (No client certificate requested) by dev.tarantool.org (Postfix) with ESMTPS id 886CD452566 for ; Tue, 5 Nov 2019 17:42:44 +0300 (MSK) From: Serge Petrenko Message-Id: <93DF4B75-6991-44C3-8CE5-2092C3F1F2CC@tarantool.org> Content-Type: multipart/alternative; boundary="Apple-Mail=_2E46587D-8DFE-4BD7-983C-E506463F7200" Mime-Version: 1.0 (Mac OS X Mail 12.4 \(3445.104.11\)) Date: Tue, 5 Nov 2019 17:42:43 +0300 In-Reply-To: References: <20191101140523.14580-1-sergepetrenko@tarantool.org> Subject: Re: [Tarantool-patches] [tarantool-patches] [PATCH v3] lua: add fiber.top() listing fiber cpu consumption List-Id: Tarantool development patches List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , To: Vladislav Shpilevoy Cc: tarantool-patches@freelists.org, tarantool-patches@dev.tarantool.org --Apple-Mail=_2E46587D-8DFE-4BD7-983C-E506463F7200 Content-Transfer-Encoding: quoted-printable Content-Type: text/plain; charset=utf-8 Hi! Thanks for your review! I pushed the changes on the branch, the diff is below. -- Serge Petrenko sergepetrenko@tarantool.org > 2 =D0=BD=D0=BE=D1=8F=D0=B1. 2019 =D0=B3., =D0=B2 20:12, Vladislav = Shpilevoy =D0=BD=D0=B0=D0=BF=D0=B8=D1=81=D0=B0= =D0=BB(=D0=B0): >=20 > Hi! Thanks for the patch! >=20 > See 3 comments below. >=20 >> diff --git a/src/lib/core/fiber.c b/src/lib/core/fiber.c >> index 93f22ae68..52888cc64 100644 >> --- a/src/lib/core/fiber.c >> +++ b/src/lib/core/fiber.c >> @@ -82,6 +86,38 @@ static int (*fiber_invoke)(fiber_func f, va_list = ap); >> +#if ENABLE_FIBER_TOP >> +static __thread bool fiber_top_enabled =3D false; >> + >> +/** >> + * An action performed each time a context switch happens. >> + * Used to count each fiber's processing time. >> + */ >> +static inline void >> +clock_set_on_csw(struct fiber *caller) >> +{ >> + caller->csw++; >> + if (!fiber_top_enabled) >> + return; >> + >> + uint64_t clock; >> + uint32_t cpu_id; >> + clock =3D __rdtscp(&cpu_id); >> + >> + if (cpu_id =3D=3D cord()->cpu_id_last) { >> + caller->clock_delta +=3D clock - cord()->clock_last; >> + cord()->clock_delta +=3D clock - cord()->clock_last; >> + } else { >> + cord()->cpu_id_last =3D cpu_id; >> + cord()->cpu_miss_count++; >> + } >> + cord()->clock_last =3D clock; >> +} >> + >> +#else >> +#define clock_set_on_csw(caller) ; >=20 > 1. With undefined ENABLE_FIBER_TOP you don't update csw counter. > I would move this #if ENABLE to the clock_set_on_csw() body, > right after csw is incremented. Fixed. >=20 >> +#endif /* ENABLE_FIBER_TOP */ >> + >> diff --git a/src/lua/fiber.c b/src/lua/fiber.c >> index 124908a05..a030e444d 100644 >> --- a/src/lua/fiber.c >> +++ b/src/lua/fiber.c >> @@ -319,6 +323,67 @@ lbox_fiber_statof_nobt(struct fiber *f, void = *cb_ctx) >> return lbox_fiber_statof(f, cb_ctx, false); >> } >>=20 >> +#if ENABLE_FIBER_TOP >> +static int >> +lbox_fiber_top_entry(struct fiber *f, void *cb_ctx) >> +{ >> + struct lua_State *L =3D (struct lua_State *) cb_ctx; >> + char name_buf[64]; >> + >> + snprintf(name_buf, sizeof(name_buf), "%u/%s", f->fid, f->name); >> + lua_pushstring(L, name_buf); >=20 > 2. A piece of advice - use tt_sprintf: >=20 > lua_pushstring(L, tt_sprintf("%u/%s", f->fid, f->name)); Thanks! Changed. >=20 >> + >> + lua_newtable(L); >> + >> + lua_pushliteral(L, "average"); >> + lua_pushnumber(L, f->clock_acc / (double)cord()->clock_acc * = 100); >> + lua_settable(L, -3); >> + lua_pushliteral(L, "instant"); >> + lua_pushnumber(L, f->clock_delta_last / = (double)cord()->clock_delta_last * 100); >> + lua_settable(L, -3); >> + lua_pushliteral(L, "time"); >> + lua_pushnumber(L, f->cputime / (double) FIBER_TIME_RES); >> + lua_settable(L, -3); >> + lua_settable(L, -3); >> + >> + return 0; >> +} >> diff --git a/test/app/fiber.result b/test/app/fiber.result >> index 3c6115a33..3b9e5da9a 100644 >> --- a/test/app/fiber.result >> +++ b/test/app/fiber.result >> @@ -1462,6 +1462,91 @@ fiber.join(fiber.self()) >> --- >> - error: the fiber is not joinable >> ... >> +sum =3D 0 >> +--- >> +... >> +-- gh-2694 fiber.top() >> +fiber.top_enable() >> +--- >> +... >> +a =3D fiber.top() >> +--- >> +... >> +type(a) >> +--- >> +- table >> +... >> +-- scheduler is present in fiber.top() >> +-- and is indexed by name >> +a["1/sched"] ~=3D nil >> +--- >> +- true >> +... >> +type(a["cpu misses"]) =3D=3D 'number' >> +--- >> +- true >> +... >> +sum_inst =3D 0 >> +--- >> +... >> +sum_avg =3D 0 >> +--- >> +... >> +-- update table to make sure >> +-- a full event loop iteration >> +-- has ended >> +a =3D fiber.top() >> +--- >> +... >> +for k, v in pairs(a) do\ >> + if type(v) =3D=3D 'table' then\ >=20 > 3. This looks hard to use. The fact, that one table contains > records totally different in their structure. I would propose > to return cpu misses and fibers separately: >=20 > fiber.top() =3D >=20 > cpu_misses =3D , > time =3D [ > '/' =3D {...}, > '/' =3D {...}, > '/' =3D {...}, > ... > ] >=20 > Then you can take fiber.top().time and be sure, that all > records here have the same structure. As far as I remember > we already had similar problems with other statistics, so > it is better to design it know in the most extendible way. > And it will be easier to add new global statistics to the > top in future. >=20 Good point. I named the subtable `cpu` instead of `time`. It makes more sense imo. Also renamed `cpu misses` to `cpu_misses` so that it can be accessed as fiber.top ().cpu_misses diff --git a/src/lib/core/fiber.c b/src/lib/core/fiber.c index 52888cc64..aebaba7f0 100644 --- a/src/lib/core/fiber.c +++ b/src/lib/core/fiber.c @@ -88,6 +88,7 @@ static int (*fiber_invoke)(fiber_func f, va_list ap); =20 #if ENABLE_FIBER_TOP static __thread bool fiber_top_enabled =3D false; +#endif /* ENABLE_FIBER_TOP */ =20 /** * An action performed each time a context switch happens. @@ -97,6 +98,8 @@ static inline void clock_set_on_csw(struct fiber *caller) { caller->csw++; + +#if ENABLE_FIBER_TOP if (!fiber_top_enabled) return; =20 @@ -112,12 +115,10 @@ clock_set_on_csw(struct fiber *caller) cord()->cpu_miss_count++; } cord()->clock_last =3D clock; -} - -#else -#define clock_set_on_csw(caller) ; #endif /* ENABLE_FIBER_TOP */ =20 +} + /* * Defines a handler to be executed on exit from cord's thread func, * accessible via cord()->on_exit (normally NULL). It is used to diff --git a/src/lua/fiber.c b/src/lua/fiber.c index a030e444d..8b3b22e55 100644 --- a/src/lua/fiber.c +++ b/src/lua/fiber.c @@ -33,6 +33,7 @@ #include #include "lua/utils.h" #include "backtrace.h" +#include "tt_static.h" =20 #include #include @@ -328,10 +329,8 @@ static int lbox_fiber_top_entry(struct fiber *f, void *cb_ctx) { struct lua_State *L =3D (struct lua_State *) cb_ctx; - char name_buf[64]; =20 - snprintf(name_buf, sizeof(name_buf), "%u/%s", f->fid, f->name); - lua_pushstring(L, name_buf); + lua_pushstring(L, tt_sprintf("%u/%s", f->fid, f->name)); =20 lua_newtable(L); =20 @@ -357,12 +356,15 @@ lbox_fiber_top(struct lua_State *L) " fiber.top_enable() first"); } lua_newtable(L); - lua_pushliteral(L, "cpu misses"); + lua_pushliteral(L, "cpu_misses"); lua_pushnumber(L, cord()->cpu_miss_count_last); lua_settable(L, -3); =20 + lua_pushliteral(L, "cpu"); + lua_newtable(L); lbox_fiber_top_entry(&cord()->sched, L); fiber_stat(lbox_fiber_top_entry, L); + lua_settable(L, -3); =20 return 1; } diff --git a/test/app/fiber.result b/test/app/fiber.result index 3b9e5da9a..4a094939f 100644 --- a/test/app/fiber.result +++ b/test/app/fiber.result @@ -1478,11 +1478,11 @@ type(a) ... -- scheduler is present in fiber.top() -- and is indexed by name -a["1/sched"] ~=3D nil +a.cpu["1/sched"] ~=3D nil --- - true ... -type(a["cpu misses"]) =3D=3D 'number' +type(a.cpu_misses) =3D=3D 'number' --- - true ... @@ -1495,14 +1495,12 @@ sum_avg =3D 0 -- update table to make sure -- a full event loop iteration -- has ended -a =3D fiber.top() +a =3D fiber.top().cpu --- ... for k, v in pairs(a) do\ - if type(v) =3D=3D 'table' then\ - sum_inst =3D sum_inst + v["instant"]\ - sum_avg =3D sum_avg + v["average"]\ - end\ + sum_inst =3D sum_inst + v["instant"]\ + sum_avg =3D sum_avg + v["average"]\ end --- ... @@ -1521,7 +1519,7 @@ tbl =3D nil f =3D fiber.new(function()\ for i =3D 1,1000 do end\ fiber.yield()\ - tbl =3D fiber.top()[fiber.self().id()..'/'..fiber.self().name()]\ + tbl =3D = fiber.top().cpu[fiber.self().id()..'/'..fiber.self().name()]\ end) --- ... diff --git a/test/app/fiber.test.lua b/test/app/fiber.test.lua index ce1f55e8d..38b85d554 100644 --- a/test/app/fiber.test.lua +++ b/test/app/fiber.test.lua @@ -638,20 +638,18 @@ a =3D fiber.top() type(a) -- scheduler is present in fiber.top() -- and is indexed by name -a["1/sched"] ~=3D nil -type(a["cpu misses"]) =3D=3D 'number' +a.cpu["1/sched"] ~=3D nil +type(a.cpu_misses) =3D=3D 'number' sum_inst =3D 0 sum_avg =3D 0 =20 -- update table to make sure -- a full event loop iteration -- has ended -a =3D fiber.top() +a =3D fiber.top().cpu for k, v in pairs(a) do\ - if type(v) =3D=3D 'table' then\ - sum_inst =3D sum_inst + v["instant"]\ - sum_avg =3D sum_avg + v["average"]\ - end\ + sum_inst =3D sum_inst + v["instant"]\ + sum_avg =3D sum_avg + v["average"]\ end =20 sum_inst @@ -661,7 +659,7 @@ tbl =3D nil f =3D fiber.new(function()\ for i =3D 1,1000 do end\ fiber.yield()\ - tbl =3D fiber.top()[fiber.self().id()..'/'..fiber.self().name()]\ + tbl =3D = fiber.top().cpu[fiber.self().id()..'/'..fiber.self().name()]\ end) while f:status() ~=3D 'dead' do fiber.sleep(0.01) end tbl["average"] > 0 --Apple-Mail=_2E46587D-8DFE-4BD7-983C-E506463F7200 Content-Transfer-Encoding: quoted-printable Content-Type: text/html; charset=utf-8 Hi! = Thanks for your review!
I pushed the changes on the = branch, the diff is below.




2= =D0=BD=D0=BE=D1=8F=D0=B1. 2019 =D0=B3., =D0=B2 20:12, Vladislav = Shpilevoy <v.shpilevoy@tarantool.org> = =D0=BD=D0=B0=D0=BF=D0=B8=D1=81=D0=B0=D0=BB(=D0=B0):

Hi! = Thanks for the patch!

See 3 comments = below.

diff --git a/src/lib/core/fiber.c b/src/lib/core/fiber.c
index 93f22ae68..52888cc64 100644
--- = a/src/lib/core/fiber.c
+++ b/src/lib/core/fiber.c
@@ -82,6 +86,38 @@ static int (*fiber_invoke)(fiber_func f, = va_list ap);
+#if ENABLE_FIBER_TOP
+static = __thread bool fiber_top_enabled =3D false;
+
+/**
+ * An action performed each time a = context switch happens.
+ * Used to count each fiber's = processing time.
+ */
+static inline void
+clock_set_on_csw(struct fiber *caller)
+{
+ = caller->csw++;
+ if (!fiber_top_enabled)
+ = = return;
+
+ uint64_t = clock;
+ uint32_t cpu_id;
+ = clock =3D __rdtscp(&cpu_id);
+
+ = if (cpu_id =3D=3D cord()->cpu_id_last) {
+ = caller->clock_delta +=3D clock - cord()->clock_last;
+ = = cord()->clock_delta +=3D clock - cord()->clock_last;
+ = } else {
+ cord()->cpu_id_last =3D = cpu_id;
+ cord()->cpu_miss_count++;
+ = }
+ cord()->clock_last =3D = clock;
+}
+
+#else
+#define clock_set_on_csw(caller) ;

1. With undefined = ENABLE_FIBER_TOP you don't update csw counter.
I would = move this #if ENABLE to the clock_set_on_csw() body,
right = after csw is incremented.

Fixed.


+#endif /* ENABLE_FIBER_TOP */
+diff --git a/src/lua/fiber.c b/src/lua/fiber.c
index 124908a05..a030e444d 100644
--- = a/src/lua/fiber.c
+++ b/src/lua/fiber.c
@@ = -319,6 +323,67 @@ lbox_fiber_statof_nobt(struct fiber *f, void = *cb_ctx)
return lbox_fiber_statof(f, = cb_ctx, false);
}

+#if = ENABLE_FIBER_TOP
+static int
+lbox_fiber_top_entry(struct fiber *f, void *cb_ctx)
+{
+ struct lua_State *L =3D (struct = lua_State *) cb_ctx;
+ char name_buf[64];
+
+ snprintf(name_buf, = sizeof(name_buf), "%u/%s", f->fid, f->name);
+ = lua_pushstring(L, name_buf);

2. A piece of advice - use tt_sprintf:

   lua_pushstring(L, tt_sprintf("%u/%s", = f->fid, f->name));

Thanks! Changed.


+
+ = lua_newtable(L);
+
+ = lua_pushliteral(L, "average");
+ = lua_pushnumber(L, f->clock_acc / (double)cord()->clock_acc = * 100);
+ lua_settable(L, -3);
+ = lua_pushliteral(L, "instant");
+ = lua_pushnumber(L, f->clock_delta_last / = (double)cord()->clock_delta_last * 100);
+ = lua_settable(L, -3);
+ lua_pushliteral(L, "time");
+ = lua_pushnumber(L, f->cputime / (double) FIBER_TIME_RES);
+ = lua_settable(L, -3);
+ lua_settable(L, -3);
+
+ return 0;
+}
diff --git a/test/app/fiber.result b/test/app/fiber.result
index 3c6115a33..3b9e5da9a 100644
--- = a/test/app/fiber.result
+++ b/test/app/fiber.result
@@ -1462,6 +1462,91 @@ fiber.join(fiber.self())
= ---
- error: the fiber is not joinable
= ...
+sum =3D 0
+---
+...
+-- gh-2694 fiber.top()
+fiber.top_enable()
+---
+...
+a =3D fiber.top()
+---+...
+type(a)
+---
+- table
+...
+-- scheduler is = present in fiber.top()
+-- and is indexed by name
+a["1/sched"] ~=3D = nil
+---
+- true
+...
+type(a["cpu misses"]) =3D=3D 'number'
+---
+- true
+...
+sum_inst =3D 0
+---
+...
+sum_avg =3D 0
+---
+...
+-- update table to = make sure
+-- a full event loop iteration
+-- = has ended
+a =3D fiber.top()
+---
+...
+for k, v in pairs(a) do\
+ =    if type(v) =3D=3D 'table' then\

3. This looks hard to use. The = fact, that one table contains
records totally different in = their structure. I would propose
to return cpu misses and = fibers separately:

   fiber.top() =3D
       cpu_misses =3D = <number>,
=        time =3D [
=            '<id&= gt;/<name>' =3D {...},
=            '<id&= gt;/<name>' =3D {...},
=            '<id&= gt;/<name>' =3D {...},
=            ...
       ]

Then you can take fiber.top().time and be sure, that all
records here have the same structure. As far as I remember
we already had similar problems with other statistics, so
it is better to design it know in the most extendible way.
And it will be easier to add new global statistics to the
top in future.


Good = point. I named the subtable `cpu` instead of `time`. It makes = more
sense imo. Also renamed `cpu misses` to `cpu_misses` so = that it can be
accessed as fiber.top().cpu_misses


diff --git a/src/lib/core/fiber.c = b/src/lib/core/fiber.c
index 52888cc64..aebaba7f0 = 100644
--- a/src/lib/core/fiber.c
+++ = b/src/lib/core/fiber.c
@@ -88,6 +88,7 @@ static int = (*fiber_invoke)(fiber_func f, va_list ap);
 
 #if ENABLE_FIBER_TOP
 static = __thread bool fiber_top_enabled =3D false;
+#endif /* = ENABLE_FIBER_TOP */
 
 /**
  * An action performed each time a context switch = happens.
@@ -97,6 +98,8 @@ static inline void
 clock_set_on_csw(struct fiber *caller)
 {
  caller->csw++;
+
+#if ENABLE_FIBER_TOP
  if = (!fiber_top_enabled)
  return;
 
@@ -112,12 +115,10 @@ = clock_set_on_csw(struct fiber *caller)
  = cord()->cpu_miss_count++;
  }
 = cord()->clock_last =3D clock;
-}
-
-#else
-#define = clock_set_on_csw(caller) ;
 #endif /* = ENABLE_FIBER_TOP */
 
+}
+
 /*
  * Defines = a handler to be executed on exit from cord's thread func,
  * accessible via cord()->on_exit (normally = NULL). It is used to
diff --git a/src/lua/fiber.c = b/src/lua/fiber.c
index a030e444d..8b3b22e55 100644
--- a/src/lua/fiber.c
+++ b/src/lua/fiber.c
@@ -33,6 +33,7 @@
 #include = <fiber.h>
 #include "lua/utils.h"
 #include "backtrace.h"
+#include = "tt_static.h"
 
 #include = <lua.h>
 #include <lauxlib.h>
@@ -328,10 +329,8 @@ static int
 lbox_fiber_top_entry(struct fiber *f, void *cb_ctx)
 {
  struct lua_State *L =3D (struct = lua_State *) cb_ctx;
- char name_buf[64];
 
- snprintf(name_buf, = sizeof(name_buf), "%u/%s", f->fid, f->name);
- = lua_pushstring(L, name_buf);
+ = lua_pushstring(L, tt_sprintf("%u/%s", f->fid, f->name));
 
  lua_newtable(L);
 
@@ -357,12 +356,15 @@ = lbox_fiber_top(struct lua_State *L)
  =       " fiber.top_enable() first");
 = }
  lua_newtable(L);
- = lua_pushliteral(L, "cpu misses");
+ = lua_pushliteral(L, "cpu_misses");
  = lua_pushnumber(L, cord()->cpu_miss_count_last);
 = lua_settable(L, -3);
 
+ = lua_pushliteral(L, "cpu");
+ = lua_newtable(L);
  = lbox_fiber_top_entry(&cord()->sched, L);
 = fiber_stat(lbox_fiber_top_entry, L);
+ = lua_settable(L, -3);
 
  return = 1;
 }
diff --git = a/test/app/fiber.result b/test/app/fiber.result
index = 3b9e5da9a..4a094939f 100644
--- a/test/app/fiber.result
+++ b/test/app/fiber.result
@@ -1478,11 = +1478,11 @@ type(a)
 ...
 -- = scheduler is present in fiber.top()
 -- and is indexed by = name
-a["1/sched"] ~=3D nil
+a.cpu["1/sched"] = ~=3D nil
 ---
 - true
 ...
-type(a["cpu misses"]) =3D=3D = 'number'
+type(a.cpu_misses) =3D=3D 'number'
 ---
 - true
 ...@@ -1495,14 +1495,12 @@ sum_avg =3D 0
 -- = update table to make sure
 -- a full event loop = iteration
 -- has ended
-a =3D fiber.top()
+a =3D = fiber.top().cpu
 ---
 ...
 for k, = v in pairs(a) do\
-    if type(v) =3D=3D = 'table' then\
-        sum_inst =3D= sum_inst + v["instant"]\
-      =   sum_avg =3D sum_avg + v["average"]\
-  =   end\
+    sum_inst =3D sum_inst = + v["instant"]\
+    sum_avg =3D sum_avg + = v["average"]\
 end
 ---
 ...
@@ -1521,7 +1519,7 @@ tbl =3D nil
 f =3D fiber.new(function()\
    =  for i =3D 1,1000 do end\
    =  fiber.yield()\
-    tbl =3D fiber.top()[fiber.self().id()..'/'..fiber.self().name()]\+    tbl =3D fiber.top().cpu[fiber.self().id()..'/'..fiber.self().name()= ]\
 end)
 ---
 ...
diff --git a/test/app/fiber.test.lua = b/test/app/fiber.test.lua
index ce1f55e8d..38b85d554 = 100644
--- a/test/app/fiber.test.lua
+++ = b/test/app/fiber.test.lua
@@ -638,20 +638,18 @@ a =3D fiber.top()
 type(a)
 -- scheduler is present in = fiber.top()
 -- and is indexed by name
-a["1/sched"] = ~=3D nil
-type(a["cpu misses"]) =3D=3D 'number'
+a.cpu["1/sched"] ~=3D nil
+type(a.cpu_misses) = =3D=3D 'number'
 sum_inst =3D 0
 sum_avg =3D 0
 
 --= update table to make sure
 -- a full event loop = iteration
 -- has ended
-a =3D fiber.top()
+a =3D = fiber.top().cpu
 for k, v in pairs(a) do\
-  =   if type(v) =3D=3D 'table' then\
-    =     sum_inst =3D sum_inst + v["instant"]\
-        sum_avg =3D sum_avg + = v["average"]\
-    end\
+ =   sum_inst =3D sum_inst + v["instant"]\
+  =   sum_avg =3D sum_avg + v["average"]\
 end 
 sum_inst
@@ -661,7 = +659,7 @@ tbl =3D nil
 f =3D fiber.new(function()\
     for i =3D 1,1000 do end\
     fiber.yield()\
-  =   tbl =3D fiber.top()[fiber.self().id()..'/'..fiber.self().name()]\+    tbl =3D fiber.top().cpu[fiber.self().id()..'/'..fiber.self().name()= ]\
 end)
 while f:status() ~=3D = 'dead' do fiber.sleep(0.01) end
 tbl["average"] > = 0

= --Apple-Mail=_2E46587D-8DFE-4BD7-983C-E506463F7200--