From patchwork Mon Feb 8 06:17:36 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: 12074049 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=-20.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,MENTIONS_GIT_HOSTING,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 4F4EBC433E0 for ; Mon, 8 Feb 2021 06:18:46 +0000 (UTC) Received: from vger.kernel.org (vger.kernel.org [23.128.96.18]) by mail.kernel.org (Postfix) with ESMTP id 132ED64E6E for ; Mon, 8 Feb 2021 06:18:46 +0000 (UTC) Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S229581AbhBHGSa (ORCPT ); Mon, 8 Feb 2021 01:18:30 -0500 Received: from lindbergh.monkeyblade.net ([23.128.96.19]:50120 "EHLO lindbergh.monkeyblade.net" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S229669AbhBHGSa (ORCPT ); Mon, 8 Feb 2021 01:18:30 -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 941A5C061788 for ; Sun, 7 Feb 2021 22:17:49 -0800 (PST) Received: by mail-ed1-x52c.google.com with SMTP id q2so16774691edi.4 for ; Sun, 07 Feb 2021 22:17:49 -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=+Mf+IfNt6WZXwCUi1S4JcV+ZjD0Hww96HTqPp5lhJPQ=; b=miqS+sVyZRhYT7Hs6qxqrXWlZRcizlUCALXbRcMVfL2veY2w66VGCvlUFBrou5pvgi iZAfvL6+v2f3+0gjq064g3hF1cRHzfIKxz7/2uMvyLvwJFcQsvoaOcpVF/mKyQzxuLZX +0F8kQ2dx0iLdxOwPnjBHATGQl9JDx1LtsyTIoklQLU/zAwnd5ryEtHTkULdVc6qpRqk 7lyBgtlqXJidl9S+S3Fj4ClKa+gijtMyZEetOvX5fTopnd/dUPmaBDQAoPCkkDvyL/EQ Ny+DkR6rX9WYTAVj+ZmzUUWwoeZgUPncTmt2aEckTRt8TV4mAbMBtNugTQJ/zZCErg2z /gzQ== 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=+Mf+IfNt6WZXwCUi1S4JcV+ZjD0Hww96HTqPp5lhJPQ=; b=MQ4zkukW10GnZCpF7Oi65V9jufQsh+N6fIxqbeYIvpw5AEdQvOTL5/ZDr6TNTUvYIp dXeBMJ9yaWuI52gomq255Z6lIkOeMQmUDVWoN3sPlOu5EBMfBAfo6lOPECKWBJZyPpt/ ClXhXmPa7zuBPcFAmfZsG5t3g5nTNPf8MQ196D7BsQrdmN1UXaauCd8K0j8FpJLYs4Ip T0OzLKsUGW98nWifeqlD9L1WSZE9olZZkB1rK48lp/gG8phB3FHnMDVdF9F0KW2mdsDL 4nKUtEydrWOfHWyrQWrbQ50p4/PnyDJzdHPPqKGG1zpsDgymS1GMJruktv+mX9ThTvDz Z2Rg== X-Gm-Message-State: AOAM531u0AujBsXwF4itZdS6z4SNHxeNJ/gIkeWI7uQzw5XgeB1VI1GJ 5Cipu6tU2N4n/DuBz+Cn53jqlEEKOyhCQg== X-Google-Smtp-Source: ABdhPJzzHdyF5HOoOSfqhwOLVXNxBRdDgsfB9AiTFXJUCoIYyByjGOP9WKPeBt3HYukoWfAfEShAug== X-Received: by 2002:a05:6402:1589:: with SMTP id c9mr16063816edv.282.1612765068333; Sun, 07 Feb 2021 22:17:48 -0800 (PST) Received: from oberon.zico.biz ([83.222.187.186]) by smtp.gmail.com with ESMTPSA id 35sm135618edp.85.2021.02.07.22.17.47 (version=TLS1_3 cipher=TLS_AES_256_GCM_SHA384 bits=256/256); Sun, 07 Feb 2021 22:17:47 -0800 (PST) From: "Tzvetomir Stoyanov (VMware)" To: rostedt@goodmis.org Cc: linux-trace-devel@vger.kernel.org Subject: [PATCH v28 1/8] trace-cmd: Save command lines in VM agent Date: Mon, 8 Feb 2021 08:17:36 +0200 Message-Id: <20210208061743.510964-2-tz.stoyanov@gmail.com> X-Mailer: git-send-email 2.29.2 In-Reply-To: <20210208061743.510964-1-tz.stoyanov@gmail.com> References: <20210208061743.510964-1-tz.stoyanov@gmail.com> MIME-Version: 1.0 Precedence: bulk List-ID: X-Mailing-List: linux-trace-devel@vger.kernel.org Command lines were not saved in the guest tracing file, due to bug inrtoduced by commit: https://git.kernel.org/pub/scm/utils/trace-cmd/trace-cmd.git/commit/?id=1eea02a4bef10507d157489a1ee97f273db7b319 Signed-off-by: Tzvetomir Stoyanov (VMware) --- lib/trace-cmd/include/private/trace-cmd-private.h | 3 +++ lib/trace-cmd/trace-output.c | 4 ++-- tracecmd/trace-record.c | 1 + 3 files changed, 6 insertions(+), 2 deletions(-) diff --git a/lib/trace-cmd/include/private/trace-cmd-private.h b/lib/trace-cmd/include/private/trace-cmd-private.h index a08566e6..d370fa8b 100644 --- a/lib/trace-cmd/include/private/trace-cmd-private.h +++ b/lib/trace-cmd/include/private/trace-cmd-private.h @@ -503,4 +503,7 @@ void *tracecmd_record_page(struct tracecmd_input *handle, void *tracecmd_record_offset(struct tracecmd_input *handle, struct tep_record *record); +int save_tracing_file_data(struct tracecmd_output *handle, + const char *filename); + #endif /* _TRACE_CMD_PRIVATE_H */ diff --git a/lib/trace-cmd/trace-output.c b/lib/trace-cmd/trace-output.c index 032c8ff4..4ffb4d47 100644 --- a/lib/trace-cmd/trace-output.c +++ b/lib/trace-cmd/trace-output.c @@ -797,8 +797,8 @@ static int read_ftrace_printk(struct tracecmd_output *handle) return -1; } -static int save_tracing_file_data(struct tracecmd_output *handle, - const char *filename) +int save_tracing_file_data(struct tracecmd_output *handle, + const char *filename) { unsigned long long endian8; char *file = NULL; diff --git a/tracecmd/trace-record.c b/tracecmd/trace-record.c index a1c4e919..a0a0b8b5 100644 --- a/tracecmd/trace-record.c +++ b/tracecmd/trace-record.c @@ -3770,6 +3770,7 @@ static void setup_agent(struct buffer_instance *instance, network_handle = tracecmd_create_init_fd_msg(instance->msg_handle, listed_events); add_options(network_handle, ctx); + save_tracing_file_data(network_handle, "saved_cmdlines"); tracecmd_write_cpus(network_handle, instance->cpu_count); tracecmd_write_options(network_handle); tracecmd_msg_finish_sending_data(instance->msg_handle); From patchwork Mon Feb 8 06:17:37 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: 12074053 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=-20.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,MENTIONS_GIT_HOSTING,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 769CCC433E9 for ; Mon, 8 Feb 2021 06:18:46 +0000 (UTC) Received: from vger.kernel.org (vger.kernel.org [23.128.96.18]) by mail.kernel.org (Postfix) with ESMTP id 360C264E56 for ; Mon, 8 Feb 2021 06:18:46 +0000 (UTC) Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S229684AbhBHGSe (ORCPT ); Mon, 8 Feb 2021 01:18:34 -0500 Received: from lindbergh.monkeyblade.net ([23.128.96.19]:50126 "EHLO lindbergh.monkeyblade.net" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S229681AbhBHGSd (ORCPT ); Mon, 8 Feb 2021 01:18:33 -0500 Received: from mail-ej1-x631.google.com (mail-ej1-x631.google.com [IPv6:2a00:1450:4864:20::631]) by lindbergh.monkeyblade.net (Postfix) with ESMTPS id 1F461C06178A for ; Sun, 7 Feb 2021 22:17:51 -0800 (PST) Received: by mail-ej1-x631.google.com with SMTP id lg21so22785766ejb.3 for ; Sun, 07 Feb 2021 22:17:51 -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=7iY9PnC49nVteWuU9AGuFKEUQ/4IeU3tgqIpRqkEY4A=; b=B5H8/3bTIJ8WXk0x56sI2TrqgGFaNY6KaTuSAVIyAO8dDPvOJjPtD039RWY+ov+P4Y F1AEgizlmOozYEOTuUivNhms3cOxfP4lxfK0TSDo0m98Vu0BkDikviSSTMq+9kPGFTrU lpqkWTOMMc2Lw+otRrmaSR0yDETKNlMufLPQkO+yhgtTINyfFj/n+Kv10tk146EPym8y 0nUXI4NFpbJh4E5so25RjnuFJCMBX06nKycHvNPrlWI/p1rcXDIYOM2m07gdMOAF4Tpr ACaRBiXAsaB5v4ngbcKuz/7T0FGr2+/dOoe6YNgPyxPPUX24LE68ltECIR/MLDFU31eL 801A== 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=7iY9PnC49nVteWuU9AGuFKEUQ/4IeU3tgqIpRqkEY4A=; b=RHsp7MJWOOIk1hm0Av++RmgCkOEWizUaipFyfBF0ppGhRIl14z6pUBv0GTAN0DEY5Y kk4FfseGNZLpzlOoGy4ys3xR7xDyCP8Rx9q73o29SzNDGOW8pXRglIyRX4m6OaMOKMvJ sxUuxuNbPwtnO1rToQcx7PkH2qdn+UFGT6xoTWQ5Y2wo+Z7HV/jho0+JB+BS8Qubnr/w 8ISh/5dph5D1ZEB3V+WQ3332f/BrmgJWubIsNIFqSjDYepkLx+bzIOQWZg43arPx83Df Go/bGGu4kpu2tunl7Cnw+qwuUS8/5RLofhjsDKeLd9OP4GtR5oFa3/KCexKODgft8zZ2 LrjQ== X-Gm-Message-State: AOAM533netC2Rw2NgcXsRA8UAs3MMHfZBNisJys1PAnB4g+2l74EBwD+ DwGGG2BZsSX9b+zOYjqk5K+VbKosjnMdVA== X-Google-Smtp-Source: ABdhPJwwEDayLSNGH3JTloDPtkHjP60qqglDsAlSKL6ClAvrU2YIA//cVOSsmh5FiQc3+hRdvraVjg== X-Received: by 2002:a17:907:7252:: with SMTP id ds18mr15474764ejc.239.1612765069933; Sun, 07 Feb 2021 22:17:49 -0800 (PST) Received: from oberon.zico.biz ([83.222.187.186]) by smtp.gmail.com with ESMTPSA id 35sm135618edp.85.2021.02.07.22.17.48 (version=TLS1_3 cipher=TLS_AES_256_GCM_SHA384 bits=256/256); Sun, 07 Feb 2021 22:17:48 -0800 (PST) From: "Tzvetomir Stoyanov (VMware)" To: rostedt@goodmis.org Cc: linux-trace-devel@vger.kernel.org Subject: [PATCH v28 2/8] trace-cmd: Fix bug in getting tracing dir in trace-cmd agent Date: Mon, 8 Feb 2021 08:17:37 +0200 Message-Id: <20210208061743.510964-3-tz.stoyanov@gmail.com> X-Mailer: git-send-email 2.29.2 In-Reply-To: <20210208061743.510964-1-tz.stoyanov@gmail.com> References: <20210208061743.510964-1-tz.stoyanov@gmail.com> MIME-Version: 1.0 Precedence: bulk List-ID: X-Mailing-List: linux-trace-devel@vger.kernel.org In trace-cmd agent context, when getting the tracing directory, a bug using srtcpy() was instroduced by that commit: https://git.kernel.org/pub/scm/utils/trace-cmd/trace-cmd.git/commit/?id=b8498696e0e8d7b7cce8f50f92e1fa94d9127e6e Signed-off-by: Tzvetomir Stoyanov (VMware) --- tracecmd/trace-record.c | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/tracecmd/trace-record.c b/tracecmd/trace-record.c index a0a0b8b5..efd96d27 100644 --- a/tracecmd/trace-record.c +++ b/tracecmd/trace-record.c @@ -3341,7 +3341,7 @@ static int create_recorder(struct buffer_instance *instance, int cpu, const char *dir = tracefs_tracing_dir(); if (dir) - path = strdup(path); + path = strdup(dir); } if (!path) die("can't get the tracing directory"); From patchwork Mon Feb 8 06:17:38 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: 12074055 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 93EEDC433E6 for ; Mon, 8 Feb 2021 06:18:46 +0000 (UTC) Received: from vger.kernel.org (vger.kernel.org [23.128.96.18]) by mail.kernel.org (Postfix) with ESMTP id 5C45E64E59 for ; Mon, 8 Feb 2021 06:18:46 +0000 (UTC) Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S229706AbhBHGSf (ORCPT ); Mon, 8 Feb 2021 01:18:35 -0500 Received: from lindbergh.monkeyblade.net ([23.128.96.19]:50138 "EHLO lindbergh.monkeyblade.net" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S229681AbhBHGSe (ORCPT ); Mon, 8 Feb 2021 01:18:34 -0500 Received: from mail-ej1-x62e.google.com (mail-ej1-x62e.google.com [IPv6:2a00:1450:4864:20::62e]) by lindbergh.monkeyblade.net (Postfix) with ESMTPS id 5AB10C06178B for ; Sun, 7 Feb 2021 22:17:52 -0800 (PST) Received: by mail-ej1-x62e.google.com with SMTP id l25so5474271eja.9 for ; Sun, 07 Feb 2021 22:17:52 -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=ZxQKytp1O+WX+MFBeCcujLCAGzL6iIOfe+UPe4Qe8J0=; b=oFV9apd16kmMa5utB6bL4cywgDm9ZlcG+WPYgqo4kbq17EwfwQQUJjvu+sTfnbWHdp vIwWUkfX3tgYw5Z+nyJOn8p5v1yegKHwWhxWfG1rYNBrqn7IR+UfLq53KzBZqK2Yr85p ljvM7g109yJ/u9s4DuBj7hDfbojFrZXU7danxpgh6LE0LoGtOMtIw+XXPqlqfQrGM6rq y+UWE9lMzU5E34lI+Lo/8B0ZZ8xihX3+vIWlyiHgIPxGiqX+MRzspYjP4el7YfGFD9sY QSo8XAMi0+5I6CRc9zyCk+C8SuTtGsK7f7/wquCZ70x+WsgLpJ2LAcxA6wsJq9gX6lA/ qGRA== 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=ZxQKytp1O+WX+MFBeCcujLCAGzL6iIOfe+UPe4Qe8J0=; b=dE8gKxbnDUcEB0EaH4637wAK2BKbqc9EcX8pA8qxijf8ouYv0YkLinZnKSkWmilk8L leaGs/AuEn+fEMBs/YUsPiieDL68XMKZyF8myyvguIGtf+IUISJKoaPeQKVQB441dowH MsO+Freip/gbNezNw2nvhxpmP8S+Nx7OYZ3cP6dhv0tKnuSMClh5p7z6deR16kHNoXHJ w7SLeyWOHtVzTUylZ/PvqiWRl7sPZZDOyHINs+rePXpa/XORiFZpujVdDWJgaezLo/KW NGdFJh+ats+CIUcrFMj9NRvc5bMWbqKOHFjRRCABi1wfG3oeTgdTeLpS7V8YN9vahkYx yQ8g== X-Gm-Message-State: AOAM532xOF/xHh/JBWTF97ubCRvIlPxW6ukjIQpbxvF3ZNSWwWeXKqW1 0T5YNzKQ8rUjaWOmosyPgLY= X-Google-Smtp-Source: ABdhPJyZT3O9GzoAiRruE079iKHRAvIcGsoq64yRSvARHPYqJvZhLea9z50Ov9BrQXDuNCmfV60tqg== X-Received: by 2002:a17:907:2a85:: with SMTP id fl5mr15238763ejc.554.1612765071134; Sun, 07 Feb 2021 22:17:51 -0800 (PST) Received: from oberon.zico.biz ([83.222.187.186]) by smtp.gmail.com with ESMTPSA id 35sm135618edp.85.2021.02.07.22.17.49 (version=TLS1_3 cipher=TLS_AES_256_GCM_SHA384 bits=256/256); Sun, 07 Feb 2021 22:17:50 -0800 (PST) From: "Tzvetomir Stoyanov (VMware)" To: rostedt@goodmis.org Cc: linux-trace-devel@vger.kernel.org Subject: [PATCH v28 3/8] trace-cmd: Removed unused s64 define Date: Mon, 8 Feb 2021 08:17:38 +0200 Message-Id: <20210208061743.510964-4-tz.stoyanov@gmail.com> X-Mailer: git-send-email 2.29.2 In-Reply-To: <20210208061743.510964-1-tz.stoyanov@gmail.com> References: <20210208061743.510964-1-tz.stoyanov@gmail.com> MIME-Version: 1.0 Precedence: bulk List-ID: X-Mailing-List: linux-trace-devel@vger.kernel.org Removed a s64 define, not used currently in trace packets. Signed-off-by: Tzvetomir Stoyanov (VMware) --- lib/trace-cmd/trace-msg.c | 1 - 1 file changed, 1 deletion(-) diff --git a/lib/trace-cmd/trace-msg.c b/lib/trace-cmd/trace-msg.c index 611af2c1..c4943165 100644 --- a/lib/trace-cmd/trace-msg.c +++ b/lib/trace-cmd/trace-msg.c @@ -30,7 +30,6 @@ typedef __u32 u32; typedef __be32 be32; -typedef __s64 s64; static inline void dprint(const char *fmt, ...) { From patchwork Mon Feb 8 06:17:39 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: 12074059 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 CBD99C43381 for ; Mon, 8 Feb 2021 06:18:46 +0000 (UTC) Received: from vger.kernel.org (vger.kernel.org [23.128.96.18]) by mail.kernel.org (Postfix) with ESMTP id 8560564E56 for ; Mon, 8 Feb 2021 06:18:46 +0000 (UTC) Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S229681AbhBHGSh (ORCPT ); Mon, 8 Feb 2021 01:18:37 -0500 Received: from lindbergh.monkeyblade.net ([23.128.96.19]:50140 "EHLO lindbergh.monkeyblade.net" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S229691AbhBHGSe (ORCPT ); Mon, 8 Feb 2021 01:18:34 -0500 Received: from mail-ej1-x636.google.com (mail-ej1-x636.google.com [IPv6:2a00:1450:4864:20::636]) by lindbergh.monkeyblade.net (Postfix) with ESMTPS id 073B8C06178C for ; Sun, 7 Feb 2021 22:17:54 -0800 (PST) Received: by mail-ej1-x636.google.com with SMTP id sa23so22838970ejb.0 for ; Sun, 07 Feb 2021 22:17:53 -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=Jttx/4ykuouNE5kIIY++m3l5C0hcUGzjlfY3w1ThQJI=; b=dQ4TjAVj4grezAitoNniouBt2kBO2pXv6Uc/WuYQVR3kn8OzSRICnb7NNz5f93wsAE 3rU7T7rAJRa5fh1MB1muoNvDgPP+BoEGq/ZdZ0HW3uSSvbs3zgeli7/XgZoUFq9anRfK MwDkXWPGO7vmY2EE2KvpX9ztm3Wp7N6Yjj7FVSxHNm5jqinasi+94Xg2L46MeSAEe3Hp YaouSPyKiRIzQ7PItdT7CZJEgI7hibFzLQDahiXSUSWOS54ug3xC/cI+g8S7lqRuCjom JKOT8AUIE+701AnTbazichCl4y+cC7JqRKGmlfzet/8QniSCmpVu4JYrVwfMPSF7GINe VRLA== 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=Jttx/4ykuouNE5kIIY++m3l5C0hcUGzjlfY3w1ThQJI=; b=nr72BEnfuIHJlGTFFQglMvTq3JiriQnaQS0MN8mrafowByfSVS109an38c5II4REQb TQpSlEM/R34ZOYw7VoyjVMBHGzLRyTxZfi6Dbl/zxBsIYWG6pAh57ripgj1K9Ge/gPQF 2wYbHPH/nIioq1JmyWrPhC2jO7bFFeLKJbDTo74o5/GEFb2Pq+dMGtYdsunFEwuzTun6 1yyC6Z0WbEtK//Z0bARKBodqzhw/TP10orTNlqzLCmygVGtRqsi9nQzNpVpoZv5rIqDK by5KDnST7NR6k3nJdSg3Fw1FDg0ajTCeS6+dmF7EhmBMWca2kYx/+QG7zCxNQTSMNYDj CAvg== X-Gm-Message-State: AOAM5303i5UJzKlS4hdN9GrBfA98nxeTpDenDHhUQx07bYnkx8r/1dRA GGYSLQZdYd6gB0tk3+TYdN5rwmJZ+0At3Q== X-Google-Smtp-Source: ABdhPJxxtv+4lH5O6XBFjGwOMkAqyTD3CjnoJ4sPHaRZO7S9WPQN+bg7+4adsZ/ZXmIg0ASlXfU5Cg== X-Received: by 2002:a17:906:27d8:: with SMTP id k24mr1377454ejc.339.1612765072597; Sun, 07 Feb 2021 22:17:52 -0800 (PST) Received: from oberon.zico.biz ([83.222.187.186]) by smtp.gmail.com with ESMTPSA id 35sm135618edp.85.2021.02.07.22.17.51 (version=TLS1_3 cipher=TLS_AES_256_GCM_SHA384 bits=256/256); Sun, 07 Feb 2021 22:17:51 -0800 (PST) From: "Tzvetomir Stoyanov (VMware)" To: rostedt@goodmis.org Cc: linux-trace-devel@vger.kernel.org Subject: [PATCH v28 4/8] trace-cmd: Add timestamp synchronization per vCPU Date: Mon, 8 Feb 2021 08:17:39 +0200 Message-Id: <20210208061743.510964-5-tz.stoyanov@gmail.com> X-Mailer: git-send-email 2.29.2 In-Reply-To: <20210208061743.510964-1-tz.stoyanov@gmail.com> References: <20210208061743.510964-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 | 188 ++++++++++------ lib/trace-cmd/trace-timesync.c | 213 +++++++++++++----- tracecmd/trace-dump.c | 52 +++-- tracecmd/trace-tsync.c | 67 ++++-- 6 files changed, 372 insertions(+), 172 deletions(-) diff --git a/lib/trace-cmd/include/private/trace-cmd-private.h b/lib/trace-cmd/include/private/trace-cmd-private.h index d370fa8b..4a352291 100644 --- a/lib/trace-cmd/include/private/trace-cmd-private.h +++ b/lib/trace-cmd/include/private/trace-cmd-private.h @@ -443,7 +443,7 @@ const char *tracecmd_tsync_proto_select(struct tracecmd_tsync_protos *protos, ch bool tsync_proto_is_supported(const char *proto_name); void tracecmd_tsync_with_host(struct tracecmd_time_sync *tsync); void tracecmd_tsync_with_guest(struct tracecmd_time_sync *tsync); -int tracecmd_tsync_get_offsets(struct tracecmd_time_sync *tsync, +int tracecmd_tsync_get_offsets(struct tracecmd_time_sync *tsync, int cpu, int *count, long long **ts, long long **offsets, long long **scalings); int tracecmd_tsync_get_proto_flags(struct tracecmd_time_sync *tsync, diff --git a/lib/trace-cmd/include/trace-tsync-local.h b/lib/trace-cmd/include/trace-tsync-local.h index 83d1721a..d4281469 100644 --- a/lib/trace-cmd/include/trace-tsync-local.h +++ b/lib/trace-cmd/include/trace-tsync-local.h @@ -8,12 +8,7 @@ #include -struct clock_sync_context { - void *proto_data; /* time sync protocol specific data */ - bool is_server; /* server side time sync role */ - bool is_guest; /* guest or host time sync role */ - struct tracefs_instance *instance; /* ftrace buffer, used for time sync events */ - +struct clock_sync_offsets { /* Arrays with calculated time offsets at given time */ int sync_size; /* Allocated size of sync_ts, * sync_offsets and sync_scalings @@ -24,6 +19,18 @@ struct clock_sync_context { long long *sync_ts; long long *sync_offsets; long long *sync_scalings; +}; + +struct clock_sync_context { + void *proto_data; /* time sync protocol specific data */ + bool is_server; /* server side time sync role */ + bool is_guest; /* guest or host time sync role */ + struct tracefs_instance *instance; /* ftrace buffer, used for time sync events */ + + int cpu_count; + struct clock_sync_offsets *offsets; /* Array of size cpu_count + * calculated offsets per CPU + */ /* Identifiers of local and remote time sync peers: cid and port */ unsigned int local_cid; @@ -37,7 +44,8 @@ int tracecmd_tsync_proto_register(const char *proto_name, int accuracy, int role int (*init)(struct tracecmd_time_sync *), int (*free)(struct tracecmd_time_sync *), int (*calc)(struct tracecmd_time_sync *, - long long *, long long *, long long *)); + long long *, long long *, + long long *, unsigned int)); int tracecmd_tsync_proto_unregister(char *proto_name); int ptp_clock_sync_register(void); diff --git a/lib/trace-cmd/trace-input.c b/lib/trace-cmd/trace-input.c index 7d28254e..d32d8ee4 100644 --- a/lib/trace-cmd/trace-input.c +++ b/lib/trace-cmd/trace-input.c @@ -91,13 +91,19 @@ struct guest_trace_info { int *cpu_pid; }; +struct timesync_offsets { + int ts_samples_count; + struct ts_offset_sample *ts_samples; + +}; + struct host_trace_info { unsigned long long peer_trace_id; unsigned int flags; bool sync_enable; struct tracecmd_input *peer_data; - int ts_samples_count; - struct ts_offset_sample *ts_samples; + int cpu_count; + struct timesync_offsets *ts_offsets; }; struct tracecmd_input { @@ -1149,53 +1155,56 @@ timestamp_correction_calc(unsigned long long ts, unsigned int flags, return ts + tscor; } -static unsigned long long timestamp_correct(unsigned long long ts, +static unsigned long long timestamp_correct(unsigned long long ts, int cpu, struct tracecmd_input *handle) { - struct host_trace_info *host = &handle->host; + struct timesync_offsets *tsync; int min, mid, max; if (handle->ts_offset) return ts + handle->ts_offset; - if (!host->sync_enable) + if (!handle->host.sync_enable) + return ts; + if (cpu >= handle->host.cpu_count) return ts; + tsync = &handle->host.ts_offsets[cpu]; /* We have one sample, nothing to calc here */ - if (host->ts_samples_count == 1) - return ts + host->ts_samples[0].offset; + if (tsync->ts_samples_count == 1) + return ts + tsync->ts_samples[0].offset; /* We have two samples, nothing to search here */ - if (host->ts_samples_count == 2) - return timestamp_correction_calc(ts, host->flags, - &host->ts_samples[0], - &host->ts_samples[1]); + if (tsync->ts_samples_count == 2) + return timestamp_correction_calc(ts, handle->host.flags, + &tsync->ts_samples[0], + &tsync->ts_samples[1]); /* We have more than two samples */ - if (ts <= host->ts_samples[0].time) - return timestamp_correction_calc(ts, host->flags, - &host->ts_samples[0], - &host->ts_samples[1]); - else if (ts >= host->ts_samples[host->ts_samples_count-1].time) - return timestamp_correction_calc(ts, host->flags, - &host->ts_samples[host->ts_samples_count-2], - &host->ts_samples[host->ts_samples_count-1]); + if (ts <= tsync->ts_samples[0].time) + return timestamp_correction_calc(ts, handle->host.flags, + &tsync->ts_samples[0], + &tsync->ts_samples[1]); + else if (ts >= tsync->ts_samples[tsync->ts_samples_count-1].time) + return timestamp_correction_calc(ts, handle->host.flags, + &tsync->ts_samples[tsync->ts_samples_count-2], + &tsync->ts_samples[tsync->ts_samples_count-1]); min = 0; - max = host->ts_samples_count-1; + max = tsync->ts_samples_count-1; mid = (min + max)/2; while (min <= max) { - if (ts < host->ts_samples[mid].time) + if (ts < tsync->ts_samples[mid].time) max = mid - 1; - else if (ts > host->ts_samples[mid].time) + else if (ts > tsync->ts_samples[mid].time) min = mid + 1; else break; mid = (min + max)/2; } - return timestamp_correction_calc(ts, host->flags, - &host->ts_samples[mid], - &host->ts_samples[mid+1]); + return timestamp_correction_calc(ts, handle->host.flags, + &tsync->ts_samples[mid], + &tsync->ts_samples[mid+1]); } /* @@ -1219,7 +1228,8 @@ static int update_page_info(struct tracecmd_input *handle, int cpu) kbuffer_subbuffer_size(kbuf)); return -1; } - handle->cpu_data[cpu].timestamp = timestamp_correct(kbuffer_timestamp(kbuf), handle); + handle->cpu_data[cpu].timestamp = timestamp_correct(kbuffer_timestamp(kbuf), + cpu, handle); if (handle->ts2secs) handle->cpu_data[cpu].timestamp *= handle->ts2secs; @@ -1852,7 +1862,7 @@ read_again: goto read_again; } - handle->cpu_data[cpu].timestamp = timestamp_correct(ts, handle); + handle->cpu_data[cpu].timestamp = timestamp_correct(ts, cpu, handle); if (handle->ts2secs) { handle->cpu_data[cpu].timestamp *= handle->ts2secs; @@ -2187,42 +2197,89 @@ static int tsync_offset_cmp(const void *a, const void *b) return 0; } -static void tsync_offset_load(struct tracecmd_input *handle, char *buf) +#define safe_read(R, C) \ + do { \ + if ((C) > size) \ + return -EFAULT; \ + (R) = tep_read_number(tep, buf, (C)); \ + buf += (C); \ + size -= (C); \ + } while (0) + +#define safe_read_loop(type) \ + do { \ + int i; \ + for (i = 0; i < ts_offsets->ts_samples_count; i++) \ + safe_read(ts_offsets->ts_samples[i].type, 8); \ + } while (0) + +static int tsync_offset_load(struct tep_handle *tep, + struct timesync_offsets *ts_offsets, char *buf, int size) { - struct host_trace_info *host = &handle->host; - long long *buf8 = (long long *)buf; + int start_size = size; int i, j; - for (i = 0; i < host->ts_samples_count; i++) { - host->ts_samples[i].time = tep_read_number(handle->pevent, - buf8 + i, 8); - host->ts_samples[i].offset = tep_read_number(handle->pevent, - buf8 + host->ts_samples_count + i, 8); - host->ts_samples[i].scaling = tep_read_number(handle->pevent, - buf8 + (2 * host->ts_samples_count) + i, 8); - } - qsort(host->ts_samples, host->ts_samples_count, + safe_read_loop(time); + safe_read_loop(offset); + safe_read_loop(scaling); + qsort(ts_offsets->ts_samples, ts_offsets->ts_samples_count, sizeof(struct ts_offset_sample), tsync_offset_cmp); + /* Filter possible samples with equal time */ - for (i = 0, j = 0; i < host->ts_samples_count; i++) { - if (i == 0 || host->ts_samples[i].time != host->ts_samples[i-1].time) - host->ts_samples[j++] = host->ts_samples[i]; + for (i = 0, j = 0; i < ts_offsets->ts_samples_count; i++) { + if (i == 0 || ts_offsets->ts_samples[i].time != ts_offsets->ts_samples[i-1].time) + ts_offsets->ts_samples[j++] = ts_offsets->ts_samples[i]; } - host->ts_samples_count = j; + ts_offsets->ts_samples_count = j; + + return start_size - size; +} + +static int tsync_cpu_offsets_load(struct tracecmd_input *handle, char *buf, int size) +{ + struct tep_handle *tep = handle->pevent; + int ret; + int i; + + safe_read(handle->host.cpu_count, 4); + handle->host.ts_offsets = calloc(handle->host.cpu_count, + sizeof(struct timesync_offsets)); + if (!handle->host.ts_offsets) + return -ENOMEM; + for (i = 0; i < handle->host.cpu_count; i++) { + safe_read(handle->host.ts_offsets[i].ts_samples_count, 4); + handle->host.ts_offsets[i].ts_samples = calloc(handle->host.ts_offsets[i].ts_samples_count, + sizeof(struct ts_offset_sample)); + if (!handle->host.ts_offsets[i].ts_samples) + return -ENOMEM; + ret = tsync_offset_load(tep, &handle->host.ts_offsets[i], buf, size); + if (ret <= 0) + return -EFAULT; + size -= ret; + buf += ret; + } + return 0; } static void tsync_check_enable(struct tracecmd_input *handle) { struct host_trace_info *host = &handle->host; struct guest_trace_info *guest; + int i; host->sync_enable = false; - if (!host->peer_data || !host->peer_data->guest || - !host->ts_samples_count || !host->ts_samples) + if (!host->peer_data || !host->peer_data->guest) return; if (host->peer_trace_id != host->peer_data->trace_id) return; + if (!host->cpu_count || !host->ts_offsets) + return; + for (i = 0; i < host->cpu_count; i++) { + if (!host->ts_offsets[i].ts_samples_count || + !host->ts_offsets[i].ts_samples) + return; + } guest = host->peer_data->guest; while (guest) { if (guest->trace_id == handle->trace_id) @@ -2237,8 +2294,14 @@ static void tsync_check_enable(struct tracecmd_input *handle) static void trace_tsync_offset_free(struct host_trace_info *host) { - free(host->ts_samples); - host->ts_samples = NULL; + int i; + + if (host->ts_offsets) { + for (i = 0; i < host->cpu_count; i++) + free(host->ts_offsets[i].ts_samples); + free(host->ts_offsets); + host->ts_offsets = NULL; + } if (host->peer_data) { tracecmd_close(host->peer_data); host->peer_data = NULL; @@ -2497,8 +2560,8 @@ static int handle_options(struct tracecmd_input *handle) struct input_buffer_instance *buffer; struct hook_list *hook; char *buf; - int samples_size; int cpus; + int ret; /* By default, use usecs, unless told otherwise */ handle->flags |= TRACECMD_FL_IN_USECS; @@ -2549,11 +2612,15 @@ static int handle_options(struct tracecmd_input *handle) /* * long long int (8 bytes) trace session ID * int (4 bytes) protocol flags. - * int (4 bytes) count of timestamp offsets. - * long long array of size [count] of times, + * int (4 bytes) CPU count. + * array of size [CPU count]: + * [ + * int (4 bytes) count of timestamp offsets. + * long long array of size [count] of times, * when the offsets were calculated. - * long long array of size [count] of timestamp offsets. - * long long array of size [count] of timestamp scaling ratios.* + * long long array of size [count] of timestamp offsets. + * long long array of size [count] of timestamp scaling ratios.* + * ] */ if (size < 16 || handle->flags & TRACECMD_FL_IGNORE_DATE) break; @@ -2561,18 +2628,9 @@ static int handle_options(struct tracecmd_input *handle) buf, 8); handle->host.flags = tep_read_number(handle->pevent, buf + 8, 4); - handle->host.ts_samples_count = tep_read_number(handle->pevent, - buf + 12, 4); - samples_size = (8 * handle->host.ts_samples_count); - if (size != (16 + (2 * samples_size))) { - warning("Failed to extract Time Shift information from the file: found size %d, expected is %d", - size, 16 + (2 * samples_size)); - break; - } - handle->host.ts_samples = malloc(2 * samples_size); - if (!handle->host.ts_samples) - return -ENOMEM; - tsync_offset_load(handle, buf + 16); + ret = tsync_cpu_offsets_load(handle, buf + 12, size - 12); + if (ret < 0) + return ret; break; case TRACECMD_OPTION_CPUSTAT: buf[size-1] = '\n'; @@ -3911,7 +3969,7 @@ unsigned long long tracecmd_get_tsync_peer(struct tracecmd_input *handle) int tracecmd_enable_tsync(struct tracecmd_input *handle, bool enable) { if (enable && - (!handle->host.ts_samples || !handle->host.ts_samples_count)) + (!handle->host.ts_offsets || !handle->host.cpu_count)) return -1; handle->host.sync_enable = enable; diff --git a/lib/trace-cmd/trace-timesync.c b/lib/trace-cmd/trace-timesync.c index 9cbed775..2581363f 100644 --- a/lib/trace-cmd/trace-timesync.c +++ b/lib/trace-cmd/trace-timesync.c @@ -34,9 +34,13 @@ struct tsync_proto { int (*clock_sync_free)(struct tracecmd_time_sync *clock_context); int (*clock_sync_calc)(struct tracecmd_time_sync *clock_context, long long *offset, long long *scaling, - long long *timestamp); + long long *timestamp, unsigned int cpu); }; +struct tsync_probe_request_msg { + unsigned short cpu; +} __packed; + static struct tsync_proto *tsync_proto_list; static struct tsync_proto *tsync_proto_find(const char *proto_name) @@ -58,7 +62,8 @@ int tracecmd_tsync_proto_register(const char *proto_name, int accuracy, int role int (*init)(struct tracecmd_time_sync *), int (*free)(struct tracecmd_time_sync *), int (*calc)(struct tracecmd_time_sync *, - long long *, long long *, long long *)) + long long *, long long *, + long long *, unsigned int)) { struct tsync_proto *proto = NULL; @@ -70,6 +75,7 @@ int tracecmd_tsync_proto_register(const char *proto_name, int accuracy, int role strncpy(proto->proto_name, proto_name, TRACECMD_TSYNC_PNAME_LENGTH); proto->accuracy = accuracy; proto->roles = roles; + proto->flags = flags; proto->supported_clocks = supported_clocks; proto->clock_sync_init = init; proto->clock_sync_free = free; @@ -112,6 +118,7 @@ bool tsync_proto_is_supported(const char *proto_name) * tracecmd_tsync_get_offsets - Return the calculated time offsets * * @tsync: Pointer to time sync context + * @cpu: CPU for which to get the calculated offsets * @count: Returns the number of calculated time offsets * @ts: Array of size @count containing timestamps of callculated offsets * @offsets: array of size @count, containing offsets for each timestamp @@ -119,7 +126,7 @@ bool tsync_proto_is_supported(const char *proto_name) * * Retuns -1 in case of an error, or 0 otherwise */ -int tracecmd_tsync_get_offsets(struct tracecmd_time_sync *tsync, +int tracecmd_tsync_get_offsets(struct tracecmd_time_sync *tsync, int cpu, int *count, long long **ts, long long **offsets, long long **scalings) { @@ -128,14 +135,16 @@ int tracecmd_tsync_get_offsets(struct tracecmd_time_sync *tsync, if (!tsync || !tsync->context) return -1; tsync_context = (struct clock_sync_context *)tsync->context; + if (cpu >= tsync_context->cpu_count || !tsync_context->offsets) + return -1; if (count) - *count = tsync_context->sync_count; + *count = tsync_context->offsets[cpu].sync_count; if (ts) - *ts = tsync_context->sync_ts; + *ts = tsync_context->offsets[cpu].sync_ts; if (offsets) - *offsets = tsync_context->sync_offsets; + *offsets = tsync_context->offsets[cpu].sync_offsets; if (scalings) - *scalings = tsync_context->sync_scalings; + *scalings = tsync_context->offsets[cpu].sync_scalings; return 0; } @@ -355,6 +364,13 @@ static int clock_context_init(struct tracecmd_time_sync *tsync, bool guest) if (!clock->instance) goto error; + clock->cpu_count = tsync->vcpu_count; + if (clock->cpu_count) { + clock->offsets = calloc(clock->cpu_count, sizeof(struct clock_sync_offsets)); + if (!clock->offsets) + goto error; + } + tsync->context = clock; if (protocol->clock_sync_init && protocol->clock_sync_init(tsync) < 0) goto error; @@ -362,6 +378,9 @@ static int clock_context_init(struct tracecmd_time_sync *tsync, bool guest) return 0; error: tsync->context = NULL; + if (clock->instance) + clock_synch_delete_instance(clock->instance); + free(clock->offsets); free(clock); return -1; } @@ -377,6 +396,7 @@ void tracecmd_tsync_free(struct tracecmd_time_sync *tsync) { struct clock_sync_context *tsync_context; struct tsync_proto *proto; + int i; if (!tsync->context) return; @@ -389,28 +409,88 @@ void tracecmd_tsync_free(struct tracecmd_time_sync *tsync) clock_synch_delete_instance(tsync_context->instance); tsync_context->instance = NULL; - free(tsync_context->sync_ts); - free(tsync_context->sync_offsets); - free(tsync_context->sync_scalings); - tsync_context->sync_ts = NULL; - tsync_context->sync_offsets = NULL; - tsync_context->sync_scalings = NULL; - tsync_context->sync_count = 0; - tsync_context->sync_size = 0; + if (tsync_context->cpu_count && tsync_context->offsets) { + for (i = 0; i < tsync_context->cpu_count; i++) { + free(tsync_context->offsets[i].sync_ts); + free(tsync_context->offsets[i].sync_offsets); + free(tsync_context->offsets[i].sync_scalings); + tsync_context->offsets[i].sync_ts = NULL; + tsync_context->offsets[i].sync_offsets = NULL; + tsync_context->offsets[i].sync_scalings = NULL; + tsync_context->offsets[i].sync_count = 0; + tsync_context->offsets[i].sync_size = 0; + } + free(tsync_context->offsets); + tsync_context->offsets = NULL; + } pthread_mutex_destroy(&tsync->lock); pthread_cond_destroy(&tsync->cond); free(tsync->clock_str); } +static cpu_set_t *pin_to_cpu(int cpu) +{ + static size_t size; + static int cpus; + cpu_set_t *mask = NULL; + cpu_set_t *old = NULL; + + if (!cpus) { + cpus = tracecmd_count_cpus(); + size = CPU_ALLOC_SIZE(cpus); + } + if (cpu >= cpus) + goto error; + + mask = CPU_ALLOC(cpus); + if (!mask) + goto error; + old = CPU_ALLOC(cpus); + if (!old) + goto error; + + CPU_ZERO_S(size, mask); + CPU_SET_S(cpu, size, mask); + if (pthread_getaffinity_np(pthread_self(), size, old)) + goto error; + if (pthread_setaffinity_np(pthread_self(), size, mask)) + goto error; + + CPU_FREE(mask); + return old; + +error: + if (mask) + CPU_FREE(mask); + if (old) + CPU_FREE(old); + return NULL; +} + +static void restore_pin_to_cpu(cpu_set_t *mask) +{ + static size_t size; + + if (!size) + size = CPU_ALLOC_SIZE(tracecmd_count_cpus()); + + pthread_setaffinity_np(pthread_self(), size, mask); + CPU_FREE(mask); +} + int tracecmd_tsync_send(struct tracecmd_time_sync *tsync, - struct tsync_proto *proto) + struct tsync_proto *proto, unsigned int cpu) { + cpu_set_t *old_set = NULL; long long timestamp = 0; long long scaling = 0; long long offset = 0; int ret; - ret = proto->clock_sync_calc(tsync, &offset, &scaling, ×tamp); + old_set = pin_to_cpu(cpu); + ret = proto->clock_sync_calc(tsync, &offset, &scaling, ×tamp, cpu); + if (old_set) + restore_pin_to_cpu(old_set); return ret; } @@ -428,8 +508,11 @@ int tracecmd_tsync_send(struct tracecmd_time_sync *tsync, void tracecmd_tsync_with_host(struct tracecmd_time_sync *tsync) { char protocol[TRACECMD_TSYNC_PNAME_LENGTH]; + struct tsync_probe_request_msg probe; struct tsync_proto *proto; unsigned int command; + unsigned int size; + char *msg; int ret; proto = tsync_proto_find(tsync->proto_name); @@ -440,47 +523,37 @@ void tracecmd_tsync_with_host(struct tracecmd_time_sync *tsync) if (!tsync->context) return; + msg = (char *)&probe; + size = sizeof(probe); while (true) { + memset(&probe, 0, size); ret = tracecmd_msg_recv_time_sync(tsync->msg_handle, protocol, &command, - NULL, NULL); + &size, &msg); if (ret || strncmp(protocol, TRACECMD_TSYNC_PROTO_NONE, TRACECMD_TSYNC_PNAME_LENGTH) || command != TRACECMD_TIME_SYNC_CMD_PROBE) break; - ret = tracecmd_tsync_send(tsync, proto); + ret = tracecmd_tsync_send(tsync, proto, probe.cpu); if (ret) break; } } -static int tsync_get_sample(struct tracecmd_time_sync *tsync, - struct tsync_proto *proto, int array_step) +static int record_sync_sample(struct clock_sync_offsets *offsets, int array_step, + long long offset, long long scaling, long long ts) { - struct clock_sync_context *clock; long long *sync_scalings = NULL; long long *sync_offsets = NULL; long long *sync_ts = NULL; - long long timestamp = 0; - long long scaling = 0; - long long offset = 0; - int ret; - ret = proto->clock_sync_calc(tsync, &offset, &scaling, ×tamp); - if (ret) { - warning("Failed to synchronize timestamps with guest"); - return -1; - } - if (!offset || !timestamp || !scaling) - return 0; - clock = tsync->context; - if (clock->sync_count >= clock->sync_size) { - sync_ts = realloc(clock->sync_ts, - (clock->sync_size + array_step) * sizeof(long long)); - sync_offsets = realloc(clock->sync_offsets, - (clock->sync_size + array_step) * sizeof(long long)); - sync_scalings = realloc(clock->sync_scalings, - (clock->sync_size + array_step) * sizeof(long long)); + if (offsets->sync_count >= offsets->sync_size) { + sync_ts = realloc(offsets->sync_ts, + (offsets->sync_size + array_step) * sizeof(long long)); + sync_offsets = realloc(offsets->sync_offsets, + (offsets->sync_size + array_step) * sizeof(long long)); + sync_scalings = realloc(offsets->sync_scalings, + (offsets->sync_size + array_step) * sizeof(long long)); if (!sync_ts || !sync_offsets || !sync_scalings) { free(sync_ts); @@ -488,20 +561,43 @@ static int tsync_get_sample(struct tracecmd_time_sync *tsync, free(sync_scalings); return -1; } - clock->sync_size += array_step; - clock->sync_ts = sync_ts; - clock->sync_offsets = sync_offsets; - clock->sync_scalings = sync_scalings; + offsets->sync_size += array_step; + offsets->sync_ts = sync_ts; + offsets->sync_offsets = sync_offsets; + offsets->sync_scalings = sync_scalings; } - clock->sync_ts[clock->sync_count] = timestamp; - clock->sync_offsets[clock->sync_count] = offset; - clock->sync_scalings[clock->sync_count] = scaling; - clock->sync_count++; + offsets->sync_ts[offsets->sync_count] = ts; + offsets->sync_offsets[offsets->sync_count] = offset; + offsets->sync_scalings[offsets->sync_count] = scaling; + offsets->sync_count++; return 0; } +static int tsync_get_sample(struct tracecmd_time_sync *tsync, unsigned int cpu, + struct tsync_proto *proto, int array_step) +{ + struct clock_sync_context *clock; + long long timestamp = 0; + long long scaling = 0; + long long offset = 0; + int ret; + + ret = proto->clock_sync_calc(tsync, &offset, &scaling, ×tamp, cpu); + if (ret) { + warning("Failed to synchronize timestamps with guest"); + return -1; + } + if (!offset || !timestamp || !scaling) + return 0; + clock = tsync->context; + if (!clock || cpu >= clock->cpu_count || !clock->offsets) + return -1; + return record_sync_sample(&clock->offsets[cpu], array_step, + offset, scaling, timestamp); +} + #define TIMER_SEC_NANO 1000000000LL static inline void get_ts_loop_delay(struct timespec *timeout, int delay_ms) { @@ -528,11 +624,13 @@ static inline void get_ts_loop_delay(struct timespec *timeout, int delay_ms) */ void tracecmd_tsync_with_guest(struct tracecmd_time_sync *tsync) { + struct tsync_probe_request_msg probe; int ts_array_size = CLOCK_TS_ARRAY; struct tsync_proto *proto; struct timespec timeout; bool end = false; int ret; + int i; proto = tsync_proto_find(tsync->proto_name); if (!proto || !proto->clock_sync_calc) @@ -548,12 +646,17 @@ void tracecmd_tsync_with_guest(struct tracecmd_time_sync *tsync) while (true) { pthread_mutex_lock(&tsync->lock); - ret = tracecmd_msg_send_time_sync(tsync->msg_handle, - TRACECMD_TSYNC_PROTO_NONE, - TRACECMD_TIME_SYNC_CMD_PROBE, - 0, NULL); - ret = tsync_get_sample(tsync, proto, ts_array_size); - if (ret || end) + for (i = 0; i < tsync->vcpu_count; i++) { + probe.cpu = i; + ret = tracecmd_msg_send_time_sync(tsync->msg_handle, + TRACECMD_TSYNC_PROTO_NONE, + TRACECMD_TIME_SYNC_CMD_PROBE, + sizeof(probe), (char *)&probe); + ret = tsync_get_sample(tsync, i, proto, ts_array_size); + if (ret) + break; + } + if (end || i < tsync->vcpu_count) break; if (tsync->loop_interval > 0) { get_ts_loop_delay(&timeout, tsync->loop_interval); diff --git a/tracecmd/trace-dump.c b/tracecmd/trace-dump.c index 6172231e..c1143eba 100644 --- a/tracecmd/trace-dump.c +++ b/tracecmd/trace-dump.c @@ -375,7 +375,8 @@ static void dump_option_timeshift(int fd, int size) long long trace_id; unsigned int count; unsigned int flags; - int i; + unsigned int cpus; + int i, j; /* * long long int (8 bytes) trace session ID @@ -393,29 +394,34 @@ static void dump_option_timeshift(int fd, int size) do_print(OPTIONS, "0x%llX [peer's trace id]\n", trace_id); read_file_number(fd, &flags, 4); do_print(OPTIONS, "0x%llX [peer's protocol flags]\n", flags); - read_file_number(fd, &count, 4); - do_print(OPTIONS, "%lld [samples count]\n", count); - times = calloc(count, sizeof(long long)); - if (!times) - goto out; - offsets = calloc(count, sizeof(long long)); - if (!offsets) - goto out; - scalings = calloc(count, sizeof(long long)); - if (!scalings) - goto out; - - for (i = 0; i < count; i++) - read_file_number(fd, times + i, 8); - for (i = 0; i < count; i++) - read_file_number(fd, offsets + i, 8); - for (i = 0; i < count; i++) - read_file_number(fd, scalings + i, 8); - - for (i = 0; i < count; i++) - do_print(OPTIONS, "\t%lld * %lld %lld [offset * scaling @ time]\n", - offsets[i], scalings[1], times[i]); + read_file_number(fd, &cpus, 4); + do_print(OPTIONS, "0x%llX [peer's CPU count]\n", cpus); + for (j = 0; j < cpus; j++) { + read_file_number(fd, &count, 4); + do_print(OPTIONS, "%lld [samples count for CPU %d]\n", count, j); + times = calloc(count, sizeof(long long)); + offsets = calloc(count, sizeof(long long)); + scalings = calloc(count, sizeof(long long)); + if (!times || !offsets || !scalings) + goto out; + for (i = 0; i < count; i++) + read_file_number(fd, times + i, 8); + for (i = 0; i < count; i++) + read_file_number(fd, offsets + i, 8); + for (i = 0; i < count; i++) + read_file_number(fd, scalings + i, 8); + + for (i = 0; i < count; i++) + do_print(OPTIONS, "\t%lld %lld %lld [offset * scaling @ time]\n", + offsets[i], scalings[1], times[i]); + free(times); + free(offsets); + free(scalings); + times = NULL; + offsets = NULL; + scalings = NULL; + } out: free(times); free(offsets); diff --git a/tracecmd/trace-tsync.c b/tracecmd/trace-tsync.c index 438c60bb..70d4dbd1 100644 --- a/tracecmd/trace-tsync.c +++ b/tracecmd/trace-tsync.c @@ -134,51 +134,75 @@ out: static void write_guest_time_shift(struct buffer_instance *instance) { - struct tracecmd_output *handle; - struct iovec vector[6]; + struct tracecmd_output *handle = NULL; + struct iovec *vector = NULL; unsigned int flags; long long *scalings = NULL; long long *offsets = NULL; long long *ts = NULL; const char *file; + int fd = -1; + int vcount; int count; + int i, j; int ret; - int fd; - ret = tracecmd_tsync_get_offsets(&instance->tsync, &count, - &ts, &offsets, &scalings); - if (ret < 0 || !count || !ts || !offsets || !scalings) + if (!instance->tsync.vcpu_count) + return; + vcount = 3 + (4 * instance->tsync.vcpu_count); + vector = calloc(vcount, sizeof(struct iovec)); + if (!vector) return; ret = tracecmd_tsync_get_proto_flags(&instance->tsync, &flags); if (ret < 0) - return; + goto out; file = instance->output_file; fd = open(file, O_RDWR); if (fd < 0) die("error opening %s", file); handle = tracecmd_get_output_handle_fd(fd); - vector[0].iov_len = 8; - vector[0].iov_base = &top_instance.trace_id; - vector[1].iov_len = 4; - vector[1].iov_base = &flags; - vector[2].iov_len = 4; - vector[2].iov_base = &count; - vector[3].iov_len = 8 * count; - vector[3].iov_base = ts; - vector[4].iov_len = 8 * count; - vector[4].iov_base = offsets; - vector[5].iov_len = 8 * count; - vector[5].iov_base = scalings; - tracecmd_add_option_v(handle, TRACECMD_OPTION_TIME_SHIFT, vector, 6); + if (!handle) + goto out; + j = 0; + vector[j].iov_len = 8; + vector[j++].iov_base = &top_instance.trace_id; + vector[j].iov_len = 4; + vector[j++].iov_base = &flags; + vector[j].iov_len = 4; + vector[j++].iov_base = &instance->tsync.vcpu_count; + for (i = 0; i < instance->tsync.vcpu_count; i++) { + if (j >= vcount) + break; + ret = tracecmd_tsync_get_offsets(&instance->tsync, i, &count, + &ts, &offsets, &scalings); + if (ret < 0 || !count || !ts || !offsets || !scalings) + break; + vector[j].iov_len = 4; + vector[j++].iov_base = &count; + vector[j].iov_len = 8 * count; + vector[j++].iov_base = ts; + vector[j].iov_len = 8 * count; + vector[j++].iov_base = offsets; + vector[j].iov_len = 8 * count; + vector[j++].iov_base = scalings; + } + if (i < instance->tsync.vcpu_count) + goto out; + tracecmd_add_option_v(handle, TRACECMD_OPTION_TIME_SHIFT, vector, vcount); tracecmd_append_options(handle); - tracecmd_output_close(handle); #ifdef TSYNC_DEBUG if (count > 1) printf("Got %d timestamp synch samples for guest %s in %lld ns trace\n\r", count, tracefs_instance_get_name(instance->tracefs), ts[count - 1] - ts[0]); #endif +out: + if (handle) + tracecmd_output_close(handle); + else if (fd >= 0) + close(fd); + free(vector); } void tracecmd_host_tsync_complete(struct buffer_instance *instance) @@ -261,6 +285,7 @@ const char *tracecmd_guest_tsync(struct tracecmd_tsync_protos *tsync_protos, pthread_attr_init(&attrib); tsync->proto_name = proto; + tsync->vcpu_count = tracecmd_count_cpus(); pthread_attr_setdetachstate(&attrib, PTHREAD_CREATE_JOINABLE); ret = pthread_create(thr_id, &attrib, tsync_agent_thread, tsync); From patchwork Mon Feb 8 06:17:40 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: 12074057 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 DDC7BC4332B for ; Mon, 8 Feb 2021 06:18:48 +0000 (UTC) Received: from vger.kernel.org (vger.kernel.org [23.128.96.18]) by mail.kernel.org (Postfix) with ESMTP id 9BE7164E59 for ; Mon, 8 Feb 2021 06:18:48 +0000 (UTC) Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S229716AbhBHGSl (ORCPT ); Mon, 8 Feb 2021 01:18:41 -0500 Received: from lindbergh.monkeyblade.net ([23.128.96.19]:50162 "EHLO lindbergh.monkeyblade.net" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S229691AbhBHGSk (ORCPT ); Mon, 8 Feb 2021 01:18:40 -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 DBB76C061756 for ; Sun, 7 Feb 2021 22:17:54 -0800 (PST) Received: by mail-ej1-x62d.google.com with SMTP id y9so22719949ejp.10 for ; Sun, 07 Feb 2021 22:17:54 -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=2i9HKc0rG7Ku6yBwucemoj5F9GSAxZRnARu8swhdHS4=; b=Tr04Ec4jLBMif0oz5TIHKnqqRQe3Ege+piN14CPJ8AFvWNX9x1A1c5gL62BUZPK/z5 rl7+F74tbQHXbwDeZG7al9Fgw19gNSYM5zE5ALLfmcVTqRgyBCkImI3fqwzBZ2HHZgO4 HBaF58UvVLcjfjgzKEP7FLbrQoayvt4zIBHLVO2THI3mUP6CUEdZml4JSq0FEYInaf0X gprVY35/Eo7yTjgAehh8JHUb18nbOk30wSonCgvLX/60040flV1wnGQiPEiGKWwarRLD dUgMmhvAt171isUgpZNr0aEz4LB5xSIclIakPXWUu60r+g2VF8hdDM+d9vWPShoZEgx8 SmjA== 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=2i9HKc0rG7Ku6yBwucemoj5F9GSAxZRnARu8swhdHS4=; b=LZQvUDH9j5Jb24lUKh5vNFo6LFep1ofP0V/15H/57lwnt8DtnYe7RPI+M1udJAB5hQ ELpIbl09YTBn90wys1FA9VoYwBmtRgB1fg98qgl0nR7Ueq5laYnMvU5QTQb04iaajZmD XYnYPjf8B7MUpgt9GMeoPgSvGwk/y7i8GHPKEijipYzZJ/3stMmhIyE/BVGHb6RaDmGo p4RHS1Oqa3uq0QDEglbB0SV+XlW4Hy0foVb8wFnqwIQ88FJnRwIeaTSUZWJFphsX99el kUtNNGvruaJgTbrUHsxuu7BNP7TXDYl5N/Dza4UhVFnARagjqKLDNUtU1os7ZNg61Xfm I5sw== X-Gm-Message-State: AOAM530ifACjKBQ80wuD+gMgHWAez/wp3pChfEAmGMIUw9WzkuJVbr1U Ac4Xv5E/giB7vBwMVizTRRc= X-Google-Smtp-Source: ABdhPJzRPM9XW6L35b72CxuL0pVqhM+2ePx1N9VKt6149bskztqQklgovtzrYSbWan9NBX9e+IxoJg== X-Received: by 2002:a17:907:7289:: with SMTP id dt9mr15435566ejc.446.1612765073694; Sun, 07 Feb 2021 22:17:53 -0800 (PST) Received: from oberon.zico.biz ([83.222.187.186]) by smtp.gmail.com with ESMTPSA id 35sm135618edp.85.2021.02.07.22.17.52 (version=TLS1_3 cipher=TLS_AES_256_GCM_SHA384 bits=256/256); Sun, 07 Feb 2021 22:17:53 -0800 (PST) From: "Tzvetomir Stoyanov (VMware)" To: rostedt@goodmis.org Cc: linux-trace-devel@vger.kernel.org Subject: [PATCH v28 5/8] trace-cmd: Add dummy function to initialize timestamp sync logic Date: Mon, 8 Feb 2021 08:17:40 +0200 Message-Id: <20210208061743.510964-6-tz.stoyanov@gmail.com> X-Mailer: git-send-email 2.29.2 In-Reply-To: <20210208061743.510964-1-tz.stoyanov@gmail.com> References: <20210208061743.510964-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 2581363f..8c1586c7 100644 --- a/lib/trace-cmd/trace-timesync.c +++ b/lib/trace-cmd/trace-timesync.c @@ -57,6 +57,14 @@ static struct tsync_proto *tsync_proto_find(const char *proto_name) return NULL; } +/** + * tracecmd_tsync_init - Initialize the global, per task, time sync data. + */ +void tracecmd_tsync_init(void) +{ + +} + int tracecmd_tsync_proto_register(const char *proto_name, int accuracy, int roles, int supported_clocks, unsigned int flags, int (*init)(struct tracecmd_time_sync *), diff --git a/tracecmd/trace-agent.c b/tracecmd/trace-agent.c index ff4a4e11..36444d32 100644 --- a/tracecmd/trace-agent.c +++ b/tracecmd/trace-agent.c @@ -248,6 +248,8 @@ static void agent_serve(unsigned int port) if (sd < 0) die("Failed to open vsocket"); + tracecmd_tsync_init(); + if (!get_local_cid(&cid)) printf("listening on @%u:%u\n", cid, port); diff --git a/tracecmd/trace-record.c b/tracecmd/trace-record.c index efd96d27..cc870124 100644 --- a/tracecmd/trace-record.c +++ b/tracecmd/trace-record.c @@ -6218,10 +6218,6 @@ static bool has_local_instances(void) return false; } -/* - * This function contains common code for the following commands: - * record, start, stream, profile. - */ static void record_trace(int argc, char **argv, struct common_record_context *ctx) { @@ -6379,12 +6375,23 @@ static void record_trace(int argc, char **argv, finalize_record_trace(ctx); } +/* + * This function contains common code for the following commands: + * record, start, stream, profile. + */ +static void record_trace_command(int argc, char **argv, + struct common_record_context *ctx) +{ + tracecmd_tsync_init(); + record_trace(argc, argv, ctx); +} + void trace_start(int argc, char **argv) { struct common_record_context ctx; parse_record_options(argc, argv, CMD_start, &ctx); - record_trace(argc, argv, &ctx); + record_trace_command(argc, argv, &ctx); exit(0); } @@ -6476,7 +6483,7 @@ void trace_stream(int argc, char **argv) struct common_record_context ctx; parse_record_options(argc, argv, CMD_stream, &ctx); - record_trace(argc, argv, &ctx); + record_trace_command(argc, argv, &ctx); exit(0); } @@ -6495,7 +6502,7 @@ void trace_profile(int argc, char **argv) if (!buffer_instances) top_instance.flags |= BUFFER_FL_PROFILE; - record_trace(argc, argv, &ctx); + record_trace_command(argc, argv, &ctx); do_trace_profile(); exit(0); } @@ -6505,7 +6512,7 @@ void trace_record(int argc, char **argv) struct common_record_context ctx; parse_record_options(argc, argv, CMD_record, &ctx); - record_trace(argc, argv, &ctx); + record_trace_command(argc, argv, &ctx); exit(0); } From patchwork Mon Feb 8 06:17:41 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: 12074061 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 79E75C433E0 for ; Mon, 8 Feb 2021 06:18:49 +0000 (UTC) Received: from vger.kernel.org (vger.kernel.org [23.128.96.18]) by mail.kernel.org (Postfix) with ESMTP id 2A52E64E59 for ; Mon, 8 Feb 2021 06:18:49 +0000 (UTC) Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S229691AbhBHGSs (ORCPT ); Mon, 8 Feb 2021 01:18:48 -0500 Received: from lindbergh.monkeyblade.net ([23.128.96.19]:50164 "EHLO lindbergh.monkeyblade.net" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S229707AbhBHGSk (ORCPT ); Mon, 8 Feb 2021 01:18:40 -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 8C42DC061793 for ; Sun, 7 Feb 2021 22:17:56 -0800 (PST) Received: by mail-ej1-x632.google.com with SMTP id w1so22706482ejf.11 for ; Sun, 07 Feb 2021 22:17:56 -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=5214qemhefpDaB6FW2oPNF593k944L10FqKVAGdc4f4=; b=bT0LwARPmyAUz5Vbb4FgV/sQTzI+V4l05D/86fpvTpNPntBp/BWSndplt951/hnhKr M0TB20j3trLxQyLgxy/i04s6hWYInaRRfiv+gdfcJ4lB20YXSmDaMbGPC3i/6rQliffR iRwznIHNSiXXt4zXAoiw8PXaiowtg+WFjuaySiMnx0UTcF0hCHM/zYzEk1sYnhaSEgv8 ViovEcVe7qYuegY8Mqsj2tMyg1dsD/+t7JVy4I2ht63rtNnCfGz065cSKkTVZTsGUJ5t zIgpGPyeG9lMTzVqELVeG9DZxa9TdmSJtjy1wv5ojspzbKgvx6jekYCRQSeSYT8+PCZM LHOQ== 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=5214qemhefpDaB6FW2oPNF593k944L10FqKVAGdc4f4=; b=FkU7KZZrH70+maO9Ur3B9ZucPE1HgnUEeI4LMQicFZcYN9MWCdKZBdDscTf+6AfVG1 xDlPjU5h+XFIcfKLBdq2gqU7B8urFOy2sGShNEJUcbhVUyC6HZ7IuHuCBteB1Lqeyxtm igPlS8gIhVIS5LyL5bPI48s0gB7WgV/h2iO3cck7RBTEg3ejLVUHmmhgT3G7TXLLOc7Y YoDRx+fuLGQbTA/mG0aAogiEYsGWDEZPHkxOjt8DRH+B7ujoDss/w0w+rofX8DKkvSGF 273JtQEjnjGdYQt4v+bO6s+pX1O2+wJcx9WjentilNEBPr1ALu5Ka52tIuF4SgjDNt9A hCgA== X-Gm-Message-State: AOAM5309acY0uacX+4XF7kxQIaxCm0QsS4lDvvyLVYuoy1BUZcXHFBB7 06jhr/4ZPRaw+Oou4ssvLAM= X-Google-Smtp-Source: ABdhPJzXF4T9Z/JfJxPooL6yaOZ535E5mUtcs/YAN5ypzh05lNDnBx76eLNKlD95A3N/esbh66a1Iw== X-Received: by 2002:a17:906:2e4f:: with SMTP id r15mr15482912eji.407.1612765075100; Sun, 07 Feb 2021 22:17:55 -0800 (PST) Received: from oberon.zico.biz ([83.222.187.186]) by smtp.gmail.com with ESMTPSA id 35sm135618edp.85.2021.02.07.22.17.53 (version=TLS1_3 cipher=TLS_AES_256_GCM_SHA384 bits=256/256); Sun, 07 Feb 2021 22:17:54 -0800 (PST) From: "Tzvetomir Stoyanov (VMware)" To: rostedt@goodmis.org Cc: linux-trace-devel@vger.kernel.org Subject: [PATCH v28 6/8] trace-cmd: [POC] PTP-like algorithm for host - guest timestamp synchronization Date: Mon, 8 Feb 2021 08:17:41 +0200 Message-Id: <20210208061743.510964-7-tz.stoyanov@gmail.com> X-Mailer: git-send-email 2.29.2 In-Reply-To: <20210208061743.510964-1-tz.stoyanov@gmail.com> References: <20210208061743.510964-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 | 1 + lib/trace-cmd/trace-timesync-ptp.c | 715 +++++++++++++++++++++++++++++ lib/trace-cmd/trace-timesync.c | 2 +- 3 files changed, 717 insertions(+), 1 deletion(-) create mode 100644 lib/trace-cmd/trace-timesync-ptp.c diff --git a/lib/trace-cmd/Makefile b/lib/trace-cmd/Makefile index 841c84f1..f41feef8 100644 --- a/lib/trace-cmd/Makefile +++ b/lib/trace-cmd/Makefile @@ -19,6 +19,7 @@ OBJS += trace-msg.o OBJS += trace-plugin.o ifeq ($(VSOCK_DEFINED), 1) OBJS += trace-timesync.o +OBJS += trace-timesync-ptp.o endif # Additional util objects diff --git a/lib/trace-cmd/trace-timesync-ptp.c b/lib/trace-cmd/trace-timesync-ptp.c new file mode 100644 index 00000000..b05f1cd0 --- /dev/null +++ b/lib/trace-cmd/trace-timesync-ptp.c @@ -0,0 +1,715 @@ +// SPDX-License-Identifier: LGPL-2.1 +/* + * Copyright (C) 2019, VMware, Tzvetomir Stoyanov tz.stoyanov@gmail.com> + * + */ + +#include +#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 8c1586c7..fb18075b 100644 --- a/lib/trace-cmd/trace-timesync.c +++ b/lib/trace-cmd/trace-timesync.c @@ -62,7 +62,7 @@ static struct tsync_proto *tsync_proto_find(const char *proto_name) */ void tracecmd_tsync_init(void) { - + ptp_clock_sync_register(); } int tracecmd_tsync_proto_register(const char *proto_name, int accuracy, int roles, From patchwork Mon Feb 8 06:17: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: 12074063 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 26980C433E0 for ; Mon, 8 Feb 2021 06:19:12 +0000 (UTC) Received: from vger.kernel.org (vger.kernel.org [23.128.96.18]) by mail.kernel.org (Postfix) with ESMTP id D51DD64E6C for ; Mon, 8 Feb 2021 06:19:11 +0000 (UTC) Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S229669AbhBHGTL (ORCPT ); Mon, 8 Feb 2021 01:19:11 -0500 Received: from lindbergh.monkeyblade.net ([23.128.96.19]:50268 "EHLO lindbergh.monkeyblade.net" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S229631AbhBHGTK (ORCPT ); Mon, 8 Feb 2021 01:19:10 -0500 Received: from mail-ej1-x631.google.com (mail-ej1-x631.google.com [IPv6:2a00:1450:4864:20::631]) by lindbergh.monkeyblade.net (Postfix) with ESMTPS id D053FC061794 for ; Sun, 7 Feb 2021 22:17:57 -0800 (PST) Received: by mail-ej1-x631.google.com with SMTP id p20so22766299ejb.6 for ; Sun, 07 Feb 2021 22:17:57 -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=astOI0rtCeGzl1x2MtZv1Qc+tSrP5O72kGJIFDTbD7J9ZrhLgjbL3YO6jtfrTMdgKy TsOIlazlhOr4VeIWLQI7OivkORSiOmGy2I8INJXmgYkSfx7eTvHnVn8vYcqtW5In+aQ+ FtW7134sJG9lfIJ492yOD+rF7uPsyAeCp56V52TD0i3NwLqRSJl354aNg7nMs8aIuX3Z GubseU9CnQx3RhsPuIFgYsdNXTFH6vMYbNw2mqFq61haDyrY764e8K3ymrq2nIRfTYhS Ts9ATMXrrJl7eFZshxYWNvX4N6JHLM0ozghQDk8sh9DH0BdpueX31mqi2i1LO8wL3fqy 54tg== 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=Bc1WwCOvg4XNjDA60twIPXs5ZfAWKbXj9zqPZ3X8KGKIKlHaersW1zmopa0eLEWQYt hZKb/ElcldxUcnkOURtWtW87UYNNn0AMazuqYc9CYnN1abAMFrUHEu27KjXSF5sApJKa kZKzWrSAN8uPcuOBv35I1WJJEp4iDDQSbUquUYCp3KonbtRTtv0ZCmHfnV4hjD9wjJTf aufrI3DyPj/JNmKXpef2fJb1Gno1SIiHFS1KfJ2I6L0cm+a5rk7DaG1hvQjpo05vM4A4 zc2RtYpIsugFXPmBfOfygIXn42XYtapMjuQ+u5ohiyrZhL2ARqeOMbLCi8A+pjfmLMM6 NeDQ== X-Gm-Message-State: AOAM533fjDjlHQYBfpE60I0JbK42+jgiIcaTEkGSUenoz2qApOU9UQVE 6Co6s2l/Vcs9wSyNWyXnNuw= X-Google-Smtp-Source: ABdhPJx2F/gVi6fkRyjHyLB+qcrguVBSNB9PBFOiHlAJwcCmM9KwDR4oZbEI5kFhD3hG+8zD0P6L8A== X-Received: by 2002:a17:907:98d7:: with SMTP id kd23mr15509279ejc.283.1612765076630; Sun, 07 Feb 2021 22:17:56 -0800 (PST) Received: from oberon.zico.biz ([83.222.187.186]) by smtp.gmail.com with ESMTPSA id 35sm135618edp.85.2021.02.07.22.17.55 (version=TLS1_3 cipher=TLS_AES_256_GCM_SHA384 bits=256/256); Sun, 07 Feb 2021 22:17:55 -0800 (PST) From: "Tzvetomir Stoyanov (VMware)" To: rostedt@goodmis.org Cc: linux-trace-devel@vger.kernel.org Subject: [PATCH v28 7/8] trace-cmd: Debug scripts for PTP-like algorithm for host - guest timestamp synchronization Date: Mon, 8 Feb 2021 08:17:42 +0200 Message-Id: <20210208061743.510964-8-tz.stoyanov@gmail.com> X-Mailer: git-send-email 2.29.2 In-Reply-To: <20210208061743.510964-1-tz.stoyanov@gmail.com> References: <20210208061743.510964-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 Mon Feb 8 06:17: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: 12074065 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 E54BBC433DB for ; Mon, 8 Feb 2021 06:19:11 +0000 (UTC) Received: from vger.kernel.org (vger.kernel.org [23.128.96.18]) by mail.kernel.org (Postfix) with ESMTP id 913F864E66 for ; Mon, 8 Feb 2021 06:19:11 +0000 (UTC) Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S229707AbhBHGTL (ORCPT ); Mon, 8 Feb 2021 01:19:11 -0500 Received: from lindbergh.monkeyblade.net ([23.128.96.19]:50270 "EHLO lindbergh.monkeyblade.net" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S229669AbhBHGTJ (ORCPT ); Mon, 8 Feb 2021 01:19:09 -0500 Received: from mail-ed1-x531.google.com (mail-ed1-x531.google.com [IPv6:2a00:1450:4864:20::531]) by lindbergh.monkeyblade.net (Postfix) with ESMTPS id 31F49C061797 for ; Sun, 7 Feb 2021 22:17:59 -0800 (PST) Received: by mail-ed1-x531.google.com with SMTP id s11so16764614edd.5 for ; Sun, 07 Feb 2021 22:17:59 -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=/U5+26oHSU+LetnZ0JRJ8wcaHfEj5vHcpq/uoJRZTZM=; b=ORxuLtK3NBTmRT8ylyM0U8P5ZzghkKFQYh9qZMlQIwLsAu0ZGo2BsVOr3sMfX6nHvK 209Xt1yUva3K28IDFCfuS228W0h/DIU+klD21xSuj/qkrdHEREh5IAoBL54jYt90aYY4 hGasfGaUt5OWem9cqRuVq2MJgAUnuHYzrHFB2o8Q/UIO5NjDiZZPkBdzaohWubXFgRey sL0+fCNiREZlBUUxaau6umAzjUpVzAXTPRTLJk9gBdWfGHOunwy1jz7MsyASwx0At7kR 4VI4Kf8705DnZrFGOZWQpBzsF+PUfCRM9IaV/Ut2osVPcswfT8LvBHRG56ZCUQ2A7Eqc yp/A== 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=/U5+26oHSU+LetnZ0JRJ8wcaHfEj5vHcpq/uoJRZTZM=; b=UAQwaUoeIQqt8tyYoh8+XR3bWlcJRBRZ6DgLIDt89JKDbvzOy8YKjJJF3TWmFIKToc epqgsEGcmuH0IGxiYaPpHkzKh/CYQnRVoRt8hdcxqGKhNPHZJJ0Zyk8UBmVLFzIYC5Pf kxLNjgYme5ptvxYIAdZMGPmaRnQUZtZiz30DwR6g0f+Pd/FM82EHo55sLqerYMIPjdDk BKEdKUILH0qB6TwfUy/TX8LfOOZzIc9uLJ2W36o3D9ljsiG9tier/PzD0tUhNmrZKZyl LE7C+k0686v3JND94cmjGAoGyBqs4dYX1862E5YV8krH3XAbDWveKozcEdqHpAp3V9Oo nQBA== X-Gm-Message-State: AOAM5339PTNvoIkJO6pV2tDwBMl3BHeXopzITAqC02Cxz4PvOtFUsm4G Hv1y8Zzv/8vDcSPbn/paufU= X-Google-Smtp-Source: ABdhPJxyBprwaqsF+M14b1NxfHgFfJbxxFHoSxrM9/6eHiuYZpPrfan6OHcwz4M8Qn7lUpGmGbluRA== X-Received: by 2002:a05:6402:40c4:: with SMTP id z4mr15698244edb.233.1612765077841; Sun, 07 Feb 2021 22:17:57 -0800 (PST) Received: from oberon.zico.biz ([83.222.187.186]) by smtp.gmail.com with ESMTPSA id 35sm135618edp.85.2021.02.07.22.17.56 (version=TLS1_3 cipher=TLS_AES_256_GCM_SHA384 bits=256/256); Sun, 07 Feb 2021 22:17:57 -0800 (PST) From: "Tzvetomir Stoyanov (VMware)" To: rostedt@goodmis.org Cc: linux-trace-devel@vger.kernel.org Subject: [PATCH v28 8/8] trace-cmd [POC]: Add KVM timestamp synchronization plugin Date: Mon, 8 Feb 2021 08:17:43 +0200 Message-Id: <20210208061743.510964-9-tz.stoyanov@gmail.com> X-Mailer: git-send-email 2.29.2 In-Reply-To: <20210208061743.510964-1-tz.stoyanov@gmail.com> References: <20210208061743.510964-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 f41feef8..e8d2dae9 100644 --- a/lib/trace-cmd/Makefile +++ b/lib/trace-cmd/Makefile @@ -20,6 +20,7 @@ OBJS += trace-plugin.o ifeq ($(VSOCK_DEFINED), 1) OBJS += trace-timesync.o OBJS += trace-timesync-ptp.o +OBJS += trace-timesync-kvm.o endif # Additional util objects diff --git a/lib/trace-cmd/include/trace-tsync-local.h b/lib/trace-cmd/include/trace-tsync-local.h index d4281469..fe91e2e3 100644 --- a/lib/trace-cmd/include/trace-tsync-local.h +++ b/lib/trace-cmd/include/trace-tsync-local.h @@ -49,5 +49,6 @@ int tracecmd_tsync_proto_register(const char *proto_name, int accuracy, int role int tracecmd_tsync_proto_unregister(char *proto_name); int ptp_clock_sync_register(void); +int kvm_clock_sync_register(void); #endif /* _TRACE_TSYNC_LOCAL_H */ diff --git a/lib/trace-cmd/trace-timesync-kvm.c b/lib/trace-cmd/trace-timesync-kvm.c new file mode 100644 index 00000000..03a4fd73 --- /dev/null +++ b/lib/trace-cmd/trace-timesync-kvm.c @@ -0,0 +1,460 @@ +// SPDX-License-Identifier: LGPL-2.1 +/* + * Copyright (C) 2020, VMware, Tzvetomir Stoyanov tz.stoyanov@gmail.com> + * + */ + +#include +#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 fb18075b..2a95512f 100644 --- a/lib/trace-cmd/trace-timesync.c +++ b/lib/trace-cmd/trace-timesync.c @@ -63,6 +63,7 @@ static struct tsync_proto *tsync_proto_find(const char *proto_name) void tracecmd_tsync_init(void) { ptp_clock_sync_register(); + kvm_clock_sync_register(); } int tracecmd_tsync_proto_register(const char *proto_name, int accuracy, int roles,