[Spice-devel] [PATCH spice-common 0/4] RFC: add structured logging and log category

Thu Jun 15 04:23:26 UTC 2017

> On 14 Jun 2017, at 19:53, Marc-André Lureau <marcandre.lureau at redhat.com> wrote:
> 
> Hi
> 
> ----- Original Message -----
>>>> 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.
>>> 
>>> We can switch to Marc-André's suggestion, or we can switch to yours,
>>> none of them will help us to solve this bug ;)
>>> More/better logs is what _may_ help, which we could even have with the
>>> current logging system..
>> 
>> In the message above, part c) is having a flight recorder that, AFTER we
>> crash, dumps something that was recorded BEFORE the crash. Below is an
>> example output from my current experimental branch
>> (https://github.com/c3d/spice-gtk/compare/master...c3d:recorder). What I did
>> is send a SIGBUS to the process with killall while it was running (please
>> check if you can figure that out from the dump :-), but of course the same
>> thing would happen with a real crash.
>> 
>> The key point I was making with my example for (c) is is that if we had this
>> amount of information in case of crash, in many cases we would not need to
>> re-do a run with some debug option, or reproduce the problem. The
>> information would already be right there. And I would like you to compare
>> the amount of available information available today (the lines beginning
>> with (spicy:78043) with the amount of information the recorder dump gives me
>> (the rest).
> 
> (fwiw, I prefer the shorter version…)

Remember that the dump only shows up in case of crash.

Are you arguing problems are easier to debug with less data?

> 
>> 
>> ddd at ptitpuce[recorder] spice-gtk> spicy  -h turbo -p 5901
>> 
>> (process:78043): Gtk-WARNING **: Locale not supported by C library.
>> 	Using the fallback 'C' locale.
>> 2017-06-14 18:57:01.165 spicy[78043:24824016] *** WARNING: Method
>> userSpaceScaleFactor in class NSView is deprecated on 10.7 and later. It
>> should not be used in new applications. Use convertRectToBacking: instead.
>> ** Message: main channel: opened
>> 
>> (spicy:78043): GSpice-CRITICAL **: spice_playback_channel_set_delay:
>> assertion 'SPICE_IS_PLAYBACK_CHANNEL(channel)' failed
>> 
>> (spicy:78043): GLib-GObject-CRITICAL **: g_object_get: assertion 'G_IS_OBJECT
>> (object)' failed
>> 
>> (spicy:78043): GLib-GObject-CRITICAL **: g_object_unref: assertion
>> 'G_IS_OBJECT (object)' failed
>> 
>> (spicy:78043): GLib-GObject-CRITICAL **: g_object_get: assertion 'G_IS_OBJECT
>> (object)' failed
>> 
>> (spicy:78043): GLib-GObject-CRITICAL **: g_object_unref: assertion
>> 'G_IS_OBJECT (object)' failed
>> 
>> (spicy:78043): Spice-WARNING **: channel-display-gst.c:339:create_pipeline:
>> GStreamer error: pas d??l?ment ??vp8dec??
>> 
>> (spicy:78043): Spice-WARNING **: channel-display-gst.c:339:create_pipeline:
>> GStreamer error: pas d??l?ment ??vp9dec??
>> 
>> (spicy:78043): Spice-WARNING **: channel-display-gst.c:339:create_pipeline:
>> GStreamer error: pas d??l?ment ??vp8dec??
>> 
>> (spicy:78043): Spice-WARNING **: channel-display-gst.c:339:create_pipeline:
>> GStreamer error: pas d??l?ment ??vp9dec??
>> 
>> (spicy:78043): Gdk-WARNING **: GdkQuartzDisplay does not implement the
>> monitor vfuncs
>> Received signal 10, dumping recorder
>> 0 [0.000000:0x103efd9ec] MAIN: spicy starts with 5 args
>> 1 [0.000011:0x103efda17] MAIN: Installing signal handlers
> 
> (snip the long log, thanks)

The long log was the point of the message. OK to snip in responses though.

> 
>>> 
>>>> 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.
>>> 
>>> I mostly read these examples as "our debug logs are bad", and most of
>>> these would be helped by more logs, which filtered output facilitates
>>> as you are not overwhelmed with too much stuff.
>> 
>> I’m sorry if I’m being dense here, but I insist, there are 5 different
>> things, only one of them is logs:
>> 
>> a) logs
>> b) trace selection
>> c) flight recorder
>> d) performance probes
>> e) tweaks
>> 
>> Of these, my RFC addresses b and e, the “recorder” branch is WIP to address
>> c, and I have yet-unpublished work for d.
> 
> Can we please focus on b) log filtering? let's avoid side-track discussions.

I’m sharing all the stuff that’s presently missing and how I plan to address this.

> 
>> 
>>> 
>>>> 
>>>>> 
>>>>> 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.
>>> 
>>> If it's a hot path, then the needed flag will be in a cache-line
>>> regardless of the approach taken.
>> 
>> You are reasoning on one flag, the only case where it’s the same. If your hot
>> path tests N categories, then it’s N cache lines versus something like
>> N/512.
>> 
> 
> This is unrealistic, if you trace something hot, you are in a single domain, or you make it use a single (sub)domain.

Any data to support that correctly wrong hypothesis?

> 
>>> and Marc-André's approach has the advantage
>>> (to me) of not needing #define MAGIC_FOO(x) ... #include "foo.defs"
>>> which I'm not a big fan of.
>> 
>> That’s the trade-off for DRY (don’t repeat yourself) vs. WET (write
>> everything twice, or we enjoy typing).
> 
> What I propose is to have a single definition line in most cases, there is no duplication. If you need to share it in multiple units, it follows the traditional C declaration/definition. And if deemed better, we can switch to you #include trick, but I am against it, as it's better to declare the domain where it's actually used, and do not trigger whole-codebase compilation on change.

And I could be swayed to trade off some performance for putting it in a library. If it’s in glib, then it’s worth the trade off. If we want to save build time, then we should look at autoconf. When switching branches, autoreconf takes 40s, the configure script 35s, total 75s. When you change spice-traces.def, it takes 22s to rebuild. So you are really inventing problems here.

> 
>> I agree this is a bit hacky, though in my opinion less complex than, say, the
>> python marshalling generators, which play a similar role of automating some
>> code generation.
> 
> I hope you can make it simpler than the python generator ;)
> 
> It generates some units to build and has few invert-dependencies, it's not included in the whole code base. (a far-stretched comparison tbh)

It’s another case where we generate code automatically. So no, not far-stretched.

> _______________________________________________
> Spice-devel mailing list
> Spice-devel at lists.freedesktop.org
> https://lists.freedesktop.org/mailman/listinfo/spice-devel