On Tue, Oct 11, 2022 at 6:49 PM Denis Plotnikov <
den-plotni...@yandex-team.ru> wrote:
> 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
> brought by
> other parts of management layer or qemu internals. This is particulary
> useful
> 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 <a...@yandex-team.ru>
> Signed-off-by: Denis Plotnikov <den-plotni...@yandex-team.ru>
> ---
> v0->v1:
> - remove interface to control "start" and "end" time values: return
> timestamps unconditionally
> - add description to qmp specification
> - leave the same timestamp format in "seconds", "microseconds" to be
> consistent 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.
>
> The format of a success response is:
>
> -{ "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} }
>
> Where,
>
> @@ -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)
>
> 2.4.2 error
> -----------
>
> The format of an error response is:
>
> -{ "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} }
>
> Where,
>
> @@ -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)
>
> NOTE: Some errors can occur before the Server is able to read the "id"
> member,
> 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);
> }
>
> +static void add_timestamps(QDict *qdict, uint64_t start_ms, uint64_t
> end_ms)
> +{
> + QDict *start_dict, *end_dict;
> +
> + start_dict = 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 = 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 = NULL;
> QDict *rsp = NULL;
> + uint64_t ts_start = g_get_real_time();
>
> dict = qobject_to(QDict, request);
> if (!dict) {
> @@ -270,5 +287,6 @@ out:
> qdict_put_obj(rsp, "id", qobject_ref(id));
> }
>
> + 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);
> }
>
> +static void test_timestamps(QDict *resp)
> +{
> + QDict *start, *end;
> + uint64_t start_s, start_us, end_s, end_us, start_ts, end_ts;
> +
> + start = qdict_get_qdict(resp, "start");
> + g_assert(start);
> + end = qdict_get_qdict(resp, "end");
> + g_assert(end);
> +
> + start_s = qdict_get_try_int(start, "seconds", 0);
> + g_assert(start_s);
> + start_us = qdict_get_try_int(start, "microseconds", 0);
> +
> + end_s = qdict_get_try_int(end, "seconds", 0);
> + g_assert(end_s);
> + end_us = qdict_get_try_int(end, "microseconds", 0);
> +
> + start_ts = (start_s * G_USEC_PER_SEC) + start_us;
> + end_ts = (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"), ==, 2);
> qmp_expect_error_and_unref(resp, "GenericError");
>
> + /* Test timestamps on success */
> + resp = qtest_qmp(qts, "{ 'execute': 'query-version' }");
> + test_timestamps(resp);
> + qobject_unref(resp);
> +
> + /* Test timestamps on error */
> + resp = qtest_qmp(qts, "{ 'execute': 'not-existing-cmd' }");
> + test_timestamps(resp);
> + qobject_unref(resp);
> +
> qtest_quit(qts);
> }
>
> 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);
> }
>
> +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 = fix;
> + g_autoptr(QDict) ret = NULL;
> +
> + ret = qmp_fd(fixture->fd, "{'execute': 'guest-ping'}");
> + g_assert_nonnull(ret);
> + qmp_assert_no_error(ret);
> +
> + start = qdict_get_qdict(ret, "start");
> + g_assert(start);
> + end = qdict_get_qdict(ret, "end");
> + g_assert(end);
> +
> + start_s = qdict_get_try_int(start, "seconds", 0);
> + g_assert(start_s);
> + start_us = qdict_get_try_int(start, "microseconds", 0);
> +
> + end_s = qdict_get_try_int(end, "seconds", 0);
> + g_assert(end_s);
> + end_us = qdict_get_try_int(end, "microseconds", 0);
> +
> + start_ts = (start_s * G_USEC_PER_SEC) + start_us;
> + end_ts = (end_s * G_USEC_PER_SEC) + end_us;
> +
> + g_assert(end_ts > start_ts);
> +}
> +
> static void test_qga_id(gconstpointer fix)
> {
> const TestFixture *fixture = fix;
> @@ -948,6 +978,7 @@ int main(int argc, char **argv)
> g_test_add_data_func("/qga/sync-delimited", &fix,
> test_qga_sync_delimited);
> 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);
>
/qga/timestaMps
lgtm otherwise
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
> char *template, ...)
> g_assert(resp);
> ret = qdict_get(resp, "return");
> g_assert(ret);
> - g_assert(qdict_size(resp) == 1);
> + g_assert(qdict_size(resp) == 3);
>
> qobject_ref(ret);
> qobject_unref(resp);
> @@ -181,7 +181,7 @@ static void do_qmp_dispatch_error(bool allow_oob,
> ErrorClass cls,
> ==, QapiErrorClass_str(cls));
> g_assert(qdict_get_try_str(error, "desc"));
> g_assert(qdict_size(error) == 2);
> - g_assert(qdict_size(resp) == 1);
> + g_assert(qdict_size(resp) == 3);
>
> qobject_unref(resp);
> qobject_unref(req);
> --
> 2.25.1
>
>
>
--
Marc-André Lureau
