| Message ID | 20220926095940.283094-1-den-plotnikov@yandex-team.ru |
|---|---|
| State | New |
| Headers | show |
| Series | [v0] qapi/qmp: Add timestamps to qmp command responses. | expand |
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 <arbn@yandex-team.ru> > Signed-off-by: Denis Plotnikov <den-plotnikov@yandex-team.ru> Reviewed-by: Vladimir Sementsov-Ogievskiy <vsementsov@yandex-team.ru> > --- > 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; > }
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 <arbn@yandex-team.ru> > Signed-off-by: Denis Plotnikov <den-plotnikov@yandex-team.ru> > --- > 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 &qmp_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, &local_err); > + monitor_init_qmp(chr, opts->pretty, opts->timestamp, &local_err); > break; > case MONITOR_MODE_READLINE: > if (!allow_hmp) { > @@ -737,6 +737,10 @@ int monitor_init(MonitorOptions *opts, bool allow_hmp, Error **errp) > error_setg(errp, "'pretty' is not compatible with HMP monitors"); > return -1; > } > + if (opts->timestamp) { > + error_setg(errp, "'timestamp' is not compatible with HMP monitors"); > + return -1; > + } > monitor_init_hmp(chr, true, &local_err); > break; > default: > @@ -782,6 +786,9 @@ QemuOptsList qemu_mon_opts = { > },{ > .name = "pretty", > .type = QEMU_OPT_BOOL, > + },{ > + .name = "timestamp", > + .type = QEMU_OPT_BOOL, > }, > { /* end of list */ } > }, > diff --git a/monitor/qmp.c b/monitor/qmp.c > index 092c527b6fc9c..fd487fee9f850 100644 > --- a/monitor/qmp.c > +++ b/monitor/qmp.c > @@ -142,7 +142,7 @@ static void monitor_qmp_dispatch(MonitorQMP *mon, QObject *req) > QDict *error; > > rsp = qmp_dispatch(mon->commands, req, qmp_oob_enabled(mon), > - &mon->common); > + mon->timestamp, &mon->common); > > if (mon->commands == &qmp_cap_negotiation_commands) { > error = qdict_get_qdict(rsp, "error"); > @@ -495,7 +495,7 @@ static void monitor_qmp_setup_handlers_bh(void *opaque) > monitor_list_append(&mon->common); > } > > -void monitor_init_qmp(Chardev *chr, bool pretty, Error **errp) > +void monitor_init_qmp(Chardev *chr, bool pretty, bool timestamp, Error **errp) > { > MonitorQMP *mon = g_new0(MonitorQMP, 1); > > @@ -510,6 +510,7 @@ void monitor_init_qmp(Chardev *chr, bool pretty, Error **errp) > qemu_chr_has_feature(chr, QEMU_CHAR_FEATURE_GCONTEXT)); > > mon->pretty = pretty; > + mon->timestamp = timestamp; > > qemu_mutex_init(&mon->qmp_queue_lock); > mon->qmp_requests = g_queue_new(); > diff --git a/qapi/control.json b/qapi/control.json > index afca2043af2fd..f4a4aef4be7f0 100644 > --- a/qapi/control.json > +++ b/qapi/control.json > @@ -199,6 +199,8 @@ > # > # @pretty: Enables pretty printing (QMP only) > # > +# @timestamp: Enables qmp command start and end timestamps printing (QMP only) > +# > # @chardev: Name of a character device to expose the monitor on > # > # Since: 5.0 > @@ -208,5 +210,6 @@ > '*id': 'str', > '*mode': 'MonitorMode', > '*pretty': 'bool', > + '*timestamp': 'bool', > 'chardev': 'str' > } } > diff --git a/qapi/qmp-dispatch.c b/qapi/qmp-dispatch.c > index 0990873ec8ec1..79885db7417ac 100644 > --- a/qapi/qmp-dispatch.c > +++ b/qapi/qmp-dispatch.c > @@ -110,6 +110,22 @@ bool qmp_is_oob(const QDict *dict) > && !qdict_haskey(dict, "execute"); > } > > +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)); > +} > + > typedef struct QmpDispatchBH { > const QmpCommand *cmd; > Monitor *cur_mon; > @@ -135,7 +151,7 @@ static void do_qmp_dispatch_bh(void *opaque) > * context for everything else. > */ > 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(); > + } > > 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; > } > diff --git a/qga/main.c b/qga/main.c > index 5a9d8252e0755..c6650e4d69ffd 100644 > --- a/qga/main.c > +++ b/qga/main.c > @@ -573,7 +573,7 @@ static void process_event(void *opaque, QObject *obj, Error *err) > } > > g_debug("processing command"); > - rsp = qmp_dispatch(&ga_commands, obj, false, NULL); > + rsp = qmp_dispatch(&ga_commands, obj, false, false, NULL); > > end: > ret = send_response(s, rsp); > diff --git a/stubs/monitor-core.c b/stubs/monitor-core.c > index afa477aae656a..dcd9643da7f4c 100644 > --- a/stubs/monitor-core.c > +++ b/stubs/monitor-core.c > @@ -12,7 +12,7 @@ Monitor *monitor_set_cur(Coroutine *co, Monitor *mon) > return NULL; > } > > -void monitor_init_qmp(Chardev *chr, bool pretty, Error **errp) > +void monitor_init_qmp(Chardev *chr, bool pretty, bool timestamp, Error **errp) > { > } > > diff --git a/tests/unit/test-qmp-cmds.c b/tests/unit/test-qmp-cmds.c > index 6085c099950b5..778146ec96c18 100644 > --- a/tests/unit/test-qmp-cmds.c > +++ b/tests/unit/test-qmp-cmds.c > @@ -150,7 +150,7 @@ static QObject *do_qmp_dispatch(bool allow_oob, const char *template, ...) > req = qdict_from_vjsonf_nofail(template, ap); > va_end(ap); > > - resp = qmp_dispatch(&qmp_commands, QOBJECT(req), allow_oob, NULL); > + resp = qmp_dispatch(&qmp_commands, QOBJECT(req), allow_oob, false, NULL); > g_assert(resp); > ret = qdict_get(resp, "return"); > g_assert(ret); > @@ -173,7 +173,7 @@ static void do_qmp_dispatch_error(bool allow_oob, ErrorClass cls, > req = qdict_from_vjsonf_nofail(template, ap); > va_end(ap); > > - resp = qmp_dispatch(&qmp_commands, QOBJECT(req), allow_oob, NULL); > + resp = qmp_dispatch(&qmp_commands, QOBJECT(req), allow_oob, false, NULL); > g_assert(resp); > error = qdict_get_qdict(resp, "error"); > g_assert(error); > @@ -229,7 +229,7 @@ static void test_dispatch_cmd_success_response(void) > QDict *resp; > > qdict_put_str(req, "execute", "cmd-success-response"); > - resp = qmp_dispatch(&qmp_commands, QOBJECT(req), false, NULL); > + resp = qmp_dispatch(&qmp_commands, QOBJECT(req), false, false, NULL); > g_assert_null(resp); > qobject_unref(req); > } > -- > 2.25.1 > > With regards, Daniel
Daniel P. Berrangé <berrange@redhat.com> 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/1000000' | 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 <arbn@yandex-team.ru> >> Signed-off-by: Denis Plotnikov <den-plotnikov@yandex-team.ru>
On 27.09.2022 09:04, Markus Armbruster wrote: > Daniel P. Berrangé <berrange@redhat.com> 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/1000000' | 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 <arbn@yandex-team.ru> >>> Signed-off-by: Denis Plotnikov <den-plotnikov@yandex-team.ru>
On Tue, Sep 27, 2022 at 08:04:11AM +0200, Markus Armbruster wrote: > Daniel P. Berrangé <berrange@redhat.com> 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.
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é <berrange@redhat.com> 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
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 &qmp_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, &local_err); + monitor_init_qmp(chr, opts->pretty, opts->timestamp, &local_err); break; case MONITOR_MODE_READLINE: if (!allow_hmp) { @@ -737,6 +737,10 @@ int monitor_init(MonitorOptions *opts, bool allow_hmp, Error **errp) error_setg(errp, "'pretty' is not compatible with HMP monitors"); return -1; } + if (opts->timestamp) { + error_setg(errp, "'timestamp' is not compatible with HMP monitors"); + return -1; + } monitor_init_hmp(chr, true, &local_err); break; default: @@ -782,6 +786,9 @@ QemuOptsList qemu_mon_opts = { },{ .name = "pretty", .type = QEMU_OPT_BOOL, + },{ + .name = "timestamp", + .type = QEMU_OPT_BOOL, }, { /* end of list */ } }, diff --git a/monitor/qmp.c b/monitor/qmp.c index 092c527b6fc9c..fd487fee9f850 100644 --- a/monitor/qmp.c +++ b/monitor/qmp.c @@ -142,7 +142,7 @@ static void monitor_qmp_dispatch(MonitorQMP *mon, QObject *req) QDict *error; rsp = qmp_dispatch(mon->commands, req, qmp_oob_enabled(mon), - &mon->common); + mon->timestamp, &mon->common); if (mon->commands == &qmp_cap_negotiation_commands) { error = qdict_get_qdict(rsp, "error"); @@ -495,7 +495,7 @@ static void monitor_qmp_setup_handlers_bh(void *opaque) monitor_list_append(&mon->common); } -void monitor_init_qmp(Chardev *chr, bool pretty, Error **errp) +void monitor_init_qmp(Chardev *chr, bool pretty, bool timestamp, Error **errp) { MonitorQMP *mon = g_new0(MonitorQMP, 1); @@ -510,6 +510,7 @@ void monitor_init_qmp(Chardev *chr, bool pretty, Error **errp) qemu_chr_has_feature(chr, QEMU_CHAR_FEATURE_GCONTEXT)); mon->pretty = pretty; + mon->timestamp = timestamp; qemu_mutex_init(&mon->qmp_queue_lock); mon->qmp_requests = g_queue_new(); diff --git a/qapi/control.json b/qapi/control.json index afca2043af2fd..f4a4aef4be7f0 100644 --- a/qapi/control.json +++ b/qapi/control.json @@ -199,6 +199,8 @@ # # @pretty: Enables pretty printing (QMP only) # +# @timestamp: Enables qmp command start and end timestamps printing (QMP only) +# # @chardev: Name of a character device to expose the monitor on # # Since: 5.0 @@ -208,5 +210,6 @@ '*id': 'str', '*mode': 'MonitorMode', '*pretty': 'bool', + '*timestamp': 'bool', 'chardev': 'str' } } diff --git a/qapi/qmp-dispatch.c b/qapi/qmp-dispatch.c index 0990873ec8ec1..79885db7417ac 100644 --- a/qapi/qmp-dispatch.c +++ b/qapi/qmp-dispatch.c @@ -110,6 +110,22 @@ bool qmp_is_oob(const QDict *dict) && !qdict_haskey(dict, "execute"); } +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)); +} + typedef struct QmpDispatchBH { const QmpCommand *cmd; Monitor *cur_mon; @@ -135,7 +151,7 @@ static void do_qmp_dispatch_bh(void *opaque) * context for everything else. */ 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(); + } 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; } diff --git a/qga/main.c b/qga/main.c index 5a9d8252e0755..c6650e4d69ffd 100644 --- a/qga/main.c +++ b/qga/main.c @@ -573,7 +573,7 @@ static void process_event(void *opaque, QObject *obj, Error *err) } g_debug("processing command"); - rsp = qmp_dispatch(&ga_commands, obj, false, NULL); + rsp = qmp_dispatch(&ga_commands, obj, false, false, NULL); end: ret = send_response(s, rsp); diff --git a/stubs/monitor-core.c b/stubs/monitor-core.c index afa477aae656a..dcd9643da7f4c 100644 --- a/stubs/monitor-core.c +++ b/stubs/monitor-core.c @@ -12,7 +12,7 @@ Monitor *monitor_set_cur(Coroutine *co, Monitor *mon) return NULL; } -void monitor_init_qmp(Chardev *chr, bool pretty, Error **errp) +void monitor_init_qmp(Chardev *chr, bool pretty, bool timestamp, Error **errp) { } diff --git a/tests/unit/test-qmp-cmds.c b/tests/unit/test-qmp-cmds.c index 6085c099950b5..778146ec96c18 100644 --- a/tests/unit/test-qmp-cmds.c +++ b/tests/unit/test-qmp-cmds.c @@ -150,7 +150,7 @@ static QObject *do_qmp_dispatch(bool allow_oob, const char *template, ...) req = qdict_from_vjsonf_nofail(template, ap); va_end(ap); - resp = qmp_dispatch(&qmp_commands, QOBJECT(req), allow_oob, NULL); + resp = qmp_dispatch(&qmp_commands, QOBJECT(req), allow_oob, false, NULL); g_assert(resp); ret = qdict_get(resp, "return"); g_assert(ret); @@ -173,7 +173,7 @@ static void do_qmp_dispatch_error(bool allow_oob, ErrorClass cls, req = qdict_from_vjsonf_nofail(template, ap); va_end(ap); - resp = qmp_dispatch(&qmp_commands, QOBJECT(req), allow_oob, NULL); + resp = qmp_dispatch(&qmp_commands, QOBJECT(req), allow_oob, false, NULL); g_assert(resp); error = qdict_get_qdict(resp, "error"); g_assert(error); @@ -229,7 +229,7 @@ static void test_dispatch_cmd_success_response(void) QDict *resp; qdict_put_str(req, "execute", "cmd-success-response"); - resp = qmp_dispatch(&qmp_commands, QOBJECT(req), false, NULL); + resp = qmp_dispatch(&qmp_commands, QOBJECT(req), false, false, NULL); g_assert_null(resp); qobject_unref(req); }
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 <arbn@yandex-team.ru> Signed-off-by: Denis Plotnikov <den-plotnikov@yandex-team.ru> --- 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(-)