[Spice-devel] [PATCH spice-common 0/4] RFC: add structured logging and log category
Christophe de Dinechin
cdupontd at redhat.com
Wed Jun 14 08:44:49 UTC 2017
> On 13 Jun 2017, at 12:17, Marc-André Lureau <marcandre.lureau at redhat.com> wrote:
>
>> - Better memory locality (not wasting a whole cache line for a single flag)
>
> minor, because log is not for hot traces.
My experience differs from yours, and as a result, the idea that “log is not for hot traces" seems particularly wrong to me. In a real-time system, if your logging system cannot properly instrument the hot paths, then your logging system is at fault, not the idea of instrumenting the hot paths, and even less the idea of designing a mechanism capable of efficiently instrumenting hot paths.
Since Spice is a real-time system, it would have expected (and I really want, sooner better than later):
a) a logging system that knows how to record stuff and print it out efficiently.
b) a tracing system that lets me view selected things as they happen, including in hot paths
c) a flight-recorder recording information continuously and dumping useful data after specific events, e.g. crash, signal, assert, etc.
d) performance probes, to continuously measure key things and report them
e) a tuning / tweaking system, to adjust internal parameters, ideally on a running system, and observe the effect
As far as I can tell, only (a) logging exists today. Why don’t we have the rest? And why is there such a strong push-back from you when I suggest we add it?
If you really believe this is useless, then I have to disagree with you. To support my opinion for each category above:
a) Being able to improve logging is obviously a hot topic, meaning the current state is not considered satisfactory.
b) commented-out calls to spice_msg_in_hexdump. Ask yourself, why is this code commented out?
c) Bugs which we have to be able to reproduce, because there is no useful information in the debug log, e.g. https://bugzilla.redhat.com/show_bug.cgi?id=1017261. Here, we know an assertion failed, but nothing about what happened to get there, so you can only guess and try to reproduce. Reported in 2013, not solved, and probably not much progress made since then.
d) Performance bugs, e.g. https://beta-bugzilla.redhat.com/show_bug.cgi?id=1363940#c1 states “please provide supporting data”, but there is no easy way for the customer to collect objective data
e) Frediano having to commit code adding a magic 2000 in the server to “try to reduce lag”, see https://cgit.freedesktop.org/~fziglio/spice-server/commit/?h=nvidia&id=855849d7a2b8e1968a14dcce3dd84d05f25bc702.
All these examples (only a sample, I can easily find dozen more) show that the need for the tools I am talking about exist.
>
> This argument is probably only valid if you have a mix of categories in a very tiny context. If you switch to a single category, there shouldn't be much performance difference locally and globally.
Actually, this argument is valid for any mechanism designed to also instrument hot paths. The first level cache is a very precious commodity. Say we have 50 categories in the normal run path. With your approche, we use 50 unrelated cache lines with nothing else of interest in them (the name and description of the category being largely uninteresting at run time). With mine, it’s one cache line, with the first category test priming the cache for subsequent category tests, ensuring they don’t stall.
Let’s design a tracing selection mechanism that can instrument hot paths at minimal cost, rather than rationalize why we don’t need to instrument hot paths.
Less important comments below, with a preliminary note that I don’t feel personal preferences such as “minor” are very compelling when trying to discuss objective pros and cons.
>
> ----- Original Message -----
>> Global declarations pros:
>> - Obeys the DRY principle, as opposed to WET category declarations
>> (e.g. SPICE_LOG_CATEGORY_DECLARE vs. SPICE_LOG_CATEGORY)
>
> True, but SPICE_LOG_CATEGORY_DECLARE should not be needed, I'd rather remove it.
But then, a category can't be used in a header, that’s an even worse limitation. See ‘rect’ category case.
>> - Makes it possible to organize categories logically, e.g. for help output
>
> Alphabetical order should be enough if categories are correctly named. I can change that easily.
Then I can’t select order foo_read, foo_write, foo_test. Or rename categories.
>
>> - Easier to find what categories already exists (no need to grep all source)
>
> minor, and you can use SPICE_DEBUG=help.
Building the code is more complicated than grep’ing the sources, and may not be possible at the times I want to check (e.g. I’m in the middle of writing code, it does not even build)
>
>> - Category changes impact a single file, easier for history or merge
>
> Or not, if for example splitting a project in subprojects (like libcacard in qemu etc)
When splitting projects, which remains quite infrequent, both projects can inherit all categories as a starting point anyway.
>
>> - Categories shared between client and server, easier e.g. for remote
>> activation
>
> Good category naming solves the sharing aspect.
Not really, I was talking about the protocol for sending trace activation data over the wire.
I guess in your approach, with appropriate code to send debug categories by name, and parsing them on the other side, this could be something like:
SPICE_DEBUG=client_category SPICE_SERVER_DEBUG=server_category spicy …
A bit convoluted, and probably more code, but I think this can be done and could be usable.
>
>> - Category errors (duplicate, missing) detected early by compiler, rather
>> than linker
>
> minor
On a daily basis, this one will matter. Getting errors faster, with more precise file / line locations, etc.
>
>> - Does not require glib at all, so would work e.g. in Windows driver
>
> drivers have different means to log/trace.
Is that a good thing? Facilities can be designed to work the same way in kernel and user space, and when they are, it’s better.
>
>> - Whole state represented as a single C struct, easy to save/restore, print
>> in debugger, etc
>
> Well, you are usually interested by a specific value,
I dont’ know who “you” is here, but that’s not me. Example: showing available categories and their values in debugger is ‘p spice_traces’ in my approach.
> so it's also a bad idea to put everything together.
I explained above why it matters for performance. But it also means you can for example have a function designed to run something from a debugger that looks like:
void run_something_with_specific_traces()
{
struct spice_traces saved = spice_traces;
spice_traces = debugger_spice_traces;
run_something();
spice_traces = saved;
}
Christophe
>
>>>
>>> Talking about common things it seems we quite agree to not using
>>> multiple domains calling GLib but just use "Spice". Maybe we can
>>> code this as a preparation change before these changes.
>>>
>>>>
>>>> From: Marc-André Lureau <marcandre.lureau at redhat.com>
>>>>
>>>> Hi,
>>>>
>>>> This is a RFC series to clean-up Spice logging infrastructure to fully
>>>> rely on glib g_log & g_log_structured if available, and add logging
>>>> categories. It is thus a counter-proposal to Christophe D. "RFC:
>>>> Lightweight tracing mechanism", with which it shares the category
>>>> selection/listing feature.
>>>>
>>>> It is useful to be able to filter the logging by domains, but GLib
>>>> only provides domain selection with G_MESSAGES_DEBUG, and it's
>>>> recommended to have few domains per application/library. Also, domain
>>>> filtering code in glib isn't very efficient, and can't be listed
>>>> easily.
>>>>
>>>> A common solution to this problem is to add some form of "sub-domain"
>>>> or "categories" on top of glib (see for ex gtkdebug.h). I propose a
>>>> simple way to register such log categories, to list and selectively
>>>> enable them with the SPICE_DEBUG= environment variable, as well as
>>>> related convenience macros.
>>>>
>>>> Comments welcome,
>>>>
>>>> Marc-André Lureau (4):
>>>> log: replace spice log with glib
>>>> Replace spice_* logging with g_*
>>>> RFC: Add spice log categories
>>>> Add 'common_ssl' Spice log
>>>>
>>>> common/canvas_base.c | 148 ++++++++++-----------
>>>> common/canvas_utils.c | 18 +--
>>>> common/gdi_canvas.c | 82 ++++++------
>>>> common/log.c | 208 +++++++----------------------
>>>> common/log.h | 175 ++++++++++++++----------
>>>> common/lz.c | 22 +--
>>>> common/lz_decompress_tmpl.c | 18 +--
>>>> common/marshaller.c | 2 +-
>>>> common/mem.c | 2 +-
>>>> common/pixman_utils.c | 156 +++++++++++-----------
>>>> common/quic.c | 88 ++++++------
>>>> common/quic_family_tmpl.c | 6 +-
>>>> common/quic_rgb_tmpl.c | 32 ++---
>>>> common/quic_tmpl.c | 32 ++---
>>>> common/rect.h | 2 +-
>>>> common/region.c | 2 +-
>>>> common/ring.h | 26 ++--
>>>> common/rop3.c | 10 +-
>>>> common/snd_codec.c | 18 +--
>>>> common/ssl_verify.c | 74 ++++++-----
>>>> common/sw_canvas.c | 20 +--
>>>> tests/test-logging.c | 317
>>>> +-------------------------------------------
>>>> 22 files changed, 544 insertions(+), 914 deletions(-)
>>>>
>>>
>>> Frediano
>>> _______________________________________________
>>> Spice-devel mailing list
>>> Spice-devel at lists.freedesktop.org
>>> <mailto:Spice-devel at lists.freedesktop.org>
>>> https://lists.freedesktop.org/mailman/listinfo/spice-devel
>>> <https://lists.freedesktop.org/mailman/listinfo/spice-devel>
>>
> _______________________________________________
> Spice-devel mailing list
> Spice-devel at lists.freedesktop.org
> https://lists.freedesktop.org/mailman/listinfo/spice-devel
More information about the Spice-devel
mailing list