From 5a45d2917cd14bf5eab690453e8a191549de4c2c Mon Sep 17 00:00:00 2001 From: Rickard Green Date: Fri, 1 Sep 2017 17:17:34 +0200 Subject: [PATCH] Bug fixes of statistics(wall_clock) and statistics(runtime) --- erts/configure.in | 2 + erts/emulator/beam/erl_bif_info.c | 5 +- erts/emulator/beam/erl_lock_check.c | 2 +- erts/emulator/beam/erl_time.h | 7 ++ erts/emulator/beam/erl_time_sup.c | 145 +++++++++++++++++------- erts/emulator/beam/sys.h | 4 - erts/emulator/sys/unix/erl_unix_sys.h | 4 + erts/emulator/test/statistics_SUITE.erl | 34 +++++- 8 files changed, 150 insertions(+), 53 deletions(-) diff --git a/erts/configure.in b/erts/configure.in index 830e3d777622..f25f5b6bcfee 100644 --- a/erts/configure.in +++ b/erts/configure.in @@ -1784,6 +1784,8 @@ AC_CHECK_HEADER(sys/resource.h, [#include ])], [],[]) +AC_CHECK_FUNCS([getrusage]) + dnl Check if we have kernel poll support have_kernel_poll=no AC_CHECK_HEADER(sys/event.h, have_kernel_poll=kqueue) diff --git a/erts/emulator/beam/erl_bif_info.c b/erts/emulator/beam/erl_bif_info.c index 96f9b284b3fe..62302ca51915 100644 --- a/erts/emulator/beam/erl_bif_info.c +++ b/erts/emulator/beam/erl_bif_info.c @@ -48,6 +48,7 @@ #include "erl_map.h" #define ERTS_PTAB_WANT_DEBUG_FUNCS__ #include "erl_ptab.h" +#include "erl_time.h" #ifdef HIPE #include "hipe_arch.h" #endif @@ -3547,7 +3548,7 @@ BIF_RETTYPE statistics_1(BIF_ALIST_1) ErtsMonotonicTime u1, u2; Eterm b1, b2; Uint hsz; - elapsed_time_both(&u1, NULL, &u2, NULL); + erts_runtime_elapsed_both(&u1, NULL, &u2, NULL); hsz = 3; /* 2-tuple */ (void) erts_bld_monotonic_time(NULL, &hsz, u1); (void) erts_bld_monotonic_time(NULL, &hsz, u2); @@ -3563,7 +3564,7 @@ BIF_RETTYPE statistics_1(BIF_ALIST_1) ErtsMonotonicTime w1, w2; Eterm b1, b2; Uint hsz; - wall_clock_elapsed_time_both(&w1, &w2); + erts_wall_clock_elapsed_both(&w1, &w2); hsz = 3; /* 2-tuple */ (void) erts_bld_monotonic_time(NULL, &hsz, w1); (void) erts_bld_monotonic_time(NULL, &hsz, w2); diff --git a/erts/emulator/beam/erl_lock_check.c b/erts/emulator/beam/erl_lock_check.c index f270d8baefef..378f86f09788 100644 --- a/erts/emulator/beam/erl_lock_check.c +++ b/erts/emulator/beam/erl_lock_check.c @@ -169,9 +169,9 @@ static erts_lc_lock_order_t erts_lock_order[] = { { "xports_list_pre_alloc_lock", "address" }, { "inet_buffer_stack_lock", NULL }, { "system_block", NULL }, - { "timeofday", NULL }, { "get_time", NULL }, { "get_corrected_time", NULL }, + { "runtime", NULL }, { "breakpoints", NULL }, { "pollsets_lock", NULL }, { "pix_lock", "address" }, diff --git a/erts/emulator/beam/erl_time.h b/erts/emulator/beam/erl_time.h index ccc55266647c..27164d50a08c 100644 --- a/erts/emulator/beam/erl_time.h +++ b/erts/emulator/beam/erl_time.h @@ -130,6 +130,13 @@ Eterm erts_get_monotonic_end_time(struct process *c_p); Eterm erts_monotonic_time_source(struct process*c_p); Eterm erts_system_time_source(struct process*c_p); +void erts_runtime_elapsed_both(ErtsMonotonicTime *ms_user, + ErtsMonotonicTime *ms_sys, + ErtsMonotonicTime *ms_user_diff, + ErtsMonotonicTime *ms_sys_diff); +void erts_wall_clock_elapsed_both(ErtsMonotonicTime *total, + ErtsMonotonicTime *diff); + #ifdef SYS_CLOCK_RESOLUTION #define ERTS_CLKTCK_RESOLUTION ((ErtsMonotonicTime) (SYS_CLOCK_RESOLUTION*1000)) #else diff --git a/erts/emulator/beam/erl_time_sup.c b/erts/emulator/beam/erl_time_sup.c index 0421adb409d2..c0fd417113f5 100644 --- a/erts/emulator/beam/erl_time_sup.c +++ b/erts/emulator/beam/erl_time_sup.c @@ -36,12 +36,29 @@ #include "erl_driver.h" #include "erl_nif.h" -static erts_smp_mtx_t erts_timeofday_mtx; static erts_smp_mtx_t erts_get_time_mtx; -static SysTimes t_start; /* Used in elapsed_time_both */ -static ErtsMonotonicTime prev_wall_clock_elapsed; /* Used in wall_clock_elapsed_time_both */ -static ErtsMonotonicTime previous_now; /* Used in get_now */ + /* used by erts_runtime_elapsed_both */ +typedef struct { + erts_smp_mtx_t mtx; + ErtsMonotonicTime user; + ErtsMonotonicTime sys; +} ErtsRunTimePrevData; + +static union { + ErtsRunTimePrevData data; + char align__[ERTS_ALC_CACHE_LINE_ALIGN_SIZE(sizeof(ErtsRunTimePrevData))]; +} runtime_prev erts_align_attribute(ERTS_CACHE_LINE_SIZE); + +static union { + erts_smp_atomic64_t time; + char align__[ERTS_ALC_CACHE_LINE_ALIGN_SIZE(sizeof(erts_smp_atomic64_t))]; +} wall_clock_prev erts_align_attribute(ERTS_CACHE_LINE_SIZE); + +static union { + erts_smp_atomic64_t time; + char align__[ERTS_ALC_CACHE_LINE_ALIGN_SIZE(sizeof(erts_smp_atomic64_t))]; +} now_prev erts_align_attribute(ERTS_CACHE_LINE_SIZE); static ErtsMonitor *time_offset_monitors = NULL; static Uint no_time_offset_monitors = 0; @@ -954,8 +971,10 @@ erts_init_time_sup(int time_correction, ErtsTimeWarpMode time_warp_mode) ASSERT(ERTS_MONOTONIC_TIME_MIN < ERTS_MONOTONIC_TIME_MAX); - erts_smp_mtx_init(&erts_timeofday_mtx, "timeofday"); erts_smp_mtx_init(&erts_get_time_mtx, "get_time"); + erts_smp_mtx_init(&runtime_prev.data.mtx, "runtime"); + runtime_prev.data.user = 0; + runtime_prev.data.sys = 0; time_sup.r.o.correction = time_correction; time_sup.r.o.warp_mode = time_warp_mode; @@ -1154,9 +1173,13 @@ erts_init_time_sup(int time_correction, ErtsTimeWarpMode time_warp_mode) time_sup.f.c.last_not_corrected_time = 0; } - prev_wall_clock_elapsed = 0; + erts_smp_atomic64_init_nob(&wall_clock_prev.time, + (erts_aint64_t) 0); + + erts_smp_atomic64_init_nob( + &now_prev.time, + (erts_aint64_t) ERTS_MONOTONIC_TO_USEC(get_time_offset())); - previous_now = ERTS_MONOTONIC_TO_USEC(get_time_offset()); #ifdef DEBUG time_sup_initialized = 1; @@ -1286,36 +1309,65 @@ erts_finalize_time_offset(void) /* info functions */ void -elapsed_time_both(ErtsMonotonicTime *ms_user, ErtsMonotonicTime *ms_sys, - ErtsMonotonicTime *ms_user_diff, ErtsMonotonicTime *ms_sys_diff) +erts_runtime_elapsed_both(ErtsMonotonicTime *ms_user, ErtsMonotonicTime *ms_sys, + ErtsMonotonicTime *ms_user_diff, ErtsMonotonicTime *ms_sys_diff) { - ErtsMonotonicTime prev_total_user, prev_total_sys; - ErtsMonotonicTime total_user, total_sys; + ErtsMonotonicTime prev_user, prev_sys, user, sys; + +#ifdef HAVE_GETRUSAGE + + struct rusage now; + + if (getrusage(RUSAGE_SELF, &now) != 0) { + erts_exit(ERTS_ABORT_EXIT, "getrusage(RUSAGE_SELF, _) failed: %d\n", errno); + return; + } + + user = (ErtsMonotonicTime) now.ru_utime.tv_sec; + user *= (ErtsMonotonicTime) 1000000; + user += (ErtsMonotonicTime) now.ru_utime.tv_usec; + user /= (ErtsMonotonicTime) 1000; + + sys = (ErtsMonotonicTime) now.ru_stime.tv_sec; + sys *= (ErtsMonotonicTime) 1000000; + sys += (ErtsMonotonicTime) now.ru_stime.tv_usec; + sys /= (ErtsMonotonicTime) 1000; + +#else + SysTimes now; sys_times(&now); - total_user = (ErtsMonotonicTime) ((now.tms_utime * 1000) / SYS_CLK_TCK); - total_sys = (ErtsMonotonicTime) ((now.tms_stime * 1000) / SYS_CLK_TCK); + user = (ErtsMonotonicTime) now.tms_utime; + user *= (ErtsMonotonicTime) 1000; + user /= (ErtsMonotonicTime) SYS_CLK_TCK; - if (ms_user != NULL) - *ms_user = total_user; - if (ms_sys != NULL) - *ms_sys = total_sys; + sys = (ErtsMonotonicTime) now.tms_stime; + sys *= (ErtsMonotonicTime) 1000; + sys /= (ErtsMonotonicTime) SYS_CLK_TCK; + +#endif + + if (ms_user) + *ms_user = user; + if (ms_sys) + *ms_sys = sys; if (ms_user_diff || ms_sys_diff) { - erts_smp_mtx_lock(&erts_timeofday_mtx); - - prev_total_user = (ErtsMonotonicTime) ((t_start.tms_utime * 1000) / SYS_CLK_TCK); - prev_total_sys = (ErtsMonotonicTime) ((t_start.tms_stime * 1000) / SYS_CLK_TCK); - t_start = now; - - erts_smp_mtx_unlock(&erts_timeofday_mtx); + + erts_smp_mtx_lock(&runtime_prev.data.mtx); + + prev_user = runtime_prev.data.user; + prev_sys = runtime_prev.data.sys; + runtime_prev.data.user = user; + runtime_prev.data.sys = sys; - if (ms_user_diff != NULL) - *ms_user_diff = total_user - prev_total_user; - - if (ms_sys_diff != NULL) - *ms_sys_diff = total_sys - prev_total_sys; + erts_smp_mtx_unlock(&runtime_prev.data.mtx); + + if (ms_user_diff) + *ms_user_diff = user - prev_user; + if (ms_sys_diff) + *ms_sys_diff = sys - prev_sys; } } @@ -1323,7 +1375,7 @@ elapsed_time_both(ErtsMonotonicTime *ms_user, ErtsMonotonicTime *ms_sys, /* wall clock routines */ void -wall_clock_elapsed_time_both(ErtsMonotonicTime *ms_total, ErtsMonotonicTime *ms_diff) +erts_wall_clock_elapsed_both(ErtsMonotonicTime *ms_total, ErtsMonotonicTime *ms_diff) { ErtsMonotonicTime now, elapsed; @@ -1331,16 +1383,18 @@ wall_clock_elapsed_time_both(ErtsMonotonicTime *ms_total, ErtsMonotonicTime *ms_ update_last_mtime(NULL, now); elapsed = ERTS_MONOTONIC_TO_MSEC(now); + elapsed -= ERTS_MONOTONIC_TO_MSEC(ERTS_MONOTONIC_BEGIN); *ms_total = elapsed; if (ms_diff) { - erts_smp_mtx_lock(&erts_timeofday_mtx); + ErtsMonotonicTime prev; - *ms_diff = elapsed - prev_wall_clock_elapsed; - prev_wall_clock_elapsed = elapsed; + prev = ((ErtsMonotonicTime) + erts_smp_atomic64_xchg_mb(&wall_clock_prev.time, + (erts_aint64_t) elapsed)); - erts_smp_mtx_unlock(&erts_timeofday_mtx); + *ms_diff = elapsed - prev; } } @@ -1719,22 +1773,27 @@ univ_to_local(Sint *year, Sint *month, Sint *day, void get_now(Uint* megasec, Uint* sec, Uint* microsec) { - ErtsMonotonicTime now_megasec, now_sec, now, mtime, time_offset; + ErtsMonotonicTime now_megasec, now_sec, now, prev, mtime, time_offset; mtime = time_sup.r.o.get_time(); time_offset = get_time_offset(); update_last_mtime(NULL, mtime); now = ERTS_MONOTONIC_TO_USEC(mtime + time_offset); - erts_smp_mtx_lock(&erts_timeofday_mtx); - /* Make sure now time is later than last time */ - if (now <= previous_now) - now = previous_now + 1; - - previous_now = now; - - erts_smp_mtx_unlock(&erts_timeofday_mtx); + prev = erts_smp_atomic64_read_nob(&now_prev.time); + while (1) { + ErtsMonotonicTime act; + if (now <= prev) + now = prev + 1; + act = ((ErtsMonotonicTime) + erts_smp_atomic64_cmpxchg_mb(&now_prev.time, + (erts_aint64_t) now, + (erts_aint64_t) prev)); + if (act == prev) + break; + prev = act; + } now_megasec = now / ERTS_MONOTONIC_TIME_TERA; now_sec = now / ERTS_MONOTONIC_TIME_MEGA; diff --git a/erts/emulator/beam/sys.h b/erts/emulator/beam/sys.h index b6c77794d217..6662685f540f 100644 --- a/erts/emulator/beam/sys.h +++ b/erts/emulator/beam/sys.h @@ -784,10 +784,6 @@ Preload* sys_preloaded(void); unsigned char* sys_preload_begin(Preload*); void sys_preload_end(Preload*); int sys_get_key(int); -void elapsed_time_both(ErtsMonotonicTime *ms_user, ErtsMonotonicTime *ms_sys, - ErtsMonotonicTime *ms_user_diff, ErtsMonotonicTime *ms_sys_diff); -void wall_clock_elapsed_time_both(ErtsMonotonicTime *ms_total, - ErtsMonotonicTime *ms_diff); void get_time(int *hour, int *minute, int *second); void get_date(int *year, int *month, int *day); void get_localtime(int *year, int *month, int *day, diff --git a/erts/emulator/sys/unix/erl_unix_sys.h b/erts/emulator/sys/unix/erl_unix_sys.h index 22059d21d595..b83837a7d25e 100644 --- a/erts/emulator/sys/unix/erl_unix_sys.h +++ b/erts/emulator/sys/unix/erl_unix_sys.h @@ -86,6 +86,10 @@ #include +#ifdef HAVE_SYS_RESOURCE_H +# include +#endif + #ifdef HAVE_IEEEFP_H #include #endif diff --git a/erts/emulator/test/statistics_SUITE.erl b/erts/emulator/test/statistics_SUITE.erl index 7690557fda04..40cc940a94b4 100644 --- a/erts/emulator/test/statistics_SUITE.erl +++ b/erts/emulator/test/statistics_SUITE.erl @@ -23,8 +23,10 @@ %% Tests the statistics/1 bif. -export([all/0, suite/0, groups/0, + wall_clock_sanity/1, wall_clock_zero_diff/1, wall_clock_update/1, - runtime_zero_diff/1, + runtime_sanity/1, + runtime_zero_diff/1, runtime_update/1, runtime_diff/1, run_queue_one/1, scheduler_wall_time/1, @@ -54,11 +56,23 @@ all() -> groups() -> [{wall_clock, [], - [wall_clock_zero_diff, wall_clock_update]}, + [wall_clock_sanity, wall_clock_zero_diff, wall_clock_update]}, {runtime, [], - [runtime_zero_diff, runtime_update, runtime_diff]}, + [runtime_sanity, runtime_zero_diff, runtime_update, runtime_diff]}, {run_queue, [], [run_queue_one]}]. +wall_clock_sanity(Config) when is_list(Config) -> + erlang:yield(), + {WallClock, _} = statistics(wall_clock), + MT = erlang:monotonic_time(), + Time = erlang:convert_time_unit(MT - erlang:system_info(start_time), + native, millisecond), + io:format("Time=~p WallClock=~p~n", + [Time, WallClock]), + true = WallClock =< Time, + true = Time - 100 =< WallClock, + ok. + %%% Testing statistics(wall_clock). %% Tests that the 'Wall clock since last call' element of the result @@ -102,6 +116,20 @@ wall_clock_update1(0) -> %%% Test statistics(runtime). +runtime_sanity(Config) when is_list(Config) -> + case erlang:system_info(logical_processors_available) of + unknown -> + {skipped, "Don't know available logical processors"}; + LP when is_integer(LP) -> + erlang:yield(), + {RunTime, _} = statistics(runtime), + MT = erlang:monotonic_time(), + Time = erlang:convert_time_unit(MT - erlang:system_info(start_time), + native, millisecond), + io:format("Time=~p RunTime=~p~n", + [Time, RunTime]), + true = RunTime =< Time*LP + end. %% Tests that the difference between the times returned from two consectuitive %% calls to statistics(runtime) is zero.