Re: [patch v0] qapi/qmp: Add timestamps to qmp command responses.
On Wed, Sep 28, 2022 at 04:24:29PM +0600, Roman Kagan wrote:
> On Tue, Sep 27, 2022 at 08:04:11AM +0200, Markus Armbruster wrote:
> > Daniel P. Berrangé writes:
> > > On Mon, Sep 26, 2022 at 12:59:40PM +0300, Denis Plotnikov wrote:
> > >> 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.
> >
> > Seconds and microseconds since when? The update to qmp-spec.txt should
> > tell.
> >
> > Why split the time into seconds and microseconds?
>
> This is exactly how timestamps in QMP events are done, so we thought
> we'd just follow suit
Yes, I think its good to have consistency with the rest of the spec,
despite Markus' point that it could be simplified to one field.
With regards,
Daniel
--
|: https://berrange.com -o-https://www.flickr.com/photos/dberrange :|
|: https://libvirt.org -o-https://fstop138.berrange.com :|
|: https://entangle-photo.org-o-https://www.instagram.com/dberrange :|
Re: [patch v0] qapi/qmp: Add timestamps to qmp command responses.
On Tue, Sep 27, 2022 at 08:04:11AM +0200, Markus Armbruster wrote:
> Daniel P. Berrangé writes:
> > On Mon, Sep 26, 2022 at 12:59:40PM +0300, Denis Plotnikov wrote:
> >> 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.
>
> Seconds and microseconds since when? The update to qmp-spec.txt should
> tell.
>
> Why split the time into seconds and microseconds?
This is exactly how timestamps in QMP events are done, so we thought
we'd just follow suit
> > The mgmt app already knows when it send the QMP command and knows
> > when it gets the QMP reply. This covers the time the QMP was
> > queued before processing (might be large if QMP is blocked on
> > another slow command) , the processing time, and the time any
> > reply was queued before sending (ought to be small).
> >
> > So IIUC, the value these fields add is that they let the mgmt
> > app extract only the command processing time, eliminating
> > any variance do to queue before/after.
Right, this is precisely the motivation.
Thanks,
Roman.
Re: [patch v0] qapi/qmp: Add timestamps to qmp command responses.
On 27.09.2022 09:04, Markus Armbruster wrote:
Daniel P. Berrangé writes:
On Mon, Sep 26, 2022 at 12:59:40PM +0300, Denis Plotnikov wrote:
Add "start" & "end" timestamps to qmp command responses.
It's disabled by default, but can be enabled with 'timestamp=on'
monitor's parameter, e.g.:
-chardev socket,id=mon1,path=/tmp/qmp.socket,server=on,wait=off
-mon chardev=mon1,mode=control,timestamp=on
I'm not convinced a cmdline flag is the right approach here.
I think it ought be something defined by the QMP spec.
The QMP spec is docs/interop/qmp-spec.txt. The feature needs to be
defined there regardless of how we control it.
ok, thanks for pointing out
The "QMP" greeting should report "timestamp" capabilities.
The 'qmp_capabilities' command can be used to turn on this
capability for all commands henceforth.
Yes, this is how optional QMP protocol features should be controlled.
Bonus: control is per connection, not just globally.
As an option extra, the 'execute' command could gain a
parameter to allow this to be requested for only an
individual command.
Needs a use case.
Alternatively we could say the overhead of adding the timestmaps
is small enough that we just add this unconditionally for
everything hence, with no opt-in/opt-out.
Yes, because the extension is backwards compatible.
May be it worth to send the timestamps always in the response if doesn't
contradicts with anything and doesn't bring any unnecessary data overhead.
From the other hand turning it on via qmp capabilities seems to be more
flexible solution.
Aside: qmp-spec.txt could be clearer on what that means.
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.
Seconds and microseconds since when? The update to qmp-spec.txt should
tell.
Why split the time into seconds and microseconds? If you use
microseconds since the Unix epoch (1970-01-01 UTC), 64 bit unsigned will
result in a year 586524 problem:
$ date --date "@`echo '2^64/100' | bc`"
Wed Jan 19 09:01:49 CET 586524
Even a mere 53 bits will last until 2255.
This is Just for convenience, may be it's too much and timestamp in msec
if enough
These times may be helpful for the management layer in understanding of
the actual timeline of a qmp command processing.
Can you explain the problem scenario in more detail.
Yes, please, because:
The mgmt app already knows when it send the QMP command and knows
when it gets the QMP reply. This covers the time the QMP was
queued before processing (might be large if QMP is blocked on
another slow command) , the processing time, and the time any
reply was queued before sending (ought to be small).
So IIUC, the value these fields add is that they let the mgmt
app extract only the command processing time, eliminating
any variance do to queue before/after.
So the scenario is the following: we need a means to understand from the
management layer prospecitive of what is the timeline of the command
execution. This is needed for a problem resolving if a qmp command
executes for too long from the management layer point of view.
Specifically, management layer sees the execution time as
"management_layer_internal_routine_time" + "qemu_dispatching_time" +
"qemu_qmp_command_execution_time". Suggested qmp command timestaps gives
"qemu_command_execution_time". Management layer calculates
"management_layer_internal_routine_time" internally. Using those two
things we can calculate "qemu_dispatching_time" and decide where the
potential delays comes from. This will gives us a direction of further
problem investigation.
Suggested-by: Andrey Ryabinin
Signed-off-by: Denis Plotnikov
Re: [patch v0] qapi/qmp: Add timestamps to qmp command responses.
Daniel P. Berrangé writes:
> On Mon, Sep 26, 2022 at 12:59:40PM +0300, Denis Plotnikov wrote:
>> Add "start" & "end" timestamps to qmp command responses.
>> It's disabled by default, but can be enabled with 'timestamp=on'
>> monitor's parameter, e.g.:
>> -chardev socket,id=mon1,path=/tmp/qmp.socket,server=on,wait=off
>> -mon chardev=mon1,mode=control,timestamp=on
>
> I'm not convinced a cmdline flag is the right approach here.
>
> I think it ought be something defined by the QMP spec.
The QMP spec is docs/interop/qmp-spec.txt. The feature needs to be
defined there regardless of how we control it.
> The "QMP" greeting should report "timestamp" capabilities.
>
> The 'qmp_capabilities' command can be used to turn on this
> capability for all commands henceforth.
Yes, this is how optional QMP protocol features should be controlled.
Bonus: control is per connection, not just globally.
> As an option extra, the 'execute' command could gain a
> parameter to allow this to be requested for only an
> individual command.
Needs a use case.
> Alternatively we could say the overhead of adding the timestmaps
> is small enough that we just add this unconditionally for
> everything hence, with no opt-in/opt-out.
Yes, because the extension is backwards compatible.
Aside: qmp-spec.txt could be clearer on what that means.
>> 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.
Seconds and microseconds since when? The update to qmp-spec.txt should
tell.
Why split the time into seconds and microseconds? If you use
microseconds since the Unix epoch (1970-01-01 UTC), 64 bit unsigned will
result in a year 586524 problem:
$ date --date "@`echo '2^64/100' | bc`"
Wed Jan 19 09:01:49 CET 586524
Even a mere 53 bits will last until 2255.
>> These times may be helpful for the management layer in understanding of
>> the actual timeline of a qmp command processing.
>
> Can you explain the problem scenario in more detail.
Yes, please, because:
> The mgmt app already knows when it send the QMP command and knows
> when it gets the QMP reply. This covers the time the QMP was
> queued before processing (might be large if QMP is blocked on
> another slow command) , the processing time, and the time any
> reply was queued before sending (ought to be small).
>
> So IIUC, the value these fields add is that they let the mgmt
> app extract only the command processing time, eliminating
> any variance do to queue before/after.
>
>> Suggested-by: Andrey Ryabinin
>> Signed-off-by: Denis Plotnikov
Re: [patch v0] qapi/qmp: Add timestamps to qmp command responses.
On Mon, Sep 26, 2022 at 12:59:40PM +0300, Denis Plotnikov wrote:
> Add "start" & "end" timestamps to qmp command responses.
> It's disabled by default, but can be enabled with 'timestamp=on'
> monitor's parameter, e.g.:
> -chardev socket,id=mon1,path=/tmp/qmp.socket,server=on,wait=off
> -mon chardev=mon1,mode=control,timestamp=on
I'm not convinced a cmdline flag is the right approach here.
I think it ought be something defined by the QMP spec.
The "QMP" greeting should report "timestamp" capabilities.
The 'qmp_capabilities' command can be used to turn on this
capability for all commands henceforth.
As an option extra, the 'execute' command could gain a
parameter to allow this to be requested for only an
individual command.
Alternatively we could say the overhead of adding the timestmaps
is small enough that we just add this unconditionally for
everything hence, with no opt-in/opt-out.
> 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.
>
> These times may be helpful for the management layer in understanding of
> the actual timeline of a qmp command processing.
Can you explain the problem scenario in more detail.
The mgmt app already knows when it send the QMP command and knows
when it gets the QMP reply. This covers the time the QMP was
queued before processing (might be large if QMP is blocked on
another slow command) , the processing time, and the time any
reply was queued before sending (ought to be small).
So IIUC, the value these fields add is that they let the mgmt
app extract only the command processing time, eliminating
any variance do to queue before/after.
> Suggested-by: Andrey Ryabinin
> Signed-off-by: Denis Plotnikov
> ---
> include/monitor/monitor.h | 2 +-
> include/qapi/qmp/dispatch.h | 2 +-
> monitor/monitor-internal.h | 1 +
> monitor/monitor.c | 9 -
> monitor/qmp.c | 5 +++--
> qapi/control.json | 3 +++
> qapi/qmp-dispatch.c | 28 +++-
> qga/main.c | 2 +-
> stubs/monitor-core.c| 2 +-
> tests/unit/test-qmp-cmds.c | 6 +++---
> 10 files changed, 49 insertions(+), 11 deletions(-)
>
> diff --git a/include/monitor/monitor.h b/include/monitor/monitor.h
> index a4b40e8391db4..2a18e9ee34bc2 100644
> --- a/include/monitor/monitor.h
> +++ b/include/monitor/monitor.h
> @@ -19,7 +19,7 @@ bool monitor_cur_is_qmp(void);
>
> void monitor_init_globals(void);
> void monitor_init_globals_core(void);
> -void monitor_init_qmp(Chardev *chr, bool pretty, Error **errp);
> +void monitor_init_qmp(Chardev *chr, bool pretty, bool timestamp, Error
> **errp);
> void monitor_init_hmp(Chardev *chr, bool use_readline, Error **errp);
> int monitor_init(MonitorOptions *opts, bool allow_hmp, Error **errp);
> int monitor_init_opts(QemuOpts *opts, Error **errp);
> diff --git a/include/qapi/qmp/dispatch.h b/include/qapi/qmp/dispatch.h
> index 1e4240fd0dbc0..d07f5764271be 100644
> --- a/include/qapi/qmp/dispatch.h
> +++ b/include/qapi/qmp/dispatch.h
> @@ -56,7 +56,7 @@ const char *qmp_command_name(const QmpCommand *cmd);
> bool qmp_has_success_response(const QmpCommand *cmd);
> QDict *qmp_error_response(Error *err);
> QDict *qmp_dispatch(const QmpCommandList *cmds, QObject *request,
> -bool allow_oob, Monitor *cur_mon);
> +bool allow_oob, bool timestamp, Monitor *cur_mon);
> bool qmp_is_oob(const QDict *dict);
>
> typedef void (*qmp_cmd_callback_fn)(const QmpCommand *cmd, void *opaque);
> diff --git a/monitor/monitor-internal.h b/monitor/monitor-internal.h
> index caa2e90ef22a4..69425a7bc8152 100644
> --- a/monitor/monitor-internal.h
> +++ b/monitor/monitor-internal.h
> @@ -136,6 +136,7 @@ typedef struct {
> Monitor common;
> JSONMessageParser parser;
> bool pretty;
> +bool timestamp;
> /*
> * When a client connects, we're in capabilities negotiation mode.
> * @commands is _cap_negotiation_commands then. When command
> diff --git a/monitor/monitor.c b/monitor/monitor.c
> index 86949024f643a..85a0b6498dbc1 100644
> --- a/monitor/monitor.c
> +++ b/monitor/monitor.c
> @@ -726,7 +726,7 @@ int monitor_init(MonitorOptions *opts, bool allow_hmp,
> Error **errp)
>
> switch (opts->mode) {
> case MONITOR_MODE_CONTROL:
> -monitor_init_qmp(chr, opts->pretty, _err);
> +monitor_init_qmp(chr, opts->pretty, opts->timestamp, _err);
> break;
> case MONITOR_MODE_READLINE:
> if (!allow_hmp) {
> @@ -737,6 +737,10 @@ int monitor_init(MonitorOptions *opts, bool allow_hmp,
> Error **errp)
>
Re: [patch v0] qapi/qmp: Add timestamps to qmp command responses.
On 9/26/22 12:59, Denis Plotnikov wrote:
Add "start" & "end" timestamps to qmp command responses.
It's disabled by default, but can be enabled with 'timestamp=on'
monitor's parameter, e.g.:
-chardev socket,id=mon1,path=/tmp/qmp.socket,server=on,wait=off
-mon chardev=mon1,mode=control,timestamp=on
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.
These times may be helpful for the management layer in understanding of
the actual timeline of a qmp command processing.
Suggested-by: Andrey Ryabinin
Signed-off-by: Denis Plotnikov
Reviewed-by: Vladimir Sementsov-Ogievskiy
---
include/monitor/monitor.h | 2 +-
include/qapi/qmp/dispatch.h | 2 +-
monitor/monitor-internal.h | 1 +
monitor/monitor.c | 9 -
monitor/qmp.c | 5 +++--
qapi/control.json | 3 +++
qapi/qmp-dispatch.c | 28 +++-
[..]
QDict *qmp_dispatch(const QmpCommandList *cmds, QObject *request,
-bool allow_oob, Monitor *cur_mon)
+bool allow_oob, bool timestamp, Monitor *cur_mon)
{
Error *err = NULL;
bool oob;
@@ -146,6 +162,11 @@ QDict *qmp_dispatch(const QmpCommandList *cmds, QObject
*request,
QObject *id;
QObject *ret = NULL;
QDict *rsp = NULL;
+uint64_t ts_start = -1;
+
+if (timestamp) {
+ts_start = g_get_real_time();
+}
Maybe, better start timing in handle_qmp_command(), to inlude waiting in the
mon->qmp_requests queue.
dict = qobject_to(QDict, request);
if (!dict) {
@@ -270,5 +291,10 @@ out:
qdict_put_obj(rsp, "id", qobject_ref(id));
}
+if (timestamp) {
+uint64_t ts_end = g_get_real_time();
+add_timestamps(rsp, ts_start, ts_end);
+}
+
return rsp;
}
--
Best regards,
Vladimir
