From patchwork Thu Mar 11 08:48:42 2021 Content-Type: text/plain; charset="utf-8" MIME-Version: 1.0 Content-Transfer-Encoding: 7bit X-Patchwork-Submitter: "Tzvetomir Stoyanov (VMware)" X-Patchwork-Id: 12130613 Return-Path: X-Spam-Checker-Version: SpamAssassin 3.4.0 (2014-02-07) on aws-us-west-2-korg-lkml-1.web.codeaurora.org X-Spam-Level: X-Spam-Status: No, score=-15.8 required=3.0 tests=BAYES_00,DKIM_SIGNED, DKIM_VALID,DKIM_VALID_AU,FREEMAIL_FORGED_FROMDOMAIN,FREEMAIL_FROM, HEADER_FROM_DIFFERENT_DOMAINS,INCLUDES_CR_TRAILER,INCLUDES_PATCH, MAILING_LIST_MULTI,SPF_HELO_NONE,SPF_PASS,USER_AGENT_GIT autolearn=ham autolearn_force=no version=3.4.0 Received: from mail.kernel.org (mail.kernel.org [198.145.29.99]) by smtp.lore.kernel.org (Postfix) with ESMTP id 583A0C433E6 for ; Thu, 11 Mar 2021 08:49:17 +0000 (UTC) Received: from vger.kernel.org (vger.kernel.org [23.128.96.18]) by mail.kernel.org (Postfix) with ESMTP id 0418B64FB1 for ; Thu, 11 Mar 2021 08:49:16 +0000 (UTC) Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S231464AbhCKItQ (ORCPT ); Thu, 11 Mar 2021 03:49:16 -0500 Received: from lindbergh.monkeyblade.net ([23.128.96.19]:42722 "EHLO lindbergh.monkeyblade.net" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S231720AbhCKItI (ORCPT ); Thu, 11 Mar 2021 03:49:08 -0500 Received: from mail-ej1-x62d.google.com (mail-ej1-x62d.google.com [IPv6:2a00:1450:4864:20::62d]) by lindbergh.monkeyblade.net (Postfix) with ESMTPS id C1CF8C061574 for ; Thu, 11 Mar 2021 00:49:07 -0800 (PST) Received: by mail-ej1-x62d.google.com with SMTP id dx17so44556740ejb.2 for ; Thu, 11 Mar 2021 00:49:07 -0800 (PST) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=gmail.com; s=20161025; h=from:to:cc:subject:date:message-id:in-reply-to:references :mime-version:content-transfer-encoding; bh=5p5RFPDN2j+oblUFthx843Hl3cm6jpi+qZTIA3kEBlA=; b=bxyOE9W7wq0Yefu9w5Wd77qaaJwdRyj3a9ufeFPPX9MuArienmFH5K/VwZNhnuI1B8 21H/7OVvSExSme0WJn8Sv2Be3ZOfATuZoGW6WILYsV62/PbJZ2bvkMPbQEqRBfMBwVNq u9gM6gZNpVLx7tbreJF2/vf3QzIYRIeLmpQJBn7qHJvSneu89Z9+XP5xnpXNohfXNE8s h7JE21xiaRUo59Pz2EhpKxw4uANtrZXqaFE2zh5EV4CcEQijkG4RAlB8ly1AOlAkVjuJ 9v3uk9Da3BFVNqaoDyd/1WYhVUQUaGjKUz9GcHfuagsG6ZiFqccmIXW6IBtdXa841Vv0 NhgQ== X-Google-DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=1e100.net; s=20161025; h=x-gm-message-state:from:to:cc:subject:date:message-id:in-reply-to :references:mime-version:content-transfer-encoding; bh=5p5RFPDN2j+oblUFthx843Hl3cm6jpi+qZTIA3kEBlA=; b=OthAhyIQXAGHdrzPwZzGwRDIOcDexPyxxrqcK2tkK+HDKZy4dZkhUcuTZz8CHf0/8/ A3dTZykuxjSosS9XqYAA6UnHMtQgVsRbcZdY/vDeEQPnfcsOGqW8yMBt1zIO6Dr+ZGui kXalHX1meLsz1kFDsEbky480XM9wCjnCFBIEb+87KRTeL2/shwU6+bCWcnZPuY/IJ6HS 4H9afV4hgKQ6KM9Zr6z/3VjOh24k0PaY6lHMFzkRCvQaYsO9NhFUQKG1I9Nv2Sfv6I65 jOlu1ImX/b7YmhXjbJ1w5WkvNCD0+KSh7IooqlhIdJgoPjHOI26HYoXKkLxUS8WVBtj/ laUw== X-Gm-Message-State: AOAM531eXbDHoG3yqcyL5v4WnEcVifFFbiS7zlNSB1yw24b1BvGOz1Py bh9tQtpCXwcHfy59aYXCxML/FONuw2yzzA== X-Google-Smtp-Source: ABdhPJyrWIWFVVxwUjKf3BeJ4qo0K3mPuYihCLRh4s6VhJ5hw7kTYK56cwxmDtXAWpT4gQIUcKh7ww== X-Received: by 2002:a17:907:2513:: with SMTP id y19mr2021055ejl.241.1615452546373; Thu, 11 Mar 2021 00:49:06 -0800 (PST) Received: from oberon.zico.biz ([83.222.187.186]) by smtp.gmail.com with ESMTPSA id fi11sm901647ejb.73.2021.03.11.00.49.05 (version=TLS1_3 cipher=TLS_AES_256_GCM_SHA384 bits=256/256); Thu, 11 Mar 2021 00:49:05 -0800 (PST) From: "Tzvetomir Stoyanov (VMware)" To: rostedt@goodmis.org Cc: linux-trace-devel@vger.kernel.org Subject: [PATCH v31 01/16] trace-cmd: Add timestamp synchronization per vCPU Date: Thu, 11 Mar 2021 10:48:42 +0200 Message-Id: <20210311084857.1919805-2-tz.stoyanov@gmail.com> X-Mailer: git-send-email 2.29.2 In-Reply-To: <20210311084857.1919805-1-tz.stoyanov@gmail.com> References: <20210311084857.1919805-1-tz.stoyanov@gmail.com> MIME-Version: 1.0 Precedence: bulk List-ID: X-Mailing-List: linux-trace-devel@vger.kernel.org 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) --- .../include/private/trace-cmd-private.h | 2 +- lib/trace-cmd/include/trace-tsync-local.h | 22 +- lib/trace-cmd/trace-input.c | 175 +++++++++----- lib/trace-cmd/trace-timesync.c | 213 +++++++++++++----- tracecmd/trace-dump.c | 52 +++-- tracecmd/trace-tsync.c | 67 ++++-- 6 files changed, 363 insertions(+), 168 deletions(-) diff --git a/lib/trace-cmd/include/private/trace-cmd-private.h b/lib/trace-cmd/include/private/trace-cmd-private.h index ecde8d13..88e9bbc1 100644 --- a/lib/trace-cmd/include/private/trace-cmd-private.h +++ b/lib/trace-cmd/include/private/trace-cmd-private.h @@ -456,7 +456,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 -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 f9d09d26..971a6c01 100644 --- a/lib/trace-cmd/trace-input.c +++ b/lib/trace-cmd/trace-input.c @@ -91,12 +91,20 @@ 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; int ts_samples_count; struct ts_offset_sample *ts_samples; + int cpu_count; + struct timesync_offsets *ts_offsets; }; struct tracecmd_input { @@ -1216,10 +1224,10 @@ 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->flags & TRACECMD_FL_IGNORE_DATE) @@ -1228,44 +1236,47 @@ static unsigned long long timestamp_correct(unsigned long long ts, 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]); } /* @@ -1289,7 +1300,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; @@ -1922,7 +1934,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; @@ -2257,34 +2269,80 @@ 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]; + } + 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; } - host->ts_samples_count = j; + return 0; } 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; + } } static int trace_pid_map_cmp(const void *a, const void *b) @@ -2538,8 +2596,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; @@ -2590,11 +2648,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; @@ -2602,18 +2664,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; tracecmd_enable_tsync(handle, true); break; case TRACECMD_OPTION_CPUSTAT: @@ -4006,7 +4059,7 @@ int tracecmd_get_guest_cpumap(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 8d01c0bc..7c11ee1b 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; } @@ -356,6 +365,13 @@ static int clock_context_init(struct tracecmd_time_sync *tsync, 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; @@ -365,6 +381,9 @@ static int clock_context_init(struct tracecmd_time_sync *tsync, return 0; error: tsync->context = NULL; + if (clock->instance) + clock_synch_delete_instance(clock->instance); + free(clock->offsets); free(clock); return -1; } @@ -380,6 +399,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; @@ -392,28 +412,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; } @@ -431,55 +511,48 @@ 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; clock_context_init(tsync, &proto, true); 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); @@ -487,20 +560,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) { @@ -527,11 +623,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; clock_context_init(tsync, &proto, false); if (!tsync->context) @@ -543,12 +641,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 05a4beb3..d7de8298 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) @@ -263,6 +287,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); From patchwork Thu Mar 11 08:48:43 2021 Content-Type: text/plain; charset="utf-8" MIME-Version: 1.0 Content-Transfer-Encoding: 7bit X-Patchwork-Submitter: "Tzvetomir Stoyanov (VMware)" X-Patchwork-Id: 12130607 Return-Path: X-Spam-Checker-Version: SpamAssassin 3.4.0 (2014-02-07) on aws-us-west-2-korg-lkml-1.web.codeaurora.org X-Spam-Level: X-Spam-Status: No, score=-15.8 required=3.0 tests=BAYES_00,DKIM_SIGNED, DKIM_VALID,DKIM_VALID_AU,FREEMAIL_FORGED_FROMDOMAIN,FREEMAIL_FROM, HEADER_FROM_DIFFERENT_DOMAINS,INCLUDES_CR_TRAILER,INCLUDES_PATCH, MAILING_LIST_MULTI,SPF_HELO_NONE,SPF_PASS,USER_AGENT_GIT autolearn=ham autolearn_force=no version=3.4.0 Received: from mail.kernel.org (mail.kernel.org [198.145.29.99]) by smtp.lore.kernel.org (Postfix) with ESMTP id 85DB6C43381 for ; Thu, 11 Mar 2021 08:49:17 +0000 (UTC) Received: from vger.kernel.org (vger.kernel.org [23.128.96.18]) by mail.kernel.org (Postfix) with ESMTP id 3910A64FB0 for ; Thu, 11 Mar 2021 08:49:17 +0000 (UTC) Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S231626AbhCKItQ (ORCPT ); Thu, 11 Mar 2021 03:49:16 -0500 Received: from lindbergh.monkeyblade.net ([23.128.96.19]:42724 "EHLO lindbergh.monkeyblade.net" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S231335AbhCKItJ (ORCPT ); Thu, 11 Mar 2021 03:49:09 -0500 Received: from mail-ed1-x52e.google.com (mail-ed1-x52e.google.com [IPv6:2a00:1450:4864:20::52e]) by lindbergh.monkeyblade.net (Postfix) with ESMTPS id 0C4F9C061574 for ; Thu, 11 Mar 2021 00:49:09 -0800 (PST) Received: by mail-ed1-x52e.google.com with SMTP id z1so1524973edb.8 for ; Thu, 11 Mar 2021 00:49:08 -0800 (PST) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=gmail.com; s=20161025; h=from:to:cc:subject:date:message-id:in-reply-to:references :mime-version:content-transfer-encoding; bh=roU/w+KMRRvR4EP+/hSvYPxbYCTZDORlU5h+TeZSAb4=; b=TZ3bqKlqp78xXbiEfZkNS6+5sX7bSUh9tRiabHJ4c7bj7oLKZEjx4b1CVCP801FAK4 EO1psaKfr9hB9N44Q8WjMTAxfbEO2rret7AXUhsV1EKTtrKoAFH1unKzUjMYrZOL5IKb t0RDDHqf3xcKgAVJcAfk4U6IsrqYGFJh0YhlG3A2ILTjpj69NfddxsULzLAqlE4Eqrzg wTl5U2DLKi7zM2WV3ZFNVV+4pN+lQ1v99aWDva6jvlFB47qoFUddPVzJsV1KLvw8huD7 5om3ZNft4RALGJfh8FFIky2nLFjjZ/WvJgK8NmeSpPaDZAbswefq8K3HXmhcIRtZN0g4 XoPQ== X-Google-DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=1e100.net; s=20161025; h=x-gm-message-state:from:to:cc:subject:date:message-id:in-reply-to :references:mime-version:content-transfer-encoding; bh=roU/w+KMRRvR4EP+/hSvYPxbYCTZDORlU5h+TeZSAb4=; b=kBKhz+4KznvQrFhz4nuLFAnpJKAHzlIgVnbpF9sXWkeKvwmR/NYnfwzayhn6tw7UJE BBVFeU7vOkcJn3IY7RslCjM2ujbZc28FmA1mxXTkN1m10JXD95ofcR1p7W23sWXYFoIK dtMYBmyvse22lrLeXl3Tf3tTXPfbLHiXIL4B34YlVJVI7XOmmX1+id9G9VmpPVFO0Ox2 50F+EnrTniN7QLzMBaHr9fW9rb0WW3+ef8sht5cnS4KrrkyKy29eWsl7LB/ngQwttV8H l1KoLfAGwAnP6IWbxTssTUtlo2wGFfXvUiOO5+TZIYJrafT+qG4LijO7jr40JawrThsp OHYA== X-Gm-Message-State: AOAM532WKjpaTDsrh9hRjqZuBgplcCQINEvDlaN8aiTA95CmJ9y8Pnxj eJIQeaZcKT6AoS9Ebr7JIGCMzMQKi7Gt5Q== X-Google-Smtp-Source: ABdhPJzcvHQd4E23hVWMY0onbNqlE/OmYEK0lgxhbLFObidFQaDrrUTJWzL7s+W2q7OF9zcXHmOB2w== X-Received: by 2002:a05:6402:2076:: with SMTP id bd22mr7342436edb.378.1615452547787; Thu, 11 Mar 2021 00:49:07 -0800 (PST) Received: from oberon.zico.biz ([83.222.187.186]) by smtp.gmail.com with ESMTPSA id fi11sm901647ejb.73.2021.03.11.00.49.06 (version=TLS1_3 cipher=TLS_AES_256_GCM_SHA384 bits=256/256); Thu, 11 Mar 2021 00:49:06 -0800 (PST) From: "Tzvetomir Stoyanov (VMware)" To: rostedt@goodmis.org Cc: linux-trace-devel@vger.kernel.org Subject: [PATCH v31 02/16] trace-cmd: Add dummy function to initialize timestamp sync logic Date: Thu, 11 Mar 2021 10:48:43 +0200 Message-Id: <20210311084857.1919805-3-tz.stoyanov@gmail.com> X-Mailer: git-send-email 2.29.2 In-Reply-To: <20210311084857.1919805-1-tz.stoyanov@gmail.com> References: <20210311084857.1919805-1-tz.stoyanov@gmail.com> MIME-Version: 1.0 Precedence: bulk List-ID: X-Mailing-List: linux-trace-devel@vger.kernel.org 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) --- 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 7c11ee1b..f49eafdd 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 e7428788..63e09b57 100644 --- a/tracecmd/trace-record.c +++ b/tracecmd/trace-record.c @@ -6242,10 +6242,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) { @@ -6403,12 +6399,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); } @@ -6500,7 +6507,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); } @@ -6519,7 +6526,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); } @@ -6529,7 +6536,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); } From patchwork Thu Mar 11 08:48:44 2021 Content-Type: text/plain; charset="utf-8" MIME-Version: 1.0 Content-Transfer-Encoding: 7bit X-Patchwork-Submitter: "Tzvetomir Stoyanov (VMware)" X-Patchwork-Id: 12130619 Return-Path: X-Spam-Checker-Version: SpamAssassin 3.4.0 (2014-02-07) on aws-us-west-2-korg-lkml-1.web.codeaurora.org X-Spam-Level: X-Spam-Status: No, score=-15.8 required=3.0 tests=BAYES_00,DKIM_SIGNED, DKIM_VALID,DKIM_VALID_AU,FREEMAIL_FORGED_FROMDOMAIN,FREEMAIL_FROM, HEADER_FROM_DIFFERENT_DOMAINS,INCLUDES_CR_TRAILER,INCLUDES_PATCH, MAILING_LIST_MULTI,SPF_HELO_NONE,SPF_PASS,USER_AGENT_GIT autolearn=ham autolearn_force=no version=3.4.0 Received: from mail.kernel.org (mail.kernel.org [198.145.29.99]) by smtp.lore.kernel.org (Postfix) with ESMTP id 9B191C4332B for ; Thu, 11 Mar 2021 08:49:17 +0000 (UTC) Received: from vger.kernel.org (vger.kernel.org [23.128.96.18]) by mail.kernel.org (Postfix) with ESMTP id 6384B64FD4 for ; Thu, 11 Mar 2021 08:49:17 +0000 (UTC) Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S231335AbhCKItR (ORCPT ); Thu, 11 Mar 2021 03:49:17 -0500 Received: from lindbergh.monkeyblade.net ([23.128.96.19]:42732 "EHLO lindbergh.monkeyblade.net" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S231426AbhCKItK (ORCPT ); Thu, 11 Mar 2021 03:49:10 -0500 Received: from mail-ed1-x52c.google.com (mail-ed1-x52c.google.com [IPv6:2a00:1450:4864:20::52c]) by lindbergh.monkeyblade.net (Postfix) with ESMTPS id 57995C061574 for ; Thu, 11 Mar 2021 00:49:10 -0800 (PST) Received: by mail-ed1-x52c.google.com with SMTP id bx7so1528803edb.12 for ; Thu, 11 Mar 2021 00:49:10 -0800 (PST) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=gmail.com; s=20161025; h=from:to:cc:subject:date:message-id:in-reply-to:references :mime-version:content-transfer-encoding; bh=kCHidoleSwidZLLjOKDHKOgMKK3ug+TfZHtK0RWBiuY=; b=N0rqr/1Trbxc0bsFcrFZq9EKvEqAT/8OS1SGXNkJpsqcwOg2oPSQyydZ+hN2f9asZ6 oCQilsobjwC22/4q2xMVjVUcSJJBezB/uWRPw/9yUZH+o5IMA2we4ZDVE0mmj9yfRcEh 1QDZuUCIR79CQQBiweKlktuEth/OgpXh8J+ngrBjhMhJ/zEW6H7dEneLBlkp8J3fvpnw YmDIkeHnoyLfvaTyNexfuoOZRMEiK3It9vFswnCY+1m5B6XV1Uil9QKBUxZgX2CYeAIu nKZ5U8D3QiQn7ruFGAdLQ5AUX8Mo0MRnAzj7pp9Q6Rh+90Mr9KFjjjCUcAPSTl3EseRU Rwkg== X-Google-DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=1e100.net; s=20161025; h=x-gm-message-state:from:to:cc:subject:date:message-id:in-reply-to :references:mime-version:content-transfer-encoding; bh=kCHidoleSwidZLLjOKDHKOgMKK3ug+TfZHtK0RWBiuY=; b=sRoAXFUL33qWQWhq2GxyrXc4KdNuIh3yPnFAcTvwKCXzXzJHzVvlb0fQJb+1B/ZI9z xG+IzuixVgMIEpb+PQ5pdyljR2ETAfrJ9C+TgNWKC0MpoGoa8BoCEPzDNOux3egcTzgM 7uSPa6Dt2BsiRWkXf7mXERfrTZAt0DyYpAKZWMKh8ZrpPOV2h3Dfnkud9PkLjMK4Pe5m w+btrZHTlbdaBxQU5Wxe3WUTO9PMFHRnCeBH/wXkBfFd1gd9iMyJhM4kAvIuIeId/KS2 AC5J2Gu9z6oZVr9t+7LnU+F3x+tfdHQncCxbB0o3QiaEvGiR7SoO7Zoka88KrlpCxph8 zSog== X-Gm-Message-State: AOAM532es/3U2yeEpazFoQSdTiAlo8bWn51m+u8BKOp2mlbGB7WUlTwQ I1JsNr+ECRivAHr1p5NCvU2QtG9LFngovQ== X-Google-Smtp-Source: ABdhPJyuCuX+joHpi1W3b4chYaLZKdxYOJvG9eRhOGMqAN0r4ifj4V2RdDXeXByXwP93sMVbkO5MTw== X-Received: by 2002:aa7:c1d0:: with SMTP id d16mr7296579edp.153.1615452548939; Thu, 11 Mar 2021 00:49:08 -0800 (PST) Received: from oberon.zico.biz ([83.222.187.186]) by smtp.gmail.com with ESMTPSA id fi11sm901647ejb.73.2021.03.11.00.49.07 (version=TLS1_3 cipher=TLS_AES_256_GCM_SHA384 bits=256/256); Thu, 11 Mar 2021 00:49:08 -0800 (PST) From: "Tzvetomir Stoyanov (VMware)" To: rostedt@goodmis.org Cc: linux-trace-devel@vger.kernel.org Subject: [PATCH v31 03/16] trace-cmd: Move time sync logic in the trace-cmd library Date: Thu, 11 Mar 2021 10:48:44 +0200 Message-Id: <20210311084857.1919805-4-tz.stoyanov@gmail.com> X-Mailer: git-send-email 2.29.2 In-Reply-To: <20210311084857.1919805-1-tz.stoyanov@gmail.com> References: <20210311084857.1919805-1-tz.stoyanov@gmail.com> MIME-Version: 1.0 Precedence: bulk List-ID: X-Mailing-List: linux-trace-devel@vger.kernel.org The whole timestamp synchronization logic is moved in the trace-cmd library. The logic is abstracted, the application receives a time sync context which represents the synchronization session. These library APIs can be used to control the synchronization session: tracecmd_tsync_init() tracecmd_tsync_proto_getall() tsync_proto_is_supported() tracecmd_tsync_with_host() tracecmd_tsync_with_host_stop() tracecmd_tsync_with_guest() tracecmd_tsync_with_guest_stop() tracecmd_tsync_free() tracecmd_tsync_get_offsets() tracecmd_tsync_get_session_params() tracecmd_write_guest_time_shift() Signed-off-by: Tzvetomir Stoyanov (VMware) --- lib/trace-cmd/Makefile | 2 - .../include/private/trace-cmd-private.h | 33 +- lib/trace-cmd/include/trace-tsync-local.h | 16 + lib/trace-cmd/trace-timesync.c | 528 ++++++++++++++++-- tracecmd/Makefile | 3 - tracecmd/include/trace-local.h | 5 +- tracecmd/trace-agent.c | 20 +- tracecmd/trace-record.c | 70 ++- tracecmd/trace-tsync.c | 319 ----------- 9 files changed, 590 insertions(+), 406 deletions(-) delete mode 100644 tracecmd/trace-tsync.c diff --git a/lib/trace-cmd/Makefile b/lib/trace-cmd/Makefile index 841c84f1..2f553ed5 100644 --- a/lib/trace-cmd/Makefile +++ b/lib/trace-cmd/Makefile @@ -17,9 +17,7 @@ OBJS += trace-util.o OBJS += trace-filter-hash.o OBJS += trace-msg.o OBJS += trace-plugin.o -ifeq ($(VSOCK_DEFINED), 1) OBJS += trace-timesync.o -endif # Additional util objects OBJS += trace-blk-hack.o diff --git a/lib/trace-cmd/include/private/trace-cmd-private.h b/lib/trace-cmd/include/private/trace-cmd-private.h index 88e9bbc1..cef8f645 100644 --- a/lib/trace-cmd/include/private/trace-cmd-private.h +++ b/lib/trace-cmd/include/private/trace-cmd-private.h @@ -421,6 +421,7 @@ const char *tracecmd_clock_id2str(enum tracecmd_clocks clock); /* --- Timestamp synchronization --- */ +struct tracecmd_time_sync; #define TRACECMD_TSYNC_PNAME_LENGTH 16 #define TRACECMD_TSYNC_PROTO_NONE "none" @@ -434,34 +435,30 @@ enum tracecmd_time_sync_role { TRACECMD_TIME_SYNC_ROLE_GUEST = (1 << 1), }; -struct tracecmd_time_sync { - const char *proto_name; - int loop_interval; - pthread_mutex_t lock; - pthread_cond_t cond; - char *clock_str; - struct tracecmd_msg_handle *msg_handle; - void *context; - int guest_pid; - int vcpu_count; -}; - /* Timestamp synchronization flags */ #define TRACECMD_TSYNC_FLAG_INTERPOLATE 0x1 void tracecmd_tsync_init(void); int tracecmd_tsync_proto_getall(struct tracecmd_tsync_protos **protos, const char *clock, int role); -const char *tracecmd_tsync_proto_select(struct tracecmd_tsync_protos *protos, char *clock, - enum tracecmd_time_sync_role role); 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); +struct tracecmd_time_sync * +tracecmd_tsync_with_host(struct tracecmd_tsync_protos *tsync_protos, + const char *clock); +int tracecmd_tsync_with_host_stop(struct tracecmd_time_sync *tsync); +struct tracecmd_time_sync * +tracecmd_tsync_with_guest(unsigned long long trace_id, int loop_interval, + unsigned int cid, unsigned int port, int guest_pid, + int guest_cpus, const char *proto_name, const char *clock); +int tracecmd_tsync_with_guest_stop(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, - unsigned int *flags); +int tracecmd_tsync_get_session_params(struct tracecmd_time_sync *tsync, + char **selected_proto, + unsigned int *tsync_port); void tracecmd_tsync_free(struct tracecmd_time_sync *tsync); +int tracecmd_write_guest_time_shift(struct tracecmd_output *handle, + struct tracecmd_time_sync *tsync); /* --- Plugin handling --- */ extern struct tep_plugin_option trace_ftrace_options[]; diff --git a/lib/trace-cmd/include/trace-tsync-local.h b/lib/trace-cmd/include/trace-tsync-local.h index d4281469..b3a3bdfc 100644 --- a/lib/trace-cmd/include/trace-tsync-local.h +++ b/lib/trace-cmd/include/trace-tsync-local.h @@ -8,6 +8,22 @@ #include +struct tracecmd_time_sync { + pthread_t thread; + bool thread_running; + unsigned long long trace_id; + char *proto_name; + int loop_interval; + pthread_mutex_t lock; + pthread_cond_t cond; + pthread_barrier_t first_sync; + char *clock_str; + struct tracecmd_msg_handle *msg_handle; + void *context; + int guest_pid; + int vcpu_count; +}; + struct clock_sync_offsets { /* Arrays with calculated time offsets at given time */ int sync_size; /* Allocated size of sync_ts, diff --git a/lib/trace-cmd/trace-timesync.c b/lib/trace-cmd/trace-timesync.c index f49eafdd..d38ee975 100644 --- a/lib/trace-cmd/trace-timesync.c +++ b/lib/trace-cmd/trace-timesync.c @@ -8,7 +8,9 @@ #include #include #include +#ifdef VSOCK #include +#endif #include #include #include @@ -158,15 +160,15 @@ int tracecmd_tsync_get_offsets(struct tracecmd_time_sync *tsync, int cpu, } /** - * tracecmd_tsync_get_proto_flags - Get protocol flags + * tsync_get_proto_flags - Get protocol flags * * @tsync: Pointer to time sync context * @flags: Returns the protocol flags, a combination of TRACECMD_TSYNC_FLAG_... * * Retuns -1 in case of an error, or 0 otherwise */ -int tracecmd_tsync_get_proto_flags(struct tracecmd_time_sync *tsync, - unsigned int *flags) +static int tsync_get_proto_flags(struct tracecmd_time_sync *tsync, + unsigned int *flags) { struct tsync_proto *protocol; @@ -186,7 +188,7 @@ int tracecmd_tsync_get_proto_flags(struct tracecmd_time_sync *tsync, #define PROTO_MASK_SIZE (sizeof(char)) #define PROTO_MASK_BITS (PROTO_MASK_SIZE * 8) /** - * tracecmd_tsync_proto_select - Select time sync protocol, to be used for + * tsync_proto_select - Select time sync protocol, to be used for * timestamp synchronization with a peer * * @protos: list of tsync protocol names @@ -197,8 +199,9 @@ int tracecmd_tsync_get_proto_flags(struct tracecmd_time_sync *tsync, * in case there is no match with supported protocols. * The returned string MUST NOT be freed by the caller */ -const char *tracecmd_tsync_proto_select(struct tracecmd_tsync_protos *protos, char *clock, - enum tracecmd_time_sync_role role) +static const char * +tsync_proto_select(struct tracecmd_tsync_protos *protos, const char *clock, + enum tracecmd_time_sync_role role) { struct tsync_proto *selected = NULL; struct tsync_proto *proto; @@ -235,7 +238,7 @@ const char *tracecmd_tsync_proto_select(struct tracecmd_tsync_protos *protos, ch } /** - * tracecmd_tsync_proto_getall - Returns bitmask of all supported + * tracecmd_tsync_proto_getall - Returns list of all supported * time sync protocols * @protos: return, allocated list of time sync protocol names, * supported by the peer. Must be freed by free() @@ -291,6 +294,109 @@ error: return -1; } +static int get_first_cpu(cpu_set_t **pin_mask, size_t *m_size) +{ + int cpus = tracecmd_count_cpus(); + cpu_set_t *cpu_mask; + int mask_size; + int i; + + cpu_mask = CPU_ALLOC(cpus); + *pin_mask = CPU_ALLOC(cpus); + if (!cpu_mask || !*pin_mask || 1) + goto error; + + mask_size = CPU_ALLOC_SIZE(cpus); + CPU_ZERO_S(mask_size, cpu_mask); + CPU_ZERO_S(mask_size, *pin_mask); + + if (sched_getaffinity(0, mask_size, cpu_mask) == -1) + goto error; + + for (i = 0; i < cpus; i++) { + if (CPU_ISSET_S(i, mask_size, cpu_mask)) { + CPU_SET_S(i, mask_size, *pin_mask); + break; + } + } + + if (CPU_COUNT_S(mask_size, *pin_mask) < 1) + goto error; + + CPU_FREE(cpu_mask); + *m_size = mask_size; + return 0; + +error: + if (cpu_mask) + CPU_FREE(cpu_mask); + if (*pin_mask) + CPU_FREE(*pin_mask); + *pin_mask = NULL; + *m_size = 0; + return -1; +} + +#ifdef VSOCK +static int vsock_open(unsigned int cid, unsigned int port) +{ + struct sockaddr_vm addr = { + .svm_family = AF_VSOCK, + .svm_cid = cid, + .svm_port = port, + }; + int sd; + + sd = socket(AF_VSOCK, SOCK_STREAM, 0); + if (sd < 0) + return -errno; + + if (connect(sd, (struct sockaddr *)&addr, sizeof(addr))) + return -errno; + + return sd; +} +static int vsock_make(void) +{ + struct sockaddr_vm addr = { + .svm_family = AF_VSOCK, + .svm_cid = VMADDR_CID_ANY, + .svm_port = VMADDR_PORT_ANY, + }; + int sd; + + sd = socket(AF_VSOCK, SOCK_STREAM, 0); + if (sd < 0) + return -errno; + + setsockopt(sd, SOL_SOCKET, SO_REUSEADDR, &(int){1}, sizeof(int)); + + if (bind(sd, (struct sockaddr *)&addr, sizeof(addr))) + return -errno; + + if (listen(sd, SOMAXCONN)) + return -errno; + + return sd; +} + +int vsock_get_port(int sd, unsigned int *port) +{ + struct sockaddr_vm addr; + socklen_t addr_len = sizeof(addr); + + if (getsockname(sd, (struct sockaddr *)&addr, &addr_len)) + return -errno; + + if (addr.svm_family != AF_VSOCK) + return -EINVAL; + + if (port) + *port = addr.svm_port; + + return 0; +} + static int get_vsocket_params(int fd, unsigned int *lcid, unsigned int *lport, unsigned int *rcid, unsigned int *rport) { @@ -317,6 +423,35 @@ static int get_vsocket_params(int fd, unsigned int *lcid, unsigned int *lport, return 0; } +#else +static int vsock_open(unsigned int cid, unsigned int port) +{ + warning("vsock is not supported"); + return -ENOTSUP; +} + +static int vsock_make(void) +{ + warning("vsock is not supported"); + return -ENOTSUP; + +} + +static int vsock_get_port(int sd, unsigned int *port) +{ + warning("vsock is not supported"); + return -ENOTSUP; +} + +static int get_vsocket_params(int fd, unsigned int *lcid, unsigned int *lport, + unsigned int *rcid, unsigned int *rport) +{ + warning("vsock is not supported"); + return -ENOTSUP; +} + +#endif + static struct tracefs_instance * clock_synch_create_instance(const char *clock, unsigned int cid) { @@ -437,6 +572,8 @@ void tracecmd_tsync_free(struct tracecmd_time_sync *tsync) pthread_mutex_destroy(&tsync->lock); pthread_cond_destroy(&tsync->cond); free(tsync->clock_str); + free(tsync->proto_name); + free(tsync); } static cpu_set_t *pin_to_cpu(int cpu) @@ -489,8 +626,8 @@ static void restore_pin_to_cpu(cpu_set_t *mask) CPU_FREE(mask); } -int tracecmd_tsync_send(struct tracecmd_time_sync *tsync, - struct tsync_proto *proto, unsigned int cpu) +static int tsync_send(struct tracecmd_time_sync *tsync, + struct tsync_proto *proto, unsigned int cpu) { cpu_set_t *old_set = NULL; long long timestamp = 0; @@ -506,17 +643,7 @@ int tracecmd_tsync_send(struct tracecmd_time_sync *tsync, return ret; } -/** - * tracecmd_tsync_with_host - Synchronize timestamps with host - * - * @tsync: Pointer to time sync context - * - * This API is supposed to be called in guest context. It waits for a time - * sync request from the host and replies with a time sample, until time sync - * stop command is received - * - */ -void tracecmd_tsync_with_host(struct tracecmd_time_sync *tsync) +static void tsync_with_host(struct tracecmd_time_sync *tsync) { char protocol[TRACECMD_TSYNC_PNAME_LENGTH]; struct tsync_probe_request_msg probe; @@ -541,7 +668,7 @@ void tracecmd_tsync_with_host(struct tracecmd_time_sync *tsync) 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, probe.cpu); + ret = tsync_send(tsync, proto, probe.cpu); if (ret) break; } @@ -620,16 +747,7 @@ static inline void get_ts_loop_delay(struct timespec *timeout, int delay_ms) } #define CLOCK_TS_ARRAY 5 -/** - * tracecmd_tsync_with_guest - Synchronize timestamps with guest - * - * @tsync: Pointer to time sync context - * - * This API is supposed to be called in host context, in a separate thread - * It loops infinite, until the timesync semaphore is released - * - */ -void tracecmd_tsync_with_guest(struct tracecmd_time_sync *tsync) +static int tsync_with_guest(struct tracecmd_time_sync *tsync) { struct tsync_probe_request_msg probe; int ts_array_size = CLOCK_TS_ARRAY; @@ -641,7 +759,7 @@ void tracecmd_tsync_with_guest(struct tracecmd_time_sync *tsync) clock_context_init(tsync, &proto, false); if (!tsync->context) - return; + return -1; if (tsync->loop_interval > 0 && tsync->loop_interval < (CLOCK_TS_ARRAY * 1000)) @@ -680,4 +798,350 @@ void tracecmd_tsync_with_guest(struct tracecmd_time_sync *tsync) TRACECMD_TSYNC_PROTO_NONE, TRACECMD_TIME_SYNC_CMD_STOP, 0, NULL); + return 0; +} + +static void *tsync_host_thread(void *data) +{ + struct tracecmd_time_sync *tsync = NULL; + + tsync = (struct tracecmd_time_sync *)data; + tsync_with_guest(tsync); + tracecmd_msg_handle_close(tsync->msg_handle); + tsync->msg_handle = NULL; + + pthread_exit(0); +} + +/** + * tracecmd_tsync_with_guest - Synchronize timestamps with guest + * + * @trace_id: Local ID for the current trace session + * @cid: CID of the guest + * @port: VSOCKET port, on which the guest listens for tsync requests + * @guest_pid: PID of the host OS process, running the guest + * @guest_cpus: Number of the guest VCPUs + * @proto_name: Name of the negotiated time synchronization protocol + * @clock: Trace clock, used for that session + * + * On success, a pointer to time sync context is returned, or NULL in + * case of an error. The context must be freed with tracecmd_tsync_free() + * + * This API is spawns a pthread, which performs time stamps synchronization + * until tracecmd_tsync_with_guest_stop() is called. + */ +struct tracecmd_time_sync * +tracecmd_tsync_with_guest(unsigned long long trace_id, int loop_interval, + unsigned int cid, unsigned int port, int guest_pid, + int guest_cpus, const char *proto_name, const char *clock) +{ + struct tracecmd_time_sync *tsync; + cpu_set_t *pin_mask = NULL; + pthread_attr_t attrib; + size_t mask_size = 0; + int fd = -1; + int ret; + + if (!proto_name) + return NULL; + + tsync = calloc(1, sizeof(*tsync)); + if (!tsync) + return NULL; + + tsync->trace_id = trace_id; + tsync->loop_interval = loop_interval; + tsync->proto_name = strdup(proto_name); + fd = vsock_open(cid, port); + if (fd < 0) + goto error; + + tsync->msg_handle = tracecmd_msg_handle_alloc(fd, 0); + if (!tsync->msg_handle) { + ret = -1; + goto error; + } + tsync->guest_pid = guest_pid; + tsync->vcpu_count = guest_cpus; + + if (clock) + tsync->clock_str = strdup(clock); + pthread_mutex_init(&tsync->lock, NULL); + pthread_cond_init(&tsync->cond, NULL); + pthread_attr_init(&attrib); + pthread_attr_setdetachstate(&attrib, PTHREAD_CREATE_JOINABLE); + + ret = pthread_create(&tsync->thread, &attrib, tsync_host_thread, tsync); + if (ret) + goto error; + tsync->thread_running = true; + + if (!get_first_cpu(&pin_mask, &mask_size)) + pthread_setaffinity_np(tsync->thread, mask_size, pin_mask); + + if (pin_mask) + CPU_FREE(pin_mask); + pthread_attr_destroy(&attrib); + + return tsync; + +error: + if (tsync->msg_handle) + tracecmd_msg_handle_close(tsync->msg_handle); + else if (fd >= 0) + close(fd); + free(tsync); + + return NULL; +} + +/** + * tracecmd_write_guest_time_shift - Write collected timestamp corrections in a file + * + * @handle: Handle to a trace file, where timestamp corrections will be saved + * @tsync: Time sync context with collected timestamp corrections + * + * Returns 0 on success, or -1 in case of an error. + * + * This API writes collected timestamp corrections in the metadata of the + * trace file, as TRACECMD_OPTION_TIME_SHIFT option. + */ +int tracecmd_write_guest_time_shift(struct tracecmd_output *handle, + struct tracecmd_time_sync *tsync) +{ + struct iovec *vector = NULL; + long long *scalings = NULL; + long long *offsets = NULL; + long long *ts = NULL; + unsigned int flags; + int ret = -1; + int vcount; + int count; + int i, j; + + if (!handle || !tsync) + return -1; + if (!tsync->vcpu_count) + return 0; + + vcount = 3 + (4 * tsync->vcpu_count); + vector = calloc(vcount, sizeof(struct iovec)); + if (!vector) + return -1; + ret = tsync_get_proto_flags(tsync, &flags); + if (ret < 0) + goto out; + + j = 0; + vector[j].iov_len = 8; + vector[j++].iov_base = &(tsync->trace_id); + vector[j].iov_len = 4; + vector[j++].iov_base = &flags; + vector[j].iov_len = 4; + vector[j++].iov_base = &tsync->vcpu_count; + for (i = 0; i < tsync->vcpu_count; i++) { + if (j >= vcount) + break; + ret = tracecmd_tsync_get_offsets(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 < tsync->vcpu_count) + goto out; + tracecmd_add_option_v(handle, TRACECMD_OPTION_TIME_SHIFT, vector, vcount); + tracecmd_append_options(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 + ret = 0; +out: + free(vector); + return ret; +} + +/** + * tracecmd_tsync_with_guest_stop - Stop the time sync session with a guest + * + * @tsync: Time sync context, representing a running time sync session + * + * Returns 0 on success, or -1 in case of an error. + * + */ +int tracecmd_tsync_with_guest_stop(struct tracecmd_time_sync *tsync) +{ + if (!tsync || !tsync->thread_running) + return -1; + + /* Signal the time synchronization thread to complete and wait for it */ + pthread_mutex_lock(&tsync->lock); + pthread_cond_signal(&tsync->cond); + pthread_mutex_unlock(&tsync->lock); + pthread_join(tsync->thread, NULL); + return 0; +} + +static void *tsync_agent_thread(void *data) +{ + struct tracecmd_time_sync *tsync = NULL; + int sd; + + tsync = (struct tracecmd_time_sync *)data; + + while (true) { + sd = accept(tsync->msg_handle->fd, NULL, NULL); + if (sd < 0) { + if (errno == EINTR) + continue; + goto out; + } + break; + } + close(tsync->msg_handle->fd); + tsync->msg_handle->fd = sd; + + tsync_with_host(tsync); + +out: + tracecmd_msg_handle_close(tsync->msg_handle); + tracecmd_tsync_free(tsync); + free(tsync); + close(sd); + + pthread_exit(0); +} + +/** + * tracecmd_tsync_with_host - Synchronize timestamps with host + * + * @tsync_protos: List of tsync protocols, supported by the host + * @clock: Trace clock, used for that session + * @port: returned, VSOCKET port, on which the guest listens for tsync requests + * + * On success, a pointer to time sync context is returned, or NULL in + * case of an error. The context must be freed with tracecmd_tsync_free() + * + * This API is spawns a pthread, which performs time stamps synchronization + * until tracecmd_tsync_with_host_stop() is called. + */ +struct tracecmd_time_sync * +tracecmd_tsync_with_host(struct tracecmd_tsync_protos *tsync_protos, + const char *clock) +{ + struct tracecmd_time_sync *tsync = NULL; + cpu_set_t *pin_mask = NULL; + pthread_attr_t attrib; + size_t mask_size = 0; + unsigned int port; + const char *proto; + int ret; + int fd; + + tsync = calloc(1, sizeof(struct tracecmd_time_sync)); + if (!tsync) + return NULL; + + proto = tsync_proto_select(tsync_protos, clock, + TRACECMD_TIME_SYNC_ROLE_GUEST); + if (!proto) + goto error; + tsync->proto_name = strdup(proto); + fd = vsock_make(); + if (fd < 0) + goto error; + + if (vsock_get_port(fd, &port) < 0) + goto error; + tsync->msg_handle = tracecmd_msg_handle_alloc(fd, 0); + if (clock) + tsync->clock_str = strdup(clock); + + pthread_attr_init(&attrib); + tsync->vcpu_count = tracecmd_count_cpus(); + pthread_attr_setdetachstate(&attrib, PTHREAD_CREATE_JOINABLE); + + ret = pthread_create(&tsync->thread, &attrib, tsync_agent_thread, tsync); + if (ret) + goto error; + tsync->thread_running = true; + if (!get_first_cpu(&pin_mask, &mask_size)) + pthread_setaffinity_np(tsync->thread, mask_size, pin_mask); + + if (pin_mask) + CPU_FREE(pin_mask); + pthread_attr_destroy(&attrib); + return tsync; + +error: + if (tsync) { + if (tsync->msg_handle) + tracecmd_msg_handle_close(tsync->msg_handle); + else if (fd >= 0) + close(fd); + free(tsync->clock_str); + free(tsync); + } + + return NULL; + +} + +/** + * tracecmd_tsync_with_host_stop - Stop the time sync session with a host + * + * @tsync: Time sync context, representing a running time sync session + * + * Returns 0 on success, or error number in case of an error. + * + */ +int tracecmd_tsync_with_host_stop(struct tracecmd_time_sync *tsync) +{ + return pthread_join(tsync->thread, NULL); +} + +/** + * tracecmd_tsync_get_session_params - Get parameters of established time sync session + * + * @tsync: Time sync context, representing a running time sync session + * @selected_proto: return, name of the selected time sync protocol for this session + * @tsync_port: return, a VSOCK port on which new time sync requests are accepted. + * + * Returns 0 on success, or error number in case of an error. + * + */ +int tracecmd_tsync_get_session_params(struct tracecmd_time_sync *tsync, + char **selected_proto, + unsigned int *tsync_port) +{ + int ret; + + if (!tsync) + return -1; + + if (tsync_port) { + if (!tsync->msg_handle) + return -1; + ret = vsock_get_port(tsync->msg_handle->fd, tsync_port); + if (ret < 0) + return ret; + } + if (selected_proto) { + if (!tsync->proto_name) + return -1; + (*selected_proto) = strdup(tsync->proto_name); + + } + + return 0; } diff --git a/tracecmd/Makefile b/tracecmd/Makefile index 2b14284b..80c69bbb 100644 --- a/tracecmd/Makefile +++ b/tracecmd/Makefile @@ -36,9 +36,6 @@ TRACE_CMD_OBJS += trace-usage.o TRACE_CMD_OBJS += trace-dump.o TRACE_CMD_OBJS += trace-clear.o TRACE_CMD_OBJS += trace-vm.o -ifeq ($(VSOCK_DEFINED), 1) -TRACE_CMD_OBJS += trace-tsync.o -endif ifeq ($(VSOCK_DEFINED), 1) TRACE_CMD_OBJS += trace-agent.o diff --git a/tracecmd/include/trace-local.h b/tracecmd/include/trace-local.h index 77271712..6e39d27d 100644 --- a/tracecmd/include/trace-local.h +++ b/tracecmd/include/trace-local.h @@ -262,9 +262,8 @@ struct buffer_instance { int *fds; bool use_fifos; - pthread_t tsync_thread; - bool tsync_thread_running; - struct tracecmd_time_sync tsync; + int tsync_loop_interval; + struct tracecmd_time_sync *tsync; }; void init_top_instance(void); diff --git a/tracecmd/trace-agent.c b/tracecmd/trace-agent.c index 36444d32..0edfa60f 100644 --- a/tracecmd/trace-agent.c +++ b/tracecmd/trace-agent.c @@ -143,12 +143,12 @@ static char *get_clock(int argc, char **argv) static void agent_handle(int sd, int nr_cpus, int page_size) { struct tracecmd_tsync_protos *tsync_protos = NULL; + struct tracecmd_time_sync *tsync = NULL; struct tracecmd_msg_handle *msg_handle; - const char *tsync_proto = NULL; + char *tsync_proto = NULL; unsigned long long trace_id; unsigned int tsync_port = 0; unsigned int *ports; - pthread_t sync_thr; char **argv = NULL; int argc = 0; bool use_fifos; @@ -176,10 +176,11 @@ static void agent_handle(int sd, int nr_cpus, int page_size) if (!use_fifos) make_vsocks(nr_cpus, fds, ports); if (tsync_protos && tsync_protos->names) { - tsync_proto = tracecmd_guest_tsync(tsync_protos, - get_clock(argc, argv), - &tsync_port, &sync_thr); - if (!tsync_proto) + tsync = tracecmd_tsync_with_host(tsync_protos, + get_clock(argc, argv)); + if (tsync) + tracecmd_tsync_get_session_params(tsync, &tsync_proto, &tsync_port); + else warning("Failed to negotiate timestamps synchronization with the host"); } trace_id = tracecmd_generate_traceid(); @@ -192,9 +193,10 @@ static void agent_handle(int sd, int nr_cpus, int page_size) trace_record_agent(msg_handle, nr_cpus, fds, argc, argv, use_fifos, trace_id); - if (tsync_proto) - pthread_join(sync_thr, NULL); - + if (tsync) { + tracecmd_tsync_with_host_stop(tsync); + tracecmd_tsync_free(tsync); + } if (tsync_protos) { free(tsync_protos->names); free(tsync_protos); diff --git a/tracecmd/trace-record.c b/tracecmd/trace-record.c index 63e09b57..595f53fd 100644 --- a/tracecmd/trace-record.c +++ b/tracecmd/trace-record.c @@ -665,7 +665,28 @@ static void delete_thread_data(void) } } -#ifdef VSOCK +static void host_tsync_complete(struct buffer_instance *instance) +{ + struct tracecmd_output *handle = NULL; + int fd = -1; + int ret; + + ret = tracecmd_tsync_with_guest_stop(instance->tsync); + if (!ret) { + fd = open(instance->output_file, O_RDWR); + if (fd < 0) + die("error opening %s", instance->output_file); + handle = tracecmd_get_output_handle_fd(fd); + if (!handle) + die("cannot create output handle"); + tracecmd_write_guest_time_shift(handle, instance->tsync); + tracecmd_output_close(handle); + } + + tracecmd_tsync_free(instance->tsync); + instance->tsync = NULL; +} + static void tell_guests_to_stop(void) { struct buffer_instance *instance; @@ -678,7 +699,7 @@ static void tell_guests_to_stop(void) for_all_instances(instance) { if (is_guest(instance)) - tracecmd_host_tsync_complete(instance); + host_tsync_complete(instance); } /* Wait for guests to acknowledge */ @@ -689,11 +710,6 @@ static void tell_guests_to_stop(void) } } } -#else -static inline void tell_guests_to_stop(void) -{ -} -#endif static void stop_threads(enum trace_type type) { @@ -3668,7 +3684,28 @@ static int open_guest_fifos(const char *guest, int **fds) return i; } -#ifdef VSOCK +static int host_tsync(struct buffer_instance *instance, + unsigned int tsync_port, char *proto) +{ + struct trace_guest *guest; + + if (!proto) + return -1; + guest = get_guest_by_cid(instance->cid); + if (guest == NULL) + return -1; + + instance->tsync = tracecmd_tsync_with_guest(top_instance.trace_id, + instance->tsync_loop_interval, + instance->cid, tsync_port, + guest->pid, guest->cpu_max, + proto, top_instance.clock); + if (!instance->tsync) + return -1; + + return 0; +} + static void connect_to_agent(struct buffer_instance *instance) { struct tracecmd_tsync_protos *protos = NULL; @@ -3697,7 +3734,7 @@ static void connect_to_agent(struct buffer_instance *instance) if (!instance->clock) instance->clock = tracefs_get_clock(NULL); - if (instance->tsync.loop_interval >= 0) + if (instance->tsync_loop_interval >= 0) tracecmd_tsync_proto_getall(&protos, instance->clock, TRACECMD_TIME_SYNC_ROLE_HOST); @@ -3719,11 +3756,10 @@ static void connect_to_agent(struct buffer_instance *instance) die("Failed to receive trace response %d", ret); if (tsync_protos_reply && tsync_protos_reply[0]) { if (tsync_proto_is_supported(tsync_protos_reply)) { - instance->tsync.proto_name = strdup(tsync_protos_reply); printf("Negotiated %s time sync protocol with guest %s\n", - instance->tsync.proto_name, + tsync_protos_reply, instance->name); - tracecmd_host_tsync(instance, tsync_port); + host_tsync(instance, tsync_port, tsync_protos_reply); } else warning("Failed to negotiate timestamps synchronization with the guest"); } @@ -3751,12 +3787,6 @@ static void connect_to_agent(struct buffer_instance *instance) /* the msg_handle now points to the guest fd */ instance->msg_handle = msg_handle; } -#else -static inline void connect_to_agent(struct buffer_instance *instance) -{ -} -#endif - static void setup_guest(struct buffer_instance *instance) { @@ -6087,7 +6117,7 @@ static void parse_record_options(int argc, break; case OPT_tsyncinterval: cmd_check_die(ctx, CMD_set, *(argv+1), "--tsync-interval"); - top_instance.tsync.loop_interval = atoi(optarg); + top_instance.tsync_loop_interval = atoi(optarg); guest_sync_set = true; break; case OPT_fork: @@ -6132,7 +6162,7 @@ static void parse_record_options(int argc, } } } - instance->tsync.loop_interval = top_instance.tsync.loop_interval; + instance->tsync_loop_interval = top_instance.tsync_loop_interval; } } diff --git a/tracecmd/trace-tsync.c b/tracecmd/trace-tsync.c deleted file mode 100644 index d7de8298..00000000 --- a/tracecmd/trace-tsync.c +++ /dev/null @@ -1,319 +0,0 @@ -// SPDX-License-Identifier: GPL-2.0 -/* - * Copyright (C) 2019, VMware, Tzvetomir Stoyanov - * - */ -#include -#include -#include -#include -#include -#include -#include - -#include "tracefs.h" -#include "trace-local.h" -#include "trace-msg.h" - -static int get_first_cpu(cpu_set_t **pin_mask, size_t *m_size) -{ - int cpus = tracecmd_count_cpus(); - cpu_set_t *cpu_mask; - int mask_size; - int i; - - cpu_mask = CPU_ALLOC(cpus); - *pin_mask = CPU_ALLOC(cpus); - if (!cpu_mask || !*pin_mask || 1) - goto error; - - mask_size = CPU_ALLOC_SIZE(cpus); - CPU_ZERO_S(mask_size, cpu_mask); - CPU_ZERO_S(mask_size, *pin_mask); - - if (sched_getaffinity(0, mask_size, cpu_mask) == -1) - goto error; - - for (i = 0; i < cpus; i++) { - if (CPU_ISSET_S(i, mask_size, cpu_mask)) { - CPU_SET_S(i, mask_size, *pin_mask); - break; - } - } - - if (CPU_COUNT_S(mask_size, *pin_mask) < 1) - goto error; - - CPU_FREE(cpu_mask); - *m_size = mask_size; - return 0; - -error: - if (cpu_mask) - CPU_FREE(cpu_mask); - if (*pin_mask) - CPU_FREE(*pin_mask); - *pin_mask = NULL; - *m_size = 0; - return -1; -} - -static void *tsync_host_thread(void *data) -{ - struct tracecmd_time_sync *tsync = NULL; - - tsync = (struct tracecmd_time_sync *)data; - - tracecmd_tsync_with_guest(tsync); - - tracecmd_msg_handle_close(tsync->msg_handle); - tsync->msg_handle = NULL; - - pthread_exit(0); -} - -int tracecmd_host_tsync(struct buffer_instance *instance, - unsigned int tsync_port) -{ - struct tracecmd_msg_handle *msg_handle = NULL; - cpu_set_t *pin_mask = NULL; - struct trace_guest *guest; - pthread_attr_t attrib; - size_t mask_size = 0; - int ret; - int fd; - - if (!instance->tsync.proto_name) - return -1; - guest = get_guest_by_cid(instance->cid); - if (guest == NULL) - return -1; - instance->tsync.guest_pid = guest->pid; - instance->tsync.vcpu_count = guest->cpu_max; - fd = trace_open_vsock(instance->cid, tsync_port); - if (fd < 0) { - ret = -1; - goto out; - } - msg_handle = tracecmd_msg_handle_alloc(fd, 0); - if (!msg_handle) { - ret = -1; - goto out; - } - - instance->tsync.msg_handle = msg_handle; - if (top_instance.clock) - instance->tsync.clock_str = strdup(top_instance.clock); - pthread_mutex_init(&instance->tsync.lock, NULL); - pthread_cond_init(&instance->tsync.cond, NULL); - - pthread_attr_init(&attrib); - pthread_attr_setdetachstate(&attrib, PTHREAD_CREATE_JOINABLE); - - ret = pthread_create(&instance->tsync_thread, &attrib, - tsync_host_thread, &instance->tsync); - - if (!ret) { - if (!get_first_cpu(&pin_mask, &mask_size)) - pthread_setaffinity_np(instance->tsync_thread, mask_size, pin_mask); - instance->tsync_thread_running = true; - } - - if (pin_mask) - CPU_FREE(pin_mask); - pthread_attr_destroy(&attrib); - -out: - if (ret) { - if (msg_handle) - tracecmd_msg_handle_close(msg_handle); - } - - return ret; -} - -static void write_guest_time_shift(struct buffer_instance *instance) -{ - 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; - - 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) - 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); - 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); -#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) -{ - if (!instance->tsync_thread_running) - return; - - /* Signal the time synchronization thread to complete and wait for it */ - pthread_mutex_lock(&instance->tsync.lock); - pthread_cond_signal(&instance->tsync.cond); - pthread_mutex_unlock(&instance->tsync.lock); - pthread_join(instance->tsync_thread, NULL); - write_guest_time_shift(instance); - tracecmd_tsync_free(&instance->tsync); -} - -static void *tsync_agent_thread(void *data) -{ - struct tracecmd_time_sync *tsync = NULL; - int sd; - - tsync = (struct tracecmd_time_sync *)data; - - while (true) { - sd = accept(tsync->msg_handle->fd, NULL, NULL); - if (sd < 0) { - if (errno == EINTR) - continue; - goto out; - } - break; - } - close(tsync->msg_handle->fd); - tsync->msg_handle->fd = sd; - - tracecmd_tsync_with_host(tsync); - -out: - tracecmd_msg_handle_close(tsync->msg_handle); - tracecmd_tsync_free(tsync); - free(tsync); - close(sd); - - pthread_exit(0); -} - -const char *tracecmd_guest_tsync(struct tracecmd_tsync_protos *tsync_protos, - char *clock, unsigned int *tsync_port, - pthread_t *thr_id) -{ - struct tracecmd_time_sync *tsync = NULL; - cpu_set_t *pin_mask = NULL; - pthread_attr_t attrib; - size_t mask_size = 0; - const char *proto; - int ret; - int fd; - - fd = -1; - proto = tracecmd_tsync_proto_select(tsync_protos, clock, - TRACECMD_TIME_SYNC_ROLE_GUEST); - if (!proto) - return NULL; -#ifdef VSOCK - fd = trace_make_vsock(VMADDR_PORT_ANY); - if (fd < 0) - goto error; - - ret = trace_get_vsock_port(fd, tsync_port); - if (ret < 0) - goto error; -#else - return NULL; -#endif - - tsync = calloc(1, sizeof(struct tracecmd_time_sync)); - if (!tsync) - goto error; - tsync->msg_handle = tracecmd_msg_handle_alloc(fd, 0); - if (clock) - tsync->clock_str = strdup(clock); - - 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); - - if (!ret) { - if (!get_first_cpu(&pin_mask, &mask_size)) - pthread_setaffinity_np(*thr_id, mask_size, pin_mask); - } - - if (pin_mask) - CPU_FREE(pin_mask); - pthread_attr_destroy(&attrib); - - if (ret) - goto error; - - return proto; - -error: - if (tsync) { - if (tsync->msg_handle) - tracecmd_msg_handle_close(tsync->msg_handle); - free(tsync->clock_str); - free(tsync); - } - if (fd > 0) - close(fd); - return NULL; -} From patchwork Thu Mar 11 08:48:45 2021 Content-Type: text/plain; charset="utf-8" MIME-Version: 1.0 Content-Transfer-Encoding: 7bit X-Patchwork-Submitter: "Tzvetomir Stoyanov (VMware)" X-Patchwork-Id: 12130611 Return-Path: X-Spam-Checker-Version: SpamAssassin 3.4.0 (2014-02-07) on aws-us-west-2-korg-lkml-1.web.codeaurora.org X-Spam-Level: X-Spam-Status: No, score=-15.8 required=3.0 tests=BAYES_00,DKIM_SIGNED, DKIM_VALID,DKIM_VALID_AU,FREEMAIL_FORGED_FROMDOMAIN,FREEMAIL_FROM, HEADER_FROM_DIFFERENT_DOMAINS,INCLUDES_CR_TRAILER,INCLUDES_PATCH, MAILING_LIST_MULTI,SPF_HELO_NONE,SPF_PASS,USER_AGENT_GIT autolearn=ham autolearn_force=no version=3.4.0 Received: from mail.kernel.org (mail.kernel.org [198.145.29.99]) by smtp.lore.kernel.org (Postfix) with ESMTP id E1FCDC4332E for ; Thu, 11 Mar 2021 08:49:17 +0000 (UTC) Received: from vger.kernel.org (vger.kernel.org [23.128.96.18]) by mail.kernel.org (Postfix) with ESMTP id 8F56B64FD8 for ; Thu, 11 Mar 2021 08:49:17 +0000 (UTC) Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S231426AbhCKItR (ORCPT ); Thu, 11 Mar 2021 03:49:17 -0500 Received: from lindbergh.monkeyblade.net ([23.128.96.19]:42736 "EHLO lindbergh.monkeyblade.net" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S231735AbhCKItL (ORCPT ); Thu, 11 Mar 2021 03:49:11 -0500 Received: from mail-ej1-x632.google.com (mail-ej1-x632.google.com [IPv6:2a00:1450:4864:20::632]) by lindbergh.monkeyblade.net (Postfix) with ESMTPS id 0E8DCC061760 for ; Thu, 11 Mar 2021 00:49:11 -0800 (PST) Received: by mail-ej1-x632.google.com with SMTP id e19so44591358ejt.3 for ; Thu, 11 Mar 2021 00:49:10 -0800 (PST) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=gmail.com; s=20161025; h=from:to:cc:subject:date:message-id:in-reply-to:references :mime-version:content-transfer-encoding; bh=995If0yn/GvAjPK8BEWKuXaVZs/c2n3wjtKJKEMASog=; b=TRCUYff7Jvw9ECQ9l+YAUYQNfO/hpaL3jRQqUWon/mQ8QhbGLdI6+1lrh21h+S4urz XRZ5mbpATWeUbjbhbytUMCwzq1S+cVu1t+ZClxdwF11q7l+rjkFaqgWN6ulFVeKKtlsd /+n4RyM36sCxQS3l3O+uTxN/aLFEuFXgpxb7tWs7lRoAEfBcDzh28hL/EvUdGlYMUE8T Ual0nqWeGfKcuXXbhKvffirMQ4wem1wYc27h1TUDnYTjOwkr8sRAYTPV3uJc2PQWacE8 ui1KXuyVkZi1lDoYiIxWj/KZiMQoh4fHap/NnltsTBUUkeMOBsbyxCSZi8h94wQld+tJ ZMMA== X-Google-DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=1e100.net; s=20161025; h=x-gm-message-state:from:to:cc:subject:date:message-id:in-reply-to :references:mime-version:content-transfer-encoding; bh=995If0yn/GvAjPK8BEWKuXaVZs/c2n3wjtKJKEMASog=; b=R1gxF8WzdQWhJPfDmtLPcBmCqqQT98QS7CZDGfLkuKoHrBthlDhyRhW1qAc6t/HceZ UHwIKw1BbShrwuqHt6a1Q86ncYD95gZsF8oNd1v9VUfWmd/NdS44cjVQkGMPevTSB1Bn DjcwmqyOeJ/tnsJCdQVNNO/DH5VwZHepT/Pt8iQh5jmbsMcuuRop7KF6hZtMQEACQlM5 fFVGWkNfmpxzDX5YOJshjyWKgNfNvpve6OHwTBLlbDa0eWKyFaqdatbqR/g2lrx8ZJZf CHppKSYkE6L/M/jSa1oPrbpYDtVXOIUI6/hMXKrXRsRRn5Tj1Beb5dpc84GJTOFQWOG8 f+ag== X-Gm-Message-State: AOAM533SADHGhGAb8BS47N0R787+Y3CYVIwFrj1bAV3yX7xvBPQc2Pyj PwBhR8A2PVW21KQor4/Jut0= X-Google-Smtp-Source: ABdhPJySY7qfguw1fHI35i9nuKXNpyHaUG7vzm5oyKRjplbV9xBFEVC6tmblVpKHx1Q7OQpljZQjWQ== X-Received: by 2002:a17:906:c402:: with SMTP id u2mr2017765ejz.546.1615452549791; Thu, 11 Mar 2021 00:49:09 -0800 (PST) Received: from oberon.zico.biz ([83.222.187.186]) by smtp.gmail.com with ESMTPSA id fi11sm901647ejb.73.2021.03.11.00.49.09 (version=TLS1_3 cipher=TLS_AES_256_GCM_SHA384 bits=256/256); Thu, 11 Mar 2021 00:49:09 -0800 (PST) From: "Tzvetomir Stoyanov (VMware)" To: rostedt@goodmis.org Cc: linux-trace-devel@vger.kernel.org Subject: [PATCH v31 04/16] trace-cmd: Wait for first time sync before the trace Date: Thu, 11 Mar 2021 10:48:45 +0200 Message-Id: <20210311084857.1919805-5-tz.stoyanov@gmail.com> X-Mailer: git-send-email 2.29.2 In-Reply-To: <20210311084857.1919805-1-tz.stoyanov@gmail.com> References: <20210311084857.1919805-1-tz.stoyanov@gmail.com> MIME-Version: 1.0 Precedence: bulk List-ID: X-Mailing-List: linux-trace-devel@vger.kernel.org Added a barrier in time synchronization threads to ensure the first time synchronization passed before to start the trace. Signed-off-by: Tzvetomir Stoyanov (VMware) --- lib/trace-cmd/trace-timesync.c | 15 ++++++++++++++- 1 file changed, 14 insertions(+), 1 deletion(-) diff --git a/lib/trace-cmd/trace-timesync.c b/lib/trace-cmd/trace-timesync.c index d38ee975..1e8ba509 100644 --- a/lib/trace-cmd/trace-timesync.c +++ b/lib/trace-cmd/trace-timesync.c @@ -571,6 +571,7 @@ void tracecmd_tsync_free(struct tracecmd_time_sync *tsync) } pthread_mutex_destroy(&tsync->lock); pthread_cond_destroy(&tsync->cond); + pthread_barrier_destroy(&tsync->first_sync); free(tsync->clock_str); free(tsync->proto_name); free(tsync); @@ -753,6 +754,7 @@ static int tsync_with_guest(struct tracecmd_time_sync *tsync) int ts_array_size = CLOCK_TS_ARRAY; struct tsync_proto *proto; struct timespec timeout; + bool first = true; bool end = false; int ret; int i; @@ -777,6 +779,10 @@ static int tsync_with_guest(struct tracecmd_time_sync *tsync) if (ret) break; } + if (first) { + first = false; + pthread_barrier_wait(&tsync->first_sync); + } if (end || i < tsync->vcpu_count) break; if (tsync->loop_interval > 0) { @@ -804,12 +810,17 @@ static int tsync_with_guest(struct tracecmd_time_sync *tsync) static void *tsync_host_thread(void *data) { struct tracecmd_time_sync *tsync = NULL; + int ret; tsync = (struct tracecmd_time_sync *)data; - tsync_with_guest(tsync); + ret = tsync_with_guest(tsync); tracecmd_msg_handle_close(tsync->msg_handle); tsync->msg_handle = NULL; + /* tsync with guest failed, release the barrier */ + if (ret) + pthread_barrier_wait(&tsync->first_sync); + pthread_exit(0); } @@ -868,6 +879,7 @@ tracecmd_tsync_with_guest(unsigned long long trace_id, int loop_interval, tsync->clock_str = strdup(clock); pthread_mutex_init(&tsync->lock, NULL); pthread_cond_init(&tsync->cond, NULL); + pthread_barrier_init(&tsync->first_sync, NULL, 2); pthread_attr_init(&attrib); pthread_attr_setdetachstate(&attrib, PTHREAD_CREATE_JOINABLE); @@ -878,6 +890,7 @@ tracecmd_tsync_with_guest(unsigned long long trace_id, int loop_interval, if (!get_first_cpu(&pin_mask, &mask_size)) pthread_setaffinity_np(tsync->thread, mask_size, pin_mask); + pthread_barrier_wait(&tsync->first_sync); if (pin_mask) CPU_FREE(pin_mask); From patchwork Thu Mar 11 08:48:46 2021 Content-Type: text/plain; charset="utf-8" MIME-Version: 1.0 Content-Transfer-Encoding: 7bit X-Patchwork-Submitter: "Tzvetomir Stoyanov (VMware)" X-Patchwork-Id: 12130617 Return-Path: X-Spam-Checker-Version: SpamAssassin 3.4.0 (2014-02-07) on aws-us-west-2-korg-lkml-1.web.codeaurora.org X-Spam-Level: X-Spam-Status: No, score=-15.8 required=3.0 tests=BAYES_00,DKIM_SIGNED, DKIM_VALID,DKIM_VALID_AU,FREEMAIL_FORGED_FROMDOMAIN,FREEMAIL_FROM, HEADER_FROM_DIFFERENT_DOMAINS,INCLUDES_CR_TRAILER,INCLUDES_PATCH, MAILING_LIST_MULTI,SPF_HELO_NONE,SPF_PASS,USER_AGENT_GIT autolearn=ham autolearn_force=no version=3.4.0 Received: from mail.kernel.org (mail.kernel.org [198.145.29.99]) by smtp.lore.kernel.org (Postfix) with ESMTP id 4D56BC4332D for ; Thu, 11 Mar 2021 08:49:18 +0000 (UTC) Received: from vger.kernel.org (vger.kernel.org [23.128.96.18]) by mail.kernel.org (Postfix) with ESMTP id 09CDF64FB0 for ; Thu, 11 Mar 2021 08:49:17 +0000 (UTC) Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S231694AbhCKItR (ORCPT ); Thu, 11 Mar 2021 03:49:17 -0500 Received: from lindbergh.monkeyblade.net ([23.128.96.19]:42744 "EHLO lindbergh.monkeyblade.net" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S231736AbhCKItM (ORCPT ); Thu, 11 Mar 2021 03:49:12 -0500 Received: from mail-ej1-x62c.google.com (mail-ej1-x62c.google.com [IPv6:2a00:1450:4864:20::62c]) by lindbergh.monkeyblade.net (Postfix) with ESMTPS id 4E7C8C061574 for ; Thu, 11 Mar 2021 00:49:12 -0800 (PST) Received: by mail-ej1-x62c.google.com with SMTP id p7so33161224eju.6 for ; Thu, 11 Mar 2021 00:49:12 -0800 (PST) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=gmail.com; s=20161025; h=from:to:cc:subject:date:message-id:in-reply-to:references :mime-version:content-transfer-encoding; bh=eIhwU6/lXs3epbTMCYsXYPl8hvwg6uT8p+k9Q2LmtrY=; b=SDx2iBkuookAhPlol3giOTdFF7Ei83qMbfsl38Yo94UgnER4mrqUTad6ZM6ICh93l+ H6LggQty1UbX/dLtvZ0UX5aJS8c+67zjjvsocX8cFZ+5YR94oPi+/6LVe09l7+xXOmyO W05YcRL8BBDkecuzBaZXtQiELHWrRYYgTZhBmrijpdHfhG5P/BpWPvSq6xhMh565c44v ZLd86dTE61MCXPV26MTDevVAH7a8zTyRzMznEslVwEhC15Z5GQI5jGv/DTFeTY+QkHhy SSFPH2EYvDpakHKZVLOJ2tH78cQIjCYHYiIeCUvxgEFt2QMTjLhm39QhwoCqfqRGddfn DPZw== X-Google-DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=1e100.net; s=20161025; h=x-gm-message-state:from:to:cc:subject:date:message-id:in-reply-to :references:mime-version:content-transfer-encoding; bh=eIhwU6/lXs3epbTMCYsXYPl8hvwg6uT8p+k9Q2LmtrY=; b=olUyKcg+wBWeVwieW99XFPBxnvY0kHPT/ZpwhM5/VLUmSP7Z9Ptt5S4xMXx0DR35nE EWS79gkncpgPSxJ0+s8sb2LSxp6BHRjy72z0Be4gkjsnsO9CgM4hKYwrxv+CbC3vkdS3 bPED4eABEfQUCcpNZCg3LWpqD91ZS1W/yFOqWNYBR6jxZQj6NkYYkr1OAjes64SXKqEg 9eTb9yc5LHQNGvqih4B/gcnUf7IHPb6EUwWKPOxwuEGqF8vvd44zGZF22OEsXX4PxRHj udKtNBMBZI949J05Ywu8HvTHD6iUyd220XRp9AhPzbFk6NJ4WD4Z1Ut52bGng7sYaYeT Or2Q== X-Gm-Message-State: AOAM533SihNkxB/rUxZnjBaLOOW+Z7oV5d4p1knMf6F55ZbS1KY9ha+T K8oTcRGPpiWNMNyrU+H5XxI= X-Google-Smtp-Source: ABdhPJx0gY8OAeSocscYDbzXaytqV/QkVZsRQaMLtshKFlm/6qR3hlqc/nUpFWu1aDzn+EojHscWng== X-Received: by 2002:a17:907:3e8b:: with SMTP id hs11mr2007707ejc.117.1615452550950; Thu, 11 Mar 2021 00:49:10 -0800 (PST) Received: from oberon.zico.biz ([83.222.187.186]) by smtp.gmail.com with ESMTPSA id fi11sm901647ejb.73.2021.03.11.00.49.09 (version=TLS1_3 cipher=TLS_AES_256_GCM_SHA384 bits=256/256); Thu, 11 Mar 2021 00:49:10 -0800 (PST) From: "Tzvetomir Stoyanov (VMware)" To: rostedt@goodmis.org Cc: linux-trace-devel@vger.kernel.org Subject: [PATCH v31 05/16] trace-cmd: PTP-like algorithm for host - guest timestamp synchronization Date: Thu, 11 Mar 2021 10:48:46 +0200 Message-Id: <20210311084857.1919805-6-tz.stoyanov@gmail.com> X-Mailer: git-send-email 2.29.2 In-Reply-To: <20210311084857.1919805-1-tz.stoyanov@gmail.com> References: <20210311084857.1919805-1-tz.stoyanov@gmail.com> MIME-Version: 1.0 Precedence: bulk List-ID: X-Mailing-List: linux-trace-devel@vger.kernel.org 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) --- lib/trace-cmd/Makefile | 3 + lib/trace-cmd/trace-timesync-ptp.c | 715 +++++++++++++++++++++++++++++ lib/trace-cmd/trace-timesync.c | 4 +- 3 files changed, 721 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 2f553ed5..e66c7b5f 100644 --- a/lib/trace-cmd/Makefile +++ b/lib/trace-cmd/Makefile @@ -18,6 +18,9 @@ OBJS += trace-filter-hash.o OBJS += trace-msg.o OBJS += trace-plugin.o OBJS += trace-timesync.o +ifeq ($(VSOCK_DEFINED), 1) +OBJS += trace-timesync-ptp.o +endif # Additional util objects OBJS += trace-blk-hack.o 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 +#include +#include +#include +#include +#include +#include +#include +#include +#include + +#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//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 1e8ba509..f939d34b 100644 --- a/lib/trace-cmd/trace-timesync.c +++ b/lib/trace-cmd/trace-timesync.c @@ -64,7 +64,9 @@ static struct tsync_proto *tsync_proto_find(const char *proto_name) */ void tracecmd_tsync_init(void) { - +#ifdef VSOCK + ptp_clock_sync_register(); +#endif } int tracecmd_tsync_proto_register(const char *proto_name, int accuracy, int roles, From patchwork Thu Mar 11 08:48:47 2021 Content-Type: text/plain; charset="utf-8" MIME-Version: 1.0 Content-Transfer-Encoding: 7bit X-Patchwork-Submitter: "Tzvetomir Stoyanov (VMware)" X-Patchwork-Id: 12130615 Return-Path: X-Spam-Checker-Version: SpamAssassin 3.4.0 (2014-02-07) on aws-us-west-2-korg-lkml-1.web.codeaurora.org X-Spam-Level: X-Spam-Status: No, score=-15.7 required=3.0 tests=BAYES_00,DKIM_SIGNED, DKIM_VALID,DKIM_VALID_AU,FREEMAIL_FORGED_FROMDOMAIN,FREEMAIL_FROM, HEADER_FROM_DIFFERENT_DOMAINS,INCLUDES_CR_TRAILER,INCLUDES_PATCH, MAILING_LIST_MULTI,SPF_HELO_NONE,SPF_PASS,URIBL_BLOCKED,USER_AGENT_GIT autolearn=ham autolearn_force=no version=3.4.0 Received: from mail.kernel.org (mail.kernel.org [198.145.29.99]) by smtp.lore.kernel.org (Postfix) with ESMTP id 78AF9C433DB for ; Thu, 11 Mar 2021 08:49:18 +0000 (UTC) Received: from vger.kernel.org (vger.kernel.org [23.128.96.18]) by mail.kernel.org (Postfix) with ESMTP id 3C1D764FB1 for ; Thu, 11 Mar 2021 08:49:18 +0000 (UTC) Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S231713AbhCKItS (ORCPT ); Thu, 11 Mar 2021 03:49:18 -0500 Received: from lindbergh.monkeyblade.net ([23.128.96.19]:42746 "EHLO lindbergh.monkeyblade.net" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S231738AbhCKItN (ORCPT ); Thu, 11 Mar 2021 03:49:13 -0500 Received: from mail-ej1-x634.google.com (mail-ej1-x634.google.com [IPv6:2a00:1450:4864:20::634]) by lindbergh.monkeyblade.net (Postfix) with ESMTPS id F3F15C061574 for ; Thu, 11 Mar 2021 00:49:12 -0800 (PST) Received: by mail-ej1-x634.google.com with SMTP id lr13so44567387ejb.8 for ; Thu, 11 Mar 2021 00:49:12 -0800 (PST) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=gmail.com; s=20161025; h=from:to:cc:subject:date:message-id:in-reply-to:references :mime-version:content-transfer-encoding; bh=IenKFzFG83xtDGf9KkCaQpGW0t9/z9lSzSq7mZfH8BY=; b=lQGOss9nxzPESurH/opJGPiSQQ5/w9Kive2h9Koms/8jRcRyUdLskPJkkxeHi4vR4V krn8CaMTsrviODmRh05a+auZQ5V6y97HhnSLXQLCMZpJdb4UoIsyYezD9zStsb31lLJx fmntWsB/alIGXaRt4DaIY5OK2dKBxfWABJZp7tCZp6ceUXk44N+GKW4OgJSCCtWycJu5 W1njg/FnEQVnDlAx1oN7GGozNmqN8Tvck7uqa8ZR6UJV3XSfE8OS2vdKQ8+sV72LsWfF upFCLCZBnJWdqzHi8jG5RyxpocLElfD1bjA9fjtxn/tCk5O+VNhzElVcT9CMJ/5HIgo7 xXew== X-Google-DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=1e100.net; s=20161025; h=x-gm-message-state:from:to:cc:subject:date:message-id:in-reply-to :references:mime-version:content-transfer-encoding; bh=IenKFzFG83xtDGf9KkCaQpGW0t9/z9lSzSq7mZfH8BY=; b=dobFpvoUPXjVu2WkBHpdkBvo+7rC6tIDLuywBTziYfp2fMrL3HPlx/UnYx1+6Fo4Uy tK936KUogDtCv2qQaZmMUAp1aowr1WQkLzceoLQqquWzmg8YWGxXXDJSbFg/TXQOuARy 0hIip3jykJfsr3cvlTAPLBw0bhj4vtbLLyQxhs7KJCOs2JfodDF6HmX3ew3Q0b7yRyQY yzRu36DG45OGcXBtbybkT71UnnUKOSBOzKJ2ofJXPrO6HDXa24QB7fO+hIWYxu+/qYsh 9GRFk20zhX0YGGtX0bCzr4rtCIcDjFFyTZ3j3NoIhUkOO5mqs90PV5VsIGBEs0GfwUDc nTSw== X-Gm-Message-State: AOAM533nUar4jT/f+MI3OdXkr5QyFqvL/9jHJRrI+fch1nZSVD7Kcpr9 Z9cE7nA8Gp4VZtJl1YZKP9Y= X-Google-Smtp-Source: ABdhPJyn2hU+HA23p2AZrwkQ5ZoDV44TpvJ8jL8shUZOWo6v0qmOyzfyCPAVVuX+QBJaR49WjqQl+Q== X-Received: by 2002:a17:906:260a:: with SMTP id h10mr2084238ejc.392.1615452551782; Thu, 11 Mar 2021 00:49:11 -0800 (PST) Received: from oberon.zico.biz ([83.222.187.186]) by smtp.gmail.com with ESMTPSA id fi11sm901647ejb.73.2021.03.11.00.49.11 (version=TLS1_3 cipher=TLS_AES_256_GCM_SHA384 bits=256/256); Thu, 11 Mar 2021 00:49:11 -0800 (PST) From: "Tzvetomir Stoyanov (VMware)" To: rostedt@goodmis.org Cc: linux-trace-devel@vger.kernel.org Subject: [PATCH v31 06/16] trace-cmd: Debug scripts for PTP-like algorithm for host - guest timestamp synchronization Date: Thu, 11 Mar 2021 10:48:47 +0200 Message-Id: <20210311084857.1919805-7-tz.stoyanov@gmail.com> X-Mailer: git-send-email 2.29.2 In-Reply-To: <20210311084857.1919805-1-tz.stoyanov@gmail.com> References: <20210311084857.1919805-1-tz.stoyanov@gmail.com> MIME-Version: 1.0 Precedence: bulk List-ID: X-Mailing-List: linux-trace-devel@vger.kernel.org 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) --- 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 +# Copyright (C) 2019, VMware Inc, Yordan Karadzhov + + +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 +# Copyright (C) 2019, VMware Inc, Yordan Karadzhov + + +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() From patchwork Thu Mar 11 08:48:48 2021 Content-Type: text/plain; charset="utf-8" MIME-Version: 1.0 Content-Transfer-Encoding: 7bit X-Patchwork-Submitter: "Tzvetomir Stoyanov (VMware)" X-Patchwork-Id: 12130629 Return-Path: X-Spam-Checker-Version: SpamAssassin 3.4.0 (2014-02-07) on aws-us-west-2-korg-lkml-1.web.codeaurora.org X-Spam-Level: X-Spam-Status: No, score=-15.8 required=3.0 tests=BAYES_00,DKIM_SIGNED, DKIM_VALID,DKIM_VALID_AU,FREEMAIL_FORGED_FROMDOMAIN,FREEMAIL_FROM, HEADER_FROM_DIFFERENT_DOMAINS,INCLUDES_CR_TRAILER,INCLUDES_PATCH, MAILING_LIST_MULTI,SPF_HELO_NONE,SPF_PASS,USER_AGENT_GIT autolearn=ham autolearn_force=no version=3.4.0 Received: from mail.kernel.org (mail.kernel.org [198.145.29.99]) by smtp.lore.kernel.org (Postfix) with ESMTP id 55260C433E9 for ; Thu, 11 Mar 2021 08:49:48 +0000 (UTC) Received: from vger.kernel.org (vger.kernel.org [23.128.96.18]) by mail.kernel.org (Postfix) with ESMTP id 1A98364FB8 for ; Thu, 11 Mar 2021 08:49:48 +0000 (UTC) Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S231630AbhCKItS (ORCPT ); Thu, 11 Mar 2021 03:49:18 -0500 Received: from lindbergh.monkeyblade.net ([23.128.96.19]:42754 "EHLO lindbergh.monkeyblade.net" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S231438AbhCKItO (ORCPT ); Thu, 11 Mar 2021 03:49:14 -0500 Received: from mail-ej1-x630.google.com (mail-ej1-x630.google.com [IPv6:2a00:1450:4864:20::630]) by lindbergh.monkeyblade.net (Postfix) with ESMTPS id 59E94C061574 for ; Thu, 11 Mar 2021 00:49:14 -0800 (PST) Received: by mail-ej1-x630.google.com with SMTP id ci14so44404976ejc.7 for ; Thu, 11 Mar 2021 00:49:14 -0800 (PST) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=gmail.com; s=20161025; h=from:to:cc:subject:date:message-id:in-reply-to:references :mime-version:content-transfer-encoding; bh=J40eKfuD0b2cNoHAq2VVIuDOkmFXKemgjKwRDIHqxZE=; b=eAY9S2gC8633HeJ326VSemvO6F/49D2EWYbZPDZlf+42CMqvBmx9E7nSfkOTu7naOI PLFGwKk52I4L+mxkXRdPLRnV4RePCb9txSwgiYzVbNyCuIsbORUuEgn6t88xkKJU4kIQ B2dADIFhKVllv51DjPr/cP2IKw6ad9PgBBFKqYd40f3BemecHbmb0ZAlaqhUc7ArwxK9 D9DwTSDRQYjZ+i/AVO+YuV+HebIkhRWwvjrm4uxX60YqO/WVZFH3kKAgdN3Kf4l1JMHh 6gOqJi1X6bo49CN7UfPakzMdwVDLEbN3ijyjuBqCbPFRGqGRbhTidg8G69W/xD7KisDm 5nGg== X-Google-DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=1e100.net; s=20161025; h=x-gm-message-state:from:to:cc:subject:date:message-id:in-reply-to :references:mime-version:content-transfer-encoding; bh=J40eKfuD0b2cNoHAq2VVIuDOkmFXKemgjKwRDIHqxZE=; b=KAePBPB1r3aqHjN3rFskBJfUvl0clmjyoh2R56jbpRAOMFxYnKaLmOT1kMygW3bQ7b nSFHc7XkzctT0P1Nq9eCwqkVI3W1DZYpa3KrvHIvgfe72XBxYnwnWYoiA1ZIOz8ZsL29 krotv5pEZBwHGnbt7aLuNzk3PZeUrBHy+6b72/l02UTW4q5xmeVu64CaG+ga/Avkhxw+ ukQpDBU/wmKuYzfW3UdEtR5pJtNr/Awmi/GtsCn0EJBpO8KaWsj6RGLQAI//6X87AeJZ gjXP6pdk1gZLvmH/1EYhjiNRmIDhe0mXWSBsY46Wc+FVaNU4tomjYE1d1pLeJBPh1KxA RefQ== X-Gm-Message-State: AOAM533AJkm0WPV4gcQ0q/dGzTXpV1rWA0zlh+jhPG4ow7eFusCt4WtL eSjjqlgQT5j4uGAfJWhbMMA= X-Google-Smtp-Source: ABdhPJwhMLO76J3lBg5MacFrsIX9jLw/nHbalBKVzoIFDMNEM/kn+5nFtoj5RBQe8eAqg+9wP3XQDg== X-Received: by 2002:a17:906:2803:: with SMTP id r3mr2044079ejc.50.1615452553014; Thu, 11 Mar 2021 00:49:13 -0800 (PST) Received: from oberon.zico.biz ([83.222.187.186]) by smtp.gmail.com with ESMTPSA id fi11sm901647ejb.73.2021.03.11.00.49.11 (version=TLS1_3 cipher=TLS_AES_256_GCM_SHA384 bits=256/256); Thu, 11 Mar 2021 00:49:12 -0800 (PST) From: "Tzvetomir Stoyanov (VMware)" To: rostedt@goodmis.org Cc: linux-trace-devel@vger.kernel.org Subject: [PATCH v31 07/16] trace-cmd [POC]: Add KVM timestamp synchronization plugin Date: Thu, 11 Mar 2021 10:48:48 +0200 Message-Id: <20210311084857.1919805-8-tz.stoyanov@gmail.com> X-Mailer: git-send-email 2.29.2 In-Reply-To: <20210311084857.1919805-1-tz.stoyanov@gmail.com> References: <20210311084857.1919805-1-tz.stoyanov@gmail.com> MIME-Version: 1.0 Precedence: bulk List-ID: X-Mailing-List: linux-trace-devel@vger.kernel.org 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) --- 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 e66c7b5f..b1a07a04 100644 --- a/lib/trace-cmd/Makefile +++ b/lib/trace-cmd/Makefile @@ -20,6 +20,7 @@ OBJS += trace-plugin.o OBJS += trace-timesync.o ifeq ($(VSOCK_DEFINED), 1) 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 b3a3bdfc..7e56d187 100644 --- a/lib/trace-cmd/include/trace-tsync-local.h +++ b/lib/trace-cmd/include/trace-tsync-local.h @@ -65,5 +65,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 +#include +#include +#include +#include + +#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//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 f939d34b..7514766a 100644 --- a/lib/trace-cmd/trace-timesync.c +++ b/lib/trace-cmd/trace-timesync.c @@ -66,6 +66,7 @@ void tracecmd_tsync_init(void) { #ifdef VSOCK ptp_clock_sync_register(); + kvm_clock_sync_register(); #endif } From patchwork Thu Mar 11 08:48:49 2021 Content-Type: text/plain; charset="utf-8" MIME-Version: 1.0 Content-Transfer-Encoding: 7bit X-Patchwork-Submitter: "Tzvetomir Stoyanov (VMware)" X-Patchwork-Id: 12130623 Return-Path: X-Spam-Checker-Version: SpamAssassin 3.4.0 (2014-02-07) on aws-us-west-2-korg-lkml-1.web.codeaurora.org X-Spam-Level: X-Spam-Status: No, score=-15.8 required=3.0 tests=BAYES_00,DKIM_SIGNED, DKIM_VALID,DKIM_VALID_AU,FREEMAIL_FORGED_FROMDOMAIN,FREEMAIL_FROM, HEADER_FROM_DIFFERENT_DOMAINS,INCLUDES_CR_TRAILER,INCLUDES_PATCH, MAILING_LIST_MULTI,SPF_HELO_NONE,SPF_PASS,USER_AGENT_GIT autolearn=ham autolearn_force=no version=3.4.0 Received: from mail.kernel.org (mail.kernel.org [198.145.29.99]) by smtp.lore.kernel.org (Postfix) with ESMTP id 2DB68C433DB for ; Thu, 11 Mar 2021 08:49:48 +0000 (UTC) Received: from vger.kernel.org (vger.kernel.org [23.128.96.18]) by mail.kernel.org (Postfix) with ESMTP id DE56064FAA for ; Thu, 11 Mar 2021 08:49:47 +0000 (UTC) Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S231720AbhCKItS (ORCPT ); Thu, 11 Mar 2021 03:49:18 -0500 Received: from lindbergh.monkeyblade.net ([23.128.96.19]:42758 "EHLO lindbergh.monkeyblade.net" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S231749AbhCKItP (ORCPT ); Thu, 11 Mar 2021 03:49:15 -0500 Received: from mail-ed1-x534.google.com (mail-ed1-x534.google.com [IPv6:2a00:1450:4864:20::534]) by lindbergh.monkeyblade.net (Postfix) with ESMTPS id 2EDF3C061574 for ; Thu, 11 Mar 2021 00:49:15 -0800 (PST) Received: by mail-ed1-x534.google.com with SMTP id h10so1527386edt.13 for ; Thu, 11 Mar 2021 00:49:15 -0800 (PST) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=gmail.com; s=20161025; h=from:to:cc:subject:date:message-id:in-reply-to:references :mime-version:content-transfer-encoding; bh=GvCw2kCrHaFZU+7kJo7HSqTgG1Tcbm1RRAcazhN8K0w=; b=jrhNHc6LjWkTEE1UzMRGV/WNPFYO/B4DQqPzAF7hdQqd4g81dZvPkfnWxFNXwa8cnN CDlmmyBV9IVHH3t6lrhcE2ijdzqT+hiUVjjLFlcDWASOFGAmUJFKadtCSb6xhfXKA/S+ pvjbXabzG92tu5z+Iyucb1rr8U8p4pWl1CfiBmkNAuY5QD4gNo6hhI8Rg0bBx4gmrhvm 3FGYLvwOCL4tYf/ijnZfORZrgUCksM3OS7B/yfJvjlJtSjzMbDY0IeygHPJeMoriVVNb AlBeDc9XqWR90xjQkpYPcL0vOsV6wc/3NFHL778E+HDIQ9X56wOG7AeYuyGJzmhpGpq6 RMBQ== X-Google-DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=1e100.net; s=20161025; h=x-gm-message-state:from:to:cc:subject:date:message-id:in-reply-to :references:mime-version:content-transfer-encoding; bh=GvCw2kCrHaFZU+7kJo7HSqTgG1Tcbm1RRAcazhN8K0w=; b=Ys7tB4bQ5/dtymqB9nsbBXF7ZPADhVMf9aNn8ziD1bLI/rUUF6NJ5Za+TCwgnjfhlX HwAcOD/rmDy8/sVcphKUi8R62m6Ib7ZLhQ+JbMg4L9B8mNLAL9+FR31wVf06F6IGchmX 3c/h9ObMA0Ug0ps2iMUSKVfYLAOv/DfBDDdY37sdRLPSMlpoP43xhMTBG30gpUg4tDWZ Cj9u/uhq8WRoQzzYDMC1Io87dJw1omU7NKGSbM+JJjo9LbfSZoubKBJ9aVra+d7XyP4O SEHbAnzGK3jgGJ/BysKqt54vCQxD2NVT/OYq8JAZSkBxJemLwJRhJ/9oO9PDS4yeqC1y m4bA== X-Gm-Message-State: AOAM530Kn8i5sPFXWJjGL9ecYIuev99QpjKtjnlFHxvKTovItNUeFBYG cZtkBNL50Uk9RkXiGfvCyQI= X-Google-Smtp-Source: ABdhPJzBWDU8MaVGL2Yhpvwdpl8s1JPYRfJrvR/p0b8YgjoyaUZsDKzYYLzhMVjzDK0xitvwT5dLrg== X-Received: by 2002:aa7:d416:: with SMTP id z22mr7342916edq.239.1615452553927; Thu, 11 Mar 2021 00:49:13 -0800 (PST) Received: from oberon.zico.biz ([83.222.187.186]) by smtp.gmail.com with ESMTPSA id fi11sm901647ejb.73.2021.03.11.00.49.13 (version=TLS1_3 cipher=TLS_AES_256_GCM_SHA384 bits=256/256); Thu, 11 Mar 2021 00:49:13 -0800 (PST) From: "Tzvetomir Stoyanov (VMware)" To: rostedt@goodmis.org Cc: linux-trace-devel@vger.kernel.org Subject: [PATCH v31 08/16] trace-cmd: Add initial perf interface in trace-cmd library Date: Thu, 11 Mar 2021 10:48:49 +0200 Message-Id: <20210311084857.1919805-9-tz.stoyanov@gmail.com> X-Mailer: git-send-email 2.29.2 In-Reply-To: <20210311084857.1919805-1-tz.stoyanov@gmail.com> References: <20210311084857.1919805-1-tz.stoyanov@gmail.com> MIME-Version: 1.0 Precedence: bulk List-ID: X-Mailing-List: linux-trace-devel@vger.kernel.org Add new trace-cmd library internal APIs for working with perf. These initial APIs offer only basic functionality - init, open and close a perf session: trace_perf_init(); trace_perf_close(); trace_perf_open(); Signed-off-by: Tzvetomir Stoyanov (VMware) --- lib/trace-cmd/Makefile | 1 + .../include/private/trace-cmd-private.h | 14 +++ lib/trace-cmd/trace-perf.c | 105 ++++++++++++++++++ 3 files changed, 120 insertions(+) create mode 100644 lib/trace-cmd/trace-perf.c diff --git a/lib/trace-cmd/Makefile b/lib/trace-cmd/Makefile index b1a07a04..ada65c44 100644 --- a/lib/trace-cmd/Makefile +++ b/lib/trace-cmd/Makefile @@ -18,6 +18,7 @@ OBJS += trace-filter-hash.o OBJS += trace-msg.o OBJS += trace-plugin.o OBJS += trace-timesync.o +OBJS += trace-perf.o ifeq ($(VSOCK_DEFINED), 1) OBJS += trace-timesync-ptp.o OBJS += trace-timesync-kvm.o diff --git a/lib/trace-cmd/include/private/trace-cmd-private.h b/lib/trace-cmd/include/private/trace-cmd-private.h index cef8f645..0f682c18 100644 --- a/lib/trace-cmd/include/private/trace-cmd-private.h +++ b/lib/trace-cmd/include/private/trace-cmd-private.h @@ -8,6 +8,7 @@ #include /* for iovec */ #include +#include /* for perf types */ #include "traceevent/event-parse.h" #include "trace-cmd/trace-cmd.h" @@ -513,4 +514,17 @@ void *tracecmd_record_page(struct tracecmd_input *handle, void *tracecmd_record_offset(struct tracecmd_input *handle, struct tep_record *record); +/* trace-cmd Perf */ +struct trace_perf { + int fd; + int cpu; + int pid; + int pages; + struct perf_event_attr pe; + struct perf_event_mmap_page *mmap; +}; +int trace_perf_init(struct trace_perf *perf, int pages, int cpu, int pid); +void trace_perf_close(struct trace_perf *perf); +int trace_perf_open(struct trace_perf *perf); + #endif /* _TRACE_CMD_PRIVATE_H */ diff --git a/lib/trace-cmd/trace-perf.c b/lib/trace-cmd/trace-perf.c new file mode 100644 index 00000000..cd61794f --- /dev/null +++ b/lib/trace-cmd/trace-perf.c @@ -0,0 +1,105 @@ +// SPDX-License-Identifier: LGPL-2.1 +/* + * Copyright (C) 2021, VMware, Tzvetomir Stoyanov + * + */ +#include +#include +#include + +#include "trace-cmd-private.h" + +static void default_perf_init_pe(struct perf_event_attr *pe) +{ + pe->type = PERF_TYPE_SOFTWARE; + pe->sample_type = PERF_SAMPLE_CPU; + pe->size = sizeof(struct perf_event_attr); + pe->config = PERF_COUNT_HW_CPU_CYCLES; + pe->disabled = 1; + pe->exclude_kernel = 1; + pe->freq = 1; + pe->sample_freq = 1000; + pe->inherit = 1; + pe->mmap = 1; + pe->comm = 1; + pe->task = 1; + pe->precise_ip = 1; + pe->sample_id_all = 1; + pe->read_format = PERF_FORMAT_ID | + PERF_FORMAT_TOTAL_TIME_ENABLED| + PERF_FORMAT_TOTAL_TIME_RUNNING; +} + +/** + * trace_perf_init - Initialize perf context + * + * @perf: structure, representing perf context, that will be initialized. + * @pages: Number of perf memory mapped pages. + * @cpu: CPU number, associated with this perf context. + * @pid: PID, associated with this perf context. + * + * The perf context in initialized with default values. The caller can set + * custom perf parameters in perf->pe, before calling trace_perf_open() API. + * + * Returns 0 on success, or -1 in case of an error. + * + */ +int trace_perf_init(struct trace_perf *perf, int pages, int cpu, int pid) +{ + if (!perf) + return -1; + + memset(perf, 0, sizeof(struct trace_perf)); + default_perf_init_pe(&perf->pe); + perf->cpu = cpu; + perf->pages = pages; + perf->pid = pid; + perf->fd = -1; + + return 0; +} + +/** + * trace_perf_close - Close perf session + * + * @perf: structure, representing context of a running perf session, opened + * with trace_perf_open() + * + */ +void trace_perf_close(struct trace_perf *perf) +{ + if (perf->fd >= 0) + close(perf->fd); + perf->fd = -1; + if (perf->mmap) + munmap(perf->mmap, (perf->pages + 1) * getpagesize()); + perf->mmap = NULL; +} + +/** + * trace_perf_open - Open perf session + * + * @perf: structure, representing perf context that will be opened. It must be + * initialized with trace_perf_init(). + * + * Returns 0 on success, or -1 in case of an error. In case of success, the + * session must be closed with trace_perf_close() + */ +int trace_perf_open(struct trace_perf *perf) +{ + perf->fd = syscall(__NR_perf_event_open, &perf->pe, perf->pid, perf->cpu, -1, 0); + if (perf->fd < 0) + return -1; + fcntl(perf->fd, F_SETFL, O_NONBLOCK); + + perf->mmap = mmap(NULL, (perf->pages + 1) * getpagesize(), + PROT_READ | PROT_WRITE, MAP_SHARED, perf->fd, 0); + if (perf->mmap == MAP_FAILED) + goto error; + + return 0; + +error: + trace_perf_close(perf); + return -1; +} From patchwork Thu Mar 11 08:48:50 2021 Content-Type: text/plain; charset="utf-8" MIME-Version: 1.0 Content-Transfer-Encoding: 7bit X-Patchwork-Submitter: "Tzvetomir Stoyanov (VMware)" X-Patchwork-Id: 12130621 Return-Path: X-Spam-Checker-Version: SpamAssassin 3.4.0 (2014-02-07) on aws-us-west-2-korg-lkml-1.web.codeaurora.org X-Spam-Level: X-Spam-Status: No, score=-15.8 required=3.0 tests=BAYES_00,DKIM_SIGNED, DKIM_VALID,DKIM_VALID_AU,FREEMAIL_FORGED_FROMDOMAIN,FREEMAIL_FROM, HEADER_FROM_DIFFERENT_DOMAINS,INCLUDES_CR_TRAILER,INCLUDES_PATCH, MAILING_LIST_MULTI,SPF_HELO_NONE,SPF_PASS,USER_AGENT_GIT autolearn=ham autolearn_force=no version=3.4.0 Received: from mail.kernel.org (mail.kernel.org [198.145.29.99]) by smtp.lore.kernel.org (Postfix) with ESMTP id 0B0AEC433E0 for ; Thu, 11 Mar 2021 08:49:48 +0000 (UTC) Received: from vger.kernel.org (vger.kernel.org [23.128.96.18]) by mail.kernel.org (Postfix) with ESMTP id BDD9264FA9 for ; Thu, 11 Mar 2021 08:49:47 +0000 (UTC) Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S231736AbhCKItS (ORCPT ); Thu, 11 Mar 2021 03:49:18 -0500 Received: from lindbergh.monkeyblade.net ([23.128.96.19]:42766 "EHLO lindbergh.monkeyblade.net" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S231515AbhCKItQ (ORCPT ); Thu, 11 Mar 2021 03:49:16 -0500 Received: from mail-ej1-x634.google.com (mail-ej1-x634.google.com [IPv6:2a00:1450:4864:20::634]) by lindbergh.monkeyblade.net (Postfix) with ESMTPS id 655D1C061574 for ; Thu, 11 Mar 2021 00:49:16 -0800 (PST) Received: by mail-ej1-x634.google.com with SMTP id c10so44450919ejx.9 for ; Thu, 11 Mar 2021 00:49:16 -0800 (PST) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=gmail.com; s=20161025; h=from:to:cc:subject:date:message-id:in-reply-to:references :mime-version:content-transfer-encoding; bh=utlFF86IMvGuh5Q2vz56loGlRA61WqH7eo2e8seFjHI=; b=slWZCf4N7aHu4sZclqUIQu60TApWYNVOrwkae8IDdYLn3nu/7qmJJx1bVpuFVuysyp z3JSG0iGVyUX5UfsjSRdP3z8ulBu1E18fhS+y9tg8eOGRvHlrh+jmeiSDIGsz+El+pBL TdFauCJO5aryn6F07SMhoMcqDRLjPgC3JOw4o6viDay6yh9fYNFLElxR/CW1+gSzxDiT ctw5Hdu1ORO0zZmao6n6pPrbsdk5esWGQ9Bb0On0jzKiKb6enDnTxX/e9VVDmsXzGr0K XqzAIwrm49QX/ukkSPwAOdWDDvt+d5P5zHKn2RagI1NdykbrGpAenS2nxeMv6ts7JjfY HPEQ== X-Google-DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=1e100.net; s=20161025; h=x-gm-message-state:from:to:cc:subject:date:message-id:in-reply-to :references:mime-version:content-transfer-encoding; bh=utlFF86IMvGuh5Q2vz56loGlRA61WqH7eo2e8seFjHI=; b=sNpop+WQeYH+MM/rHrsvyVaStR+YGJfYQJDBQGo9voI3fn4A/Zqr/SLReIGewBJmgK ULD6QNb3y1AA5qWLIYJ5iSd0D+xDX3VToG9e1OwwsMo+hcKWkbNg1UmIvqh8drK9Qmt1 dKf27E9xEDGi+kaTl/EHlw8sMzYD5Agst0RbSzfEbeqCTagyD5YhlFu09FxkTGP16jvj fQ5wGHHecCYxR8P2fAGX5FIGYhVRK/5nANYw0z1Q1uwPkLiT90EyLCM2H5VP9NdZLfo9 2dpp8pA0z5SSgHLOEU+1m5s8+dWMcP71aMB7h8wqBycnqzqaxwqtTZaw/Xfg4qFGtRN+ Py9w== X-Gm-Message-State: AOAM531IBRKVL/Pb7NW8OXV6j6I5msh+VQkTYIov++7jRGNptU9Zcieo PmFaD/lmJNeaMI/19XPPVrZ9neTXgBt58g== X-Google-Smtp-Source: ABdhPJxngoIlRAS/BhwqQ4whmHjvcUV9pxSHJTT3dhvnXXg3EkYKp4W+JZ8cnsGVn+91SBO8hXJavQ== X-Received: by 2002:a17:907:10c1:: with SMTP id rv1mr2117838ejb.5.1615452555199; Thu, 11 Mar 2021 00:49:15 -0800 (PST) Received: from oberon.zico.biz ([83.222.187.186]) by smtp.gmail.com with ESMTPSA id fi11sm901647ejb.73.2021.03.11.00.49.14 (version=TLS1_3 cipher=TLS_AES_256_GCM_SHA384 bits=256/256); Thu, 11 Mar 2021 00:49:14 -0800 (PST) From: "Tzvetomir Stoyanov (VMware)" To: rostedt@goodmis.org Cc: linux-trace-devel@vger.kernel.org Subject: [PATCH v31 09/16] trace-cmd: Add logic for TSC to nanosecond conversion Date: Thu, 11 Mar 2021 10:48:50 +0200 Message-Id: <20210311084857.1919805-10-tz.stoyanov@gmail.com> X-Mailer: git-send-email 2.29.2 In-Reply-To: <20210311084857.1919805-1-tz.stoyanov@gmail.com> References: <20210311084857.1919805-1-tz.stoyanov@gmail.com> MIME-Version: 1.0 Precedence: bulk List-ID: X-Mailing-List: linux-trace-devel@vger.kernel.org Added new logic to get multiplier and shift for converting TSC trace clock to nanoseconds, using perf kernel interface. The new logic is used only in host - guest tracing use case, when the user did not specify any tracing clock and KVM time sync plugin is available. Then the x86-tsc clock is auto selected for the current tracing session. There is one limitation - per CPU multiplier or shift is not supported. Signed-off-by: Tzvetomir Stoyanov (VMware) --- tracecmd/include/trace-local.h | 7 ++ tracecmd/trace-record.c | 124 ++++++++++++++++++++++++++------- 2 files changed, 107 insertions(+), 24 deletions(-) diff --git a/tracecmd/include/trace-local.h b/tracecmd/include/trace-local.h index 6e39d27d..8a88ab9c 100644 --- a/tracecmd/include/trace-local.h +++ b/tracecmd/include/trace-local.h @@ -199,6 +199,12 @@ struct filter_pids { int exclude; }; +struct tsc_nsec { + int mult; + int shift; + int offset; +}; + struct buffer_instance { struct buffer_instance *next; char *name; @@ -234,6 +240,7 @@ struct buffer_instance { int get_procmap; const char *clock; + struct tsc_nsec tsc2nsec; unsigned int *client_ports; struct trace_seq *s_save; diff --git a/tracecmd/trace-record.c b/tracecmd/trace-record.c index 595f53fd..38428c8d 100644 --- a/tracecmd/trace-record.c +++ b/tracecmd/trace-record.c @@ -57,6 +57,7 @@ #define MAX_LATENCY "tracing_max_latency" #define STAMP "stamp" #define FUNC_STACK_TRACE "func_stack_trace" +#define TSC_CLOCK "x86-tsc" enum trace_type { TRACE_TYPE_RECORD = 1, @@ -4104,6 +4105,7 @@ enum { DATA_FL_NONE = 0, DATA_FL_DATE = 1, DATA_FL_OFFSET = 2, + DATA_FL_GUEST = 3, }; static void add_options(struct tracecmd_output *handle, struct common_record_context *ctx) @@ -5676,6 +5678,100 @@ check_instance_die(struct buffer_instance *instance, char *param) tracefs_instance_get_name(instance->tracefs), param); } +static int get_tsc_nsec(int *shift, int *mult, int *offset) +{ + int cpus = tracecmd_count_cpus(); + int cpu_shift, cpu_mult, cpu_offset; + struct trace_perf perf; + int ret; + int i; + + ret = trace_perf_init(&perf, 1, 0, getpid()); + if (!ret) + ret = trace_perf_open(&perf); + if (ret) + return ret; + cpu_shift = perf.mmap->time_shift; + cpu_mult = perf.mmap->time_mult; + /* ToDo set the offset, should we use perf.mmap->time_offset ? */ + cpu_offset = 0; + for (i = 1; i < cpus; i++) { + trace_perf_close(&perf); + ret = trace_perf_init(&perf, 1, i, getpid()); + if (!ret) + ret = trace_perf_open(&perf); + if (ret) + break; + if (perf.mmap->time_shift != cpu_shift || + perf.mmap->time_mult != cpu_mult) { + warning("Found different TSC multiplier and shift for CPU %d: %d;%d instead of %d;%d", + i, perf.mmap->time_mult, perf.mmap->time_shift, cpu_mult, cpu_shift); + break; + } + } + trace_perf_close(&perf); + if (i < cpus) + return -1; + + *shift = cpu_shift; + *mult = cpu_mult; + *offset = cpu_offset; + + return 0; +} + +static void set_vsync_clock(void) +{ + const char *clock = top_instance.clock; + struct buffer_instance *instance; + bool tsc2nsec = false; + int shift, mult, offset; + + /* + * If no clock is specified for the top trace instance AND + * KVM time sync protocol is available AND + * TSC to nsec multiplier and shift are available: + * force using the x86-tsc clock for this host-guest tracing session + * and store TSC to nsec multiplier and shift. + */ + if (!clock && tsync_proto_is_supported("kvm") && + !get_tsc_nsec(&shift, &mult, &offset) && mult) { + top_instance.clock = strdup(TSC_CLOCK); + if (!top_instance.clock) + die("Could not allocate top instance clock"); + clock = top_instance.clock; + top_instance.tsc2nsec.mult = mult; + top_instance.tsc2nsec.shift = shift; + top_instance.tsc2nsec.offset = offset; + tsc2nsec = true; + } + + if (!clock && !top_instance.tsync_loop_interval) + return; + for_all_instances(instance) { + if (clock) { + /* use the same clock in all tracing peers */ + if (is_guest(instance) && + !(instance->flags & BUFFER_FL_HAS_CLOCK)) { + add_argv(instance, + (char *)top_instance.clock, true); + add_argv(instance, "-C", true); + if (!instance->clock) { + instance->clock = strdup((char *)top_instance.clock); + if (!instance->clock) + die("Could not allocate instance clock"); + } + if (tsc2nsec) { + instance->tsc2nsec.mult = mult; + instance->tsc2nsec.shift = shift; + instance->tsc2nsec.offset = offset; + } + } + } + instance->tsync_loop_interval = top_instance.tsync_loop_interval; + } +} + static void parse_record_options(int argc, char **argv, enum trace_cmd curr_cmd, @@ -5691,7 +5787,6 @@ static void parse_record_options(int argc, int name_counter = 0; int negative = 0; struct buffer_instance *instance, *del_list = NULL; - bool guest_sync_set = false; int do_children = 0; int fpids_count = 0; @@ -5825,6 +5920,7 @@ static void parse_record_options(int argc, ctx->instance->port = port; ctx->instance->name = name; add_instance(ctx->instance, 0); + ctx->data_flags |= DATA_FL_GUEST; break; } case 'F': @@ -5872,8 +5968,6 @@ static void parse_record_options(int argc, check_instance_die(ctx->instance, "-C"); ctx->instance->clock = optarg; ctx->instance->flags |= BUFFER_FL_HAS_CLOCK; - if (is_top_instance(ctx->instance)) - guest_sync_set = true; break; case 'v': negative = 1; @@ -6118,7 +6212,6 @@ static void parse_record_options(int argc, case OPT_tsyncinterval: cmd_check_die(ctx, CMD_set, *(argv+1), "--tsync-interval"); top_instance.tsync_loop_interval = atoi(optarg); - guest_sync_set = true; break; case OPT_fork: if (!IS_START(ctx)) @@ -6145,26 +6238,6 @@ static void parse_record_options(int argc, add_argv(instance, "--date", true); } } - if (guest_sync_set) { - /* If -C is specified, prepend clock to all guest VM flags */ - for_all_instances(instance) { - if (top_instance.clock) { - if (is_guest(instance) && - !(instance->flags & BUFFER_FL_HAS_CLOCK)) { - add_argv(instance, - (char *)top_instance.clock, - true); - add_argv(instance, "-C", true); - if (!instance->clock) { - instance->clock = strdup((char *)top_instance.clock); - if (!instance->clock) - die("Could not allocate instance clock"); - } - } - } - instance->tsync_loop_interval = top_instance.tsync_loop_interval; - } - } if (!ctx->filtered && ctx->instance->filter_mod) add_func(&ctx->instance->filter_funcs, @@ -6297,6 +6370,9 @@ static void record_trace(int argc, char **argv, if (!ctx->output) ctx->output = DEFAULT_INPUT_FILE; + if (ctx->data_flags & DATA_FL_GUEST) + set_vsync_clock(); + make_instances(); /* Save the state of tracing_on before starting */ From patchwork Thu Mar 11 08:48:51 2021 Content-Type: text/plain; charset="utf-8" MIME-Version: 1.0 Content-Transfer-Encoding: 7bit X-Patchwork-Submitter: "Tzvetomir Stoyanov (VMware)" X-Patchwork-Id: 12130625 Return-Path: X-Spam-Checker-Version: SpamAssassin 3.4.0 (2014-02-07) on aws-us-west-2-korg-lkml-1.web.codeaurora.org X-Spam-Level: X-Spam-Status: No, score=-15.8 required=3.0 tests=BAYES_00,DKIM_SIGNED, DKIM_VALID,DKIM_VALID_AU,FREEMAIL_FORGED_FROMDOMAIN,FREEMAIL_FROM, HEADER_FROM_DIFFERENT_DOMAINS,INCLUDES_CR_TRAILER,INCLUDES_PATCH, MAILING_LIST_MULTI,SPF_HELO_NONE,SPF_PASS,USER_AGENT_GIT autolearn=ham autolearn_force=no version=3.4.0 Received: from mail.kernel.org (mail.kernel.org [198.145.29.99]) by smtp.lore.kernel.org (Postfix) with ESMTP id 7F558C433E6 for ; Thu, 11 Mar 2021 08:49:48 +0000 (UTC) Received: from vger.kernel.org (vger.kernel.org [23.128.96.18]) by mail.kernel.org (Postfix) with ESMTP id 596F364FA8 for ; Thu, 11 Mar 2021 08:49:48 +0000 (UTC) Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S231515AbhCKItS (ORCPT ); Thu, 11 Mar 2021 03:49:18 -0500 Received: from lindbergh.monkeyblade.net ([23.128.96.19]:42768 "EHLO lindbergh.monkeyblade.net" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S231700AbhCKItR (ORCPT ); Thu, 11 Mar 2021 03:49:17 -0500 Received: from mail-ej1-x630.google.com (mail-ej1-x630.google.com [IPv6:2a00:1450:4864:20::630]) by lindbergh.monkeyblade.net (Postfix) with ESMTPS id 5A055C061574 for ; Thu, 11 Mar 2021 00:49:17 -0800 (PST) Received: by mail-ej1-x630.google.com with SMTP id p8so44502971ejb.10 for ; Thu, 11 Mar 2021 00:49:17 -0800 (PST) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=gmail.com; s=20161025; h=from:to:cc:subject:date:message-id:in-reply-to:references :mime-version:content-transfer-encoding; bh=cIjLZ2jxcnzei4wiiNaWxNAYYBrYURdLiNC6d2iRrmM=; b=izfFGSaU0DD7l7U4p2PdbtdnGmWrr0ize4Toc+VUTFDT9OzkY4HA40O1mFYQBXWxRN vXrW0Qjx4qgJHLApvAMvyD7jdZCNmhuMMQeto4xhMm/KX+wvDb1MRNPxDQS+4wF5FB0C 6TrbJf2+2tPkNcT81sUUognfZQq2kyAdWWY+n7Xbh7ymsi7bhVAa9SN720+h3DtTqFXJ KA6woGlmJVvclmAN/oeQtfaSoBxa2xrOKMOrgWQ3CWR2gEUn9Gn8VFDGy1LNKV+SoxBR FBlqVlJftZxq/UwEnMgJqWxuzpvfAdoTiYo0ldAsl1vas8eZVC+JMCqoUUow96TRkTws 0vLA== X-Google-DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=1e100.net; s=20161025; h=x-gm-message-state:from:to:cc:subject:date:message-id:in-reply-to :references:mime-version:content-transfer-encoding; bh=cIjLZ2jxcnzei4wiiNaWxNAYYBrYURdLiNC6d2iRrmM=; b=e4bOZh1OXAG5WReKarYpZVXzin3RFXNfmQGSbzCR1CUsgJmJt3RZGzU2bHRiGIPoVx gPVf/Kse8prVFaCHD7lh6ecRELzJS/FZQXLuzpS8STWY0ubEgdmzsIB798rEE/rbwURp 6w8OoldM350K1opbngSlOD/lLaxtOUX6+HQKLc+wPJkpiP3+NnXxeWD4AMMfLhClrDze QyD3N8tuH8qObwb8oOSY1/++dbQkmU1vHRdM88g2BajsLZunKg5TF+xaahgrqY4crCjn 63nopF5sNBF3TnnLmspGZ28m+oySuu3M833jHzEonh6E33U4+O+5kKSt5l3Ox0qTHoqQ FW+Q== X-Gm-Message-State: AOAM531oKBvbhJNGeExMuxX3/YeWTuZfMGeIraC8LgRMwFoCBhF8c8aY 5toUos6GsTmIybJL1sDejHf8h9kvKRy4aQ== X-Google-Smtp-Source: ABdhPJzFCZRc/a9s4eeuehlVnzQ7tfbdM7zOPabkbM71w/38bfosglmShxhP9LytQYVEvAvsGc/kvw== X-Received: by 2002:a17:906:3849:: with SMTP id w9mr2084518ejc.7.1615452556060; Thu, 11 Mar 2021 00:49:16 -0800 (PST) Received: from oberon.zico.biz ([83.222.187.186]) by smtp.gmail.com with ESMTPSA id fi11sm901647ejb.73.2021.03.11.00.49.15 (version=TLS1_3 cipher=TLS_AES_256_GCM_SHA384 bits=256/256); Thu, 11 Mar 2021 00:49:15 -0800 (PST) From: "Tzvetomir Stoyanov (VMware)" To: rostedt@goodmis.org Cc: linux-trace-devel@vger.kernel.org Subject: [PATCH v31 10/16] trace-cmd: Append new options into guest trace file at the end of the tracing session Date: Thu, 11 Mar 2021 10:48:51 +0200 Message-Id: <20210311084857.1919805-11-tz.stoyanov@gmail.com> X-Mailer: git-send-email 2.29.2 In-Reply-To: <20210311084857.1919805-1-tz.stoyanov@gmail.com> References: <20210311084857.1919805-1-tz.stoyanov@gmail.com> MIME-Version: 1.0 Precedence: bulk List-ID: X-Mailing-List: linux-trace-devel@vger.kernel.org Moved the logic for appending new options into guest trace file from tracecmd_write_guest_time_shift() to host_tsync_complete() context. The guest time shift may not be the only option to append, the right place for this logic is when the tracing session is completed. Signed-off-by: Tzvetomir Stoyanov (VMware) --- lib/trace-cmd/trace-timesync.c | 1 - tracecmd/trace-record.c | 1 + 2 files changed, 1 insertion(+), 1 deletion(-) diff --git a/lib/trace-cmd/trace-timesync.c b/lib/trace-cmd/trace-timesync.c index 7514766a..3a70eedd 100644 --- a/lib/trace-cmd/trace-timesync.c +++ b/lib/trace-cmd/trace-timesync.c @@ -974,7 +974,6 @@ int tracecmd_write_guest_time_shift(struct tracecmd_output *handle, if (i < tsync->vcpu_count) goto out; tracecmd_add_option_v(handle, TRACECMD_OPTION_TIME_SHIFT, vector, vcount); - tracecmd_append_options(handle); #ifdef TSYNC_DEBUG if (count > 1) printf("Got %d timestamp synch samples for guest %s in %lld ns trace\n\r", diff --git a/tracecmd/trace-record.c b/tracecmd/trace-record.c index 38428c8d..15521d0d 100644 --- a/tracecmd/trace-record.c +++ b/tracecmd/trace-record.c @@ -681,6 +681,7 @@ static void host_tsync_complete(struct buffer_instance *instance) if (!handle) die("cannot create output handle"); tracecmd_write_guest_time_shift(handle, instance->tsync); + tracecmd_append_options(handle); tracecmd_output_close(handle); } From patchwork Thu Mar 11 08:48:52 2021 Content-Type: text/plain; charset="utf-8" MIME-Version: 1.0 Content-Transfer-Encoding: 7bit X-Patchwork-Submitter: "Tzvetomir Stoyanov (VMware)" X-Patchwork-Id: 12130631 Return-Path: X-Spam-Checker-Version: SpamAssassin 3.4.0 (2014-02-07) on aws-us-west-2-korg-lkml-1.web.codeaurora.org X-Spam-Level: X-Spam-Status: No, score=-15.8 required=3.0 tests=BAYES_00,DKIM_SIGNED, DKIM_VALID,DKIM_VALID_AU,FREEMAIL_FORGED_FROMDOMAIN,FREEMAIL_FROM, HEADER_FROM_DIFFERENT_DOMAINS,INCLUDES_CR_TRAILER,INCLUDES_PATCH, MAILING_LIST_MULTI,SPF_HELO_NONE,SPF_PASS,USER_AGENT_GIT autolearn=ham autolearn_force=no version=3.4.0 Received: from mail.kernel.org (mail.kernel.org [198.145.29.99]) by smtp.lore.kernel.org (Postfix) with ESMTP id AC5CCC43381 for ; Thu, 11 Mar 2021 08:49:48 +0000 (UTC) Received: from vger.kernel.org (vger.kernel.org [23.128.96.18]) by mail.kernel.org (Postfix) with ESMTP id 76F3864FB3 for ; Thu, 11 Mar 2021 08:49:48 +0000 (UTC) Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S231714AbhCKItr (ORCPT ); Thu, 11 Mar 2021 03:49:47 -0500 Received: from lindbergh.monkeyblade.net ([23.128.96.19]:42776 "EHLO lindbergh.monkeyblade.net" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S231738AbhCKItS (ORCPT ); Thu, 11 Mar 2021 03:49:18 -0500 Received: from mail-ej1-x635.google.com (mail-ej1-x635.google.com [IPv6:2a00:1450:4864:20::635]) by lindbergh.monkeyblade.net (Postfix) with ESMTPS id 832B9C061574 for ; Thu, 11 Mar 2021 00:49:18 -0800 (PST) Received: by mail-ej1-x635.google.com with SMTP id e19so44592226ejt.3 for ; Thu, 11 Mar 2021 00:49:18 -0800 (PST) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=gmail.com; s=20161025; h=from:to:cc:subject:date:message-id:in-reply-to:references :mime-version:content-transfer-encoding; bh=cGItAm0KdBmyA0uZhimYLjv3a/cNK6WQJH0OOStbyAU=; b=n1a/WjRv2pBS4WBOdCVMbVck0YUcrpJaGhZ/n3yLgSOoSLSmsV2nA/ZpQf4z0307Ir NCp8k9CfDGf6N/vzUs3NQ3LXLvLev0VCFjoDrDesB18MdG56KeihMEZMkKPlal0TofIZ yS75Eaf1Z+qfAyHKjb+XRUXMlGE9+FobTHnKYEI2dgOhqWLQbvVqBOuGvxySt49t53ia VlpqGhc33DMX5fI5Tb6KXWorhqyyz5dSsXcJOlzcj5S2I/tQlTQS+gz4E4mAetjeRauJ qQJ446Onk6mWO39x6kpMCwyXzkiAB3hNh/Kq6qVH5IF5STTO5GcnAhv/wT1eUZk5gwkr yOsA== X-Google-DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=1e100.net; s=20161025; h=x-gm-message-state:from:to:cc:subject:date:message-id:in-reply-to :references:mime-version:content-transfer-encoding; bh=cGItAm0KdBmyA0uZhimYLjv3a/cNK6WQJH0OOStbyAU=; b=rSlp0dfvj4Ou5ybQR91jp94Nxq8HT6UR8X5wqNYogK8mFKsdZrvpQm6udLRiDOXYaF H/+f8BD+6QKuEglrJ4ahOrH8igTI2yLAoX5QM2OBZ0uApka8yQGlCtfxO51cYvPUL5kA xg0AuyAqzKjfXmR6uChnLXZ7tsAxfvk7zBtrKaSnr2fHyx77mu/cpU1cuqRY77WeI3iU sBk0zG6n5N4Ob8J7XCs9Ce1Pg5Iwt/rlSpCJTedbMRGH2QRh5jJfNzPFXgna+15xNivJ 92taA8a0AOOYPhze/eo3x2gAnd3hCalHooGHjEcB6ZSl///KPzvIPZXlSUTfS6wL94gN JT9w== X-Gm-Message-State: AOAM530qjFGN/DNKj6eTsnezd19vHi/c5WfpGtm96YkLWfAQJ9uLnLcK DzgIeWZE75X1uFaeUTW/yyJaapwUDw3owQ== X-Google-Smtp-Source: ABdhPJznOpC8PTLz/x93VIY5WGR5C1KbTg+Jr+8btRc5U5Q2o9gFSdocezDYViIEb0Hnf7joEJUv/g== X-Received: by 2002:a17:907:76b6:: with SMTP id jw22mr2042671ejc.11.1615452557355; Thu, 11 Mar 2021 00:49:17 -0800 (PST) Received: from oberon.zico.biz ([83.222.187.186]) by smtp.gmail.com with ESMTPSA id fi11sm901647ejb.73.2021.03.11.00.49.16 (version=TLS1_3 cipher=TLS_AES_256_GCM_SHA384 bits=256/256); Thu, 11 Mar 2021 00:49:16 -0800 (PST) From: "Tzvetomir Stoyanov (VMware)" To: rostedt@goodmis.org Cc: linux-trace-devel@vger.kernel.org Subject: [PATCH v31 11/16] trace-cmd: Add a new option in trace file metadata for tsc2nsec conversion Date: Thu, 11 Mar 2021 10:48:52 +0200 Message-Id: <20210311084857.1919805-12-tz.stoyanov@gmail.com> X-Mailer: git-send-email 2.29.2 In-Reply-To: <20210311084857.1919805-1-tz.stoyanov@gmail.com> References: <20210311084857.1919805-1-tz.stoyanov@gmail.com> MIME-Version: 1.0 Precedence: bulk List-ID: X-Mailing-List: linux-trace-devel@vger.kernel.org A new option is added in the trace.dat file for holding the multiplier and shift, used for converting TSC trace clock to nanoseconds. Signed-off-by: Tzvetomir Stoyanov (VMware) --- .../include/private/trace-cmd-private.h | 1 + tracecmd/trace-dump.c | 18 ++++++++++++++++++ 2 files changed, 19 insertions(+) diff --git a/lib/trace-cmd/include/private/trace-cmd-private.h b/lib/trace-cmd/include/private/trace-cmd-private.h index 0f682c18..49e0bb42 100644 --- a/lib/trace-cmd/include/private/trace-cmd-private.h +++ b/lib/trace-cmd/include/private/trace-cmd-private.h @@ -125,6 +125,7 @@ enum { TRACECMD_OPTION_TRACEID, TRACECMD_OPTION_TIME_SHIFT, TRACECMD_OPTION_GUEST, + TRACECMD_OPTION_TSC2NSEC, }; enum { diff --git a/tracecmd/trace-dump.c b/tracecmd/trace-dump.c index c1143eba..31b13af4 100644 --- a/tracecmd/trace-dump.c +++ b/tracecmd/trace-dump.c @@ -487,6 +487,21 @@ out: free(buf); } +void dump_option_tsc2nsec(int fd, int size) +{ + int mult, shift, offset; + + do_print(OPTIONS, "\n\t\t[Option TSC2NSEC, %d bytes]\n", size); + + if (read_file_number(fd, &mult, 4)) + die("cannot read tsc2nsec multiplier"); + if (read_file_number(fd, &shift, 4)) + die("cannot read tsc2nsec shift"); + if (read_file_number(fd, &offset, 4)) + die("cannot read tsc2nsec offset"); + do_print(OPTIONS, "%d %d %d [multiplier, shift, offset]\n", mult, shift, offset); +} + static void dump_options(int fd) { unsigned short option; @@ -546,6 +561,9 @@ static void dump_options(int fd) case TRACECMD_OPTION_GUEST: dump_option_guest(fd, size); break; + case TRACECMD_OPTION_TSC2NSEC: + dump_option_tsc2nsec(fd, size); + break; default: do_print(OPTIONS, " %d %d\t[Unknown option, size - skipping]\n", option, size); From patchwork Thu Mar 11 08:48:53 2021 Content-Type: text/plain; charset="utf-8" MIME-Version: 1.0 Content-Transfer-Encoding: 7bit X-Patchwork-Submitter: "Tzvetomir Stoyanov (VMware)" X-Patchwork-Id: 12130635 Return-Path: X-Spam-Checker-Version: SpamAssassin 3.4.0 (2014-02-07) on aws-us-west-2-korg-lkml-1.web.codeaurora.org X-Spam-Level: X-Spam-Status: No, score=-15.8 required=3.0 tests=BAYES_00,DKIM_SIGNED, DKIM_VALID,DKIM_VALID_AU,FREEMAIL_FORGED_FROMDOMAIN,FREEMAIL_FROM, HEADER_FROM_DIFFERENT_DOMAINS,INCLUDES_CR_TRAILER,INCLUDES_PATCH, MAILING_LIST_MULTI,SPF_HELO_NONE,SPF_PASS,USER_AGENT_GIT autolearn=ham autolearn_force=no version=3.4.0 Received: from mail.kernel.org (mail.kernel.org [198.145.29.99]) by smtp.lore.kernel.org (Postfix) with ESMTP id 5B47FC4332E for ; Thu, 11 Mar 2021 08:49:49 +0000 (UTC) Received: from vger.kernel.org (vger.kernel.org [23.128.96.18]) by mail.kernel.org (Postfix) with ESMTP id 1A6F464FC4 for ; Thu, 11 Mar 2021 08:49:49 +0000 (UTC) Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S231341AbhCKIts (ORCPT ); Thu, 11 Mar 2021 03:49:48 -0500 Received: from lindbergh.monkeyblade.net ([23.128.96.19]:42780 "EHLO lindbergh.monkeyblade.net" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S231700AbhCKItT (ORCPT ); Thu, 11 Mar 2021 03:49:19 -0500 Received: from mail-ej1-x62a.google.com (mail-ej1-x62a.google.com [IPv6:2a00:1450:4864:20::62a]) by lindbergh.monkeyblade.net (Postfix) with ESMTPS id 8F101C061574 for ; Thu, 11 Mar 2021 00:49:19 -0800 (PST) Received: by mail-ej1-x62a.google.com with SMTP id p8so44503179ejb.10 for ; Thu, 11 Mar 2021 00:49:19 -0800 (PST) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=gmail.com; s=20161025; h=from:to:cc:subject:date:message-id:in-reply-to:references :mime-version:content-transfer-encoding; bh=lz7i5CVQ8hJ13/3J0CL0Vw1ZQNOv4KoXY5o1XgGysU0=; b=vgSaoKbD7A9EvcZO0J4QEslNM+AeDwHzCtBvQLdgpswfOUBhvaarNllDoFrsTpK9G6 c0V3JpMt2s9tc3dlKnN6XhzWEmDOIWKejaG5COihnbqeeV1X5S+o8P8Lw79U5E5uXF4Q pkDMzwYfGjoFAev1Kz2fzyBjrKD0X2IlPB0CLbH4YD10jm4afElODcRi2n+zNgYmPS3e IWD36QsBRSVUHGZ2ieYDe101n7guO+4FGzbjR3N5DccgpzRAxhdgi6FNJeVK1u31ByEk 297ULGfyVONgVtvkszqbXKpkqaWtD/1p7e12Lqne57pOOWyVBKlxnthP37LAfrQn+SvS mjRw== X-Google-DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=1e100.net; s=20161025; h=x-gm-message-state:from:to:cc:subject:date:message-id:in-reply-to :references:mime-version:content-transfer-encoding; bh=lz7i5CVQ8hJ13/3J0CL0Vw1ZQNOv4KoXY5o1XgGysU0=; b=PgrgkAfjWYXhdjZrRO3jyKymyIlw8JrJiT8uW0xJcvDKIFf0vgjFi7BbujT4/Msj9R JXxlLSnLR8YeNK0zTatE2WcDTez5UuaCV9fiAdsaDfanafSD4LY57GF2Gg5MJsQTWIH1 Wks/lIBwvCEiIikGw/M4gOb6ynavj+Msc5xSpC9hxQsB/Lvuz6OikEZ7V2laEK2pPzp5 wxeaPcVGrfrygBtnJAB6ki49FRLAR6GDKyxRpnDirLfmRnTOQrZoctZHn3hoek9zOOBD ehge2qX/DvH2rJpGz3sfOTmSi7HPFfYfb5tUkz+KwyCcTv6/tGJ6U0IAUooXtKL7UPl+ 6jwg== X-Gm-Message-State: AOAM532IgTnFt4Bajw27ElfpAZrdpyBIl3K3rgALrbWPytrUjhoaA3jp Go3rAERgWz1zoRbk46uLCz8= X-Google-Smtp-Source: ABdhPJxxsWwK2beoQMu1cgK8ITHSweYdhx/xFSnfXOgO7zTu6AJbmub3RPv9WQPOaKb1TG7al3FT2w== X-Received: by 2002:a17:906:c24b:: with SMTP id bl11mr2118032ejb.80.1615452558312; Thu, 11 Mar 2021 00:49:18 -0800 (PST) Received: from oberon.zico.biz ([83.222.187.186]) by smtp.gmail.com with ESMTPSA id fi11sm901647ejb.73.2021.03.11.00.49.17 (version=TLS1_3 cipher=TLS_AES_256_GCM_SHA384 bits=256/256); Thu, 11 Mar 2021 00:49:17 -0800 (PST) From: "Tzvetomir Stoyanov (VMware)" To: rostedt@goodmis.org Cc: linux-trace-devel@vger.kernel.org Subject: [PATCH v31 12/16] trace-cmd: Save information for tsc to nanoseconds conversion in trace file Date: Thu, 11 Mar 2021 10:48:53 +0200 Message-Id: <20210311084857.1919805-13-tz.stoyanov@gmail.com> X-Mailer: git-send-email 2.29.2 In-Reply-To: <20210311084857.1919805-1-tz.stoyanov@gmail.com> References: <20210311084857.1919805-1-tz.stoyanov@gmail.com> MIME-Version: 1.0 Precedence: bulk List-ID: X-Mailing-List: linux-trace-devel@vger.kernel.org Store multiplier and shift, required for TSC clock to nanosecond conversion in the metadata of the trace file. Signed-off-by: Tzvetomir Stoyanov (VMware) --- tracecmd/trace-record.c | 30 ++++++++++++++++++++++++++++++ 1 file changed, 30 insertions(+) diff --git a/tracecmd/trace-record.c b/tracecmd/trace-record.c index 15521d0d..1313af03 100644 --- a/tracecmd/trace-record.c +++ b/tracecmd/trace-record.c @@ -666,6 +666,17 @@ static void delete_thread_data(void) } } +static void +add_tsc2nsec(struct tracecmd_output *handle, struct buffer_instance *instance) +{ + int array[] = { instance->tsc2nsec.mult, + instance->tsc2nsec.shift, + instance->tsc2nsec.offset}; + + tracecmd_add_option(handle, TRACECMD_OPTION_TSC2NSEC, + sizeof(array), array); +} + static void host_tsync_complete(struct buffer_instance *instance) { struct tracecmd_output *handle = NULL; @@ -680,6 +691,16 @@ static void host_tsync_complete(struct buffer_instance *instance) handle = tracecmd_get_output_handle_fd(fd); if (!handle) die("cannot create output handle"); + + /* + * If TSC is used as current trace clock and there is + * information for tsc to nanosecond conversion, store it + * in the trace file + */ + if (instance->tsc2nsec.mult && instance->clock && + !strncmp(top_instance.clock, TSC_CLOCK, strlen(TSC_CLOCK))) + add_tsc2nsec(handle, instance); + tracecmd_write_guest_time_shift(handle, instance->tsync); tracecmd_append_options(handle); tracecmd_output_close(handle); @@ -4269,6 +4290,15 @@ static void record_data(struct common_record_context *ctx) add_guest_info(handle, instance); } + /* + * If TSC is used as current trace clock and there is + * information for tsc to nanosecond conversion, store it + * in the trace file + */ + if (top_instance.tsc2nsec.mult && top_instance.clock && + !strncmp(top_instance.clock, TSC_CLOCK, strlen(TSC_CLOCK))) + add_tsc2nsec(handle, &top_instance); + if (tracecmd_write_cmdlines(handle)) die("Writing cmdlines"); From patchwork Thu Mar 11 08:48:54 2021 Content-Type: text/plain; charset="utf-8" MIME-Version: 1.0 Content-Transfer-Encoding: 7bit X-Patchwork-Submitter: "Tzvetomir Stoyanov (VMware)" X-Patchwork-Id: 12130627 Return-Path: X-Spam-Checker-Version: SpamAssassin 3.4.0 (2014-02-07) on aws-us-west-2-korg-lkml-1.web.codeaurora.org X-Spam-Level: X-Spam-Status: No, score=-15.8 required=3.0 tests=BAYES_00,DKIM_SIGNED, DKIM_VALID,DKIM_VALID_AU,FREEMAIL_FORGED_FROMDOMAIN,FREEMAIL_FROM, HEADER_FROM_DIFFERENT_DOMAINS,INCLUDES_CR_TRAILER,INCLUDES_PATCH, MAILING_LIST_MULTI,SPF_HELO_NONE,SPF_PASS,USER_AGENT_GIT autolearn=ham autolearn_force=no version=3.4.0 Received: from mail.kernel.org (mail.kernel.org [198.145.29.99]) by smtp.lore.kernel.org (Postfix) with ESMTP id 11213C4332D for ; Thu, 11 Mar 2021 08:49:49 +0000 (UTC) Received: from vger.kernel.org (vger.kernel.org [23.128.96.18]) by mail.kernel.org (Postfix) with ESMTP id C4A3964FA9 for ; Thu, 11 Mar 2021 08:49:48 +0000 (UTC) Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S231492AbhCKIts (ORCPT ); Thu, 11 Mar 2021 03:49:48 -0500 Received: from lindbergh.monkeyblade.net ([23.128.96.19]:42788 "EHLO lindbergh.monkeyblade.net" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S231749AbhCKItU (ORCPT ); Thu, 11 Mar 2021 03:49:20 -0500 Received: from mail-ed1-x529.google.com (mail-ed1-x529.google.com [IPv6:2a00:1450:4864:20::529]) by lindbergh.monkeyblade.net (Postfix) with ESMTPS id 5195DC061574 for ; Thu, 11 Mar 2021 00:49:20 -0800 (PST) Received: by mail-ed1-x529.google.com with SMTP id bx7so1529458edb.12 for ; Thu, 11 Mar 2021 00:49:20 -0800 (PST) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=gmail.com; s=20161025; h=from:to:cc:subject:date:message-id:in-reply-to:references :mime-version:content-transfer-encoding; bh=ubW2VtRXk6619zvLvFgs1cmDN0fZDzihD4b6s1f7Hf0=; b=qHJM7dHc6asgWAIYlAhgG3pBG4bozJWqaNWGDMG766LKsbrhQNuoM3dR9TGQ2yg8dK w9Cts58RJ/Cnbai+bQt4NbeiIVQWk0X0SvgWXJy3YRiH3DffmSmH+EePTRllsCl6gXyF lEUL5/wWw1MxAcmy0sfC4f9hDKt1ZM5al85kQj7nBwdL3m/bJW019YxnvWpjE5BhW5cU fol7duwdd6zVo87qYXywwceMjBAo3rAb8mQ8wJdwQjmzmhh+kDVGIIsgwjf8219F2Ay8 pw4UhqGSX8WzawlZKHZM1XrFU/cRWSl0K8azZgz8kN1pIM8iFyC4nDGXgE5m653rn0w5 LpPA== X-Google-DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=1e100.net; s=20161025; h=x-gm-message-state:from:to:cc:subject:date:message-id:in-reply-to :references:mime-version:content-transfer-encoding; bh=ubW2VtRXk6619zvLvFgs1cmDN0fZDzihD4b6s1f7Hf0=; b=hxSbV25IzHxa3fCH3yrA2ZZ5pa2JYG+jktQylPM5xy/zS3VEkC6++G6CdciupZVHSy dv1IVSWGaDwDsy4+sgzYcVQis985knpkSeGptAaxV8h/z/sESrrnXaTdTReXR0ot5E1x qJAueM0Oh9VwCuJPJptSNr9Jb5Ihfp32ES53jJeOmePkwhkqeXY8Bj2yHWCE2kVdMJzz NbAO8KQAPuRrA4JoFTokVYymYKSLxPWSBQVzqeMiyGuGe6ouHIzNYKU8By1/dgtae4wG oKPAbM5sJL6zdltCqD5wFBVT0koUBnP+zrFVHSAfnjG+8PimhWUoIggnx7a1i2rV2FyM I/1A== X-Gm-Message-State: AOAM533BempfmU2kuCBO/+Zg3jwnCga/NCJCDfrJXuzBSoDfmlgDgBTA C5GAiOL/FuBzKmSnPuLzjuY= X-Google-Smtp-Source: ABdhPJygqERIejnjkD5L4l5p6eb1TgZlqV4FPufDmBN2c0hvF4okWrxIWa5yV+6LH1An1AzakKm1Gw== X-Received: by 2002:a05:6402:3047:: with SMTP id bu7mr7418430edb.227.1615452559115; Thu, 11 Mar 2021 00:49:19 -0800 (PST) Received: from oberon.zico.biz ([83.222.187.186]) by smtp.gmail.com with ESMTPSA id fi11sm901647ejb.73.2021.03.11.00.49.18 (version=TLS1_3 cipher=TLS_AES_256_GCM_SHA384 bits=256/256); Thu, 11 Mar 2021 00:49:18 -0800 (PST) From: "Tzvetomir Stoyanov (VMware)" To: rostedt@goodmis.org Cc: linux-trace-devel@vger.kernel.org Subject: [PATCH v31 13/16] trace-cmd: Read information for tsc to nanoseconds conversion from trace file Date: Thu, 11 Mar 2021 10:48:54 +0200 Message-Id: <20210311084857.1919805-14-tz.stoyanov@gmail.com> X-Mailer: git-send-email 2.29.2 In-Reply-To: <20210311084857.1919805-1-tz.stoyanov@gmail.com> References: <20210311084857.1919805-1-tz.stoyanov@gmail.com> MIME-Version: 1.0 Precedence: bulk List-ID: X-Mailing-List: linux-trace-devel@vger.kernel.org Read multiplier and shift, required for TSC clock to nanosecond conversion from the metadata of the trace file and save them in the tracecmd input file handler. Signed-off-by: Tzvetomir Stoyanov (VMware) --- lib/trace-cmd/trace-input.c | 18 ++++++++++++++++++ 1 file changed, 18 insertions(+) diff --git a/lib/trace-cmd/trace-input.c b/lib/trace-cmd/trace-input.c index 971a6c01..1a3133e8 100644 --- a/lib/trace-cmd/trace-input.c +++ b/lib/trace-cmd/trace-input.c @@ -107,6 +107,12 @@ struct host_trace_info { struct timesync_offsets *ts_offsets; }; +struct tsc2nsec { + int mult; + int shift; + int offset; +}; + struct tracecmd_input { struct tep_handle *pevent; unsigned long file_state; @@ -126,6 +132,8 @@ struct tracecmd_input { bool use_pipe; struct cpu_data *cpu_data; long long ts_offset; + struct tsc2nsec tsc_calc; + struct host_trace_info host; double ts2secs; char * cpustats; @@ -2727,6 +2735,16 @@ static int handle_options(struct tracecmd_input *handle) case TRACECMD_OPTION_GUEST: trace_guest_load(handle, buf, size); break; + case TRACECMD_OPTION_TSC2NSEC: + if (size != 12) + break; + handle->tsc_calc.mult = tep_read_number(handle->pevent, + buf, 4); + handle->tsc_calc.shift = tep_read_number(handle->pevent, + buf + 4, 4); + handle->tsc_calc.offset = tep_read_number(handle->pevent, + buf + 8, 4); + break; default: warning("unknown option %d", option); break; From patchwork Thu Mar 11 08:48:55 2021 Content-Type: text/plain; charset="utf-8" MIME-Version: 1.0 Content-Transfer-Encoding: 7bit X-Patchwork-Submitter: "Tzvetomir Stoyanov (VMware)" X-Patchwork-Id: 12130633 Return-Path: X-Spam-Checker-Version: SpamAssassin 3.4.0 (2014-02-07) on aws-us-west-2-korg-lkml-1.web.codeaurora.org X-Spam-Level: X-Spam-Status: No, score=-15.8 required=3.0 tests=BAYES_00,DKIM_SIGNED, DKIM_VALID,DKIM_VALID_AU,FREEMAIL_FORGED_FROMDOMAIN,FREEMAIL_FROM, HEADER_FROM_DIFFERENT_DOMAINS,INCLUDES_CR_TRAILER,INCLUDES_PATCH, MAILING_LIST_MULTI,SPF_HELO_NONE,SPF_PASS,USER_AGENT_GIT autolearn=ham autolearn_force=no version=3.4.0 Received: from mail.kernel.org (mail.kernel.org [198.145.29.99]) by smtp.lore.kernel.org (Postfix) with ESMTP id 666E4C43332 for ; Thu, 11 Mar 2021 08:49:49 +0000 (UTC) Received: from vger.kernel.org (vger.kernel.org [23.128.96.18]) by mail.kernel.org (Postfix) with ESMTP id 3B97A64FAA for ; Thu, 11 Mar 2021 08:49:49 +0000 (UTC) Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S231533AbhCKIts (ORCPT ); Thu, 11 Mar 2021 03:49:48 -0500 Received: from lindbergh.monkeyblade.net ([23.128.96.19]:42790 "EHLO lindbergh.monkeyblade.net" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S231751AbhCKItV (ORCPT ); Thu, 11 Mar 2021 03:49:21 -0500 Received: from mail-ej1-x632.google.com (mail-ej1-x632.google.com [IPv6:2a00:1450:4864:20::632]) by lindbergh.monkeyblade.net (Postfix) with ESMTPS id 8EB97C061574 for ; Thu, 11 Mar 2021 00:49:21 -0800 (PST) Received: by mail-ej1-x632.google.com with SMTP id r17so44491830ejy.13 for ; Thu, 11 Mar 2021 00:49:21 -0800 (PST) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=gmail.com; s=20161025; h=from:to:cc:subject:date:message-id:in-reply-to:references :mime-version:content-transfer-encoding; bh=vUcvTEjKkWIcmMOByMKvh5s8F0YAO/OkTuBFL0Uy31Y=; b=ZWF79Zn/ru3DwZcTmNdqkCdai7AO5SS9HJ6qcgThu4T39cmg+xyh9RayrKOncfUghC WAEEWvid2HVwoRKsP/Amw24pCBoDRnz13q3QAl2FYtuCZqAsTkVDxy3qwv9t4g9OMBZ6 Ir34dNWlKHs8a6oJTrhxh1seGOczkyOmcKKJFgPM7cLDMSER2tjGVRpgKR/WXJSqu7MN nb9Tnn+czgDalM2vc/CzbVnXROhLCEuvvB5jQk01ZlJO5baJBrIAncRJkCdyuN31dB9n /+Ocf8+1q0TiajU3U7vXRHy+lQWKmd7xOxVimQeGZpGCLVGExwY3Kf8FOq9ADuPXXEW7 Kfbg== X-Google-DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=1e100.net; s=20161025; h=x-gm-message-state:from:to:cc:subject:date:message-id:in-reply-to :references:mime-version:content-transfer-encoding; bh=vUcvTEjKkWIcmMOByMKvh5s8F0YAO/OkTuBFL0Uy31Y=; b=C7Pw4zB6La43YmDp5Iz0+OXgLLvssw6oRhlqALmQ7fAzWQ+Y8z4CEJwIKFpBvxmcaf Q5zmK9vs3g3xkJoqbVH0F4g2+Oi0W0CdIAk18EhWr/t8+BkCvasUPvyAIo4N8V+M86J6 ClAr0968pc0HaVD9C+/1A3kop/u910Scxtnx7T3jQRZGzrYPsm7x4QG3+I3YXWXGPRq/ Pgk6QqenpskQLMYLMiTsYZUDeItMwm+46R+LC1PK2lYFalxwW09hf3j1K23pR2eYFVnA IqvjNhTRVhNVrsT6CeYt+K++vEt9VoKZVeNOW1LbW1070yKnL1SjUwsBvwkxexhhKoJ0 HUvg== X-Gm-Message-State: AOAM5335jI2U3ufmm5BWpnNWSlo9nCcdYUC3R257YM4SPWX75QhlDSkz RzU3MWCaa1+0Mns6fAFRNF57XMMlLnvhrg== X-Google-Smtp-Source: ABdhPJyn2cLsKmJwLnztnXdzpai1N6VGsphvUTK7jU1jiDtzTQZ4QgH071kI5axVyEsWqQnbcugUuA== X-Received: by 2002:a17:907:2513:: with SMTP id y19mr2021738ejl.241.1615452560267; Thu, 11 Mar 2021 00:49:20 -0800 (PST) Received: from oberon.zico.biz ([83.222.187.186]) by smtp.gmail.com with ESMTPSA id fi11sm901647ejb.73.2021.03.11.00.49.19 (version=TLS1_3 cipher=TLS_AES_256_GCM_SHA384 bits=256/256); Thu, 11 Mar 2021 00:49:19 -0800 (PST) From: "Tzvetomir Stoyanov (VMware)" To: rostedt@goodmis.org Cc: linux-trace-devel@vger.kernel.org Subject: [PATCH v31 14/16] trace-cmd: Remove unneeded multiply in events timestamp reading Date: Thu, 11 Mar 2021 10:48:55 +0200 Message-Id: <20210311084857.1919805-15-tz.stoyanov@gmail.com> X-Mailer: git-send-email 2.29.2 In-Reply-To: <20210311084857.1919805-1-tz.stoyanov@gmail.com> References: <20210311084857.1919805-1-tz.stoyanov@gmail.com> MIME-Version: 1.0 Precedence: bulk List-ID: X-Mailing-List: linux-trace-devel@vger.kernel.org When the event timestamp is converted to seconds, the local variable that holds this timestamp is converted to seconds also. As this variable is not used in the function later, this conversion in not needed. Signed-off-by: Tzvetomir Stoyanov (VMware) --- lib/trace-cmd/trace-input.c | 4 +--- 1 file changed, 1 insertion(+), 3 deletions(-) diff --git a/lib/trace-cmd/trace-input.c b/lib/trace-cmd/trace-input.c index 1a3133e8..9bdf9da7 100644 --- a/lib/trace-cmd/trace-input.c +++ b/lib/trace-cmd/trace-input.c @@ -1944,10 +1944,8 @@ read_again: handle->cpu_data[cpu].timestamp = timestamp_correct(ts, cpu, handle); - if (handle->ts2secs) { + if (handle->ts2secs) handle->cpu_data[cpu].timestamp *= handle->ts2secs; - ts *= handle->ts2secs; - } index = kbuffer_curr_offset(kbuf); From patchwork Thu Mar 11 08:48:56 2021 Content-Type: text/plain; charset="utf-8" MIME-Version: 1.0 Content-Transfer-Encoding: 7bit X-Patchwork-Submitter: "Tzvetomir Stoyanov (VMware)" X-Patchwork-Id: 12130639 Return-Path: X-Spam-Checker-Version: SpamAssassin 3.4.0 (2014-02-07) on aws-us-west-2-korg-lkml-1.web.codeaurora.org X-Spam-Level: X-Spam-Status: No, score=-15.8 required=3.0 tests=BAYES_00,DKIM_SIGNED, DKIM_VALID,DKIM_VALID_AU,FREEMAIL_FORGED_FROMDOMAIN,FREEMAIL_FROM, HEADER_FROM_DIFFERENT_DOMAINS,INCLUDES_CR_TRAILER,INCLUDES_PATCH, MAILING_LIST_MULTI,SPF_HELO_NONE,SPF_PASS,USER_AGENT_GIT autolearn=ham autolearn_force=no version=3.4.0 Received: from mail.kernel.org (mail.kernel.org [198.145.29.99]) by smtp.lore.kernel.org (Postfix) with ESMTP id 32792C43333 for ; Thu, 11 Mar 2021 08:49:50 +0000 (UTC) Received: from vger.kernel.org (vger.kernel.org [23.128.96.18]) by mail.kernel.org (Postfix) with ESMTP id ED80564FBB for ; Thu, 11 Mar 2021 08:49:49 +0000 (UTC) Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S231700AbhCKItt (ORCPT ); Thu, 11 Mar 2021 03:49:49 -0500 Received: from lindbergh.monkeyblade.net ([23.128.96.19]:42800 "EHLO lindbergh.monkeyblade.net" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S231405AbhCKItX (ORCPT ); Thu, 11 Mar 2021 03:49:23 -0500 Received: from mail-ed1-x52f.google.com (mail-ed1-x52f.google.com [IPv6:2a00:1450:4864:20::52f]) by lindbergh.monkeyblade.net (Postfix) with ESMTPS id A48EEC061574 for ; Thu, 11 Mar 2021 00:49:22 -0800 (PST) Received: by mail-ed1-x52f.google.com with SMTP id j3so1524722edp.11 for ; Thu, 11 Mar 2021 00:49:22 -0800 (PST) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=gmail.com; s=20161025; h=from:to:cc:subject:date:message-id:in-reply-to:references :mime-version:content-transfer-encoding; bh=FRK7YrP3vAmeLQ4bYf0AKVl73RxYXJHpz9lk9pfzyNo=; b=kQ1Dl+HHQYJNLBduwEhOrshad4IJNImIwi+FEjzfayV0QjbSjb9LxIinueEVYG4Ujv 4wCyqk010nrW6chH8Km9KNRPkyqQ6Hcs81aYZMIuPdJcndeAbky7s3g0MoKVovz6p+YW W0L3uFGLC5S4nxxN/Qcp3wYVD99qM4eVl068d+0pXaOyWRxGw+7K+KTedEpCBw2+qQBr /r2QigLr3954sizunL5NIyx4jz1xQeTAfSgOkCyKAIMd9FBTr8h7JuNtnlbfoDja8yrs 0ysdc4BtuC1Hedo3pS1FV2fHYOM9/1lLMFxaesV/9jfNwY6He6+9bFzmjXvMXPJUIEga dhUA== X-Google-DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=1e100.net; s=20161025; h=x-gm-message-state:from:to:cc:subject:date:message-id:in-reply-to :references:mime-version:content-transfer-encoding; bh=FRK7YrP3vAmeLQ4bYf0AKVl73RxYXJHpz9lk9pfzyNo=; b=rCggzrUKzN2dTgDsWvMOqD2dC8xbQCLoAzY7vrXaXP0aP/I/MEfk0bgEcXJdk0F/RZ Qc8pBxAWjJg1Gas8lYJyxAun+zzPMKwzVvumQ+drt97agoQDz2+aTaJudn3EHWsAJOO3 OWGrfas5KxwNcegKOXTUA+PC5N5ojxNXCPhjnXHhI7W2PvCFh1Ypb7x14uBGOgQOB1Y7 QImxe//abkVwfZm0fFOyceUzEa377neM5VUpgyeT3kDkx5ytB8wHqdxe04PLDUvkrzPf zwJfoWHt84xXATBAmODRoFFGYBDOUIrCe0MZqsNkK2szlVzcyw0nT3auweIEOQPGhAFH k14A== X-Gm-Message-State: AOAM5312JGlZEt3iXbZr9Yxqyl4K5GFSebOYcgAIQOUuv5LoYwMt//L5 HW9p4VEk5tYiEIBqXMrTmJujBnBeCyogCw== X-Google-Smtp-Source: ABdhPJylmmkYBdH7O5WV5uZyL0dXZVK1g0hKtlyT+j5yGnU53G+MACuFLxHrgPbHZGNEAW/N5U0rNA== X-Received: by 2002:aa7:c1d0:: with SMTP id d16mr7297227edp.153.1615452561362; Thu, 11 Mar 2021 00:49:21 -0800 (PST) Received: from oberon.zico.biz ([83.222.187.186]) by smtp.gmail.com with ESMTPSA id fi11sm901647ejb.73.2021.03.11.00.49.20 (version=TLS1_3 cipher=TLS_AES_256_GCM_SHA384 bits=256/256); Thu, 11 Mar 2021 00:49:20 -0800 (PST) From: "Tzvetomir Stoyanov (VMware)" To: rostedt@goodmis.org Cc: linux-trace-devel@vger.kernel.org Subject: [PATCH v31 15/16] trace-cmd: Perform all timestamp corrections in a single function Date: Thu, 11 Mar 2021 10:48:56 +0200 Message-Id: <20210311084857.1919805-16-tz.stoyanov@gmail.com> X-Mailer: git-send-email 2.29.2 In-Reply-To: <20210311084857.1919805-1-tz.stoyanov@gmail.com> References: <20210311084857.1919805-1-tz.stoyanov@gmail.com> MIME-Version: 1.0 Precedence: bulk List-ID: X-Mailing-List: linux-trace-devel@vger.kernel.org When reading event timestamps from a trace file, there could be various corrections depending on the metadata information from the file. Move all logic that performs timestamp calculations in a single function. Signed-off-by: Tzvetomir Stoyanov (VMware) --- lib/trace-cmd/trace-input.c | 25 ++++++++++++++++--------- 1 file changed, 16 insertions(+), 9 deletions(-) diff --git a/lib/trace-cmd/trace-input.c b/lib/trace-cmd/trace-input.c index 9bdf9da7..60a59873 100644 --- a/lib/trace-cmd/trace-input.c +++ b/lib/trace-cmd/trace-input.c @@ -1287,6 +1287,19 @@ static unsigned long long timestamp_correct(unsigned long long ts, int cpu, &tsync->ts_samples[mid+1]); } +static unsigned long long timestamp_calc(unsigned long long ts, int cpu, + struct tracecmd_input *handle) +{ + unsigned long long tstamp; + + tstamp = timestamp_correct(ts, cpu, handle); + + if (handle->ts2secs) + tstamp *= handle->ts2secs; + + return tstamp; +} + /* * Page is mapped, now read in the page header info. */ @@ -1308,11 +1321,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), - cpu, handle); - - if (handle->ts2secs) - handle->cpu_data[cpu].timestamp *= handle->ts2secs; + handle->cpu_data[cpu].timestamp = timestamp_calc(kbuffer_timestamp(kbuf), + cpu, handle); return 0; } @@ -1942,10 +1952,7 @@ read_again: goto read_again; } - handle->cpu_data[cpu].timestamp = timestamp_correct(ts, cpu, handle); - - if (handle->ts2secs) - handle->cpu_data[cpu].timestamp *= handle->ts2secs; + handle->cpu_data[cpu].timestamp = timestamp_calc(ts, cpu, handle); index = kbuffer_curr_offset(kbuf); From patchwork Thu Mar 11 08:48:57 2021 Content-Type: text/plain; charset="utf-8" MIME-Version: 1.0 Content-Transfer-Encoding: 7bit X-Patchwork-Submitter: "Tzvetomir Stoyanov (VMware)" X-Patchwork-Id: 12130637 Return-Path: X-Spam-Checker-Version: SpamAssassin 3.4.0 (2014-02-07) on aws-us-west-2-korg-lkml-1.web.codeaurora.org X-Spam-Level: X-Spam-Status: No, score=-15.8 required=3.0 tests=BAYES_00,DKIM_SIGNED, DKIM_VALID,DKIM_VALID_AU,FREEMAIL_FORGED_FROMDOMAIN,FREEMAIL_FROM, HEADER_FROM_DIFFERENT_DOMAINS,INCLUDES_CR_TRAILER,INCLUDES_PATCH, MAILING_LIST_MULTI,SPF_HELO_NONE,SPF_PASS,USER_AGENT_GIT autolearn=ham autolearn_force=no version=3.4.0 Received: from mail.kernel.org (mail.kernel.org [198.145.29.99]) by smtp.lore.kernel.org (Postfix) with ESMTP id 8C05EC43331 for ; Thu, 11 Mar 2021 08:49:49 +0000 (UTC) Received: from vger.kernel.org (vger.kernel.org [23.128.96.18]) by mail.kernel.org (Postfix) with ESMTP id 60F0664FBB for ; Thu, 11 Mar 2021 08:49:49 +0000 (UTC) Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S231571AbhCKItt (ORCPT ); Thu, 11 Mar 2021 03:49:49 -0500 Received: from lindbergh.monkeyblade.net ([23.128.96.19]:42802 "EHLO lindbergh.monkeyblade.net" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S231755AbhCKItX (ORCPT ); Thu, 11 Mar 2021 03:49:23 -0500 Received: from mail-ed1-x534.google.com (mail-ed1-x534.google.com [IPv6:2a00:1450:4864:20::534]) by lindbergh.monkeyblade.net (Postfix) with ESMTPS id 72D8FC061574 for ; Thu, 11 Mar 2021 00:49:23 -0800 (PST) Received: by mail-ed1-x534.google.com with SMTP id dm8so1527553edb.2 for ; Thu, 11 Mar 2021 00:49:23 -0800 (PST) DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=gmail.com; s=20161025; h=from:to:cc:subject:date:message-id:in-reply-to:references :mime-version:content-transfer-encoding; bh=RICwZa/SJTEbfo0d3e5OR2tYOHLkAgRWMHeH7N1IA2Q=; b=DbYAeNB+19zFBs/9HDvdZlAn6NFEkfMj8RRZZvpSg90PKXkRnLgT8oSZkkVM3g7T8v cDbyJSirjl7/YenyRS2ujHxAgpVTRtEoAWyfpjzyOEECpEnmzujhJ0E5vYNgXH7baNR0 CiF9FFig2a4ngYQ3U9Tq387VCg5OtbXEAHqm3jAMjJLGLSfwlGFvDUE9fWjVio52zGJJ Hc4qOHBF6nWfccsQkJ3S6ubGr8cUc0FV7FWd//XciE+PzehhtUXc/gN0nPCC9rbGo67j Dz1ekRvAswMcqpA0jhMEyICfJtqAW3GHpoav95Isd2ecNMnbm/2V1B9dpJ509tGkNavY bDrg== X-Google-DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=1e100.net; s=20161025; h=x-gm-message-state:from:to:cc:subject:date:message-id:in-reply-to :references:mime-version:content-transfer-encoding; bh=RICwZa/SJTEbfo0d3e5OR2tYOHLkAgRWMHeH7N1IA2Q=; b=PMCIzX/ERrbrYAFtlJUe2rOynEg3l8JZRjF7omBkApVBJOYrkUBkvgbh/aPjJS8riB oGlZi3IZ32nTFHi5vWLli4+R9i4bOZIY9ipZ+v9GjTEhTzQ+dAPpqL75/TnrnWw7C+9N diete8WeohoqWG0y5CJZNb+bf7+/8bH1fxiBvTEoc5wWYQTIkaLITbj0ABf288Rh/6A1 ohtDTiSBpKbjrq76T8x/eUMLA2yUTMaOn3zwfUhH4qjhUnWdxW1qCZnyF9eAVJbnhLgu X9X6XKaPQSBgmSwnLp2RghiAzqGL6OStNhKOC1m9VvOlMrYftHeRUZ6EQKa9I+xoRsjy 7O+A== X-Gm-Message-State: AOAM533PT4pNpT7L/679oy/npsUoXcKrSY7N2R0Kx8+5g1C3N8wLYRrD RQgLp3/HGiQuOHhxMA6cQFqrjcvQZRVp1Q== X-Google-Smtp-Source: ABdhPJwPVNIMVAf3KpXdIMdE/etyETbgmK5nam01CdIlrzuEicVKwx9hBeUl+pyGNXvBFeAVL4pmCA== X-Received: by 2002:a05:6402:51cd:: with SMTP id r13mr7513082edd.116.1615452562236; Thu, 11 Mar 2021 00:49:22 -0800 (PST) Received: from oberon.zico.biz ([83.222.187.186]) by smtp.gmail.com with ESMTPSA id fi11sm901647ejb.73.2021.03.11.00.49.21 (version=TLS1_3 cipher=TLS_AES_256_GCM_SHA384 bits=256/256); Thu, 11 Mar 2021 00:49:21 -0800 (PST) From: "Tzvetomir Stoyanov (VMware)" To: rostedt@goodmis.org Cc: linux-trace-devel@vger.kernel.org Subject: [PATCH v31 16/16] trace-cmd: Convert tsc timestamps to nanosecods when reading trace data from a file Date: Thu, 11 Mar 2021 10:48:57 +0200 Message-Id: <20210311084857.1919805-17-tz.stoyanov@gmail.com> X-Mailer: git-send-email 2.29.2 In-Reply-To: <20210311084857.1919805-1-tz.stoyanov@gmail.com> References: <20210311084857.1919805-1-tz.stoyanov@gmail.com> MIME-Version: 1.0 Precedence: bulk List-ID: X-Mailing-List: linux-trace-devel@vger.kernel.org If there is information for TSC to nanoseconds conversion in the trace file metadata, use it to recalculate the timestamps of all events. Signed-off-by: Tzvetomir Stoyanov (VMware) --- lib/trace-cmd/trace-input.c | 28 ++++++++++++++++++++++++---- 1 file changed, 24 insertions(+), 4 deletions(-) diff --git a/lib/trace-cmd/trace-input.c b/lib/trace-cmd/trace-input.c index 60a59873..66483cc8 100644 --- a/lib/trace-cmd/trace-input.c +++ b/lib/trace-cmd/trace-input.c @@ -1287,17 +1287,37 @@ static unsigned long long timestamp_correct(unsigned long long ts, int cpu, &tsync->ts_samples[mid+1]); } +static unsigned long long mul_u64_u32_shr(unsigned long long a, + unsigned long long mul, unsigned int shift) +{ + unsigned int ah, al; + unsigned long long ret; + + al = a; + ah = a >> 32; + + ret = (al * mul) >> shift; + if (ah) + ret += (ah * mul) << (32 - shift); + + return ret; +} + static unsigned long long timestamp_calc(unsigned long long ts, int cpu, struct tracecmd_input *handle) { - unsigned long long tstamp; + unsigned long long t; - tstamp = timestamp_correct(ts, cpu, handle); + t = timestamp_correct(ts, cpu, handle); if (handle->ts2secs) - tstamp *= handle->ts2secs; + t *= handle->ts2secs; + else if (handle->tsc_calc.mult) { + t = mul_u64_u32_shr(t, handle->tsc_calc.mult, handle->tsc_calc.shift); + t += handle->tsc_calc.offset; + } - return tstamp; + return t; } /*