Re: [PATCH v3] qapi/qmp: Add timestamps to qmp command responses

[Denis Plotnikov]

On 13.10.2022 18:00, Markus Armbruster wrote:
> Denis Plotnikov <den-plotnikov@yandex-team.ru> writes:
>
> > Add "start" & "end" time values to qmp command responses.
> Please spell it QMP.  More of the same below.
ok
> Can you tell me about a problem you cracked (or could have cracked) with
> the help of this?

We have a management layer which interacts with qemu via qmp. When it 
issues a qmp command we measure execution time which takes to perform a 
certain qmp command. Some of that commands seems to execute longer that 
expected. In that case there is a question what part of command 
execution takes the majority of time. Is it the flaw in the management 
layer or in qemu qmp command scheduling or the qmp command execution 
itself? The timestaps being added help to exclude the qmp command 
execution time from the question. Also timestamps helps to get know the 
exact time when the command is started and ended and put that 
information to a system logs properly according to timestamps.

> >       "return": {"status": "running", "singlestep": false, "running": true}}
> >
> > The responce of the qmp command contains the start & end time of
> response
ok
> > the qmp command processing.
> >
> > Suggested-by: Andrey Ryabinin <arbn@yandex-team.ru>
> > Signed-off-by: Denis Plotnikov <den-plotnikov@yandex-team.ru>
> > Reviewed-by: Daniel P. Berrangé <berrange@redhat.com>
> Please spell out that this affects both QMP and qemu-ga.
ok
> >     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)
> What's a "fixed json-object"?
>
> Hmm, I guess you're copying from the description of event member
> "timestamp".
That's right
> Let's go with "a json-object with the number of seconds and microseconds
> since the Unix epoch" everywhere.
ok
> Make this int64_t, because that's what g_get_real_time() returns.
>
> Same for add_timestamps() parameters.
ok, will fix the type everywhere
> +    qobject_unref(resp);
> I'd be tempted to fold this into existing tests.

Do you want me to put timestamp checking to an existing testcase?


Thanks,

Denis

> > +
> >       qtest_quit(qts);
> >   }
> >   
> > diff --git a/tests/unit/test-qga.c b/tests/unit/test-qga.c
> > index b4e0a145737d1..18ec9bac3650e 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/timestamps", &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 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);