diff options
| -rw-r--r-- | erts/doc/src/erlang.xml | 64 | ||||
| -rw-r--r-- | erts/emulator/beam/atom.names | 2 | ||||
| -rw-r--r-- | erts/emulator/beam/erl_bif_trace.c | 41 | ||||
| -rw-r--r-- | erts/emulator/beam/erl_process.c | 1 | ||||
| -rw-r--r-- | erts/emulator/beam/erl_process.h | 87 | ||||
| -rw-r--r-- | erts/emulator/beam/erl_trace.c | 700 | ||||
| -rw-r--r-- | erts/emulator/beam/erl_trace.h | 32 | ||||
| -rw-r--r-- | erts/emulator/test/system_profile_SUITE.erl | 155 | ||||
| -rw-r--r-- | erts/emulator/test/trace_bif_SUITE.erl | 249 | ||||
| -rw-r--r-- | erts/preloaded/ebin/erlang.beam | bin | 102000 -> 102116 bytes | |||
| -rw-r--r-- | erts/preloaded/src/erlang.erl | 13 | ||||
| -rw-r--r-- | lib/kernel/doc/src/seq_trace.xml | 28 | ||||
| -rw-r--r-- | lib/kernel/src/kernel.app.src | 2 | ||||
| -rw-r--r-- | lib/kernel/src/seq_trace.erl | 14 | ||||
| -rw-r--r-- | 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 <c>inactive</c>, and later <c>active</c> when the port callback returns.</p> </item> + <tag><c>monotonic_timestamp</c></tag> + <item> + <p>Timestamps in profile messages will use + <seealso marker="time_correction#Erlang_Monotonic_Time">Erlang + monotonic time</seealso>. The time-stamp (Ts) has the same + format and value as produced by <c>erlang:monotonic_time()</c>.</p> + </item> <tag><c>runnable_procs</c></tag> <item> <p>If a process is put into or removed from the run queue, a @@ -7759,6 +7766,25 @@ ok <c>{profile, scheduler, Id, State, NoScheds, Ts}</c>, is sent to <c><anno>ProfilerPid</anno></c>.</p> </item> + <tag><c>strict_monotonic_timestamp</c></tag> + <item> + <p>Timestamps in profile messages will consisting of + <seealso marker="time_correction#Erlang_Monotonic_Time">Erlang + monotonic time</seealso> and a monotonically increasing + integer. The time-stamp (Ts) has the same format and value + as produced by <c>{erlang:monotonic_time(), + erlang:unique_integer([monotonic])}</c>.</p> + </item> + <tag><c>timestamp</c></tag> + <item> + <p>Timestamps in profile messages will include a + time-stamp (Ts) that has the same form as returned by + <c>erlang:now()</c>. This is also the default if no + timestamp flag is given. If <c>cpu_timestamp</c> has + been enabled via <c>erlang:trace/3</c>, this will also + effect the timestamp produced in profiling messages + when <c>timestamp</c> flag is enabled.</p> + </item> </taglist> <note><p><c>erlang:system_profile</c> is considered experimental and its behavior can change in a future release.</p> @@ -8118,7 +8144,10 @@ timestamp() -> <tag><c>cpu_timestamp</c></tag> <item> <p>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 <c>timestamp</c> flag to be + in CPU time, not wall clock time. That is, <c>cpu_timestamp</c> + will not be used if <c>monotonic_timestamp</c>, or + <c>strict_monotonic_timestamp</c> is enabled. Only allowed with <c>PidSpec==all</c>. If the host machine OS does not support high-resolution CPU time measurements, <c>trace/3</c> 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.</p> </item> + <tag><c>monotonic_timestamp</c></tag> + <item> + <p>Includes an + <seealso marker="time_correction#Erlang_Monotonic_Time">Erlang + monotonic time</seealso> time-stamp in all trace messages. The + time-stamp (Ts) has the same format and value as produced by + <c>erlang:monotonic_time()</c>. This flag overrides + the <c>cpu_timestamp</c> flag.</p> + </item> + <tag><c>strict_monotonic_timestamp</c></tag> + <item> + <p>Includes an timestamp consisting of + <seealso marker="time_correction#Erlang_Monotonic_Time">Erlang + monotonic time</seealso> and a monotonically increasing + integer in all trace messages. The time-stamp (Ts) has the + same format and value as produced by + <c>{erlang:monotonic_time(), + erlang:unique_integer([monotonic])}</c>. This flag overrides + the <c>cpu_timestamp</c> flag.</p> + </item> <tag><c>arity</c></tag> <item> <p>Used with the <c>call</c> trace flag. @@ -8172,9 +8221,16 @@ timestamp() -> in the following list. <c>Pid</c> is the process identifier of the traced process in which the traced event has occurred. The third tuple element is the message tag.</p> - <p>If flag <c>timestamp</c> is given, the first tuple - element is <c>trace_ts</c> instead, and the time-stamp - is added last in the message tuple.</p> + <p>If flag <c>timestamp</c>, <c>strict_monotonic_timestamp</c>, or + <c>monotonic_timestamp</c> is given, the first tuple + element is <c>trace_ts</c> instead, and the time-stamp + is added as an extra element last in the message tuple. If + multiple timestamp flags are passed, <c>timestamp</c> has + precedence over <c>strict_monotonic_timestamp</c> which + in turn has precedence over <c>monotonic_timestamp</c>. 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.</p> <marker id="trace_3_trace_messages"></marker> <taglist> <tag><c>{trace, Pid, 'receive', Msg}</c></tag> 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 Binary files differindex 58516c0ff3..36862802ca 100644 --- a/erts/preloaded/ebin/erlang.beam +++ b/erts/preloaded/ebin/erlang.beam 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 <c>false</c>.</p> </item> + <tag><c>set_token(strict_monotonic_timestamp, <anno>Bool</anno>)</c></tag> + <item> + <p>A trace token flag (<c>true | false</c>) which + enables/disables a strict monotonic timestamp to be generated + for each traced event. Default is <c>false</c>. Timestamps will + consist of + <seealso marker="erts:time_correction#Erlang_Monotonic_Time">Erlang + monotonic time</seealso> and a monotonically increasing + integer. The time-stamp has the same format and value + as produced by <c>{erlang:monotonic_time(), + erlang:unique_integer([monotonic])}</c>.</p> + </item> + <tag><c>set_token(monotonic_timestamp, <anno>Bool</anno>)</c></tag> + <item> + <p>A trace token flag (<c>true | false</c>) which + enables/disables a strict monotonic timestamp to be generated + for each traced event. Default is <c>false</c>. Timestamps + will use + <seealso marker="erts:time_correction#Erlang_Monotonic_Time">Erlang + monotonic time</seealso>. The time-stamp has the same + format and value as produced by <c>erlang:monotonic_time()</c>.</p> + </item> + <p>If multiple timestamp flags are passed, <c>timestamp</c> has + precedence over <c>strict_monotonic_timestamp</c> which + in turn has precedence over <c>monotonic_timestamp</c>. 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.</p> </taglist> </desc> </func> 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}]). |