From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: Received: from smtp16.mail.ru (smtp16.mail.ru [94.100.176.153]) (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 7FC5343D679 for ; Fri, 25 Oct 2019 18:13:33 +0300 (MSK) From: Serge Petrenko Message-Id: Content-Type: multipart/alternative; boundary="Apple-Mail=_EE59F4D1-B725-4C74-AE25-12D32DF66656" Mime-Version: 1.0 (Mac OS X Mail 12.4 \(3445.104.11\)) Date: Fri, 25 Oct 2019 18:13:32 +0300 In-Reply-To: <5b3c1fae-1c49-4b13-3a0e-0774c4add3fb@tarantool.org> References: <5b3c1fae-1c49-4b13-3a0e-0774c4add3fb@tarantool.org> Subject: Re: [Tarantool-patches] [tarantool-patches] [PATCH v2 2/2] lua: add fiber.top() listing fiber cpu consumption List-Id: Tarantool development 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=_EE59F4D1-B725-4C74-AE25-12D32DF66656 Content-Transfer-Encoding: quoted-printable Content-Type: text/plain; charset=utf-8 Hi! Thank you for review! I addressed your comments and answered inline. Incremental diff is below. > 23 =D0=BE=D0=BA=D1=82. 2019 =D0=B3., =D0=B2 0:18, Vladislav Shpilevoy = =D0=BD=D0=B0=D0=BF=D0=B8=D1=81=D0=B0=D0=BB(=D0= =B0): >=20 > Thanks for the patch! >=20 > Sorry, the version in the email is a bit outdated. I > pasted below the actual version from the branch. >=20 > See 9 comments below. >=20 >> lua: add fiber.top() listing fiber cpu consumption >>=20 >> Implement a new function in Lua fiber library: top(). It returns a = table >> of alive fibers (including the scheduler). Each table entry has = two >> fields: average cpu consumption, which is calculated with = exponential >> moving average over event loop iterations, and current cpu = consumption, >> which shows fiber's cpu usage over the last event loop iteration. >> The patch relies on CPU timestamp counter to measure each fiber's = time >> share. >>=20 >> Closes #2694 >>=20 >> @TarantoolBot document >> Title: fiber: new function `fiber.top()` >>=20 >> `fiber.top()` returns a table of all alive fibers and lists their = cpu >> consumption. Let's take a look at the example: >> ``` >> tarantool> fiber.top() >> --- >> - 1: >> cpu average (%): 10.779696493982 >> cpu instant (%): 10.435256168573 >=20 > 1. Have you considered making these option names > one word? 'cpu average (%)' -> 'average'. The > same for instant. My motivation is that it could > simplify wrappers which are going to use the top > to show it in a GUI or something. You actually use > it in the tests. >=20 > It would not hard readability IMO. It is obvious > that top is in percents, and about CPU time. No problem. >=20 >> 115: >> cpu average (%): 5.4571279061075 >> cpu instant (%): 5.9653973440576 >> 120: >> cpu average (%): 21.944382148464 >> cpu instant (%): 23.849021825646 >> 116: >> cpu average (%): 8.6603872318158 >> cpu instant (%): 9.6812031335093 >> 119: >> cpu average (%): 21.933168871944 >> cpu instant (%): 20.007540530351 >> cpu misses: 0 >> 118: >> cpu average (%): 19.342901995963 >> cpu instant (%): 16.932679820703 >> 117: >> cpu average (%): 11.549674814981 >> cpu instant (%): 13.128901177161 >> ... >> ``` >=20 > 2. This is super cool! >=20 > Could we give names to predefined fibers? For > example, make an alias top.scheduler =3D top[1]. >=20 > So as in the console output I would see: >=20 > --- > - scheduler: > cpu average (%): 98.230148883023 > cpu instant (%): 100 >=20 > Instead of '1'. Because personally I didn't > even know that 1 is always the scheduler, and > I would be confused to see a regular fiber > consumed 99% of time in a console. Hmm, what about this? --- a/src/lua/fiber.c +++ b/src/lua/fiber.c @@ -325,13 +325,18 @@ lbox_fiber_top_entry(struct fiber *f, void = *cb_ctx) { struct lua_State *L =3D (struct lua_State *) cb_ctx; =20 - lua_pushinteger(L, f->fid); + /* Index system fibers by name instead of id */ + if (f->fid <=3D FIBER_ID_MAX_RESERVED) { + lua_pushstring(L, f->name); + } else { + lua_pushinteger(L, f->fid); + } lua_newtable(L); >=20 >> In the table above keys are fiber id's (and a single 'cpu misses' = key >> which indicates the amount of times tx thread was rescheduled on a >> different cpu core. More on that later). >> The two metrics available for each fiber are: >> 1) cpu instant (per cent), >> which indicates the share of time fiber was executing during the >> previous event loop iteration >> 2) cpu average (per cent), which is calculated as an exponential = moving >> average of `cpu instant` values over all previous event loop = iterations. >>=20 >> More info on `cpu misses` field returned by `fiber.top()`: >> `cpu misses` indicates the amount of times tx thread detected it = was >> rescheduled on a different cpu core during the last event loop >> iteration. >> fiber.top() uses cpu timestamp counter to measure each fiber's = execution >> time. However, each cpu core may have its own counter value (you = can >> only rely on counter deltas if both measurements were taken on the = same >> core, otherwise the delta may even get negative). >> When tx thread is rescheduled to a different cpu core, tarantool = just >> assumes cpu delta was zero for the lust measurement. This loweres >> precision of our computations, so the bigger `cpu misses` value = the >> lower the precision of fiber.top() results. >>=20 >> Fiber.top() doesn't work on arm architecture at the moment. >=20 > 2. Have you done benchmarks how much top slows down fiber > switching? It should not be hard to measure. Just switching. > Lots of fibers which only yield. And measure loop iterations > per second. Won't work? Or average/median duration of one > loop iteration. Hi! I tested context switches per second. The results are in the issue comments: = https://github.com/tarantool/tarantool/issues/2694#issuecomment-546381304 = Performance degradation is between 10 and 16 per cent. >>=20 >> diff --git a/src/lib/core/fiber.c b/src/lib/core/fiber.c >> index b813c1739..bea49eb41 100644 >> --- a/src/lib/core/fiber.c >> +++ b/src/lib/core/fiber.c >> @@ -37,11 +37,14 @@ >> #include >> #include >> #include >> - >> #include "assoc.h" >=20 > 3. Sorry, looks like stray diff. Could you > please drop it? >=20 Thanks for noticing! Fixed. >> #include "memory.h" >> #include "trigger.h" >> @@ -82,6 +85,34 @@ static int (*fiber_invoke)(fiber_func f, va_list = ap); >> err; = \ >> }) >>=20 >> +#if ENABLE_FIBER_TOP >> +/** >> + * An action performed each time a context switch happens. >> + * Used to count each fiber's processing time. >> + * This is a macro rather than a function, since it is used >> + * in scheduler too. >=20 > 4. Hm. Not sure if I understand. Ok, it is used in the scheduler, > so why does it prevent making it a function? Caller is always > struct fiber *, so you can make it a function taking fiber * > parameter, can't you? You cannot call functions from scheduler cos it doesn=E2=80=99t have a stack AFAIU. I can make it an inline function if you want me to. >=20 >> + */ >> +#define clock_set_on_csw(caller) = \ >> +({ = \ >> + 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; = \ >> +})> @@ -584,6 +617,7 @@ fiber_schedule_list(struct rlist *list) >> } >> last->caller =3D fiber(); >> assert(fiber() =3D=3D &cord()->sched); >> + clock_set_on_csw(fiber()); >=20 > 5. Am I right, that we need to update CPU consumption each > time a context switch happens? Yep. > If so, then by logic you > would need to call clock_set_on_csw() on each fiber->csw++, > correct? Right. I also call clock_set_on_csw() on each event loop iteration end. >=20 > Currently that happens in 2 places: fiber_call_impl() and > fiber_yield(). In both these places you already call > clock_set_on_csw(): >=20 > - You always call clock_set_on_csw() right before > fiber_call_impl(); >=20 > - You call clock_set_on_csw() in fiber_yield(). >=20 > I would then move fiber->cws++ logic into your macros too. > So all the context switch and CPU time tracking logic > would be in one place. >=20 > The only problem is that your macros takes caller, but csw++ > is done for callee. Probably we could increment it for the > caller instead, I don't anything depends on that. >=20 > Also it would lead to increment of the scheduler's csw > counter. Not sure whether it is ok. Loop iteration end isn=E2=80=99t a context switch, but I still update clocks here. I don=E2=80=99t want to increment csw here as a side effect, so maybe leave csw increment as it is? >=20 > Like that (I didn't test it): >=20 > =3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D= =3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D= =3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D >=20 > diff --git a/src/lib/core/fiber.c b/src/lib/core/fiber.c > index bea49eb41..e9aac99d0 100644 > --- a/src/lib/core/fiber.c > +++ b/src/lib/core/fiber.c > @@ -105,6 +105,7 @@ static int (*fiber_invoke)(fiber_func f, va_list = ap); > cord()->cpu_id_last =3D cpu_id; = \ > cord()->cpu_miss_count++; = \ > } = \ > + caller->csw++; = \ > cord()->clock_last =3D clock; = \ > }) >=20 > @@ -258,7 +259,7 @@ fiber_call_impl(struct fiber *callee) > cord->fiber =3D callee; >=20 > callee->flags &=3D ~FIBER_IS_READY; > - callee->csw++; > + clock_set_on_csw(caller); > ASAN_START_SWITCH_FIBER(asan_state, 1, > callee->stack, > callee->stack_size); > @@ -277,7 +278,6 @@ fiber_call(struct fiber *callee) > /** By convention, these triggers must not throw. */ > if (! rlist_empty(&caller->on_yield)) > trigger_run(&caller->on_yield, NULL); > - clock_set_on_csw(caller); > callee->caller =3D caller; > callee->flags |=3D FIBER_IS_READY; > caller->flags |=3D FIBER_IS_READY; > @@ -511,7 +511,6 @@ fiber_yield(void) > assert(callee->flags & FIBER_IS_READY || callee =3D=3D = &cord->sched); > assert(! (callee->flags & FIBER_IS_DEAD)); > cord->fiber =3D callee; > - callee->csw++; > callee->flags &=3D ~FIBER_IS_READY; > ASAN_START_SWITCH_FIBER(asan_state, > (caller->flags & FIBER_IS_DEAD) =3D=3D = 0, > @@ -617,7 +616,6 @@ fiber_schedule_list(struct rlist *list) > } > last->caller =3D fiber(); > assert(fiber() =3D=3D &cord()->sched); > - clock_set_on_csw(fiber()); > fiber_call_impl(first); > } >=20 > =3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D= =3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D= =3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D >=20 >> fiber_call_impl(first); >> } >>=20 >> @@ -1044,6 +1082,107 @@ fiber_destroy_all(struct cord *cord)> +bool >> +fiber_top_is_enabled() >> +{ >> + return fiber_top_enabled; >> +} >> + >> +inline void >> +fiber_top_enable() >=20 > 6. Please, add 'static' modifier. Looks like > this function is used inside this file only. > The same for fiber_top_disable(). It=E2=80=99s used in lua fiber module. >=20 >> +{ >> + if (!fiber_top_enabled) { >> + ev_prepare_start(cord()->loop, &cord()->prepare_event); >> + ev_check_start(cord()->loop, &cord()->check_event); >> + fiber_top_enabled =3D true; >> + >> + cord()->clock_acc =3D 0; >> + cord()->cpu_miss_count_last =3D 0; >> + cord()->clock_delta_last =3D 0; >> + } >> +} >> @@ -1077,6 +1216,14 @@ cord_create(struct cord *cord, const char = *name) >> ev_async_init(&cord->wakeup_event, fiber_schedule_wakeup); >>=20 >> ev_idle_init(&cord->idle_event, fiber_schedule_idle); >> + >> +#if ENABLE_FIBER_TOP >> + /* fiber.top() currently works only for the main thread. */ >> + if (cord_is_main()) { >> + fiber_top_init(); >> + fiber_top_enable(); >=20 > 7. I think, we need to enable top by default only > when we are sure that it does not affect performance. Ok, disabled it by default. User can turn it on with fiber.top_enable(). This also resolved the issue I had with your swim test. Looking at perf difference, maybe we can turn it on by default? >=20 >> + } >> +#endif /* ENABLE_FIBER_TOP */ >> cord_set_name(name); >>=20 >> #if ENABLE_ASAN >> diff --git a/src/lua/fiber.c b/src/lua/fiber.c >> index 336be60a2..2adff1536 100644 >> --- a/src/lua/fiber.c >> +++ b/src/lua/fiber.c >> @@ -319,6 +319,61 @@ lbox_fiber_statof_nobt(struct fiber *f, void = *cb_ctx) >> + >> +static int >> +lbox_fiber_top(struct lua_State *L) >> +{ >> + if (!fiber_top_is_enabled()) { >> + luaL_error(L, "fiber.top() is disabled. enable it with" >=20 > 8. 'enable' is a first word in the sentence. So probably > it is 'Enable=E2=80=99. Yep. Done. >=20 >> + " fiber.top_enable() first"); >> + } >> + lua_newtable(L); >> + lua_pushliteral(L, "cpu misses"); >> + lua_pushnumber(L, cord()->cpu_miss_count_last); >> + lua_settable(L, -3); >> + >> + lbox_fiber_top_entry(&cord()->sched, L); >> + fiber_stat(lbox_fiber_top_entry, L); >> + >> + return 1; >> +} >> diff --git a/test/app/fiber.result b/test/app/fiber.result >> index 3c6115a33..196fae3b7 100644 >> --- a/test/app/fiber.result >> +++ b/test/app/fiber.result >> @@ -1462,6 +1462,84 @@ fiber.join(fiber.self()) >> --- >> - error: the fiber is not joinable >> ... >> +sum =3D 0 >> +--- >> +... >> +-- gh-2694 fiber.top() >> +a =3D fiber.top() >> +--- >> +... >> +-- scheduler is present in fiber.top() >> +a[1] ~=3D nil >> +--- >> +- true >> +... >> +type(a["cpu misses"]) =3D=3D 'number' >> +--- >> +- true >> +... >> +sum_inst =3D 0 >> +--- >> +... >> +sum_avg =3D 0 >> +--- >> +... >> +test_run:cmd('setopt delimiter ";"') >=20 > 9. I would consider usage of '\' instead of a > delimiter change for such a short piece of > multiline code. But up to you. Just in case > you didn't know about '\', because I didn't > know either until recently. >=20 I didn=E2=80=99t know about =E2=80=98\=E2=80=99 as well. Thanks. Here=E2=80=99s the incremental diff: diff --git a/src/lib/core/fiber.c b/src/lib/core/fiber.c index bea49eb41..883fbac36 100644 --- a/src/lib/core/fiber.c +++ b/src/lib/core/fiber.c @@ -37,6 +37,7 @@ #include #include #include + #include "assoc.h" #include "memory.h" #include "trigger.h" @@ -1221,7 +1222,6 @@ cord_create(struct cord *cord, const char *name) /* fiber.top() currently works only for the main thread. */ if (cord_is_main()) { fiber_top_init(); - fiber_top_enable(); } #endif /* ENABLE_FIBER_TOP */ cord_set_name(name); diff --git a/src/lua/fiber.c b/src/lua/fiber.c index 62f3ccce4..c38bd886f 100644 --- a/src/lua/fiber.c +++ b/src/lua/fiber.c @@ -325,13 +325,18 @@ lbox_fiber_top_entry(struct fiber *f, void = *cb_ctx) { struct lua_State *L =3D (struct lua_State *) cb_ctx; =20 - lua_pushinteger(L, f->fid); + /* Index system fibers by name instead of id */ + if (f->fid <=3D FIBER_ID_MAX_RESERVED) { + lua_pushstring(L, f->name); + } else { + lua_pushinteger(L, f->fid); + } lua_newtable(L); =20 - lua_pushliteral(L, "cpu average (%)"); + lua_pushliteral(L, "average"); lua_pushnumber(L, f->clock_acc / (double)cord()->clock_acc * = 100); lua_settable(L, -3); - lua_pushliteral(L, "cpu instant (%)"); + lua_pushliteral(L, "instant"); lua_pushnumber(L, f->clock_delta_last / = (double)cord()->clock_delta_last * 100); lua_settable(L, -3); lua_settable(L, -3); @@ -343,7 +348,7 @@ static int lbox_fiber_top(struct lua_State *L) { if (!fiber_top_is_enabled()) { - luaL_error(L, "fiber.top() is disabled. enable it with" + luaL_error(L, "fiber.top() is disabled. Enable it with" " fiber.top_enable() first"); } lua_newtable(L); diff --git a/test/app/fiber.result b/test/app/fiber.result index 196fae3b7..e45cd7639 100644 --- a/test/app/fiber.result +++ b/test/app/fiber.result @@ -1466,11 +1466,19 @@ sum =3D 0 --- ... -- gh-2694 fiber.top() +fiber.top_enable() +--- +... a =3D fiber.top() --- ... +type(a) +--- +- table +... -- scheduler is present in fiber.top() -a[1] ~=3D nil +-- and is indexed by name +a["sched"] ~=3D nil --- - true ... @@ -1484,21 +1492,19 @@ sum_inst =3D 0 sum_avg =3D 0 --- ... -test_run:cmd('setopt delimiter ";"') ---- -- true -... -for k, v in pairs(a) do - if type(v) =3D=3D 'table' then - sum_inst =3D sum_inst + v["cpu instant (%)"] - sum_avg =3D sum_avg + v["cpu average (%)"] - end -end; +-- update table to make sure +-- a full event loop iteration +-- has ended +a =3D fiber.top() --- ... -test_run:cmd('setopt delimiter ""'); +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\ +end --- -- true ... sum_inst --- @@ -1518,11 +1524,11 @@ f =3D fiber.new(function() for i =3D 1,1000 do = end fiber.yield() tbl =3D fiber.top()[f while f:status() ~=3D 'dead' do fiber.sleep(0.01) end --- ... -tbl["cpu average (%)"] > 0 +tbl["average"] > 0 --- - true ... -tbl["cpu instant (%)"] > 0 +tbl["instant"] > 0 --- - true ... @@ -1531,14 +1537,7 @@ fiber.top_disable() ... fiber.top() --- -- error: fiber.top() is disabled. enable it with fiber.top_enable() = first -... -fiber.top_enable() ---- -... -type(fiber.top()) ---- -- table +- error: fiber.top() is disabled. Enable it with fiber.top_enable() = first ... -- cleanup test_run:cmd("clear filter") diff --git a/test/app/fiber.test.lua b/test/app/fiber.test.lua index 15507c2c7..e30aba77e 100644 --- a/test/app/fiber.test.lua +++ b/test/app/fiber.test.lua @@ -632,33 +632,39 @@ fiber.join(fiber.self()) sum =3D 0 =20 -- gh-2694 fiber.top() +fiber.top_enable() + a =3D fiber.top() +type(a) -- scheduler is present in fiber.top() -a[1] ~=3D nil +-- and is indexed by name +a["sched"] ~=3D nil type(a["cpu misses"]) =3D=3D 'number' sum_inst =3D 0 sum_avg =3D 0 -test_run:cmd('setopt delimiter ";"') -for k, v in pairs(a) do - if type(v) =3D=3D 'table' then - sum_inst =3D sum_inst + v["cpu instant (%)"] - sum_avg =3D sum_avg + v["cpu average (%)"] - end -end; -test_run:cmd('setopt delimiter ""'); + +-- 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\ + sum_inst =3D sum_inst + v["instant"]\ + sum_avg =3D sum_avg + v["average"]\ + end\ +end + sum_inst -- not exact due to accumulated integer division errors sum_avg > 99 and sum_avg < 101 or sum_avg tbl =3D nil f =3D fiber.new(function() for i =3D 1,1000 do end fiber.yield() tbl =3D = fiber.top()[fiber.self().id()] end) while f:status() ~=3D 'dead' do fiber.sleep(0.01) end -tbl["cpu average (%)"] > 0 -tbl["cpu instant (%)"] > 0 +tbl["average"] > 0 +tbl["instant"] > 0 =20 fiber.top_disable() fiber.top() -fiber.top_enable() -type(fiber.top()) =20 -- cleanup test_run:cmd("clear filter") -- Serge Petrenko sergepetrenko@tarantool.org --Apple-Mail=_EE59F4D1-B725-4C74-AE25-12D32DF66656 Content-Transfer-Encoding: quoted-printable Content-Type: text/html; charset=utf-8
Hi! Thank you for review!
I addressed your comments and answered inline.
Incremental diff is below.

23 = =D0=BE=D0=BA=D1=82. 2019 =D0=B3., =D0=B2 0:18, Vladislav Shpilevoy = <v.shpilevoy@tarantool.org> = =D0=BD=D0=B0=D0=BF=D0=B8=D1=81=D0=B0=D0=BB(=D0=B0):

Thanks= for the patch!

Sorry, the version in the = email is a bit outdated. I
pasted below the actual version = from the branch.

See 9 comments below.

   lua: add fiber.top() listing fiber cpu = consumption

   Implement a = new function in Lua fiber library: top(). It returns a table
   of alive fibers (including the scheduler). = Each table entry has two
   fields: = average cpu consumption, which is calculated with exponential
   moving average over event loop iterations, = and current cpu consumption,
   which = shows fiber's cpu usage over the last event loop iteration.
=    The patch relies on CPU timestamp counter to measure = each fiber's time
   share.

   Closes #2694

   @TarantoolBot document
   Title: fiber: new function `fiber.top()`

   `fiber.top()` returns a table of all alive fibers and = lists their cpu
   consumption. Let's take = a look at the example:
   ```
=    tarantool> fiber.top()
   ---
   - 1:
=        cpu average (%): = 10.779696493982
=        cpu instant (%): = 10.435256168573

1. Have you = considered making these option names
one word? 'cpu = average (%)' -> 'average'. The
same for instant. My = motivation is that it could
simplify wrappers which are = going to use the top
to show it in a GUI or something. You = actually use
it in the tests.

It would not hard readability IMO. It is obvious
that top is in percents, and about CPU time.

No = problem.


     115:
       cpu average (%): = 5.4571279061075
=        cpu instant (%): = 5.9653973440576
     120:
       cpu average (%): = 21.944382148464
=        cpu instant (%): = 23.849021825646
     116:
       cpu average (%): = 8.6603872318158
=        cpu instant (%): = 9.6812031335093
     119:
       cpu average (%): = 21.933168871944
=        cpu instant (%): = 20.007540530351
     cpu misses: = 0
     118:
=        cpu average (%): = 19.342901995963
=        cpu instant (%): = 16.932679820703
     117:
       cpu average (%): = 11.549674814981
=        cpu instant (%): = 13.128901177161
   ...
=    ```

2. This = is super cool!

Could we give names to = predefined fibers? For
example, make an alias = top.scheduler =3D top[1].

So as in the = console output I would see:

=    ---
   - scheduler:
       cpu average (%): = 98.230148883023
=        cpu instant (%): 100

Instead of '1'. Because personally I didn't
even know that 1 is always the scheduler, and
I = would be confused to see a regular fiber
consumed 99% of = time in a console.

Hmm, what about this?

--- a/src/lua/fiber.c
+++ = b/src/lua/fiber.c
@@ -325,13 +325,18 = @@ lbox_fiber_top_entry(struct fiber *f, void *cb_ctx)
 {
        struct = lua_State *L =3D (struct lua_State *) cb_ctx;
 
-       lua_pushinteger(L, = f->fid);
+       /* Index = system fibers by name instead of id */
+   =     if (f->fid <=3D FIBER_ID_MAX_RESERVED) {
+             =   lua_pushstring(L, f->name);
+   =     } else {
+       =         lua_pushinteger(L, f->fid);
+       }
  =       lua_newtable(L);



   In the table above keys are fiber id's = (and a single 'cpu misses' key
   which = indicates the amount of times tx thread was rescheduled on a
   different cpu core. More on that = later).
   The two metrics available for = each fiber are:
   1) cpu instant (per = cent),
   which indicates the share of = time fiber was executing during the
=    previous event loop iteration
=    2) cpu average (per cent), which is calculated as an = exponential moving
   average of `cpu = instant` values over all previous event loop iterations.
   More info on `cpu misses` field returned = by `fiber.top()`:
   `cpu misses` indicates the amount of times = tx thread detected it was
   rescheduled = on a different cpu core during the last event loop
=    iteration.
   fiber.top() uses cpu timestamp = counter to measure each fiber's execution
=    time. However, each cpu core may have its own counter = value (you can
   only rely on counter = deltas if both measurements were taken on the same
=    core, otherwise the delta may even get negative).
   When tx thread is rescheduled to a = different cpu core, tarantool just
=    assumes cpu delta was zero for the lust measurement. = This loweres
   precision of our = computations, so the bigger `cpu misses` value the
=    lower the precision of fiber.top() results.

=    Fiber.top() = doesn't work on arm architecture at the moment.

2. Have you done benchmarks how = much top slows down fiber
switching? It should not be hard = to measure. Just switching.
Lots of fibers which only = yield. And measure loop iterations
per second. Won't work? = Or average/median duration of one
loop iteration.

Hi! I = tested context switches per second.
The results are in the = issue comments:
https://github.com/tarantool/tarantool/issues/2694#issuecomment= -546381304
Performance degradation = is between 10 and 16 per cent.


diff --git a/src/lib/core/fiber.c b/src/lib/core/fiber.c
index b813c1739..bea49eb41 100644
--- = a/src/lib/core/fiber.c
+++ b/src/lib/core/fiber.c
@@ -37,11 +37,14 @@
#include = <stdlib.h>
#include <string.h>
= #include <pmatomic.h>
-
#include = "assoc.h"

3. Sorry, looks like = stray diff. Could you
please drop it?


Thanks = for noticing! Fixed.

#include "memory.h"
#include "trigger.h"
@@ -82,6 +85,34 @@ static int (*fiber_invoke)(fiber_func f, = va_list ap);
err; \
})

+#if ENABLE_FIBER_TOP
+/**
+ * An action performed each time a context switch = happens.
+ * Used to count each fiber's processing = time.
+ * This is a macro rather than a function, since it = is used
+ * in scheduler too.
4. Hm. Not sure if I understand. Ok, it is used in the = scheduler,
so why does it prevent making it a function? = Caller is always
struct fiber *, so you can make it a = function taking fiber *
parameter, can't you?

You = cannot call functions from scheduler cos it doesn=E2=80=99t have = a
stack AFAIU. I can make it an inline function if you want me = to.


+ */
+#define clock_set_on_csw(caller) \
+({ = = = = = = = = = \
+ 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; = = = = = \
+})> @@ -584,6 +617,7 @@ = fiber_schedule_list(struct rlist *list)
}
= last->caller =3D fiber();
= assert(fiber() =3D=3D &cord()->sched);
+ = clock_set_on_csw(fiber());

5. Am I right, that we need to update CPU consumption each
time a context switch happens? =

Yep.

If so, then by logic you
would need to call = clock_set_on_csw() on each fiber->csw++,
correct?

Right. I = also call clock_set_on_csw() on each event loop = iteration
end.


Currently that happens in 2 places: fiber_call_impl() and
fiber_yield(). In both these places you already call
clock_set_on_csw():

=    - You always call clock_set_on_csw() right before
     fiber_call_impl();

   - You call = clock_set_on_csw() in fiber_yield().

I = would then move fiber->cws++ logic into your macros too.
So all the context switch and CPU time tracking logic
would be in one place.

The only = problem is that your macros takes caller, but csw++
is = done for callee. Probably we could increment it for the
caller instead, I don't anything depends on that.

Also it would lead to increment of the = scheduler's csw
counter. Not sure whether it is ok.

Loop = iteration end isn=E2=80=99t a context switch, but I still = update
clocks here. I don=E2=80=99t want to increment csw here = as a side
effect, so maybe leave csw increment as it = is?


Like that (I didn't test = it):

=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D= =3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D= =3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D

diff --git a/src/lib/core/fiber.c b/src/lib/core/fiber.c
index bea49eb41..e9aac99d0 100644
--- = a/src/lib/core/fiber.c
+++ b/src/lib/core/fiber.c
@@ -105,6 +105,7 @@ static int (*fiber_invoke)(fiber_func f, = va_list ap);
cord()->cpu_id_last =3D = cpu_id; = = = = \
cord()->cpu_miss_count++; \
= } = = = = = = = = \
+ caller->csw++; \
= cord()->clock_last =3D clock; \
})

@@ -258,7 +259,7 @@ fiber_call_impl(struct = fiber *callee)
cord->fiber =3D callee;

callee->flags &=3D = ~FIBER_IS_READY;
- callee->csw++;
+ = clock_set_on_csw(caller);
= ASAN_START_SWITCH_FIBER(asan_state, 1,
= callee->stack,
callee->stack_size);
@@ -277,7 +278,6 @@ fiber_call(struct fiber *callee)
= /** By convention, these triggers must not throw. */
= = if (! rlist_empty(&caller->on_yield))
= trigger_run(&caller->on_yield, NULL);
- = clock_set_on_csw(caller);
= callee->caller =3D caller;
= callee->flags |=3D FIBER_IS_READY;
= caller->flags |=3D FIBER_IS_READY;
@@ -511,7 = +511,6 @@ fiber_yield(void)
assert(callee->flags & = FIBER_IS_READY || callee =3D=3D &cord->sched);
= = assert(! (callee->flags & FIBER_IS_DEAD));
= = cord->fiber =3D callee;
- = callee->csw++;
callee->flags &=3D = ~FIBER_IS_READY;
= ASAN_START_SWITCH_FIBER(asan_state,
= (caller->flags & FIBER_IS_DEAD) =3D=3D 0,
@@ = -617,7 +616,6 @@ fiber_schedule_list(struct rlist *list)
= = }
last->caller =3D fiber();
= assert(fiber() =3D=3D &cord()->sched);
- = clock_set_on_csw(fiber());
= fiber_call_impl(first);
}

=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D= =3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D= =3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D

= fiber_call_impl(first);
}

@@ -1044,6 +1082,107 @@ fiber_destroy_all(struct cord = *cord)> +bool
+fiber_top_is_enabled()
+{+ = return fiber_top_enabled;
+}
+
+inline void
+fiber_top_enable()

6. Please, add 'static' modifier. = Looks like
this function is used inside this file only.
The same for fiber_top_disable().

It=E2=80=99s= used in lua fiber module.


+{
+ if = (!fiber_top_enabled) {
+ ev_prepare_start(cord()->loop, = &cord()->prepare_event);
+ = ev_check_start(cord()->loop, &cord()->check_event);
+ = = fiber_top_enabled =3D true;
+
+ = cord()->clock_acc =3D 0;
+ = cord()->cpu_miss_count_last =3D 0;
+ = cord()->clock_delta_last =3D 0;
+ }
+}
@@ -1077,6 +1216,14 @@ cord_create(struct = cord *cord, const char *name)
= ev_async_init(&cord->wakeup_event, = fiber_schedule_wakeup);

= ev_idle_init(&cord->idle_event, fiber_schedule_idle);
+
+#if ENABLE_FIBER_TOP
+ /* fiber.top() currently works = only for the main thread. */
+ if (cord_is_main()) {
+ = = fiber_top_init();
+ fiber_top_enable();

7. I think, we need to enable top = by default only
when we are sure that it does not affect = performance.

Ok, disabled it by default. User can turn it on = with
fiber.top_enable(). This also resolved the issue I = had
with your swim test.

Looking at perf difference, maybe we can turn it = on by default?


+ }
+#endif /* = ENABLE_FIBER_TOP */
cord_set_name(name);

#if ENABLE_ASAN
diff --git = a/src/lua/fiber.c b/src/lua/fiber.c
index = 336be60a2..2adff1536 100644
--- a/src/lua/fiber.c
+++ b/src/lua/fiber.c
@@ -319,6 +319,61 @@ = lbox_fiber_statof_nobt(struct fiber *f, void *cb_ctx)
+
+static int
+lbox_fiber_top(struct lua_State = *L)
+{
+ if (!fiber_top_is_enabled()) {
+ = = luaL_error(L, "fiber.top() is disabled. enable it with"

8. 'enable' is a first word in = the sentence. So probably
it is 'Enable=E2=80=99.

Yep. = Done.


+ = = =      " fiber.top_enable() first");
+ = }
+ lua_newtable(L);
+ = lua_pushliteral(L, "cpu misses");
+ = lua_pushnumber(L, cord()->cpu_miss_count_last);
+ = lua_settable(L, -3);
+
+ = lbox_fiber_top_entry(&cord()->sched, L);
+ = fiber_stat(lbox_fiber_top_entry, L);
+
+ = return 1;
+}
diff --git = a/test/app/fiber.result b/test/app/fiber.result
index = 3c6115a33..196fae3b7 100644
--- a/test/app/fiber.result
+++ b/test/app/fiber.result
@@ -1462,6 +1462,84 = @@ fiber.join(fiber.self())
---
- error: = the fiber is not joinable
...
+sum =3D 0
+---
+...
+-- gh-2694 fiber.top()
+a =3D = fiber.top()
+---
+...
+-- scheduler is = present in fiber.top()
+a[1] ~=3D nil
+---
+- true
+...
+type(a["cpu misses"]) =3D=3D 'number'
+---
+- true
+...
+sum_inst =3D 0
+---
+...
+sum_avg =3D 0
+---
+...
+test_run:cmd('setopt delimiter ";"')

9. I would consider usage of '\' = instead of a
delimiter change for such a short piece of
multiline code. But up to you. Just in case
you = didn't know about '\', because I didn't
know either until = recently.


I didn=E2=80=99t know = about =E2=80=98\=E2=80=99 as well. Thanks.


Here=E2=80=99s the incremental diff:

diff --git a/src/lib/core/fiber.c = b/src/lib/core/fiber.c
index bea49eb41..883fbac36 = 100644
--- a/src/lib/core/fiber.c
+++ = b/src/lib/core/fiber.c
@@ -37,6 +37,7 @@
 #include <stdlib.h>
 #include = <string.h>
 #include <pmatomic.h>
+
 #include "assoc.h"
 #include "memory.h"
 #include = "trigger.h"
@@ -1221,7 +1222,6 @@ cord_create(struct cord = *cord, const char *name)
  /* fiber.top() currently works = only for the main thread. */
  if = (cord_is_main()) {
  fiber_top_init();
- = fiber_top_enable();
  }
 #endif /* ENABLE_FIBER_TOP */
  = cord_set_name(name);
diff --git a/src/lua/fiber.c = b/src/lua/fiber.c
index 62f3ccce4..c38bd886f 100644
--- a/src/lua/fiber.c
+++ b/src/lua/fiber.c
@@ -325,13 +325,18 @@ lbox_fiber_top_entry(struct fiber *f, = void *cb_ctx)
 {
  struct = lua_State *L =3D (struct lua_State *) cb_ctx;
 
- = lua_pushinteger(L, f->fid);
+ /* Index = system fibers by name instead of id */
+ if = (f->fid <=3D FIBER_ID_MAX_RESERVED) {
+ = lua_pushstring(L, f->name);
+ } else = {
+= lua_pushinteger(L, f->fid);
+ }
 = lua_newtable(L);
 
- = lua_pushliteral(L, "cpu average (%)");
+ = lua_pushliteral(L, "average");
  = lua_pushnumber(L, f->clock_acc / (double)cord()->clock_acc = * 100);
  lua_settable(L, -3);
- = lua_pushliteral(L, "cpu instant (%)");
+ = lua_pushliteral(L, "instant");
  = lua_pushnumber(L, f->clock_delta_last / = (double)cord()->clock_delta_last * 100);
  = lua_settable(L, -3);
  = lua_settable(L, -3);
@@ -343,7 +348,7 @@ static = int
 lbox_fiber_top(struct lua_State *L)
 {
  if (!fiber_top_is_enabled()) {
- = luaL_error(L, "fiber.top() is disabled. enable it with"
+ = luaL_error(L, "fiber.top() is disabled. Enable it with"
 =       " = fiber.top_enable() first");
  }
 = lua_newtable(L);
diff --git = a/test/app/fiber.result b/test/app/fiber.result
index = 196fae3b7..e45cd7639 100644
--- a/test/app/fiber.result
+++ b/test/app/fiber.result
@@ -1466,11 = +1466,19 @@ sum =3D 0
 ---
 ...
 -- gh-2694 fiber.top()
+fiber.top_enable()
+---
+...
 a =3D fiber.top()
 ---
 ...
+type(a)
+---
+- table
+...
 -- scheduler is present in fiber.top()
-a[1] ~=3D nil
+-- = and is indexed by name
+a["sched"] ~=3D nil
 ---
 - true
 ...@@ -1484,21 +1492,19 @@ sum_inst =3D 0
 sum_avg =3D 0
 ---
 ...
-test_run:cmd('setopt delimiter = ";"')
----
-- true
-...
-for k, v in pairs(a) do
-    if = type(v) =3D=3D 'table' then
-      =   sum_inst =3D sum_inst + v["cpu instant (%)"]
-        sum_avg =3D sum_avg + = v["cpu average (%)"]
-    end
-end;
+-- update table to make sure
+-- a full event loop iteration
+-- has = ended
+a =3D fiber.top()
 ---
 ...
-test_run:cmd('setopt delimiter = ""');
+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\
+end ---
-- true
 ...
 sum_inst
 ---
@@ = -1518,11 +1524,11 @@ f =3D fiber.new(function() for i =3D 1,1000 do end = fiber.yield() tbl =3D fiber.top()[f
 while f:status() ~=3D = 'dead' do fiber.sleep(0.01) end
 ---
 ...
-tbl["cpu average (%)"] > 0
+tbl["average"] > 0
 ---
 - true
 ...
-tbl["cpu = instant (%)"] > 0
+tbl["instant"] > 0
 ---
 - true
 ...@@ -1531,14 +1537,7 @@ fiber.top_disable()
 ...
 fiber.top()
 ---
-- = error: fiber.top() is = disabled. enable it with fiber.top_enable() first
-...
-fiber.top_enable()
----
-...
-type(fiber.top())
----
-- table
+- error: fiber.top() is disabled. Enable it with = fiber.top_enable() first
 ...
 -- = cleanup
 test_run:cmd("clear filter")
diff --git a/test/app/fiber.test.lua = b/test/app/fiber.test.lua
index 15507c2c7..e30aba77e = 100644
--- a/test/app/fiber.test.lua
+++ = b/test/app/fiber.test.lua
@@ -632,33 +632,39 @@ = fiber.join(fiber.self())
 sum =3D 0
 
 -- gh-2694 fiber.top()
+fiber.top_enable()
+
 a =3D = fiber.top()
+type(a)
 -- scheduler is present in fiber.top()
-a[1] = ~=3D nil
+-- and is indexed by name
+a["sched"] ~=3D nil
 type(a["cpu = misses"]) =3D=3D 'number'
 sum_inst =3D 0
 sum_avg =3D 0
-test_run:cmd('setopt = delimiter ";"')
-for k, v in pairs(a) do
-    if type(v) =3D=3D 'table' then
-        sum_inst =3D sum_inst + = v["cpu instant (%)"]
-      =   sum_avg =3D sum_avg + v["cpu average (%)"]
-    end
-end;
-test_run:cmd('setopt delimiter ""');
+
+-- 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\
+        sum_inst =3D= sum_inst + v["instant"]\
+      =   sum_avg =3D sum_avg + v["average"]\
+  =   end\
+end
+
 sum_inst
 -- not exact due to = accumulated integer division errors
 sum_avg > 99 = and sum_avg < 101 or sum_avg
 tbl =3D nil
 f =3D fiber.new(function() for i =3D 1,1000 do end = fiber.yield() tbl =3D fiber.top()[fiber.self().id()] end)
 while f:status() ~=3D 'dead' do fiber.sleep(0.01) = end
-tbl["cpu average (%)"] > 0
-tbl["cpu = instant (%)"] > 0
+tbl["average"] > 0
+tbl["instant"] > 0
 
 fiber.top_disable()
 fiber.top()
-fiber.top_enable()
-type(fiber.top())
 
 -- cleanup
 test_run:cmd("clear filter")

= --Apple-Mail=_EE59F4D1-B725-4C74-AE25-12D32DF66656--