From 858c6f7fa44f7b2dc363b359198d6522dd60e914 Mon Sep 17 00:00:00 2001 From: Rickard Green Date: Tue, 5 Jan 2016 16:55:04 +0100 Subject: Introduce time warp safe trace timestamp formats New timestamp options for trace, sequential trace, and system profile: - monotonic_timestamp - strict_monotonic_timestamp --- erts/doc/src/erlang.xml | 64 ++- erts/emulator/beam/atom.names | 2 + erts/emulator/beam/erl_bif_trace.c | 41 +- erts/emulator/beam/erl_process.c | 1 + erts/emulator/beam/erl_process.h | 87 ++-- erts/emulator/beam/erl_trace.c | 700 +++++++++++++++++----------- erts/emulator/beam/erl_trace.h | 32 +- erts/emulator/test/system_profile_SUITE.erl | 155 ++++-- erts/emulator/test/trace_bif_SUITE.erl | 249 ++++++---- erts/preloaded/ebin/erlang.beam | Bin 102000 -> 102116 bytes erts/preloaded/src/erlang.erl | 13 +- lib/kernel/doc/src/seq_trace.xml | 28 ++ lib/kernel/src/kernel.app.src | 2 +- lib/kernel/src/seq_trace.erl | 14 +- lib/kernel/test/seq_trace_SUITE.erl | 166 +++++-- 15 files changed, 1081 insertions(+), 473 deletions(-) diff --git a/erts/doc/src/erlang.xml b/erts/doc/src/erlang.xml index 64eebec936..79d3f66ea8 100644 --- a/erts/doc/src/erlang.xml +++ b/erts/doc/src/erlang.xml @@ -7739,6 +7739,13 @@ ok inactive, and later active when the port callback returns.

+ monotonic_timestamp + +

Timestamps in profile messages will use + Erlang + monotonic time. The time-stamp (Ts) has the same + format and value as produced by erlang:monotonic_time().

+ runnable_procs

If a process is put into or removed from the run queue, a @@ -7759,6 +7766,25 @@ ok {profile, scheduler, Id, State, NoScheds, Ts}, is sent to ProfilerPid.

 + strict_monotonic_timestamp + +

Timestamps in profile messages will consisting of + Erlang + monotonic time and a monotonically increasing + integer. The time-stamp (Ts) has the same format and value + as produced by {erlang:monotonic_time(), + erlang:unique_integer([monotonic])}.

+ + timestamp + +

Timestamps in profile messages will include a + time-stamp (Ts) that has the same form as returned by + erlang:now(). This is also the default if no + timestamp flag is given. If cpu_timestamp has + been enabled via erlang:trace/3, this will also + effect the timestamp produced in profiling messages + when timestamp flag is enabled.

+

erlang:system_profile is considered experimental and its behavior can change in a future release.

@@ -8118,7 +8144,10 @@ timestamp() -> cpu_timestamp

A global trace flag for the Erlang node that makes all - trace time-stamps to be in CPU time, not wall clock time. + trace time-stamps using the timestamp flag to be + in CPU time, not wall clock time. That is, cpu_timestamp + will not be used if monotonic_timestamp, or + strict_monotonic_timestamp is enabled. Only allowed with PidSpec==all. If the host machine OS does not support high-resolution CPU time measurements, trace/3 exits with @@ -8126,6 +8155,26 @@ timestamp() -> not synchronize this value across cores, so be prepared that time might seem to go backwards when using this option.

 + monotonic_timestamp + +

Includes an + Erlang + monotonic time time-stamp in all trace messages. The + time-stamp (Ts) has the same format and value as produced by + erlang:monotonic_time(). This flag overrides + the cpu_timestamp flag.

+ + strict_monotonic_timestamp + +

Includes an timestamp consisting of + Erlang + monotonic time and a monotonically increasing + integer in all trace messages. The time-stamp (Ts) has the + same format and value as produced by + {erlang:monotonic_time(), + erlang:unique_integer([monotonic])}. This flag overrides + the cpu_timestamp flag.

+ arity

Used with the call trace flag. @@ -8172,9 +8221,16 @@ timestamp() -> in the following list. Pid is the process identifier of the traced process in which the traced event has occurred. The third tuple element is the message tag.

-

If flag timestamp is given, the first tuple - element is trace_ts instead, and the time-stamp - is added last in the message tuple.

+

If flag timestamp, strict_monotonic_timestamp, or + monotonic_timestamp is given, the first tuple + element is trace_ts instead, and the time-stamp + is added as an extra element last in the message tuple. If + multiple timestamp flags are passed, timestamp has + precedence over strict_monotonic_timestamp which + in turn has precedence over monotonic_timestamp. All + timestamp flags are remembered, so if two are passed + and the one with highest precedence later is disabled + the other one will become active.

{trace, Pid, 'receive', Msg} diff --git a/erts/emulator/beam/atom.names b/erts/emulator/beam/atom.names index fb3368eae2..07f6492948 100644 --- a/erts/emulator/beam/atom.names +++ b/erts/emulator/beam/atom.names @@ -370,6 +370,7 @@ atom monitor atom monitor_nodes atom monitors atom monotonic +atom monotonic_timestamp atom more atom multi_scheduling atom multiline @@ -559,6 +560,7 @@ atom static atom stderr_to_stdout atom stop atom stream +atom strict_monotonic_timestamp atom sunrm atom suspend atom suspended diff --git a/erts/emulator/beam/erl_bif_trace.c b/erts/emulator/beam/erl_bif_trace.c index 03f51132b1..08807d72c9 100644 --- a/erts/emulator/beam/erl_bif_trace.c +++ b/erts/emulator/beam/erl_bif_trace.c @@ -431,6 +431,9 @@ Uint erts_trace_flag2bit(Eterm flag) { switch (flag) { + case am_timestamp: return F_NOW_TS; + case am_strict_monotonic_timestamp: return F_STRICT_MON_TS; + case am_monotonic_timestamp: return F_MON_TS; case am_all: return TRACEE_FLAGS; case am_send: return F_TRACE_SEND; case am_receive: return F_TRACE_RECEIVE; @@ -439,7 +442,6 @@ erts_trace_flag2bit(Eterm flag) case am_set_on_first_spawn: return F_TRACE_SOS1; case am_set_on_link: return F_TRACE_SOL; case am_set_on_first_link: return F_TRACE_SOL1; - case am_timestamp: return F_TIMESTAMP; case am_running: return F_TRACE_SCHED; case am_exiting: return F_TRACE_SCHED_EXIT; case am_garbage_collection: return F_TRACE_GC; @@ -592,7 +594,7 @@ Eterm trace_3(BIF_ALIST_3) ERTS_TRACE_FLAGS(tracee_port) |= mask; else ERTS_TRACE_FLAGS(tracee_port) &= ~mask; - + if (!ERTS_TRACE_FLAGS(tracee_port)) ERTS_TRACER_PROC(tracee_port) = NIL; else if (tracer != NIL) @@ -978,7 +980,7 @@ trace_info_pid(Process* p, Eterm pid_spec, Eterm key) } if (key == am_flags) { - int num_flags = 19; /* MAXIMUM number of flags. */ + int num_flags = 21; /* MAXIMUM number of flags. */ Uint needed = 3+2*num_flags; Eterm flag_list = NIL; Eterm* limit; @@ -996,6 +998,9 @@ trace_info_pid(Process* p, Eterm pid_spec, Eterm key) #endif hp = HAlloc(p, needed); limit = hp+needed; + FLAG(F_NOW_TS, am_timestamp); + FLAG(F_STRICT_MON_TS, am_strict_monotonic_timestamp); + FLAG(F_MON_TS, am_monotonic_timestamp); FLAG(F_TRACE_SEND, am_send); FLAG(F_TRACE_RECEIVE, am_receive); FLAG(F_TRACE_SOS, am_set_on_spawn); @@ -1007,7 +1012,6 @@ trace_info_pid(Process* p, Eterm pid_spec, Eterm key) FLAG(F_TRACE_SCHED, am_running); FLAG(F_TRACE_SCHED_EXIT, am_exiting); FLAG(F_TRACE_GC, am_garbage_collection); - FLAG(F_TIMESTAMP, am_timestamp); FLAG(F_TRACE_ARITY_ONLY, am_arity); FLAG(F_TRACE_RETURN_TO, am_return_to); FLAG(F_TRACE_SILENT, am_silent); @@ -1798,7 +1802,11 @@ Eterm erts_seq_trace(Process *p, Eterm arg1, Eterm arg2, } else if (arg1 == am_print) { current_flag = SEQ_TRACE_PRINT; } else if (arg1 == am_timestamp) { - current_flag = SEQ_TRACE_TIMESTAMP; + current_flag = SEQ_TRACE_NOW_TS; + } else if (arg1 == am_strict_monotonic_timestamp) { + current_flag = SEQ_TRACE_STRICT_MON_TS; + } else if (arg1 == am_monotonic_timestamp) { + current_flag = SEQ_TRACE_MON_TS; } else current_flag = 0; @@ -1909,7 +1917,9 @@ BIF_RETTYPE erl_seq_trace_info(Process *p, Eterm item) #endif ) { if ((item == am_send) || (item == am_receive) || - (item == am_print) || (item == am_timestamp)) { + (item == am_print) || (item == am_timestamp) + || (item == am_monotonic_timestamp) + || (item == am_strict_monotonic_timestamp)) { hp = HAlloc(p,3); res = TUPLE2(hp, item, am_false); BIF_RET(res); @@ -1927,7 +1937,11 @@ BIF_RETTYPE erl_seq_trace_info(Process *p, Eterm item) } else if (item == am_print) { current_flag = SEQ_TRACE_PRINT; } else if (item == am_timestamp) { - current_flag = SEQ_TRACE_TIMESTAMP; + current_flag = SEQ_TRACE_NOW_TS; + } else if (item == am_strict_monotonic_timestamp) { + current_flag = SEQ_TRACE_STRICT_MON_TS; + } else if (item == am_monotonic_timestamp) { + current_flag = SEQ_TRACE_MON_TS; } else { current_flag = 0; } @@ -2237,6 +2251,7 @@ static Eterm system_profile_get(Process *p) { if (erts_system_profile_flags.exclusive) { res = CONS(hp, am_exclusive, res); hp += 2; } + return TUPLE2(hp, system_profile, res); } } @@ -2255,6 +2270,7 @@ BIF_RETTYPE system_profile_2(BIF_ALIST_2) int system_blocked = 0; Process *profiler_p = NULL; Port *profiler_port = NULL; + int ts; if (profiler == am_undefined || list == NIL) { prev = system_profile_get(p); @@ -2286,7 +2302,8 @@ BIF_RETTYPE system_profile_2(BIF_ALIST_2) goto error; } - for (scheduler = 0, runnable_ports = 0, runnable_procs = 0, exclusive = 0; + for (ts = ERTS_TRACE_FLG_NOW_TIMESTAMP, scheduler = 0, + runnable_ports = 0, runnable_procs = 0, exclusive = 0; is_list(list); list = CDR(list_val(list))) { @@ -2299,6 +2316,12 @@ BIF_RETTYPE system_profile_2(BIF_ALIST_2) exclusive = !0; } else if (t == am_scheduler) { scheduler = !0; + } else if (t == am_timestamp) { + ts = ERTS_TRACE_FLG_NOW_TIMESTAMP; + } else if (t == am_strict_monotonic_timestamp) { + ts = ERTS_TRACE_FLG_STRICT_MONOTONIC_TIMESTAMP; + } else if (t == am_monotonic_timestamp) { + ts = ERTS_TRACE_FLG_MONOTONIC_TIMESTAMP; } else goto error; } if (is_not_nil(list)) goto error; @@ -2311,7 +2334,7 @@ BIF_RETTYPE system_profile_2(BIF_ALIST_2) erts_system_profile_flags.runnable_ports = !!runnable_ports; erts_system_profile_flags.runnable_procs = !!runnable_procs; erts_system_profile_flags.exclusive = !!exclusive; - + erts_system_profile_ts_type = ts; erts_smp_thr_progress_unblock(); erts_smp_proc_lock(p, ERTS_PROC_LOCK_MAIN); diff --git a/erts/emulator/beam/erl_process.c b/erts/emulator/beam/erl_process.c index b47aae0f74..c1d2e8db8e 100644 --- a/erts/emulator/beam/erl_process.c +++ b/erts/emulator/beam/erl_process.c @@ -353,6 +353,7 @@ struct erts_system_monitor_flags_t erts_system_monitor_flags; /* system performance monitor */ Eterm erts_system_profile; struct erts_system_profile_flags_t erts_system_profile_flags; +int erts_system_profile_ts_type = ERTS_TRACE_FLG_NOW_TIMESTAMP; #if ERTS_MAX_PROCESSES > 0x7fffffff #error "Need to store process_count in another type" diff --git a/erts/emulator/beam/erl_process.h b/erts/emulator/beam/erl_process.h index fd7d4183f4..6512710f48 100644 --- a/erts/emulator/beam/erl_process.h +++ b/erts/emulator/beam/erl_process.h @@ -60,6 +60,9 @@ typedef struct process Process; #include "erl_mseg.h" #include "erl_async.h" #include "erl_gc.h" +#define ERTS_ONLY_INCLUDE_TRACE_FLAGS +#include "erl_trace.h" +#undef ERTS_ONLY_INCLUDE_TRACE_FLAGS #ifdef HIPE #include "hipe_process.h" @@ -1292,6 +1295,7 @@ struct erts_system_profile_flags_t { unsigned int exclusive : 1; }; extern struct erts_system_profile_flags_t erts_system_profile_flags; +extern int erts_system_profile_ts_type; /* process flags */ #define F_HIBERNATE_SCHED (1 << 0) /* Schedule out after hibernate op */ @@ -1307,61 +1311,90 @@ extern struct erts_system_profile_flags_t erts_system_profile_flags; #define F_FORCE_GC (1 << 10) /* Force gc at process in-scheduling */ #define F_DISABLE_GC (1 << 11) /* Disable GC */ +#define ERTS_TRACE_FLAGS_TS_TYPE_SHIFT 0 + +#define F_TRACE_FLAG(N) (1 << (ERTS_TRACE_TS_TYPE_BITS + (N))) + /* process trace_flags */ -#define F_SENSITIVE (1 << 0) -#define F_TRACE_SEND (1 << 1) -#define F_TRACE_RECEIVE (1 << 2) -#define F_TRACE_SOS (1 << 3) /* Set on spawn */ -#define F_TRACE_SOS1 (1 << 4) /* Set on first spawn */ -#define F_TRACE_SOL (1 << 5) /* Set on link */ -#define F_TRACE_SOL1 (1 << 6) /* Set on first link */ -#define F_TRACE_CALLS (1 << 7) -#define F_TIMESTAMP (1 << 8) -#define F_TRACE_PROCS (1 << 9) -#define F_TRACE_FIRST_CHILD (1 << 10) -#define F_TRACE_SCHED (1 << 11) -#define F_TRACE_GC (1 << 12) -#define F_TRACE_ARITY_ONLY (1 << 13) -#define F_TRACE_RETURN_TO (1 << 14) /* Return_to trace when breakpoint tracing */ -#define F_TRACE_SILENT (1 << 15) /* No call trace msg suppress */ -#define F_TRACER (1 << 16) /* May be (has been) tracer */ -#define F_EXCEPTION_TRACE (1 << 17) /* May have exception trace on stack */ + +#define F_NOW_TS (ERTS_TRACE_FLG_NOW_TIMESTAMP \ + << ERTS_TRACE_FLAGS_TS_TYPE_SHIFT) +#define F_STRICT_MON_TS (ERTS_TRACE_FLG_STRICT_MONOTONIC_TIMESTAMP \ + << ERTS_TRACE_FLAGS_TS_TYPE_SHIFT) +#define F_MON_TS (ERTS_TRACE_FLG_MONOTONIC_TIMESTAMP \ + << ERTS_TRACE_FLAGS_TS_TYPE_SHIFT) +#define F_SENSITIVE F_TRACE_FLAG(0) +#define F_TRACE_SEND F_TRACE_FLAG(1) +#define F_TRACE_RECEIVE F_TRACE_FLAG(2) +#define F_TRACE_SOS F_TRACE_FLAG(3) /* Set on spawn */ +#define F_TRACE_SOS1 F_TRACE_FLAG(4) /* Set on first spawn */ +#define F_TRACE_SOL F_TRACE_FLAG(5) /* Set on link */ +#define F_TRACE_SOL1 F_TRACE_FLAG(6) /* Set on first link */ +#define F_TRACE_CALLS F_TRACE_FLAG(7) +#define F_TRACE_PROCS F_TRACE_FLAG(8) +#define F_TRACE_FIRST_CHILD F_TRACE_FLAG(9) +#define F_TRACE_SCHED F_TRACE_FLAG(10) +#define F_TRACE_GC F_TRACE_FLAG(11) +#define F_TRACE_ARITY_ONLY F_TRACE_FLAG(12) +#define F_TRACE_RETURN_TO F_TRACE_FLAG(13) /* Return_to trace when breakpoint tracing */ +#define F_TRACE_SILENT F_TRACE_FLAG(14) /* No call trace msg suppress */ +#define F_TRACER F_TRACE_FLAG(15) /* May be (has been) tracer */ +#define F_EXCEPTION_TRACE F_TRACE_FLAG(16) /* May have exception trace on stack */ /* port trace flags, currently the same as process trace flags */ -#define F_TRACE_SCHED_PORTS (1 << 18) /* Trace of port scheduling */ -#define F_TRACE_SCHED_PROCS (1 << 19) /* With virtual scheduling */ -#define F_TRACE_PORTS (1 << 20) /* Ports equivalent to F_TRACE_PROCS */ -#define F_TRACE_SCHED_NO (1 << 21) /* Trace with scheduler id */ -#define F_TRACE_SCHED_EXIT (1 << 22) +#define F_TRACE_SCHED_PORTS F_TRACE_FLAG(17) /* Trace of port scheduling */ +#define F_TRACE_SCHED_PROCS F_TRACE_FLAG(18) /* With virtual scheduling */ +#define F_TRACE_PORTS F_TRACE_FLAG(19) /* Ports equivalent to F_TRACE_PROCS */ +#define F_TRACE_SCHED_NO F_TRACE_FLAG(20) /* Trace with scheduler id */ +#define F_TRACE_SCHED_EXIT F_TRACE_FLAG(21) -#define F_NUM_FLAGS 23 +#define F_NUM_FLAGS (ERTS_TRACE_TS_TYPE_BITS + 22) #ifdef DEBUG # define F_INITIAL_TRACE_FLAGS (5 << F_NUM_FLAGS) #else # define F_INITIAL_TRACE_FLAGS 0 #endif +/* F_TIMESTAMP_MASK is a bit-field of all all timestamp types */ +#define F_TIMESTAMP_MASK \ + (ERTS_TRACE_TS_TYPE_MASK << ERTS_TRACE_FLAGS_TS_TYPE_SHIFT) + #define TRACEE_FLAGS ( F_TRACE_PROCS | F_TRACE_CALLS \ | F_TRACE_SOS | F_TRACE_SOS1| F_TRACE_RECEIVE \ | F_TRACE_SOL | F_TRACE_SOL1 | F_TRACE_SEND \ - | F_TRACE_SCHED | F_TIMESTAMP | F_TRACE_GC \ + | F_TRACE_SCHED | F_TIMESTAMP_MASK | F_TRACE_GC \ | F_TRACE_ARITY_ONLY | F_TRACE_RETURN_TO \ | F_TRACE_SILENT | F_TRACE_SCHED_PROCS | F_TRACE_PORTS \ | F_TRACE_SCHED_PORTS | F_TRACE_SCHED_NO \ | F_TRACE_SCHED_EXIT) #define ERTS_TRACEE_MODIFIER_FLAGS \ - (F_TRACE_SILENT | F_TIMESTAMP | F_TRACE_SCHED_NO) + (F_TRACE_SILENT | F_TIMESTAMP_MASK | F_TRACE_SCHED_NO) #define ERTS_PORT_TRACEE_FLAGS \ (ERTS_TRACEE_MODIFIER_FLAGS | F_TRACE_PORTS | F_TRACE_SCHED_PORTS) #define ERTS_PROC_TRACEE_FLAGS \ ((TRACEE_FLAGS & ~ERTS_PORT_TRACEE_FLAGS) | ERTS_TRACEE_MODIFIER_FLAGS) +#define SEQ_TRACE_FLAG(N) (1 << (ERTS_TRACE_TS_TYPE_BITS + (N))) + /* Sequential trace flags */ + +/* SEQ_TRACE_TIMESTAMP_MASK is a bit-field */ +#define SEQ_TRACE_TIMESTAMP_MASK \ + (ERTS_TRACE_TS_TYPE_MASK << ERTS_SEQ_TRACE_FLAGS_TS_TYPE_SHIFT) + #define SEQ_TRACE_SEND (1 << 0) #define SEQ_TRACE_RECEIVE (1 << 1) #define SEQ_TRACE_PRINT (1 << 2) -#define SEQ_TRACE_TIMESTAMP (1 << 3) + +#define ERTS_SEQ_TRACE_FLAGS_TS_TYPE_SHIFT 3 + +#define SEQ_TRACE_NOW_TS (ERTS_TRACE_FLG_NOW_TIMESTAMP \ + << ERTS_SEQ_TRACE_FLAGS_TS_TYPE_SHIFT) +#define SEQ_TRACE_STRICT_MON_TS (ERTS_TRACE_FLG_STRICT_MONOTONIC_TIMESTAMP \ + << ERTS_SEQ_TRACE_FLAGS_TS_TYPE_SHIFT) +#define SEQ_TRACE_MON_TS (ERTS_TRACE_FLG_MONOTONIC_TIMESTAMP \ + << ERTS_SEQ_TRACE_FLAGS_TS_TYPE_SHIFT) #ifdef USE_VM_PROBES #define DT_UTAG_PERMANENT (1 << 0) diff --git a/erts/emulator/beam/erl_trace.c b/erts/emulator/beam/erl_trace.c index e1b03a057f..2243639099 100644 --- a/erts/emulator/beam/erl_trace.c +++ b/erts/emulator/beam/erl_trace.c @@ -38,6 +38,7 @@ #include "erl_binary.h" #include "erl_bits.h" #include "erl_thr_progress.h" +#include "erl_bif_unique.h" #if 0 #define DEBUG_PRINTOUTS @@ -77,6 +78,263 @@ enum ErtsSysMsgType { SYS_MSG_TYPE_SYSPROF }; +#define ERTS_TRACE_TS_NOW_MAX_SIZE \ + 4 +#define ERTS_TRACE_TS_MONOTONIC_MAX_SIZE \ + ERTS_MAX_SINT64_HEAP_SIZE +#define ERTS_TRACE_TS_STRICT_MONOTONIC_MAX_SIZE \ + (3 + ERTS_MAX_SINT64_HEAP_SIZE \ + + ERTS_MAX_UINT64_HEAP_SIZE) + +#define ERTS_TRACE_PATCH_TS_MAX_SIZE \ + (1 + ((ERTS_TRACE_TS_NOW_MAX_SIZE \ + > ERTS_TRACE_TS_MONOTONIC_MAX_SIZE) \ + ? ((ERTS_TRACE_TS_NOW_MAX_SIZE \ + > ERTS_TRACE_TS_STRICT_MONOTONIC_MAX_SIZE) \ + ? ERTS_TRACE_TS_NOW_MAX_SIZE \ + : ERTS_TRACE_TS_STRICT_MONOTONIC_MAX_SIZE) \ + : ((ERTS_TRACE_TS_MONOTONIC_MAX_SIZE \ + > ERTS_TRACE_TS_STRICT_MONOTONIC_MAX_SIZE) \ + ? ERTS_TRACE_TS_MONOTONIC_MAX_SIZE \ + : ERTS_TRACE_TS_STRICT_MONOTONIC_MAX_SIZE))) + +#define TFLGS_TS_TYPE(p) ERTS_TFLGS2TSTYPE(ERTS_TRACE_FLAGS((p))) + +/* + * FUTURE CHANGES: + * + * The timestamp functionality has intentionally been + * split in two parts for future use even though it + * is not used like this today. take_timestamp() takes + * the timestamp and calculate heap need for it (which + * is not constant). write_timestamp() writes the + * timestamp to the allocated heap. That is, one typically + * want to take the timestamp before allocating the heap + * and then write it to the heap. + * + * The trace output functionality now use patch_ts_size(), + * write_ts(), and patch_ts(). write_ts() both takes the + * timestamp and writes it. Since we don't know the + * heap need when allocating the heap area we need to + * over allocate (maximum size from patch_ts_size()) and + * then potentially (often) shrink the heap area after the + * timestamp has been written. The only reason it is + * currently done this way is because we do not want to + * make major changes of the trace behavior in a patch. + * This is planned to be changed in next major release. + */ + +typedef struct { + int ts_type_flag; + union { + struct { + Uint ms; + Uint s; + Uint us; + } now; + struct { + ErtsMonotonicTime time; + Sint64 raw_unique; + } monotonic; + } u; +} ErtsTraceTimeStamp; + +static ERTS_INLINE Uint +take_timestamp(ErtsTraceTimeStamp *tsp, int ts_type) +{ + int ts_type_flag = ts_type & -ts_type; /* least significant flag */ + + ASSERT(ts_type_flag == ERTS_TRACE_FLG_NOW_TIMESTAMP + || ts_type_flag == ERTS_TRACE_FLG_MONOTONIC_TIMESTAMP + || ts_type_flag == ERTS_TRACE_FLG_STRICT_MONOTONIC_TIMESTAMP + || ts_type_flag == 0); + + tsp->ts_type_flag = ts_type_flag; + switch (ts_type_flag) { + case 0: + return (Uint) 0; + case ERTS_TRACE_FLG_NOW_TIMESTAMP: +#ifdef HAVE_ERTS_NOW_CPU + if (erts_cpu_timestamp) + erts_get_now_cpu(&tsp->u.now.ms, &tsp->u.now.s, &tsp->u.now.us); + else +#endif + get_now(&tsp->u.now.ms, &tsp->u.now.s, &tsp->u.now.us); + return (Uint) 4; + case ERTS_TRACE_FLG_MONOTONIC_TIMESTAMP: + case ERTS_TRACE_FLG_STRICT_MONOTONIC_TIMESTAMP: { + Uint hsz = 0; + ErtsMonotonicTime mtime = erts_get_monotonic_time(NULL); + mtime += ERTS_MONOTONIC_OFFSET_NATIVE; + hsz = (IS_SSMALL(mtime) ? + (Uint) 0 + : ERTS_SINT64_HEAP_SIZE((Sint64) mtime)); + tsp->u.monotonic.time = mtime; + if (ts_type_flag == ERTS_TRACE_FLG_STRICT_MONOTONIC_TIMESTAMP) { + Sint64 raw_unique; + hsz += 3; /* 2-tuple */ + raw_unique = erts_raw_get_unique_monotonic_integer(); + tsp->u.monotonic.raw_unique = raw_unique; + hsz += erts_raw_unique_monotonic_integer_heap_size(raw_unique); + } + return hsz; + } + default: + ERTS_INTERNAL_ERROR("invalid timestamp type"); + return 0; + } +} + +static ERTS_INLINE Eterm +write_timestamp(ErtsTraceTimeStamp *tsp, Eterm **hpp) +{ + int ts_type_flag = tsp->ts_type_flag; + Eterm res; + + switch (ts_type_flag) { + case 0: + return NIL; + case ERTS_TRACE_FLG_NOW_TIMESTAMP: + res = TUPLE3(*hpp, + make_small(tsp->u.now.ms), + make_small(tsp->u.now.s), + make_small(tsp->u.now.us)); + *hpp += 4; + return res; + case ERTS_TRACE_FLG_MONOTONIC_TIMESTAMP: + case ERTS_TRACE_FLG_STRICT_MONOTONIC_TIMESTAMP: { + Sint64 mtime, raw; + Eterm unique, emtime; + + mtime = (Sint64) tsp->u.monotonic.time; + emtime = (IS_SSMALL(mtime) + ? make_small((Sint64) mtime) + : erts_sint64_to_big((Sint64) mtime, hpp)); + + if (ts_type_flag == ERTS_TRACE_FLG_MONOTONIC_TIMESTAMP) + return emtime; + + raw = tsp->u.monotonic.raw_unique; + unique = erts_raw_make_unique_monotonic_integer_value(hpp, + raw); + res = TUPLE2(*hpp, emtime, unique); + *hpp += 3; + return res; + } + default: + ERTS_INTERNAL_ERROR("invalid timestamp type"); + return THE_NON_VALUE; + } +} + +#define PATCH_TS_SIZE(p) patch_ts_size(TFLGS_TS_TYPE(p)) + +static ERTS_INLINE Uint +patch_ts_size(int ts_type) +{ + int ts_type_flag = ts_type & -ts_type; /* least significant flag */ + switch (ts_type_flag) { + case 0: + return 0; + case ERTS_TRACE_FLG_NOW_TIMESTAMP: + return 1 + ERTS_TRACE_TS_NOW_MAX_SIZE; + case ERTS_TRACE_FLG_MONOTONIC_TIMESTAMP: + return 1 + ERTS_TRACE_TS_MONOTONIC_MAX_SIZE; + case ERTS_TRACE_FLG_STRICT_MONOTONIC_TIMESTAMP: + return 1 + ERTS_TRACE_TS_STRICT_MONOTONIC_MAX_SIZE; + default: + ERTS_INTERNAL_ERROR("invalid timestamp type"); + return 0; + } +} + +/* + * Write a timestamp. The timestamp MUST be the last + * thing built on the heap. This since write_ts() might + * adjust the size of the used area. + */ +static Eterm +write_ts(int ts_type, Eterm *hp, ErlHeapFragment *bp, Process *tracer) +{ + ErtsTraceTimeStamp ts; + Sint shrink; + Eterm res, *ts_hp = hp; + Uint hsz; + + ASSERT(ts_type); + + hsz = take_timestamp(&ts, ts_type); + + res = write_timestamp(&ts, &ts_hp); + + ASSERT(ts_hp == hp + hsz); + + switch (ts.ts_type_flag) { + case ERTS_TRACE_FLG_MONOTONIC_TIMESTAMP: + shrink = ERTS_TRACE_TS_MONOTONIC_MAX_SIZE; + break; + case ERTS_TRACE_FLG_STRICT_MONOTONIC_TIMESTAMP: + shrink = ERTS_TRACE_TS_STRICT_MONOTONIC_MAX_SIZE; + break; + default: + return res; + } + + shrink -= hsz; + + ASSERT(shrink >= 0); + + if (shrink) { + if (bp) + bp->used_size -= shrink; +#ifndef ERTS_SMP + else if (tracer) { + Eterm *endp = ts_hp + shrink; + HRelease(tracer, endp, ts_hp); + } +#endif + } + + return res; +} + +/* + * Patch a timestamp into a tuple. The tuple MUST be the last thing + * built on the heap before the call, and the timestamp MUST be + * the last thing after the call. This since patch_ts() might adjust + * the size of the used area. + */ + +#define PATCH_TS__(Type, Tuple, Hp, Bp, Tracer) \ + do { \ + int ts_type__ = (Type); \ + if (ts_type__) \ + patch_ts(ts_type__, (Tuple), (Hp), (Bp), (Tracer)); \ + } while (0) + +#ifdef ERTS_SMP +#define PATCH_TS(Type, Tuple, Hp, Bp, Tracer) \ + PATCH_TS__((Type), (Tuple), (Hp), (Bp), NULL) +#else +#define PATCH_TS(Type, Tuple, Hp, Bp, Tracer) \ + PATCH_TS__((Type), (Tuple), (Hp), (Bp), (Tracer)) +#endif + +static ERTS_INLINE void +patch_ts(int ts_type, Eterm tuple, Eterm* hp, ErlHeapFragment *bp, Process *tracer) +{ + Eterm *tptr = tuple_val(tuple); + int arity = arityval(*tptr); + + ASSERT(ts_type); + ASSERT((tptr+arity+1) == hp); + + tptr[0] = make_arityval(arity+1); + tptr[1] = am_trace_ts; + + *hp = write_ts(ts_type, hp+1, bp, tracer); +} + #ifdef ERTS_SMP static void enqueue_sys_msg_unlocked(enum ErtsSysMsgType type, Eterm from, @@ -365,23 +623,6 @@ erts_get_system_profile(void) { return profile; } - -#ifdef HAVE_ERTS_NOW_CPU -# define GET_NOW(m, s, u) \ -do { \ - if (erts_cpu_timestamp) \ - erts_get_now_cpu(m, s, u); \ - else \ - get_now(m, s, u); \ -} while (0) -#else -# define GET_NOW(m, s, u) do {get_now(m, s, u);} while (0) -#endif - - - -static Eterm* patch_ts(Eterm tuple4, Eterm* hp); - #ifdef ERTS_SMP static void do_send_to_port(Eterm to, @@ -436,11 +677,11 @@ WRITE_SYS_MSG_TO_PORT(Eterm unused_to, /* Send {trace_ts, Pid, out, 0, Timestamp} * followed by {trace_ts, Pid, in, 0, NewTimestamp} * - * 'NewTimestamp' is fetched from GET_NOW() through patch_ts(). + * 'NewTimestamp' through patch_ts(). */ static void -do_send_schedfix_to_port(Port *trace_port, Eterm pid, Eterm timestamp) { -#define LOCAL_HEAP_SIZE (4+5+5) +do_send_schedfix_to_port(Port *trace_port, Eterm pid, Eterm timestamp, int ts_type) { +#define LOCAL_HEAP_SIZE (5+5+ERTS_TRACE_PATCH_TS_MAX_SIZE) DeclareTmpHeapNoproc(local_heap,LOCAL_HEAP_SIZE); Eterm message; Eterm *hp; @@ -462,9 +703,11 @@ do_send_schedfix_to_port(Port *trace_port, Eterm pid, Eterm timestamp) { SYS_MSG_TYPE_UNDEFINED, message); - message = TUPLE4(hp, am_trace_ts, pid, am_in, mfarity); - hp += 5; - hp = patch_ts(message, hp); + + message = TUPLE5(hp, am_trace_ts, pid, am_in, mfarity, + NIL /* Will be overwritten by timestamp */); + hp += 6; + hp[-1] = write_ts(ts_type, hp, NULL, NULL); do_send_to_port(trace_port->common.id, trace_port, @@ -481,7 +724,7 @@ do_send_schedfix_to_port(Port *trace_port, Eterm pid, Eterm timestamp) { * It is assumed that 'message' is not an 'out' message. * * 'c_p' is the currently executing process, "tracee" is the traced process - * which 'message' concerns => if (*tracee_flags & F_TIMESTAMP), + * which 'message' concerns => if (*tracee_flags & F_TIMESTAMP_MASK), * 'message' must contain a timestamp. */ static void @@ -489,8 +732,9 @@ send_to_port(Process *c_p, Eterm message, Eterm *tracer_pid, Uint *tracee_flags) { Port* trace_port; #ifndef ERTS_SMP -#define LOCAL_HEAP_SIZE (4) - Eterm ts, *hp; + int ts_type; +#define LOCAL_HEAP_SIZE ERTS_TRACE_PATCH_TS_MAX_SIZE + Eterm ts; DeclareTmpHeapNoproc(local_heap,LOCAL_HEAP_SIZE); #endif @@ -519,7 +763,7 @@ send_to_port(Process *c_p, Eterm message, */ if ( c_p == NULL || - (! IS_TRACED_FL(c_p, F_TRACE_SCHED | F_TIMESTAMP))) { + (! IS_TRACED_FL(c_p, F_TRACE_SCHED | F_TIMESTAMP_MASK))) { #endif do_send_to_port(*tracer_pid, trace_port, @@ -538,22 +782,12 @@ send_to_port(Process *c_p, Eterm message, */ UseTmpHeapNoproc(LOCAL_HEAP_SIZE); - if (*tracee_flags & F_TIMESTAMP) { - ASSERT(is_tuple(message)); - hp = tuple_val(message); - ts = hp[arityval(hp[0])]; - } else { - /* A fake schedule might be needed, - * but this message does not contain a timestamp. - * Create a dummy trace message with timestamp to be - * passed to do_send_schedfix_to_port(). - */ - Uint ms,s,us; - GET_NOW(&ms, &s, &us); - hp = local_heap; - ts = TUPLE3(hp, make_small(ms), make_small(s), make_small(us)); - hp += 4; - } + /* A fake schedule might be needed. + * Create a dummy trace message with timestamp to be + * passed to do_send_schedfix_to_port(). + */ + ts_type = TFLGS_TS_TYPE(c_p); + ts = write_ts(ts_type, local_heap, NULL, NULL); trace_port->control_flags &= ~PORT_CONTROL_FLAG_HEAVY; do_send_to_port(*tracer_pid, @@ -572,7 +806,7 @@ send_to_port(Process *c_p, Eterm message, * just after writning the real trace message, and now gets scheduled * in again. */ - do_send_schedfix_to_port(trace_port, c_p->common.id, ts); + do_send_schedfix_to_port(trace_port, c_p->common.id, ts, ts_type); } erts_port_release(trace_port); @@ -641,20 +875,19 @@ profile_send(Eterm from, Eterm message) { /* A fake schedule out/in message pair will be sent, * if the driver so requests. - * If (timestamp == NIL), one is fetched from GET_NOW(). * * 'c_p' is the currently executing process, may be NULL. */ static void seq_trace_send_to_port(Process *c_p, Eterm seq_tracer, - Eterm message, - Eterm timestamp) + Eterm message) { Port* trace_port; #ifndef ERTS_SMP - Eterm ts, *hp; -#define LOCAL_HEAP_SIZE (4) + int ts_type; + Eterm ts; +#define LOCAL_HEAP_SIZE ERTS_TRACE_PATCH_TS_MAX_SIZE DeclareTmpHeapNoproc(local_heap,LOCAL_HEAP_SIZE); UseTmpHeapNoproc(LOCAL_HEAP_SIZE); #endif @@ -679,7 +912,7 @@ seq_trace_send_to_port(Process *c_p, } if (c_p == NULL - || (! IS_TRACED_FL(c_p, F_TRACE_SCHED | F_TIMESTAMP))) { + || (! IS_TRACED_FL(c_p, F_TRACE_SCHED | F_TIMESTAMP_MASK))) { #endif do_send_to_port(seq_tracer, trace_port, @@ -696,20 +929,12 @@ seq_trace_send_to_port(Process *c_p, * with 'running' and 'timestamp'. */ - if (timestamp != NIL) { - ts = timestamp; - } else { - /* A fake schedule might be needed, - * but this message does not contain a timestamp. - * Create a dummy trace message with timestamp to be - * passed to do_send_schedfix_to_port(). - */ - Uint ms,s,us; - GET_NOW(&ms, &s, &us); - hp = local_heap; - ts = TUPLE3(hp, make_small(ms), make_small(s), make_small(us)); - hp += 4; - } + /* A fake schedule might be needed. + * Create a dummy trace message with timestamp to be + * passed to do_send_schedfix_to_port(). + */ + ts_type = TFLGS_TS_TYPE(c_p); + ts = write_ts(ts_type, local_heap, NULL, NULL); trace_port->control_flags &= ~PORT_CONTROL_FLAG_HEAVY; do_send_to_port(seq_tracer, @@ -728,7 +953,7 @@ seq_trace_send_to_port(Process *c_p, * just after writing the real trace message, and now gets scheduled * in again. */ - do_send_schedfix_to_port(trace_port, c_p->common.id, ts); + do_send_schedfix_to_port(trace_port, c_p->common.id, ts, ts_type); } erts_port_release(trace_port); @@ -738,32 +963,6 @@ seq_trace_send_to_port(Process *c_p, #endif } -#define TS_HEAP_WORDS 5 -#define TS_SIZE(p) ((ERTS_TRACE_FLAGS((p)) & F_TIMESTAMP) \ - ? TS_HEAP_WORDS \ - : 0) - -/* - * Patch a timestamp into a tuple. The tuple must be the last thing - * built on the heap. - * - * Returns the new hp pointer. -*/ -static Eterm* -patch_ts(Eterm tuple, Eterm* hp) -{ - Uint ms, s, us; - Eterm* ptr = tuple_val(tuple); - int arity = arityval(*ptr); - - ASSERT((ptr+arity+1) == hp); - ptr[0] = make_arityval(arity+1); - ptr[1] = am_trace_ts; - GET_NOW(&ms, &s, &us); - *hp = TUPLE3(hp+1, make_small(ms), make_small(s), make_small(us)); - return hp+5; -} - static ERTS_INLINE void send_to_tracer(Process *tracee, ERTS_TRACER_REF_TYPE tracer_ref, @@ -776,13 +975,13 @@ send_to_tracer(Process *tracee, erts_smp_mtx_lock(&smq_mtx); - if (ERTS_TRACE_FLAGS(tracee) & F_TIMESTAMP) - *hpp = patch_ts(msg, *hpp); - - if (is_internal_pid(ERTS_TRACER_PROC(tracee))) + if (is_internal_pid(ERTS_TRACER_PROC(tracee))) { + PATCH_TS(TFLGS_TS_TYPE(tracee), msg, *hpp, bp, tracer_ref); ERTS_ENQ_TRACE_MSG(tracee->common.id, tracer_ref, msg, bp); + } else { ASSERT(is_internal_port(ERTS_TRACER_PROC(tracee))); + PATCH_TS(TFLGS_TS_TYPE(tracee), msg, *hpp, NULL, NULL); send_to_port(no_fake_sched ? NULL : tracee, msg, &ERTS_TRACER_PROC(tracee), @@ -796,7 +995,7 @@ send_to_tracer(Process *tracee, static void trace_sched_aux(Process *p, Eterm what, int never_fake_sched) { -#define LOCAL_HEAP_SIZE (5+4+1+TS_HEAP_WORDS) +#define LOCAL_HEAP_SIZE (5+4+1+ERTS_TRACE_PATCH_TS_MAX_SIZE) DeclareTmpHeap(local_heap,LOCAL_HEAP_SIZE,p); Eterm tmp, mess, *hp; ErlHeapFragment *bp = NULL; @@ -852,7 +1051,7 @@ trace_sched_aux(Process *p, Eterm what, int never_fake_sched) size += 4; if (sched_no) size += 1; - size += TS_SIZE(p); + size += PATCH_TS_SIZE(p); hp = ERTS_ALLOC_SYSMSG_HEAP(size, &bp, &off_heap, tracer_ref); } @@ -926,7 +1125,7 @@ trace_send(Process *p, Eterm to, Eterm msg) } if (is_internal_port(ERTS_TRACER_PROC(p))) { -#define LOCAL_HEAP_SIZE (11) +#define LOCAL_HEAP_SIZE (6 + ERTS_TRACE_PATCH_TS_MAX_SIZE) DeclareTmpHeapNoproc(local_heap,LOCAL_HEAP_SIZE); UseTmpHeapNoproc(LOCAL_HEAP_SIZE); @@ -934,9 +1133,7 @@ trace_send(Process *p, Eterm to, Eterm msg) mess = TUPLE5(hp, am_trace, p->common.id, operation, msg, to); hp += 6; erts_smp_mtx_lock(&smq_mtx); - if (ERTS_TRACE_FLAGS(p) & F_TIMESTAMP) { - hp = patch_ts(mess, hp); - } + PATCH_TS(TFLGS_TS_TYPE(p), mess, hp, NULL, NULL); send_to_port(p, mess, &ERTS_TRACER_PROC(p), &ERTS_TRACE_FLAGS(p)); UnUseTmpHeapNoproc(LOCAL_HEAP_SIZE); #undef LOCAL_HEAP_SIZE @@ -955,7 +1152,7 @@ trace_send(Process *p, Eterm to, Eterm msg) sz_msg = size_object(msg); sz_to = size_object(to); - need = sz_msg + sz_to + 6 + TS_SIZE(p); + need = sz_msg + sz_to + 6 + PATCH_TS_SIZE(p); hp = ERTS_ALLOC_SYSMSG_HEAP(need, &bp, &off_heap, tracer_ref); @@ -972,10 +1169,7 @@ trace_send(Process *p, Eterm to, Eterm msg) erts_smp_mtx_lock(&smq_mtx); - if (ERTS_TRACE_FLAGS(p) & F_TIMESTAMP) { - patch_ts(mess, hp); - } - + PATCH_TS(TFLGS_TS_TYPE(p), mess, hp, bp, tracer_ref); ERTS_ENQ_TRACE_MSG(p->common.id, tracer_ref, mess, bp); erts_smp_mtx_unlock(&smq_mtx); } @@ -992,7 +1186,7 @@ trace_receive(Process *rp, Eterm msg) Eterm* hp; if (is_internal_port(ERTS_TRACER_PROC(rp))) { -#define LOCAL_HEAP_SIZE (10) +#define LOCAL_HEAP_SIZE (5+ERTS_TRACE_PATCH_TS_MAX_SIZE) DeclareTmpHeapNoproc(local_heap,LOCAL_HEAP_SIZE); UseTmpHeapNoproc(LOCAL_HEAP_SIZE); @@ -1000,9 +1194,7 @@ trace_receive(Process *rp, Eterm msg) mess = TUPLE4(hp, am_trace, rp->common.id, am_receive, msg); hp += 5; erts_smp_mtx_lock(&smq_mtx); - if (ERTS_TRACE_FLAGS(rp) & F_TIMESTAMP) { - hp = patch_ts(mess, hp); - } + PATCH_TS(TFLGS_TS_TYPE(rp), mess, hp, NULL, NULL); send_to_port(rp, mess, &ERTS_TRACER_PROC(rp), &ERTS_TRACE_FLAGS(rp)); UnUseTmpHeapNoproc(LOCAL_HEAP_SIZE); #undef LOCAL_HEAP_SIZE @@ -1021,7 +1213,7 @@ trace_receive(Process *rp, Eterm msg) sz_msg = size_object(msg); - hsz = sz_msg + 5 + TS_SIZE(rp); + hsz = sz_msg + 5 + PATCH_TS_SIZE(rp); hp = ERTS_ALLOC_SYSMSG_HEAP(hsz, &bp, &off_heap, tracer_ref); @@ -1031,10 +1223,7 @@ trace_receive(Process *rp, Eterm msg) erts_smp_mtx_lock(&smq_mtx); - if (ERTS_TRACE_FLAGS(rp) & F_TIMESTAMP) { - patch_ts(mess, hp); - } - + PATCH_TS(TFLGS_TS_TYPE(rp), mess, hp, bp, tracer_ref); ERTS_ENQ_TRACE_MSG(rp->common.id, tracer_ref, mess, bp); erts_smp_mtx_unlock(&smq_mtx); } @@ -1084,6 +1273,7 @@ seq_trace_output_generic(Eterm token, Eterm msg, Uint type, Eterm type_atom; int sz_exit; Eterm seq_tracer; + int ts_type; seq_tracer = erts_get_system_seq_tracer(); @@ -1111,8 +1301,10 @@ seq_trace_output_generic(Eterm token, Eterm msg, Uint type, return; /* no need to send anything */ } + ts_type = ERTS_SEQTFLGS2TSTYPE(unsigned_val(SEQ_TRACE_T_FLAGS(token))); + if (is_internal_port(seq_tracer)) { -#define LOCAL_HEAP_SIZE (64) +#define LOCAL_HEAP_SIZE (60 + ERTS_TRACE_PATCH_TS_MAX_SIZE) DeclareTmpHeapNoproc(local_heap,LOCAL_HEAP_SIZE); UseTmpHeapNoproc(LOCAL_HEAP_SIZE); @@ -1128,17 +1320,17 @@ seq_trace_output_generic(Eterm token, Eterm msg, Uint type, mess = TUPLE5(hp, type_atom, lastcnt_serial, SEQ_TRACE_T_SENDER(token), receiver, msg); hp += 6; + erts_smp_mtx_lock(&smq_mtx); - if ((unsigned_val(SEQ_TRACE_T_FLAGS(token)) & SEQ_TRACE_TIMESTAMP) == 0) { + if (!ts_type) { mess = TUPLE3(hp, am_seq_trace, label, mess); - seq_trace_send_to_port(NULL, seq_tracer, mess, NIL); + seq_trace_send_to_port(NULL, seq_tracer, mess); } else { - Uint ms,s,us,ts; - GET_NOW(&ms, &s, &us); - ts = TUPLE3(hp, make_small(ms),make_small(s), make_small(us)); - hp += 4; - mess = TUPLE4(hp, am_seq_trace, label, mess, ts); - seq_trace_send_to_port(process, seq_tracer, mess, ts); + mess = TUPLE4(hp, am_seq_trace, label, mess, + NIL /* Will be overwritten by timestamp */); + hp += 5; + hp[-1] = write_ts(ts_type, hp, NULL, NULL); + seq_trace_send_to_port(process, seq_tracer, mess); } UnUseTmpHeapNoproc(LOCAL_HEAP_SIZE); #undef LOCAL_HEAP_SIZE @@ -1173,8 +1365,7 @@ seq_trace_output_generic(Eterm token, Eterm msg, Uint type, sz_lastcnt_serial = 3; /* TUPLE2 */ sz_msg = size_object(msg); - sz_ts = ((unsigned_val(SEQ_TRACE_T_FLAGS(token)) & SEQ_TRACE_TIMESTAMP) ? - 5 : 0); + sz_ts = patch_ts_size(ts_type); if (exitfrom != NIL) { sz_exit = 4; /* create {'EXIT',exitfrom,msg} */ sz_exitfrom = size_object(exitfrom); @@ -1218,14 +1409,20 @@ seq_trace_output_generic(Eterm token, Eterm msg, Uint type, erts_smp_mtx_lock(&smq_mtx); - if (sz_ts) {/* timestamp should be included */ - Uint ms,s,us,ts; - GET_NOW(&ms, &s, &us); - ts = TUPLE3(hp, make_small(ms),make_small(s), make_small(us)); - hp += 4; - mess = TUPLE4(hp, am_seq_trace, label, mess, ts); - } else { + if (!ts_type) mess = TUPLE3(hp, am_seq_trace, label, mess); + else { + mess = TUPLE4(hp, am_seq_trace, label, mess, + NIL /* Will be overwritten by timestamp */); + hp += 5; + /* Write timestamp in element 6 of the 'msg' tuple */ + hp[-1] = write_ts(ts_type, hp, bp, +#ifndef ERTS_SMP + tracer +#else + NULL +#endif + ); } #ifdef ERTS_SMP @@ -1244,7 +1441,7 @@ seq_trace_output_generic(Eterm token, Eterm msg, Uint type, void erts_trace_return_to(Process *p, BeamInstr *pc) { -#define LOCAL_HEAP_SIZE (4+5+5) +#define LOCAL_HEAP_SIZE (4+5+ERTS_TRACE_PATCH_TS_MAX_SIZE) Eterm* hp; Eterm mfa; Eterm mess; @@ -1269,9 +1466,7 @@ erts_trace_return_to(Process *p, BeamInstr *pc) erts_smp_mtx_lock(&smq_mtx); - if (ERTS_TRACE_FLAGS(p) & F_TIMESTAMP) { - hp = patch_ts(mess, hp); - } + PATCH_TS(TFLGS_TS_TYPE(p), mess, hp, NULL, NULL); if (is_internal_port(ERTS_TRACER_PROC(p))) { send_to_port(p, mess, &ERTS_TRACER_PROC(p), &ERTS_TRACE_FLAGS(p)); @@ -1318,6 +1513,7 @@ erts_trace_return(Process* p, BeamInstr* fi, Eterm retval, Eterm *tracer_pid) Eterm mod, name; int arity; Uint meta_flags, *tracee_flags; + int ts_type; #ifdef ERTS_SMP Eterm tracee; #endif @@ -1353,7 +1549,7 @@ erts_trace_return(Process* p, BeamInstr* fi, Eterm retval, Eterm *tracer_pid) * meta trace => * use fixed flag set instead of process flags */ - meta_flags = F_TRACE_CALLS | F_TIMESTAMP; + meta_flags = F_TRACE_CALLS | F_NOW_TS; tracee_flags = &meta_flags; #ifdef ERTS_SMP tracee = NIL; @@ -1367,8 +1563,10 @@ erts_trace_return(Process* p, BeamInstr* fi, Eterm retval, Eterm *tracer_pid) name = fi[1]; arity = fi[2]; + ts_type = ERTS_TFLGS2TSTYPE(*tracee_flags); + if (is_internal_port(*tracer_pid)) { -#define LOCAL_HEAP_SIZE (4+6+5) +#define LOCAL_HEAP_SIZE (4+6+ERTS_TRACE_PATCH_TS_MAX_SIZE) DeclareTmpHeapNoproc(local_heap,LOCAL_HEAP_SIZE); UseTmpHeapNoproc(LOCAL_HEAP_SIZE); hp = local_heap; @@ -1377,9 +1575,7 @@ erts_trace_return(Process* p, BeamInstr* fi, Eterm retval, Eterm *tracer_pid) mess = TUPLE5(hp, am_trace, p->common.id, am_return_from, mfa, retval); hp += 6; erts_smp_mtx_lock(&smq_mtx); - if (*tracee_flags & F_TIMESTAMP) { - hp = patch_ts(mess, hp); - } + PATCH_TS(ts_type, mess, hp, NULL, NULL); send_to_port(p, mess, tracer_pid, tracee_flags); UnUseTmpHeapNoproc(LOCAL_HEAP_SIZE); #undef LOCAL_HEAP_SIZE @@ -1390,24 +1586,15 @@ erts_trace_return(Process* p, BeamInstr* fi, Eterm retval, Eterm *tracer_pid) ERTS_TRACER_REF_TYPE tracer_ref; unsigned size; unsigned retval_size; -#ifdef DEBUG - Eterm* limit; -#endif ASSERT(is_internal_pid(*tracer_pid)); ERTS_GET_TRACER_REF(tracer_ref, *tracer_pid, *tracee_flags); - + retval_size = size_object(retval); - size = 6 + 4 + retval_size; - if (*tracee_flags & F_TIMESTAMP) { - size += 1+4; - } + size = 6 + 4 + retval_size + patch_ts_size(ts_type); hp = ERTS_ALLOC_SYSMSG_HEAP(size, &bp, &off_heap, tracer_ref); -#ifdef DEBUG - limit = hp + size; -#endif /* * Build the trace tuple and put it into receive queue of the tracer process. @@ -1421,11 +1608,7 @@ erts_trace_return(Process* p, BeamInstr* fi, Eterm retval, Eterm *tracer_pid) erts_smp_mtx_lock(&smq_mtx); - if (*tracee_flags & F_TIMESTAMP) { - hp = patch_ts(mess, hp); - } - - ASSERT(hp == limit); + PATCH_TS(ts_type, mess, hp, bp, tracer_ref); ERTS_ENQ_TRACE_MSG(tracee, tracer_ref, mess, bp); erts_smp_mtx_unlock(&smq_mtx); @@ -1448,6 +1631,7 @@ erts_trace_exception(Process* p, BeamInstr mfa[3], Eterm class, Eterm value, Eterm cv; Eterm mess; Uint meta_flags, *tracee_flags; + int ts_type; #ifdef ERTS_SMP Eterm tracee; #endif @@ -1486,15 +1670,17 @@ erts_trace_exception(Process* p, BeamInstr mfa[3], Eterm class, Eterm value, * meta trace => * use fixed flag set instead of process flags */ - meta_flags = F_TRACE_CALLS | F_TIMESTAMP; + meta_flags = F_TRACE_CALLS | F_NOW_TS; tracee_flags = &meta_flags; #ifdef ERTS_SMP tracee = NIL; #endif } + ts_type = ERTS_TFLGS2TSTYPE(*tracee_flags); + if (is_internal_port(*tracer_pid)) { -#define LOCAL_HEAP_SIZE (4+3+6+5) +#define LOCAL_HEAP_SIZE (4+3+6+ERTS_TRACE_PATCH_TS_MAX_SIZE) DeclareTmpHeapNoproc(local_heap,LOCAL_HEAP_SIZE); UseTmpHeapNoproc(LOCAL_HEAP_SIZE); @@ -1507,10 +1693,7 @@ erts_trace_exception(Process* p, BeamInstr mfa[3], Eterm class, Eterm value, hp += 6; ASSERT((hp - local_heap) <= LOCAL_HEAP_SIZE); erts_smp_mtx_lock(&smq_mtx); - if (*tracee_flags & F_TIMESTAMP) { - hp = patch_ts(mess, hp); /* hp += 5 */ - ASSERT((hp - local_heap) == LOCAL_HEAP_SIZE); - } + PATCH_TS(ts_type, mess, hp, NULL, NULL); send_to_port(p, mess, tracer_pid, tracee_flags); UnUseTmpHeapNoproc(LOCAL_HEAP_SIZE); #undef LOCAL_HEAP_SIZE @@ -1521,24 +1704,15 @@ erts_trace_exception(Process* p, BeamInstr mfa[3], Eterm class, Eterm value, ERTS_TRACER_REF_TYPE tracer_ref; unsigned size; unsigned value_size; -#ifdef DEBUG - Eterm* limit; -#endif ASSERT(is_internal_pid(*tracer_pid)); ERTS_GET_TRACER_REF(tracer_ref, *tracer_pid, *tracee_flags); value_size = size_object(value); - size = 6 + 4 + 3 + value_size; - if (*tracee_flags & F_TIMESTAMP) { - size += 1+4; - } + size = 6 + 4 + 3 + value_size + patch_ts_size(ts_type); hp = ERTS_ALLOC_SYSMSG_HEAP(size, &bp, &off_heap, tracer_ref); -#ifdef DEBUG - limit = hp + size; -#endif /* * Build the trace tuple and put it into receive queue of the tracer process. @@ -1555,11 +1729,7 @@ erts_trace_exception(Process* p, BeamInstr mfa[3], Eterm class, Eterm value, erts_smp_mtx_lock(&smq_mtx); - if (*tracee_flags & F_TIMESTAMP) { - hp = patch_ts(mess, hp); - } - - ASSERT(hp == limit); + PATCH_TS(ts_type, mess, hp, bp, tracer_ref); ERTS_ENQ_TRACE_MSG(tracee, tracer_ref, mess, bp); erts_smp_mtx_unlock(&smq_mtx); @@ -1592,6 +1762,7 @@ erts_call_trace(Process* p, BeamInstr mfa[3], Binary *match_spec, Eterm pam_result = am_true; Eterm mess; Uint meta_flags, *tracee_flags; + int ts_type; #ifdef ERTS_SMP Eterm tracee; #endif @@ -1633,7 +1804,7 @@ erts_call_trace(Process* p, BeamInstr mfa[3], Binary *match_spec, /* No trace messages for sensitive processes. */ return 0; } - meta_flags = F_TRACE_CALLS | F_TIMESTAMP; + meta_flags = F_TRACE_CALLS | F_NOW_TS; tracee_flags = &meta_flags; #ifdef ERTS_SMP tracee = NIL; @@ -1676,12 +1847,14 @@ erts_call_trace(Process* p, BeamInstr mfa[3], Binary *match_spec, } args = transformed_args; + ts_type = ERTS_TFLGS2TSTYPE(*tracee_flags); + if (is_internal_port(*tracer_pid)) { #if HEAP_ON_C_STACK - Eterm local_heap[64+MAX_ARG]; + Eterm local_heap[60+ERTS_TRACE_PATCH_TS_MAX_SIZE+MAX_ARG]; #else Eterm *local_heap = erts_alloc(ERTS_ALC_T_TEMP_TERM, - sizeof(Eterm)*(64+MAX_ARG)); + sizeof(Eterm)*(60+ERTS_TRACE_PATCH_TS_MAX_SIZE+MAX_ARG)); #endif hp = local_heap; @@ -1796,9 +1969,7 @@ erts_call_trace(Process* p, BeamInstr mfa[3], Binary *match_spec, *hp++ = pam_result; } erts_smp_mtx_lock(&smq_mtx); - if (*tracee_flags & F_TIMESTAMP) { - hp = patch_ts(mess, hp); - } + PATCH_TS(ts_type, mess, hp, NULL, NULL); send_to_port(p, mess, tracer_pid, tracee_flags); erts_smp_mtx_unlock(&smq_mtx); erts_match_set_release_result(p); @@ -1820,9 +1991,6 @@ erts_call_trace(Process* p, BeamInstr mfa[3], Binary *match_spec, unsigned sizes[MAX_ARG]; unsigned pam_result_size = 0; int invalid_tracer; -#ifdef DEBUG - Eterm* limit; -#endif ASSERT(is_internal_pid(*tracer_pid)); @@ -1915,10 +2083,7 @@ erts_call_trace(Process* p, BeamInstr mfa[3], Binary *match_spec, size += sizes[i]; } } - if (*tracee_flags & F_TIMESTAMP) { - size += 1 + 4; - /* One element in trace tuple + timestamp tuple. */ - } + size += patch_ts_size(ts_type); if (pam_result != am_true) { pam_result_size = size_object(pam_result); size += 1 + pam_result_size; @@ -1926,9 +2091,6 @@ erts_call_trace(Process* p, BeamInstr mfa[3], Binary *match_spec, } hp = ERTS_ALLOC_SYSMSG_HEAP(size, &bp, &off_heap, tracer_ref); -#ifdef DEBUG - limit = hp + size; -#endif /* * Build the the {M,F,A} tuple in the message buffer. @@ -1971,11 +2133,7 @@ erts_call_trace(Process* p, BeamInstr mfa[3], Binary *match_spec, erts_smp_mtx_lock(&smq_mtx); - if (*tracee_flags & F_TIMESTAMP) { - hp = patch_ts(mess, hp); - } - - ASSERT(hp == limit); + PATCH_TS(ts_type, mess, hp, bp, tracer_ref); ERTS_ENQ_TRACE_MSG(tracee, tracer_ref, mess, bp); erts_smp_mtx_unlock(&smq_mtx); UnUseTmpHeap(ERL_SUB_BIN_SIZE,p); @@ -2010,9 +2168,7 @@ trace_proc(Process *c_p, Process *t_p, Eterm what, Eterm data) mess = TUPLE4(hp, am_trace, t_p->common.id, what, data); hp += 5; erts_smp_mtx_lock(&smq_mtx); - if (ERTS_TRACE_FLAGS(t_p) & F_TIMESTAMP) { - hp = patch_ts(mess, hp); - } + PATCH_TS(TFLGS_TS_TYPE(t_p), mess, hp, NULL, NULL); send_to_port( #ifndef ERTS_SMP /* No fake schedule out and in again after an exit */ @@ -2042,7 +2198,7 @@ trace_proc(Process *c_p, Process *t_p, Eterm what, Eterm data) sz_data = size_object(data); - need = sz_data + 5 + TS_SIZE(t_p); + need = sz_data + 5 + PATCH_TS_SIZE(t_p); hp = ERTS_ALLOC_SYSMSG_HEAP(need, &bp, &off_heap, tracer_ref); @@ -2052,9 +2208,7 @@ trace_proc(Process *c_p, Process *t_p, Eterm what, Eterm data) erts_smp_mtx_lock(&smq_mtx); - if (ERTS_TRACE_FLAGS(t_p) & F_TIMESTAMP) { - hp = patch_ts(mess, hp); - } + PATCH_TS(TFLGS_TS_TYPE(t_p), mess, hp, bp, tracer_ref); ERTS_ENQ_TRACE_MSG(t_p->common.id, tracer_ref, mess, bp); erts_smp_mtx_unlock(&smq_mtx); @@ -2088,9 +2242,7 @@ trace_proc_spawn(Process *p, Eterm pid, mess = TUPLE5(hp, am_trace, p->common.id, am_spawn, pid, mfa); hp += 6; erts_smp_mtx_lock(&smq_mtx); - if (ERTS_TRACE_FLAGS(p) & F_TIMESTAMP) { - hp = patch_ts(mess, hp); - } + PATCH_TS(TFLGS_TS_TYPE(p), mess, hp, NULL, NULL); send_to_port(p, mess, &ERTS_TRACER_PROC(p), &ERTS_TRACE_FLAGS(p)); UnUseTmpHeapNoproc(LOCAL_HEAP_SIZE); #undef LOCAL_HEAP_SIZE @@ -2111,7 +2263,7 @@ trace_proc_spawn(Process *p, Eterm pid, sz_args = size_object(args); sz_pid = size_object(pid); - need = sz_args + 4 + 6 + TS_SIZE(p); + need = sz_args + 4 + 6 + PATCH_TS_SIZE(p); hp = ERTS_ALLOC_SYSMSG_HEAP(need, &bp, &off_heap, tracer_ref); @@ -2124,9 +2276,7 @@ trace_proc_spawn(Process *p, Eterm pid, erts_smp_mtx_lock(&smq_mtx); - if (ERTS_TRACE_FLAGS(p) & F_TIMESTAMP) { - hp = patch_ts(mess, hp); - } + PATCH_TS(TFLGS_TS_TYPE(p), mess, hp, bp, tracer_ref); ERTS_ENQ_TRACE_MSG(p->common.id, tracer_ref, mess, bp); erts_smp_mtx_unlock(&smq_mtx); @@ -2208,11 +2358,8 @@ trace_gc(Process *p, Eterm what) #define LOCAL_HEAP_SIZE \ (sizeof(values)/sizeof(*values)) * \ (2/*cons*/ + 3/*2-tuple*/ + BIG_UINT_HEAP_SIZE) + \ - 5/*4-tuple */ + TS_HEAP_WORDS + 5/*4-tuple */ + ERTS_TRACE_PATCH_TS_MAX_SIZE DeclareTmpHeap(local_heap,LOCAL_HEAP_SIZE,p); -#ifdef DEBUG - Eterm* limit; -#endif ERTS_CT_ASSERT(sizeof(values)/sizeof(*values) == sizeof(tags)/sizeof(Eterm)); @@ -2227,7 +2374,7 @@ trace_gc(Process *p, Eterm what) sizeof(values)/sizeof(*values), tags, values); - size += 5/*4-tuple*/ + TS_SIZE(p); + size += 5/*4-tuple*/ + PATCH_TS_SIZE(p); #endif } else { ASSERT(is_internal_pid(ERTS_TRACER_PROC(p))); @@ -2242,15 +2389,12 @@ trace_gc(Process *p, Eterm what) sizeof(values)/sizeof(*values), tags, values); - size += 5/*4-tuple*/ + TS_SIZE(p); + size += 5/*4-tuple*/ + PATCH_TS_SIZE(p); hp = ERTS_ALLOC_SYSMSG_HEAP(size, &bp, &off_heap, tracer_ref); } -#ifdef DEBUG - limit = hp + size; ASSERT(size <= LOCAL_HEAP_SIZE); -#endif msg = erts_bld_atom_uword_2tup_list(&hp, NULL, @@ -2263,14 +2407,14 @@ trace_gc(Process *p, Eterm what) erts_smp_mtx_lock(&smq_mtx); - if (ERTS_TRACE_FLAGS(p) & F_TIMESTAMP) { - hp = patch_ts(msg, hp); - } - ASSERT(hp == limit); - if (is_internal_port(ERTS_TRACER_PROC(p))) + if (is_internal_port(ERTS_TRACER_PROC(p))) { + PATCH_TS(TFLGS_TS_TYPE(p), msg, hp, NULL, NULL); send_to_port(p, msg, &ERTS_TRACER_PROC(p), &ERTS_TRACE_FLAGS(p)); - else + } + else { + PATCH_TS(TFLGS_TS_TYPE(p), msg, hp, bp, tracer_ref); ERTS_ENQ_TRACE_MSG(p->common.id, tracer_ref, msg, bp); + } erts_smp_mtx_unlock(&smq_mtx); UnUseTmpHeap(LOCAL_HEAP_SIZE,p); #undef LOCAL_HEAP_SIZE @@ -2574,19 +2718,18 @@ monitor_generic(Process *p, Eterm type, Eterm spec) { void profile_scheduler(Eterm scheduler_id, Eterm state) { - Eterm *hp, msg, timestamp; - Uint Ms, s, us; + Eterm *hp, msg; + ErlHeapFragment *bp = NULL; #ifndef ERTS_SMP -#define LOCAL_HEAP_SIZE (4 + 7) +#define LOCAL_HEAP_SIZE (7 + ERTS_TRACE_PATCH_TS_MAX_SIZE) DeclareTmpHeapNoproc(local_heap,LOCAL_HEAP_SIZE); UseTmpHeapNoproc(LOCAL_HEAP_SIZE); hp = local_heap; #else - ErlHeapFragment *bp; Uint hsz; - hsz = 4 + 7; + hsz = 7 + patch_ts_size(erts_system_profile_ts_type)-1; bp = new_message_buffer(hsz); hp = bp->mem; @@ -2606,10 +2749,13 @@ profile_scheduler(Eterm scheduler_id, Eterm state) { break; } - GET_NOW(&Ms, &s, &us); - timestamp = TUPLE3(hp, make_small(Ms), make_small(s), make_small(us)); hp += 4; - msg = TUPLE6(hp, am_profile, am_scheduler, scheduler_id, state, - make_small(active_sched), timestamp); hp += 7; + msg = TUPLE6(hp, am_profile, am_scheduler, scheduler_id, + state, make_small(active_sched), + NIL /* Will be overwritten by timestamp */); + hp += 7; + + /* Write timestamp in element 6 of the 'msg' tuple */ + hp[-1] = write_ts(erts_system_profile_ts_type, hp, bp, NULL); #ifndef ERTS_SMP profile_send(NIL, msg); @@ -2680,7 +2826,7 @@ trace_port_open(Port *p, Eterm calling_pid, Eterm drv_name) { Eterm* hp; if (is_internal_port(ERTS_TRACER_PROC(p))) { -#define LOCAL_HEAP_SIZE (5+6) +#define LOCAL_HEAP_SIZE (6+ERTS_TRACE_PATCH_TS_MAX_SIZE) DeclareTmpHeapNoproc(local_heap,LOCAL_HEAP_SIZE); UseTmpHeapNoproc(LOCAL_HEAP_SIZE); @@ -2689,9 +2835,7 @@ trace_port_open(Port *p, Eterm calling_pid, Eterm drv_name) { mess = TUPLE5(hp, am_trace, calling_pid, am_open, p->common.id, drv_name); hp += 6; erts_smp_mtx_lock(&smq_mtx); - if (ERTS_TRACE_FLAGS(p) & F_TIMESTAMP) { - hp = patch_ts(mess, hp); - } + PATCH_TS(TFLGS_TS_TYPE(p), mess, hp, NULL, NULL); /* No fake schedule */ send_to_port(NULL, mess, &ERTS_TRACER_PROC(p), &ERTS_TRACE_FLAGS(p)); UnUseTmpHeapNoproc(LOCAL_HEAP_SIZE); @@ -2705,7 +2849,7 @@ trace_port_open(Port *p, Eterm calling_pid, Eterm drv_name) { ASSERT(is_internal_pid(ERTS_TRACER_PROC(p))); - sz_data = 6 + TS_SIZE(p); + sz_data = 6 + PATCH_TS_SIZE(p); ERTS_GET_TRACER_REF(tracer_ref, ERTS_TRACER_PROC(p), @@ -2718,9 +2862,7 @@ trace_port_open(Port *p, Eterm calling_pid, Eterm drv_name) { erts_smp_mtx_lock(&smq_mtx); - if (ERTS_TRACE_FLAGS(p) & F_TIMESTAMP) { - hp = patch_ts(mess, hp); - } + PATCH_TS(TFLGS_TS_TYPE(p), mess, hp, bp, tracer_ref); ERTS_ENQ_TRACE_MSG(p->common.id, tracer_ref, mess, bp); erts_smp_mtx_unlock(&smq_mtx); @@ -2744,7 +2886,7 @@ trace_port(Port *t_p, Eterm what, Eterm data) { || erts_thr_progress_is_blocking()); if (is_internal_port(ERTS_TRACER_PROC(t_p))) { -#define LOCAL_HEAP_SIZE (5+5) +#define LOCAL_HEAP_SIZE (5+ERTS_TRACE_PATCH_TS_MAX_SIZE) DeclareTmpHeapNoproc(local_heap,LOCAL_HEAP_SIZE); UseTmpHeapNoproc(LOCAL_HEAP_SIZE); @@ -2752,9 +2894,7 @@ trace_port(Port *t_p, Eterm what, Eterm data) { mess = TUPLE4(hp, am_trace, t_p->common.id, what, data); hp += 5; erts_smp_mtx_lock(&smq_mtx); - if (ERTS_TRACE_FLAGS(t_p) & F_TIMESTAMP) { - hp = patch_ts(mess, hp); - } + PATCH_TS(TFLGS_TS_TYPE(t_p), mess, hp, NULL, NULL); /* No fake schedule */ send_to_port(NULL,mess,&ERTS_TRACER_PROC(t_p),&ERTS_TRACE_FLAGS(t_p)); UnUseTmpHeapNoproc(LOCAL_HEAP_SIZE); @@ -2768,7 +2908,7 @@ trace_port(Port *t_p, Eterm what, Eterm data) { ASSERT(is_internal_pid(ERTS_TRACER_PROC(t_p))); - sz_data = 5 + TS_SIZE(t_p); + sz_data = 5 + PATCH_TS_SIZE(t_p); ERTS_GET_TRACER_REF(tracer_ref, ERTS_TRACER_PROC(t_p), @@ -2781,9 +2921,7 @@ trace_port(Port *t_p, Eterm what, Eterm data) { erts_smp_mtx_lock(&smq_mtx); - if (ERTS_TRACE_FLAGS(t_p) & F_TIMESTAMP) { - hp = patch_ts(mess, hp); - } + PATCH_TS(TFLGS_TS_TYPE(t_p), mess, hp, bp, tracer_ref); ERTS_ENQ_TRACE_MSG(t_p->common.id, tracer_ref, mess, bp); erts_smp_mtx_unlock(&smq_mtx); @@ -2811,7 +2949,7 @@ trace_sched_ports_where(Port *p, Eterm what, Eterm where) { Eterm sched_id = am_undefined; if (is_internal_port(ERTS_TRACER_PROC(p))) { -#define LOCAL_HEAP_SIZE (5+6) +#define LOCAL_HEAP_SIZE (6+ERTS_TRACE_PATCH_TS_MAX_SIZE) DeclareTmpHeapNoproc(local_heap,LOCAL_HEAP_SIZE); UseTmpHeapNoproc(LOCAL_HEAP_SIZE); @@ -2834,9 +2972,8 @@ trace_sched_ports_where(Port *p, Eterm what, Eterm where) { hp += ws; erts_smp_mtx_lock(&smq_mtx); - if (ERTS_TRACE_FLAGS(p) & F_TIMESTAMP) { - hp = patch_ts(mess, hp); - } + + PATCH_TS(TFLGS_TS_TYPE(p), mess, hp, NULL, NULL); /* No fake scheduling */ send_to_port(NULL, mess, &ERTS_TRACER_PROC(p), &ERTS_TRACE_FLAGS(p)); @@ -2856,7 +2993,7 @@ trace_sched_ports_where(Port *p, Eterm what, Eterm where) { ERTS_TRACER_PROC(p), ERTS_TRACE_FLAGS(p)); - hp = ERTS_ALLOC_SYSMSG_HEAP(ws+TS_SIZE(p), &bp, &off_heap, tracer_ref); + hp = ERTS_ALLOC_SYSMSG_HEAP(ws+PATCH_TS_SIZE(p), &bp, &off_heap, tracer_ref); if (IS_TRACED_FL(p, F_TRACE_SCHED_NO)) { #ifdef ERTS_SMP @@ -2874,10 +3011,7 @@ trace_sched_ports_where(Port *p, Eterm what, Eterm where) { erts_smp_mtx_lock(&smq_mtx); - if (ERTS_TRACE_FLAGS(p) & F_TIMESTAMP) { - hp = patch_ts(mess, hp); - } - + PATCH_TS(TFLGS_TS_TYPE(p), mess, hp, bp, tracer_ref); ERTS_ENQ_TRACE_MSG(p->common.id, tracer_ref, mess, bp); erts_smp_mtx_unlock(&smq_mtx); } @@ -2887,13 +3021,12 @@ trace_sched_ports_where(Port *p, Eterm what, Eterm where) { void profile_runnable_port(Port *p, Eterm status) { - Uint Ms, s, us; - Eterm *hp, msg, timestamp; - + Eterm *hp, msg; + ErlHeapFragment *bp = NULL; Eterm count = make_small(0); #ifndef ERTS_SMP -#define LOCAL_HEAP_SIZE (4 + 6) +#define LOCAL_HEAP_SIZE (6 + ERTS_TRACE_PATCH_TS_MAX_SIZE) DeclareTmpHeapNoproc(local_heap,LOCAL_HEAP_SIZE); UseTmpHeapNoproc(LOCAL_HEAP_SIZE); @@ -2901,10 +3034,9 @@ profile_runnable_port(Port *p, Eterm status) { hp = local_heap; #else - ErlHeapFragment *bp; Uint hsz; - hsz = 4 + 6; + hsz = 6 + patch_ts_size(erts_system_profile_ts_type)-1; bp = new_message_buffer(hsz); hp = bp->mem; @@ -2912,9 +3044,12 @@ profile_runnable_port(Port *p, Eterm status) { erts_smp_mtx_lock(&smq_mtx); - GET_NOW(&Ms, &s, &us); - timestamp = TUPLE3(hp, make_small(Ms), make_small(s), make_small(us)); hp += 4; - msg = TUPLE5(hp, am_profile, p->common.id, status, count, timestamp); hp += 6; + msg = TUPLE5(hp, am_profile, p->common.id, status, count, + NIL /* Will be overwritten by timestamp */); + hp += 6; + + /* Write timestamp in element 5 of the 'msg' tuple */ + hp[-1] = write_ts(erts_system_profile_ts_type, hp, bp, NULL); #ifndef ERTS_SMP profile_send(p->common.id, msg); @@ -2929,20 +3064,19 @@ profile_runnable_port(Port *p, Eterm status) { /* Process profiling */ void profile_runnable_proc(Process *p, Eterm status){ - Uint Ms, s, us; - Eterm *hp, msg, timestamp; + Eterm *hp, msg; Eterm where = am_undefined; + ErlHeapFragment *bp = NULL; #ifndef ERTS_SMP -#define LOCAL_HEAP_SIZE (4 + 6 + 4) +#define LOCAL_HEAP_SIZE (4 + 6 + ERTS_TRACE_PATCH_TS_MAX_SIZE) DeclareTmpHeapNoproc(local_heap,LOCAL_HEAP_SIZE); UseTmpHeapNoproc(LOCAL_HEAP_SIZE); hp = local_heap; #else - ErlHeapFragment *bp; - Uint hsz = 4 + 6 + 4; + Uint hsz = 4 + 6 + patch_ts_size(erts_system_profile_ts_type)-1; #endif if (!p->current) { @@ -2951,7 +3085,7 @@ profile_runnable_proc(Process *p, Eterm status){ #ifdef ERTS_SMP if (!p->current) { - hsz = 4 + 6; + hsz -= 4; } bp = new_message_buffer(hsz); @@ -2966,9 +3100,13 @@ profile_runnable_proc(Process *p, Eterm status){ erts_smp_mtx_lock(&smq_mtx); - GET_NOW(&Ms, &s, &us); - timestamp = TUPLE3(hp, make_small(Ms), make_small(s), make_small(us)); hp += 4; - msg = TUPLE5(hp, am_profile, p->common.id, status, where, timestamp); hp += 6; + msg = TUPLE5(hp, am_profile, p->common.id, status, where, + NIL /* Will be overwritten by timestamp */); + hp += 6; + + /* Write timestamp in element 5 of the 'msg' tuple */ + hp[-1] = write_ts(erts_system_profile_ts_type, hp, bp, NULL); + #ifndef ERTS_SMP profile_send(p->common.id, msg); UnUseTmpHeapNoproc(LOCAL_HEAP_SIZE); diff --git a/erts/emulator/beam/erl_trace.h b/erts/emulator/beam/erl_trace.h index 7405490f76..a0058264d7 100644 --- a/erts/emulator/beam/erl_trace.h +++ b/erts/emulator/beam/erl_trace.h @@ -18,8 +18,38 @@ * %CopyrightEnd% */ +#ifndef ERL_TRACE_H__FLAGS__ +#define ERL_TRACE_H__FLAGS__ +/* + * NOTE! The bits used for these flags matter. The flag with + * the least significant bit will take precedence! + * + * The "now timestamp" has highest precedence due to + * compatibility reasons. + */ +#define ERTS_TRACE_FLG_NOW_TIMESTAMP (1 << 0) +#define ERTS_TRACE_FLG_STRICT_MONOTONIC_TIMESTAMP (1 << 1) +#define ERTS_TRACE_FLG_MONOTONIC_TIMESTAMP (1 << 2) + +/* + * The bits used effects trace flags (of processes and ports) + * as well as sequential trace flags. If changed make sure + * these arn't messed up... + */ +#define ERTS_TRACE_TS_TYPE_BITS 3 +#define ERTS_TRACE_TS_TYPE_MASK \ + ((1 << ERTS_TRACE_TS_TYPE_BITS) - 1) + +#define ERTS_TFLGS2TSTYPE(TFLGS) \ + ((int) (((TFLGS) >> ERTS_TRACE_FLAGS_TS_TYPE_SHIFT) \ + & ERTS_TRACE_TS_TYPE_MASK)) +#define ERTS_SEQTFLGS2TSTYPE(SEQTFLGS) \ + ((int) (((SEQTFLGS) >> ERTS_SEQ_TRACE_FLAGS_TS_TYPE_SHIFT) \ + & ERTS_TRACE_TS_TYPE_MASK)) + +#endif /* ERL_TRACE_H__FLAGS__ */ -#ifndef ERL_TRACE_H__ +#if !defined(ERL_TRACE_H__) && !defined(ERTS_ONLY_INCLUDE_TRACE_FLAGS) #define ERL_TRACE_H__ struct binary; diff --git a/erts/emulator/test/system_profile_SUITE.erl b/erts/emulator/test/system_profile_SUITE.erl index e4b6511d1f..2ecb4a28a7 100644 --- a/erts/emulator/test/system_profile_SUITE.erl +++ b/erts/emulator/test/system_profile_SUITE.erl @@ -113,13 +113,27 @@ runnable_procs(suite) -> runnable_procs(doc) -> ["Tests system_profiling with runnable_procs."]; runnable_procs(Config) when is_list(Config) -> + lists:foreach(fun (TsType) -> + Arg = case TsType of + no_timestamp -> + {timestamp, []}; + _ -> + {TsType, [TsType]} + end, + do_runnable_procs(Arg), + receive after 1000 -> ok end + end, + [no_timestamp, timestamp, monotonic_timestamp, + strict_monotonic_timestamp]). + +do_runnable_procs({TsType, TsTypeFlag}) -> Pid = start_profiler_process(), % start a ring of processes % FIXME: Set #laps and #nodes in config file Nodes = 10, Laps = 10, Master = ring(Nodes), - undefined = erlang:system_profile(Pid, [runnable_procs]), + undefined = erlang:system_profile(Pid, [runnable_procs]++TsTypeFlag), % loop a message ok = ring_message(Master, message, Laps), Events = get_profiler_events(), @@ -127,9 +141,9 @@ runnable_procs(Config) when is_list(Config) -> erlang:system_profile(undefined, []), put(master, Master), put(laps, Laps), - true = has_runnable_event(Events), + true = has_runnable_event(TsType, Events), Pids = sort_events_by_pid(Events), - ok = check_events(Pids), + ok = check_events(TsType, Pids), erase(), exit(Pid,kill), ok. @@ -139,8 +153,22 @@ runnable_ports(suite) -> runnable_ports(doc) -> ["Tests system_profiling with runnable_port."]; runnable_ports(Config) when is_list(Config) -> + lists:foreach(fun (TsType) -> + Arg = case TsType of + no_timestamp -> + {timestamp, []}; + _ -> + {TsType, [TsType]} + end, + do_runnable_ports(Arg, Config), + receive after 1000 -> ok end + end, + [no_timestamp, timestamp, monotonic_timestamp, + strict_monotonic_timestamp]). + +do_runnable_ports({TsType, TsTypeFlag}, Config) -> Pid = start_profiler_process(), - undefined = erlang:system_profile(Pid, [runnable_ports]), + undefined = erlang:system_profile(Pid, [runnable_ports]++TsTypeFlag), EchoPid = echo(Config), % FIXME: Set config to number_of_echos Laps = 10, @@ -149,9 +177,9 @@ runnable_ports(Config) when is_list(Config) -> Events = get_profiler_events(), kill_em_all = kill_echo(EchoPid), erlang:system_profile(undefined, []), - true = has_runnable_event(Events), + true = has_runnable_event(TsType, Events), Pids = sort_events_by_pid(Events), - ok = check_events(Pids), + ok = check_events(TsType, Pids), erase(), exit(Pid,kill), ok. @@ -166,8 +194,19 @@ scheduler(Config) when is_list(Config) -> {_, 1} -> {skipped, "No need for scheduler test when only one scheduler online."}; _ -> Nodes = 10, - ok = check_block_system(Nodes), - ok = check_multi_scheduling_block(Nodes) + lists:foreach(fun (TsType) -> + Arg = case TsType of + no_timestamp -> + {timestamp, []}; + _ -> + {TsType, [TsType]} + end, + ok = check_block_system(Arg, Nodes), + ok = check_multi_scheduling_block(Arg, Nodes), + receive after 1000 -> ok end + end, + [no_timestamp, timestamp, monotonic_timestamp, + strict_monotonic_timestamp]) end. % the profiler pid should not be profiled @@ -195,9 +234,9 @@ dont_profile_profiler(Config) when is_list(Config) -> %%% Check scheduler profiling -check_multi_scheduling_block(Nodes) -> +check_multi_scheduling_block({TsType, TsTypeFlag}, Nodes) -> Pid = start_profiler_process(), - undefined = erlang:system_profile(Pid, [scheduler]), + undefined = erlang:system_profile(Pid, [scheduler]++TsTypeFlag), {ok, Supervisor} = start_load(Nodes), wait(600), erlang:system_flag(multi_scheduling, block), @@ -205,23 +244,23 @@ check_multi_scheduling_block(Nodes) -> erlang:system_flag(multi_scheduling, unblock), {Pid, [scheduler]} = erlang:system_profile(undefined, []), Events = get_profiler_events(), - true = has_scheduler_event(Events), + true = has_scheduler_event(TsType, Events), stop_load(Supervisor), exit(Pid,kill), erase(), ok. -check_block_system(Nodes) -> +check_block_system({TsType, TsTypeFlag}, Nodes) -> Dummy = spawn(?MODULE, profiler_process, [[]]), Pid = start_profiler_process(), - undefined = erlang:system_profile(Pid, [scheduler]), + undefined = erlang:system_profile(Pid, [scheduler]++TsTypeFlag), {ok, Supervisor} = start_load(Nodes), wait(300), undefined = erlang:system_monitor(Dummy, [busy_port]), {Dummy, [busy_port]} = erlang:system_monitor(undefined, []), {Pid, [scheduler]} = erlang:system_profile(undefined, []), Events = get_profiler_events(), - true = has_scheduler_event(Events), + true = has_scheduler_event(TsType, Events), stop_load(Supervisor), exit(Pid,kill), exit(Dummy,kill), @@ -230,40 +269,49 @@ check_block_system(Nodes) -> %%% Check events -check_events([]) -> ok; -check_events([Pid | Pids]) -> +check_events(_TsType, []) -> ok; +check_events(TsType, [Pid | Pids]) -> Master = get(master), Laps = get(laps), CheckPids = get(pids), {Events, N} = get_pid_events(Pid), ok = check_event_flow(Events), - ok = check_event_ts(Events), + ok = check_event_ts(TsType, Events), IsMember = lists:member(Pid, CheckPids), case Pid of Master -> io:format("Expected ~p and got ~p profile events from ~p: ok~n", [Laps*2+2, N, Pid]), N = Laps*2 + 2, - check_events(Pids); + check_events(TsType, Pids); Pid when IsMember == true -> io:format("Expected ~p and got ~p profile events from ~p: ok~n", [Laps*2, N, Pid]), N = Laps*2, - check_events(Pids); + check_events(TsType, Pids); Pid -> - check_events(Pids) + check_events(TsType, Pids) end. %% timestamp consistency check for descending timestamps -check_event_ts(Events) -> - check_event_ts(Events, undefined). -check_event_ts([], _) -> ok; -check_event_ts([Event | Events], undefined) -> - check_event_ts(Events, Event); -check_event_ts([{Pid, _, _, TS1}=Event | Events], {Pid,_,_,TS0}) -> - Time = timer:now_diff(TS1, TS0), +check_event_ts(TsType, Events) -> + check_event_ts(TsType, Events, undefined). +check_event_ts(_TsType, [], _) -> ok; +check_event_ts(TsType, [Event | Events], undefined) -> + check_event_ts(TsType, Events, Event); +check_event_ts(TsType, [{Pid, _, _, TS1}=Event | Events], {Pid,_,_,TS0}) -> + Time = case TsType of + timestamp -> + timer:now_diff(TS1, TS0); + monotonic_timestamp -> + TS1 - TS0; + strict_monotonic_timestamp -> + {MT1, _} = TS1, + {MT0, _} = TS0, + MT1 - MT0 + end, if Time < 0.0 -> timestamp_error; - true -> check_event_ts(Events, Event) + true -> check_event_ts(TsType, Events, Event) end. %% consistency check for active vs. inactive activity (runnable) @@ -428,6 +476,44 @@ port_echo_loop(Port) -> %% Helpers %%% +check_ts(no_timestamp, Ts) -> + try + no_timestamp = Ts + catch + _ : _ -> + ?t:fail({unexpected_timestamp, Ts}) + end, + ok; +check_ts(timestamp, Ts) -> + try + {Ms,S,Us} = Ts, + true = is_integer(Ms), + true = is_integer(S), + true = is_integer(Us) + catch + _ : _ -> + ?t:fail({unexpected_timestamp, Ts}) + end, + ok; +check_ts(monotonic_timestamp, Ts) -> + try + true = is_integer(Ts) + catch + _ : _ -> + ?t:fail({unexpected_timestamp, Ts}) + end, + ok; +check_ts(strict_monotonic_timestamp, Ts) -> + try + {MT, UMI} = Ts, + true = is_integer(MT), + true = is_integer(UMI) + catch + _ : _ -> + ?t:fail({unexpected_timestamp, Ts}) + end, + ok. + start_load(N) -> Pid = spawn_link(?MODULE, run_load, [N, []]), {ok, Pid}. @@ -454,21 +540,24 @@ list_load() -> end, list_load(). - -has_scheduler_event(Events) -> +has_scheduler_event(TsType, Events) -> lists:any( fun (Pred) -> case Pred of - {profile, scheduler, _ID, _Activity, _NR, _TS} -> true; + {profile, scheduler, _ID, _Activity, _NR, TS} -> + check_ts(TsType, TS), + true; _ -> false end end, Events). -has_runnable_event(Events) -> +has_runnable_event(TsType, Events) -> lists:any( fun (Pred) -> case Pred of - {profile, _Pid, _Activity, _MFA, _TS} -> true; + {profile, _Pid, _Activity, _MFA, TS} -> + check_ts(TsType, TS), + true; _ -> false end end, Events). diff --git a/erts/emulator/test/trace_bif_SUITE.erl b/erts/emulator/test/trace_bif_SUITE.erl index a12c41a3aa..760666d077 100644 --- a/erts/emulator/test/trace_bif_SUITE.erl +++ b/erts/emulator/test/trace_bif_SUITE.erl @@ -67,7 +67,8 @@ trace_on_and_off(Config) when is_list(Config) -> ?line Pid = spawn(?MODULE, bif_process, []), ?line Self = self(), ?line 1 = erlang:trace(Pid, true, [call,timestamp]), - ?line {flags,[timestamp,call]} = erlang:trace_info(Pid,flags), + ?line {flags, Flags} = erlang:trace_info(Pid,flags), + ?line [call,timestamp] = lists:sort(Flags), ?line {tracer, Self} = erlang:trace_info(Pid,tracer), ?line 1 = erlang:trace(Pid, false, [timestamp]), ?line {flags,[call]} = erlang:trace_info(Pid,flags), @@ -111,93 +112,145 @@ do_trace_bif(Flags) -> trace_bif_timestamp(doc) -> "Test tracing BIFs with timestamps."; trace_bif_timestamp(Config) when is_list(Config) -> - do_trace_bif_timestamp([]). - + do_trace_bif_timestamp([], timestamp, [timestamp]), + do_trace_bif_timestamp([], timestamp, + [timestamp, + monotonic_timestamp, + strict_monotonic_timestamp]), + do_trace_bif_timestamp([], strict_monotonic_timestamp, + [strict_monotonic_timestamp]), + do_trace_bif_timestamp([], strict_monotonic_timestamp, + [monotonic_timestamp, strict_monotonic_timestamp]), + do_trace_bif_timestamp([], monotonic_timestamp, [monotonic_timestamp]). + trace_bif_timestamp_local(doc) -> "Test tracing BIFs with timestamps and local flag."; trace_bif_timestamp_local(Config) when is_list(Config) -> - do_trace_bif_timestamp([local]). - -do_trace_bif_timestamp(Flags) -> - ?line Pid=spawn(?MODULE, bif_process, []), - ?line 1 = erlang:trace(Pid, true, [call,timestamp]), - ?line erlang:trace_pattern({erlang,'_','_'}, [], Flags), - - ?line Pid ! {do_bif, time, []}, - ?line receive_trace_msg_ts({trace_ts,Pid,call,{erlang,time,[]}}), - - ?line Pid ! {do_bif, statistics, [runtime]}, - ?line receive_trace_msg_ts({trace_ts,Pid,call, - {erlang,statistics, [runtime]}}), - - ?line Pid ! {do_time_bif}, - ?line receive_trace_msg_ts({trace_ts,Pid,call, - {erlang,time, []}}), - - ?line Pid ! {do_statistics_bif}, - ?line receive_trace_msg_ts({trace_ts,Pid,call, - {erlang,statistics, [runtime]}}), + do_trace_bif_timestamp([local], timestamp, [timestamp]), + do_trace_bif_timestamp([local], timestamp, + [timestamp, + monotonic_timestamp, + strict_monotonic_timestamp]), + do_trace_bif_timestamp([local], strict_monotonic_timestamp, + [strict_monotonic_timestamp]), + do_trace_bif_timestamp([local], strict_monotonic_timestamp, + [monotonic_timestamp, strict_monotonic_timestamp]), + do_trace_bif_timestamp([local], monotonic_timestamp, [monotonic_timestamp]). + +do_trace_bif_timestamp(Flags, TsType, TsFlags) -> + io:format("Testing with TsType=~p TsFlags=~p~n", [TsType, TsFlags]), + Pid=spawn(?MODULE, bif_process, []), + 1 = erlang:trace(Pid, true, [call]++TsFlags), + erlang:trace_pattern({erlang,'_','_'}, [], Flags), + + Ts0 = make_ts(TsType), + Pid ! {do_bif, time, []}, + Ts1 = receive_trace_msg_ts({trace_ts,Pid,call,{erlang,time,[]}}, + Ts0,TsType), + + Pid ! {do_bif, statistics, [runtime]}, + Ts2 = receive_trace_msg_ts({trace_ts,Pid,call, + {erlang,statistics, [runtime]}}, + Ts1, TsType), + + Pid ! {do_time_bif}, + Ts3 = receive_trace_msg_ts({trace_ts,Pid,call, + {erlang,time, []}}, + Ts2, TsType), + + Pid ! {do_statistics_bif}, + Ts4 = receive_trace_msg_ts({trace_ts,Pid,call, + {erlang,statistics, [runtime]}}, + Ts3, TsType), + + check_ts(TsType, Ts4, make_ts(TsType)), %% We should be able to turn off the timestamp. - ?line 1 = erlang:trace(Pid, false, [timestamp]), + 1 = erlang:trace(Pid, false, TsFlags), - ?line Pid ! {do_statistics_bif}, - ?line receive_trace_msg({trace,Pid,call, - {erlang,statistics, [runtime]}}), + Pid ! {do_statistics_bif}, + receive_trace_msg({trace,Pid,call, + {erlang,statistics, [runtime]}}), - ?line Pid ! {do_bif, statistics, [runtime]}, - ?line receive_trace_msg({trace,Pid,call, - {erlang,statistics, [runtime]}}), + Pid ! {do_bif, statistics, [runtime]}, + receive_trace_msg({trace,Pid,call, + {erlang,statistics, [runtime]}}), - ?line 1 = erlang:trace(Pid, false, [call]), - ?line erlang:trace_pattern({erlang,'_','_'}, false, Flags), + 1 = erlang:trace(Pid, false, [call]), + erlang:trace_pattern({erlang,'_','_'}, false, Flags), - ?line exit(Pid, die), + exit(Pid, die), ok. trace_bif_return(doc) -> "Test tracing BIF's with return/return_to trace."; trace_bif_return(Config) when is_list(Config) -> - ?line Pid=spawn(?MODULE, bif_process, []), - ?line 1 = erlang:trace(Pid, true, [call,timestamp,return_to]), - ?line erlang:trace_pattern({erlang,'_','_'}, [{'_',[],[{return_trace}]}], - [local]), - - - ?line Pid ! {do_bif, time, []}, - ?line receive_trace_msg_ts({trace_ts,Pid,call,{erlang,time,[]}}), - ?line receive_trace_msg_ts_return_from({trace_ts,Pid,return_from, - {erlang,time,0}}), - ?line receive_trace_msg_ts_return_to({trace_ts,Pid,return_to, - {?MODULE, bif_process,0}}), - - - ?line Pid ! {do_bif, statistics, [runtime]}, - ?line receive_trace_msg_ts({trace_ts,Pid,call, - {erlang,statistics, [runtime]}}), - ?line receive_trace_msg_ts_return_from({trace_ts,Pid,return_from, - {erlang,statistics,1}}), - ?line receive_trace_msg_ts_return_to({trace_ts,Pid,return_to, - {?MODULE, bif_process,0}}), - - - ?line Pid ! {do_time_bif}, - ?line receive_trace_msg_ts({trace_ts,Pid,call, - {erlang,time, []}}), - ?line receive_trace_msg_ts_return_from({trace_ts,Pid,return_from, - {erlang,time,0}}), - ?line receive_trace_msg_ts_return_to({trace_ts,Pid,return_to, - {?MODULE, bif_process,0}}), - - - - ?line Pid ! {do_statistics_bif}, - ?line receive_trace_msg_ts({trace_ts,Pid,call, - {erlang,statistics, [runtime]}}), - ?line receive_trace_msg_ts_return_from({trace_ts,Pid,return_from, - {erlang,statistics,1}}), - ?line receive_trace_msg_ts_return_to({trace_ts,Pid,return_to, - {?MODULE, bif_process,0}}), + do_trace_bif_return(timestamp, [timestamp]), + do_trace_bif_return(timestamp, + [timestamp, + monotonic_timestamp, + strict_monotonic_timestamp]), + do_trace_bif_return(strict_monotonic_timestamp, + [strict_monotonic_timestamp]), + do_trace_bif_return(strict_monotonic_timestamp, + [monotonic_timestamp, strict_monotonic_timestamp]), + do_trace_bif_return(monotonic_timestamp, [monotonic_timestamp]). + +do_trace_bif_return(TsType, TsFlags) -> + io:format("Testing with TsType=~p TsFlags=~p~n", [TsType, TsFlags]), + Pid=spawn(?MODULE, bif_process, []), + 1 = erlang:trace(Pid, true, [call,return_to]++TsFlags), + erlang:trace_pattern({erlang,'_','_'}, [{'_',[],[{return_trace}]}], + [local]), + + Ts0 = make_ts(TsType), + Pid ! {do_bif, time, []}, + Ts1 = receive_trace_msg_ts({trace_ts,Pid,call,{erlang,time,[]}}, + Ts0, TsType), + Ts2 = receive_trace_msg_ts_return_from({trace_ts,Pid,return_from, + {erlang,time,0}}, + Ts1, TsType), + Ts3 = receive_trace_msg_ts_return_to({trace_ts,Pid,return_to, + {?MODULE, bif_process,0}}, + Ts2, TsType), + + + Pid ! {do_bif, statistics, [runtime]}, + Ts4 = receive_trace_msg_ts({trace_ts,Pid,call, + {erlang,statistics, [runtime]}}, + Ts3, TsType), + Ts5 = receive_trace_msg_ts_return_from({trace_ts,Pid,return_from, + {erlang,statistics,1}}, + Ts4, TsType), + Ts6 = receive_trace_msg_ts_return_to({trace_ts,Pid,return_to, + {?MODULE, bif_process,0}}, + Ts5, TsType), + + + Pid ! {do_time_bif}, + Ts7 = receive_trace_msg_ts({trace_ts,Pid,call, + {erlang,time, []}}, + Ts6, TsType), + Ts8 = receive_trace_msg_ts_return_from({trace_ts,Pid,return_from, + {erlang,time,0}}, + Ts7, TsType), + Ts9 = receive_trace_msg_ts_return_to({trace_ts,Pid,return_to, + {?MODULE, bif_process,0}}, + Ts8, TsType), + + + + Pid ! {do_statistics_bif}, + Ts10 = receive_trace_msg_ts({trace_ts,Pid,call, + {erlang,statistics, [runtime]}}, + Ts9, TsType), + Ts11 = receive_trace_msg_ts_return_from({trace_ts,Pid,return_from, + {erlang,statistics,1}}, + Ts10, TsType), + Ts12 = receive_trace_msg_ts_return_to({trace_ts,Pid,return_to, + {?MODULE, bif_process,0}}, + Ts11, TsType), + check_ts(TsType, Ts12, make_ts(TsType)), ok. @@ -213,10 +266,11 @@ receive_trace_msg(Mess) -> ?t:fail() end. -receive_trace_msg_ts({trace_ts, Pid, call, {erlang,F,A}}) -> +receive_trace_msg_ts({trace_ts, Pid, call, {erlang,F,A}}, PrevTs, TsType) -> receive - {trace_ts, Pid, call, {erlang, F, A}, _Ts} -> - ok; + {trace_ts, Pid, call, {erlang, F, A}, Ts} -> + check_ts(TsType, PrevTs, Ts), + Ts; Other -> io:format("Expected: {trace, ~p, call, {~p, ~p, ~p}, TimeStamp}},~n" "Got: ~p~n", @@ -227,10 +281,11 @@ receive_trace_msg_ts({trace_ts, Pid, call, {erlang,F,A}}) -> ?t:fail() end. -receive_trace_msg_ts_return_from({trace_ts, Pid, return_from, {erlang,F,A}}) -> +receive_trace_msg_ts_return_from({trace_ts, Pid, return_from, {erlang,F,A}}, PrevTs, TsType) -> receive - {trace_ts, Pid, return_from, {erlang, F, A}, _Value, _Ts} -> - ok; + {trace_ts, Pid, return_from, {erlang, F, A}, _Value, Ts} -> + check_ts(TsType, PrevTs, Ts), + Ts; Other -> io:format("Expected: {trace_ts, ~p, return_from, {~p, ~p, ~p}, Value, TimeStamp}},~n" "Got: ~p~n", @@ -241,10 +296,11 @@ receive_trace_msg_ts_return_from({trace_ts, Pid, return_from, {erlang,F,A}}) -> ?t:fail() end. -receive_trace_msg_ts_return_to({trace_ts, Pid, return_to, {M,F,A}}) -> +receive_trace_msg_ts_return_to({trace_ts, Pid, return_to, {M,F,A}}, PrevTs, TsType) -> receive - {trace_ts, Pid, return_to, {M, F, A}, _Ts} -> - ok; + {trace_ts, Pid, return_to, {M, F, A}, Ts} -> + check_ts(TsType, PrevTs, Ts), + Ts; Other -> io:format("Expected: {trace_ts, ~p, return_to, {~p, ~p, ~p}, TimeStamp}},~n" "Got: ~p~n", @@ -255,6 +311,33 @@ receive_trace_msg_ts_return_to({trace_ts, Pid, return_to, {M,F,A}}) -> ?t:fail() end. +make_ts(timestamp) -> + erlang:now(); +make_ts(monotonic_timestamp) -> + erlang:monotonic_time(); +make_ts(strict_monotonic_timestamp) -> + MT = erlang:monotonic_time(), + UMI = erlang:unique_integer([monotonic]), + {MT, UMI}. + +check_ts(timestamp, PrevTs, Ts) -> + {Ms, S, Us} = Ts, + true = is_integer(Ms), + true = is_integer(S), + true = is_integer(Us), + true = PrevTs < Ts, + Ts; +check_ts(monotonic_timestamp, PrevTs, Ts) -> + true = is_integer(Ts), + true = PrevTs =< Ts, + Ts; +check_ts(strict_monotonic_timestamp, PrevTs, Ts) -> + {MT, UMI} = Ts, + true = is_integer(MT), + true = is_integer(UMI), + true = PrevTs < Ts, + Ts. + bif_process() -> receive {do_bif, Name, Args} -> diff --git a/erts/preloaded/ebin/erlang.beam b/erts/preloaded/ebin/erlang.beam index 58516c0ff3..36862802ca 100644 Binary files a/erts/preloaded/ebin/erlang.beam and b/erts/preloaded/ebin/erlang.beam differ diff --git a/erts/preloaded/src/erlang.erl b/erts/preloaded/src/erlang.erl index 5fc6d14938..063b9a1f26 100644 --- a/erts/preloaded/src/erlang.erl +++ b/erts/preloaded/src/erlang.erl @@ -185,6 +185,8 @@ 'receive' | 'print' | 'timestamp' | + 'monotonic_timestamp' | + 'strict_monotonic_timestamp' | 'label' | 'serial'. @@ -198,7 +200,10 @@ 'exclusive' | 'runnable_ports' | 'runnable_procs' | - 'scheduler'. + 'scheduler' | + 'timestamp' | + 'monotonic_timestamp' | + 'strict_monotonic_timestamp'. -type system_monitor_option() :: 'busy_port' | @@ -230,6 +235,8 @@ garbage_collection | timestamp | cpu_timestamp | + monotonic_timestamp | + strict_monotonic_timestamp | arity | set_on_spawn | set_on_first_spawn | @@ -258,6 +265,8 @@ running | garbage_collection | timestamp | + monotonic_timestamp | + strict_monotonic_timestamp | arity. -type trace_info_return() :: @@ -2178,6 +2187,8 @@ send(_Dest,_Msg,_Options) -> ('receive') -> {'receive', boolean()}; (print) -> {print, boolean()}; (timestamp) -> {timestamp, boolean()}; + (monotonic_timestamp) -> {timestamp, boolean()}; + (strict_monotonic_timestamp) -> {strict_monotonic_timestamp, boolean()}; (label) -> [] | {label, non_neg_integer()}; (serial) -> [] | {serial, {non_neg_integer(), non_neg_integer()}}. seq_trace_info(_What) -> diff --git a/lib/kernel/doc/src/seq_trace.xml b/lib/kernel/doc/src/seq_trace.xml index 3439111035..9f191d488d 100644 --- a/lib/kernel/doc/src/seq_trace.xml +++ b/lib/kernel/doc/src/seq_trace.xml @@ -127,6 +127,34 @@ seq_trace:set_token(OldToken), % activate the trace token again enables/disables a timestamp to be generated for each traced event. Default is false.

 + set_token(strict_monotonic_timestamp, Bool) + +

A trace token flag (true | false) which + enables/disables a strict monotonic timestamp to be generated + for each traced event. Default is false. Timestamps will + consist of + Erlang + monotonic time and a monotonically increasing + integer. The time-stamp has the same format and value + as produced by {erlang:monotonic_time(), + erlang:unique_integer([monotonic])}.

+ + set_token(monotonic_timestamp, Bool) + +

A trace token flag (true | false) which + enables/disables a strict monotonic timestamp to be generated + for each traced event. Default is false. Timestamps + will use + Erlang + monotonic time. The time-stamp has the same + format and value as produced by erlang:monotonic_time().

+ +

If multiple timestamp flags are passed, timestamp has + precedence over strict_monotonic_timestamp which + in turn has precedence over monotonic_timestamp. All + timestamp flags are remembered, so if two are passed + and the one with highest precedence later is disabled + the other one will become active.

diff --git a/lib/kernel/src/kernel.app.src b/lib/kernel/src/kernel.app.src index b5555ca1a5..419dc0a2fc 100644 --- a/lib/kernel/src/kernel.app.src +++ b/lib/kernel/src/kernel.app.src @@ -116,6 +116,6 @@ {applications, []}, {env, [{error_logger, tty}]}, {mod, {kernel, []}}, - {runtime_dependencies, ["erts-7.0", "stdlib-2.6", "sasl-2.6"]} + {runtime_dependencies, ["erts-7.3", "stdlib-2.6", "sasl-2.6"]} ] }. diff --git a/lib/kernel/src/seq_trace.erl b/lib/kernel/src/seq_trace.erl index 07ccd3e494..a7a782c29c 100644 --- a/lib/kernel/src/seq_trace.erl +++ b/lib/kernel/src/seq_trace.erl @@ -23,7 +23,9 @@ -define(SEQ_TRACE_SEND, 1). %(1 << 0) -define(SEQ_TRACE_RECEIVE, 2). %(1 << 1) -define(SEQ_TRACE_PRINT, 4). %(1 << 2) --define(SEQ_TRACE_TIMESTAMP, 8). %(1 << 3) +-define(SEQ_TRACE_NOW_TIMESTAMP, 8). %(1 << 3) +-define(SEQ_TRACE_STRICT_MON_TIMESTAMP, 16). %(1 << 4) +-define(SEQ_TRACE_MON_TIMESTAMP, 32). %(1 << 5) -export([set_token/1, set_token/2, @@ -37,7 +39,7 @@ %%--------------------------------------------------------------------------- --type flag() :: 'send' | 'receive' | 'print' | 'timestamp'. +-type flag() :: 'send' | 'receive' | 'print' | 'timestamp' | 'monotonic_timestamp' | 'strict_monotonic_timestamp'. -type component() :: 'label' | 'serial' | flag(). -type value() :: (Integer :: non_neg_integer()) | {Previous :: non_neg_integer(), @@ -135,5 +137,9 @@ decode_flags(Flags) -> Print = (Flags band ?SEQ_TRACE_PRINT) > 0, Send = (Flags band ?SEQ_TRACE_SEND) > 0, Rec = (Flags band ?SEQ_TRACE_RECEIVE) > 0, - Ts = (Flags band ?SEQ_TRACE_TIMESTAMP) > 0, - [{print,Print},{send,Send},{'receive',Rec},{timestamp,Ts}]. + NowTs = (Flags band ?SEQ_TRACE_NOW_TIMESTAMP) > 0, + StrictMonTs = (Flags band ?SEQ_TRACE_STRICT_MON_TIMESTAMP) > 0, + MonTs = (Flags band ?SEQ_TRACE_MON_TIMESTAMP) > 0, + [{print,Print},{send,Send},{'receive',Rec},{timestamp,NowTs}, + {strict_monotonic_timestamp, StrictMonTs}, + {monotonic_timestamp, MonTs}]. diff --git a/lib/kernel/test/seq_trace_SUITE.erl b/lib/kernel/test/seq_trace_SUITE.erl index 7df0bc3d2f..6a63f7bc9c 100644 --- a/lib/kernel/test/seq_trace_SUITE.erl +++ b/lib/kernel/test/seq_trace_SUITE.erl @@ -35,6 +35,11 @@ %-define(line_trace, 1). -include_lib("test_server/include/test_server.hrl"). +-define(TIMESTAMP_MODES, [no_timestamp, + timestamp, + monotonic_timestamp, + strict_monotonic_timestamp]). + -define(default_timeout, ?t:minutes(1)). suite() -> [{ct_hooks,[ts_install_cth]}]. @@ -75,6 +80,17 @@ end_per_testcase(_Case, Config) -> token_set_get(doc) -> []; token_set_get(suite) -> []; token_set_get(Config) when is_list(Config) -> + do_token_set_get(timestamp), + do_token_set_get(monotonic_timestamp), + do_token_set_get(strict_monotonic_timestamp). + +do_token_set_get(TsType) -> + io:format("Testing ~p~n", [TsType]), + Flags = case TsType of + timestamp -> 15; + strict_monotonic_timestamp -> 23; + monotonic_timestamp -> 39 + end, ?line Self = self(), ?line seq_trace:reset_trace(), %% Test that initial seq_trace is disabled @@ -88,22 +104,22 @@ token_set_get(Config) when is_list(Config) -> ?line {send,true} = seq_trace:get_token(send), ?line false = seq_trace:set_token('receive',true), ?line {'receive',true} = seq_trace:get_token('receive'), - ?line false = seq_trace:set_token(timestamp,true), - ?line {timestamp,true} = seq_trace:get_token(timestamp), + ?line false = seq_trace:set_token(TsType,true), + ?line {TsType,true} = seq_trace:get_token(TsType), %% Check the whole token - ?line {15,17,0,Self,0} = seq_trace:get_token(), % all flags are set + ?line {Flags,17,0,Self,0} = seq_trace:get_token(), % all flags are set %% Test setting and reading the 'serial' field ?line {0,0} = seq_trace:set_token(serial,{3,5}), ?line {serial,{3,5}} = seq_trace:get_token(serial), %% Check the whole token, test that a whole token can be set and get - ?line {15,17,5,Self,3} = seq_trace:get_token(), - ?line seq_trace:set_token({15,19,7,Self,5}), - ?line {15,19,7,Self,5} = seq_trace:get_token(), + ?line {Flags,17,5,Self,3} = seq_trace:get_token(), + ?line seq_trace:set_token({Flags,19,7,Self,5}), + ?line {Flags,19,7,Self,5} = seq_trace:get_token(), %% Check that receive timeout does not reset token ?line receive after 0 -> ok end, - ?line {15,19,7,Self,5} = seq_trace:get_token(), + ?line {Flags,19,7,Self,5} = seq_trace:get_token(), %% Check that token can be unset - ?line {15,19,7,Self,5} = seq_trace:set_token([]), + ?line {Flags,19,7,Self,5} = seq_trace:set_token([]), ?line [] = seq_trace:get_token(), %% Check that Previous serial counter survived unset token ?line 0 = seq_trace:set_token(label, 17), @@ -139,30 +155,42 @@ tracer_set_get(Config) when is_list(Config) -> print(doc) -> []; print(suite) -> []; print(Config) when is_list(Config) -> + lists:foreach(fun do_print/1, ?TIMESTAMP_MODES). + +do_print(TsType) -> ?line start_tracer(), - ?line seq_trace:set_token(print,true), + ?line set_token_flags([print, TsType]), ?line seq_trace:print(0,print1), ?line seq_trace:print(1,print2), ?line seq_trace:print(print3), ?line seq_trace:reset_trace(), - ?line [{0,{print,_,_,[],print1}}, - {0,{print,_,_,[],print3}}] = stop_tracer(2). + ?line [{0,{print,_,_,[],print1}, Ts0}, + {0,{print,_,_,[],print3}, Ts1}] = stop_tracer(2), + check_ts(TsType, Ts0), + check_ts(TsType, Ts1). send(doc) -> []; send(suite) -> []; send(Config) when is_list(Config) -> + lists:foreach(fun do_send/1, ?TIMESTAMP_MODES). + +do_send(TsType) -> ?line seq_trace:reset_trace(), ?line start_tracer(), ?line Receiver = spawn(?MODULE,one_time_receiver,[]), - ?line seq_trace:set_token(send,true), + ?line set_token_flags([send, TsType]), ?line Receiver ! send, ?line Self = self(), ?line seq_trace:reset_trace(), - ?line [{0,{send,_,Self,Receiver,send}}] = stop_tracer(1). + ?line [{0,{send,_,Self,Receiver,send}, Ts}] = stop_tracer(1), + check_ts(TsType, Ts). distributed_send(doc) -> []; distributed_send(suite) -> []; distributed_send(Config) when is_list(Config) -> + lists:foreach(fun do_distributed_send/1, ?TIMESTAMP_MODES). + +do_distributed_send(TsType) -> ?line {ok,Node} = start_node(seq_trace_other,[]), ?line {_,Dir} = code:is_loaded(?MODULE), ?line Mdir = filename:dirname(Dir), @@ -170,30 +198,39 @@ distributed_send(Config) when is_list(Config) -> ?line seq_trace:reset_trace(), ?line start_tracer(), ?line Receiver = spawn(Node,?MODULE,one_time_receiver,[]), - ?line seq_trace:set_token(send,true), + ?line set_token_flags([send,TsType]), ?line Receiver ! send, ?line Self = self(), ?line seq_trace:reset_trace(), ?line stop_node(Node), - ?line [{0,{send,_,Self,Receiver,send}}] = stop_tracer(1). + ?line [{0,{send,_,Self,Receiver,send}, Ts}] = stop_tracer(1), + check_ts(TsType, Ts). + recv(doc) -> []; recv(suite) -> []; recv(Config) when is_list(Config) -> + lists:foreach(fun do_recv/1, ?TIMESTAMP_MODES). + +do_recv(TsType) -> ?line seq_trace:reset_trace(), ?line start_tracer(), ?line Receiver = spawn(?MODULE,one_time_receiver,[]), - ?line seq_trace:set_token('receive',true), + ?line set_token_flags(['receive',TsType]), ?line Receiver ! 'receive', %% let the other process receive the message: ?line receive after 1 -> ok end, ?line Self = self(), ?line seq_trace:reset_trace(), - ?line [{0,{'receive',_,Self,Receiver,'receive'}}] = stop_tracer(1). + ?line [{0,{'receive',_,Self,Receiver,'receive'}, Ts}] = stop_tracer(1), + check_ts(TsType, Ts). distributed_recv(doc) -> []; distributed_recv(suite) -> []; distributed_recv(Config) when is_list(Config) -> + lists:foreach(fun do_distributed_recv/1, ?TIMESTAMP_MODES). + +do_distributed_recv(TsType) -> ?line {ok,Node} = start_node(seq_trace_other,[]), ?line {_,Dir} = code:is_loaded(?MODULE), ?line Mdir = filename:dirname(Dir), @@ -201,7 +238,7 @@ distributed_recv(Config) when is_list(Config) -> ?line seq_trace:reset_trace(), ?line rpc:call(Node,?MODULE,start_tracer,[]), ?line Receiver = spawn(Node,?MODULE,one_time_receiver,[]), - ?line seq_trace:set_token('receive',true), + ?line set_token_flags(['receive',TsType]), ?line Receiver ! 'receive', %% let the other process receive the message: ?line receive after 1 -> ok end, @@ -210,16 +247,20 @@ distributed_recv(Config) when is_list(Config) -> ?line Result = rpc:call(Node,?MODULE,stop_tracer,[1]), ?line stop_node(Node), ?line ok = io:format("~p~n",[Result]), - ?line [{0,{'receive',_,Self,Receiver,'receive'}}] = Result. + ?line [{0,{'receive',_,Self,Receiver,'receive'}, Ts}] = Result, + check_ts(TsType, Ts). trace_exit(doc) -> []; trace_exit(suite) -> []; trace_exit(Config) when is_list(Config) -> + lists:foreach(fun do_trace_exit/1, ?TIMESTAMP_MODES). + +do_trace_exit(TsType) -> ?line seq_trace:reset_trace(), ?line start_tracer(), ?line Receiver = spawn_link(?MODULE, one_time_receiver, [exit]), ?line process_flag(trap_exit, true), - ?line seq_trace:set_token(send,true), + ?line set_token_flags([send, TsType]), ?line Receiver ! {before, exit}, %% let the other process receive the message: ?line receive @@ -233,13 +274,18 @@ trace_exit(Config) when is_list(Config) -> ?line Result = stop_tracer(2), ?line seq_trace:reset_trace(), ?line ok = io:format("~p~n", [Result]), - ?line [{0, {send, {0,1}, Self, Receiver, {before, exit}}}, + ?line [{0, {send, {0,1}, Self, Receiver, {before, exit}}, Ts0}, {0, {send, {1,2}, Receiver, Self, - {'EXIT', Receiver, {exit, {before, exit}}}}}] = Result. + {'EXIT', Receiver, {exit, {before, exit}}}}, Ts1}] = Result, + check_ts(TsType, Ts0), + check_ts(TsType, Ts1). distributed_exit(doc) -> []; distributed_exit(suite) -> []; distributed_exit(Config) when is_list(Config) -> + lists:foreach(fun do_distributed_exit/1, ?TIMESTAMP_MODES). + +do_distributed_exit(TsType) -> ?line {ok, Node} = start_node(seq_trace_other, []), ?line {_, Dir} = code:is_loaded(?MODULE), ?line Mdir = filename:dirname(Dir), @@ -248,7 +294,7 @@ distributed_exit(Config) when is_list(Config) -> ?line rpc:call(Node, ?MODULE, start_tracer,[]), ?line Receiver = spawn_link(Node, ?MODULE, one_time_receiver, [exit]), ?line process_flag(trap_exit, true), - ?line seq_trace:set_token(send, true), + ?line set_token_flags([send, TsType]), ?line Receiver ! {before, exit}, %% let the other process receive the message: ?line receive @@ -264,7 +310,8 @@ distributed_exit(Config) when is_list(Config) -> ?line stop_node(Node), ?line ok = io:format("~p~n", [Result]), ?line [{0, {send, {1, 2}, Receiver, Self, - {'EXIT', Receiver, {exit, {before, exit}}}}}] = Result. + {'EXIT', Receiver, {exit, {before, exit}}}}, Ts}] = Result, + check_ts(TsType, Ts). call(doc) -> "Tests special forms {is_seq_trace} and {get_seq_token} " @@ -361,14 +408,22 @@ port(doc) -> "Send trace messages to a port."; port(suite) -> []; port(Config) when is_list(Config) -> + lists:foreach(fun (TsType) -> do_port(TsType, Config) end, + ?TIMESTAMP_MODES). + +do_port(TsType, Config) -> + io:format("Testing ~p~n",[TsType]), ?line Port = load_tracer(Config), ?line seq_trace:set_system_tracer(Port), - ?line seq_trace:set_token(print, true), + ?line set_token_flags([print, TsType]), ?line Small = [small,term], ?line seq_trace:print(0, Small), ?line case get_port_message(Port) of - {seq_trace,0,{print,_,_,[],Small}} -> + {seq_trace,0,{print,_,_,[],Small}} when TsType == no_timestamp -> + ok; + {seq_trace,0,{print,_,_,[],Small},Ts0} when TsType /= no_timestamp -> + check_ts(TsType, Ts0), ok; Other -> ?line seq_trace:reset_trace(), @@ -382,7 +437,10 @@ port(Config) when is_list(Config) -> ?line seq_trace:print(0, OtherSmall), ?line seq_trace:reset_trace(), ?line case get_port_message(Port) of - {seq_trace,0,{print,_,_,[],OtherSmall}} -> + {seq_trace,0,{print,_,_,[],OtherSmall}} when TsType == no_timestamp -> + ok; + {seq_trace,0,{print,_,_,[],OtherSmall}, Ts1} when TsType /= no_timestamp -> + check_ts(TsType, Ts1), ok; Other1 -> ?line ?t:fail({unexpected,Other1}) @@ -399,6 +457,8 @@ port(Config) when is_list(Config) -> Other2 -> ?line ?t:fail({unexpected,Other2}) end, + unlink(Port), + exit(Port,kill), ok. get_port_message(Port) -> @@ -734,7 +794,7 @@ simple_tracer(Data, DN) -> {seq_trace,Label,Info,Ts} -> simple_tracer([{Label,Info,Ts}|Data], DN+1); {seq_trace,Label,Info} -> - simple_tracer([{Label,Info}|Data], DN+1); + simple_tracer([{Label,Info, no_timestamp}|Data], DN+1); {stop,N,From} when DN >= N -> From ! {tracerlog,lists:reverse(Data)} end. @@ -759,7 +819,55 @@ start_tracer() -> seq_trace:set_system_tracer(Pid), Pid. - + +set_token_flags([]) -> + ok; +set_token_flags([no_timestamp|Flags]) -> + seq_trace:set_token(timestamp, false), + seq_trace:set_token(monotonic_timestamp, false), + seq_trace:set_token(strict_monotonic_timestamp, false), + set_token_flags(Flags); +set_token_flags([Flag|Flags]) -> + seq_trace:set_token(Flag, true), + set_token_flags(Flags). + +check_ts(no_timestamp, Ts) -> + try + no_timestamp = Ts + catch + _ : _ -> + ?t:fail({unexpected_timestamp, Ts}) + end, + ok; +check_ts(timestamp, Ts) -> + try + {Ms,S,Us} = Ts, + true = is_integer(Ms), + true = is_integer(S), + true = is_integer(Us) + catch + _ : _ -> + ?t:fail({unexpected_timestamp, Ts}) + end, + ok; +check_ts(monotonic_timestamp, Ts) -> + try + true = is_integer(Ts) + catch + _ : _ -> + ?t:fail({unexpected_timestamp, Ts}) + end, + ok; +check_ts(strict_monotonic_timestamp, Ts) -> + try + {MT, UMI} = Ts, + true = is_integer(MT), + true = is_integer(UMI) + catch + _ : _ -> + ?t:fail({unexpected_timestamp, Ts}) + end, + ok. start_node(Name, Param) -> test_server:start_node(Name, slave, [{args, Param}]). -- cgit v1.2.3 From dc8e62f33ad0ca7a772ec74d67b6d3e157f639b4 Mon Sep 17 00:00:00 2001 From: Rickard Green Date: Wed, 13 Jan 2016 18:33:42 +0100 Subject: Introduce time warp safe replacement for safe_fixed option The new time warp safe option is safe_fixed_monotonic_time which gives erlang:monotonic_time(). The safe_fixed option was also slightly changed. It now gives erlang:timestamp() instead of erlang:now(). This has however not been documented, so it is considered a compatible change. The above effects both ets, and dets. This commit also include the bugfix OTP-13239 for dets:info(Tab, safe_fixed). The timestamp in the result returned by dets:info(Tab, safe_fixed) was unintentionally broken as a result of the time API rewrites in OTP 18.0. --- erts/emulator/beam/erl_db.c | 46 ++++++++++++++++++++++++++++---------- erts/emulator/beam/erl_db_util.h | 5 ++++- erts/emulator/beam/erl_time_sup.c | 47 ++++++++++++++++++++++++++++++--------- erts/emulator/beam/sys.h | 4 ++++ lib/stdlib/doc/src/dets.xml | 31 +++++++++++++++++++++++--- lib/stdlib/doc/src/ets.xml | 41 ++++++++++++++++++++++++++++------ lib/stdlib/src/dets.erl | 36 +++++++++++++++++++++++------- lib/stdlib/src/ets.erl | 2 +- lib/stdlib/src/stdlib.app.src | 2 +- lib/stdlib/test/dets_SUITE.erl | 24 ++++++++++++++++++++ lib/stdlib/test/ets_SUITE.erl | 35 ++++++++++++++++++++++++----- 11 files changed, 223 insertions(+), 50 deletions(-) diff --git a/erts/emulator/beam/erl_db.c b/erts/emulator/beam/erl_db.c index 878ee32b47..645f9e3c28 100644 --- a/erts/emulator/beam/erl_db.c +++ b/erts/emulator/beam/erl_db.c @@ -1376,7 +1376,6 @@ BIF_RETTYPE ets_new_2(BIF_ALIST_2) status |= DB_ORDERED_SET; status &= ~(DB_SET | DB_BAG | DB_DUPLICATE_BAG); } - /*TT*/ else if (is_tuple(val)) { Eterm *tp = tuple_val(val); if (arityval(tp[0]) == 2) { @@ -3466,10 +3465,10 @@ static void fix_table_locked(Process* p, DbTable* tb) #endif erts_refc_inc(&tb->common.ref,1); fix = tb->common.fixations; - if (fix == NULL) { - get_now(&(tb->common.megasec), - &(tb->common.sec), - &(tb->common.microsec)); + if (fix == NULL) { + tb->common.time.monotonic + = erts_get_monotonic_time(ERTS_PROC_GET_SCHDATA(p)); + tb->common.time.offset = erts_get_time_offset(); } else { for (; fix != NULL; fix = fix->next) { @@ -3731,6 +3730,7 @@ static int free_table_cont(Process *p, static Eterm table_info(Process* p, DbTable* tb, Eterm What) { Eterm ret = THE_NON_VALUE; + int use_monotonic; if (What == am_size) { ret = make_small(erts_smp_atomic_read_nob(&tb->common.nitems)); @@ -3788,7 +3788,10 @@ static Eterm table_info(Process* p, DbTable* tb, Eterm What) ret = am_true; else ret = am_false; - } else if (What == am_atom_put("safe_fixed",10)) { + } else if ((use_monotonic + = ERTS_IS_ATOM_STR("safe_fixed_monotonic_time", + What)) + || ERTS_IS_ATOM_STR("safe_fixed", What)) { #ifdef ERTS_SMP erts_smp_mtx_lock(&tb->common.fixlock); #endif @@ -3797,7 +3800,19 @@ static Eterm table_info(Process* p, DbTable* tb, Eterm What) Eterm *hp; Eterm tpl, lst; DbFixation *fix; - need = 7; + Sint64 mtime; + + need = 3; + if (use_monotonic) { + mtime = (Sint64) tb->common.time.monotonic; + mtime += ERTS_MONOTONIC_OFFSET_NATIVE; + if (!IS_SSMALL(mtime)) + need += ERTS_SINT64_HEAP_SIZE(mtime); + } + else { + mtime = 0; + need += 4; + } for (fix = tb->common.fixations; fix != NULL; fix = fix->next) { need += 5; } @@ -3809,11 +3824,18 @@ static Eterm table_info(Process* p, DbTable* tb, Eterm What) lst = CONS(hp,tpl,lst); hp += 2; } - tpl = TUPLE3(hp, - make_small(tb->common.megasec), - make_small(tb->common.sec), - make_small(tb->common.microsec)); - hp += 4; + if (use_monotonic) + tpl = (IS_SSMALL(mtime) + ? make_small(mtime) + : erts_sint64_to_big(mtime, &hp)); + else { + Uint ms, s, us; + erts_make_timestamp_value(&ms, &s, &us, + tb->common.time.monotonic, + tb->common.time.offset); + tpl = TUPLE3(hp, make_small(ms), make_small(s), make_small(us)); + hp += 4; + } ret = TUPLE2(hp, tpl, lst); } else { ret = am_false; diff --git a/erts/emulator/beam/erl_db_util.h b/erts/emulator/beam/erl_db_util.h index 1ccdc0305b..0903a40460 100644 --- a/erts/emulator/beam/erl_db_util.h +++ b/erts/emulator/beam/erl_db_util.h @@ -229,7 +229,10 @@ typedef struct db_table_common { DbTableMethod* meth; /* table methods */ erts_smp_atomic_t nitems; /* Total number of items in table */ erts_smp_atomic_t memory_size;/* Total memory size. NOTE: in bytes! */ - Uint megasec,sec,microsec; /* Last fixation time */ + struct { /* Last fixation time */ + ErtsMonotonicTime monotonic; + ErtsMonotonicTime offset; + } time; DbFixation* fixations; /* List of processes who have done safe_fixtable, "local" fixations not included. */ /* All 32-bit fields */ diff --git a/erts/emulator/beam/erl_time_sup.c b/erts/emulator/beam/erl_time_sup.c index 7327e0b48c..2c87b8e81c 100644 --- a/erts/emulator/beam/erl_time_sup.c +++ b/erts/emulator/beam/erl_time_sup.c @@ -1747,6 +1747,39 @@ erts_get_monotonic_time(ErtsSchedulerData *esdp) return mtime; } +ErtsMonotonicTime +erts_get_time_offset(void) +{ + return get_time_offset(); +} + +static ERTS_INLINE void +make_timestamp_value(Uint* megasec, Uint* sec, Uint* microsec, + ErtsMonotonicTime mtime, ErtsMonotonicTime offset) +{ + ErtsMonotonicTime stime, as; + Uint ms; + + stime = ERTS_MONOTONIC_TO_USEC(mtime + offset); + + as = stime / ERTS_MONOTONIC_TIME_MEGA; + *megasec = ms = (Uint) (stime / ERTS_MONOTONIC_TIME_TERA); + *sec = (Uint) (as - (((ErtsMonotonicTime) ms) + * ERTS_MONOTONIC_TIME_MEGA)); + *microsec = (Uint) (stime - as*ERTS_MONOTONIC_TIME_MEGA); + + ASSERT(((ErtsMonotonicTime) ms)*ERTS_MONOTONIC_TIME_TERA + + ((ErtsMonotonicTime) *sec)*ERTS_MONOTONIC_TIME_MEGA + + *microsec == stime); +} + +void +erts_make_timestamp_value(Uint* megasec, Uint* sec, Uint* microsec, + ErtsMonotonicTime mtime, ErtsMonotonicTime offset) +{ + make_timestamp_value(megasec, sec, microsec, mtime, offset); +} + void get_sys_now(Uint* megasec, Uint* sec, Uint* microsec) { @@ -2220,22 +2253,14 @@ BIF_RETTYPE time_offset_1(BIF_ALIST_1) BIF_RETTYPE timestamp_0(BIF_ALIST_0) { Eterm *hp, res; - ErtsMonotonicTime stime, mtime, all_sec, offset; + ErtsMonotonicTime mtime, offset; Uint mega_sec, sec, micro_sec; mtime = time_sup.r.o.get_time(); offset = get_time_offset(); update_last_mtime(ERTS_PROC_GET_SCHDATA(BIF_P), mtime); - stime = ERTS_MONOTONIC_TO_USEC(mtime + offset); - all_sec = stime / ERTS_MONOTONIC_TIME_MEGA; - mega_sec = (Uint) (stime / ERTS_MONOTONIC_TIME_TERA); - sec = (Uint) (all_sec - (((ErtsMonotonicTime) mega_sec) - * ERTS_MONOTONIC_TIME_MEGA)); - micro_sec = (Uint) (stime - all_sec*ERTS_MONOTONIC_TIME_MEGA); - - ASSERT(((ErtsMonotonicTime) mega_sec)*ERTS_MONOTONIC_TIME_TERA - + ((ErtsMonotonicTime) sec)*ERTS_MONOTONIC_TIME_MEGA - + micro_sec == stime); + + make_timestamp_value(&mega_sec, &sec, µ_sec, mtime, offset); /* * Mega seconds is the only value that potentially diff --git a/erts/emulator/beam/sys.h b/erts/emulator/beam/sys.h index ec94e3a596..03e30573de 100644 --- a/erts/emulator/beam/sys.h +++ b/erts/emulator/beam/sys.h @@ -819,6 +819,10 @@ int local_to_univ(Sint *year, Sint *month, Sint *day, void get_now(Uint*, Uint*, Uint*); struct ErtsSchedulerData_; ErtsMonotonicTime erts_get_monotonic_time(struct ErtsSchedulerData_ *); +ErtsMonotonicTime erts_get_time_offset(void); +void +erts_make_timestamp_value(Uint* megasec, Uint* sec, Uint* microsec, + ErtsMonotonicTime mtime, ErtsMonotonicTime offset); void get_sys_now(Uint*, Uint*, Uint*); void set_break_quit(void (*)(void), void (*)(void)); diff --git a/lib/stdlib/doc/src/dets.xml b/lib/stdlib/doc/src/dets.xml index a0d3f95b6a..48400733d1 100644 --- a/lib/stdlib/doc/src/dets.xml +++ b/lib/stdlib/doc/src/dets.xml @@ -399,15 +399,40 @@ kept in RAM.

-

{safe_fixed, SafeFixed}. If the table - is fixed, SafeFixed is a tuple {FixedAtTime, [{Pid,RefCount}]}. FixedAtTime is the time when +

{safe_fixed_monotonic_time, SafeFixed}. If the table + is fixed, SafeFixed is a tuple {FixedAtTime, [{Pid,RefCount}]}. + FixedAtTime is the time when the table was first fixed, and Pid is the pid of the process that fixes the table RefCount times. There may be any number of processes in the list. If the table is not fixed, SafeFixed is the atom false.

+

FixedAtTime will correspond to the result + returned by + erlang:monotonic_time/0 + at the time of fixation. The usage of safe_fixed_monotonic_time is + time warp + safe.

 -

{version, integer(), the version of the format of +

+ {safe_fixed, SafeFixed}. The same as + {safe_fixed_monotonic_time, SafeFixed} with the exception + of the format and value of FixedAtTime. +

+

+ FixedAtTime will correspond to the result returned by + erlang:timestamp/0 + at the time of fixation. Note that when the system is using + single or multi + time warp + modes this might produce strange results. This + since the usage of safe_fixed is not + time warp + safe. Time warp safe code need to use + safe_fixed_monotonic_time instead.

+ + +

{version, integer()}, the version of the format of the table.

 diff --git a/lib/stdlib/doc/src/ets.xml b/lib/stdlib/doc/src/ets.xml index 7b01109ff8..447fe51130 100644 --- a/lib/stdlib/doc/src/ets.xml +++ b/lib/stdlib/doc/src/ets.xml @@ -488,14 +488,39 @@ Error: fun containing local Erlang function calls Item=fixed, Value=boolean()

Indicates if the table is fixed by any process or not. - -

Item=safe_fixed, Value={FirstFixed,Info}|false

+ +

Item=safe_fixed|safe_fixed_monotonic_time, Value={FixationTime,Info}|false

-

If the table has been fixed using safe_fixtable/2, - the call returns a tuple where FirstFixed is the +

If the table has been fixed using + safe_fixtable/2, + the call returns a tuple where FixationTime is the time when the table was first fixed by a process, which may or may not be one of the processes it is fixed by right now.

+

The format and value of FixationTime depends on + Item:

+ + safe_fixed +

FixationTime will correspond to the result + returned by + erlang:timestamp/0 + at the time of fixation. Note that when the system is using + single or multi + time warp + modes this might produce strange results. This + since the usage of safe_fixed is not + time warp + safe. Time warp safe code need to use + safe_fixed_monotonic_time instead.

 + + safe_fixed_monotonic_time +

FixationTime will correspond to the result + returned by + erlang:monotonic_time/0 + at the time of fixation. The usage of safe_fixed_monotonic_time is + time warp + safe.

 +

Info is a possibly empty lists of tuples {Pid,RefCount}, one tuple for every process the table is fixed by right now. RefCount is the value @@ -1135,9 +1160,11 @@ clean_all_with_value(Tab,X,Key) -> table but never releases it, the memory used by the deleted objects will never be freed. The performance of operations on the table will also degrade significantly.

-

Use info/2 to retrieve information about which - processes have fixed which tables. A system with a lot of - processes fixing tables may need a monitor which sends alarms +

Use + info(Tab, + safe_fixed_monotonic_time) to retrieve information + about which processes have fixed which tables. A system with a lot + of processes fixing tables may need a monitor which sends alarms when tables have been fixed for too long.

Note that for tables of the ordered_set type, safe_fixtable/2 is not necessary as calls to diff --git a/lib/stdlib/src/dets.erl b/lib/stdlib/src/dets.erl index 6d07f4018a..2d037ff795 100644 --- a/lib/stdlib/src/dets.erl +++ b/lib/stdlib/src/dets.erl @@ -372,7 +372,7 @@ info(Tab) -> Item :: 'access' | 'auto_save' | 'bchunk_format' | 'hash' | 'file_size' | 'filename' | 'keypos' | 'memory' | 'no_keys' | 'no_objects' | 'no_slots' | 'owner' | 'ram_file' - | 'safe_fixed' | 'size' | 'type' | 'version', + | 'safe_fixed' | 'safe_fixed_monotonic_time' | 'size' | 'type' | 'version', Value :: term(). info(Tab, owner) -> @@ -1964,7 +1964,9 @@ do_safe_fixtable(Head, Pid, true) -> case Head#head.fixed of false -> link(Pid), - Fixed = {utime_now(), [{Pid, 1}]}, + MonTime = erlang:monotonic_time(), + TimeOffset = erlang:time_offset(), + Fixed = {{MonTime, TimeOffset}, [{Pid, 1}]}, Ftab = dets_utils:get_freelists(Head), Head#head{fixed = Fixed, freelists = {Ftab, Ftab}}; {TimeStamp, Counters} -> @@ -2091,7 +2093,22 @@ finfo(H, no_keys) -> finfo(H, no_slots) -> {H, (H#head.mod):no_slots(H)}; finfo(H, pid) -> {H, self()}; finfo(H, ram_file) -> {H, H#head.ram_file}; -finfo(H, safe_fixed) -> {H, H#head.fixed}; +finfo(H, safe_fixed) -> + {H, + case H#head.fixed of + false -> + false; + {{FixMonTime, TimeOffset}, RefList} -> + {make_timestamp(FixMonTime, TimeOffset), RefList} + end}; +finfo(H, safe_fixed_monotonic_time) -> + {H, + case H#head.fixed of + false -> + false; + {{FixMonTime, _TimeOffset}, RefList} -> + {FixMonTime, RefList} + end}; finfo(H, size) -> case catch write_cache(H) of {H2, []} -> @@ -3275,11 +3292,14 @@ err(Error) -> time_now() -> erlang:monotonic_time(1000000). --compile({inline, [utime_now/0]}). -utime_now() -> - Time = time_now(), - UniqueCounter = erlang:unique_integer([monotonic]), - {Time, UniqueCounter}. +make_timestamp(MonTime, TimeOffset) -> + ErlangSystemTime = erlang:convert_time_unit(MonTime+TimeOffset, + native, + micro_seconds), + MegaSecs = ErlangSystemTime div 1000000000000, + Secs = ErlangSystemTime div 1000000 - MegaSecs*1000000, + MicroSecs = ErlangSystemTime rem 1000000, + {MegaSecs, Secs, MicroSecs}. %%%%%%%%%%%%%%%%% DEBUG functions %%%%%%%%%%%%%%%% diff --git a/lib/stdlib/src/ets.erl b/lib/stdlib/src/ets.erl index 847def2fd8..1fca3624dc 100644 --- a/lib/stdlib/src/ets.erl +++ b/lib/stdlib/src/ets.erl @@ -146,7 +146,7 @@ info(_) -> Tab :: tab(), Item :: compressed | fixed | heir | keypos | memory | name | named_table | node | owner | protection - | safe_fixed | size | stats | type + | safe_fixed | safe_fixed_monotonic_time | size | stats | type | write_concurrency | read_concurrency, Value :: term(). diff --git a/lib/stdlib/src/stdlib.app.src b/lib/stdlib/src/stdlib.app.src index 7f9bbbf649..b8a7973cf2 100644 --- a/lib/stdlib/src/stdlib.app.src +++ b/lib/stdlib/src/stdlib.app.src @@ -105,7 +105,7 @@ dets]}, {applications, [kernel]}, {env, []}, - {runtime_dependencies, ["sasl-2.6","kernel-4.1","erts-7.0","crypto-3.3", + {runtime_dependencies, ["sasl-2.6","kernel-4.1","erts-7.3","crypto-3.3", "compiler-5.0"]} ]}. diff --git a/lib/stdlib/test/dets_SUITE.erl b/lib/stdlib/test/dets_SUITE.erl index 7f5e06524a..35e587afcc 100644 --- a/lib/stdlib/test/dets_SUITE.erl +++ b/lib/stdlib/test/dets_SUITE.erl @@ -1876,9 +1876,33 @@ fixtable(Config, Version) when is_list(Config) -> {ok, _} = dets:open_file(T, [{type, duplicate_bag} | Args]), %% In a fixed table, delete and re-insert an object. ok = dets:insert(T, {1, a, b}), + SysBefore = erlang:timestamp(), + MonBefore = erlang:monotonic_time(), dets:safe_fixtable(T, true), + MonAfter = erlang:monotonic_time(), + SysAfter = erlang:timestamp(), + Self = self(), + {FixMonTime,[{Self,1}]} = dets:info(T,safe_fixed_monotonic_time), + {FixSysTime,[{Self,1}]} = dets:info(T,safe_fixed), + true = is_integer(FixMonTime), + true = MonBefore =< FixMonTime, + true = FixMonTime =< MonAfter, + {FstMs,FstS,FstUs} = FixSysTime, + true = is_integer(FstMs), + true = is_integer(FstS), + true = is_integer(FstUs), + case erlang:system_info(time_warp_mode) of + no_time_warp -> + true = timer:now_diff(FixSysTime, SysBefore) >= 0, + true = timer:now_diff(SysAfter, FixSysTime) >= 0; + _ -> + %% ets:info(Tab,safe_fixed) not timewarp safe... + ignore + end, ok = dets:match_delete(T, {1, a, b}), ok = dets:insert(T, {1, a, b}), + {FixMonTime,[{Self,1}]} = dets:info(T,safe_fixed_monotonic_time), + {FixSysTime,[{Self,1}]} = dets:info(T,safe_fixed), dets:safe_fixtable(T, false), 1 = length(dets:match_object(T, '_')), diff --git a/lib/stdlib/test/ets_SUITE.erl b/lib/stdlib/test/ets_SUITE.erl index ae431d66d9..30a158d9e1 100644 --- a/lib/stdlib/test/ets_SUITE.erl +++ b/lib/stdlib/test/ets_SUITE.erl @@ -3989,15 +3989,37 @@ safe_fixtable_do(Opts) -> ?line true = ets:safe_fixtable(Tab, true), ?line receive after 1 -> ok end, ?line true = ets:safe_fixtable(Tab, false), - ?line false = ets:info(Tab,safe_fixed), - ?line true = ets:safe_fixtable(Tab, true), + false = ets:info(Tab,safe_fixed_monotonic_time), + false = ets:info(Tab,safe_fixed), + SysBefore = erlang:timestamp(), + MonBefore = erlang:monotonic_time(), + true = ets:safe_fixtable(Tab, true), + MonAfter = erlang:monotonic_time(), + SysAfter = erlang:timestamp(), Self = self(), - ?line {{_,_,_},[{Self,1}]} = ets:info(Tab,safe_fixed), + {FixMonTime,[{Self,1}]} = ets:info(Tab,safe_fixed_monotonic_time), + {FixSysTime,[{Self,1}]} = ets:info(Tab,safe_fixed), + true = is_integer(FixMonTime), + true = MonBefore =< FixMonTime, + true = FixMonTime =< MonAfter, + {FstMs,FstS,FstUs} = FixSysTime, + true = is_integer(FstMs), + true = is_integer(FstS), + true = is_integer(FstUs), + case erlang:system_info(time_warp_mode) of + no_time_warp -> + true = timer:now_diff(FixSysTime, SysBefore) >= 0, + true = timer:now_diff(SysAfter, FixSysTime) >= 0; + _ -> + %% ets:info(Tab,safe_fixed) not timewarp safe... + ignore + end, %% Test that an unjustified 'unfix' is a no-op. {Pid,MRef} = my_spawn_monitor(fun() -> true = ets:safe_fixtable(Tab,false) end), {'DOWN', MRef, process, Pid, normal} = receive M -> M end, - ?line true = ets:info(Tab,fixed), - ?line {{_,_,_},[{Self,1}]} = ets:info(Tab,safe_fixed), + true = ets:info(Tab,fixed), + {FixMonTime,[{Self,1}]} = ets:info(Tab,safe_fixed_monotonic_time), + {FixSysTime,[{Self,1}]} = ets:info(Tab,safe_fixed), %% badarg's ?line {'EXIT', {badarg, _}} = (catch ets:safe_fixtable(Tab, foobar)), ?line true = ets:info(Tab,fixed), @@ -4043,6 +4065,7 @@ info_do(Opts) -> ?line undefined = ets:info(non_existing_table_xxyy,type), ?line undefined = ets:info(non_existing_table_xxyy,node), ?line undefined = ets:info(non_existing_table_xxyy,named_table), + ?line undefined = ets:info(non_existing_table_xxyy,safe_fixed_monotonic_time), ?line undefined = ets:info(non_existing_table_xxyy,safe_fixed), ?line verify_etsmem(EtsMem). @@ -5532,7 +5555,7 @@ otp_8166_zombie_creator(T,Deleted) -> [{'=<','$1', Deleted}], [true]}]), Pid ! zombies_created, - repeat_while(fun() -> case ets:info(T,safe_fixed) of + repeat_while(fun() -> case ets:info(T,safe_fixed_monotonic_time) of {_,[_P1,_P2]} -> false; _ -> -- cgit v1.2.3 From 3f33428db9aea0d767295322c4e882a5c6bbf7db Mon Sep 17 00:00:00 2001 From: Rickard Green Date: Tue, 19 Jan 2016 17:05:55 +0100 Subject: Introduce time management in native APIs --- erts/doc/src/erl_driver.xml | 112 +++++++++++++++++++ erts/doc/src/erl_nif.xml | 112 +++++++++++++++++++ erts/emulator/beam/erl_driver.h | 92 +++++----------- erts/emulator/beam/erl_drv_nif.h | 84 ++++++++++++++ erts/emulator/beam/erl_nif.c | 20 ++++ erts/emulator/beam/erl_nif.h | 62 +++-------- erts/emulator/beam/erl_nif_api_funcs.h | 6 + erts/emulator/beam/erl_time.h | 4 + erts/emulator/beam/erl_time_sup.c | 145 ++++++++++++++++++++++++ erts/emulator/beam/io.c | 23 ++++ erts/emulator/sys/win32/erl_win_dyn_driver.h | 14 +++ erts/emulator/test/nif_SUITE.erl | 153 +++++++++++++++++++++++++- erts/emulator/test/nif_SUITE_data/nif_SUITE.c | 94 +++++++++++++++- 13 files changed, 809 insertions(+), 112 deletions(-) diff --git a/erts/doc/src/erl_driver.xml b/erts/doc/src/erl_driver.xml index e717fc0c4e..e338e95938 100644 --- a/erts/doc/src/erl_driver.xml +++ b/erts/doc/src/erl_driver.xml @@ -347,6 +347,16 @@ the driver does not handle sizes that overflow an int all will work as before.

 + Time Measurement +

Support for time measurement in drivers: + + ErlDrvTime + ErlDrvTimeUnit + erl_drv_monotonic_time() + erl_drv_time_offset() + erl_drv_convert_time_unit() +

+ @@ -860,6 +870,24 @@ typedef struct ErlIOVec { erl_drv_tsd_get().

+ ErlDrvTime + +

A signed 64-bit integer type for representation of time.

+ + ErlDrvTimeUnit + +

An enumeration of time units supported by the driver API:

+ + ERL_DRV_SEC +

Seconds

 + ERL_DRV_MSEC +

Milliseconds

 + ERL_DRV_USEC +

Microseconds

 + ERL_DRV_NSEC +

Nanoseconds

 + + @@ -1023,6 +1051,10 @@ typedef struct ErlIOVec { Read a system timestamp +

This function is deprecated! Do not use it! + Use the documented + time measurement functionality + instead.

This function reads a timestamp into the memory pointed to by the parameter now. See the description of ErlDrvNowData for specification of its fields.

@@ -2997,6 +3029,86 @@ ERL_DRV_MAP int sz + + ErlDrvTimeerl_drv_monotonic_time(ErlDrvTimeUnit time_unit) + Get Erlang Monotonic Time + + +

Arguments:

+ + time_unit + Time unit of returned value. + +

+ Returns + Erlang + monotonic time. Note that it is not uncommon with + negative values. +

+

Returns ERL_DRV_TIME_ERROR if called with an invalid + time unit argument, or if called from a thread that is not a + scheduler thread.

+

See also:

+ + ErlDrvTime + ErlDrvTimeUnit + + + + + + ErlDrvTimeerl_drv_time_offset(ErlDrvTimeUnit time_unit) + Get current Time Offset + + +

Arguments:

+ + time_unit + Time unit of returned value. + +

Returns the current time offset between + Erlang monotonic time + and + Erlang system time + converted into the time_unit passed as argument.

+

Returns ERL_DRV_TIME_ERROR if called with an invalid + time unit argument, or if called from a thread that is not a + scheduler thread.

+

See also:

+ + ErlDrvTime + ErlDrvTimeUnit + + + + + + ErlDrvTimeerl_drv_convert_time_unit(ErlDrvTime val, ErlDrvTimeUnit from, ErlDrvTimeUnit to) + Convert time unit of a time value + + +

Arguments:

+ + val + Value to convert time unit for. + from + Time unit of val. + to + Time unit of returned value. + +

Converts the val value of time unit from to + the corresponding value of time unit to. The result is + rounded using the floor function.

+

Returns ERL_DRV_TIME_ERROR if called with an invalid + time unit argument.

+

See also:

+ + ErlDrvTime + ErlDrvTimeUnit + + + +
SEE ALSO diff --git a/erts/doc/src/erl_nif.xml b/erts/doc/src/erl_nif.xml index 2d8706169f..420c9fea38 100644 --- a/erts/doc/src/erl_nif.xml +++ b/erts/doc/src/erl_nif.xml @@ -317,6 +317,17 @@ ok libraries might however fail if deprecated features are used.

+ Time Measurement +

Support for time measurement in NIF libraries: + + ErlNifTime + ErlNifTimeUnit + enif_monotonic_time() + enif_time_offset() + enif_convert_time_unit() +

+ + Long-running NIFs

Native functions @@ -560,6 +571,25 @@ typedef enum {

A native signed 64-bit integer type.

 ErlNifUInt64

A native unsigned 64-bit integer type.

 + + ErlNifTime + +

A signed 64-bit integer type for representation of time.

+ + ErlNifTimeUnit + +

An enumeration of time units supported by the NIF API:

+ + ERL_NIF_SEC +

Seconds

 + ERL_NIF_MSEC +

Milliseconds

 + ERL_NIF_USEC +

Microseconds

 + ERL_NIF_NSEC +

Nanoseconds

 + +
@@ -1486,6 +1516,88 @@ enif_map_iterator_destroy(env, &iter);

Same as erl_drv_tsd_set.

+ + + + ErlNifTimeenif_monotonic_time(ErlNifTimeUnit time_unit) + Get Erlang Monotonic Time + + +

Arguments:

+ + time_unit + Time unit of returned value. + +

+ Returns + Erlang + monotonic time. Note that it is not uncommon with + negative values. +

+

Returns ERL_NIF_TIME_ERROR if called with an invalid + time unit argument, or if called from a thread that is not a + scheduler thread.

+

See also:

+ + ErlNifTime + ErlNifTimeUnit + + + + + + ErlNifTimeenif_time_offset(ErlNifTimeUnit time_unit) + Get current Time Offset + + +

Arguments:

+ + time_unit + Time unit of returned value. + +

Returns the current time offset between + Erlang monotonic time + and + Erlang system time + converted into the time_unit passed as argument.

+

Returns ERL_NIF_TIME_ERROR if called with an invalid + time unit argument, or if called from a thread that is not a + scheduler thread.

+

See also:

+ + ErlNifTime + ErlNifTimeUnit + + + + + + ErlNifTimeenif_convert_time_unit(ErlNifTime val, ErlNifTimeUnit from, ErlNifTimeUnit to) + Convert time unit of a time value + + +

Arguments:

+ + val + Value to convert time unit for. + from + Time unit of val. + to + Time unit of returned value. + +

Converts the val value of time unit from to + the corresponding value of time unit to. The result is + rounded using the floor function.

+

Returns ERL_NIF_TIME_ERROR if called with an invalid + time unit argument.

+

See also:

+ + ErlNifTime + ErlNifTimeUnit + + + +
SEE ALSO diff --git a/erts/emulator/beam/erl_driver.h b/erts/emulator/beam/erl_driver.h index dbb4d719c1..7ab58e336b 100644 --- a/erts/emulator/beam/erl_driver.h +++ b/erts/emulator/beam/erl_driver.h @@ -37,47 +37,6 @@ # endif #endif -#ifdef SIZEOF_CHAR -# define SIZEOF_CHAR_SAVED__ SIZEOF_CHAR -# undef SIZEOF_CHAR -#endif -#ifdef SIZEOF_SHORT -# define SIZEOF_SHORT_SAVED__ SIZEOF_SHORT -# undef SIZEOF_SHORT -#endif -#ifdef SIZEOF_INT -# define SIZEOF_INT_SAVED__ SIZEOF_INT -# undef SIZEOF_INT -#endif -#ifdef SIZEOF_LONG -# define SIZEOF_LONG_SAVED__ SIZEOF_LONG -# undef SIZEOF_LONG -#endif -#ifdef SIZEOF_LONG_LONG -# define SIZEOF_LONG_LONG_SAVED__ SIZEOF_LONG_LONG -# undef SIZEOF_LONG_LONG -#endif -#ifdef HALFWORD_HEAP_EMULATOR -# define HALFWORD_HEAP_EMULATOR_SAVED__ HALFWORD_HEAP_EMULATOR -# undef HALFWORD_HEAP_EMULATOR -#endif -#include "erl_int_sizes_config.h" -#if defined(SIZEOF_CHAR_SAVED__) && SIZEOF_CHAR_SAVED__ != SIZEOF_CHAR -# error SIZEOF_CHAR mismatch -#endif -#if defined(SIZEOF_SHORT_SAVED__) && SIZEOF_SHORT_SAVED__ != SIZEOF_SHORT -# error SIZEOF_SHORT mismatch -#endif -#if defined(SIZEOF_INT_SAVED__) && SIZEOF_INT_SAVED__ != SIZEOF_INT -# error SIZEOF_INT mismatch -#endif -#if defined(SIZEOF_LONG_SAVED__) && SIZEOF_LONG_SAVED__ != SIZEOF_LONG -# error SIZEOF_LONG mismatch -#endif -#if defined(SIZEOF_LONG_LONG_SAVED__) && SIZEOF_LONG_LONG_SAVED__ != SIZEOF_LONG_LONG -# error SIZEOF_LONG_LONG mismatch -#endif - /* This is OK to override by the NIF/driver implementor */ #if defined(HALFWORD_HEAP_EMULATOR_SAVED__) && !defined(HALFWORD_HEAP_EMULATOR) #define HALFWORD_HEAP_EMULATOR HALFWORD_HEAP_EMULATOR_SAVED__ @@ -134,7 +93,7 @@ typedef struct { #define ERL_DRV_EXTENDED_MARKER (0xfeeeeeed) #define ERL_DRV_EXTENDED_MAJOR_VERSION 3 -#define ERL_DRV_EXTENDED_MINOR_VERSION 2 +#define ERL_DRV_EXTENDED_MINOR_VERSION 3 /* * The emulator will refuse to load a driver with a major version @@ -176,28 +135,12 @@ typedef struct { /* * Integer types */ -#if defined(__WIN32__) && (SIZEOF_VOID_P == 8) -typedef unsigned __int64 ErlDrvTermData; -typedef unsigned __int64 ErlDrvUInt; -typedef signed __int64 ErlDrvSInt; -#else -typedef unsigned long ErlDrvTermData; -typedef unsigned long ErlDrvUInt; -typedef signed long ErlDrvSInt; -#endif -#if defined(__WIN32__) -typedef unsigned __int64 ErlDrvUInt64; -typedef __int64 ErlDrvSInt64; -#elif SIZEOF_LONG == 8 -typedef unsigned long ErlDrvUInt64; -typedef long ErlDrvSInt64; -#elif SIZEOF_LONG_LONG == 8 -typedef unsigned long long ErlDrvUInt64; -typedef long long ErlDrvSInt64; -#else -#error No 64-bit integer type -#endif +typedef ErlNapiUInt64 ErlDrvUInt64; +typedef ErlNapiSInt64 ErlDrvSInt64; +typedef ErlNapiUInt ErlDrvUInt; +typedef ErlNapiSInt ErlDrvSInt; +typedef ErlNapiUInt ErlDrvTermData; #if defined(__WIN32__) || defined(_WIN32) typedef ErlDrvUInt ErlDrvSizeT; @@ -250,6 +193,17 @@ typedef struct { unsigned long microsecs; } ErlDrvNowData; +typedef ErlDrvSInt64 ErlDrvTime; + +#define ERL_DRV_TIME_ERROR ((ErlDrvSInt64) ERTS_NAPI_TIME_ERROR__) + +typedef enum { + ERL_DRV_SEC = ERTS_NAPI_SEC__, + ERL_DRV_MSEC = ERTS_NAPI_MSEC__, + ERL_DRV_USEC = ERTS_NAPI_USEC__, + ERL_DRV_NSEC = ERTS_NAPI_NSEC__ +} ErlDrvTimeUnit; + /* * Error codes that can be return from driver. */ @@ -685,8 +639,16 @@ EXTERN long driver_async(ErlDrvPort ix, EXTERN int driver_lock_driver(ErlDrvPort ix); /* Get the current 'now' timestamp (analogue to erlang:now()) */ -EXTERN int driver_get_now(ErlDrvNowData *now); - +EXTERN int driver_get_now(ErlDrvNowData *now) ERL_DRV_DEPRECATED_FUNC; + +/* Erlang Monotonic Time */ +EXTERN ErlDrvTime erl_drv_monotonic_time(ErlDrvTimeUnit time_unit); +/* Time offset between Erlang Monotonic Time and Erlang System Time */ +EXTERN ErlDrvTime erl_drv_time_offset(ErlDrvTimeUnit time_unit); +/* Time unit conversion */ +EXTERN ErlDrvTime erl_drv_convert_time_unit(ErlDrvTime val, + ErlDrvTimeUnit from, + ErlDrvTimeUnit to); /* These were removed from the ANSI version, now they're back. */ diff --git a/erts/emulator/beam/erl_drv_nif.h b/erts/emulator/beam/erl_drv_nif.h index e2385f63f4..f6b946ae82 100644 --- a/erts/emulator/beam/erl_drv_nif.h +++ b/erts/emulator/beam/erl_drv_nif.h @@ -50,6 +50,90 @@ typedef enum { } ErlDrvDirtyJobFlags; #endif +#ifdef SIZEOF_CHAR +# define SIZEOF_CHAR_SAVED__ SIZEOF_CHAR +# undef SIZEOF_CHAR +#endif +#ifdef SIZEOF_SHORT +# define SIZEOF_SHORT_SAVED__ SIZEOF_SHORT +# undef SIZEOF_SHORT +#endif +#ifdef SIZEOF_INT +# define SIZEOF_INT_SAVED__ SIZEOF_INT +# undef SIZEOF_INT +#endif +#ifdef SIZEOF_LONG +# define SIZEOF_LONG_SAVED__ SIZEOF_LONG +# undef SIZEOF_LONG +#endif +#ifdef SIZEOF_LONG_LONG +# define SIZEOF_LONG_LONG_SAVED__ SIZEOF_LONG_LONG +# undef SIZEOF_LONG_LONG +#endif +#ifdef HALFWORD_HEAP_EMULATOR +# define HALFWORD_HEAP_EMULATOR_SAVED__ HALFWORD_HEAP_EMULATOR +# undef HALFWORD_HEAP_EMULATOR +#endif +#include "erl_int_sizes_config.h" +#if defined(SIZEOF_CHAR_SAVED__) && SIZEOF_CHAR_SAVED__ != SIZEOF_CHAR +# error SIZEOF_CHAR mismatch +#endif +#if defined(SIZEOF_SHORT_SAVED__) && SIZEOF_SHORT_SAVED__ != SIZEOF_SHORT +# error SIZEOF_SHORT mismatch +#endif +#if defined(SIZEOF_INT_SAVED__) && SIZEOF_INT_SAVED__ != SIZEOF_INT +# error SIZEOF_INT mismatch +#endif +#if defined(SIZEOF_LONG_SAVED__) && SIZEOF_LONG_SAVED__ != SIZEOF_LONG +# error SIZEOF_LONG mismatch +#endif +#if defined(SIZEOF_LONG_LONG_SAVED__) && SIZEOF_LONG_LONG_SAVED__ != SIZEOF_LONG_LONG +# error SIZEOF_LONG_LONG mismatch +#endif + +#if !defined(__GNUC__) && (defined(__WIN32__) || defined(_WIN32) || defined(_WIN32_)) +typedef unsigned __int64 ErlNapiUInt64; +typedef signed __int64 ErlNapiSInt64; +#define ERL_NAPI_SINT64_MAX__ 9223372036854775807i64 +#define ERL_NAPI_SINT64_MIN__ (-ERL_NAPI_SINT64_MAX__ - 1i64) +#elif SIZEOF_LONG == 8 +typedef unsigned long ErlNapiUInt64; +typedef signed long ErlNapiSInt64; +#define ERL_NAPI_SINT64_MAX__ 9223372036854775807L +#define ERL_NAPI_SINT64_MIN__ (-ERL_NAPI_SINT64_MAX__ - 1L) +#elif SIZEOF_LONG_LONG == 8 +typedef unsigned long long ErlNapiUInt64; +typedef signed long long ErlNapiSInt64; +#define ERL_NAPI_SINT64_MAX__ 9223372036854775807LL +#define ERL_NAPI_SINT64_MIN__ (-ERL_NAPI_SINT64_MAX__ - 1LL) +#else +# error No 64-bit integer type +#endif + +#if SIZEOF_VOID_P == 8 +typedef ErlNapiUInt64 ErlNapiUInt; +typedef ErlNapiSInt64 ErlNapiSInt; +#elif SIZEOF_VOID_P == 4 +# if SIZEOF_LONG == SIZEOF_VOID_P +typedef unsigned long ErlNapiUInt; +typedef signed long ErlNapiSInt; +# elif SIZEOF_INT == SIZEOF_VOID_P +typedef unsigned int ErlNapiUInt; +typedef signed int ErlNapiSInt; +# else +# error No 32-bit integer type +# endif +#else +# error Not support arch +#endif + +#define ERTS_NAPI_TIME_ERROR__ ERL_NAPI_SINT64_MIN__ + +#define ERTS_NAPI_SEC__ 0 +#define ERTS_NAPI_MSEC__ 1 +#define ERTS_NAPI_USEC__ 2 +#define ERTS_NAPI_NSEC__ 3 + #endif /* __ERL_DRV_NIF_H__ */ diff --git a/erts/emulator/beam/erl_nif.c b/erts/emulator/beam/erl_nif.c index d7a2076d85..3141b05e2b 100644 --- a/erts/emulator/beam/erl_nif.c +++ b/erts/emulator/beam/erl_nif.c @@ -1175,6 +1175,26 @@ void enif_thread_exit(void *resp) { erl_drv_thread_exit(resp); } int enif_thread_join(ErlNifTid tid, void **respp) { return erl_drv_thread_join(tid,respp); } int enif_getenv(const char *key, char *value, size_t *value_size) { return erl_drv_getenv(key, value, value_size); } +ErlNifTime enif_monotonic_time(ErlNifTimeUnit time_unit) +{ + return (ErlNifTime) erts_napi_monotonic_time((int) time_unit); +} + +ErlNifTime enif_time_offset(ErlNifTimeUnit time_unit) +{ + return (ErlNifTime) erts_napi_time_offset((int) time_unit); +} + +ErlNifTime +enif_convert_time_unit(ErlNifTime val, + ErlNifTimeUnit from, + ErlNifTimeUnit to) +{ + return (ErlNifTime) erts_napi_convert_time_unit((ErtsMonotonicTime) val, + (int) from, + (int) to); +} + int enif_fprintf(void* filep, const char* format, ...) { int ret; diff --git a/erts/emulator/beam/erl_nif.h b/erts/emulator/beam/erl_nif.h index 5e39343e9b..75070ad901 100644 --- a/erts/emulator/beam/erl_nif.h +++ b/erts/emulator/beam/erl_nif.h @@ -49,9 +49,10 @@ ** add ErlNifFunc flags ** 2.8: 18.0 add enif_has_pending_exception ** 2.9: 18.2 enif_getenv +** 2.10: Time API */ #define ERL_NIF_MAJOR_VERSION 2 -#define ERL_NIF_MINOR_VERSION 9 +#define ERL_NIF_MINOR_VERSION 10 /* * The emulator will refuse to load a nif-lib with a major version @@ -67,63 +68,36 @@ #include -#ifdef SIZEOF_CHAR -# define SIZEOF_CHAR_SAVED__ SIZEOF_CHAR -# undef SIZEOF_CHAR -#endif -#ifdef SIZEOF_SHORT -# define SIZEOF_SHORT_SAVED__ SIZEOF_SHORT -# undef SIZEOF_SHORT -#endif -#ifdef SIZEOF_INT -# define SIZEOF_INT_SAVED__ SIZEOF_INT -# undef SIZEOF_INT -#endif -#ifdef SIZEOF_LONG -# define SIZEOF_LONG_SAVED__ SIZEOF_LONG -# undef SIZEOF_LONG -#endif -#ifdef SIZEOF_LONG_LONG -# define SIZEOF_LONG_LONG_SAVED__ SIZEOF_LONG_LONG -# undef SIZEOF_LONG_LONG -#endif -#ifdef HALFWORD_HEAP_EMULATOR -# define HALFWORD_HEAP_EMULATOR_SAVED__ HALFWORD_HEAP_EMULATOR -# undef HALFWORD_HEAP_EMULATOR -#endif -#include "erl_int_sizes_config.h" - #ifdef __cplusplus extern "C" { #endif -#if (defined(__WIN32__) || defined(_WIN32) || defined(_WIN32_)) -typedef unsigned __int64 ErlNifUInt64; -typedef __int64 ErlNifSInt64; -#elif SIZEOF_LONG == 8 -typedef unsigned long ErlNifUInt64; -typedef long ErlNifSInt64; -#elif SIZEOF_LONG_LONG == 8 -typedef unsigned long long ErlNifUInt64; -typedef long long ErlNifSInt64; -#else -#error No 64-bit integer type -#endif +typedef ErlNapiUInt64 ErlNifUInt64; +typedef ErlNapiSInt64 ErlNifSInt64; +typedef ErlNapiUInt ErlNifUInt; +typedef ErlNapiSInt ErlNifSInt; #ifdef HALFWORD_HEAP_EMULATOR # define ERL_NIF_VM_VARIANT "beam.halfword" typedef unsigned int ERL_NIF_TERM; #else # define ERL_NIF_VM_VARIANT "beam.vanilla" -# if SIZEOF_LONG == SIZEOF_VOID_P -typedef unsigned long ERL_NIF_TERM; -# elif SIZEOF_LONG_LONG == SIZEOF_VOID_P -typedef unsigned long long ERL_NIF_TERM; -# endif +typedef ErlNifUInt ERL_NIF_TERM; #endif typedef ERL_NIF_TERM ERL_NIF_UINT; +typedef ErlNifSInt64 ErlNifTime; + +#define ERL_NIF_TIME_ERROR ((ErlNifSInt64) ERTS_NAPI_TIME_ERROR__) + +typedef enum { + ERL_NIF_SEC = ERTS_NAPI_SEC__, + ERL_NIF_MSEC = ERTS_NAPI_MSEC__, + ERL_NIF_USEC = ERTS_NAPI_USEC__, + ERL_NIF_NSEC = ERTS_NAPI_NSEC__ +} ErlNifTimeUnit; + struct enif_environment_t; typedef struct enif_environment_t ErlNifEnv; diff --git a/erts/emulator/beam/erl_nif_api_funcs.h b/erts/emulator/beam/erl_nif_api_funcs.h index 08b9afc6af..1448a508a2 100644 --- a/erts/emulator/beam/erl_nif_api_funcs.h +++ b/erts/emulator/beam/erl_nif_api_funcs.h @@ -160,6 +160,9 @@ ERL_NIF_API_FUNC_DECL(ERL_NIF_TERM,enif_schedule_nif,(ErlNifEnv*,const char*,int ERL_NIF_API_FUNC_DECL(int, enif_has_pending_exception, (ErlNifEnv *env, ERL_NIF_TERM* reason)); ERL_NIF_API_FUNC_DECL(ERL_NIF_TERM, enif_raise_exception, (ErlNifEnv *env, ERL_NIF_TERM reason)); ERL_NIF_API_FUNC_DECL(int,enif_getenv,(const char* key, char* value, size_t* value_size)); +ERL_NIF_API_FUNC_DECL(ErlNifTime, enif_monotonic_time, (ErlNifTimeUnit)); +ERL_NIF_API_FUNC_DECL(ErlNifTime, enif_time_offset, (ErlNifTimeUnit)); +ERL_NIF_API_FUNC_DECL(ErlNifTime, enif_convert_time_unit, (ErlNifTime, ErlNifTimeUnit, ErlNifTimeUnit)); /* ** ADD NEW ENTRIES HERE (before this comment) !!! @@ -312,6 +315,9 @@ ERL_NIF_API_FUNC_DECL(int,enif_is_on_dirty_scheduler,(ErlNifEnv*)); # define enif_has_pending_exception ERL_NIF_API_FUNC_MACRO(enif_has_pending_exception) # define enif_raise_exception ERL_NIF_API_FUNC_MACRO(enif_raise_exception) # define enif_getenv ERL_NIF_API_FUNC_MACRO(enif_getenv) +# define enif_monotonic_time ERL_NIF_API_FUNC_MACRO(enif_monotonic_time) +# define enif_time_offset ERL_NIF_API_FUNC_MACRO(enif_time_offset) +# define enif_convert_time_unit ERL_NIF_API_FUNC_MACRO(enif_convert_time_unit) /* ** ADD NEW ENTRIES HERE (before this comment) diff --git a/erts/emulator/beam/erl_time.h b/erts/emulator/beam/erl_time.h index 43e543e035..93a0d556bf 100644 --- a/erts/emulator/beam/erl_time.h +++ b/erts/emulator/beam/erl_time.h @@ -133,6 +133,10 @@ typedef struct { extern ErtsTimeSupData erts_time_sup__; +ErtsMonotonicTime erts_napi_monotonic_time(int time_unit); +ErtsMonotonicTime erts_napi_time_offset(int time_unit); +ErtsMonotonicTime erts_napi_convert_time_unit(ErtsMonotonicTime val, int from, int to); + ERTS_GLB_INLINE Uint64 erts_time_unit_conversion(Uint64 value, Uint32 from_time_unit, diff --git a/erts/emulator/beam/erl_time_sup.c b/erts/emulator/beam/erl_time_sup.c index 2c87b8e81c..5f12c7809a 100644 --- a/erts/emulator/beam/erl_time_sup.c +++ b/erts/emulator/beam/erl_time_sup.c @@ -33,6 +33,8 @@ #include "global.h" #define ERTS_WANT_TIMER_WHEEL_API #include "erl_time.h" +#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; @@ -57,6 +59,7 @@ static int time_sup_initialized = 0; #define ERTS_MONOTONIC_TIME_TERA \ (ERTS_MONOTONIC_TIME_GIGA*ERTS_MONOTONIC_TIME_KILO) +static void init_time_napi(void); static void schedule_send_time_offset_changed_notifications(ErtsMonotonicTime new_offset); @@ -948,6 +951,8 @@ erts_init_time_sup(int time_correction, ErtsTimeWarpMode time_warp_mode) ErtsMonotonicTime abs_native_offset, native_offset; #endif + init_time_napi(); + erts_hl_timer_init(); ASSERT(ERTS_MONOTONIC_TIME_MIN < ERTS_MONOTONIC_TIME_MAX); @@ -2197,6 +2202,146 @@ time_unit_conversion(Process *c_p, Eterm term, ErtsMonotonicTime val, ErtsMonoto return ret; } + +/* + * Time Native API (drivers and NIFs) + */ + +#define ERTS_NAPI_TIME_ERROR ((ErtsMonotonicTime) ERTS_NAPI_TIME_ERROR__) + +static void +init_time_napi(void) +{ + /* Verify that time native api constants are as expected... */ + + ASSERT(sizeof(ErtsMonotonicTime) == sizeof(ErlDrvTime)); + ASSERT(ERL_DRV_TIME_ERROR == (ErlDrvTime) ERTS_NAPI_TIME_ERROR); + ASSERT(ERL_DRV_TIME_ERROR < (ErlDrvTime) 0); + ASSERT(ERTS_NAPI_SEC__ == (int) ERL_DRV_SEC); + ASSERT(ERTS_NAPI_MSEC__ == (int) ERL_DRV_MSEC); + ASSERT(ERTS_NAPI_USEC__ == (int) ERL_DRV_USEC); + ASSERT(ERTS_NAPI_NSEC__ == (int) ERL_DRV_NSEC); + + ASSERT(sizeof(ErtsMonotonicTime) == sizeof(ErlNifTime)); + ASSERT(ERL_NIF_TIME_ERROR == (ErlNifTime) ERTS_NAPI_TIME_ERROR); + ASSERT(ERL_NIF_TIME_ERROR < (ErlNifTime) 0); + ASSERT(ERTS_NAPI_SEC__ == (int) ERL_NIF_SEC); + ASSERT(ERTS_NAPI_MSEC__ == (int) ERL_NIF_MSEC); + ASSERT(ERTS_NAPI_USEC__ == (int) ERL_NIF_USEC); + ASSERT(ERTS_NAPI_NSEC__ == (int) ERL_NIF_NSEC); +} + +ErtsMonotonicTime +erts_napi_monotonic_time(int time_unit) +{ + ErtsSchedulerData *esdp; + ErtsMonotonicTime mtime; + + /* At least for now only allow schedulers to do this... */ + esdp = erts_get_scheduler_data(); + if (!esdp) + return ERTS_NAPI_TIME_ERROR; + + mtime = time_sup.r.o.get_time(); + update_last_mtime(esdp, mtime); + + switch (time_unit) { + case ERTS_NAPI_SEC__: + mtime = ERTS_MONOTONIC_TO_SEC(mtime); + mtime += ERTS_MONOTONIC_OFFSET_SEC; + break; + case ERTS_NAPI_MSEC__: + mtime = ERTS_MONOTONIC_TO_MSEC(mtime); + mtime += ERTS_MONOTONIC_OFFSET_MSEC; + break; + case ERTS_NAPI_USEC__: + mtime = ERTS_MONOTONIC_TO_USEC(mtime); + mtime += ERTS_MONOTONIC_OFFSET_USEC; + break; + case ERTS_NAPI_NSEC__: + mtime = ERTS_MONOTONIC_TO_NSEC(mtime); + mtime += ERTS_MONOTONIC_OFFSET_NSEC; + break; + default: + return ERTS_NAPI_TIME_ERROR; + } + + return mtime; +} + +ErtsMonotonicTime +erts_napi_time_offset(int time_unit) +{ + ErtsSchedulerData *esdp; + ErtsSystemTime offs; + + /* At least for now only allow schedulers to do this... */ + esdp = erts_get_scheduler_data(); + if (!esdp) + return ERTS_NAPI_TIME_ERROR; + + offs = get_time_offset(); + switch (time_unit) { + case ERTS_NAPI_SEC__: + offs = ERTS_MONOTONIC_TO_SEC(offs); + offs -= ERTS_MONOTONIC_OFFSET_SEC; + break; + case ERTS_NAPI_MSEC__: + offs = ERTS_MONOTONIC_TO_MSEC(offs); + offs -= ERTS_MONOTONIC_OFFSET_MSEC; + break; + case ERTS_NAPI_USEC__: + offs = ERTS_MONOTONIC_TO_USEC(offs); + offs -= ERTS_MONOTONIC_OFFSET_USEC; + break; + case ERTS_NAPI_NSEC__: + offs = ERTS_MONOTONIC_TO_NSEC(offs); + offs -= ERTS_MONOTONIC_OFFSET_NSEC; + break; + default: + return ERTS_NAPI_TIME_ERROR; + } + return offs; +} + +ErtsMonotonicTime +erts_napi_convert_time_unit(ErtsMonotonicTime val, int from, int to) +{ + ErtsMonotonicTime ffreq, tfreq, denom; + /* + * Convertion between time units using floor function. + * + * Note that this needs to work also for negative + * values. Ordinary integer division on a negative + * value will give ceiling... + */ + + switch ((int) from) { + case ERTS_NAPI_SEC__: ffreq = 1; break; + case ERTS_NAPI_MSEC__: ffreq = 1000; break; + case ERTS_NAPI_USEC__: ffreq = 1000*1000; break; + case ERTS_NAPI_NSEC__: ffreq = 1000*1000*1000; break; + default: return ERTS_NAPI_TIME_ERROR; + } + + switch ((int) to) { + case ERTS_NAPI_SEC__: tfreq = 1; break; + case ERTS_NAPI_MSEC__: tfreq = 1000; break; + case ERTS_NAPI_USEC__: tfreq = 1000*1000; break; + case ERTS_NAPI_NSEC__: tfreq = 1000*1000*1000; break; + default: return ERTS_NAPI_TIME_ERROR; + } + + if (tfreq >= ffreq) + return val * (tfreq / ffreq); + + denom = ffreq / tfreq; + if (val >= 0) + return val / denom; + + return (val - (denom - 1)) / denom; +} + /* Built in functions */ BIF_RETTYPE monotonic_time_0(BIF_ALIST_0) diff --git a/erts/emulator/beam/io.c b/erts/emulator/beam/io.c index c64c8802b9..2bd31ee97e 100644 --- a/erts/emulator/beam/io.c +++ b/erts/emulator/beam/io.c @@ -50,6 +50,7 @@ #include "erl_map.h" #include "erl_bif_unique.h" #include "erl_hl_timer.h" +#include "erl_time.h" extern ErlDrvEntry fd_driver_entry; #ifndef __OSE__ @@ -6762,6 +6763,28 @@ driver_get_now(ErlDrvNowData *now_data) return 0; } +ErlDrvTime +erl_drv_monotonic_time(ErlDrvTimeUnit time_unit) +{ + return (ErlDrvTime) erts_napi_monotonic_time((int) time_unit); +} + +ErlDrvTime +erl_drv_time_offset(ErlDrvTimeUnit time_unit) +{ + return (ErlDrvTime) erts_napi_time_offset((int) time_unit); +} + +ErlDrvTime +erl_drv_convert_time_unit(ErlDrvTime val, + ErlDrvTimeUnit from, + ErlDrvTimeUnit to) +{ + return (ErlDrvTime) erts_napi_convert_time_unit((ErtsMonotonicTime) val, + (int) from, + (int) to); +} + static void ref_to_driver_monitor(Eterm ref, ErlDrvMonitor *mon) { RefThing *refp; diff --git a/erts/emulator/sys/win32/erl_win_dyn_driver.h b/erts/emulator/sys/win32/erl_win_dyn_driver.h index baac7c903e..9c699fdba0 100644 --- a/erts/emulator/sys/win32/erl_win_dyn_driver.h +++ b/erts/emulator/sys/win32/erl_win_dyn_driver.h @@ -103,6 +103,11 @@ WDD_TYPEDEF(ErlDrvSInt, driver_pdl_inc_refc, (ErlDrvPDL)); WDD_TYPEDEF(ErlDrvSInt, driver_pdl_dec_refc, (ErlDrvPDL)); WDD_TYPEDEF(void, driver_system_info, (ErlDrvSysInfo *, size_t)); WDD_TYPEDEF(int, driver_get_now, (ErlDrvNowData *)); +WDD_TYPEDEF(ErlDrvTime, erl_drv_monotonic_time, (ErlDrvTimeUnit)); +WDD_TYPEDEF(ErlDrvTime, erl_drv_time_offset, (ErlDrvTimeUnit)); +WDD_TYPEDEF(ErlDrvTime, erl_drv_convert_time_unit, (ErlDrvTime, + ErlDrvTimeUnit, + ErlDrvTimeUnit)); WDD_TYPEDEF(int, driver_monitor_process, (ErlDrvPort port, ErlDrvTermData process, ErlDrvMonitor *monitor)); @@ -217,6 +222,9 @@ typedef struct { WDD_FTYPE(driver_pdl_dec_refc) *driver_pdl_dec_refc; WDD_FTYPE(driver_system_info) *driver_system_info; WDD_FTYPE(driver_get_now) *driver_get_now; + WDD_FTYPE(erl_drv_monotonic_time) *erl_drv_monotonic_time; + WDD_FTYPE(erl_drv_time_offset) *erl_drv_time_offset; + WDD_FTYPE(erl_drv_convert_time_unit) *erl_drv_convert_time_unit; WDD_FTYPE(driver_monitor_process) *driver_monitor_process; WDD_FTYPE(driver_demonitor_process) *driver_demonitor_process; WDD_FTYPE(driver_get_monitored_process) *driver_get_monitored_process; @@ -328,6 +336,9 @@ extern TWinDynDriverCallbacks WinDynDriverCallbacks; #define driver_pdl_dec_refc (WinDynDriverCallbacks.driver_pdl_dec_refc) #define driver_system_info (WinDynDriverCallbacks.driver_system_info) #define driver_get_now (WinDynDriverCallbacks.driver_get_now) +#define erl_drv_monotonic_time (WinDynDriverCallbacks.erl_drv_monotonic_time) +#define erl_drv_time_offset (WinDynDriverCallbacks.erl_drv_time_offset) +#define erl_drv_convert_time_unit (WinDynDriverCallbacks.erl_drv_convert_time_unit) #define driver_monitor_process \ (WinDynDriverCallbacks.driver_monitor_process) #define driver_demonitor_process \ @@ -463,6 +474,9 @@ do { \ ((W).driver_pdl_dec_refc) = driver_pdl_dec_refc; \ ((W).driver_system_info) = driver_system_info; \ ((W).driver_get_now) = driver_get_now; \ +((W).erl_drv_monotonic_time) = erl_drv_monotonic_time; \ +((W).erl_drv_time_offset) = erl_drv_time_offset; \ +((W).erl_drv_convert_time_unit) = erl_drv_convert_time_unit; \ ((W).driver_monitor_process) = driver_monitor_process; \ ((W).driver_demonitor_process) = driver_demonitor_process; \ ((W).driver_get_monitored_process) = driver_get_monitored_process; \ diff --git a/erts/emulator/test/nif_SUITE.erl b/erts/emulator/test/nif_SUITE.erl index af2b955184..3d478654b1 100644 --- a/erts/emulator/test/nif_SUITE.erl +++ b/erts/emulator/test/nif_SUITE.erl @@ -42,7 +42,8 @@ otp_9668/1, consume_timeslice/1, dirty_nif/1, dirty_nif_send/1, dirty_nif_exception/1, call_dirty_nif_exception/1, nif_schedule/1, nif_exception/1, call_nif_exception/1, - nif_nan_and_inf/1, nif_atom_too_long/1 + nif_nan_and_inf/1, nif_atom_too_long/1, + nif_monotonic_time/1, nif_time_offset/1, nif_convert_time_unit/1 ]). -export([many_args_100/100]). @@ -72,7 +73,8 @@ all() -> otp_9828, otp_9668, consume_timeslice, nif_schedule, dirty_nif, dirty_nif_send, dirty_nif_exception, - nif_exception, nif_nan_and_inf, nif_atom_too_long + nif_exception, nif_nan_and_inf, nif_atom_too_long, + nif_monotonic_time, nif_time_offset, nif_convert_time_unit ]. groups() -> @@ -1783,6 +1785,148 @@ nif_raise_exceptions(NifFunc) -> end end, ok, ExcTerms). +-define(ERL_NIF_TIME_ERROR, -9223372036854775808). +-define(TIME_UNITS, [seconds, milli_seconds, micro_seconds, nano_seconds]). + +nif_monotonic_time(Config) -> + ?ERL_NIF_TIME_ERROR = monotonic_time(invalid_time_unit), + mtime_loop(1000000). + +mtime_loop(0) -> + ok; +mtime_loop(N) -> + chk_mtime(?TIME_UNITS), + mtime_loop(N-1). + +chk_mtime([]) -> + ok; +chk_mtime([TU|TUs]) -> + A = erlang:monotonic_time(TU), + B = monotonic_time(TU), + C = erlang:monotonic_time(TU), + try + true = A =< B, + true = B =< C + catch + _ : _ -> + ?t:fail({monotonic_time_missmatch, TU, A, B, C}) + end, + chk_mtime(TUs). + +nif_time_offset(Config) -> + ?ERL_NIF_TIME_ERROR = time_offset(invalid_time_unit), + toffs_loop(1000000). + +toffs_loop(0) -> + ok; +toffs_loop(N) -> + chk_toffs(?TIME_UNITS), + toffs_loop(N-1). + +chk_toffs([]) -> + ok; +chk_toffs([TU|TUs]) -> + TO = erlang:time_offset(TU), + NifTO = time_offset(TU), + case TO =:= NifTO of + true -> + ok; + false -> + case erlang:system_info(time_warp_mode) of + no_time_warp -> + ?t:fail({time_offset_mismatch, TU, TO, NifTO}); + _ -> + %% Most frequent time offset change + %% is currently only every 15:th + %% second so this should currently + %% work... + NTO = erlang:time_offset(TU), + case NifTO =:= NTO of + true -> + ok; + false -> + ?t:fail({time_offset_mismatch, TU, TO, NifTO, NTO}) + end + end + end, + chk_toffs(TUs). + +nif_convert_time_unit(Config) -> + ?ERL_NIF_TIME_ERROR = convert_time_unit(0, seconds, invalid_time_unit), + ?ERL_NIF_TIME_ERROR = convert_time_unit(0, invalid_time_unit, seconds), + ?ERL_NIF_TIME_ERROR = convert_time_unit(0, invalid_time_unit, invalid_time_unit), + lists:foreach(fun (Offset) -> + lists:foreach(fun (Diff) -> + chk_ctu(Diff+(Offset*1000*1000*1000)) + end, + [999999999999, + 99999999999, + 9999999999, + 999999999, + 99999999, + 9999999, + 999999, + 99999, + 999, + 99, + 9, + 1, + 11, + 101, + 1001, + 10001, + 100001, + 1000001, + 10000001, + 100000001, + 1000000001, + 100000000001, + 1000000000001, + 5, + 50, + 500, + 5000, + 50000, + 500000, + 5000000, + 50000000, + 500000000, + 5000000000, + 50000000000, + 500000000000]) + end, + [-4711, -1000, -475, -5, -4, -3, -2, -1, 0, + 1, 2, 3, 4, 5, 475, 1000, 4711]), + ctu_loop(1000000). + +ctu_loop(0) -> + ok; +ctu_loop(N) -> + chk_ctu(erlang:monotonic_time(nano_seconds)), + ctu_loop(N-1). + +chk_ctu(Time) -> + chk_ctu(Time, ?TIME_UNITS). + +chk_ctu(_Time, []) -> + ok; +chk_ctu(Time, [FromTU|FromTUs]) -> + chk_ctu(Time, FromTU, ?TIME_UNITS), + chk_ctu(Time, FromTUs). + +chk_ctu(_Time, _FromTU, []) -> + ok; +chk_ctu(Time, FromTU, [ToTU|ToTUs]) -> + T = erlang:convert_time_unit(Time, nano_seconds, FromTU), + TE = erlang:convert_time_unit(T, FromTU, ToTU), + TN = convert_time_unit(T, FromTU, ToTU), + case TE =:= TN of + false -> + ?t:fail({conversion_mismatch, FromTU, T, ToTU, TE, TN}); + true -> + chk_ctu(Time, FromTU, ToTUs) + end. + %% The NIFs: lib_version() -> undefined. call_history() -> ?nif_stub. @@ -1852,6 +1996,11 @@ make_map_remove_nif(_,_) -> ?nif_stub. maps_from_list_nif(_) -> ?nif_stub. sorted_list_from_maps_nif(_) -> ?nif_stub. +%% Time +monotonic_time(_) -> ?nif_stub. +time_offset(_) -> ?nif_stub. +convert_time_unit(_,_,_) -> ?nif_stub. + nif_stub_error(Line) -> exit({nif_not_loaded,module,?MODULE,line,Line}). diff --git a/erts/emulator/test/nif_SUITE_data/nif_SUITE.c b/erts/emulator/test/nif_SUITE_data/nif_SUITE.c index 98e1efe18f..8ebce4fef4 100644 --- a/erts/emulator/test/nif_SUITE_data/nif_SUITE.c +++ b/erts/emulator/test/nif_SUITE_data/nif_SUITE.c @@ -34,6 +34,10 @@ static ERL_NIF_TERM atom_self; static ERL_NIF_TERM atom_ok; static ERL_NIF_TERM atom_join; static ERL_NIF_TERM atom_binary_resource_type; +static ERL_NIF_TERM atom_seconds; +static ERL_NIF_TERM atom_milli_seconds; +static ERL_NIF_TERM atom_micro_seconds; +static ERL_NIF_TERM atom_nano_seconds; typedef struct @@ -138,6 +142,10 @@ static int load(ErlNifEnv* env, void** priv_data, ERL_NIF_TERM load_info) atom_ok = enif_make_atom(env,"ok"); atom_join = enif_make_atom(env,"join"); atom_binary_resource_type = enif_make_atom(env,"binary_resource_type"); + atom_seconds = enif_make_atom(env,"seconds"); + atom_milli_seconds = enif_make_atom(env,"milli_seconds"); + atom_micro_seconds = enif_make_atom(env,"micro_seconds"); + atom_nano_seconds = enif_make_atom(env,"nano_seconds"); *priv_data = data; return 0; @@ -1885,6 +1893,87 @@ static ERL_NIF_TERM sorted_list_from_maps_nif(ErlNifEnv* env, int argc, const ER return enif_make_tuple2(env, list_f, list_b); } + +static ERL_NIF_TERM monotonic_time(ErlNifEnv* env, int argc, const ERL_NIF_TERM argv[]) +{ + ErlNifTimeUnit time_unit; + + if (argc != 1) + return atom_false; + + if (enif_compare(argv[0], atom_seconds) == 0) + time_unit = ERL_NIF_SEC; + else if (enif_compare(argv[0], atom_milli_seconds) == 0) + time_unit = ERL_NIF_MSEC; + else if (enif_compare(argv[0], atom_micro_seconds) == 0) + time_unit = ERL_NIF_USEC; + else if (enif_compare(argv[0], atom_nano_seconds) == 0) + time_unit = ERL_NIF_NSEC; + else + time_unit = 4711; /* invalid time unit */ + + return enif_make_int64(env, enif_monotonic_time(time_unit)); +} + +static ERL_NIF_TERM time_offset(ErlNifEnv* env, int argc, const ERL_NIF_TERM argv[]) +{ + ErlNifTimeUnit time_unit; + + if (argc != 1) + return atom_false; + + if (enif_compare(argv[0], atom_seconds) == 0) + time_unit = ERL_NIF_SEC; + else if (enif_compare(argv[0], atom_milli_seconds) == 0) + time_unit = ERL_NIF_MSEC; + else if (enif_compare(argv[0], atom_micro_seconds) == 0) + time_unit = ERL_NIF_USEC; + else if (enif_compare(argv[0], atom_nano_seconds) == 0) + time_unit = ERL_NIF_NSEC; + else + time_unit = 4711; /* invalid time unit */ + return enif_make_int64(env, enif_time_offset(time_unit)); +} + +static ERL_NIF_TERM convert_time_unit(ErlNifEnv* env, int argc, const ERL_NIF_TERM argv[]) +{ + ErlNifSInt64 i64; + ErlNifTime val; + ErlNifTimeUnit from, to; + + if (argc != 3) + return atom_false; + + if (!enif_get_int64(env, argv[0], &i64)) + return enif_make_badarg(env); + + val = (ErlNifTime) i64; + + if (enif_compare(argv[1], atom_seconds) == 0) + from = ERL_NIF_SEC; + else if (enif_compare(argv[1], atom_milli_seconds) == 0) + from = ERL_NIF_MSEC; + else if (enif_compare(argv[1], atom_micro_seconds) == 0) + from = ERL_NIF_USEC; + else if (enif_compare(argv[1], atom_nano_seconds) == 0) + from = ERL_NIF_NSEC; + else + from = 4711; /* invalid time unit */ + + if (enif_compare(argv[2], atom_seconds) == 0) + to = ERL_NIF_SEC; + else if (enif_compare(argv[2], atom_milli_seconds) == 0) + to = ERL_NIF_MSEC; + else if (enif_compare(argv[2], atom_micro_seconds) == 0) + to = ERL_NIF_USEC; + else if (enif_compare(argv[2], atom_nano_seconds) == 0) + to = ERL_NIF_NSEC; + else + to = 4711; /* invalid time unit */ + + return enif_make_int64(env, enif_convert_time_unit(val, from, to)); +} + static ErlNifFunc nif_funcs[] = { {"lib_version", 0, lib_version}, @@ -1954,7 +2043,10 @@ static ErlNifFunc nif_funcs[] = {"make_map_update_nif", 3, make_map_update_nif}, {"make_map_remove_nif", 2, make_map_remove_nif}, {"maps_from_list_nif", 1, maps_from_list_nif}, - {"sorted_list_from_maps_nif", 1, sorted_list_from_maps_nif} + {"sorted_list_from_maps_nif", 1, sorted_list_from_maps_nif}, + {"monotonic_time", 1, monotonic_time}, + {"time_offset", 1, time_offset}, + {"convert_time_unit", 3, convert_time_unit} }; ERL_NIF_INIT(nif_SUITE,nif_funcs,load,reload,upgrade,unload) -- cgit v1.2.3