Bug 1749634

Just to document.

At a later stage, after confirming the above does not create too much noise and is being used by CEE we could continue adding other filters, i.e.:
~~~
log_filters="1:libvirt 1:qemu 1:conf 1:security 3:event 3:json 3:file 3:object 1:util"
~~~

What you request, basically, is a revert of bug 1125237 and https://gerrit.ovirt.org/#/c/31135/4/lib/vdsm/tool/configurators/libvirt.py

It could improve debugging, but harms performance, and often creates more spam than usefulness.

(In reply to Dan Kenigsberg from comment #2)
> What you request, basically, is a revert of bug 1125237 and
> https://gerrit.ovirt.org/#/c/31135/4/lib/vdsm/tool/configurators/libvirt.py
> 
> It could improve debugging, but harms performance, and often creates more
> spam than usefulness.

Dan, yes.
We never liked this change in the support and over years it was proven that we miss root causes or some bugs due to no logging available, which is sad, time consuming etc.

I am wondering if there are other performance improvements have happened in the product since that "feature" was implemented (3.5) and maybe it is not an issue anymore. I didn't read all the comments on it, but was it actually proven that it performance decreases due to libvirt logging or due to some other factors, that logging contributes? Maybe this can be tunable? Maybe we can add a recommendation for disk space to accommodate the extra logging? And to add a recommendation to disable the logging, if looking for performance increase.

Daniel, can you please suggest if there are any other optimizations can be done on the logging filters to reduce unnecessary logs to minimal?

Debug logging inherently has an impact on performance that is directly related to the amount of logging emitted. There will be some CPU time hit for formatting the log messages, and more importantly some time required to write the logs to disk which is probably the bigger impact. The latter will vary depending on use of rotating rust disk vs SSDs.

If DanK says this was an unacceptable performance penalty when previously tried, then there's nothing I can really suggest to magically solve that.

The only thing in our favour these days is that libvirt added the 'virt-admin' command line tool. This allows administrators to turn on/off debug logging in libvirt *without* having to restart libvirtd. Thus if ship with *no* logging enabled by default, it is not quite so disruptive to ask customers to turn it on again now.

(In reply to Dan Kenigsberg from comment #2)
> What you request, basically, is a revert of bug 1125237 and
> https://gerrit.ovirt.org/#/c/31135/4/lib/vdsm/tool/configurators/libvirt.py
> 
> It could improve debugging, but harms performance, and often creates more
> spam than usefulness.

If you look closely, the requested filter at this moment is very different from what was there before.

Requested:
~~~
log_filters="1:qemu"
~~~

Previous BZ1125237:
~~~
3:virobject 3:virfile 2:virnetlink  3:cgroup 3:event 3:json 1:libvirt 1:util 1:qemu
~~~

The requested one is a lot quieter. The one above will indeed generate a lot of noise.

(In reply to Daniel Berrangé from comment #5)
> The only thing in our favour these days is that libvirt added the
> 'virt-admin' command line tool. This allows administrators to turn on/off
> debug logging in libvirt *without* having to restart libvirtd. Thus if ship
> with *no* logging enabled by default, it is not quite so disruptive to ask
> customers to turn it on again now.

Yes, we use this a lot. However, not every problem is easily reproducible, there are a few bugs around stuck due to lack of logs and we don't know how to reproduce.

Logging a bit can be useful, even if it does not capture the problem, it can help with having an idea of what was happening and give some problem reproduction ideas to attempt, so we can raise better bugzillas for you.

Therefore the suggestion to start again with something small, that we know captures useful information, and go from there as we need.

Meital, 
Can your team please help testing and see how the performance is impacted with those changes?

The documentation text flag should only be set after 'doc text' field is provided. Please provide the documentation text and set the flag to '?' again.

> If you look closely, the requested filter at this moment is very different from what was there before.

all right, Germano.

I should explicitly support adding plenty of logs for rhv-4.4-on-el8. libvirt, qemu and kernel surprises are expected.
Backporting to 4.3.z requires testing that we do not kill our ability to "eat monster VMs for breakfast", as you requested.

(In reply to Dan Kenigsberg from comment #9)
> I should explicitly support adding plenty of logs for rhv-4.4-on-el8.
> libvirt, qemu and kernel surprises are expected.

Are you suggesting it might be a good idea to add even more logging at the lower layers?

> Backporting to 4.3.z requires testing that we do not kill our ability to
> "eat monster VMs for breakfast", as you requested.

I'm fine if you decide to not 4.3.z this. I would be happy if its in 4.4.

Also, by 4.4 we should also have reduced the noise generated by VDSM, 
so the net result is 0 or even negative. So far I've opened:
https://bugzilla.redhat.com/show_bug.cgi?id=1720977
https://bugzilla.redhat.com/show_bug.cgi?id=1751520
https://bugzilla.redhat.com/show_bug.cgi?id=1720975
https://bugzilla.redhat.com/show_bug.cgi?id=1720976

But there are more things to trim, I'm sure.

Patch with log_filters="1:qemu" posted. I can see it already generates quite a lot of output. Germano, are debug messages really useful or would it suffice to have info messages?

(In reply to Milan Zamazal from comment #11)
> Patch with log_filters="1:qemu" posted. I can see it already generates quite
> a lot of output. Germano, are debug messages really useful or would it
> suffice to have info messages?

Hi Milan,

I'm afraid debug is the most useful, as it gets the QMP interactions. 
This was chosen as a good starting point after RHOSP folks working with libvirt developers.

1:qemu has been in place on RHOSP for some time now, on several versions. I'm not aware of them having excessive logging problems.
Do you have numbers in relation to the impact (i.e. compared to VDSM)?

Thanks

Hi Germano,

I can see a single quietly running VM generates about 3,5 MB of libvirt logs in half an hour on my host. This is about 170 MB per day-VM. Most of the log lines are guest agent related but there is also VM storage monitoring etc. VMs without a guest agent would probably produce significantly less amount of log data.

Vdsm with DEBUG enabled produces about the same amount of logs during the same time span, but most of it seems to be unrelated to a particular VM (storage checks on the host etc.), so with more VMs it wouldn't grow that much.

These are of course just very rough numbers and no serious measurement, to get some basic idea. If it is OK for you then we can merge the patch.

Hi Milan,

Now I see your concern.

That sounds excessive and different to what we tested last year.
Please hold the patch, I'll test it here, maybe something changed and we need to tweak it a bit more before having this by default in RHV.

Keeping the needinfo on me.

Hi Milan,

There is indeed a ton of [not useful] logs in qemu monitor due to VDSM IoTune calls, which end up as query-named-block-nodes/query-blockstats in qemu monitor, every 15 seconds.

I'm not sure if there is a recent change in qemu that could be producing more logs than last year when we raised this, but it does not seem safe to enable 1:qemu for now in RHV.
So thank you very much for raising the concern. I also tried with 3:qemu, but it does not change much as the offending log is INFO level.

The snapshot argument for this change has somewhat dimished since then. I think we can close this BZ without merging for now, and I'll investigate other options and
perhaps open a BZ against qemu to be able to filter out those 2. After that we can merge the patch.

I assume RHOSP is not doing the same detailed monitoring, which explains why its not a problem for them.

Thanks,

Hi Germano,

thank you for clarification. I also think that discussing logging changes with QEMU is the best thing to do now and that we can close this bug.