On 14.10.2022 16:19, Daniel P. Berrangé wrote:
On Fri, Oct 14, 2022 at 02:57:06PM +0200, Markus Armbruster wrote:
Daniel P. Berrangé <berra...@redhat.com> writes:
On Fri, Oct 14, 2022 at 11:31:13AM +0200, Markus Armbruster wrote:
Daniel P. Berrangé <berra...@redhat.com> writes:
On Thu, Oct 13, 2022 at 05:00:26PM +0200, Markus Armbruster wrote:
Denis Plotnikov <den-plotni...@yandex-team.ru> writes:
Add "start" & "end" time values to qmp command responses.
Please spell it QMP. More of the same below.
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.
I'm still having difficulties seeing the value add over existing
tracepoints and logging.
Can you tell me about a problem you cracked (or could have cracked) with
the help of this?
Consider your QMP client is logging all commands and replies in its
own logfile (libvirt can do this). Having this start/end timestamps
included means the QMP client log is self contained.
A QMP client can include client-side timestamps in its log. What value
is being added by server-side timestamps? According to the commit
message, it's for getting "the exact command execution time without any
other time variance which might be brought by other parts of management
layer or qemu internals." Why is that useful? In particular, why is
excluding network and QEMU queueing delays (inbound and outbound)
useful?
Lets, say some commands normally runs in ~100ms, but occasionally
runs in 2secs, and you want to understand why.
A first step is understanding whether a given command itself is
slow at executing, or whether its execution has merely been
delayed because some other aspect of QEMU has delayed its execution.
If the server timestamps show it was very fast, then that indicates
delayed processing. Thus instead of debugging the slow command, I
can think about what scenarios would be responsible for the delay.
Perhaps a previous QMP command was very slow, or maybe there is
simply a large volume of QMP commands backlogged, or some part of
QEMU got blocked.
Another case would be a command that is normally fast, and sometimes
is slower, but still relatively fast. The network and queueing side
might be a significant enough proportion of the total time to obscure
the slowdown. If you can eliminate the non-execution time, you can
see the performance trends over time to spot the subtle slowdowns
and detect abnormal behaviour before it becomes too terrible.
This is troubleshooting. Asking for better troubleshooting tools is
fair.
However, the proposed timestamps provide much more limited insight than
existing tracepoints. For instance, enabling
tracepoints are absolutely great and let you get a hell of alot
more information, *provided* you are in a position to actually
use tracepoints. This is, unfortunately, frequently not the case
when supporting real world production deployments.
Exactly!!! Thanks for the pointing out!
Bug reports from customers typically include little more than a
log file they got from the mgmt client at time the problem happened.
The problem experianced may no longer exist, so asking them to run
a tracepoint script is not possible. They may also be reluctant to
actually run tracepoint scripts on a production system, or simply
lack the ability todo so at all, due to constraints of the deployment
environment. Logs from libvirt are something that are collected by
default for many mgmt apps, or can be turned on by the user with
minimal risk of disruption.
Overall, there's a compelling desire to be proactive in collecting
information ahead of time, that might be useful in diagnosing
future bug reports.
This is the main reason. When you encounter a problem one of the first
questions is "Was there something similar in the past. Another question
is how often does it happen.
With the timestamps these questions answering becomes easier.
Another thing is that with the qmp command timestamps you can build a
monitoring system which will report about the cases when
execution_time_from_mgmt_perspective - excution_time_qmp_command >
some_threshold which in turn proactively tell you about the potential
problems. And then you'll start using the qmp tracepoints (and other
means) to figure out the real reason of the execution time variance.
Thanks, Denis
So it isn't an 'either / or' decision of QMP reply logs vs use of
tracepoints, both are beneficial, with their own pros/cons.
With regards,
Daniel
