aboutsummaryrefslogtreecommitdiffstats
diff options
context:
space:
mode:
-rw-r--r--erts/doc/src/erlang.xml64
-rw-r--r--erts/emulator/beam/atom.names2
-rw-r--r--erts/emulator/beam/erl_bif_trace.c41
-rw-r--r--erts/emulator/beam/erl_process.c1
-rw-r--r--erts/emulator/beam/erl_process.h87
-rw-r--r--erts/emulator/beam/erl_trace.c700
-rw-r--r--erts/emulator/beam/erl_trace.h32
-rw-r--r--erts/emulator/test/system_profile_SUITE.erl155
-rw-r--r--erts/emulator/test/trace_bif_SUITE.erl249
-rw-r--r--erts/preloaded/ebin/erlang.beambin102000 -> 102116 bytes
-rw-r--r--erts/preloaded/src/erlang.erl13
-rw-r--r--lib/kernel/doc/src/seq_trace.xml28
-rw-r--r--lib/kernel/src/kernel.app.src2
-rw-r--r--lib/kernel/src/seq_trace.erl14
-rw-r--r--lib/kernel/test/seq_trace_SUITE.erl166
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
index 58516c0ff3..36862802ca 100644
--- a/erts/preloaded/ebin/erlang.beam
+++ b/erts/preloaded/ebin/erlang.beam
Binary files differ
diff --git a/erts/preloaded/src/erlang.erl b/erts/preloaded/src/erlang.erl
index 5fc6d14938..063b9a1f26 100644
--- a/erts/preloaded/src/erlang.erl
+++ b/erts/preloaded/src/erlang.erl
@@ -185,6 +185,8 @@
'receive' |
'print' |
'timestamp' |
+ 'monotonic_timestamp' |
+ 'strict_monotonic_timestamp' |
'label' |
'serial'.
@@ -198,7 +200,10 @@
'exclusive' |
'runnable_ports' |
'runnable_procs' |
- 'scheduler'.
+ 'scheduler' |
+ 'timestamp' |
+ 'monotonic_timestamp' |
+ 'strict_monotonic_timestamp'.
-type system_monitor_option() ::
'busy_port' |
@@ -230,6 +235,8 @@
garbage_collection |
timestamp |
cpu_timestamp |
+ monotonic_timestamp |
+ strict_monotonic_timestamp |
arity |
set_on_spawn |
set_on_first_spawn |
@@ -258,6 +265,8 @@
running |
garbage_collection |
timestamp |
+ monotonic_timestamp |
+ strict_monotonic_timestamp |
arity.
-type trace_info_return() ::
@@ -2178,6 +2187,8 @@ send(_Dest,_Msg,_Options) ->
('receive') -> {'receive', boolean()};
(print) -> {print, boolean()};
(timestamp) -> {timestamp, boolean()};
+ (monotonic_timestamp) -> {timestamp, boolean()};
+ (strict_monotonic_timestamp) -> {strict_monotonic_timestamp, boolean()};
(label) -> [] | {label, non_neg_integer()};
(serial) -> [] | {serial, {non_neg_integer(), non_neg_integer()}}.
seq_trace_info(_What) ->
diff --git a/lib/kernel/doc/src/seq_trace.xml b/lib/kernel/doc/src/seq_trace.xml
index 3439111035..9f191d488d 100644
--- a/lib/kernel/doc/src/seq_trace.xml
+++ b/lib/kernel/doc/src/seq_trace.xml
@@ -127,6 +127,34 @@ seq_trace:set_token(OldToken), % activate the trace token again
enables/disables a timestamp to be generated for each
traced event. Default is <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}]).