* [PATCH v28 0/8] Timestamp synchronization of host - guest tracing session
@ 2021-02-08 6:17 Tzvetomir Stoyanov (VMware)
2021-02-08 6:17 ` [PATCH v28 1/8] trace-cmd: Save command lines in VM agent Tzvetomir Stoyanov (VMware)
` (8 more replies)
0 siblings, 9 replies; 25+ messages in thread
From: Tzvetomir Stoyanov (VMware) @ 2021-02-08 6:17 UTC (permalink / raw)
To: rostedt; +Cc: linux-trace-devel
Basic infrastructure for host - guest timestamp synchronization and a
PoC implementation of PTP-like and KVM algorithms.
The KVM plugin is with higher weight than PTP, it is preferred in case both
are active. KVM is used only if x86-tsc clock is selected for the current
trace, PTP is used for all other cases.
These changes depend on commits:
"trace-cmd: Fix plist allocation check in trace-msg.c"
https://patchwork.kernel.org/project/linux-trace-devel/patch/20210203165431.792152a4@gandalf.local.home/
"trace-cmd: Fix SEGFAULT when no tsync_protos are supplied"
https://patchwork.kernel.org/project/linux-trace-devel/patch/20210203171018.5b82a0a7@gandalf.local.home/
v28 changes:
- Fix bugs, introduced by previous trace-cmd commits, related to tracefs
library usage.
- Removed unused type defines for trace packets.
v27 changes:
- Fixed broken compilation due to usage of old libtracefs APIs.
- Rewrote complex macros to follow the Linux kernel requirements for macros.
- Removed pathces from the set, that were already merged upstream.
v26 changes:
- Rebased on top of latest master.
- Abstracted Time sync protocol names in a structure, to avoid using
triple char pointers.
- Removed a patch from the set, as it is already merged:
"trace-cmd: Add new libtrasefs API to get the current trace clock".
- Minor coding style changes, for better code readability.
v25 changes:
- Addressed Steven's comments.
- Reorded the patches in the plugin - put the PTP and KVM PoC patches
last and all other fixes and improvements before them.
- Implemented a new libtrasefs API to get the current trace clock.
- Replaced IDs of trace timestamps synchronization protocols with strings.
- Implemented an "accuracy" parameter for timestamps synchronization
protocols.
- Added "scaling ratio" correction, calculated by the timestamp
synchronization protocols.
- Added flags, declared by the timestamps synchronization protocols,
and stored in the trace.dat file, together with the calculated
time offsets.
- Implemented timestamp offset calculation per virtual CPU.
v24 changes:
- trace-cmd internal refactoring, needed for KVM timestamp synchronization
plugin.
- Added KVM timestamp synchronization plugin.
v23 changes:
- Added flags to PTP start message to control the behaviour of the
algorithm. This is for development purposes mostly, to compare and
evaluate how these changes affect the accuracy.
PTP_FLAG_FASTEST_RESPONSE: Consider only the probe with fastest
response time, otherwise make a histogram
from all probes.
PTP_FLAG_USE_MARKER: Use trace marker to get the clock,
otherwise use directly the system clock
v22 changes, addressed Steven's comments:
- Fixed error flow in read_qemu_guests_pids(), free allocated resources
in case of an error.
- Fixed initialisation of reallocated memmory in set_vcpu_pid_mapping().
- Fixed bitmask logic in tracecmd_tsync_proto_select().
- Fixed usage of wrong structure in make_trace_resp().
v21 changes:
- Rebased on top of latest master.
- Remove these two patches from the set, as they are already merged:
trace-cmd: Add new library API for local CPU count
trace-cmd: Add support for negative time offsets in trace.dat file
- Added more descriptive warning message when fails to extract Time Shift
information from the trace.dat file.
- Added a warning message when fails to obtain vcpu - pid mappings.
- Handle the case with sparse VCPU numbers in VCPU - PID mapping
array.
- Fixed broken recording over FIFOs.
v20 changes:
- Rebased on top of latest master.
- Removed the VCPUS_MAX hardcoded limit, reimplemented the cpu_pid[] array
to be dynamically allocated.
- Added a warning when reading of TRACECMD_OPTION_TIME_SHIFT option
fails, due to unexpected option's size.
- Improved loading of TRACECMD_OPTION_GUEST option data, as Steven
suggested.
v19 changes:
- Rebased on top of latest master. The librtacefs is already merged,
this allows to drop few patches from the set and use librtacefs APIs
instead.
- Reimplemented all new trace.dat options to be in binary format,
instead of text. Leverage the new "trace-cmd dump" sub command to
track what is written in the file.
- Addressed Steven's comments.
v18 changes: addressed Steven Rostdet comments:
- Replaced semaphores with pthread mutexes.
- Made bitmask with time sync protocols unlimited, so we can support
more than 32 protocols. That required to redesign the trace request
packet format.
- A lot of small fixes.
v17 changes:
- Implemented new PTP logic for calculating the clocks offset, using
histogram of all PTP samples. It gives better results than the logic
with the fastest response time, so set the new one as default in the
POC patch.
v16 changes:
- Fixed compilation in case no VSOCK is available (Thanks to Slavomir Kaslev)
- Fixed a typo in trace-cmd-record.1.txt (Thanks to Slavomir Kaslev)
- Added forgotten file in the patch "trace-cmd: Add new library APIs for
ftrace instances." - trace-instance.c
- Fixed few compilation warnings related to TSYNC_DEBUG code.
- Removed a blank line at the end of "tsync_readme" file.
v15 changes:
- Removed the patch for "--proc-map" from the series, as it should not
be part of it.
v14 changes:
- Bring back the PTP-like algorithm and removed the ftrace event based logic.
- Reimplemented the PTP-like algorithm to use raw ftrace markers, instead of clock_gettime() API.
- Refactored the logic to be algorithm independent and plugin friendly.
- Implemented continuous timestamps synchronization, while the trace is running.
- Moved logic from trace-cmd application to libtracecmd, as new library APIs.
- Implemented new trace id functionality.
- Implemented new guest section in host trace.dat file.
v13 changes:
- Remove few patches from the set, as they were merged.
- Rebased to the latest master, Slavomirs patchest "Add VM kernel tracing over
vsockets and FIFOs" got merged!
v12 changes:
- Rebased on top of Slavomir's v13 "Add VM kernel tracing over vsockets and FIFOs"
v11 changes:
- Rebased on top of Slavomir's v10 "Add VM kernel tracing over vsockets and FIFOs"
- Addressed Slavomir's commnents from version 10 of the patch series.
v10 changes:
- Fixed broken compilation, call to timestamp_correction_calc() in timestamp_correct
was smashed.
- Replaced deprecated tep_data_event_from_type() API with tep_find_event().
- Fixed a warning on assignment const to non const.
v9 changes:
- Fixed implementation of binary search algorithm in timestamp_correct()
v8 changes:
- Added rmdir() call in tracecmd_remove_instance(), to completely remove the instance.
However, there is an issue with deleting the instances using rmdir(), which is investigated.
- Few changes in read_qemu_guests_pids(), timestamp_correct(), tsync_offset_load()
tracecmd_clock_context_new() and find_raw_events() suggested by Slavomir.
v7 changes:
- Added warning messages in case time synchronization cannot be negotiated or fails.
- Few optimizations and checks in read_qemu_guests_pids(), tsync_offset_load(),
and find_raw_events(), suggested by Slavomir Kaslev.
- Reworked timestamp_correct() to not use static variables.
- Check TRACECMD_OPTION_TIME_SHIFT before reading time sync samples from the trace.dat file
v6 changes:
- Refactored tracecmd_msg_snd_time_sync() and tracecmd_msg_rcv_time_sync() functions:
removed any time sync calculations logic as separate functions in trace-timesync.c file
- Defined TSYNC_PROBE, TSYNC_REQ and TSYNC_RESP messages, in order to make the time sync
protocol comprehensible.
- Addressed Steven Rostedt comments.
- Addressed Slavomir Kaslev commnets.
v5 changes:
- Rebased to Slavomir's v8 "Add VM kernel tracing over vsockets and FIFOs"
patch series.
- Implemented an algorithm for time drift correction.
- Addressed Slavomir's commnets.
- Refactored the code: moved all time sync specific implementation in trace-timesync.c
- Isolated all hardcoded event specific stuff in a structure, so it could be easily
moved to external plugins.
- Added a check for VSOCK support: do not perform vsock dependent time synchronisation
in case there is no VSOCK support.
v4 changes:
- Removed the implementation of PTP-like algorithm. The current
logic relies on matching time stamps of kvm_exit/virtio_transport_recv_pkt
events on host to virtio_transport_alloc_pkt/vp_notify events on guest.
- Rebased to Slavomir's v7 "Add VM kernel tracing over vsockets and FIFOs"
patch series.
- Decreased the time synch probes from 5000 to 300.
- Addressed Steven Rostedt comments.
- Code cleanup.
v3 changes:
- Removed any magic constants, used in the PTP-like algorithm,
as Slavomir Kaslev suggested.
- Implemented new algorithm, based on mapping kvm_exit events
in host context to vsock_send events in guest context,
suggested by Steven Rostedt.
v2 changes:
- Addressed Steven Rostedt comments.
- Modified PTP-like timestamps sync algorithm to gain more accuracy, with the
help of Yordan Karadzhov and Slavomir Kaslev.
Tzvetomir Stoyanov (VMware) (8):
trace-cmd: Save command lines in VM agent
trace-cmd: Fix bug in getting tracing dir in trace-cmd agent
trace-cmd: Removed unused s64 define
trace-cmd: Add timestamp synchronization per vCPU
trace-cmd: Add dummy function to initialize timestamp sync logic
trace-cmd: [POC] PTP-like algorithm for host - guest timestamp
synchronization
trace-cmd: Debug scripts for PTP-like algorithm for host - guest
timestamp synchronization
trace-cmd [POC]: Add KVM timestamp synchronization plugin
lib/trace-cmd/Makefile | 2 +
.../include/private/trace-cmd-private.h | 5 +-
lib/trace-cmd/include/trace-tsync-local.h | 23 +-
lib/trace-cmd/trace-input.c | 188 +++--
lib/trace-cmd/trace-msg.c | 1 -
lib/trace-cmd/trace-output.c | 4 +-
lib/trace-cmd/trace-timesync-kvm.c | 460 +++++++++++
lib/trace-cmd/trace-timesync-ptp.c | 715 ++++++++++++++++++
lib/trace-cmd/trace-timesync.c | 222 ++++--
scripts/debug/tsync_hist.py | 57 ++
scripts/debug/tsync_readme | 12 +
scripts/debug/tsync_res.py | 46 ++
tracecmd/trace-agent.c | 2 +
tracecmd/trace-dump.c | 52 +-
tracecmd/trace-record.c | 26 +-
tracecmd/trace-tsync.c | 67 +-
16 files changed, 1698 insertions(+), 184 deletions(-)
create mode 100644 lib/trace-cmd/trace-timesync-kvm.c
create mode 100644 lib/trace-cmd/trace-timesync-ptp.c
create mode 100644 scripts/debug/tsync_hist.py
create mode 100644 scripts/debug/tsync_readme
create mode 100644 scripts/debug/tsync_res.py
--
2.29.2
^ permalink raw reply [flat|nested] 25+ messages in thread
* [PATCH v28 1/8] trace-cmd: Save command lines in VM agent
2021-02-08 6:17 [PATCH v28 0/8] Timestamp synchronization of host - guest tracing session Tzvetomir Stoyanov (VMware)
@ 2021-02-08 6:17 ` Tzvetomir Stoyanov (VMware)
2021-02-17 20:55 ` Steven Rostedt
2021-02-08 6:17 ` [PATCH v28 2/8] trace-cmd: Fix bug in getting tracing dir in trace-cmd agent Tzvetomir Stoyanov (VMware)
` (7 subsequent siblings)
8 siblings, 1 reply; 25+ messages in thread
From: Tzvetomir Stoyanov (VMware) @ 2021-02-08 6:17 UTC (permalink / raw)
To: rostedt; +Cc: linux-trace-devel
Command lines were not saved in the guest tracing file, due to bug
inrtoduced by commit:
https://git.kernel.org/pub/scm/utils/trace-cmd/trace-cmd.git/commit/?id=1eea02a4bef10507d157489a1ee97f273db7b319
Signed-off-by: Tzvetomir Stoyanov (VMware) <tz.stoyanov@gmail.com>
---
lib/trace-cmd/include/private/trace-cmd-private.h | 3 +++
lib/trace-cmd/trace-output.c | 4 ++--
tracecmd/trace-record.c | 1 +
3 files changed, 6 insertions(+), 2 deletions(-)
diff --git a/lib/trace-cmd/include/private/trace-cmd-private.h b/lib/trace-cmd/include/private/trace-cmd-private.h
index a08566e6..d370fa8b 100644
--- a/lib/trace-cmd/include/private/trace-cmd-private.h
+++ b/lib/trace-cmd/include/private/trace-cmd-private.h
@@ -503,4 +503,7 @@ void *tracecmd_record_page(struct tracecmd_input *handle,
void *tracecmd_record_offset(struct tracecmd_input *handle,
struct tep_record *record);
+int save_tracing_file_data(struct tracecmd_output *handle,
+ const char *filename);
+
#endif /* _TRACE_CMD_PRIVATE_H */
diff --git a/lib/trace-cmd/trace-output.c b/lib/trace-cmd/trace-output.c
index 032c8ff4..4ffb4d47 100644
--- a/lib/trace-cmd/trace-output.c
+++ b/lib/trace-cmd/trace-output.c
@@ -797,8 +797,8 @@ static int read_ftrace_printk(struct tracecmd_output *handle)
return -1;
}
-static int save_tracing_file_data(struct tracecmd_output *handle,
- const char *filename)
+int save_tracing_file_data(struct tracecmd_output *handle,
+ const char *filename)
{
unsigned long long endian8;
char *file = NULL;
diff --git a/tracecmd/trace-record.c b/tracecmd/trace-record.c
index a1c4e919..a0a0b8b5 100644
--- a/tracecmd/trace-record.c
+++ b/tracecmd/trace-record.c
@@ -3770,6 +3770,7 @@ static void setup_agent(struct buffer_instance *instance,
network_handle = tracecmd_create_init_fd_msg(instance->msg_handle,
listed_events);
add_options(network_handle, ctx);
+ save_tracing_file_data(network_handle, "saved_cmdlines");
tracecmd_write_cpus(network_handle, instance->cpu_count);
tracecmd_write_options(network_handle);
tracecmd_msg_finish_sending_data(instance->msg_handle);
--
2.29.2
^ permalink raw reply related [flat|nested] 25+ messages in thread
* [PATCH v28 2/8] trace-cmd: Fix bug in getting tracing dir in trace-cmd agent
2021-02-08 6:17 [PATCH v28 0/8] Timestamp synchronization of host - guest tracing session Tzvetomir Stoyanov (VMware)
2021-02-08 6:17 ` [PATCH v28 1/8] trace-cmd: Save command lines in VM agent Tzvetomir Stoyanov (VMware)
@ 2021-02-08 6:17 ` Tzvetomir Stoyanov (VMware)
2021-02-08 6:17 ` [PATCH v28 3/8] trace-cmd: Removed unused s64 define Tzvetomir Stoyanov (VMware)
` (6 subsequent siblings)
8 siblings, 0 replies; 25+ messages in thread
From: Tzvetomir Stoyanov (VMware) @ 2021-02-08 6:17 UTC (permalink / raw)
To: rostedt; +Cc: linux-trace-devel
In trace-cmd agent context, when getting the tracing directory, a bug
using srtcpy() was instroduced by that commit:
https://git.kernel.org/pub/scm/utils/trace-cmd/trace-cmd.git/commit/?id=b8498696e0e8d7b7cce8f50f92e1fa94d9127e6e
Signed-off-by: Tzvetomir Stoyanov (VMware) <tz.stoyanov@gmail.com>
---
tracecmd/trace-record.c | 2 +-
1 file changed, 1 insertion(+), 1 deletion(-)
diff --git a/tracecmd/trace-record.c b/tracecmd/trace-record.c
index a0a0b8b5..efd96d27 100644
--- a/tracecmd/trace-record.c
+++ b/tracecmd/trace-record.c
@@ -3341,7 +3341,7 @@ static int create_recorder(struct buffer_instance *instance, int cpu,
const char *dir = tracefs_tracing_dir();
if (dir)
- path = strdup(path);
+ path = strdup(dir);
}
if (!path)
die("can't get the tracing directory");
--
2.29.2
^ permalink raw reply related [flat|nested] 25+ messages in thread
* [PATCH v28 3/8] trace-cmd: Removed unused s64 define
2021-02-08 6:17 [PATCH v28 0/8] Timestamp synchronization of host - guest tracing session Tzvetomir Stoyanov (VMware)
2021-02-08 6:17 ` [PATCH v28 1/8] trace-cmd: Save command lines in VM agent Tzvetomir Stoyanov (VMware)
2021-02-08 6:17 ` [PATCH v28 2/8] trace-cmd: Fix bug in getting tracing dir in trace-cmd agent Tzvetomir Stoyanov (VMware)
@ 2021-02-08 6:17 ` Tzvetomir Stoyanov (VMware)
2021-02-08 6:17 ` [PATCH v28 4/8] trace-cmd: Add timestamp synchronization per vCPU Tzvetomir Stoyanov (VMware)
` (5 subsequent siblings)
8 siblings, 0 replies; 25+ messages in thread
From: Tzvetomir Stoyanov (VMware) @ 2021-02-08 6:17 UTC (permalink / raw)
To: rostedt; +Cc: linux-trace-devel
Removed a s64 define, not used currently in trace packets.
Signed-off-by: Tzvetomir Stoyanov (VMware) <tz.stoyanov@gmail.com>
---
lib/trace-cmd/trace-msg.c | 1 -
1 file changed, 1 deletion(-)
diff --git a/lib/trace-cmd/trace-msg.c b/lib/trace-cmd/trace-msg.c
index 611af2c1..c4943165 100644
--- a/lib/trace-cmd/trace-msg.c
+++ b/lib/trace-cmd/trace-msg.c
@@ -30,7 +30,6 @@
typedef __u32 u32;
typedef __be32 be32;
-typedef __s64 s64;
static inline void dprint(const char *fmt, ...)
{
--
2.29.2
^ permalink raw reply related [flat|nested] 25+ messages in thread
* [PATCH v28 4/8] trace-cmd: Add timestamp synchronization per vCPU
2021-02-08 6:17 [PATCH v28 0/8] Timestamp synchronization of host - guest tracing session Tzvetomir Stoyanov (VMware)
` (2 preceding siblings ...)
2021-02-08 6:17 ` [PATCH v28 3/8] trace-cmd: Removed unused s64 define Tzvetomir Stoyanov (VMware)
@ 2021-02-08 6:17 ` Tzvetomir Stoyanov (VMware)
2021-02-08 6:17 ` [PATCH v28 5/8] trace-cmd: Add dummy function to initialize timestamp sync logic Tzvetomir Stoyanov (VMware)
` (4 subsequent siblings)
8 siblings, 0 replies; 25+ messages in thread
From: Tzvetomir Stoyanov (VMware) @ 2021-02-08 6:17 UTC (permalink / raw)
To: rostedt; +Cc: linux-trace-devel
Timestamp synchronization logic is changed to work per virtual CPU. Some
hypervisors maintain time offset and scaling per vCPU. The host-guest
communication protocol is changed to request time stamp offset calculation
for particular vCPU. The guest thread, responsible for running that logic
is pinned to the requested CPU. The time sync medata data, saved in the
trace.dat file is changed to an array of vCPUs. When an event time stamp
is corrected, the CPU on that the event happened is used to get the
correct offset.
Signed-off-by: Tzvetomir Stoyanov (VMware) <tz.stoyanov@gmail.com>
---
.../include/private/trace-cmd-private.h | 2 +-
lib/trace-cmd/include/trace-tsync-local.h | 22 +-
lib/trace-cmd/trace-input.c | 188 ++++++++++------
lib/trace-cmd/trace-timesync.c | 213 +++++++++++++-----
tracecmd/trace-dump.c | 52 +++--
tracecmd/trace-tsync.c | 67 ++++--
6 files changed, 372 insertions(+), 172 deletions(-)
diff --git a/lib/trace-cmd/include/private/trace-cmd-private.h b/lib/trace-cmd/include/private/trace-cmd-private.h
index d370fa8b..4a352291 100644
--- a/lib/trace-cmd/include/private/trace-cmd-private.h
+++ b/lib/trace-cmd/include/private/trace-cmd-private.h
@@ -443,7 +443,7 @@ const char *tracecmd_tsync_proto_select(struct tracecmd_tsync_protos *protos, ch
bool tsync_proto_is_supported(const char *proto_name);
void tracecmd_tsync_with_host(struct tracecmd_time_sync *tsync);
void tracecmd_tsync_with_guest(struct tracecmd_time_sync *tsync);
-int tracecmd_tsync_get_offsets(struct tracecmd_time_sync *tsync,
+int tracecmd_tsync_get_offsets(struct tracecmd_time_sync *tsync, int cpu,
int *count, long long **ts,
long long **offsets, long long **scalings);
int tracecmd_tsync_get_proto_flags(struct tracecmd_time_sync *tsync,
diff --git a/lib/trace-cmd/include/trace-tsync-local.h b/lib/trace-cmd/include/trace-tsync-local.h
index 83d1721a..d4281469 100644
--- a/lib/trace-cmd/include/trace-tsync-local.h
+++ b/lib/trace-cmd/include/trace-tsync-local.h
@@ -8,12 +8,7 @@
#include <stdbool.h>
-struct clock_sync_context {
- void *proto_data; /* time sync protocol specific data */
- bool is_server; /* server side time sync role */
- bool is_guest; /* guest or host time sync role */
- struct tracefs_instance *instance; /* ftrace buffer, used for time sync events */
-
+struct clock_sync_offsets {
/* Arrays with calculated time offsets at given time */
int sync_size; /* Allocated size of sync_ts,
* sync_offsets and sync_scalings
@@ -24,6 +19,18 @@ struct clock_sync_context {
long long *sync_ts;
long long *sync_offsets;
long long *sync_scalings;
+};
+
+struct clock_sync_context {
+ void *proto_data; /* time sync protocol specific data */
+ bool is_server; /* server side time sync role */
+ bool is_guest; /* guest or host time sync role */
+ struct tracefs_instance *instance; /* ftrace buffer, used for time sync events */
+
+ int cpu_count;
+ struct clock_sync_offsets *offsets; /* Array of size cpu_count
+ * calculated offsets per CPU
+ */
/* Identifiers of local and remote time sync peers: cid and port */
unsigned int local_cid;
@@ -37,7 +44,8 @@ int tracecmd_tsync_proto_register(const char *proto_name, int accuracy, int role
int (*init)(struct tracecmd_time_sync *),
int (*free)(struct tracecmd_time_sync *),
int (*calc)(struct tracecmd_time_sync *,
- long long *, long long *, long long *));
+ long long *, long long *,
+ long long *, unsigned int));
int tracecmd_tsync_proto_unregister(char *proto_name);
int ptp_clock_sync_register(void);
diff --git a/lib/trace-cmd/trace-input.c b/lib/trace-cmd/trace-input.c
index 7d28254e..d32d8ee4 100644
--- a/lib/trace-cmd/trace-input.c
+++ b/lib/trace-cmd/trace-input.c
@@ -91,13 +91,19 @@ struct guest_trace_info {
int *cpu_pid;
};
+struct timesync_offsets {
+ int ts_samples_count;
+ struct ts_offset_sample *ts_samples;
+
+};
+
struct host_trace_info {
unsigned long long peer_trace_id;
unsigned int flags;
bool sync_enable;
struct tracecmd_input *peer_data;
- int ts_samples_count;
- struct ts_offset_sample *ts_samples;
+ int cpu_count;
+ struct timesync_offsets *ts_offsets;
};
struct tracecmd_input {
@@ -1149,53 +1155,56 @@ timestamp_correction_calc(unsigned long long ts, unsigned int flags,
return ts + tscor;
}
-static unsigned long long timestamp_correct(unsigned long long ts,
+static unsigned long long timestamp_correct(unsigned long long ts, int cpu,
struct tracecmd_input *handle)
{
- struct host_trace_info *host = &handle->host;
+ struct timesync_offsets *tsync;
int min, mid, max;
if (handle->ts_offset)
return ts + handle->ts_offset;
- if (!host->sync_enable)
+ if (!handle->host.sync_enable)
+ return ts;
+ if (cpu >= handle->host.cpu_count)
return ts;
+ tsync = &handle->host.ts_offsets[cpu];
/* We have one sample, nothing to calc here */
- if (host->ts_samples_count == 1)
- return ts + host->ts_samples[0].offset;
+ if (tsync->ts_samples_count == 1)
+ return ts + tsync->ts_samples[0].offset;
/* We have two samples, nothing to search here */
- if (host->ts_samples_count == 2)
- return timestamp_correction_calc(ts, host->flags,
- &host->ts_samples[0],
- &host->ts_samples[1]);
+ if (tsync->ts_samples_count == 2)
+ return timestamp_correction_calc(ts, handle->host.flags,
+ &tsync->ts_samples[0],
+ &tsync->ts_samples[1]);
/* We have more than two samples */
- if (ts <= host->ts_samples[0].time)
- return timestamp_correction_calc(ts, host->flags,
- &host->ts_samples[0],
- &host->ts_samples[1]);
- else if (ts >= host->ts_samples[host->ts_samples_count-1].time)
- return timestamp_correction_calc(ts, host->flags,
- &host->ts_samples[host->ts_samples_count-2],
- &host->ts_samples[host->ts_samples_count-1]);
+ if (ts <= tsync->ts_samples[0].time)
+ return timestamp_correction_calc(ts, handle->host.flags,
+ &tsync->ts_samples[0],
+ &tsync->ts_samples[1]);
+ else if (ts >= tsync->ts_samples[tsync->ts_samples_count-1].time)
+ return timestamp_correction_calc(ts, handle->host.flags,
+ &tsync->ts_samples[tsync->ts_samples_count-2],
+ &tsync->ts_samples[tsync->ts_samples_count-1]);
min = 0;
- max = host->ts_samples_count-1;
+ max = tsync->ts_samples_count-1;
mid = (min + max)/2;
while (min <= max) {
- if (ts < host->ts_samples[mid].time)
+ if (ts < tsync->ts_samples[mid].time)
max = mid - 1;
- else if (ts > host->ts_samples[mid].time)
+ else if (ts > tsync->ts_samples[mid].time)
min = mid + 1;
else
break;
mid = (min + max)/2;
}
- return timestamp_correction_calc(ts, host->flags,
- &host->ts_samples[mid],
- &host->ts_samples[mid+1]);
+ return timestamp_correction_calc(ts, handle->host.flags,
+ &tsync->ts_samples[mid],
+ &tsync->ts_samples[mid+1]);
}
/*
@@ -1219,7 +1228,8 @@ static int update_page_info(struct tracecmd_input *handle, int cpu)
kbuffer_subbuffer_size(kbuf));
return -1;
}
- handle->cpu_data[cpu].timestamp = timestamp_correct(kbuffer_timestamp(kbuf), handle);
+ handle->cpu_data[cpu].timestamp = timestamp_correct(kbuffer_timestamp(kbuf),
+ cpu, handle);
if (handle->ts2secs)
handle->cpu_data[cpu].timestamp *= handle->ts2secs;
@@ -1852,7 +1862,7 @@ read_again:
goto read_again;
}
- handle->cpu_data[cpu].timestamp = timestamp_correct(ts, handle);
+ handle->cpu_data[cpu].timestamp = timestamp_correct(ts, cpu, handle);
if (handle->ts2secs) {
handle->cpu_data[cpu].timestamp *= handle->ts2secs;
@@ -2187,42 +2197,89 @@ static int tsync_offset_cmp(const void *a, const void *b)
return 0;
}
-static void tsync_offset_load(struct tracecmd_input *handle, char *buf)
+#define safe_read(R, C) \
+ do { \
+ if ((C) > size) \
+ return -EFAULT; \
+ (R) = tep_read_number(tep, buf, (C)); \
+ buf += (C); \
+ size -= (C); \
+ } while (0)
+
+#define safe_read_loop(type) \
+ do { \
+ int i; \
+ for (i = 0; i < ts_offsets->ts_samples_count; i++) \
+ safe_read(ts_offsets->ts_samples[i].type, 8); \
+ } while (0)
+
+static int tsync_offset_load(struct tep_handle *tep,
+ struct timesync_offsets *ts_offsets, char *buf, int size)
{
- struct host_trace_info *host = &handle->host;
- long long *buf8 = (long long *)buf;
+ int start_size = size;
int i, j;
- for (i = 0; i < host->ts_samples_count; i++) {
- host->ts_samples[i].time = tep_read_number(handle->pevent,
- buf8 + i, 8);
- host->ts_samples[i].offset = tep_read_number(handle->pevent,
- buf8 + host->ts_samples_count + i, 8);
- host->ts_samples[i].scaling = tep_read_number(handle->pevent,
- buf8 + (2 * host->ts_samples_count) + i, 8);
- }
- qsort(host->ts_samples, host->ts_samples_count,
+ safe_read_loop(time);
+ safe_read_loop(offset);
+ safe_read_loop(scaling);
+ qsort(ts_offsets->ts_samples, ts_offsets->ts_samples_count,
sizeof(struct ts_offset_sample), tsync_offset_cmp);
+
/* Filter possible samples with equal time */
- for (i = 0, j = 0; i < host->ts_samples_count; i++) {
- if (i == 0 || host->ts_samples[i].time != host->ts_samples[i-1].time)
- host->ts_samples[j++] = host->ts_samples[i];
+ for (i = 0, j = 0; i < ts_offsets->ts_samples_count; i++) {
+ if (i == 0 || ts_offsets->ts_samples[i].time != ts_offsets->ts_samples[i-1].time)
+ ts_offsets->ts_samples[j++] = ts_offsets->ts_samples[i];
}
- host->ts_samples_count = j;
+ ts_offsets->ts_samples_count = j;
+
+ return start_size - size;
+}
+
+static int tsync_cpu_offsets_load(struct tracecmd_input *handle, char *buf, int size)
+{
+ struct tep_handle *tep = handle->pevent;
+ int ret;
+ int i;
+
+ safe_read(handle->host.cpu_count, 4);
+ handle->host.ts_offsets = calloc(handle->host.cpu_count,
+ sizeof(struct timesync_offsets));
+ if (!handle->host.ts_offsets)
+ return -ENOMEM;
+ for (i = 0; i < handle->host.cpu_count; i++) {
+ safe_read(handle->host.ts_offsets[i].ts_samples_count, 4);
+ handle->host.ts_offsets[i].ts_samples = calloc(handle->host.ts_offsets[i].ts_samples_count,
+ sizeof(struct ts_offset_sample));
+ if (!handle->host.ts_offsets[i].ts_samples)
+ return -ENOMEM;
+ ret = tsync_offset_load(tep, &handle->host.ts_offsets[i], buf, size);
+ if (ret <= 0)
+ return -EFAULT;
+ size -= ret;
+ buf += ret;
+ }
+ return 0;
}
static void tsync_check_enable(struct tracecmd_input *handle)
{
struct host_trace_info *host = &handle->host;
struct guest_trace_info *guest;
+ int i;
host->sync_enable = false;
- if (!host->peer_data || !host->peer_data->guest ||
- !host->ts_samples_count || !host->ts_samples)
+ if (!host->peer_data || !host->peer_data->guest)
return;
if (host->peer_trace_id != host->peer_data->trace_id)
return;
+ if (!host->cpu_count || !host->ts_offsets)
+ return;
+ for (i = 0; i < host->cpu_count; i++) {
+ if (!host->ts_offsets[i].ts_samples_count ||
+ !host->ts_offsets[i].ts_samples)
+ return;
+ }
guest = host->peer_data->guest;
while (guest) {
if (guest->trace_id == handle->trace_id)
@@ -2237,8 +2294,14 @@ static void tsync_check_enable(struct tracecmd_input *handle)
static void trace_tsync_offset_free(struct host_trace_info *host)
{
- free(host->ts_samples);
- host->ts_samples = NULL;
+ int i;
+
+ if (host->ts_offsets) {
+ for (i = 0; i < host->cpu_count; i++)
+ free(host->ts_offsets[i].ts_samples);
+ free(host->ts_offsets);
+ host->ts_offsets = NULL;
+ }
if (host->peer_data) {
tracecmd_close(host->peer_data);
host->peer_data = NULL;
@@ -2497,8 +2560,8 @@ static int handle_options(struct tracecmd_input *handle)
struct input_buffer_instance *buffer;
struct hook_list *hook;
char *buf;
- int samples_size;
int cpus;
+ int ret;
/* By default, use usecs, unless told otherwise */
handle->flags |= TRACECMD_FL_IN_USECS;
@@ -2549,11 +2612,15 @@ static int handle_options(struct tracecmd_input *handle)
/*
* long long int (8 bytes) trace session ID
* int (4 bytes) protocol flags.
- * int (4 bytes) count of timestamp offsets.
- * long long array of size [count] of times,
+ * int (4 bytes) CPU count.
+ * array of size [CPU count]:
+ * [
+ * int (4 bytes) count of timestamp offsets.
+ * long long array of size [count] of times,
* when the offsets were calculated.
- * long long array of size [count] of timestamp offsets.
- * long long array of size [count] of timestamp scaling ratios.*
+ * long long array of size [count] of timestamp offsets.
+ * long long array of size [count] of timestamp scaling ratios.*
+ * ]
*/
if (size < 16 || handle->flags & TRACECMD_FL_IGNORE_DATE)
break;
@@ -2561,18 +2628,9 @@ static int handle_options(struct tracecmd_input *handle)
buf, 8);
handle->host.flags = tep_read_number(handle->pevent,
buf + 8, 4);
- handle->host.ts_samples_count = tep_read_number(handle->pevent,
- buf + 12, 4);
- samples_size = (8 * handle->host.ts_samples_count);
- if (size != (16 + (2 * samples_size))) {
- warning("Failed to extract Time Shift information from the file: found size %d, expected is %d",
- size, 16 + (2 * samples_size));
- break;
- }
- handle->host.ts_samples = malloc(2 * samples_size);
- if (!handle->host.ts_samples)
- return -ENOMEM;
- tsync_offset_load(handle, buf + 16);
+ ret = tsync_cpu_offsets_load(handle, buf + 12, size - 12);
+ if (ret < 0)
+ return ret;
break;
case TRACECMD_OPTION_CPUSTAT:
buf[size-1] = '\n';
@@ -3911,7 +3969,7 @@ unsigned long long tracecmd_get_tsync_peer(struct tracecmd_input *handle)
int tracecmd_enable_tsync(struct tracecmd_input *handle, bool enable)
{
if (enable &&
- (!handle->host.ts_samples || !handle->host.ts_samples_count))
+ (!handle->host.ts_offsets || !handle->host.cpu_count))
return -1;
handle->host.sync_enable = enable;
diff --git a/lib/trace-cmd/trace-timesync.c b/lib/trace-cmd/trace-timesync.c
index 9cbed775..2581363f 100644
--- a/lib/trace-cmd/trace-timesync.c
+++ b/lib/trace-cmd/trace-timesync.c
@@ -34,9 +34,13 @@ struct tsync_proto {
int (*clock_sync_free)(struct tracecmd_time_sync *clock_context);
int (*clock_sync_calc)(struct tracecmd_time_sync *clock_context,
long long *offset, long long *scaling,
- long long *timestamp);
+ long long *timestamp, unsigned int cpu);
};
+struct tsync_probe_request_msg {
+ unsigned short cpu;
+} __packed;
+
static struct tsync_proto *tsync_proto_list;
static struct tsync_proto *tsync_proto_find(const char *proto_name)
@@ -58,7 +62,8 @@ int tracecmd_tsync_proto_register(const char *proto_name, int accuracy, int role
int (*init)(struct tracecmd_time_sync *),
int (*free)(struct tracecmd_time_sync *),
int (*calc)(struct tracecmd_time_sync *,
- long long *, long long *, long long *))
+ long long *, long long *,
+ long long *, unsigned int))
{
struct tsync_proto *proto = NULL;
@@ -70,6 +75,7 @@ int tracecmd_tsync_proto_register(const char *proto_name, int accuracy, int role
strncpy(proto->proto_name, proto_name, TRACECMD_TSYNC_PNAME_LENGTH);
proto->accuracy = accuracy;
proto->roles = roles;
+ proto->flags = flags;
proto->supported_clocks = supported_clocks;
proto->clock_sync_init = init;
proto->clock_sync_free = free;
@@ -112,6 +118,7 @@ bool tsync_proto_is_supported(const char *proto_name)
* tracecmd_tsync_get_offsets - Return the calculated time offsets
*
* @tsync: Pointer to time sync context
+ * @cpu: CPU for which to get the calculated offsets
* @count: Returns the number of calculated time offsets
* @ts: Array of size @count containing timestamps of callculated offsets
* @offsets: array of size @count, containing offsets for each timestamp
@@ -119,7 +126,7 @@ bool tsync_proto_is_supported(const char *proto_name)
*
* Retuns -1 in case of an error, or 0 otherwise
*/
-int tracecmd_tsync_get_offsets(struct tracecmd_time_sync *tsync,
+int tracecmd_tsync_get_offsets(struct tracecmd_time_sync *tsync, int cpu,
int *count, long long **ts,
long long **offsets, long long **scalings)
{
@@ -128,14 +135,16 @@ int tracecmd_tsync_get_offsets(struct tracecmd_time_sync *tsync,
if (!tsync || !tsync->context)
return -1;
tsync_context = (struct clock_sync_context *)tsync->context;
+ if (cpu >= tsync_context->cpu_count || !tsync_context->offsets)
+ return -1;
if (count)
- *count = tsync_context->sync_count;
+ *count = tsync_context->offsets[cpu].sync_count;
if (ts)
- *ts = tsync_context->sync_ts;
+ *ts = tsync_context->offsets[cpu].sync_ts;
if (offsets)
- *offsets = tsync_context->sync_offsets;
+ *offsets = tsync_context->offsets[cpu].sync_offsets;
if (scalings)
- *scalings = tsync_context->sync_scalings;
+ *scalings = tsync_context->offsets[cpu].sync_scalings;
return 0;
}
@@ -355,6 +364,13 @@ static int clock_context_init(struct tracecmd_time_sync *tsync, bool guest)
if (!clock->instance)
goto error;
+ clock->cpu_count = tsync->vcpu_count;
+ if (clock->cpu_count) {
+ clock->offsets = calloc(clock->cpu_count, sizeof(struct clock_sync_offsets));
+ if (!clock->offsets)
+ goto error;
+ }
+
tsync->context = clock;
if (protocol->clock_sync_init && protocol->clock_sync_init(tsync) < 0)
goto error;
@@ -362,6 +378,9 @@ static int clock_context_init(struct tracecmd_time_sync *tsync, bool guest)
return 0;
error:
tsync->context = NULL;
+ if (clock->instance)
+ clock_synch_delete_instance(clock->instance);
+ free(clock->offsets);
free(clock);
return -1;
}
@@ -377,6 +396,7 @@ void tracecmd_tsync_free(struct tracecmd_time_sync *tsync)
{
struct clock_sync_context *tsync_context;
struct tsync_proto *proto;
+ int i;
if (!tsync->context)
return;
@@ -389,28 +409,88 @@ void tracecmd_tsync_free(struct tracecmd_time_sync *tsync)
clock_synch_delete_instance(tsync_context->instance);
tsync_context->instance = NULL;
- free(tsync_context->sync_ts);
- free(tsync_context->sync_offsets);
- free(tsync_context->sync_scalings);
- tsync_context->sync_ts = NULL;
- tsync_context->sync_offsets = NULL;
- tsync_context->sync_scalings = NULL;
- tsync_context->sync_count = 0;
- tsync_context->sync_size = 0;
+ if (tsync_context->cpu_count && tsync_context->offsets) {
+ for (i = 0; i < tsync_context->cpu_count; i++) {
+ free(tsync_context->offsets[i].sync_ts);
+ free(tsync_context->offsets[i].sync_offsets);
+ free(tsync_context->offsets[i].sync_scalings);
+ tsync_context->offsets[i].sync_ts = NULL;
+ tsync_context->offsets[i].sync_offsets = NULL;
+ tsync_context->offsets[i].sync_scalings = NULL;
+ tsync_context->offsets[i].sync_count = 0;
+ tsync_context->offsets[i].sync_size = 0;
+ }
+ free(tsync_context->offsets);
+ tsync_context->offsets = NULL;
+ }
pthread_mutex_destroy(&tsync->lock);
pthread_cond_destroy(&tsync->cond);
free(tsync->clock_str);
}
+static cpu_set_t *pin_to_cpu(int cpu)
+{
+ static size_t size;
+ static int cpus;
+ cpu_set_t *mask = NULL;
+ cpu_set_t *old = NULL;
+
+ if (!cpus) {
+ cpus = tracecmd_count_cpus();
+ size = CPU_ALLOC_SIZE(cpus);
+ }
+ if (cpu >= cpus)
+ goto error;
+
+ mask = CPU_ALLOC(cpus);
+ if (!mask)
+ goto error;
+ old = CPU_ALLOC(cpus);
+ if (!old)
+ goto error;
+
+ CPU_ZERO_S(size, mask);
+ CPU_SET_S(cpu, size, mask);
+ if (pthread_getaffinity_np(pthread_self(), size, old))
+ goto error;
+ if (pthread_setaffinity_np(pthread_self(), size, mask))
+ goto error;
+
+ CPU_FREE(mask);
+ return old;
+
+error:
+ if (mask)
+ CPU_FREE(mask);
+ if (old)
+ CPU_FREE(old);
+ return NULL;
+}
+
+static void restore_pin_to_cpu(cpu_set_t *mask)
+{
+ static size_t size;
+
+ if (!size)
+ size = CPU_ALLOC_SIZE(tracecmd_count_cpus());
+
+ pthread_setaffinity_np(pthread_self(), size, mask);
+ CPU_FREE(mask);
+}
+
int tracecmd_tsync_send(struct tracecmd_time_sync *tsync,
- struct tsync_proto *proto)
+ struct tsync_proto *proto, unsigned int cpu)
{
+ cpu_set_t *old_set = NULL;
long long timestamp = 0;
long long scaling = 0;
long long offset = 0;
int ret;
- ret = proto->clock_sync_calc(tsync, &offset, &scaling, ×tamp);
+ old_set = pin_to_cpu(cpu);
+ ret = proto->clock_sync_calc(tsync, &offset, &scaling, ×tamp, cpu);
+ if (old_set)
+ restore_pin_to_cpu(old_set);
return ret;
}
@@ -428,8 +508,11 @@ int tracecmd_tsync_send(struct tracecmd_time_sync *tsync,
void tracecmd_tsync_with_host(struct tracecmd_time_sync *tsync)
{
char protocol[TRACECMD_TSYNC_PNAME_LENGTH];
+ struct tsync_probe_request_msg probe;
struct tsync_proto *proto;
unsigned int command;
+ unsigned int size;
+ char *msg;
int ret;
proto = tsync_proto_find(tsync->proto_name);
@@ -440,47 +523,37 @@ void tracecmd_tsync_with_host(struct tracecmd_time_sync *tsync)
if (!tsync->context)
return;
+ msg = (char *)&probe;
+ size = sizeof(probe);
while (true) {
+ memset(&probe, 0, size);
ret = tracecmd_msg_recv_time_sync(tsync->msg_handle,
protocol, &command,
- NULL, NULL);
+ &size, &msg);
if (ret || strncmp(protocol, TRACECMD_TSYNC_PROTO_NONE, TRACECMD_TSYNC_PNAME_LENGTH) ||
command != TRACECMD_TIME_SYNC_CMD_PROBE)
break;
- ret = tracecmd_tsync_send(tsync, proto);
+ ret = tracecmd_tsync_send(tsync, proto, probe.cpu);
if (ret)
break;
}
}
-static int tsync_get_sample(struct tracecmd_time_sync *tsync,
- struct tsync_proto *proto, int array_step)
+static int record_sync_sample(struct clock_sync_offsets *offsets, int array_step,
+ long long offset, long long scaling, long long ts)
{
- struct clock_sync_context *clock;
long long *sync_scalings = NULL;
long long *sync_offsets = NULL;
long long *sync_ts = NULL;
- long long timestamp = 0;
- long long scaling = 0;
- long long offset = 0;
- int ret;
- ret = proto->clock_sync_calc(tsync, &offset, &scaling, ×tamp);
- if (ret) {
- warning("Failed to synchronize timestamps with guest");
- return -1;
- }
- if (!offset || !timestamp || !scaling)
- return 0;
- clock = tsync->context;
- if (clock->sync_count >= clock->sync_size) {
- sync_ts = realloc(clock->sync_ts,
- (clock->sync_size + array_step) * sizeof(long long));
- sync_offsets = realloc(clock->sync_offsets,
- (clock->sync_size + array_step) * sizeof(long long));
- sync_scalings = realloc(clock->sync_scalings,
- (clock->sync_size + array_step) * sizeof(long long));
+ if (offsets->sync_count >= offsets->sync_size) {
+ sync_ts = realloc(offsets->sync_ts,
+ (offsets->sync_size + array_step) * sizeof(long long));
+ sync_offsets = realloc(offsets->sync_offsets,
+ (offsets->sync_size + array_step) * sizeof(long long));
+ sync_scalings = realloc(offsets->sync_scalings,
+ (offsets->sync_size + array_step) * sizeof(long long));
if (!sync_ts || !sync_offsets || !sync_scalings) {
free(sync_ts);
@@ -488,20 +561,43 @@ static int tsync_get_sample(struct tracecmd_time_sync *tsync,
free(sync_scalings);
return -1;
}
- clock->sync_size += array_step;
- clock->sync_ts = sync_ts;
- clock->sync_offsets = sync_offsets;
- clock->sync_scalings = sync_scalings;
+ offsets->sync_size += array_step;
+ offsets->sync_ts = sync_ts;
+ offsets->sync_offsets = sync_offsets;
+ offsets->sync_scalings = sync_scalings;
}
- clock->sync_ts[clock->sync_count] = timestamp;
- clock->sync_offsets[clock->sync_count] = offset;
- clock->sync_scalings[clock->sync_count] = scaling;
- clock->sync_count++;
+ offsets->sync_ts[offsets->sync_count] = ts;
+ offsets->sync_offsets[offsets->sync_count] = offset;
+ offsets->sync_scalings[offsets->sync_count] = scaling;
+ offsets->sync_count++;
return 0;
}
+static int tsync_get_sample(struct tracecmd_time_sync *tsync, unsigned int cpu,
+ struct tsync_proto *proto, int array_step)
+{
+ struct clock_sync_context *clock;
+ long long timestamp = 0;
+ long long scaling = 0;
+ long long offset = 0;
+ int ret;
+
+ ret = proto->clock_sync_calc(tsync, &offset, &scaling, ×tamp, cpu);
+ if (ret) {
+ warning("Failed to synchronize timestamps with guest");
+ return -1;
+ }
+ if (!offset || !timestamp || !scaling)
+ return 0;
+ clock = tsync->context;
+ if (!clock || cpu >= clock->cpu_count || !clock->offsets)
+ return -1;
+ return record_sync_sample(&clock->offsets[cpu], array_step,
+ offset, scaling, timestamp);
+}
+
#define TIMER_SEC_NANO 1000000000LL
static inline void get_ts_loop_delay(struct timespec *timeout, int delay_ms)
{
@@ -528,11 +624,13 @@ static inline void get_ts_loop_delay(struct timespec *timeout, int delay_ms)
*/
void tracecmd_tsync_with_guest(struct tracecmd_time_sync *tsync)
{
+ struct tsync_probe_request_msg probe;
int ts_array_size = CLOCK_TS_ARRAY;
struct tsync_proto *proto;
struct timespec timeout;
bool end = false;
int ret;
+ int i;
proto = tsync_proto_find(tsync->proto_name);
if (!proto || !proto->clock_sync_calc)
@@ -548,12 +646,17 @@ void tracecmd_tsync_with_guest(struct tracecmd_time_sync *tsync)
while (true) {
pthread_mutex_lock(&tsync->lock);
- ret = tracecmd_msg_send_time_sync(tsync->msg_handle,
- TRACECMD_TSYNC_PROTO_NONE,
- TRACECMD_TIME_SYNC_CMD_PROBE,
- 0, NULL);
- ret = tsync_get_sample(tsync, proto, ts_array_size);
- if (ret || end)
+ for (i = 0; i < tsync->vcpu_count; i++) {
+ probe.cpu = i;
+ ret = tracecmd_msg_send_time_sync(tsync->msg_handle,
+ TRACECMD_TSYNC_PROTO_NONE,
+ TRACECMD_TIME_SYNC_CMD_PROBE,
+ sizeof(probe), (char *)&probe);
+ ret = tsync_get_sample(tsync, i, proto, ts_array_size);
+ if (ret)
+ break;
+ }
+ if (end || i < tsync->vcpu_count)
break;
if (tsync->loop_interval > 0) {
get_ts_loop_delay(&timeout, tsync->loop_interval);
diff --git a/tracecmd/trace-dump.c b/tracecmd/trace-dump.c
index 6172231e..c1143eba 100644
--- a/tracecmd/trace-dump.c
+++ b/tracecmd/trace-dump.c
@@ -375,7 +375,8 @@ static void dump_option_timeshift(int fd, int size)
long long trace_id;
unsigned int count;
unsigned int flags;
- int i;
+ unsigned int cpus;
+ int i, j;
/*
* long long int (8 bytes) trace session ID
@@ -393,29 +394,34 @@ static void dump_option_timeshift(int fd, int size)
do_print(OPTIONS, "0x%llX [peer's trace id]\n", trace_id);
read_file_number(fd, &flags, 4);
do_print(OPTIONS, "0x%llX [peer's protocol flags]\n", flags);
- read_file_number(fd, &count, 4);
- do_print(OPTIONS, "%lld [samples count]\n", count);
- times = calloc(count, sizeof(long long));
- if (!times)
- goto out;
- offsets = calloc(count, sizeof(long long));
- if (!offsets)
- goto out;
- scalings = calloc(count, sizeof(long long));
- if (!scalings)
- goto out;
-
- for (i = 0; i < count; i++)
- read_file_number(fd, times + i, 8);
- for (i = 0; i < count; i++)
- read_file_number(fd, offsets + i, 8);
- for (i = 0; i < count; i++)
- read_file_number(fd, scalings + i, 8);
-
- for (i = 0; i < count; i++)
- do_print(OPTIONS, "\t%lld * %lld %lld [offset * scaling @ time]\n",
- offsets[i], scalings[1], times[i]);
+ read_file_number(fd, &cpus, 4);
+ do_print(OPTIONS, "0x%llX [peer's CPU count]\n", cpus);
+ for (j = 0; j < cpus; j++) {
+ read_file_number(fd, &count, 4);
+ do_print(OPTIONS, "%lld [samples count for CPU %d]\n", count, j);
+ times = calloc(count, sizeof(long long));
+ offsets = calloc(count, sizeof(long long));
+ scalings = calloc(count, sizeof(long long));
+ if (!times || !offsets || !scalings)
+ goto out;
+ for (i = 0; i < count; i++)
+ read_file_number(fd, times + i, 8);
+ for (i = 0; i < count; i++)
+ read_file_number(fd, offsets + i, 8);
+ for (i = 0; i < count; i++)
+ read_file_number(fd, scalings + i, 8);
+
+ for (i = 0; i < count; i++)
+ do_print(OPTIONS, "\t%lld %lld %lld [offset * scaling @ time]\n",
+ offsets[i], scalings[1], times[i]);
+ free(times);
+ free(offsets);
+ free(scalings);
+ times = NULL;
+ offsets = NULL;
+ scalings = NULL;
+ }
out:
free(times);
free(offsets);
diff --git a/tracecmd/trace-tsync.c b/tracecmd/trace-tsync.c
index 438c60bb..70d4dbd1 100644
--- a/tracecmd/trace-tsync.c
+++ b/tracecmd/trace-tsync.c
@@ -134,51 +134,75 @@ out:
static void write_guest_time_shift(struct buffer_instance *instance)
{
- struct tracecmd_output *handle;
- struct iovec vector[6];
+ struct tracecmd_output *handle = NULL;
+ struct iovec *vector = NULL;
unsigned int flags;
long long *scalings = NULL;
long long *offsets = NULL;
long long *ts = NULL;
const char *file;
+ int fd = -1;
+ int vcount;
int count;
+ int i, j;
int ret;
- int fd;
- ret = tracecmd_tsync_get_offsets(&instance->tsync, &count,
- &ts, &offsets, &scalings);
- if (ret < 0 || !count || !ts || !offsets || !scalings)
+ if (!instance->tsync.vcpu_count)
+ return;
+ vcount = 3 + (4 * instance->tsync.vcpu_count);
+ vector = calloc(vcount, sizeof(struct iovec));
+ if (!vector)
return;
ret = tracecmd_tsync_get_proto_flags(&instance->tsync, &flags);
if (ret < 0)
- return;
+ goto out;
file = instance->output_file;
fd = open(file, O_RDWR);
if (fd < 0)
die("error opening %s", file);
handle = tracecmd_get_output_handle_fd(fd);
- vector[0].iov_len = 8;
- vector[0].iov_base = &top_instance.trace_id;
- vector[1].iov_len = 4;
- vector[1].iov_base = &flags;
- vector[2].iov_len = 4;
- vector[2].iov_base = &count;
- vector[3].iov_len = 8 * count;
- vector[3].iov_base = ts;
- vector[4].iov_len = 8 * count;
- vector[4].iov_base = offsets;
- vector[5].iov_len = 8 * count;
- vector[5].iov_base = scalings;
- tracecmd_add_option_v(handle, TRACECMD_OPTION_TIME_SHIFT, vector, 6);
+ if (!handle)
+ goto out;
+ j = 0;
+ vector[j].iov_len = 8;
+ vector[j++].iov_base = &top_instance.trace_id;
+ vector[j].iov_len = 4;
+ vector[j++].iov_base = &flags;
+ vector[j].iov_len = 4;
+ vector[j++].iov_base = &instance->tsync.vcpu_count;
+ for (i = 0; i < instance->tsync.vcpu_count; i++) {
+ if (j >= vcount)
+ break;
+ ret = tracecmd_tsync_get_offsets(&instance->tsync, i, &count,
+ &ts, &offsets, &scalings);
+ if (ret < 0 || !count || !ts || !offsets || !scalings)
+ break;
+ vector[j].iov_len = 4;
+ vector[j++].iov_base = &count;
+ vector[j].iov_len = 8 * count;
+ vector[j++].iov_base = ts;
+ vector[j].iov_len = 8 * count;
+ vector[j++].iov_base = offsets;
+ vector[j].iov_len = 8 * count;
+ vector[j++].iov_base = scalings;
+ }
+ if (i < instance->tsync.vcpu_count)
+ goto out;
+ tracecmd_add_option_v(handle, TRACECMD_OPTION_TIME_SHIFT, vector, vcount);
tracecmd_append_options(handle);
- tracecmd_output_close(handle);
#ifdef TSYNC_DEBUG
if (count > 1)
printf("Got %d timestamp synch samples for guest %s in %lld ns trace\n\r",
count, tracefs_instance_get_name(instance->tracefs),
ts[count - 1] - ts[0]);
#endif
+out:
+ if (handle)
+ tracecmd_output_close(handle);
+ else if (fd >= 0)
+ close(fd);
+ free(vector);
}
void tracecmd_host_tsync_complete(struct buffer_instance *instance)
@@ -261,6 +285,7 @@ const char *tracecmd_guest_tsync(struct tracecmd_tsync_protos *tsync_protos,
pthread_attr_init(&attrib);
tsync->proto_name = proto;
+ tsync->vcpu_count = tracecmd_count_cpus();
pthread_attr_setdetachstate(&attrib, PTHREAD_CREATE_JOINABLE);
ret = pthread_create(thr_id, &attrib, tsync_agent_thread, tsync);
--
2.29.2
^ permalink raw reply related [flat|nested] 25+ messages in thread
* [PATCH v28 5/8] trace-cmd: Add dummy function to initialize timestamp sync logic
2021-02-08 6:17 [PATCH v28 0/8] Timestamp synchronization of host - guest tracing session Tzvetomir Stoyanov (VMware)
` (3 preceding siblings ...)
2021-02-08 6:17 ` [PATCH v28 4/8] trace-cmd: Add timestamp synchronization per vCPU Tzvetomir Stoyanov (VMware)
@ 2021-02-08 6:17 ` Tzvetomir Stoyanov (VMware)
2021-02-08 6:17 ` [PATCH v28 6/8] trace-cmd: [POC] PTP-like algorithm for host - guest timestamp synchronization Tzvetomir Stoyanov (VMware)
` (3 subsequent siblings)
8 siblings, 0 replies; 25+ messages in thread
From: Tzvetomir Stoyanov (VMware) @ 2021-02-08 6:17 UTC (permalink / raw)
To: rostedt; +Cc: linux-trace-devel
A dummy empty function is added, will be used to initialize timestamp
synchronization logic:
tracecmd_tsync_init()
When this code is implemented as real plugins, this function will be
removed. Then the initializion will be triggered at plugin load time.
Signed-off-by: Tzvetomir Stoyanov (VMware) <tz.stoyanov@gmail.com>
---
lib/trace-cmd/trace-timesync.c | 8 ++++++++
tracecmd/trace-agent.c | 2 ++
tracecmd/trace-record.c | 23 +++++++++++++++--------
3 files changed, 25 insertions(+), 8 deletions(-)
diff --git a/lib/trace-cmd/trace-timesync.c b/lib/trace-cmd/trace-timesync.c
index 2581363f..8c1586c7 100644
--- a/lib/trace-cmd/trace-timesync.c
+++ b/lib/trace-cmd/trace-timesync.c
@@ -57,6 +57,14 @@ static struct tsync_proto *tsync_proto_find(const char *proto_name)
return NULL;
}
+/**
+ * tracecmd_tsync_init - Initialize the global, per task, time sync data.
+ */
+void tracecmd_tsync_init(void)
+{
+
+}
+
int tracecmd_tsync_proto_register(const char *proto_name, int accuracy, int roles,
int supported_clocks, unsigned int flags,
int (*init)(struct tracecmd_time_sync *),
diff --git a/tracecmd/trace-agent.c b/tracecmd/trace-agent.c
index ff4a4e11..36444d32 100644
--- a/tracecmd/trace-agent.c
+++ b/tracecmd/trace-agent.c
@@ -248,6 +248,8 @@ static void agent_serve(unsigned int port)
if (sd < 0)
die("Failed to open vsocket");
+ tracecmd_tsync_init();
+
if (!get_local_cid(&cid))
printf("listening on @%u:%u\n", cid, port);
diff --git a/tracecmd/trace-record.c b/tracecmd/trace-record.c
index efd96d27..cc870124 100644
--- a/tracecmd/trace-record.c
+++ b/tracecmd/trace-record.c
@@ -6218,10 +6218,6 @@ static bool has_local_instances(void)
return false;
}
-/*
- * This function contains common code for the following commands:
- * record, start, stream, profile.
- */
static void record_trace(int argc, char **argv,
struct common_record_context *ctx)
{
@@ -6379,12 +6375,23 @@ static void record_trace(int argc, char **argv,
finalize_record_trace(ctx);
}
+/*
+ * This function contains common code for the following commands:
+ * record, start, stream, profile.
+ */
+static void record_trace_command(int argc, char **argv,
+ struct common_record_context *ctx)
+{
+ tracecmd_tsync_init();
+ record_trace(argc, argv, ctx);
+}
+
void trace_start(int argc, char **argv)
{
struct common_record_context ctx;
parse_record_options(argc, argv, CMD_start, &ctx);
- record_trace(argc, argv, &ctx);
+ record_trace_command(argc, argv, &ctx);
exit(0);
}
@@ -6476,7 +6483,7 @@ void trace_stream(int argc, char **argv)
struct common_record_context ctx;
parse_record_options(argc, argv, CMD_stream, &ctx);
- record_trace(argc, argv, &ctx);
+ record_trace_command(argc, argv, &ctx);
exit(0);
}
@@ -6495,7 +6502,7 @@ void trace_profile(int argc, char **argv)
if (!buffer_instances)
top_instance.flags |= BUFFER_FL_PROFILE;
- record_trace(argc, argv, &ctx);
+ record_trace_command(argc, argv, &ctx);
do_trace_profile();
exit(0);
}
@@ -6505,7 +6512,7 @@ void trace_record(int argc, char **argv)
struct common_record_context ctx;
parse_record_options(argc, argv, CMD_record, &ctx);
- record_trace(argc, argv, &ctx);
+ record_trace_command(argc, argv, &ctx);
exit(0);
}
--
2.29.2
^ permalink raw reply related [flat|nested] 25+ messages in thread
* [PATCH v28 6/8] trace-cmd: [POC] PTP-like algorithm for host - guest timestamp synchronization
2021-02-08 6:17 [PATCH v28 0/8] Timestamp synchronization of host - guest tracing session Tzvetomir Stoyanov (VMware)
` (4 preceding siblings ...)
2021-02-08 6:17 ` [PATCH v28 5/8] trace-cmd: Add dummy function to initialize timestamp sync logic Tzvetomir Stoyanov (VMware)
@ 2021-02-08 6:17 ` Tzvetomir Stoyanov (VMware)
2021-02-08 6:17 ` [PATCH v28 7/8] trace-cmd: Debug scripts for " Tzvetomir Stoyanov (VMware)
` (2 subsequent siblings)
8 siblings, 0 replies; 25+ messages in thread
From: Tzvetomir Stoyanov (VMware) @ 2021-02-08 6:17 UTC (permalink / raw)
To: rostedt; +Cc: linux-trace-devel
PTP protocol is designed for synchronizing clocks of machines in a local network.
The same approach can be used for host - guest timestamp synchronization.
This implementation uses ftrace raw markers to track trace timestamps of PTP events.
The patch is a POC, two different algorithms for PTP calculations are proposed:
- Choosing the sample with the fastest response time for calculating the clocks offset.
- Calculating the clocks offset using the average of all PTP samples.
The implementation can be tuned using those parameters:
- #define FASTEST_RESPONSE - is defined, the sample with the fastest response time
is used for calculating the clocks offset. Otherwise the histogram of all samples is used.
- #define PTP_SYNC_LOOP 340 - defines the number of samples, used for one calculation.
- --tsync-interval - a trace-cmd argument, choose the intervals between offset calculations,
performed continuously during the trace.
- #define TSYNC_DEBUG - if defined, a debug information is collected and stored in files,
in the guest machine:
s-cid*.txt - For each offset calculation: host and guest clocks and calculated offset.
res-cid*.txt - For each tracing session: all calculated clock offsets.
Signed-off-by: Tzvetomir Stoyanov (VMware) <tz.stoyanov@gmail.com>
---
lib/trace-cmd/Makefile | 1 +
lib/trace-cmd/trace-timesync-ptp.c | 715 +++++++++++++++++++++++++++++
lib/trace-cmd/trace-timesync.c | 2 +-
3 files changed, 717 insertions(+), 1 deletion(-)
create mode 100644 lib/trace-cmd/trace-timesync-ptp.c
diff --git a/lib/trace-cmd/Makefile b/lib/trace-cmd/Makefile
index 841c84f1..f41feef8 100644
--- a/lib/trace-cmd/Makefile
+++ b/lib/trace-cmd/Makefile
@@ -19,6 +19,7 @@ OBJS += trace-msg.o
OBJS += trace-plugin.o
ifeq ($(VSOCK_DEFINED), 1)
OBJS += trace-timesync.o
+OBJS += trace-timesync-ptp.o
endif
# Additional util objects
diff --git a/lib/trace-cmd/trace-timesync-ptp.c b/lib/trace-cmd/trace-timesync-ptp.c
new file mode 100644
index 00000000..b05f1cd0
--- /dev/null
+++ b/lib/trace-cmd/trace-timesync-ptp.c
@@ -0,0 +1,715 @@
+// SPDX-License-Identifier: LGPL-2.1
+/*
+ * Copyright (C) 2019, VMware, Tzvetomir Stoyanov tz.stoyanov@gmail.com>
+ *
+ */
+
+#include <fcntl.h>
+#include <stdlib.h>
+#include <unistd.h>
+#include <arpa/inet.h>
+#include <linux/vm_sockets.h>
+#include <sys/types.h>
+#include <linux/types.h>
+#include <time.h>
+#include <sched.h>
+#include <limits.h>
+
+#include "trace-cmd.h"
+#include "trace-cmd-private.h"
+#include "tracefs.h"
+#include "trace-tsync-local.h"
+#include "trace-msg.h"
+#include "trace-cmd-local.h"
+
+typedef __be32 be32;
+typedef __u64 u64;
+typedef __s64 s64;
+
+#define PTP_SYNC_LOOP 339
+
+#define PTP_SYNC_PKT_START 1
+#define PTP_SYNC_PKT_PROBE 2
+#define PTP_SYNC_PKT_PROBES 3
+#define PTP_SYNC_PKT_OFFSET 4
+#define PTP_SYNC_PKT_END 5
+
+/* print time sync debug messages */
+#define TSYNC_DEBUG
+
+struct ptp_clock_sync {
+ struct tep_handle *tep;
+ struct tep_format_field *id;
+ int raw_id;
+ int marker_fd;
+ int series_id;
+ int flags;
+ int debug_fd;
+};
+
+enum {
+/*
+ * Consider only the probe with fastest response time,
+ * otherwise make a histogram from all probes.
+ */
+ PTP_FLAG_FASTEST_RESPONSE = (1 << 0),
+/*
+ * Use trace marker to get the clock,
+ * otherwise use the system clock directly.
+ */
+ PTP_FLAG_USE_MARKER = (1 << 1),
+};
+static int ptp_flags = PTP_FLAG_FASTEST_RESPONSE | PTP_FLAG_USE_MARKER;
+
+/*
+ * Calculated using formula [CPU rate]*[calculated offset deviation]
+ * tested on 3GHz CPU, with x86-tsc trace clock and compare the calculated
+ * offset with /sys/kernel/debug/kvm/<VM ID>/vcpu0/tsc-offset
+ * measured 2000ns deviation
+ * using PTP flags PTP_FLAG_FASTEST_RESPONSE | PTP_FLAG_USE_MARKER
+ */
+#define PTP_ACCURACY 6000
+#define PTP_NAME "ptp"
+
+struct ptp_clock_start_msg {
+ be32 series_id;
+ be32 flags;
+} __packed;
+
+struct ptp_clock_sample {
+ s64 ts;
+ be32 id;
+} __packed;
+
+struct ptp_clock_result_msg {
+ be32 series_id;
+ be32 count;
+ struct ptp_clock_sample samples[2*PTP_SYNC_LOOP];
+} __packed;
+
+struct ptp_clock_offset_msg {
+ s64 ts;
+ s64 offset;
+};
+
+struct ptp_markers_context {
+ struct clock_sync_context *clock;
+ struct ptp_clock_sync *ptp;
+ struct ptp_clock_result_msg msg;
+ int size;
+};
+
+struct ptp_marker_buf {
+ int local_cid;
+ int remote_cid;
+ int count;
+ int packet_id;
+} __packed;
+
+struct ptp_marker {
+ int series_id;
+ struct ptp_marker_buf data;
+} __packed;
+
+static int ptp_clock_sync_init(struct tracecmd_time_sync *tsync)
+{
+ const char *systems[] = {"ftrace", NULL};
+ struct clock_sync_context *clock_context;
+ struct ptp_clock_sync *ptp;
+ struct tep_event *raw;
+ char *path;
+
+ if (!tsync || !tsync->context)
+ return -1;
+ clock_context = (struct clock_sync_context *)tsync->context;
+ if (clock_context->proto_data)
+ return 0;
+
+ ptp = calloc(1, sizeof(struct ptp_clock_sync));
+ if (!ptp)
+ return -1;
+
+ ptp->marker_fd = -1;
+ ptp->debug_fd = -1;
+
+ path = tracefs_instance_get_dir(clock_context->instance);
+ if (!path)
+ goto error;
+ ptp->tep = tracefs_local_events_system(path, systems);
+ tracefs_put_tracing_file(path);
+ if (!ptp->tep)
+ goto error;
+ raw = tep_find_event_by_name(ptp->tep, "ftrace", "raw_data");
+ if (!raw)
+ goto error;
+ ptp->id = tep_find_field(raw, "id");
+ if (!ptp->id)
+ goto error;
+ ptp->raw_id = raw->id;
+
+ tep_set_file_bigendian(ptp->tep, tracecmd_host_bigendian());
+ tep_set_local_bigendian(ptp->tep, tracecmd_host_bigendian());
+
+ path = tracefs_instance_get_file(clock_context->instance, "trace_marker_raw");
+ if (!path)
+ goto error;
+ ptp->marker_fd = open(path, O_WRONLY);
+ tracefs_put_tracing_file(path);
+
+ clock_context->proto_data = ptp;
+
+#ifdef TSYNC_DEBUG
+ if (clock_context->is_server) {
+ char buff[256];
+ int res_fd;
+
+ sprintf(buff, "res-cid%d.txt", clock_context->remote_cid);
+
+ res_fd = open(buff, O_CREAT|O_WRONLY|O_TRUNC, 0644);
+ if (res_fd > 0)
+ close(res_fd);
+ }
+#endif
+
+ return 0;
+
+error:
+ if (ptp) {
+ tep_free(ptp->tep);
+ if (ptp->marker_fd >= 0)
+ close(ptp->marker_fd);
+ }
+ free(ptp);
+ return -1;
+}
+
+static int ptp_clock_sync_free(struct tracecmd_time_sync *tsync)
+{
+ struct clock_sync_context *clock_context;
+ struct ptp_clock_sync *ptp;
+
+ if (!tsync || !tsync->context)
+ return -1;
+ clock_context = (struct clock_sync_context *)tsync->context;
+
+ if (clock_context && clock_context->proto_data) {
+ ptp = (struct ptp_clock_sync *)clock_context->proto_data;
+ tep_free(ptp->tep);
+ if (ptp->marker_fd >= 0)
+ close(ptp->marker_fd);
+ if (ptp->debug_fd >= 0)
+ close(ptp->debug_fd);
+ free(clock_context->proto_data);
+ clock_context->proto_data = NULL;
+ }
+ return 0;
+}
+
+/* Save the timestamps of sent ('s') and returned ('r') probes in the
+ * ctx->msg.samples[] array. Depending of the context (server or client), there
+ * may be only returned probes, or both sent and returned probes. The returned
+ * probes are saved first in the array, after them are the sent probes.
+ * Depending of the context, the array can be with size:
+ * [0 .. max data.count] - holds only returned probes
+ * [0 .. 2 * max data.count] - holds both returned and sent probes
+ */
+static void ptp_probe_store(struct ptp_markers_context *ctx,
+ struct ptp_marker *marker,
+ unsigned long long ts)
+{
+ int index = -1;
+
+ if (marker->data.packet_id == 'r' &&
+ marker->data.count <= ctx->size) {
+ index = marker->data.count - 1;
+ } else if (marker->data.packet_id == 's' &&
+ marker->data.count * 2 <= ctx->size){
+ index = ctx->size / 2 + marker->data.count - 1;
+ }
+
+ if (index >= 0) {
+ ctx->msg.samples[index].id = marker->data.count;
+ ctx->msg.samples[index].ts = ts;
+ ctx->msg.count++;
+ }
+}
+
+static int ptp_marker_find(struct tep_event *event, struct tep_record *record,
+ int cpu, void *context)
+{
+ struct ptp_markers_context *ctx;
+ struct ptp_marker *marker;
+
+ ctx = (struct ptp_markers_context *)context;
+
+ /* Make sure this is our event */
+ if (event->id != ctx->ptp->raw_id || !ctx->ptp->id)
+ return 0;
+ if (record->size >= (ctx->ptp->id->offset + sizeof(struct ptp_marker))) {
+ marker = (struct ptp_marker *)(record->data + ctx->ptp->id->offset);
+ if (marker->data.local_cid == ctx->clock->local_cid &&
+ marker->data.remote_cid == ctx->clock->remote_cid &&
+ marker->series_id == ctx->ptp->series_id &&
+ marker->data.count)
+ ptp_probe_store(ctx, marker, record->ts);
+ }
+
+ return 0;
+}
+
+static inline bool good_probe(struct ptp_clock_sample *server_sample,
+ struct ptp_clock_sample *send_sample,
+ struct ptp_clock_sample *client_sample,
+ int *bad_probes)
+{
+ if (server_sample->ts && send_sample->ts && client_sample->ts &&
+ server_sample->id == send_sample->id &&
+ server_sample->id == client_sample->id)
+ return true;
+ (*bad_probes)++;
+ return false;
+}
+
+static int ptp_calc_offset_fastest(struct clock_sync_context *clock,
+ struct ptp_clock_result_msg *server,
+ struct ptp_clock_result_msg *client,
+ long long *offset_ret, long long *ts_ret,
+ int *bad_probes)
+{
+ struct ptp_clock_sample *sample_send;
+ long long delta_min = LLONG_MAX;
+ long long offset = 0;
+ long long delta = 0;
+ long long ts = 0;
+ int max_i;
+ int i;
+
+ *bad_probes = 0;
+ sample_send = server->samples + (server->count / 2);
+ max_i = server->count / 2 < client->count ?
+ server->count / 2 : client->count;
+ for (i = 0; i < max_i; i++) {
+ if (!good_probe(&server->samples[i], &sample_send[i],
+ &client->samples[i], bad_probes))
+ continue;
+ ts = (sample_send[i].ts + server->samples[i].ts) / 2;
+ offset = client->samples[i].ts - ts;
+
+ delta = server->samples[i].ts - sample_send[i].ts;
+ if (delta_min > delta) {
+ delta_min = delta;
+ *offset_ret = offset;
+ *ts_ret = ts;
+ }
+#ifdef TSYNC_DEBUG
+ {
+ struct ptp_clock_sync *ptp;
+
+ ptp = (struct ptp_clock_sync *)clock->proto_data;
+ if (ptp && ptp->debug_fd > 0) {
+ char buff[256];
+
+ sprintf(buff, "%lld %lld %lld\n",
+ ts, client->samples[i].ts, offset);
+ write(ptp->debug_fd, buff, strlen(buff));
+ }
+ }
+#endif
+ }
+
+ return 0;
+}
+
+static int ptp_calc_offset_hist(struct clock_sync_context *clock,
+ struct ptp_clock_result_msg *server,
+ struct ptp_clock_result_msg *client,
+ long long *offset_ret, long long *ts_ret,
+ int *bad_probes)
+{
+ struct ptp_clock_sample *sample_send;
+ long long timestamps[PTP_SYNC_LOOP];
+ long long offsets[PTP_SYNC_LOOP];
+ long long offset_min = LLONG_MAX;
+ long long offset_max = 0;
+ int hist[PTP_SYNC_LOOP];
+ int ind, max = 0;
+ long long bin;
+ int i, k = 0;
+
+ *bad_probes = 0;
+ memset(hist, 0, sizeof(int) * PTP_SYNC_LOOP);
+ sample_send = server->samples + (server->count / 2);
+ for (i = 0; i * 2 < server->count && i < client->count; i++) {
+ if (!good_probe(&server->samples[i], &sample_send[i],
+ &client->samples[i], bad_probes))
+ continue;
+ timestamps[k] = (sample_send[i].ts + server->samples[i].ts) / 2;
+ offsets[k] = client->samples[i].ts - timestamps[k];
+ if (offset_max < llabs(offsets[k]))
+ offset_max = llabs(offsets[k]);
+ if (offset_min > llabs(offsets[k]))
+ offset_min = llabs(offsets[k]);
+#ifdef TSYNC_DEBUG
+ {
+ struct ptp_clock_sync *ptp;
+
+ ptp = (struct ptp_clock_sync *)clock->proto_data;
+
+ if (ptp && ptp->debug_fd > 0) {
+ char buff[256];
+
+ sprintf(buff, "%lld %lld %lld\n",
+ timestamps[k],
+ client->samples[i].ts, offsets[k]);
+ write(ptp->debug_fd, buff, strlen(buff));
+ }
+ }
+#endif
+ k++;
+ }
+
+ bin = (offset_max - offset_min) / PTP_SYNC_LOOP;
+ for (i = 0; i < k; i++) {
+ ind = (llabs(offsets[i]) - offset_min) / bin;
+ if (ind < PTP_SYNC_LOOP) {
+ hist[ind]++;
+ if (max < hist[ind]) {
+ max = hist[ind];
+ *offset_ret = offsets[i];
+ *ts_ret = timestamps[i];
+ }
+ }
+ }
+
+ return 0;
+}
+
+static void ntoh_ptp_results(struct ptp_clock_result_msg *msg)
+{
+ int i;
+
+ msg->count = ntohl(msg->count);
+ for (i = 0; i < msg->count; i++) {
+ msg->samples[i].id = ntohl(msg->samples[i].id);
+ msg->samples[i].ts = ntohll(msg->samples[i].ts);
+ }
+ msg->series_id = ntohl(msg->series_id);
+}
+
+
+static void hton_ptp_results(struct ptp_clock_result_msg *msg)
+{
+ int i;
+
+ for (i = 0; i < msg->count; i++) {
+ msg->samples[i].id = htonl(msg->samples[i].id);
+ msg->samples[i].ts = htonll(msg->samples[i].ts);
+ }
+ msg->series_id = htonl(msg->series_id);
+ msg->count = htonl(msg->count);
+}
+
+static inline void ptp_track_clock(struct ptp_markers_context *ctx,
+ struct ptp_marker *marker)
+{
+ if (ctx->ptp->flags & PTP_FLAG_USE_MARKER) {
+ write(ctx->ptp->marker_fd, marker, sizeof(struct ptp_marker));
+ } else {
+ struct timespec clock;
+ unsigned long long ts;
+
+ clock_gettime(CLOCK_MONOTONIC_RAW, &clock);
+ ts = clock.tv_sec * 1000000000LL;
+ ts += clock.tv_nsec;
+ ptp_probe_store(ctx, marker, ts);
+ }
+}
+
+static int ptp_clock_client(struct tracecmd_time_sync *tsync,
+ long long *offset, long long *timestamp)
+{
+ char sync_proto[TRACECMD_TSYNC_PNAME_LENGTH];
+ struct clock_sync_context *clock_context;
+ struct ptp_clock_offset_msg res_offset;
+ struct ptp_clock_start_msg start;
+ struct ptp_markers_context ctx;
+ struct ptp_clock_sync *ptp;
+ struct ptp_marker marker;
+ unsigned int sync_msg;
+ unsigned int size;
+ char *msg;
+ int count;
+ int ret;
+
+ if (!tsync || !tsync->context || !tsync->msg_handle)
+ return -1;
+
+ clock_context = (struct clock_sync_context *)tsync->context;
+ if (clock_context->proto_data == NULL)
+ return -1;
+
+ ptp = (struct ptp_clock_sync *)clock_context->proto_data;
+ size = sizeof(start);
+ msg = (char *)&start;
+ ret = tracecmd_msg_recv_time_sync(tsync->msg_handle,
+ sync_proto, &sync_msg,
+ &size, &msg);
+ if (ret || strncmp(sync_proto, PTP_NAME, TRACECMD_TSYNC_PNAME_LENGTH) ||
+ sync_msg != PTP_SYNC_PKT_START)
+ return -1;
+ ret = tracecmd_msg_send_time_sync(tsync->msg_handle, PTP_NAME,
+ PTP_SYNC_PKT_START, sizeof(start),
+ (char *)&start);
+ marker.data.local_cid = clock_context->local_cid;
+ marker.data.remote_cid = clock_context->remote_cid;
+ marker.series_id = ntohl(start.series_id);
+ marker.data.packet_id = 'r';
+ ptp->series_id = marker.series_id;
+ ptp->flags = ntohl(start.flags);
+ msg = (char *)&count;
+ size = sizeof(count);
+ ctx.msg.count = 0;
+ ctx.size = PTP_SYNC_LOOP;
+ ctx.ptp = ptp;
+ ctx.clock = clock_context;
+ ctx.msg.series_id = ptp->series_id;
+ while (true) {
+ count = 0;
+ ret = tracecmd_msg_recv_time_sync(tsync->msg_handle,
+ sync_proto, &sync_msg,
+ &size, &msg);
+ if (ret || strncmp(sync_proto, PTP_NAME, TRACECMD_TSYNC_PNAME_LENGTH) ||
+ sync_msg != PTP_SYNC_PKT_PROBE || !ntohl(count))
+ break;
+ marker.data.count = ntohl(count);
+ ptp_track_clock(&ctx, &marker);
+ ret = tracecmd_msg_send_time_sync(tsync->msg_handle, PTP_NAME,
+ PTP_SYNC_PKT_PROBE,
+ sizeof(count), (char *)&count);
+ if (ret)
+ break;
+ }
+
+ if (strncmp(sync_proto, PTP_NAME, TRACECMD_TSYNC_PNAME_LENGTH) ||
+ sync_msg != PTP_SYNC_PKT_END)
+ return -1;
+
+ if (ptp->flags & PTP_FLAG_USE_MARKER)
+ tracefs_iterate_raw_events(ptp->tep, clock_context->instance,
+ NULL, 0, ptp_marker_find, &ctx);
+
+ hton_ptp_results(&ctx.msg);
+ ret = tracecmd_msg_send_time_sync(tsync->msg_handle, PTP_NAME,
+ PTP_SYNC_PKT_PROBES,
+ sizeof(ctx.msg), (char *)&ctx.msg);
+
+ msg = (char *)&res_offset;
+ size = sizeof(res_offset);
+ ret = tracecmd_msg_recv_time_sync(tsync->msg_handle,
+ sync_proto, &sync_msg,
+ &size, (char **)&msg);
+ if (ret || strncmp(sync_proto, PTP_NAME, TRACECMD_TSYNC_PNAME_LENGTH) ||
+ sync_msg != PTP_SYNC_PKT_OFFSET)
+ return -1;
+
+ *offset = ntohll(res_offset.offset);
+ *timestamp = ntohll(res_offset.ts);
+
+ return 0;
+}
+
+
+static int ptp_clock_server(struct tracecmd_time_sync *tsync,
+ long long *offset, long long *timestamp)
+{
+ char sync_proto[TRACECMD_TSYNC_PNAME_LENGTH];
+ struct ptp_clock_result_msg *results = NULL;
+ struct clock_sync_context *clock_context;
+ struct ptp_clock_offset_msg res_offset;
+ struct ptp_clock_start_msg start;
+ struct ptp_markers_context ctx;
+ int sync_loop = PTP_SYNC_LOOP;
+ struct ptp_clock_sync *ptp;
+ struct ptp_marker marker;
+ unsigned int sync_msg;
+ unsigned int size;
+ int bad_probes;
+ int count = 1;
+ int msg_count;
+ int msg_ret;
+ char *msg;
+ int ret;
+
+ if (!tsync || !tsync->context || !tsync->msg_handle)
+ return -1;
+
+ clock_context = (struct clock_sync_context *)tsync->context;
+ if (clock_context->proto_data == NULL)
+ return -1;
+
+ ptp = (struct ptp_clock_sync *)clock_context->proto_data;
+ ptp->flags = ptp_flags;
+ memset(&start, 0, sizeof(start));
+ start.series_id = htonl(ptp->series_id + 1);
+ start.flags = htonl(ptp->flags);
+ ret = tracecmd_msg_send_time_sync(tsync->msg_handle, PTP_NAME,
+ PTP_SYNC_PKT_START, sizeof(start),
+ (char *)&start);
+ if (!ret)
+ ret = tracecmd_msg_recv_time_sync(tsync->msg_handle,
+ sync_proto, &sync_msg,
+ NULL, NULL);
+ if (ret || strncmp(sync_proto, PTP_NAME, TRACECMD_TSYNC_PNAME_LENGTH) ||
+ sync_msg != PTP_SYNC_PKT_START)
+ return -1;
+
+ tracefs_instance_file_write(clock_context->instance, "trace", "\0");
+
+ ptp->series_id++;
+ marker.data.local_cid = clock_context->local_cid;
+ marker.data.remote_cid = clock_context->remote_cid;
+ marker.series_id = ptp->series_id;
+ msg = (char *)&msg_ret;
+ size = sizeof(msg_ret);
+ ctx.size = 2*PTP_SYNC_LOOP;
+ ctx.ptp = ptp;
+ ctx.clock = clock_context;
+ ctx.msg.count = 0;
+ ctx.msg.series_id = ptp->series_id;
+ do {
+ marker.data.count = count++;
+ marker.data.packet_id = 's';
+ msg_count = htonl(marker.data.count);
+ ptp_track_clock(&ctx, &marker);
+ ret = tracecmd_msg_send_time_sync(tsync->msg_handle, PTP_NAME,
+ PTP_SYNC_PKT_PROBE,
+ sizeof(msg_count),
+ (char *)&msg_count);
+ if (!ret)
+ ret = tracecmd_msg_recv_time_sync(tsync->msg_handle,
+ sync_proto, &sync_msg,
+ &size, &msg);
+
+ marker.data.packet_id = 'r';
+ ptp_track_clock(&ctx, &marker);
+ if (ret || strncmp(sync_proto, PTP_NAME, TRACECMD_TSYNC_PNAME_LENGTH) ||
+ sync_msg != PTP_SYNC_PKT_PROBE ||
+ ntohl(msg_ret) != marker.data.count)
+ break;
+ } while (--sync_loop);
+
+ if (sync_loop)
+ return -1;
+
+ ret = tracecmd_msg_send_time_sync(tsync->msg_handle, PTP_NAME,
+ PTP_SYNC_PKT_END, 0, NULL);
+
+ size = 0;
+ ret = tracecmd_msg_recv_time_sync(tsync->msg_handle,
+ sync_proto, &sync_msg,
+ &size, (char **)&results);
+ if (ret || strncmp(sync_proto, PTP_NAME, TRACECMD_TSYNC_PNAME_LENGTH) ||
+ sync_msg != PTP_SYNC_PKT_PROBES || size == 0 || results == NULL)
+ return -1;
+
+ ntoh_ptp_results(results);
+ if (ptp->flags & PTP_FLAG_USE_MARKER)
+ tracefs_iterate_raw_events(ptp->tep, clock_context->instance,
+ NULL, 0, ptp_marker_find, &ctx);
+ if (ptp->flags & PTP_FLAG_FASTEST_RESPONSE)
+ ptp_calc_offset_fastest(clock_context, &ctx.msg, results, offset,
+ timestamp, &bad_probes);
+ else
+ ptp_calc_offset_hist(clock_context, &ctx.msg, results, offset,
+ timestamp, &bad_probes);
+#ifdef TSYNC_DEBUG
+ {
+ char buff[256];
+ int res_fd;
+
+ sprintf(buff, "res-cid%d.txt", clock_context->remote_cid);
+
+ res_fd = open(buff, O_WRONLY|O_APPEND, 0644);
+ if (res_fd > 0) {
+ if (*offset && *timestamp) {
+ sprintf(buff, "%d %lld %lld\n",
+ ptp->series_id, *offset, *timestamp);
+ write(res_fd, buff, strlen(buff));
+ }
+ close(res_fd);
+ }
+
+ printf("\n calculated offset %d: %lld, %d probes, filtered out %d, PTP flags 0x%X\n\r",
+ ptp->series_id, *offset, results->count, bad_probes, ptp->flags);
+ if (ptp && ptp->debug_fd > 0) {
+ sprintf(buff, "%lld %lld 0\n", *offset, *timestamp);
+ write(ptp->debug_fd, buff, strlen(buff));
+ close(ptp->debug_fd);
+ ptp->debug_fd = -1;
+ }
+
+ }
+#endif
+
+ res_offset.offset = htonll(*offset);
+ res_offset.ts = htonll(*timestamp);
+ ret = tracecmd_msg_send_time_sync(tsync->msg_handle, PTP_NAME,
+ PTP_SYNC_PKT_OFFSET,
+ sizeof(res_offset),
+ (char *)&res_offset);
+
+ free(results);
+ return 0;
+}
+
+static int ptp_clock_sync_calc(struct tracecmd_time_sync *tsync,
+ long long *offset, long long *scaling,
+ long long *timestamp, unsigned int cpu)
+{
+ struct clock_sync_context *clock_context;
+ int ret;
+
+ if (!tsync || !tsync->context)
+ return -1;
+ clock_context = (struct clock_sync_context *)tsync->context;
+
+#ifdef TSYNC_DEBUG
+ if (clock_context->is_server) {
+ struct ptp_clock_sync *ptp;
+ char buff[256];
+
+ ptp = (struct ptp_clock_sync *)clock_context->proto_data;
+ if (ptp->debug_fd > 0)
+ close(ptp->debug_fd);
+ sprintf(buff, "s-cid%d_%d.txt",
+ clock_context->remote_cid, ptp->series_id+1);
+ ptp->debug_fd = open(buff, O_CREAT|O_WRONLY|O_TRUNC, 0644);
+ }
+#endif
+
+ if (scaling)
+ *scaling = 1;
+ if (clock_context->is_server)
+ ret = ptp_clock_server(tsync, offset, timestamp);
+ else
+ ret = ptp_clock_client(tsync, offset, timestamp);
+
+ return ret;
+}
+
+int ptp_clock_sync_register(void)
+{
+ return tracecmd_tsync_proto_register(PTP_NAME, PTP_ACCURACY,
+ TRACECMD_TIME_SYNC_ROLE_GUEST |
+ TRACECMD_TIME_SYNC_ROLE_HOST,
+ 0, TRACECMD_TSYNC_FLAG_INTERPOLATE,
+ ptp_clock_sync_init,
+ ptp_clock_sync_free,
+ ptp_clock_sync_calc);
+
+}
+
+int ptp_clock_sync_unregister(void)
+{
+ return tracecmd_tsync_proto_unregister(PTP_NAME);
+}
diff --git a/lib/trace-cmd/trace-timesync.c b/lib/trace-cmd/trace-timesync.c
index 8c1586c7..fb18075b 100644
--- a/lib/trace-cmd/trace-timesync.c
+++ b/lib/trace-cmd/trace-timesync.c
@@ -62,7 +62,7 @@ static struct tsync_proto *tsync_proto_find(const char *proto_name)
*/
void tracecmd_tsync_init(void)
{
-
+ ptp_clock_sync_register();
}
int tracecmd_tsync_proto_register(const char *proto_name, int accuracy, int roles,
--
2.29.2
^ permalink raw reply related [flat|nested] 25+ messages in thread
* [PATCH v28 7/8] trace-cmd: Debug scripts for PTP-like algorithm for host - guest timestamp synchronization
2021-02-08 6:17 [PATCH v28 0/8] Timestamp synchronization of host - guest tracing session Tzvetomir Stoyanov (VMware)
` (5 preceding siblings ...)
2021-02-08 6:17 ` [PATCH v28 6/8] trace-cmd: [POC] PTP-like algorithm for host - guest timestamp synchronization Tzvetomir Stoyanov (VMware)
@ 2021-02-08 6:17 ` Tzvetomir Stoyanov (VMware)
2021-02-08 6:17 ` [PATCH v28 8/8] trace-cmd [POC]: Add KVM timestamp synchronization plugin Tzvetomir Stoyanov (VMware)
2021-02-09 5:32 ` [PATCH v28 0/8] Timestamp synchronization of host - guest tracing session Dario Faggioli
8 siblings, 0 replies; 25+ messages in thread
From: Tzvetomir Stoyanov (VMware) @ 2021-02-08 6:17 UTC (permalink / raw)
To: rostedt; +Cc: linux-trace-devel
These scripts can be used to visualise debug files, written when the PTP-like algorithm
is compiled with TSYNC_DEBUG defined. The files are located in the guest machine:
s-cid*.txt - For each offset calculation: host and guest clocks and calculated offset.
res-cid*.txt - For each tracing session: all calculated clock offsets.
tsync_hist.py plots a histogram, using data from a s-cid*.txt file:
"python tsync_hist.py s-cid2_1.txt"
tsync_res.py plots a line, using data from res-cid*.txt file:
"python tsync_res.py res-cid2.txt"
Signed-off-by: Tzvetomir Stoyanov (VMware) <tz.stoyanov@gmail.com>
---
scripts/debug/tsync_hist.py | 57 +++++++++++++++++++++++++++++++++++++
scripts/debug/tsync_readme | 12 ++++++++
scripts/debug/tsync_res.py | 46 ++++++++++++++++++++++++++++++
3 files changed, 115 insertions(+)
create mode 100644 scripts/debug/tsync_hist.py
create mode 100644 scripts/debug/tsync_readme
create mode 100644 scripts/debug/tsync_res.py
diff --git a/scripts/debug/tsync_hist.py b/scripts/debug/tsync_hist.py
new file mode 100644
index 00000000..819d1e8f
--- /dev/null
+++ b/scripts/debug/tsync_hist.py
@@ -0,0 +1,57 @@
+# SPDX-License-Identifier: GPL-2.0
+#
+# Copyright (C) 2019, VMware Inc, Tzvetomir Stoyanov <tz.stoyanov@gmail.com>
+# Copyright (C) 2019, VMware Inc, Yordan Karadzhov <ykaradzhov@vmware.com>
+
+
+import matplotlib.pyplot as plt
+import matplotlib.lines as mlines
+import numpy as np
+import sys
+
+def newline(p1, p2):
+ ax = plt.gca()
+ xmin, xmax = ax.get_xbound()
+
+ if(p2[0] == p1[0]):
+ xmin = xmax = p1[0]
+ ymin, ymax = ax.get_ybound()
+ else:
+ ymax = p1[1]+(p2[1]-p1[1])/(p2[0]-p1[0])*(xmax-p1[0])
+ ymin = p1[1]+(p2[1]-p1[1])/(p2[0]-p1[0])*(xmin-p1[0])
+
+ l = mlines.Line2D([xmin,xmax], [ymin,ymax], color='red')
+ ax.add_line(l)
+ return l
+
+
+data = np.loadtxt(fname = sys.argv[1])
+selected_ts = data[-1, 1]
+selected_ofs = data[-1, 0]
+data = data[:-1,:]
+
+x = data[:, 1] - data[:, 0]
+
+mean = x.mean()
+std = x.std()
+
+num_bins = 500
+min = x.min() #+ .4 * (x.max() - x.min())
+max = x.max() #- .4 * (x.max() - x.min())
+bins = np.linspace(min, max, num_bins, endpoint = False, dtype=int)
+
+fig, ax = plt.subplots()
+
+# the histogram of the data
+n, bins, patches = ax.hist(x, bins, histtype=u'step');
+
+ax.set_xlabel('clock offset [$\mu$s]')
+ax.set_ylabel('entries')
+ax.set_title("$\sigma$=%i" % std)
+
+x1, y1 = [selected_ofs, min], [selected_ofs, max]
+newline(x1, y1)
+
+# Tweak spacing to prevent clipping of ylabel
+fig.tight_layout()
+plt.show()
diff --git a/scripts/debug/tsync_readme b/scripts/debug/tsync_readme
new file mode 100644
index 00000000..f3ebb25d
--- /dev/null
+++ b/scripts/debug/tsync_readme
@@ -0,0 +1,12 @@
+PTP-like algorithm debug
+========================
+
+tsync_*.py scripts can be used to visualise debug files, written when the PTP-like algorithm
+is compiled with TSYNC_DEBUG defined. The files are located in the guest machine:
+ s-cid*.txt - For each offset calculation: host and guest clocks and calculated offset.
+ res-cid*.txt - For each tracing session: all calculated clock offsets.
+
+tsync_hist.py plots a histogram, using data from a s-cid*.txt file:
+ "python tsync_hist.py s-cid2_1.txt"
+tsync_res.py plots a line, using data from res-cid*.txt file:
+ "python tsync_res.py res-cid2.txt"
diff --git a/scripts/debug/tsync_res.py b/scripts/debug/tsync_res.py
new file mode 100644
index 00000000..7d109863
--- /dev/null
+++ b/scripts/debug/tsync_res.py
@@ -0,0 +1,46 @@
+# SPDX-License-Identifier: GPL-2.0
+#
+# Copyright (C) 2019, VMware Inc, Tzvetomir Stoyanov <tz.stoyanov@gmail.com>
+# Copyright (C) 2019, VMware Inc, Yordan Karadzhov <ykaradzhov@vmware.com>
+
+
+import matplotlib.pyplot as plt
+import matplotlib.lines as mlines
+import numpy as np
+import sys
+
+def newline(p1, p2):
+ ax = plt.gca()
+ xmin, xmax = ax.get_xbound()
+
+ if(p2[0] == p1[0]):
+ xmin = xmax = p1[0]
+ ymin, ymax = ax.get_ybound()
+ else:
+ ymax = p1[1]+(p2[1]-p1[1])/(p2[0]-p1[0])*(xmax-p1[0])
+ ymin = p1[1]+(p2[1]-p1[1])/(p2[0]-p1[0])*(xmin-p1[0])
+
+ l = mlines.Line2D([xmin,xmax], [ymin,ymax], color='red')
+ ax.add_line(l)
+ return l
+
+data = np.loadtxt(fname = sys.argv[1])
+x = data[:, 0]
+y = data[:, 1]
+
+fig, ax = plt.subplots()
+
+ax.set_xlabel('samples (t)')
+ax.set_ylabel('clock offset')
+ax.set_title("$\delta$=%i ns" % (max(y) - min(y)))
+
+l = mlines.Line2D(x, y)
+ax.add_line(l)
+ax.set_xlim(min(x), max(x))
+ax.set_ylim(min(y), max(y) )
+
+print(min(y), max(y), max(y) - min(y))
+
+# Tweak spacing to prevent clipping of ylabel
+fig.tight_layout()
+plt.show()
--
2.29.2
^ permalink raw reply related [flat|nested] 25+ messages in thread
* [PATCH v28 8/8] trace-cmd [POC]: Add KVM timestamp synchronization plugin
2021-02-08 6:17 [PATCH v28 0/8] Timestamp synchronization of host - guest tracing session Tzvetomir Stoyanov (VMware)
` (6 preceding siblings ...)
2021-02-08 6:17 ` [PATCH v28 7/8] trace-cmd: Debug scripts for " Tzvetomir Stoyanov (VMware)
@ 2021-02-08 6:17 ` Tzvetomir Stoyanov (VMware)
2021-02-16 20:48 ` Steven Rostedt
2021-02-09 5:32 ` [PATCH v28 0/8] Timestamp synchronization of host - guest tracing session Dario Faggioli
8 siblings, 1 reply; 25+ messages in thread
From: Tzvetomir Stoyanov (VMware) @ 2021-02-08 6:17 UTC (permalink / raw)
To: rostedt; +Cc: linux-trace-devel
Added new timestamp synchronization plugin for KVM hosts. It reads the
clock offsets directly from the KVM debug filesystem, if available.
The plugin works only with x86-tsc ftrace clock.
Signed-off-by: Tzvetomir Stoyanov (VMware) <tz.stoyanov@gmail.com>
---
lib/trace-cmd/Makefile | 1 +
lib/trace-cmd/include/trace-tsync-local.h | 1 +
lib/trace-cmd/trace-timesync-kvm.c | 460 ++++++++++++++++++++++
lib/trace-cmd/trace-timesync.c | 1 +
4 files changed, 463 insertions(+)
create mode 100644 lib/trace-cmd/trace-timesync-kvm.c
diff --git a/lib/trace-cmd/Makefile b/lib/trace-cmd/Makefile
index f41feef8..e8d2dae9 100644
--- a/lib/trace-cmd/Makefile
+++ b/lib/trace-cmd/Makefile
@@ -20,6 +20,7 @@ OBJS += trace-plugin.o
ifeq ($(VSOCK_DEFINED), 1)
OBJS += trace-timesync.o
OBJS += trace-timesync-ptp.o
+OBJS += trace-timesync-kvm.o
endif
# Additional util objects
diff --git a/lib/trace-cmd/include/trace-tsync-local.h b/lib/trace-cmd/include/trace-tsync-local.h
index d4281469..fe91e2e3 100644
--- a/lib/trace-cmd/include/trace-tsync-local.h
+++ b/lib/trace-cmd/include/trace-tsync-local.h
@@ -49,5 +49,6 @@ int tracecmd_tsync_proto_register(const char *proto_name, int accuracy, int role
int tracecmd_tsync_proto_unregister(char *proto_name);
int ptp_clock_sync_register(void);
+int kvm_clock_sync_register(void);
#endif /* _TRACE_TSYNC_LOCAL_H */
diff --git a/lib/trace-cmd/trace-timesync-kvm.c b/lib/trace-cmd/trace-timesync-kvm.c
new file mode 100644
index 00000000..03a4fd73
--- /dev/null
+++ b/lib/trace-cmd/trace-timesync-kvm.c
@@ -0,0 +1,460 @@
+// SPDX-License-Identifier: LGPL-2.1
+/*
+ * Copyright (C) 2020, VMware, Tzvetomir Stoyanov tz.stoyanov@gmail.com>
+ *
+ */
+
+#include <fcntl.h>
+#include <stdlib.h>
+#include <unistd.h>
+#include <sys/stat.h>
+#include <dirent.h>
+
+#include "trace-cmd.h"
+#include "trace-cmd-private.h"
+#include "tracefs.h"
+#include "trace-tsync-local.h"
+
+#define KVM_DEBUG_FS "/sys/kernel/debug/kvm"
+#define KVM_DEBUG_OFFSET_FILE "tsc-offset"
+#define KVM_DEBUG_SCALING_FILE "tsc-scaling-ratio"
+#define KVM_DEBUG_VCPU_DIR "vcpu"
+
+#define KVM_SYNC_PKT_REQUEST 1
+#define KVM_SYNC_PKT_RESPONSE 2
+
+typedef __s64 s64;
+
+// equal to /sys/kernel/debug/kvm/<VM ID>/vcpu0/tsc-offset
+#define KVM_ACCURACY 0
+#define KVM_NAME "kvm"
+
+struct kvm_clock_sync {
+ int vcpu_count;
+ char **vcpu_offsets;
+ char **vcpu_scalings;
+ int marker_fd;
+ struct tep_handle *tep;
+ int raw_id;
+ unsigned long long ts;
+};
+
+struct kvm_clock_offset_msg {
+ s64 ts;
+ s64 offset;
+ s64 scaling;
+};
+
+static bool kvm_support_check(bool guest)
+{
+ struct stat st;
+ int ret;
+
+ if (guest)
+ return true;
+
+ ret = stat(KVM_DEBUG_FS, &st);
+ if (ret < 0)
+ return false;
+
+ if (!S_ISDIR(st.st_mode))
+ return false;
+ return true;
+}
+
+static int kvm_open_vcpu_dir(struct kvm_clock_sync *kvm, int cpu, char *dir_str)
+{
+ struct dirent *entry;
+ char path[PATH_MAX];
+ DIR *dir;
+
+ dir = opendir(dir_str);
+ if (!dir)
+ goto error;
+ while ((entry = readdir(dir))) {
+ if (entry->d_type != DT_DIR) {
+ if (!strncmp(entry->d_name, KVM_DEBUG_OFFSET_FILE,
+ strlen(KVM_DEBUG_OFFSET_FILE))) {
+ snprintf(path, sizeof(path), "%s/%s",
+ dir_str, entry->d_name);
+ kvm->vcpu_offsets[cpu] = strdup(path);
+ }
+ if (!strncmp(entry->d_name, KVM_DEBUG_SCALING_FILE,
+ strlen(KVM_DEBUG_SCALING_FILE))) {
+ snprintf(path, sizeof(path), "%s/%s",
+ dir_str, entry->d_name);
+ kvm->vcpu_scalings[cpu] = strdup(path);
+ }
+ }
+ }
+ if (!kvm->vcpu_offsets[cpu])
+ goto error;
+ closedir(dir);
+ return 0;
+
+error:
+ if (dir)
+ closedir(dir);
+ free(kvm->vcpu_offsets[cpu]);
+ kvm->vcpu_offsets[cpu] = NULL;
+ free(kvm->vcpu_scalings[cpu]);
+ kvm->vcpu_scalings[cpu] = NULL;
+ return -1;
+}
+
+static int kvm_open_debug_files(struct kvm_clock_sync *kvm, int pid)
+{
+ char *vm_dir_str = NULL;
+ struct dirent *entry;
+ char *pid_str = NULL;
+ char path[PATH_MAX];
+ long vcpu;
+ DIR *dir;
+ int i;
+
+ dir = opendir(KVM_DEBUG_FS);
+ if (!dir)
+ goto error;
+ if (asprintf(&pid_str, "%d-", pid) <= 0)
+ goto error;
+ while ((entry = readdir(dir))) {
+ if (!(entry->d_type == DT_DIR &&
+ !strncmp(entry->d_name, pid_str, strlen(pid_str))))
+ continue;
+ asprintf(&vm_dir_str, "%s/%s", KVM_DEBUG_FS, entry->d_name);
+ break;
+ }
+ closedir(dir);
+ dir = NULL;
+ if (!vm_dir_str)
+ goto error;
+ dir = opendir(vm_dir_str);
+ if (!dir)
+ goto error;
+ while ((entry = readdir(dir))) {
+ if (!(entry->d_type == DT_DIR &&
+ !strncmp(entry->d_name, KVM_DEBUG_VCPU_DIR, strlen(KVM_DEBUG_VCPU_DIR))))
+ continue;
+ vcpu = strtol(entry->d_name + strlen(KVM_DEBUG_VCPU_DIR), NULL, 10);
+ if (vcpu < 0 || vcpu >= kvm->vcpu_count)
+ continue;
+ snprintf(path, sizeof(path), "%s/%s", vm_dir_str, entry->d_name);
+ if (kvm_open_vcpu_dir(kvm, vcpu, path) < 0)
+ goto error;
+ }
+ for (i = 0; i < kvm->vcpu_count; i++) {
+ if (!kvm->vcpu_offsets[i])
+ goto error;
+ }
+ closedir(dir);
+ free(pid_str);
+ free(vm_dir_str);
+ return 0;
+error:
+ free(pid_str);
+ free(vm_dir_str);
+ if (dir)
+ closedir(dir);
+ return -1;
+}
+
+static int kvm_clock_sync_init_host(struct tracecmd_time_sync *tsync,
+ struct kvm_clock_sync *kvm)
+{
+ kvm->vcpu_count = tsync->vcpu_count;
+ kvm->vcpu_offsets = calloc(kvm->vcpu_count, sizeof(char *));
+ kvm->vcpu_scalings = calloc(kvm->vcpu_count, sizeof(char *));
+ if (!kvm->vcpu_offsets || !kvm->vcpu_scalings)
+ goto error;
+ if (kvm_open_debug_files(kvm, tsync->guest_pid) < 0)
+ goto error;
+ return 0;
+
+error:
+ free(kvm->vcpu_offsets);
+ free(kvm->vcpu_scalings);
+ return -1;
+}
+
+static int kvm_clock_sync_init_guest(struct tracecmd_time_sync *tsync,
+ struct kvm_clock_sync *kvm)
+{
+ const char *systems[] = {"ftrace", NULL};
+ struct clock_sync_context *clock_context;
+ struct tep_event *raw;
+ char *path;
+
+ clock_context = (struct clock_sync_context *)tsync->context;
+ path = tracefs_instance_get_dir(clock_context->instance);
+ if (!path)
+ goto error;
+ kvm->tep = tracefs_local_events_system(path, systems);
+ tracefs_put_tracing_file(path);
+ if (!kvm->tep)
+ goto error;
+ raw = tep_find_event_by_name(kvm->tep, "ftrace", "raw_data");
+ if (!raw)
+ goto error;
+
+ kvm->raw_id = raw->id;
+ tep_set_file_bigendian(kvm->tep, tracecmd_host_bigendian());
+ tep_set_local_bigendian(kvm->tep, tracecmd_host_bigendian());
+
+ path = tracefs_instance_get_file(clock_context->instance, "trace_marker_raw");
+ if (!path)
+ goto error;
+ kvm->marker_fd = open(path, O_WRONLY);
+ tracefs_put_tracing_file(path);
+
+ return 0;
+
+error:
+ if (kvm->tep)
+ tep_free(kvm->tep);
+ if (kvm->marker_fd >= 0)
+ close(kvm->marker_fd);
+
+ return -1;
+}
+
+static int kvm_clock_sync_init(struct tracecmd_time_sync *tsync)
+{
+ struct clock_sync_context *clock_context;
+ struct kvm_clock_sync *kvm;
+ int ret;
+
+ if (!tsync || !tsync->context)
+ return -1;
+ clock_context = (struct clock_sync_context *)tsync->context;
+
+ if (!kvm_support_check(clock_context->is_guest))
+ return -1;
+ kvm = calloc(1, sizeof(struct kvm_clock_sync));
+ if (!kvm)
+ return -1;
+ kvm->marker_fd = -1;
+ if (clock_context->is_guest)
+ ret = kvm_clock_sync_init_guest(tsync, kvm);
+ else
+ ret = kvm_clock_sync_init_host(tsync, kvm);
+ if (ret < 0)
+ goto error;
+
+ clock_context->proto_data = kvm;
+ return 0;
+
+error:
+ free(kvm);
+ return -1;
+}
+
+static int kvm_clock_sync_free(struct tracecmd_time_sync *tsync)
+{
+ struct clock_sync_context *clock_context;
+ struct kvm_clock_sync *kvm = NULL;
+ int i;
+
+ clock_context = (struct clock_sync_context *)tsync->context;
+ if (clock_context)
+ kvm = (struct kvm_clock_sync *)clock_context->proto_data;
+ if (kvm) {
+ for (i = 0; i < kvm->vcpu_count; i++) {
+ free(kvm->vcpu_offsets[i]);
+ kvm->vcpu_offsets[i] = NULL;
+ free(kvm->vcpu_scalings[i]);
+ kvm->vcpu_scalings[i] = NULL;
+ }
+ if (kvm->tep)
+ tep_free(kvm->tep);
+ if (kvm->marker_fd >= 0)
+ close(kvm->marker_fd);
+ free(kvm);
+ }
+ return -1;
+}
+
+static int read_ll_form_file(char *file, long long *res)
+{
+ char buf[32];
+ int ret;
+ int fd;
+
+ if (!file)
+ return -1;
+ fd = open(file, O_RDONLY | O_NONBLOCK);
+ if (fd < 0)
+ return -1;
+ ret = read(fd, buf, 32);
+ close(fd);
+ if (ret <= 0)
+ return -1;
+
+ *res = strtoll(buf, NULL, 10);
+
+ return 0;
+}
+
+static int kvm_clock_host(struct tracecmd_time_sync *tsync,
+ long long *offset, long long *scaling,
+ long long *timestamp, unsigned int cpu)
+{
+ char sync_proto[TRACECMD_TSYNC_PNAME_LENGTH];
+ struct clock_sync_context *clock_context;
+ struct kvm_clock_offset_msg packet;
+ struct kvm_clock_sync *kvm = NULL;
+ long long kvm_scaling = 1;
+ unsigned int sync_msg;
+ long long kvm_offset;
+ unsigned int size;
+ char *msg;
+ int ret;
+
+ clock_context = (struct clock_sync_context *)tsync->context;
+ if (clock_context)
+ kvm = (struct kvm_clock_sync *)clock_context->proto_data;
+ if (!kvm || !kvm->vcpu_offsets || !kvm->vcpu_offsets[0])
+ return -1;
+ if (cpu >= kvm->vcpu_count)
+ return -1;
+ ret = read_ll_form_file(kvm->vcpu_offsets[cpu], &kvm_offset);
+ if (ret < 0)
+ return -1;
+ if (kvm->vcpu_scalings && kvm->vcpu_scalings[cpu])
+ read_ll_form_file(kvm->vcpu_scalings[cpu], &kvm_scaling);
+ msg = (char *)&packet;
+ size = sizeof(packet);
+ ret = tracecmd_msg_recv_time_sync(tsync->msg_handle,
+ sync_proto, &sync_msg,
+ &size, &msg);
+ if (ret || strncmp(sync_proto, KVM_NAME, TRACECMD_TSYNC_PNAME_LENGTH) ||
+ sync_msg != KVM_SYNC_PKT_REQUEST)
+ return -1;
+
+ packet.offset = -kvm_offset;
+ packet.scaling = kvm_scaling;
+ ret = tracecmd_msg_send_time_sync(tsync->msg_handle, KVM_NAME,
+ KVM_SYNC_PKT_RESPONSE, sizeof(packet),
+ (char *)&packet);
+ if (ret)
+ return -1;
+
+ *scaling = packet.scaling;
+ *offset = packet.offset;
+ *timestamp = packet.ts;
+
+ return 0;
+}
+
+#define KVM_EVENT_MARKER "kvm sync event"
+static int kvm_marker_find(struct tep_event *event, struct tep_record *record,
+ int cpu, void *context)
+{
+ struct kvm_clock_sync *kvm = (struct kvm_clock_sync *)context;
+ struct tep_format_field *field;
+ struct tep_format_field *id;
+ char *marker;
+
+ /* Make sure this is our event */
+ if (event->id != kvm->raw_id)
+ return 0;
+ id = tep_find_field(event, "id");
+ field = tep_find_field(event, "buf");
+ if (field && id &&
+ record->size >= (id->offset + strlen(KVM_EVENT_MARKER) + 1)) {
+ marker = (char *)(record->data + id->offset);
+ if (!strcmp(marker, KVM_EVENT_MARKER)) {
+ kvm->ts = record->ts;
+ return 1;
+ }
+ }
+
+ return 0;
+}
+
+
+static int kvm_clock_guest(struct tracecmd_time_sync *tsync,
+ long long *offset,
+ long long *scaling,
+ long long *timestamp)
+{
+ char sync_proto[TRACECMD_TSYNC_PNAME_LENGTH];
+ struct clock_sync_context *clock_context;
+ struct kvm_clock_offset_msg packet;
+ struct kvm_clock_sync *kvm = NULL;
+ unsigned int sync_msg;
+ unsigned int size;
+ char *msg;
+ int ret;
+
+ clock_context = (struct clock_sync_context *)tsync->context;
+ if (clock_context)
+ kvm = (struct kvm_clock_sync *)clock_context->proto_data;
+ if (!kvm)
+ return -1;
+ kvm->ts = 0;
+ memset(&packet, 0, sizeof(packet));
+ tracefs_instance_file_write(clock_context->instance, "trace", "\0");
+ write(kvm->marker_fd, KVM_EVENT_MARKER, strlen(KVM_EVENT_MARKER) + 1);
+ kvm->ts = 0;
+ tracefs_iterate_raw_events(kvm->tep, clock_context->instance,
+ NULL, 0, kvm_marker_find, kvm);
+ packet.ts = kvm->ts;
+ ret = tracecmd_msg_send_time_sync(tsync->msg_handle, KVM_NAME,
+ KVM_SYNC_PKT_REQUEST, sizeof(packet),
+ (char *)&packet);
+ if (ret)
+ return -1;
+ msg = (char *)&packet;
+ size = sizeof(packet);
+ ret = tracecmd_msg_recv_time_sync(tsync->msg_handle,
+ sync_proto, &sync_msg,
+ &size, &msg);
+ if (ret || strncmp(sync_proto, KVM_NAME, TRACECMD_TSYNC_PNAME_LENGTH) ||
+ sync_msg != KVM_SYNC_PKT_RESPONSE)
+ return -1;
+
+ *scaling = packet.scaling;
+ *offset = packet.offset;
+ *timestamp = packet.ts;
+ return 0;
+}
+
+static int kvm_clock_sync_calc(struct tracecmd_time_sync *tsync,
+ long long *offset, long long *scaling,
+ long long *timestamp, unsigned int cpu)
+{
+ struct clock_sync_context *clock_context;
+ int ret;
+
+ if (!tsync || !tsync->context)
+ return -1;
+
+ clock_context = (struct clock_sync_context *)tsync->context;
+
+ if (clock_context->is_guest)
+ ret = kvm_clock_guest(tsync, offset, scaling, timestamp);
+ else
+ ret = kvm_clock_host(tsync, offset, scaling, timestamp, cpu);
+ return ret;
+}
+
+int kvm_clock_sync_register(void)
+{
+ int role = TRACECMD_TIME_SYNC_ROLE_GUEST;
+ int clock = 0;
+
+ if (kvm_support_check(false)) {
+ role |= TRACECMD_TIME_SYNC_ROLE_HOST;
+ clock = TRACECMD_CLOCK_X86_TSC;
+ }
+ return tracecmd_tsync_proto_register(KVM_NAME, KVM_ACCURACY,
+ role, clock, 0,
+ kvm_clock_sync_init,
+ kvm_clock_sync_free,
+ kvm_clock_sync_calc);
+}
+
+int kvm_clock_sync_unregister(void)
+{
+ return tracecmd_tsync_proto_unregister(KVM_NAME);
+}
diff --git a/lib/trace-cmd/trace-timesync.c b/lib/trace-cmd/trace-timesync.c
index fb18075b..2a95512f 100644
--- a/lib/trace-cmd/trace-timesync.c
+++ b/lib/trace-cmd/trace-timesync.c
@@ -63,6 +63,7 @@ static struct tsync_proto *tsync_proto_find(const char *proto_name)
void tracecmd_tsync_init(void)
{
ptp_clock_sync_register();
+ kvm_clock_sync_register();
}
int tracecmd_tsync_proto_register(const char *proto_name, int accuracy, int roles,
--
2.29.2
^ permalink raw reply related [flat|nested] 25+ messages in thread
* Re: [PATCH v28 0/8] Timestamp synchronization of host - guest tracing session
2021-02-08 6:17 [PATCH v28 0/8] Timestamp synchronization of host - guest tracing session Tzvetomir Stoyanov (VMware)
` (7 preceding siblings ...)
2021-02-08 6:17 ` [PATCH v28 8/8] trace-cmd [POC]: Add KVM timestamp synchronization plugin Tzvetomir Stoyanov (VMware)
@ 2021-02-09 5:32 ` Dario Faggioli
2021-02-09 6:03 ` Tzvetomir Stoyanov
8 siblings, 1 reply; 25+ messages in thread
From: Dario Faggioli @ 2021-02-09 5:32 UTC (permalink / raw)
To: Tzvetomir Stoyanov (VMware), rostedt; +Cc: linux-trace-devel
[-- Attachment #1: Type: text/plain, Size: 3033 bytes --]
Hello,
On Mon, 2021-02-08 at 08:17 +0200, Tzvetomir Stoyanov (VMware) wrote:
> Basic infrastructure for host - guest timestamp synchronization and a
> PoC implementation of PTP-like and KVM algorithms.
>
I'm trying to play with trace-cmd agent & clock syncronization, so I
applied this series.
However, when I try to connect to a VM where I have the agent running,
I'm seeing this (on the host):
# ./tracecmd/trace-cmd record --debug -p nop -e sched:* -e kvm:* -e timer:hrtimer* -A tumbleweed-jeos:8888 -e all sleep 1
trace-cmd: No such file or directory
Failed to receive trace response -107
I tried to do a strace, still on the host, and this is what I see (the
last part of the output):
rt_sigaction(SIGINT, {sa_handler=0x4116a5, sa_mask=[INT], sa_flags=SA_RESTORER|SA_RESTART, sa_restorer=0x7f29f1b55b70}, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=0}, 8) = 0
openat(AT_FDCWD, "/var/lib/trace-cmd/virt/(null)/trace-pipe-cpu0.out", O_RDONLY|O_NONBLOCK) = -1 ENOENT (No such file or directory)
socket(AF_VSOCK, SOCK_STREAM, 0) = 4
connect(4, {sa_family=AF_VSOCK, sa_data="\0\0\270\"\0\0\3\0\0\0\0\0\0\0"}, 16) = 0
openat(AT_FDCWD, "/sys/kernel/debug/tracing/trace_clock", O_RDONLY) = 6
read(6, "local global counter uptime perf"..., 8192) = 62
read(6, "", 8192) = 0
close(6) = 0
write(4, "\0\0\0<\0\0\0\6\0\0\0\20\0\0\0\0\0\0\0\0\347\366+n\204\271\35\334", 28) = 28
write(4, "\0\0\0\0\0\0\0\v\0\0\0\2-e\0all\0\0\0\0\1\0\0\0\5ptp\0\0", 32) = 32
read(4, "", 12) = 0
dup(2) = 6
fcntl(6, F_GETFL) = 0x402 (flags O_RDWR|O_APPEND)
fstat(6, {st_mode=S_IFCHR|0620, st_rdev=makedev(0x88, 0x9), ...}) = 0
write(6, "trace-cmd: No such file or direc"..., 37trace-cmd: No such file or directory
) = 37
close(6) = 0
write(2, " ", 2 ) = 2
write(2, "Failed to receive trace response"..., 37Failed to receive trace response -107) = 37
write(2, "\n", 1
) = 1
exit_group(2) = ?
+++ exited with 2 +++
Finally, if I use `--debug` both on the host and in the VM, here's what
I get.
Guest:
# ./tracecmd/trace-cmd agent -p 8888 --debug
listening on @3:8888
msg received: 6 (TRACE_REQ) [60]
Segmentation fault
Host:
# ./tracecmd/trace-cmd record --debug -p nop -e sched:* -e kvm:* -e timer:hrtimer* -A tumbleweed-jeos:8888 -e all sleep 1
msg send: 6 (TRACE_REQ) [60]
trace-cmd: No such file or directory
Failed to receive trace response -107
Am I doing something wrong? :-)
If necessary, I can provide more info about my setup, or do more tests.
Thanks and Regards
--
Dario Faggioli, Ph.D
http://about.me/dario.faggioli
Virtualization Software Engineer
SUSE Labs, SUSE https://www.suse.com/
-------------------------------------------------------------------
<<This happens because _I_ choose it to happen!>> (Raistlin Majere)
[-- Attachment #2: This is a digitally signed message part --]
[-- Type: application/pgp-signature, Size: 833 bytes --]
^ permalink raw reply [flat|nested] 25+ messages in thread
* Re: [PATCH v28 0/8] Timestamp synchronization of host - guest tracing session
2021-02-09 5:32 ` [PATCH v28 0/8] Timestamp synchronization of host - guest tracing session Dario Faggioli
@ 2021-02-09 6:03 ` Tzvetomir Stoyanov
2021-02-09 6:08 ` Tzvetomir Stoyanov
2021-02-09 7:18 ` Dario Faggioli
0 siblings, 2 replies; 25+ messages in thread
From: Tzvetomir Stoyanov @ 2021-02-09 6:03 UTC (permalink / raw)
To: Dario Faggioli; +Cc: Steven Rostedt, Linux Trace Devel
Hi Dario,
On Tue, Feb 9, 2021 at 7:32 AM Dario Faggioli <dfaggioli@suse.com> wrote:
>
> Hello,
>
> On Mon, 2021-02-08 at 08:17 +0200, Tzvetomir Stoyanov (VMware) wrote:
> > Basic infrastructure for host - guest timestamp synchronization and a
> > PoC implementation of PTP-like and KVM algorithms.
> >
> I'm trying to play with trace-cmd agent & clock syncronization, so I
> applied this series.
>
> However, when I try to connect to a VM where I have the agent running,
> I'm seeing this (on the host):
>
> # ./tracecmd/trace-cmd record --debug -p nop -e sched:* -e kvm:* -e timer:hrtimer* -A tumbleweed-jeos:8888 -e all sleep 1
> trace-cmd: No such file or directory
> Failed to receive trace response -107
>
> I tried to do a strace, still on the host, and this is what I see (the
> last part of the output):
>
> rt_sigaction(SIGINT, {sa_handler=0x4116a5, sa_mask=[INT], sa_flags=SA_RESTORER|SA_RESTART, sa_restorer=0x7f29f1b55b70}, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=0}, 8) = 0
> openat(AT_FDCWD, "/var/lib/trace-cmd/virt/(null)/trace-pipe-cpu0.out", O_RDONLY|O_NONBLOCK) = -1 ENOENT (No such file or directory)
> socket(AF_VSOCK, SOCK_STREAM, 0) = 4
> connect(4, {sa_family=AF_VSOCK, sa_data="\0\0\270\"\0\0\3\0\0\0\0\0\0\0"}, 16) = 0
> openat(AT_FDCWD, "/sys/kernel/debug/tracing/trace_clock", O_RDONLY) = 6
> read(6, "local global counter uptime perf"..., 8192) = 62
> read(6, "", 8192) = 0
> close(6) = 0
> write(4, "\0\0\0<\0\0\0\6\0\0\0\20\0\0\0\0\0\0\0\0\347\366+n\204\271\35\334", 28) = 28
> write(4, "\0\0\0\0\0\0\0\v\0\0\0\2-e\0all\0\0\0\0\1\0\0\0\5ptp\0\0", 32) = 32
> read(4, "", 12) = 0
> dup(2) = 6
> fcntl(6, F_GETFL) = 0x402 (flags O_RDWR|O_APPEND)
> fstat(6, {st_mode=S_IFCHR|0620, st_rdev=makedev(0x88, 0x9), ...}) = 0
> write(6, "trace-cmd: No such file or direc"..., 37trace-cmd: No such file or directory
> ) = 37
> close(6) = 0
> write(2, " ", 2 ) = 2
> write(2, "Failed to receive trace response"..., 37Failed to receive trace response -107) = 37
> write(2, "\n", 1
> ) = 1
> exit_group(2) = ?
> +++ exited with 2 +++
>
> Finally, if I use `--debug` both on the host and in the VM, here's what
> I get.
>
> Guest:
> # ./tracecmd/trace-cmd agent -p 8888 --debug
> listening on @3:8888
> msg received: 6 (TRACE_REQ) [60]
> Segmentation fault
>
> Host:
> # ./tracecmd/trace-cmd record --debug -p nop -e sched:* -e kvm:* -e timer:hrtimer* -A tumbleweed-jeos:8888 -e all sleep 1
> msg send: 6 (TRACE_REQ) [60]
> trace-cmd: No such file or directory
> Failed to receive trace response -107
>
> Am I doing something wrong? :-)
>
> If necessary, I can provide more info about my setup, or do more tests.
There are a few limitations that we are working to address:
1. Ensure that vhost_vsock module is loaded on the host.
2. You should add a vsock device manually to your VM config, I use
"virsh edit <vm name>" to add:
<vsock model='virtio'>
<cid auto='yes'/>
<address type='pci' domain='0x0000' bus='0x00' slot='0x09'
function='0x0'/>
</vsock>
somewhere in the <devices> </devices> section.
>
> Thanks and Regards
> --
> Dario Faggioli, Ph.D
> http://about.me/dario.faggioli
> Virtualization Software Engineer
> SUSE Labs, SUSE https://www.suse.com/
> -------------------------------------------------------------------
> <<This happens because _I_ choose it to happen!>> (Raistlin Majere)
--
Tzvetomir (Ceco) Stoyanov
VMware Open Source Technology Center
^ permalink raw reply [flat|nested] 25+ messages in thread
* Re: [PATCH v28 0/8] Timestamp synchronization of host - guest tracing session
2021-02-09 6:03 ` Tzvetomir Stoyanov
@ 2021-02-09 6:08 ` Tzvetomir Stoyanov
2021-02-09 7:28 ` Dario Faggioli
2021-02-09 7:18 ` Dario Faggioli
1 sibling, 1 reply; 25+ messages in thread
From: Tzvetomir Stoyanov @ 2021-02-09 6:08 UTC (permalink / raw)
To: Dario Faggioli; +Cc: Steven Rostedt, Linux Trace Devel
On Tue, Feb 9, 2021 at 8:03 AM Tzvetomir Stoyanov <tz.stoyanov@gmail.com> wrote:
>
> Hi Dario,
>
> On Tue, Feb 9, 2021 at 7:32 AM Dario Faggioli <dfaggioli@suse.com> wrote:
> >
> > Hello,
> >
> > On Mon, 2021-02-08 at 08:17 +0200, Tzvetomir Stoyanov (VMware) wrote:
> > > Basic infrastructure for host - guest timestamp synchronization and a
> > > PoC implementation of PTP-like and KVM algorithms.
> > >
> > I'm trying to play with trace-cmd agent & clock syncronization, so I
> > applied this series.
> >
> > However, when I try to connect to a VM where I have the agent running,
> > I'm seeing this (on the host):
> >
> > # ./tracecmd/trace-cmd record --debug -p nop -e sched:* -e kvm:* -e timer:hrtimer* -A tumbleweed-jeos:8888 -e all sleep 1
> > trace-cmd: No such file or directory
> > Failed to receive trace response -107
> >
> > I tried to do a strace, still on the host, and this is what I see (the
> > last part of the output):
> >
> > rt_sigaction(SIGINT, {sa_handler=0x4116a5, sa_mask=[INT], sa_flags=SA_RESTORER|SA_RESTART, sa_restorer=0x7f29f1b55b70}, {sa_handler=SIG_DFL, sa_mask=[], sa_flags=0}, 8) = 0
> > openat(AT_FDCWD, "/var/lib/trace-cmd/virt/(null)/trace-pipe-cpu0.out", O_RDONLY|O_NONBLOCK) = -1 ENOENT (No such file or directory)
> > socket(AF_VSOCK, SOCK_STREAM, 0) = 4
> > connect(4, {sa_family=AF_VSOCK, sa_data="\0\0\270\"\0\0\3\0\0\0\0\0\0\0"}, 16) = 0
> > openat(AT_FDCWD, "/sys/kernel/debug/tracing/trace_clock", O_RDONLY) = 6
> > read(6, "local global counter uptime perf"..., 8192) = 62
> > read(6, "", 8192) = 0
> > close(6) = 0
> > write(4, "\0\0\0<\0\0\0\6\0\0\0\20\0\0\0\0\0\0\0\0\347\366+n\204\271\35\334", 28) = 28
> > write(4, "\0\0\0\0\0\0\0\v\0\0\0\2-e\0all\0\0\0\0\1\0\0\0\5ptp\0\0", 32) = 32
> > read(4, "", 12) = 0
> > dup(2) = 6
> > fcntl(6, F_GETFL) = 0x402 (flags O_RDWR|O_APPEND)
> > fstat(6, {st_mode=S_IFCHR|0620, st_rdev=makedev(0x88, 0x9), ...}) = 0
> > write(6, "trace-cmd: No such file or direc"..., 37trace-cmd: No such file or directory
> > ) = 37
> > close(6) = 0
> > write(2, " ", 2 ) = 2
> > write(2, "Failed to receive trace response"..., 37Failed to receive trace response -107) = 37
> > write(2, "\n", 1
> > ) = 1
> > exit_group(2) = ?
> > +++ exited with 2 +++
> >
> > Finally, if I use `--debug` both on the host and in the VM, here's what
> > I get.
> >
> > Guest:
> > # ./tracecmd/trace-cmd agent -p 8888 --debug
> > listening on @3:8888
> > msg received: 6 (TRACE_REQ) [60]
> > Segmentation fault
> >
> > Host:
> > # ./tracecmd/trace-cmd record --debug -p nop -e sched:* -e kvm:* -e timer:hrtimer* -A tumbleweed-jeos:8888 -e all sleep 1
> > msg send: 6 (TRACE_REQ) [60]
> > trace-cmd: No such file or directory
> > Failed to receive trace response -107
> >
> > Am I doing something wrong? :-)
> >
> > If necessary, I can provide more info about my setup, or do more tests.
>
> There are a few limitations that we are working to address:
> 1. Ensure that vhost_vsock module is loaded on the host.
> 2. You should add a vsock device manually to your VM config, I use
> "virsh edit <vm name>" to add:
> <vsock model='virtio'>
> <cid auto='yes'/>
> <address type='pci' domain='0x0000' bus='0x00' slot='0x09'
> function='0x0'/>
> </vsock>
> somewhere in the <devices> </devices> section.
>
Also, please note that there are two patches that should be applied also,
not part of v28 version of the patchset:
"trace-cmd: Fix plist allocation check in trace-msg.c"
https://patchwork.kernel.org/project/linux-trace-devel/patch/20210203165431.792152a4@gandalf.local.home/
"trace-cmd: Fix SEGFAULT when no tsync_protos are supplied"
https://patchwork.kernel.org/project/linux-trace-devel/patch/20210203171018.5b82a0a7@gandalf.local.home/
> >
> > Thanks and Regards
> > --
> > Dario Faggioli, Ph.D
> > http://about.me/dario.faggioli
> > Virtualization Software Engineer
> > SUSE Labs, SUSE https://www.suse.com/
> > -------------------------------------------------------------------
> > <<This happens because _I_ choose it to happen!>> (Raistlin Majere)
>
>
>
> --
> Tzvetomir (Ceco) Stoyanov
> VMware Open Source Technology Center
--
Tzvetomir (Ceco) Stoyanov
VMware Open Source Technology Center
^ permalink raw reply [flat|nested] 25+ messages in thread
* Re: [PATCH v28 0/8] Timestamp synchronization of host - guest tracing session
2021-02-09 6:03 ` Tzvetomir Stoyanov
2021-02-09 6:08 ` Tzvetomir Stoyanov
@ 2021-02-09 7:18 ` Dario Faggioli
1 sibling, 0 replies; 25+ messages in thread
From: Dario Faggioli @ 2021-02-09 7:18 UTC (permalink / raw)
To: Tzvetomir Stoyanov; +Cc: Steven Rostedt, Linux Trace Devel
[-- Attachment #1: Type: text/plain, Size: 1438 bytes --]
On Tue, 2021-02-09 at 08:03 +0200, Tzvetomir Stoyanov wrote:
> Hi Dario,
>
Hi!
> On Tue, Feb 9, 2021 at 7:32 AM Dario Faggioli <dfaggioli@suse.com>
> wrote:
> >
> > If necessary, I can provide more info about my setup, or do more
> > tests.
>
> There are a few limitations that we are working to address:
> 1. Ensure that vhost_vsock module is loaded on the host.
> 2. You should add a vsock device manually to your VM config, I use
> "virsh edit <vm name>" to add:
> <vsock model='virtio'>
> <cid auto='yes'/>
> <address type='pci' domain='0x0000' bus='0x00' slot='0x09'
> function='0x0'/>
> </vsock>
> somewhere in the <devices> </devices> section.
>
Yep, these are both fine. In fact, I tested host<-->guest communication
via vsock independently, and it works, so it does not seem a vsock
issue...
I also try without the series applied (but keeping patch 2) and it
still fails in the same way.
FTR, in the past, I've used trace-cmd from git with an earlier version
of this series applied (the "KVM clock" wasn't there yet) on the same
environment I'm using now, and it worked.
Regards
--
Dario Faggioli, Ph.D
http://about.me/dario.faggioli
Virtualization Software Engineer
SUSE Labs, SUSE https://www.suse.com/
-------------------------------------------------------------------
<<This happens because _I_ choose it to happen!>> (Raistlin Majere)
[-- Attachment #2: This is a digitally signed message part --]
[-- Type: application/pgp-signature, Size: 833 bytes --]
^ permalink raw reply [flat|nested] 25+ messages in thread
* Re: [PATCH v28 0/8] Timestamp synchronization of host - guest tracing session
2021-02-09 6:08 ` Tzvetomir Stoyanov
@ 2021-02-09 7:28 ` Dario Faggioli
2021-02-09 11:44 ` Tzvetomir Stoyanov
0 siblings, 1 reply; 25+ messages in thread
From: Dario Faggioli @ 2021-02-09 7:28 UTC (permalink / raw)
To: Tzvetomir Stoyanov; +Cc: Steven Rostedt, Linux Trace Devel
[-- Attachment #1: Type: text/plain, Size: 1095 bytes --]
On Tue, 2021-02-09 at 08:08 +0200, Tzvetomir Stoyanov wrote:
>
> Also, please note that there are two patches that should be applied
> also,
> not part of v28 version of the patchset:
>
Aha!
> "trace-cmd: Fix plist allocation check in trace-msg.c"
>
> https://patchwork.kernel.org/project/linux-trace-devel/patch/20210203165431.792152a4@gandalf.local.home/
> "trace-cmd: Fix SEGFAULT when no tsync_protos are supplied"
>
> https://patchwork.kernel.org/project/linux-trace-devel/patch/20210203171018.5b82a0a7@gandalf.local.home/
>
I just applied both, and it now seems that things work!
Or at least, host and guest talk, and I see this: "Negotiated kvm time
sync protocol with guest (null)" (is that "(null)" ok/intentional? I
guess I can check the code... :-))
Thanks a lot. :-)
--
Dario Faggioli, Ph.D
http://about.me/dario.faggioli
Virtualization Software Engineer
SUSE Labs, SUSE https://www.suse.com/
-------------------------------------------------------------------
<<This happens because _I_ choose it to happen!>> (Raistlin Majere)
[-- Attachment #2: This is a digitally signed message part --]
[-- Type: application/pgp-signature, Size: 833 bytes --]
^ permalink raw reply [flat|nested] 25+ messages in thread
* Re: [PATCH v28 0/8] Timestamp synchronization of host - guest tracing session
2021-02-09 7:28 ` Dario Faggioli
@ 2021-02-09 11:44 ` Tzvetomir Stoyanov
2021-02-09 12:24 ` Dario Faggioli
0 siblings, 1 reply; 25+ messages in thread
From: Tzvetomir Stoyanov @ 2021-02-09 11:44 UTC (permalink / raw)
To: Dario Faggioli; +Cc: Steven Rostedt, Linux Trace Devel
Hi Dario,
On Tue, Feb 9, 2021 at 9:28 AM Dario Faggioli <dfaggioli@suse.com> wrote:
>
> On Tue, 2021-02-09 at 08:08 +0200, Tzvetomir Stoyanov wrote:
> >
> > Also, please note that there are two patches that should be applied
> > also,
> > not part of v28 version of the patchset:
> >
> Aha!
>
> > "trace-cmd: Fix plist allocation check in trace-msg.c"
> >
> > https://patchwork.kernel.org/project/linux-trace-devel/patch/20210203165431.792152a4@gandalf.local.home/
> > "trace-cmd: Fix SEGFAULT when no tsync_protos are supplied"
> >
> > https://patchwork.kernel.org/project/linux-trace-devel/patch/20210203171018.5b82a0a7@gandalf.local.home/
> >
> I just applied both, and it now seems that things work!
>
> Or at least, host and guest talk, and I see this: "Negotiated kvm time
> sync protocol with guest (null)" (is that "(null)" ok/intentional? I
> guess I can check the code... :-))
That null looks like an error, the name of the guest VM should be printed there.
Thanks for testing these patches, I hope the code will be stabilized
and merged soon.
>
> Thanks a lot. :-)
> --
> Dario Faggioli, Ph.D
> http://about.me/dario.faggioli
> Virtualization Software Engineer
> SUSE Labs, SUSE https://www.suse.com/
> -------------------------------------------------------------------
> <<This happens because _I_ choose it to happen!>> (Raistlin Majere)
--
Tzvetomir (Ceco) Stoyanov
VMware Open Source Technology Center
^ permalink raw reply [flat|nested] 25+ messages in thread
* Re: [PATCH v28 0/8] Timestamp synchronization of host - guest tracing session
2021-02-09 11:44 ` Tzvetomir Stoyanov
@ 2021-02-09 12:24 ` Dario Faggioli
2021-02-09 13:00 ` Tzvetomir Stoyanov
2021-02-10 21:59 ` Steven Rostedt
0 siblings, 2 replies; 25+ messages in thread
From: Dario Faggioli @ 2021-02-09 12:24 UTC (permalink / raw)
To: Tzvetomir Stoyanov; +Cc: Steven Rostedt, Linux Trace Devel
[-- Attachment #1: Type: text/plain, Size: 7260 bytes --]
On Tue, 2021-02-09 at 13:44 +0200, Tzvetomir Stoyanov wrote:
> Hi Dario,
>
Hi again,
> On Tue, Feb 9, 2021 at 9:28 AM Dario Faggioli <dfaggioli@suse.com>
> wrote:
> >
> > Or at least, host and guest talk, and I see this: "Negotiated kvm
> > time
> > sync protocol with guest (null)" (is that "(null)" ok/intentional?
> > I
> > guess I can check the code... :-))
>
> That null looks like an error, the name of the guest VM should be
> printed there.
>
Yep, in fact, as I said, I tired this before and --now that I think
about it-- I do remember that the guest "name" was what was there.
BTW, if I can pester you a little bit more, now that it works I'm
trying to use this, and here's what I'm doing.
== VM:
# echo tsc > /sys/devices/system/clocksource/clocksource0/current_clocksource
# echo x86-tsc > /sys/kernel/tracing/trace_clock
# trace-cmd agent
== Host:
# echo x86-tsc > /sys/kernel/tracing/trace_clock
# trace-cmd record -p nop -e sched:* -e kvm:* -e timer:hrtimer* -A tumbleweed-jeos:823 -e sched:* -e syscalls:*_clock_nanosleep -e timer:hrtimer* sleep 1
And I do end up with the two files: trace.dat for the host and trace-
(null).dat (oh, well :-D) for the guest.
Now, just `trace-cmd report`-ing them, I get this (just some small
fragments, of course).
== Host (trace.dat):
<...>-24791 [001]308219686938467: sched_switch: prev_comm=sleep prev_pid=24791 prev_prio=120 prev_state=S ==> next_comm=swapper/1 next_pid=0 next_prio=120
<idle>-0 [001]308219691836595: hrtimer_cancel: hrtimer=0xffff96694faec710
<idle>-0 [001]308219691837544: hrtimer_expire_entry: hrtimer=0xffff96694faec710 function=apic_timer_fn now=76856318840891
<idle>-0 [001]308219691840271: sched_waking: comm=CPU 0/KVM pid=9196 prio=120 target_cpu=001
<idle>-0 [001]308219691849474: sched_wakeup: comm=CPU 0/KVM pid=9196 prio=120 target_cpu=001
<idle>-0 [001]308219691850914: hrtimer_expire_exit: hrtimer=0xffff96694faec710
<idle>-0 [001]308219691856548: sched_switch: prev_comm=swapper/1 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=CPU 0/KVM next_pid=9196 next_prio=120
CPU 0/KVM-9196 [001]308219691876512: kvm_vcpu_wakeup: wait time 2352265 ns, polling valid
CPU 0/KVM-9196 [001]308219691880170: kvm_apic_accept_irq: apicid 0 vec 236 (Fixed|edge)
CPU 0/KVM-9196 [001]308219691884210: kvm_pv_tlb_flush: vcpu 0 need_flush_tlb false
== Guest (trace-(null).dat):
<...>-12068 [000]118613084443085: sched_stat_runtime: comm=trace-cmd pid=12068 runtime=97403 [ns] vruntime=5101562006274 [ns]
<...>-12068 [000]118613084451479: sched_switch: prev_comm=trace-cmd prev_pid=12068 prev_prio=120 prev_state=S ==> next_comm=trace-cmd next_pid=12070 next_prio=120
<...>-12070 [000]118613084662730: sched_stat_runtime: comm=trace-cmd pid=12070 runtime=55912 [ns] vruntime=5101564964781 [ns]
<...>-12070 [000]118613084665219: sched_switch: prev_comm=trace-cmd prev_pid=12070 prev_prio=120 prev_state=S ==> next_comm=swapper/0 next_pid=0 next_prio=120
<idle>-0 [000]118613085002791: sched_waking: comm=kworker/0:0 pid=10458 prio=120 target_cpu=000
<idle>-0 [000]118613085006567: sched_wakeup: comm=kworker/0:0 pid=10458 prio=120 target_cpu=000
<idle>-0 [000]118613085011740: sched_switch: prev_comm=swapper/0 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=kworker/0:0 next_pid=10458 next_prio=120
kworker/0:0-10458 [000]118613085023034: sched_waking: comm=trace-cmd pid=12070 prio=120 target_cpu=000
kworker/0:0-10458 [000]118613085023774: sched_stat_runtime: comm=kworker/0:0 pid=10458 runtime=4848 [ns] vruntime=5101561969629 [ns]
kworker/0:0-10458 [000]118613085025356: sched_wakeup: comm=trace-cmd pid=12070 prio=120 target_cpu=000
So, the timestamps seems still a bit apart to me. Is this fine, and
hence there is some more post-processing that I should do (and, if yes,
what?). Or should they be already in sync?
I've also tried to open trace.dat in kernelshark2, and then append
trace-(null).dat but from the few that I see (as said in my other
email, kernelshark2 is not fully functional for me) the events from the
two traces are still completely separated.
I also tried with the following, but it's still the same:
# echo kvm-clock > /sys/devices/[...]/current_clocksource in the guest
Then, I've removed the last patch of the series, the one for "KVM
clock", after which, I was correctly (I think) seeing:
"Negotiated ptp time sync protocol with guest (null)"
But then again:
== Host:
CPU 0/KVM-9196 [001]249509851092735: kvm_exit: vcpu 0 reason PREEMPTION_TIMER rip 0x7f0da050b357 info1 0x0000000000000000 info2 0x0000000000000000 intr_info 0x00000000 error_code 0x00000000
CPU 0/KVM-9196 [001]249509851096316: kvm_apic_accept_irq: apicid 0 vec 236 (Fixed|edge)
CPU 0/KVM-9196 [001]249509851112525: kvm_exit: vcpu 0 reason MSR_WRITE rip 0xffffffffac475164 info1 0x0000000000000000 info2 0x0000000000000000 intr_info 0x00000000 error_code 0x00000000
CPU 0/KVM-9196 [001]249509851114034: kvm_hv_timer_state: vcpu_id 0 hv_timer 1
CPU 0/KVM-9196 [001]249509851115032: kvm_msr: msr_write 6e0 = 0x367b512478b0
sleep-26457 [000]249509851765258: sched_process_exec: filename=/usr/bin/sleep pid=26457 old_pid=26457
CPU 0/KVM-9196 [001]249509853247850: kvm_exit: vcpu 0 reason EXTERNAL_INTERRUPT rip 0xffffffffad00015d info1 0x0000000000000000 info2 0x0000000000000000 intr_info 0x800000ec error_code 0x00000000
CPU 0/KVM-9196 [001]249509853250399: hrtimer_cancel: hrtimer=0xffff96709fc61980
== Guest:
<...>-12891 [000]125778006088605: sched_stat_runtime: comm=trace-cmd pid=12891 runtime=84358 [ns] vruntime=5110265291610 [ns]
<...>-12891 [000]125778006095698: sched_switch: prev_comm=trace-cmd prev_pid=12891 prev_prio=120 prev_state=S ==> next_comm=trace-cmd next_pid=12893 next_prio=120
<...>-12893 [000]125778006320003: sched_stat_runtime: comm=trace-cmd pid=12893 runtime=58448 [ns] vruntime=5110268246764 [ns]
<...>-12893 [000]125778006322729: sched_switch: prev_comm=trace-cmd prev_pid=12893 prev_prio=120 prev_state=S ==> next_comm=swapper/0 next_pid=0 next_prio=120
<idle>-0 [000]125778021774505: hrtimer_cancel: hrtimer=0xffff99d67bc21980
<idle>-0 [000]125778021776481: hrtimer_expire_entry: hrtimer=0xffff99d67bc21980 function=tick_sched_timer now=31370890644808
<idle>-0 [000]125778021782895: hrtimer_expire_exit: hrtimer=0xffff99d67bc21980
So, what am I missing? :-)
And, of course, thanks a lot again!
--
Dario Faggioli, Ph.D
http://about.me/dario.faggioli
Virtualization Software Engineer
SUSE Labs, SUSE https://www.suse.com/
-------------------------------------------------------------------
<<This happens because _I_ choose it to happen!>> (Raistlin Majere)
[-- Attachment #2: This is a digitally signed message part --]
[-- Type: application/pgp-signature, Size: 833 bytes --]
^ permalink raw reply [flat|nested] 25+ messages in thread
* Re: [PATCH v28 0/8] Timestamp synchronization of host - guest tracing session
2021-02-09 12:24 ` Dario Faggioli
@ 2021-02-09 13:00 ` Tzvetomir Stoyanov
2021-02-09 15:28 ` Dario Faggioli
2021-02-10 21:59 ` Steven Rostedt
1 sibling, 1 reply; 25+ messages in thread
From: Tzvetomir Stoyanov @ 2021-02-09 13:00 UTC (permalink / raw)
To: Dario Faggioli; +Cc: Steven Rostedt, Linux Trace Devel
On Tue, Feb 9, 2021 at 2:24 PM Dario Faggioli <dfaggioli@suse.com> wrote:
>
> On Tue, 2021-02-09 at 13:44 +0200, Tzvetomir Stoyanov wrote:
> > Hi Dario,
> >
> Hi again,
>
> > On Tue, Feb 9, 2021 at 9:28 AM Dario Faggioli <dfaggioli@suse.com>
> > wrote:
> > >
> > > Or at least, host and guest talk, and I see this: "Negotiated kvm
> > > time
> > > sync protocol with guest (null)" (is that "(null)" ok/intentional?
> > > I
> > > guess I can check the code... :-))
> >
> > That null looks like an error, the name of the guest VM should be
> > printed there.
> >
> Yep, in fact, as I said, I tired this before and --now that I think
> about it-- I do remember that the guest "name" was what was there.
>
> BTW, if I can pester you a little bit more, now that it works I'm
> trying to use this, and here's what I'm doing.
>
> == VM:
> # echo tsc > /sys/devices/system/clocksource/clocksource0/current_clocksource
> # echo x86-tsc > /sys/kernel/tracing/trace_clock
> # trace-cmd agent
>
> == Host:
> # echo x86-tsc > /sys/kernel/tracing/trace_clock
> # trace-cmd record -p nop -e sched:* -e kvm:* -e timer:hrtimer* -A tumbleweed-jeos:823 -e sched:* -e syscalls:*_clock_nanosleep -e timer:hrtimer* sleep 1
>
> And I do end up with the two files: trace.dat for the host and trace-
> (null).dat (oh, well :-D) for the guest.
>
> Now, just `trace-cmd report`-ing them, I get this (just some small
> fragments, of course).
>
> == Host (trace.dat):
> <...>-24791 [001]308219686938467: sched_switch: prev_comm=sleep prev_pid=24791 prev_prio=120 prev_state=S ==> next_comm=swapper/1 next_pid=0 next_prio=120
> <idle>-0 [001]308219691836595: hrtimer_cancel: hrtimer=0xffff96694faec710
> <idle>-0 [001]308219691837544: hrtimer_expire_entry: hrtimer=0xffff96694faec710 function=apic_timer_fn now=76856318840891
> <idle>-0 [001]308219691840271: sched_waking: comm=CPU 0/KVM pid=9196 prio=120 target_cpu=001
> <idle>-0 [001]308219691849474: sched_wakeup: comm=CPU 0/KVM pid=9196 prio=120 target_cpu=001
> <idle>-0 [001]308219691850914: hrtimer_expire_exit: hrtimer=0xffff96694faec710
> <idle>-0 [001]308219691856548: sched_switch: prev_comm=swapper/1 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=CPU 0/KVM next_pid=9196 next_prio=120
> CPU 0/KVM-9196 [001]308219691876512: kvm_vcpu_wakeup: wait time 2352265 ns, polling valid
> CPU 0/KVM-9196 [001]308219691880170: kvm_apic_accept_irq: apicid 0 vec 236 (Fixed|edge)
> CPU 0/KVM-9196 [001]308219691884210: kvm_pv_tlb_flush: vcpu 0 need_flush_tlb false
>
>
> == Guest (trace-(null).dat):
> <...>-12068 [000]118613084443085: sched_stat_runtime: comm=trace-cmd pid=12068 runtime=97403 [ns] vruntime=5101562006274 [ns]
> <...>-12068 [000]118613084451479: sched_switch: prev_comm=trace-cmd prev_pid=12068 prev_prio=120 prev_state=S ==> next_comm=trace-cmd next_pid=12070 next_prio=120
> <...>-12070 [000]118613084662730: sched_stat_runtime: comm=trace-cmd pid=12070 runtime=55912 [ns] vruntime=5101564964781 [ns]
> <...>-12070 [000]118613084665219: sched_switch: prev_comm=trace-cmd prev_pid=12070 prev_prio=120 prev_state=S ==> next_comm=swapper/0 next_pid=0 next_prio=120
> <idle>-0 [000]118613085002791: sched_waking: comm=kworker/0:0 pid=10458 prio=120 target_cpu=000
> <idle>-0 [000]118613085006567: sched_wakeup: comm=kworker/0:0 pid=10458 prio=120 target_cpu=000
> <idle>-0 [000]118613085011740: sched_switch: prev_comm=swapper/0 prev_pid=0 prev_prio=120 prev_state=R ==> next_comm=kworker/0:0 next_pid=10458 next_prio=120
> kworker/0:0-10458 [000]118613085023034: sched_waking: comm=trace-cmd pid=12070 prio=120 target_cpu=000
> kworker/0:0-10458 [000]118613085023774: sched_stat_runtime: comm=kworker/0:0 pid=10458 runtime=4848 [ns] vruntime=5101561969629 [ns]
> kworker/0:0-10458 [000]118613085025356: sched_wakeup: comm=trace-cmd pid=12070 prio=120 target_cpu=000
>
> So, the timestamps seems still a bit apart to me. Is this fine, and
> hence there is some more post-processing that I should do (and, if yes,
> what?). Or should they be already in sync?
The timestamps, recorded in both files are not synchronised. That's
why you are seeing the original timestamps. The offsets between both
clocks are recorded in the metadata of the guest trace file. You can verify
this using "trace-cmd dump --options trace-guest.dat" and
"trace-cmd dump --options trace.dat"
When both files are opened together, then that metadata is used to align
guest's timestamps to the host time. Currently trace-cmd report does not
have support for opening more trace files as a session, yet. This is in our
short todo list.
>
> I've also tried to open trace.dat in kernelshark2, and then append
> trace-(null).dat but from the few that I see (as said in my other
> email, kernelshark2 is not fully functional for me) the events from the
> two traces are still completely separated.
Currently using KernelShark2-beta is the only way to display host and
guests tracing files, as a session. There is logic for synchronising timestamps,
using metadata from the files. What repo are you using for getting the
KernelShark2-beta ?
Yordan can give more details on that.
>
> I also tried with the following, but it's still the same:
> # echo kvm-clock > /sys/devices/[...]/current_clocksource in the guest
>
> Then, I've removed the last patch of the series, the one for "KVM
> clock", after which, I was correctly (I think) seeing:
>
> "Negotiated ptp time sync protocol with guest (null)"
That "null" really bothers me, as I cannot reproduce it. The logic for
getting the
guest name, cid and port uses "/proc/<qemu pid>/cmdline". Please, can you send
me that string, from /proc/... or just "ps afx | grep qemu", to see
what is wrong with
our parsing logic.
Also, if you have any ideas how to get name, cid and port of running
libvirt VMs -
please share. The current approach parsing the qemu command line is a work
around, not a final solution.
Thanks!
>
> But then again:
>
> == Host:
> CPU 0/KVM-9196 [001]249509851092735: kvm_exit: vcpu 0 reason PREEMPTION_TIMER rip 0x7f0da050b357 info1 0x0000000000000000 info2 0x0000000000000000 intr_info 0x00000000 error_code 0x00000000
> CPU 0/KVM-9196 [001]249509851096316: kvm_apic_accept_irq: apicid 0 vec 236 (Fixed|edge)
> CPU 0/KVM-9196 [001]249509851112525: kvm_exit: vcpu 0 reason MSR_WRITE rip 0xffffffffac475164 info1 0x0000000000000000 info2 0x0000000000000000 intr_info 0x00000000 error_code 0x00000000
> CPU 0/KVM-9196 [001]249509851114034: kvm_hv_timer_state: vcpu_id 0 hv_timer 1
> CPU 0/KVM-9196 [001]249509851115032: kvm_msr: msr_write 6e0 = 0x367b512478b0
> sleep-26457 [000]249509851765258: sched_process_exec: filename=/usr/bin/sleep pid=26457 old_pid=26457
> CPU 0/KVM-9196 [001]249509853247850: kvm_exit: vcpu 0 reason EXTERNAL_INTERRUPT rip 0xffffffffad00015d info1 0x0000000000000000 info2 0x0000000000000000 intr_info 0x800000ec error_code 0x00000000
> CPU 0/KVM-9196 [001]249509853250399: hrtimer_cancel: hrtimer=0xffff96709fc61980
>
> == Guest:
> <...>-12891 [000]125778006088605: sched_stat_runtime: comm=trace-cmd pid=12891 runtime=84358 [ns] vruntime=5110265291610 [ns]
> <...>-12891 [000]125778006095698: sched_switch: prev_comm=trace-cmd prev_pid=12891 prev_prio=120 prev_state=S ==> next_comm=trace-cmd next_pid=12893 next_prio=120
> <...>-12893 [000]125778006320003: sched_stat_runtime: comm=trace-cmd pid=12893 runtime=58448 [ns] vruntime=5110268246764 [ns]
> <...>-12893 [000]125778006322729: sched_switch: prev_comm=trace-cmd prev_pid=12893 prev_prio=120 prev_state=S ==> next_comm=swapper/0 next_pid=0 next_prio=120
> <idle>-0 [000]125778021774505: hrtimer_cancel: hrtimer=0xffff99d67bc21980
> <idle>-0 [000]125778021776481: hrtimer_expire_entry: hrtimer=0xffff99d67bc21980 function=tick_sched_timer now=31370890644808
> <idle>-0 [000]125778021782895: hrtimer_expire_exit: hrtimer=0xffff99d67bc21980
>
> So, what am I missing? :-)
>
> And, of course, thanks a lot again!
> --
> Dario Faggioli, Ph.D
> http://about.me/dario.faggioli
> Virtualization Software Engineer
> SUSE Labs, SUSE https://www.suse.com/
> -------------------------------------------------------------------
> <<This happens because _I_ choose it to happen!>> (Raistlin Majere)
--
Tzvetomir (Ceco) Stoyanov
VMware Open Source Technology Center
^ permalink raw reply [flat|nested] 25+ messages in thread
* Re: [PATCH v28 0/8] Timestamp synchronization of host - guest tracing session
2021-02-09 13:00 ` Tzvetomir Stoyanov
@ 2021-02-09 15:28 ` Dario Faggioli
2021-02-09 17:01 ` Tzvetomir Stoyanov
0 siblings, 1 reply; 25+ messages in thread
From: Dario Faggioli @ 2021-02-09 15:28 UTC (permalink / raw)
To: Tzvetomir Stoyanov; +Cc: Steven Rostedt, Linux Trace Devel
[-- Attachment #1: Type: text/plain, Size: 9935 bytes --]
On Tue, 2021-02-09 at 15:00 +0200, Tzvetomir Stoyanov wrote:
> On Tue, Feb 9, 2021 at 2:24 PM Dario Faggioli <dfaggioli@suse.com>
> wrote:
> >
> > So, the timestamps seems still a bit apart to me. Is this fine, and
> > hence there is some more post-processing that I should do (and, if
> > yes,
> > what?). Or should they be already in sync?
>
> The timestamps, recorded in both files are not synchronised. That's
> why you are seeing the original timestamps. The offsets between both
> clocks are recorded in the metadata of the guest trace file.
>
Ah, sure! So I was right about me being missing something: I was
missing this. :-)
> You can verify
> this using "trace-cmd dump --options trace-guest.dat" and
> "trace-cmd dump --options trace.dat"
> When both files are opened together, then that metadata is used to
> align
> guest's timestamps to the host time.
>
Right.
> Currently trace-cmd report does not
> have support for opening more trace files as a session, yet. This is
> in our
> short todo list.
>
Ok, is there a WiP already, or someone working on it? I'm asking
because maybe I can help.
In fact, I am helping some University students with their theses, and
I'm planning to have them doing something in the area of virtualization
tracing. In fact, I will have quite a few other questions in the
upcoming days (hoping you guys don't mind)... But, IAC, something like
this could be a place from where to start.
>
> Currently using KernelShark2-beta is the only way to display host and
> guests tracing files, as a session. There is logic for synchronising
> timestamps,
> using metadata from the files. What repo are you using for getting
> the
> KernelShark2-beta ?
> Yordan can give more details on that.
>
Yes, I was already using the right repo (https://github.com/yordan-
karadzhov/kernel-shark-v2.beta ) but missed a rebase/update. And in
fact, Yordan pointed me to it, and know things are a lot better (still
not perfect, but that's for the other thread).
> > "Negotiated ptp time sync protocol with guest (null)"
>
> That "null" really bothers me, as I cannot reproduce it. The logic
> for
> getting the
> guest name, cid and port uses "/proc/<qemu pid>/cmdline". Please, can
> you send
> me that string, from /proc/...
>
Sure. Brace yourself, though. It's a qemu command line, and you know
that qemu command line are, well, a bit long ;-P
/usr/bin/qemu-system-x86_64-nameguest=tumbleweed-jeos,debug-threads=on-
S-
objectsecret,id=masterKey0,format=raw,file=/var/lib/libvirt/qemu/domain
-1-tumbleweed-jeos/master-key.aes-machinepc-q35-
5.2,accel=kvm,usb=off,dump-guest-core=off,memory-backend=pc.ram-
cpuSkylake-Server-IBRS,ss=on,vmx=on,pdcm=on,hypervisor=on,tsc-
adjust=on,clflushopt=on,umip=on,md-clear=on,stibp=on,arch-
capabilities=on,ssbd=on,xsaves=on,ibpb=on,amd-stibp=on,amd-
ssbd=on,pschange-mc-no=on,pku=off-m4096-objectmemory-backend-
ram,id=pc.ram,size=4294967296-overcommitmem-lock=off-
smp1,sockets=1,cores=1,threads=1-uuid57a61f7b-506e-49d8-a8d7-
63b5baae8534-no-user-config-nodefaults-
chardevsocket,id=charmonitor,fd=29,server,nowait-
monchardev=charmonitor,id=monitor,mode=control-
rtcbase=utc,driftfix=slew-globalkvm-pit.lost_tick_policy=delay-no-hpet-
no-shutdown-globalICH9-LPC.disable_s3=1-globalICH9-LPC.disable_s4=1-
bootstrict=on-devicepcie-root-
port,port=0x10,chassis=1,id=pci.1,bus=pcie.0,multifunction=on,addr=0x2-
devicepcie-root-
port,port=0x11,chassis=2,id=pci.2,bus=pcie.0,addr=0x2.0x1-devicepcie-
root-port,port=0x12,chassis=3,id=pci.3,bus=pcie.0,addr=0x2.0x2-
devicepcie-root-
port,port=0x13,chassis=4,id=pci.4,bus=pcie.0,addr=0x2.0x3-devicepcie-
root-port,port=0x14,chassis=5,id=pci.5,bus=pcie.0,addr=0x2.0x4-
devicepcie-root-
port,port=0x15,chassis=6,id=pci.6,bus=pcie.0,addr=0x2.0x5-devicepcie-
root-port,port=0x16,chassis=7,id=pci.7,bus=pcie.0,addr=0x2.0x6-
deviceqemu-xhci,p2=15,p3=15,id=usb,bus=pci.2,addr=0x0-devicevirtio-
serial-pci,id=virtio-serial0,bus=pci.3,addr=0x0-
blockdev{"driver":"file","filename":"/var/lib/libvirt/images/openSUSE-
Tumbleweed-JeOS.x86_64-15.1.0-kvm-and-xen-
Snapshot20210205.qcow2","node-name":"libvirt-1-storage","auto-read-
only":true,"discard":"unmap"}-blockdev{"node-name":"libvirt-1-
format","read-only":false,"driver":"qcow2","file":"libvirt-1-
storage","backing":null}-devicevirtio-blk-
pci,bus=pci.4,addr=0x0,drive=libvirt-1-format,id=virtio-
disk0,bootindex=1-netdevtap,fd=31,id=hostnet0,vhost=on,vhostfd=32-
devicevirtio-net-
pci,netdev=hostnet0,id=net0,mac=52:54:00:77:d6:ea,bus=pci.1,addr=0x0-
chardevpty,id=charserial0-deviceisa-
serial,chardev=charserial0,id=serial0-
chardevsocket,id=charchannel0,fd=33,server,nowait-
devicevirtserialport,bus=virtio-
serial0.0,nr=1,chardev=charchannel0,id=channel0,name=org.qemu.guest_age
nt.0-deviceusb-tablet,id=input0,bus=usb.0,port=1-
spiceport=5900,addr=0.0.0.0,disable-ticketing,seamless-migration=on-
deviceqxl-
vga,id=video0,ram_size=67108864,vram_size=67108864,vram64_size_mb=0,vga
mem_mb=16,max_outputs=1,bus=pcie.0,addr=0x1-devicevirtio-balloon-
pci,id=balloon0,bus=pci.5,addr=0x0-objectrng-
random,id=objrng0,filename=/dev/urandom-devicevirtio-rng-
pci,rng=objrng0,id=rng0,bus=pci.6,addr=0x0-
sandboxon,obsolete=deny,elevateprivileges=deny,spawn=deny,resourcecontr
ol=deny-devicevhost-vsock-pci,id=vsock0,guest-
cid=3,vhostfd=26,bus=pci.7,addr=0x0-msgtimestamp=ontoolbox-dario
> or just "ps afx | grep qemu",
>
Also a mess. But here you go:
# ps afx | grep qemu
12952 ? S 0:00 | | \_ ssh -l root -T -e none --
192.168.0.31 sh -c 'which virt-ssh-helper 1>/dev/null 2>&1; if test $?
= 0; then virt-ssh-helper 'qemu:///system'; else if 'nc' -q 2>&1
| grep "requires an argument" >/dev/null 2>&1; then ARG=-q0;else
ARG=;fi;'nc' $ARG -U /var/run/libvirt/libvirt-sock; fi'
8758 pts/9 S+ 0:00 | | | \_ grep --
color=auto qemu
9168 ? Sl 224:55 | \_ /usr/bin/qemu-system-x86_64 -name
guest=tumbleweed-jeos,debug-threads=on -S -object
secret,id=masterKey0,format=raw,file=/var/lib/libvirt/qemu/domain-1-
tumbleweed-jeos/master-key.aes -machine pc-q35-
5.2,accel=kvm,usb=off,dump-guest-core=off,memory-backend=pc.ram -cpu
Skylake-Server-IBRS,ss=on,vmx=on,pdcm=on,hypervisor=on,tsc-
adjust=on,clflushopt=on,umip=on,md-clear=on,stibp=on,arch-
capabilities=on,ssbd=on,xsaves=on,ibpb=on,amd-stibp=on,amd-
ssbd=on,pschange-mc-no=on,pku=off -m 4096 -object memory-backend-
ram,id=pc.ram,size=4294967296 -overcommit mem-lock=off -smp
1,sockets=1,cores=1,threads=1 -uuid 57a61f7b-506e-49d8-a8d7-
63b5baae8534 -no-user-config -nodefaults -chardev
socket,id=charmonitor,fd=29,server,nowait -mon
chardev=charmonitor,id=monitor,mode=control -rtc base=utc,driftfix=slew
-global kvm-pit.lost_tick_policy=delay -no-hpet -no-shutdown -global
ICH9-LPC.disable_s3=1 -global ICH9-LPC.disable_s4=1 -boot strict=on -
device pcie-root-
port,port=0x10,chassis=1,id=pci.1,bus=pcie.0,multifunction=on,addr=0x2
-device pcie-root-
port,port=0x11,chassis=2,id=pci.2,bus=pcie.0,addr=0x2.0x1 -device pcie-
root-port,port=0x12,chassis=3,id=pci.3,bus=pcie.0,addr=0x2.0x2 -device
pcie-root-port,port=0x13,chassis=4,id=pci.4,bus=pcie.0,addr=0x2.0x3 -
device pcie-root-
port,port=0x14,chassis=5,id=pci.5,bus=pcie.0,addr=0x2.0x4 -device pcie-
root-port,port=0x15,chassis=6,id=pci.6,bus=pcie.0,addr=0x2.0x5 -device
pcie-root-port,port=0x16,chassis=7,id=pci.7,bus=pcie.0,addr=0x2.0x6 -
device qemu-xhci,p2=15,p3=15,id=usb,bus=pci.2,addr=0x0 -device virtio-
serial-pci,id=virtio-serial0,bus=pci.3,addr=0x0 -blockdev
{"driver":"file","filename":"/var/lib/libvirt/images/openSUSE-
Tumbleweed-JeOS.x86_64-15.1.0-kvm-and-xen-
Snapshot20210205.qcow2","node-name":"libvirt-1-storage","auto-read-
only":true,"discard":"unmap"} -blockdev {"node-name":"libvirt-1-
format","read-only":false,"driver":"qcow2","file":"libvirt-1-
storage","backing":null} -device virtio-blk-
pci,bus=pci.4,addr=0x0,drive=libvirt-1-format,id=virtio-
disk0,bootindex=1 -netdev tap,fd=31,id=hostnet0,vhost=on,vhostfd=32 -
device virtio-net-
pci,netdev=hostnet0,id=net0,mac=52:54:00:77:d6:ea,bus=pci.1,addr=0x0 -
chardev pty,id=charserial0 -device isa-
serial,chardev=charserial0,id=serial0 -chardev
socket,id=charchannel0,fd=33,server,nowait -device
virtserialport,bus=virtio-
serial0.0,nr=1,chardev=charchannel0,id=channel0,name=org.qemu.guest_age
nt.0 -device usb-tablet,id=input0,bus=usb.0,port=1 -spice
port=5900,addr=0.0.0.0,disable-ticketing,seamless-migration=on -device
qxl-
vga,id=video0,ram_size=67108864,vram_size=67108864,vram64_size_mb=0,vga
mem_mb=16,max_outputs=1,bus=pcie.0,addr=0x1 -device virtio-balloon-
pci,id=balloon0,bus=pci.5,addr=0x0 -object rng-
random,id=objrng0,filename=/dev/urandom -device virtio-rng-
pci,rng=objrng0,id=rng0,bus=pci.6,addr=0x0 -sandbox
on,obsolete=deny,elevateprivileges=deny,spawn=deny,resourcecontrol=deny
-device vhost-vsock-pci,id=vsock0,guest-
cid=3,vhostfd=26,bus=pci.7,addr=0x0 -msg timestamp=on
It's a bit of an unusual setup, as the VM (and hence QEMU too) is
running inside a podman container. But it seems the info you're after
is indeed present on the commandline.
> to see
> what is wrong with
> our parsing logic.
> Also, if you have any ideas how to get name, cid and port of running
> libvirt VMs -
> please share. The current approach parsing the qemu command line is a
> work
> around, not a final solution.
>
Mmm... not sure. I'll have a look at the code where you go and fetch
it, and see if anything comes to mind.
Thanks and Regards
--
Dario Faggioli, Ph.D
http://about.me/dario.faggioli
Virtualization Software Engineer
SUSE Labs, SUSE https://www.suse.com/
-------------------------------------------------------------------
<<This happens because _I_ choose it to happen!>> (Raistlin Majere)
[-- Attachment #2: This is a digitally signed message part --]
[-- Type: application/pgp-signature, Size: 833 bytes --]
^ permalink raw reply [flat|nested] 25+ messages in thread
* Re: [PATCH v28 0/8] Timestamp synchronization of host - guest tracing session
2021-02-09 15:28 ` Dario Faggioli
@ 2021-02-09 17:01 ` Tzvetomir Stoyanov
2021-02-10 22:02 ` Steven Rostedt
0 siblings, 1 reply; 25+ messages in thread
From: Tzvetomir Stoyanov @ 2021-02-09 17:01 UTC (permalink / raw)
To: Dario Faggioli; +Cc: Steven Rostedt, Linux Trace Devel
On Tue, Feb 9, 2021 at 5:28 PM Dario Faggioli <dfaggioli@suse.com> wrote:
>
> On Tue, 2021-02-09 at 15:00 +0200, Tzvetomir Stoyanov wrote:
> > On Tue, Feb 9, 2021 at 2:24 PM Dario Faggioli <dfaggioli@suse.com>
> > wrote:
> > >
> > > So, the timestamps seems still a bit apart to me. Is this fine, and
> > > hence there is some more post-processing that I should do (and, if
> > > yes,
> > > what?). Or should they be already in sync?
> >
> > The timestamps, recorded in both files are not synchronised. That's
> > why you are seeing the original timestamps. The offsets between both
> > clocks are recorded in the metadata of the guest trace file.
> >
> Ah, sure! So I was right about me being missing something: I was
> missing this. :-)
>
> > You can verify
> > this using "trace-cmd dump --options trace-guest.dat" and
> > "trace-cmd dump --options trace.dat"
> > When both files are opened together, then that metadata is used to
> > align
> > guest's timestamps to the host time.
> >
> Right.
>
> > Currently trace-cmd report does not
> > have support for opening more trace files as a session, yet. This is
> > in our
> > short todo list.
> >
> Ok, is there a WiP already, or someone working on it? I'm asking
> because maybe I can help.
None is working on that yet, any help is highly appreciated :) I just
created an issue in Bugzilla for that:
https://bugzilla.kernel.org/show_bug.cgi?id=211657
>
> In fact, I am helping some University students with their theses, and
> I'm planning to have them doing something in the area of virtualization
> tracing. In fact, I will have quite a few other questions in the
> upcoming days (hoping you guys don't mind)... But, IAC, something like
> this could be a place from where to start.
>
> >
> > Currently using KernelShark2-beta is the only way to display host and
> > guests tracing files, as a session. There is logic for synchronising
> > timestamps,
> > using metadata from the files. What repo are you using for getting
> > the
> > KernelShark2-beta ?
> > Yordan can give more details on that.
> >
> Yes, I was already using the right repo (https://github.com/yordan-
> karadzhov/kernel-shark-v2.beta ) but missed a rebase/update. And in
> fact, Yordan pointed me to it, and know things are a lot better (still
> not perfect, but that's for the other thread).
>
> > > "Negotiated ptp time sync protocol with guest (null)"
> >
> > That "null" really bothers me, as I cannot reproduce it. The logic
> > for
> > getting the
> > guest name, cid and port uses "/proc/<qemu pid>/cmdline". Please, can
> > you send
> > me that string, from /proc/...
> >
> Sure. Brace yourself, though. It's a qemu command line, and you know
> that qemu command line are, well, a bit long ;-P
>
> /usr/bin/qemu-system-x86_64-nameguest=tumbleweed-jeos,debug-threads=on-
That "-nameguest=tumbleweed-jeos" is the thing that we are looking for
while trying
to figure out the name of the quest, but looks like we should improve
our parser or
better find a more reliable way for getting that information.
> S-
> objectsecret,id=masterKey0,format=raw,file=/var/lib/libvirt/qemu/domain
> -1-tumbleweed-jeos/master-key.aes-machinepc-q35-
> 5.2,accel=kvm,usb=off,dump-guest-core=off,memory-backend=pc.ram-
> cpuSkylake-Server-IBRS,ss=on,vmx=on,pdcm=on,hypervisor=on,tsc-
> adjust=on,clflushopt=on,umip=on,md-clear=on,stibp=on,arch-
> capabilities=on,ssbd=on,xsaves=on,ibpb=on,amd-stibp=on,amd-
> ssbd=on,pschange-mc-no=on,pku=off-m4096-objectmemory-backend-
> ram,id=pc.ram,size=4294967296-overcommitmem-lock=off-
> smp1,sockets=1,cores=1,threads=1-uuid57a61f7b-506e-49d8-a8d7-
> 63b5baae8534-no-user-config-nodefaults-
> chardevsocket,id=charmonitor,fd=29,server,nowait-
> monchardev=charmonitor,id=monitor,mode=control-
> rtcbase=utc,driftfix=slew-globalkvm-pit.lost_tick_policy=delay-no-hpet-
> no-shutdown-globalICH9-LPC.disable_s3=1-globalICH9-LPC.disable_s4=1-
> bootstrict=on-devicepcie-root-
> port,port=0x10,chassis=1,id=pci.1,bus=pcie.0,multifunction=on,addr=0x2-
> devicepcie-root-
> port,port=0x11,chassis=2,id=pci.2,bus=pcie.0,addr=0x2.0x1-devicepcie-
> root-port,port=0x12,chassis=3,id=pci.3,bus=pcie.0,addr=0x2.0x2-
> devicepcie-root-
> port,port=0x13,chassis=4,id=pci.4,bus=pcie.0,addr=0x2.0x3-devicepcie-
> root-port,port=0x14,chassis=5,id=pci.5,bus=pcie.0,addr=0x2.0x4-
> devicepcie-root-
> port,port=0x15,chassis=6,id=pci.6,bus=pcie.0,addr=0x2.0x5-devicepcie-
> root-port,port=0x16,chassis=7,id=pci.7,bus=pcie.0,addr=0x2.0x6-
> deviceqemu-xhci,p2=15,p3=15,id=usb,bus=pci.2,addr=0x0-devicevirtio-
> serial-pci,id=virtio-serial0,bus=pci.3,addr=0x0-
> blockdev{"driver":"file","filename":"/var/lib/libvirt/images/openSUSE-
> Tumbleweed-JeOS.x86_64-15.1.0-kvm-and-xen-
> Snapshot20210205.qcow2","node-name":"libvirt-1-storage","auto-read-
> only":true,"discard":"unmap"}-blockdev{"node-name":"libvirt-1-
> format","read-only":false,"driver":"qcow2","file":"libvirt-1-
> storage","backing":null}-devicevirtio-blk-
> pci,bus=pci.4,addr=0x0,drive=libvirt-1-format,id=virtio-
> disk0,bootindex=1-netdevtap,fd=31,id=hostnet0,vhost=on,vhostfd=32-
> devicevirtio-net-
> pci,netdev=hostnet0,id=net0,mac=52:54:00:77:d6:ea,bus=pci.1,addr=0x0-
> chardevpty,id=charserial0-deviceisa-
> serial,chardev=charserial0,id=serial0-
> chardevsocket,id=charchannel0,fd=33,server,nowait-
> devicevirtserialport,bus=virtio-
> serial0.0,nr=1,chardev=charchannel0,id=channel0,name=org.qemu.guest_age
> nt.0-deviceusb-tablet,id=input0,bus=usb.0,port=1-
> spiceport=5900,addr=0.0.0.0,disable-ticketing,seamless-migration=on-
> deviceqxl-
> vga,id=video0,ram_size=67108864,vram_size=67108864,vram64_size_mb=0,vga
> mem_mb=16,max_outputs=1,bus=pcie.0,addr=0x1-devicevirtio-balloon-
> pci,id=balloon0,bus=pci.5,addr=0x0-objectrng-
> random,id=objrng0,filename=/dev/urandom-devicevirtio-rng-
> pci,rng=objrng0,id=rng0,bus=pci.6,addr=0x0-
> sandboxon,obsolete=deny,elevateprivileges=deny,spawn=deny,resourcecontr
> ol=deny-devicevhost-vsock-pci,id=vsock0,guest-
> cid=3,vhostfd=26,bus=pci.7,addr=0x0-msgtimestamp=ontoolbox-dario
>
> > or just "ps afx | grep qemu",
> >
> Also a mess. But here you go:
>
> # ps afx | grep qemu
> 12952 ? S 0:00 | | \_ ssh -l root -T -e none --
> 192.168.0.31 sh -c 'which virt-ssh-helper 1>/dev/null 2>&1; if test $?
> = 0; then virt-ssh-helper 'qemu:///system'; else if 'nc' -q 2>&1
> | grep "requires an argument" >/dev/null 2>&1; then ARG=-q0;else
> ARG=;fi;'nc' $ARG -U /var/run/libvirt/libvirt-sock; fi'
> 8758 pts/9 S+ 0:00 | | | \_ grep --
> color=auto qemu
> 9168 ? Sl 224:55 | \_ /usr/bin/qemu-system-x86_64 -name
> guest=tumbleweed-jeos,debug-threads=on -S -object
> secret,id=masterKey0,format=raw,file=/var/lib/libvirt/qemu/domain-1-
> tumbleweed-jeos/master-key.aes -machine pc-q35-
> 5.2,accel=kvm,usb=off,dump-guest-core=off,memory-backend=pc.ram -cpu
> Skylake-Server-IBRS,ss=on,vmx=on,pdcm=on,hypervisor=on,tsc-
> adjust=on,clflushopt=on,umip=on,md-clear=on,stibp=on,arch-
> capabilities=on,ssbd=on,xsaves=on,ibpb=on,amd-stibp=on,amd-
> ssbd=on,pschange-mc-no=on,pku=off -m 4096 -object memory-backend-
> ram,id=pc.ram,size=4294967296 -overcommit mem-lock=off -smp
> 1,sockets=1,cores=1,threads=1 -uuid 57a61f7b-506e-49d8-a8d7-
> 63b5baae8534 -no-user-config -nodefaults -chardev
> socket,id=charmonitor,fd=29,server,nowait -mon
> chardev=charmonitor,id=monitor,mode=control -rtc base=utc,driftfix=slew
> -global kvm-pit.lost_tick_policy=delay -no-hpet -no-shutdown -global
> ICH9-LPC.disable_s3=1 -global ICH9-LPC.disable_s4=1 -boot strict=on -
> device pcie-root-
> port,port=0x10,chassis=1,id=pci.1,bus=pcie.0,multifunction=on,addr=0x2
> -device pcie-root-
> port,port=0x11,chassis=2,id=pci.2,bus=pcie.0,addr=0x2.0x1 -device pcie-
> root-port,port=0x12,chassis=3,id=pci.3,bus=pcie.0,addr=0x2.0x2 -device
> pcie-root-port,port=0x13,chassis=4,id=pci.4,bus=pcie.0,addr=0x2.0x3 -
> device pcie-root-
> port,port=0x14,chassis=5,id=pci.5,bus=pcie.0,addr=0x2.0x4 -device pcie-
> root-port,port=0x15,chassis=6,id=pci.6,bus=pcie.0,addr=0x2.0x5 -device
> pcie-root-port,port=0x16,chassis=7,id=pci.7,bus=pcie.0,addr=0x2.0x6 -
> device qemu-xhci,p2=15,p3=15,id=usb,bus=pci.2,addr=0x0 -device virti876714o-
> serial-pci,id=virtio-serial0,bus=pci.3,addr=0x0 -blockdev
> {"driver":"file","filename":"/var/lib/libvirt/images/openSUSE-
> Tumbleweed-JeOS.x86_64-15.1.0-kvm-and-xen-
> Snapshot20210205.qcow2","node-name":"libvirt-1-storage","auto-read-
> only":true,"discard":"unmap"} -blockdev {"node-name":"libvirt-1-
> format","read-only":false,"driver":"qcow2","file":"libvirt-1-
> storage","backing":null} -device virtio-blk-
> pci,bus=pci.4,addr=0x0,drive=libvirt-1-format,id=virtio-
> disk0,bootindex=1 -netdev tap,fd=31,id=hostnet0,vhost=on,vhostfd=32 -
> device virtio-net-
> pci,netdev=hostnet0,id=net0,mac=52:54:00:77:d6:ea,bus=pci.1,addr=0x0 -
> chardev pty,id=charserial0 -device isa-
> serial,chardev=charserial0,id=serial0 -chardev
> socket,id=charchannel0,fd=33,server,nowait -device
> virtserialport,bus=virtio-
> serial0.0,nr=1,chardev=charchannel0,id=channel0,name=org.qemu.guest_age
> nt.0 -device usb-tablet,id=input0,bus=usb.0,port=1 -spice
> port=5900,addr=0.0.0.0,disable-ticketing,seamless-migration=on -device
> qxl-
> vga,id=video0,ram_size=67108864,vram_size=67108864,vram64_size_mb=0,vga
> mem_mb=16,max_outputs=1,bus=pcie.0,addr=0x1 -device virtio-balloon-
> pci,id=balloon0,bus=pci.5,addr=0x0 -object rng-
> random,id=objrng0,filename=/dev/urandom -device virtio-rng-
> pci,rng=objrng0,id=rng0,bus=pci.6,addr=0x0 -sandbox
> on,obsolete=deny,elevateprivileges=deny,spawn=deny,resourcecontrol=deny
> -device vhost-vsock-pci,id=vsock0,guest-
> cid=3,vhostfd=26,bus=pci.7,addr=0x0 -msg timestamp=on
>
> It's a bit of an unusual setup, as the VM (and hence QEMU too) is
> running inside a podman container. But it seems the info you're after
> is indeed present on the commandline.
>
> > to see
> > what is wrong with
> > our parsing logic.
> > Also, if you have any ideas how to get name, cid and port of running
> > libvirt VMs -
> > please share. The current approach parsing the qemu command line is a
> > work
> > around, not a final solution.
> >
> Mmm... not sure. I'll have a look at the code where you go and fetch
> it, and see if anything comes to mind.
Thanks a lot, Dario!
>
> Thanks and Regards
> --
> Dario Faggioli, Ph.D
> http://about.me/dario.faggioli
> Virtualization Software Engineer
> SUSE Labs, SUSE https://www.suse.com/
> -------------------------------------------------------------------
> <<This happens because _I_ choose it to happen!>> (Raistlin Majere)
--
Tzvetomir (Ceco) Stoyanov
VMware Open Source Technology Center
^ permalink raw reply [flat|nested] 25+ messages in thread
* Re: [PATCH v28 0/8] Timestamp synchronization of host - guest tracing session
2021-02-09 12:24 ` Dario Faggioli
2021-02-09 13:00 ` Tzvetomir Stoyanov
@ 2021-02-10 21:59 ` Steven Rostedt
2021-02-10 23:33 ` Dario Faggioli
1 sibling, 1 reply; 25+ messages in thread
From: Steven Rostedt @ 2021-02-10 21:59 UTC (permalink / raw)
To: Dario Faggioli; +Cc: Tzvetomir Stoyanov, Linux Trace Devel
On Tue, 09 Feb 2021 13:24:23 +0100
Dario Faggioli <dfaggioli@suse.com> wrote:
>
> BTW, if I can pester you a little bit more, now that it works I'm
> trying to use this, and here's what I'm doing.
>
> == VM:
> # echo tsc > /sys/devices/system/clocksource/clocksource0/current_clocksource
> # echo x86-tsc > /sys/kernel/tracing/trace_clock
> # trace-cmd agent
>
> == Host:
> # echo x86-tsc > /sys/kernel/tracing/trace_clock
> # trace-cmd record -p nop -e sched:* -e kvm:* -e timer:hrtimer* -A tumbleweed-jeos:823 -e sched:* -e syscalls:*_clock_nanosleep -e timer:hrtimer* sleep 1
>
Note you can use -C x86-tsc on the command line which would handle the
clocks for you. I believe it may update the agent as well, but if not, you
can add it to the agent as well. Also "-p nop" shouldn't be needed, as that
would happen automatically if "-p" is left off.
trace-cmd record -e sched -e kvm -e 'hrtimer*' -C x86-tsc \
-A tumbleweed-jeos:823 -e sched -e '*_clock_nanosleep' -e 'hrtimer*' \
sleep 1
should be equivalent. You may need to add '-C x86-tsc' after the -A, but I
think we made it match the host if a clock was supplied.
> And I do end up with the two files: trace.dat for the host and trace-
> (null).dat (oh, well :-D) for the guest.
I believe my latest push should fix that ;-)
-- Steve
^ permalink raw reply [flat|nested] 25+ messages in thread
* Re: [PATCH v28 0/8] Timestamp synchronization of host - guest tracing session
2021-02-09 17:01 ` Tzvetomir Stoyanov
@ 2021-02-10 22:02 ` Steven Rostedt
2021-02-10 23:35 ` Dario Faggioli
0 siblings, 1 reply; 25+ messages in thread
From: Steven Rostedt @ 2021-02-10 22:02 UTC (permalink / raw)
To: Tzvetomir Stoyanov; +Cc: Dario Faggioli, Linux Trace Devel
On Tue, 9 Feb 2021 19:01:04 +0200
Tzvetomir Stoyanov <tz.stoyanov@gmail.com> wrote:
> > Ok, is there a WiP already, or someone working on it? I'm asking
> > because maybe I can help.
>
> None is working on that yet, any help is highly appreciated :) I just
> created an issue in Bugzilla for that:
> https://bugzilla.kernel.org/show_bug.cgi?id=211657
I had the below patch locally for some time now. It's a somewhat a hack, but
should work. But this should be done properly. The hack below works if you
include only two files, the host first followed by the guest:
trace-cmd report -i trace-host.dat -i trace-guest.dat
Also, the following patch should be applied as well:
https://patchwork.kernel.org/project/linux-trace-devel/patch/20210210164543.5ecd9dbd@gandalf.local.home/
-- Steve
Index: trace-cmd.git/tracecmd/trace-read.c
===================================================================
--- trace-cmd.git.orig/tracecmd/trace-read.c
+++ trace-cmd.git/tracecmd/trace-read.c
@@ -339,6 +339,9 @@ static void add_input(const char *file)
last_input_file = item;
}
+static struct tracecmd_input *host;
+static struct tracecmd_input *guest;
+
static void add_handle(struct tracecmd_input *handle, const char *file)
{
struct handle_list *item;
@@ -358,6 +361,12 @@ static void add_handle(struct tracecmd_i
max_file_size = strlen(item->file);
}
list_add_tail(&item->list, &handle_list);
+ if (handle_list.next != &item->list) {
+ item = container_of(handle_list.next,
+ struct handle_list, list);
+ host = item->handle;
+ guest = handle;
+ }
}
static void free_inputs(void)
@@ -1283,6 +1292,8 @@ static void read_data_info(struct list_h
}
}
+ tracecmd_pair_peer(guest, host);
+
if (otype != OUTPUT_NORMAL)
return;
^ permalink raw reply [flat|nested] 25+ messages in thread
* Re: [PATCH v28 0/8] Timestamp synchronization of host - guest tracing session
2021-02-10 21:59 ` Steven Rostedt
@ 2021-02-10 23:33 ` Dario Faggioli
0 siblings, 0 replies; 25+ messages in thread
From: Dario Faggioli @ 2021-02-10 23:33 UTC (permalink / raw)
To: Steven Rostedt; +Cc: Tzvetomir Stoyanov, Linux Trace Devel
[-- Attachment #1: Type: text/plain, Size: 1847 bytes --]
On Wed, 2021-02-10 at 16:59 -0500, Steven Rostedt wrote:
> On Tue, 09 Feb 2021 13:24:23 +0100
> Dario Faggioli <dfaggioli@suse.com> wrote:
> >
> > == VM:
> > # echo tsc >
> > /sys/devices/system/clocksource/clocksource0/current_clocksource
> > # echo x86-tsc > /sys/kernel/tracing/trace_clock
> > # trace-cmd agent
> >
> > == Host:
> > # echo x86-tsc > /sys/kernel/tracing/trace_clock
> > # trace-cmd record -p nop -e sched:* -e kvm:* -e timer:hrtimer* -A
> > tumbleweed-jeos:823 -e sched:* -e syscalls:*_clock_nanosleep -e
> > timer:hrtimer* sleep 1
> >
>
> Note you can use -C x86-tsc on the command line which would handle
> the
> clocks for you. I believe it may update the agent as well, but if
> not, you
> can add it to the agent as well. Also "-p nop" shouldn't be needed,
> as that
> would happen automatically if "-p" is left off.
>
> trace-cmd record -e sched -e kvm -e 'hrtimer*' -C x86-tsc \
> -A tumbleweed-jeos:823 -e sched -e '*_clock_nanosleep' -e
> 'hrtimer*' \
> sleep 1
>
Right. That's better indeed.
> > And I do end up with the two files: trace.dat for the host and
> > trace-
> > (null).dat (oh, well :-D) for the guest.
>
> I believe my latest push should fix that ;-)
>
Yes, 27c464a74f8f54d0 (trace-cmd: Use instance->name for guests and not
tracefs instance name) fixes this for me.
I was also trying to do some debugging, out of curiosity. And in fact I
was not understanding where the name was being copied in the place
where tracefs_instance_get_name() looks for it. :-)
Thanks!
--
Dario Faggioli, Ph.D
http://about.me/dario.faggioli
Virtualization Software Engineer
SUSE Labs, SUSE https://www.suse.com/
-------------------------------------------------------------------
<<This happens because _I_ choose it to happen!>> (Raistlin Majere)
[-- Attachment #2: This is a digitally signed message part --]
[-- Type: application/pgp-signature, Size: 833 bytes --]
^ permalink raw reply [flat|nested] 25+ messages in thread
* Re: [PATCH v28 0/8] Timestamp synchronization of host - guest tracing session
2021-02-10 22:02 ` Steven Rostedt
@ 2021-02-10 23:35 ` Dario Faggioli
0 siblings, 0 replies; 25+ messages in thread
From: Dario Faggioli @ 2021-02-10 23:35 UTC (permalink / raw)
To: Steven Rostedt, Tzvetomir Stoyanov; +Cc: Linux Trace Devel
[-- Attachment #1: Type: text/plain, Size: 1021 bytes --]
On Wed, 2021-02-10 at 17:02 -0500, Steven Rostedt wrote:
> On Tue, 9 Feb 2021 19:01:04 +0200
> Tzvetomir Stoyanov <tz.stoyanov@gmail.com> wrote:
> >
> > None is working on that yet, any help is highly appreciated :) I
> > just
> > created an issue in Bugzilla for that:
> > https://bugzilla.kernel.org/show_bug.cgi?id=211657
>
> I had the below patch locally for some time now. It's a somewhat a
> hack, but
> should work. But this should be done properly. The hack below works
> if you
> include only two files, the host first followed by the guest:
>
> trace-cmd report -i trace-host.dat -i trace-guest.dat
>
Ah, very useful indeed, if only as a starting point!
Thanks for sharing this. Much appreciated. :-)
Regards
--
Dario Faggioli, Ph.D
http://about.me/dario.faggioli
Virtualization Software Engineer
SUSE Labs, SUSE https://www.suse.com/
-------------------------------------------------------------------
<<This happens because _I_ choose it to happen!>> (Raistlin Majere)
[-- Attachment #2: This is a digitally signed message part --]
[-- Type: application/pgp-signature, Size: 833 bytes --]
^ permalink raw reply [flat|nested] 25+ messages in thread
* Re: [PATCH v28 8/8] trace-cmd [POC]: Add KVM timestamp synchronization plugin
2021-02-08 6:17 ` [PATCH v28 8/8] trace-cmd [POC]: Add KVM timestamp synchronization plugin Tzvetomir Stoyanov (VMware)
@ 2021-02-16 20:48 ` Steven Rostedt
0 siblings, 0 replies; 25+ messages in thread
From: Steven Rostedt @ 2021-02-16 20:48 UTC (permalink / raw)
To: Tzvetomir Stoyanov (VMware); +Cc: linux-trace-devel
On Mon, 8 Feb 2021 08:17:43 +0200
"Tzvetomir Stoyanov (VMware)" <tz.stoyanov@gmail.com> wrote:
> index 00000000..03a4fd73
> --- /dev/null
> +++ b/lib/trace-cmd/trace-timesync-kvm.c
> @@ -0,0 +1,460 @@
> +// SPDX-License-Identifier: LGPL-2.1
> +/*
> + * Copyright (C) 2020, VMware, Tzvetomir Stoyanov tz.stoyanov@gmail.com>
> + *
> + */
> +
> +#include <fcntl.h>
> +#include <stdlib.h>
> +#include <unistd.h>
> +#include <sys/stat.h>
> +#include <dirent.h>
> +
> +#include "trace-cmd.h"
> +#include "trace-cmd-private.h"
> +#include "tracefs.h"
> +#include "trace-tsync-local.h"
> +
> +#define KVM_DEBUG_FS "/sys/kernel/debug/kvm"
> +#define KVM_DEBUG_OFFSET_FILE "tsc-offset"
> +#define KVM_DEBUG_SCALING_FILE "tsc-scaling-ratio"
> +#define KVM_DEBUG_VCPU_DIR "vcpu"
> +
> +#define KVM_SYNC_PKT_REQUEST 1
> +#define KVM_SYNC_PKT_RESPONSE 2
> +
> +typedef __s64 s64;
I get:
trace-timesync-kvm.c:26:1: error: unknown type name ‘__s64’
typedef __s64 s64;
^
On one of my machines without the below patch:
-- Steve
> +
> +// equal to /sys/kernel/debug/kvm/<VM ID>/vcpu0/tsc-offset
> +#define KVM_ACCURACY 0
> +#define KVM_NAME "kvm"
> +
diff --git a/lib/trace-cmd/trace-timesync-kvm.c b/lib/trace-cmd/trace-timesync-kvm.c
index 03a4fd7..0b0267b 100644
--- a/lib/trace-cmd/trace-timesync-kvm.c
+++ b/lib/trace-cmd/trace-timesync-kvm.c
@@ -8,6 +8,7 @@
#include <stdlib.h>
#include <unistd.h>
#include <sys/stat.h>
+#include <linux/types.h>
#include <dirent.h>
#include "trace-cmd.h"
^ permalink raw reply related [flat|nested] 25+ messages in thread
* Re: [PATCH v28 1/8] trace-cmd: Save command lines in VM agent
2021-02-08 6:17 ` [PATCH v28 1/8] trace-cmd: Save command lines in VM agent Tzvetomir Stoyanov (VMware)
@ 2021-02-17 20:55 ` Steven Rostedt
0 siblings, 0 replies; 25+ messages in thread
From: Steven Rostedt @ 2021-02-17 20:55 UTC (permalink / raw)
To: Tzvetomir Stoyanov (VMware); +Cc: linux-trace-devel
On Mon, 8 Feb 2021 08:17:36 +0200
"Tzvetomir Stoyanov (VMware)" <tz.stoyanov@gmail.com> wrote:
> Command lines were not saved in the guest tracing file, due to bug
> inrtoduced by commit:
> https://git.kernel.org/pub/scm/utils/trace-cmd/trace-cmd.git/commit/?id=1eea02a4bef10507d157489a1ee97f273db7b319
I already pulled this in (not really noticing this link), but for next
time, the proper way of doing this is to add a "Fixes:" tag.
Fixes: 1eea02a4bef ("trace-cmd: Add missing APIs to libtracecmd main man page")
This way, we can easily add a search to the git history looking for fixes
that should be backported to a previous release.
-- Steve
>
> Signed-off-by: Tzvetomir Stoyanov (VMware) <tz.stoyanov@gmail.com>
> ---
>
^ permalink raw reply [flat|nested] 25+ messages in thread
end of thread, other threads:[~2021-02-17 20:56 UTC | newest]
Thread overview: 25+ messages (download: mbox.gz / follow: Atom feed)
-- links below jump to the message on this page --
2021-02-08 6:17 [PATCH v28 0/8] Timestamp synchronization of host - guest tracing session Tzvetomir Stoyanov (VMware)
2021-02-08 6:17 ` [PATCH v28 1/8] trace-cmd: Save command lines in VM agent Tzvetomir Stoyanov (VMware)
2021-02-17 20:55 ` Steven Rostedt
2021-02-08 6:17 ` [PATCH v28 2/8] trace-cmd: Fix bug in getting tracing dir in trace-cmd agent Tzvetomir Stoyanov (VMware)
2021-02-08 6:17 ` [PATCH v28 3/8] trace-cmd: Removed unused s64 define Tzvetomir Stoyanov (VMware)
2021-02-08 6:17 ` [PATCH v28 4/8] trace-cmd: Add timestamp synchronization per vCPU Tzvetomir Stoyanov (VMware)
2021-02-08 6:17 ` [PATCH v28 5/8] trace-cmd: Add dummy function to initialize timestamp sync logic Tzvetomir Stoyanov (VMware)
2021-02-08 6:17 ` [PATCH v28 6/8] trace-cmd: [POC] PTP-like algorithm for host - guest timestamp synchronization Tzvetomir Stoyanov (VMware)
2021-02-08 6:17 ` [PATCH v28 7/8] trace-cmd: Debug scripts for " Tzvetomir Stoyanov (VMware)
2021-02-08 6:17 ` [PATCH v28 8/8] trace-cmd [POC]: Add KVM timestamp synchronization plugin Tzvetomir Stoyanov (VMware)
2021-02-16 20:48 ` Steven Rostedt
2021-02-09 5:32 ` [PATCH v28 0/8] Timestamp synchronization of host - guest tracing session Dario Faggioli
2021-02-09 6:03 ` Tzvetomir Stoyanov
2021-02-09 6:08 ` Tzvetomir Stoyanov
2021-02-09 7:28 ` Dario Faggioli
2021-02-09 11:44 ` Tzvetomir Stoyanov
2021-02-09 12:24 ` Dario Faggioli
2021-02-09 13:00 ` Tzvetomir Stoyanov
2021-02-09 15:28 ` Dario Faggioli
2021-02-09 17:01 ` Tzvetomir Stoyanov
2021-02-10 22:02 ` Steven Rostedt
2021-02-10 23:35 ` Dario Faggioli
2021-02-10 21:59 ` Steven Rostedt
2021-02-10 23:33 ` Dario Faggioli
2021-02-09 7:18 ` Dario Faggioli
This is a public inbox, see mirroring instructions
for how to clone and mirror all data and code used for this inbox;
as well as URLs for NNTP newsgroup(s).