On 27.09.2022 09:04, Markus Armbruster wrote:
Daniel P. Berrangé <berra...@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 <a...@yandex-team.ru>
Signed-off-by: Denis Plotnikov <den-plotni...@yandex-team.ru>
