From mboxrd@z Thu Jan 1 00:00:00 1970 Return-Path: Received: from smtp40.i.mail.ru (smtp40.i.mail.ru [94.100.177.100]) (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 19CD7440F3C for ; Mon, 18 Nov 2019 19:11:23 +0300 (MSK) From: Serge Petrenko Message-Id: Content-Type: multipart/alternative; boundary="Apple-Mail=_7A0179D1-0FCB-45C5-9DA4-AF34F031F104" Mime-Version: 1.0 (Mac OS X Mail 12.4 \(3445.104.11\)) Date: Mon, 18 Nov 2019 19:11:22 +0300 In-Reply-To: <61341332-a57f-1ac1-506b-181cafd38154@tarantool.org> References: <61341332-a57f-1ac1-506b-181cafd38154@tarantool.org> Subject: Re: [Tarantool-patches] [PATCH v2 1/2] fiber: reset clock stats on fiber.top_enable() List-Id: Tarantool development patches List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , To: Vladislav Shpilevoy Cc: tarantool-patches@dev.tarantool.org --Apple-Mail=_7A0179D1-0FCB-45C5-9DA4-AF34F031F104 Content-Transfer-Encoding: quoted-printable Content-Type: text/plain; charset=utf-8 Hi! Thankyou for reviewing this. I=E2=80=99ve managed to finally find the cause of test failures. It is fixed in the second patch of the newly sent series. I addressed your comments and resent v3. -- Serge Petrenko sergepetrenko@tarantool.org > 16 =D0=BD=D0=BE=D1=8F=D0=B1. 2019 =D0=B3., =D0=B2 0:39, Vladislav = Shpilevoy =D0=BD=D0=B0=D0=BF=D0=B8=D1=81=D0=B0= =D0=BB(=D0=B0): >=20 > Hi! Thanks for the fixes! >=20 > See 2 comments below. >=20 > On 15/11/2019 15:58, Serge Petrenko wrote: >> We didn't refresh last remembered clock on fiber.top_enable() >> This means that the fiber issuing fiber.top_enable() would get a huge >> chunk of cpu time on its first yield. Fix this. >> Also reset clock_delta and cpu_miss_count. >>=20 >> If fiber.top() is issued on the same ev loop iteration as >> fiber.top_enable(), clock_delta_last is 0 for both cord and all the >> fibers, so report "instant" and "average" stats per last iteration as = 0 >> instead of NaN. >>=20 >> Follow-up #2694 >> --- >> src/lib/core/fiber.c | 21 +++++++++++++++++++++ >> src/lua/fiber.c | 12 ++++++++++-- >> 2 files changed, 31 insertions(+), 2 deletions(-) >>=20 >> diff --git a/src/lib/core/fiber.c b/src/lib/core/fiber.c >> index aebaba7f0..258c094f5 100644 >> --- a/src/lib/core/fiber.c >> +++ b/src/lib/core/fiber.c >> @@ -1203,9 +1203,30 @@ fiber_top_enable() >> ev_check_start(cord()->loop, &cord()->check_event); >> fiber_top_enabled =3D true; >>=20 >> + /* >> + * Reset cord and fiber clock stats in order to >> + * count from zero even on reenable. >> + */ >> cord()->clock_acc =3D 0; >> cord()->cpu_miss_count_last =3D 0; >> cord()->clock_delta_last =3D 0; >> + cord()->clock_delta =3D 0; >> + >> + struct fiber * fiber; >> + rlist_foreach_entry(fiber, &cord()->alive, link) { >> + fiber->clock_acc =3D 0; >> + fiber->clock_delta_last =3D 0; >> + fiber->clock_delta =3D 0; >> + fiber->cputime =3D 0; >=20 > 1. fiber_reset() should do exactly the same, right? > Then why doesn't it nullify clock_delta_last? I just didn=E2=80=99t notice that, sorry. >=20 > This mess with numerous time fields, and their reset, > looks like a necessity to create a new structure, > which would be included into cord and fiber structures. > And which would provide methods for cleaning and > updating the members. Done. >=20 >> + } >> + >> + cord()->sched.clock_acc =3D 0; >> + cord()->sched.clock_delta_last =3D 0; >> + cord()->sched.clock_delta =3D 0; >> + cord()->sched.cputime =3D 0; >> + >> + cord()->clock_last =3D __rdtscp(&cord()->cpu_id_last); >> + cord()->cpu_miss_count =3D 0; >> struct timespec ts; >> if (clock_gettime(CLOCK_THREAD_CPUTIME_ID, &ts) !=3D 0) = { >> say_debug("clock_gettime(): failed to get this" >> diff --git a/src/lua/fiber.c b/src/lua/fiber.c >> index 8b3b22e55..647505643 100644 >> --- a/src/lua/fiber.c >> +++ b/src/lua/fiber.c >> @@ -335,11 +335,19 @@ lbox_fiber_top_entry(struct fiber *f, void = *cb_ctx) >> lua_newtable(L); >>=20 >> lua_pushliteral(L, "average"); >> - lua_pushnumber(L, f->clock_acc / (double)cord()->clock_acc * = 100); >> + if (cord()->clock_acc) >=20 > 2. Sorry for a nit, we usually compare with 0 > explicitly, '!=3D 0', and avoid implicit casts. No problem. Fixed. >=20 >> + lua_pushnumber(L, f->clock_acc / = (double)cord()->clock_acc * 100); >> + else >> + lua_pushnumber(L, 0); >> lua_settable(L, -3); >> + >> lua_pushliteral(L, "instant"); >> - lua_pushnumber(L, f->clock_delta_last / = (double)cord()->clock_delta_last * 100); >> + if (cord()->clock_delta_last) >> + lua_pushnumber(L, f->clock_delta_last / = (double)cord()->clock_delta_last * 100); >> + else >> + lua_pushnumber(L, 0); >> lua_settable(L, -3); >> + >> lua_pushliteral(L, "time"); >> lua_pushnumber(L, f->cputime / (double) FIBER_TIME_RES); >> lua_settable(L, -3); --Apple-Mail=_7A0179D1-0FCB-45C5-9DA4-AF34F031F104 Content-Transfer-Encoding: quoted-printable Content-Type: text/html; charset=utf-8 Hi! = Thankyou for reviewing this.

I=E2=80=99ve managed to finally find the cause of test = failures.
It is fixed in the second patch of the = newly sent series.
I addressed your comments and = resent v3.




16 =D0=BD=D0=BE=D1=8F=D0=B1. 2019 =D0=B3., =D0=B2 0:39, = 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 = fixes!

See 2 = comments below.

On 15/11/2019 15:58, Serge Petrenko wrote:
We = didn't refresh last remembered clock on fiber.top_enable()
This means that the fiber issuing fiber.top_enable() would = get a huge
chunk of cpu time on its first yield. Fix = this.
Also reset clock_delta and cpu_miss_count.

If fiber.top() is issued on the same ev loop iteration as
fiber.top_enable(), clock_delta_last is 0 for both cord and = all the
fibers, so report "instant" and "average" stats = per last iteration as 0
instead of NaN.

Follow-up #2694
---
src/lib/core/fiber.c | 21 +++++++++++++++++++++
src/lua/fiber.c      | 12 = ++++++++++--
2 files changed, 31 insertions(+), 2 = deletions(-)

diff --git = a/src/lib/core/fiber.c b/src/lib/core/fiber.c
index = aebaba7f0..258c094f5 100644
--- a/src/lib/core/fiber.c
+++ b/src/lib/core/fiber.c
@@ -1203,9 +1203,30 = @@ fiber_top_enable()
ev_check_start(cord()->loop, = &cord()->check_event);
fiber_top_enabled =3D true;

+ /*
+  * Reset cord and fiber = clock stats in order to
+  * count from zero even on = reenable.
+  */
= cord()->clock_acc =3D 0;
= cord()->cpu_miss_count_last =3D 0;
= cord()->clock_delta_last =3D 0;
+ = cord()->clock_delta =3D 0;
+
+ struct = fiber * fiber;
+ rlist_foreach_entry(fiber, = &cord()->alive, link) {
+ = fiber->clock_acc =3D 0;
+ = fiber->clock_delta_last =3D 0;
+ = fiber->clock_delta =3D 0;
+ = fiber->cputime =3D 0;

1. fiber_reset() should do = exactly the same, right?
Then why doesn't it nullify clock_delta_last?

I just = didn=E2=80=99t notice that, sorry.


This mess with numerous time fields, and their = reset,
looks like a = necessity to create a new structure,
which would be included into cord and fiber = structures.
And which = would provide methods for cleaning and
updating the members.

Done.


+ }
+
+ = = cord()->sched.clock_acc =3D 0;
+ = cord()->sched.clock_delta_last =3D 0;
+ = cord()->sched.clock_delta =3D 0;
+ = cord()->sched.cputime =3D 0;
+
+ = = cord()->clock_last =3D = __rdtscp(&cord()->cpu_id_last);
+ = cord()->cpu_miss_count =3D 0;
struct = timespec ts;
if = (clock_gettime(CLOCK_THREAD_CPUTIME_ID, &ts) !=3D 0) {
= = = say_debug("clock_gettime(): failed to get this"
diff = --git a/src/lua/fiber.c b/src/lua/fiber.c
index = 8b3b22e55..647505643 100644
--- a/src/lua/fiber.c
+++ b/src/lua/fiber.c
@@ -335,11 +335,19 @@ = lbox_fiber_top_entry(struct fiber *f, void *cb_ctx)
= lua_newtable(L);

= lua_pushliteral(L, "average");
- = lua_pushnumber(L, f->clock_acc / (double)cord()->clock_acc = * 100);
+ if (cord()->clock_acc)

2. Sorry for a nit, we usually compare with 0
explicitly, '!=3D 0', and avoid = implicit casts.

No problem. Fixed.


+ lua_pushnumber(L, f->clock_acc = / (double)cord()->clock_acc * 100);
+ else
+ = = lua_pushnumber(L, 0);
lua_settable(L, -3);
+
lua_pushliteral(L, "instant");
- = lua_pushnumber(L, f->clock_delta_last / = (double)cord()->clock_delta_last * 100);
+ if = (cord()->clock_delta_last)
+ = lua_pushnumber(L, f->clock_delta_last / = (double)cord()->clock_delta_last * 100);
+ else
+ = = lua_pushnumber(L, 0);
lua_settable(L, -3);
+
lua_pushliteral(L, "time");
= lua_pushnumber(L, f->cputime / (double) FIBER_TIME_RES);
= lua_settable(L, -3);

= --Apple-Mail=_7A0179D1-0FCB-45C5-9DA4-AF34F031F104--