From nobody Mon Feb 9 04:02:58 2026 Delivered-To: importer@patchew.org Authentication-Results: mx.zohomail.com; dkim=pass; spf=pass (zohomail.com: domain of gnu.org designates 209.51.188.17 as permitted sender) smtp.mailfrom=qemu-devel-bounces+importer=patchew.org@nongnu.org; dmarc=pass(p=none dis=none) header.from=yandex-team.ru ARC-Seal: i=1; a=rsa-sha256; t=1665499929; cv=none; d=zohomail.com; s=zohoarc; b=CU9pIqfDzLDuzTYJsKcH+dbFDmFAfXyJDWkwDTNLhJGeuw38TwnntSFb9/JvBnH+qm2Myn6zVc/rnJpKIdQo9ue+bRn61H3k7dTAga4DldXojWcTlyj/vFwKPPFRzdbjX1W6bGb998o5IOGxSutXR1SeJoo/TuLIR3QFuQrh7eY= ARC-Message-Signature: i=1; a=rsa-sha256; c=relaxed/relaxed; d=zohomail.com; s=zohoarc; t=1665499929; h=Content-Transfer-Encoding:Cc:Date:From:List-Subscribe:List-Post:List-Id:List-Archive:List-Help:List-Unsubscribe:MIME-Version:Message-ID:Sender:Subject:To; bh=ZjCJ/23Vzu7j3qRPx1xJB//ruXY/6YIukAIlC8gf2sY=; b=gFYAi31L/0SllloBQtvHs67Qo86gI71oCThjSOuC7PSi6qr/Fjc14TjdXCFX2riP6tc85imj6Wi6IKOVLrSZc4fjjERuwOgKbG0xprEG29ecNZLysxMbEtt4b0Qt8c+YxqjDnydgzzTMEuPz5KHCNIsHxTYTYr/kFllpK5gn3zQ= ARC-Authentication-Results: i=1; mx.zohomail.com; dkim=pass; spf=pass (zohomail.com: domain of gnu.org designates 209.51.188.17 as permitted sender) smtp.mailfrom=qemu-devel-bounces+importer=patchew.org@nongnu.org; dmarc=pass header.from= (p=none dis=none) Return-Path: Received: from lists.gnu.org (lists.gnu.org [209.51.188.17]) by mx.zohomail.com with SMTPS id 1665499928792347.34153850054497; Tue, 11 Oct 2022 07:52:08 -0700 (PDT) Received: from localhost ([::1]:51800 helo=lists1p.gnu.org) by lists.gnu.org with esmtp (Exim 4.90_1) (envelope-from ) id 1oiGc3-0003YW-CF for importer@patchew.org; Tue, 11 Oct 2022 10:52:07 -0400 Received: from eggs.gnu.org ([2001:470:142:3::10]:41196) by lists.gnu.org with esmtps (TLS1.2:ECDHE_RSA_AES_256_GCM_SHA384:256) (Exim 4.90_1) (envelope-from ) id 1oiGXz-0001Ry-2W for qemu-devel@nongnu.org; Tue, 11 Oct 2022 10:48:00 -0400 Received: from forwardcorp1c.mail.yandex.net ([178.154.239.200]:60426) by eggs.gnu.org with esmtps (TLS1.2:ECDHE_RSA_AES_256_GCM_SHA384:256) (Exim 4.90_1) (envelope-from ) id 1oiGVe-0004O6-2j for qemu-devel@nongnu.org; Tue, 11 Oct 2022 10:45:33 -0400 Received: from sas1-c73b4b4f4b95.qloud-c.yandex.net (sas1-c73b4b4f4b95.qloud-c.yandex.net [IPv6:2a02:6b8:c08:12a9:0:640:c73b:4b4f]) by forwardcorp1c.mail.yandex.net (Yandex) with ESMTP id 8C53460108; Tue, 11 Oct 2022 17:45:18 +0300 (MSK) Received: from den-plotnikov-w.yandex-team.ru (unknown [2a02:6b8:b081:9::1:36]) by sas1-c73b4b4f4b95.qloud-c.yandex.net (smtpcorp/Yandex) with ESMTPSA id zfeAkQMvyu-jGOWvuZ2; Tue, 11 Oct 2022 17:45:17 +0300 (using TLSv1.3 with cipher TLS_AES_256_GCM_SHA384 (256/256 bits)) (Client certificate not present) Precedence: bulk X-Yandex-Fwd: 1 DKIM-Signature: v=1; a=rsa-sha256; c=relaxed/relaxed; d=yandex-team.ru; s=default; t=1665499517; bh=ZjCJ/23Vzu7j3qRPx1xJB//ruXY/6YIukAIlC8gf2sY=; h=Message-Id:Date:Cc:Subject:To:From; b=KKzvZIfnrE9OoHMy7uhajeeaZ+6TginnQ0dHgrAAT4G/Uic1emcSvHv0Fv1HXsUzz ssW3/8S9OuSlN0MR7KLA78wjieKiMX+9t4EBA78Ycakwlcr67J0Q9VivWnoISU9lz+ SfmVKPEmGRJAdZwyDDV92OWmIwW/KBdIR3LurylU= Authentication-Results: sas1-c73b4b4f4b95.qloud-c.yandex.net; dkim=pass header.i=@yandex-team.ru From: Denis Plotnikov To: qemu-devel@nongnu.org Cc: yc-core@yandex-team.ru, armbru@redhat.com, michael.roth@amd.com, vsementsov@yandex-team.ru, berrange@redhat.com Subject: [PATCH v2] qapi/qmp: Add timestamps to qmp command responses Date: Tue, 11 Oct 2022 17:45:09 +0300 Message-Id: <20221011144509.493646-1-den-plotnikov@yandex-team.ru> X-Mailer: git-send-email 2.25.1 MIME-Version: 1.0 Content-Transfer-Encoding: quoted-printable Received-SPF: pass (zohomail.com: domain of gnu.org designates 209.51.188.17 as permitted sender) client-ip=209.51.188.17; envelope-from=qemu-devel-bounces+importer=patchew.org@nongnu.org; helo=lists.gnu.org; Received-SPF: pass client-ip=178.154.239.200; envelope-from=den-plotnikov@yandex-team.ru; helo=forwardcorp1c.mail.yandex.net X-Spam_score_int: -20 X-Spam_score: -2.1 X-Spam_bar: -- X-Spam_report: (-2.1 / 5.0 requ) BAYES_00=-1.9, DKIM_SIGNED=0.1, DKIM_VALID=-0.1, DKIM_VALID_AU=-0.1, DKIM_VALID_EF=-0.1, SPF_HELO_NONE=0.001, SPF_PASS=-0.001 autolearn=ham autolearn_force=no X-Spam_action: no action X-BeenThere: qemu-devel@nongnu.org X-Mailman-Version: 2.1.29 List-Id: List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , Errors-To: qemu-devel-bounces+importer=patchew.org@nongnu.org Sender: "Qemu-devel" X-ZohoMail-DKIM: pass (identity @yandex-team.ru) X-ZM-MESSAGEID: 1665499931117100003 Content-Type: text/plain; charset="utf-8" Add "start" & "end" time values to qmp command responses. These time values are added to let the qemu management layer get the exact command execution time without any other time variance which might be broug= ht by other parts of management layer or qemu internals. This is particulary usef= ul for the management layer logging for later problems resolving. Example of result: ./qemu/scripts/qmp/qmp-shell /tmp/qmp.socket (QEMU) query-status {"end": {"seconds": 1650367305, "microseconds": 831032}, "start": {"seconds": 1650367305, "microseconds": 831012}, "return": {"status": "running", "singlestep": false, "running": true}} The responce of the qmp command contains the start & end time of the qmp command processing. Suggested-by: Andrey Ryabinin Signed-off-by: Denis Plotnikov Reviewed-by: Daniel P. Berrang=C3=A9 --- v0->v1: - remove interface to control "start" and "end" time values: return timest= amps unconditionally - add description to qmp specification - leave the same timestamp format in "seconds", "microseconds" to be consi= stent with events timestamp - fix patch description v1->v2: - rephrase doc descriptions [Daniel] - add tests for qmp timestamps to qmp test and qga test [Daniel] - adjust asserts in test-qmp-cmds according to the new number of returning= keys docs/interop/qmp-spec.txt | 28 ++++++++++++++++++++++++++-- qapi/qmp-dispatch.c | 18 ++++++++++++++++++ tests/qtest/qmp-test.c | 34 ++++++++++++++++++++++++++++++++++ tests/unit/test-qga.c | 31 +++++++++++++++++++++++++++++++ tests/unit/test-qmp-cmds.c | 4 ++-- 5 files changed, 111 insertions(+), 4 deletions(-) diff --git a/docs/interop/qmp-spec.txt b/docs/interop/qmp-spec.txt index b0e8351d5b261..2e0b7de0c4dc7 100644 --- a/docs/interop/qmp-spec.txt +++ b/docs/interop/qmp-spec.txt @@ -158,7 +158,9 @@ responses that have an unknown "id" field. =20 The format of a success response is: =20 -{ "return": json-value, "id": json-value } +{ "return": json-value, "id": json-value, + "start": {"seconds": json-value, "microseconds": json-value}, + "end": {"seconds": json-value, "microseconds": json-value} } =20 Where, =20 @@ -169,13 +171,25 @@ The format of a success response is: command does not return data - The "id" member contains the transaction identification associated with the command execution if issued by the Client +- The "start" member contains the exact time of when the server + started executing the command. This excludes any time the + command request spent queued, after reading it off the wire. + It is a fixed json-object with time in seconds and microseconds + relative to the Unix Epoch (1 Jan 1970) +- The "end" member contains the exact time of when the server + finished executing the command. This excludes any time the + command response spent queued, waiting to be sent on the wire. + It is a fixed json-object with time in seconds and microseconds + relative to the Unix Epoch (1 Jan 1970) =20 2.4.2 error ----------- =20 The format of an error response is: =20 -{ "error": { "class": json-string, "desc": json-string }, "id": json-value= } +{ "error": { "class": json-string, "desc": json-string }, "id": json-value + "start": {"seconds": json-value, "microseconds": json-value}, + "end": {"seconds": json-value, "microseconds": json-value} } =20 Where, =20 @@ -184,6 +198,16 @@ The format of an error response is: not attempt to parse this message. - The "id" member contains the transaction identification associated with the command execution if issued by the Client +- The "start" member contains the exact time of when the server + started executing the command. This excludes any time the + command request spent queued, after reading it off the wire. + It is a fixed json-object with time in seconds and microseconds + relative to the Unix Epoch (1 Jan 1970) +- The "end" member contains the exact time of when the server + finished executing the command. This excludes any time the + command response spent queued, waiting to be sent on the wire. + It is a fixed json-object with time in seconds and microseconds + relative to the Unix Epoch (1 Jan 1970) =20 NOTE: Some errors can occur before the Server is able to read the "id" mem= ber, in these cases the "id" member will not be part of the error response, even diff --git a/qapi/qmp-dispatch.c b/qapi/qmp-dispatch.c index 0990873ec8ec1..fce87416f2128 100644 --- a/qapi/qmp-dispatch.c +++ b/qapi/qmp-dispatch.c @@ -130,6 +130,22 @@ static void do_qmp_dispatch_bh(void *opaque) aio_co_wake(data->co); } =20 +static void add_timestamps(QDict *qdict, uint64_t start_ms, uint64_t end_m= s) +{ + QDict *start_dict, *end_dict; + + start_dict =3D qdict_new(); + qdict_put_int(start_dict, "seconds", start_ms / G_USEC_PER_SEC); + qdict_put_int(start_dict, "microseconds", start_ms % G_USEC_PER_SEC); + + end_dict =3D qdict_new(); + qdict_put_int(end_dict, "seconds", end_ms / G_USEC_PER_SEC); + qdict_put_int(end_dict, "microseconds", end_ms % G_USEC_PER_SEC); + + qdict_put_obj(qdict, "start", QOBJECT(start_dict)); + qdict_put_obj(qdict, "end", QOBJECT(end_dict)); +} + /* * Runs outside of coroutine context for OOB commands, but in coroutine * context for everything else. @@ -146,6 +162,7 @@ QDict *qmp_dispatch(const QmpCommandList *cmds, QObject= *request, QObject *id; QObject *ret =3D NULL; QDict *rsp =3D NULL; + uint64_t ts_start =3D g_get_real_time(); =20 dict =3D qobject_to(QDict, request); if (!dict) { @@ -270,5 +287,6 @@ out: qdict_put_obj(rsp, "id", qobject_ref(id)); } =20 + add_timestamps(rsp, ts_start, g_get_real_time()); return rsp; } diff --git a/tests/qtest/qmp-test.c b/tests/qtest/qmp-test.c index 22957fa49c228..e0d83eea91ae5 100644 --- a/tests/qtest/qmp-test.c +++ b/tests/qtest/qmp-test.c @@ -33,6 +33,30 @@ static void test_version(QObject *version) visit_free(v); } =20 +static void test_timestamps(QDict *resp) +{ + QDict *start, *end; + uint64_t start_s, start_us, end_s, end_us, start_ts, end_ts; + + start =3D qdict_get_qdict(resp, "start"); + g_assert(start); + end =3D qdict_get_qdict(resp, "end"); + g_assert(end); + + start_s =3D qdict_get_try_int(start, "seconds", 0); + g_assert(start_s); + start_us =3D qdict_get_try_int(start, "microseconds", 0); + + end_s =3D qdict_get_try_int(end, "seconds", 0); + g_assert(end_s); + end_us =3D qdict_get_try_int(end, "microseconds", 0); + + start_ts =3D (start_s * G_USEC_PER_SEC) + start_us; + end_ts =3D (end_s * G_USEC_PER_SEC) + end_us; + + g_assert(end_ts > start_ts); +} + static void assert_recovered(QTestState *qts) { QDict *resp; @@ -156,6 +180,16 @@ static void test_qmp_protocol(void) g_assert_cmpint(qdict_get_int(resp, "id"), =3D=3D, 2); qmp_expect_error_and_unref(resp, "GenericError"); =20 + /* Test timestamps on success */ + resp =3D qtest_qmp(qts, "{ 'execute': 'query-version' }"); + test_timestamps(resp); + qobject_unref(resp); + + /* Test timestamps on error */ + resp =3D qtest_qmp(qts, "{ 'execute': 'not-existing-cmd' }"); + test_timestamps(resp); + qobject_unref(resp); + qtest_quit(qts); } =20 diff --git a/tests/unit/test-qga.c b/tests/unit/test-qga.c index b4e0a145737d1..b30a3d1abe55f 100644 --- a/tests/unit/test-qga.c +++ b/tests/unit/test-qga.c @@ -217,6 +217,36 @@ static void test_qga_ping(gconstpointer fix) qmp_assert_no_error(ret); } =20 +static void test_qga_timestamps(gconstpointer fix) +{ + QDict *start, *end; + uint64_t start_s, start_us, end_s, end_us, start_ts, end_ts; + const TestFixture *fixture =3D fix; + g_autoptr(QDict) ret =3D NULL; + + ret =3D qmp_fd(fixture->fd, "{'execute': 'guest-ping'}"); + g_assert_nonnull(ret); + qmp_assert_no_error(ret); + + start =3D qdict_get_qdict(ret, "start"); + g_assert(start); + end =3D qdict_get_qdict(ret, "end"); + g_assert(end); + + start_s =3D qdict_get_try_int(start, "seconds", 0); + g_assert(start_s); + start_us =3D qdict_get_try_int(start, "microseconds", 0); + + end_s =3D qdict_get_try_int(end, "seconds", 0); + g_assert(end_s); + end_us =3D qdict_get_try_int(end, "microseconds", 0); + + start_ts =3D (start_s * G_USEC_PER_SEC) + start_us; + end_ts =3D (end_s * G_USEC_PER_SEC) + end_us; + + g_assert(end_ts > start_ts); +} + static void test_qga_id(gconstpointer fix) { const TestFixture *fixture =3D fix; @@ -948,6 +978,7 @@ int main(int argc, char **argv) g_test_add_data_func("/qga/sync-delimited", &fix, test_qga_sync_delimi= ted); g_test_add_data_func("/qga/sync", &fix, test_qga_sync); g_test_add_data_func("/qga/ping", &fix, test_qga_ping); + g_test_add_data_func("/qga/timestaps", &fix, test_qga_timestamps); g_test_add_data_func("/qga/info", &fix, test_qga_info); g_test_add_data_func("/qga/network-get-interfaces", &fix, test_qga_network_get_interfaces); diff --git a/tests/unit/test-qmp-cmds.c b/tests/unit/test-qmp-cmds.c index 6085c099950b5..54d63bb8e346f 100644 --- a/tests/unit/test-qmp-cmds.c +++ b/tests/unit/test-qmp-cmds.c @@ -154,7 +154,7 @@ static QObject *do_qmp_dispatch(bool allow_oob, const c= har *template, ...) g_assert(resp); ret =3D qdict_get(resp, "return"); g_assert(ret); - g_assert(qdict_size(resp) =3D=3D 1); + g_assert(qdict_size(resp) =3D=3D 3); =20 qobject_ref(ret); qobject_unref(resp); @@ -181,7 +181,7 @@ static void do_qmp_dispatch_error(bool allow_oob, Error= Class cls, =3D=3D, QapiErrorClass_str(cls)); g_assert(qdict_get_try_str(error, "desc")); g_assert(qdict_size(error) =3D=3D 2); - g_assert(qdict_size(resp) =3D=3D 1); + g_assert(qdict_size(resp) =3D=3D 3); =20 qobject_unref(resp); qobject_unref(req); --=20 2.25.1