Re: [PATCH v2] qapi/qmp: Add timestamps to qmp command responses
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
> Signed-off-by: Denis Plotnikov
> ---
> 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();
> +
Re: [PATCH v2] qapi/qmp: Add timestamps to qmp command responses
On Tue, Oct 11, 2022 at 05:45:09PM +0300, Denis Plotnikov 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
> Signed-off-by: Denis Plotnikov
> ---
> 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(-)
Reviewed-by: Daniel P. Berrangé
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 :|
[PATCH v2] qapi/qmp: Add timestamps to qmp command responses
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
Signed-off-by: Denis Plotnikov
---
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 %
