Re: [patch v0] qapi/qmp: Add timestamps to qmp command responses.

[Daniel P . Berrangé]

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
-- 
|: 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 :|