Re: [Spice-devel] RFC: Lightweight tracing mechanism

[Marc-André Lureau]

Hi

- Original Message -
> Top remark: here is what I expected to see discussed when I shared the code.
> 

Sending a github link isn't really sharing code. It is not our cmmon practice, 
so we can't easily review/discuss it.

> 1. What categories do we want?
> 2. How do spread the categorization work?

Very good questions, no easy answer. This is I think some kind of ontological 
problem, and many things could actually belong to many "categories". Imho, in 
code, the file/unit is the natural split. If a unit is doing several things, it 
could be split. If a category is shared in several units, it means we have 
sub-categories (ex: widget, wiget_egl, widget_cairo etc)

> 3. How much do today’s developers depend on existing output?

A lot obviously (it doesn't mean we can just keep adding whatever log there).

> 4. What categories do we request e.g. in bug reports (IOW, what should
> --spice-debug select)

Imho, SPICE_DEBUG=1 (or --spice-debug for spice-gtk) should log all categories 
(from production or debug build). It is just simpler that way.

> 5. What tracing options and tweaks are potentially dangerous for end-users
> (e.g. what could expose security information)

Log should never allow to expose a security sensitive information in production 
builds. We are not doing that well in spice-gtk logs for ex, in particular 
logging key scancode isn't a good idea.

> 6. Consequently, what tracing options do hide in release builds, current POV
> ranging from “as many as possible" (me) to “none of them” (you)

It's not easy to identify, imho logging key scancode should only be in debug 
builds for ex.

> 7. What are the existing hard-coded parameters? Explicit (e.g. 400ms delay in
> the server) or implicit (e.g. unbounded memory usage)
> 8. Among these, which ones would we like to tweak?

No idea, you would have to grep the code for hardcoded values.

> 9. Among those we want to tweak, which ones would deserve dedicated options
> or env variables, which ones would be perfectly OK with a more generic
> option like the -t I proposed.

If you want to add more options to spice-gtk or spice-sever, feel free to 
propose it, but be aware it will be frowned up for the reason already discussed 
in the thread.

> It did not go as planned, but if you have time, I think these are interesting
> questions.
> 

Yes, they are interesting, that's why this thread is hot. And I hope my 
contribution helps. For the rest of your question, there is too much 
misunderstanding, and you are very time consuming, I'll try to answer later. 
(btw, I didn't meant to attack you personally when I say "you can't use gdb" 
for ex, but you said you couldn't easily use it on macos iirc - and yes I 
strongly believe that logging is too often used as a poor-man way of debugging 
- if you feel offended, you shouldn't as I believe you know how to use it).

I agree with you on log category / filtering and adding more debugging. I 
strongly disagree on using another facility to tweak runtime than existing 
option parsing or environment variables, or coupling it with logging. I 
proposed an alternative to add log categories/filtering which I believe fits 
better and simplify our code. 

So let's send patches, and let's review them please.

thanks
___
Spice-devel mailing list
Spice-devel@lists.freedesktop.org
https://lists.freedesktop.org/mailman/listinfo/spice-devel

Re: [Spice-devel] RFC: Lightweight tracing mechanism

[Marc-André Lureau]

Hi

- Original Message -
> Hi
> 
> - Original Message -
> > On Fri, Jun 09, 2017 at 12:11:50PM -0400, Marc-André Lureau wrote:
> > > I don't get the problem with spice-gtk logging though.
> > 
> > I never remember whether G_MESSAGES_DEBUG=all, SPICE_DEBUG=1 and
> > --spice-debug are the same or not, I think they are not, and if you only
> > use eg G_MESSAGES_DEBUG=all, you don't get all possible debug, which I
> > would expect.
> > Maybe this was introduced when switching to glog.
> 

To get back to your remark, G_MESSAGES_DEBUG=all will not enable GSpice log 
(and will not enable all categories in my RFC). I agree with you it would be 
simpler and convenient to have G_MESSAGES_DEBUG=all do that, and it shouldn't 
be difficult or controversial to change that behaviour.
___
Spice-devel mailing list
Spice-devel@lists.freedesktop.org
https://lists.freedesktop.org/mailman/listinfo/spice-devel

Re: [Spice-devel] RFC: Lightweight tracing mechanism

[Marc-André Lureau]

Hi

- Original Message -
> On Fri, Jun 09, 2017 at 12:11:50PM -0400, Marc-André Lureau wrote:
> > I don't get the problem with spice-gtk logging though.
> 
> I never remember whether G_MESSAGES_DEBUG=all, SPICE_DEBUG=1 and
> --spice-debug are the same or not, I think they are not, and if you only
> use eg G_MESSAGES_DEBUG=all, you don't get all possible debug, which I
> would expect.
> Maybe this was introduced when switching to glog.

Historically, from what I remember in spice-gtk:

- SPICE_DEBUG=1 has "always" (since 0.1) been there to enable spice-gtk 
debugging with glog
- --spice-debug was added when GOptionGroup was added, as a convenience. It 
should have the same effect as SPICE_DEBUG=1. Last call to 
spice_util_set_debug() should win, so --spice-debug overrides SPICE_DEBUG=1.
- then G_MESSAGES_DEBUG happened, and spice-gtk learned to add its GSpice 
domain there (but not the controller, which is a seperate, mostly deprecated 
now, library)

spice-common/server log has also an history:

- it used to have mostly unconfigurable log in stderr
- then SPICE_DEBUG_LEVEL= was added in 2011
- default abort() behaviour was problematic, I added SPICE_ABORT_LEVEL, so it 
could be tweaked (similar to glib fatal-warnings, fatal-criticals etc)
- at that time, I tried to move to a very similar API to glog, in the hope that 
some day we could easily switch over
- then glib logging was added end of 2015 by Christophe F., where we started to 
deprecate SPICE_{DEBUG,ABORT}_LEVEL, but didn't switch to direct glog usage 
though for compatibility reasons. G_MESSAGES_DEBUG is partially wrong, as 
described earlier, which contributes to some confusion
- Christophe D. suggests to add categories and more tweaking options through a 
new SPICE_TRACES variable
- I suggest to remove SPICE_DEBUG_LEVEL/SPICE_ABORT_LEVEL and switch more to 
direct glog, and add categories tweakable with SPICE_DEBUG

G_MESSAGES_DEBUG & G_DEBUG will remain no matter what. I would like to keep 
SPICE_DEBUG=1 to enable all SpiceGtk logging as it has proven to be very 
convenient over the years. I suggest to get rid of SPICE_*_LEVEL, and extend 
SPICE_DEBUG= with categories filtering only, and used structured logging to 
ease query and log manipulation. I would liek to further run-time "tweaking" to 
be considered a case-by-case and apart from log category selection.
___
Spice-devel mailing list
Spice-devel@lists.freedesktop.org
https://lists.freedesktop.org/mailman/listinfo/spice-devel

Re: [Spice-devel] RFC: Lightweight tracing mechanism

[Christophe Fergeau]

On Fri, Jun 09, 2017 at 12:11:50PM -0400, Marc-André Lureau wrote:
> I don't get the problem with spice-gtk logging though.

I never remember whether G_MESSAGES_DEBUG=all, SPICE_DEBUG=1 and
--spice-debug are the same or not, I think they are not, and if you only
use eg G_MESSAGES_DEBUG=all, you don't get all possible debug, which I
would expect.
Maybe this was introduced when switching to glog.

Christophe


signature.asc
Description: PGP signature
___
Spice-devel mailing list
Spice-devel@lists.freedesktop.org
https://lists.freedesktop.org/mailman/listinfo/spice-devel

Re: [Spice-devel] RFC: Lightweight tracing mechanism

[Christophe de Dinechin]

Top remark: here is what I expected to see discussed when I shared the code.

1. What categories do we want?

2. How do spread the categorization work?

3. How much do today’s developers depend on existing output?

4. What categories do we request e.g. in bug reports (IOW, what should 
--spice-debug select)

5. What tracing options and tweaks are potentially dangerous for end-users 
(e.g. what could expose security information)

6. Consequently, what tracing options do hide in release builds, current POV 
ranging from “as many as possible" (me) to “none of them” (you)

7. What are the existing hard-coded parameters? Explicit (e.g. 400ms delay in 
the server) or implicit (e.g. unbounded memory usage)

8. Among these, which ones would we like to tweak?

9. Among those we want to tweak, which ones would deserve dedicated options or 
env variables, which ones would be perfectly OK with a more generic option like 
the -t I proposed.


It did not go as planned, but if you have time, I think these are interesting 
questions.



> On 9 Jun 2017, at 18:06, Marc-André Lureau  
> wrote:
> 
> 
> 
> - Original Message -
> 
>> [drop_stats]id=0 #in-frames=99 #late=99 (100.00%, avg 2995.89 ms)
>> #drop-on-playback=0 (0.00%)
>> [drop_stats]id=0 #in-frames=198 #late=198 (100.00%, avg 2160.48 ms)
>> #drop-on-playback=3 (1.52%)
>> [drop_stats]id=0 #in-frames=297 #late=297 (100.00%, avg 1881.11 ms)
>> #drop-on-playback=12 (4.04%)
>> 
>> But then:
>> 
>> Why 5? How much I want to put a tweak there and see what happens if I change
>> that value.
>> 
>>  #define STREAM_PLAYBACK_SYNC_DROP_SEQ_LEN_LIMIT 5
>> 
>> Why 100? What happens if you change it?
>> 
>>op->multi_media_time = mmtime + 100; /* workaround... */
>> 
> 
> I don't get your tweaks, they look specific to the problem at hand, I don't 
> think such esoteric code should be checked in code, it will just decay.

Are you telling me that you like this kind of magic, undocumented values  that 
you can’t change without recompiling? If that is really what you are saying, 
could you please explain the rationale to me? If not, what are you really 
saying?

Let me go on record stating that to me, most magic values like this in the code 
reek of “quick and dirty”, i.e. it’s cheap enough now, we believe it does not 
matter but never quite tested it.

> 
>> 
>> Here is a more serious follow up with another tweaks I just pushed,
>> latency_offset:
>> 
>> ddd@ptitpuce[traces] spice-gtk> spicy -t latency_offset=1900:drop_stats=25 -h
>> turbo -p 5901
>> [drop_stats]id=0 #in-frames=25 #late=0 (0.00%, avg 0.00 ms)
>> #drop-on-playback=0 (0.00%)
>> […]
>> [drop_stats]id=0 #in-frames=225 #late=0 (0.00%, avg 0.00 ms)
>> #drop-on-playback=14 (6.22%)
>> [drop_stats]id=0 #in-frames=250 #late=17 (6.80%, avg 2027.82 ms)
>> #drop-on-playback=15 (6.00%)
>> [drop_stats]id=0 #in-frames=275 #late=36 (13.09%, avg 2353.86 ms)
>> #drop-on-playback=26 (9.45%)
>> [drop_stats]id=0 #in-frames=300 #late=58 (19.33%, avg 2445.26 ms)
>> #drop-on-playback=50 (16.67%)
>> [drop_stats]id=0 #in-frames=325 #late=58 (17.85%, avg 2445.26 ms)
>> #drop-on-playback=50 (15.38%)
>> 
> 
> same idea, this is playing with the code, not code that should remain.

First, “playing with the code”, aka “interactivity”, is indeed what this is 
about. That what the point of my “punchcard” analogy. By being interactive, 
terminals made many things possible that don’t even seem to make sense with a 
punchcard reader and a line printer. And the mechanism I’m talking about there, 
as simple as it is, makes spice testing more interactive.

Second, whether that or any other instrumentation remains or not would depend 
on a number of things. If the instrumentation showed that something interesting 
happens with “latency_offset=1600”, then I believe I would share the 
instrumentation to let others replicate my experiment. If variations of that 
parameter allowed me to observe a 2x effect in some performance aspect, then I 
would certainly leave the tweak in and suggest we collectively work on 
optimizing its value.



> 
>>> 
 
 3. What is actually received during the early protocol exchange? That’s
 mostly for my curiosity, to see how chatty the protocol is, the size of
 packets it tends to exchange, etc. To answer a question from Marc André,
 this one and the next are tools that would immediately have shown me where
 the macOS version was goofing up.
 
> spicy -t wire_read -h turbo -p 5901
 [wire_read]Read 16 bytes in 0x7f8b150d85a8
 [wire_read]:  52 45 44 51 02 00 00 00 02 00 00 00 BA 00 00 00
 
 [wire_read]Read 186 bytes in 0x7f8b141c6650
 [wire_read]:  00 00 00 00 30 81 9F 30 0D 06 09 2A 86 48 86 F7
 [wire_read]0010:  0D 01 01 01 05 00 03 81 8D 00 30 81 89 02 81 81
 [wire_read]0020:  00 D2 A9 FE 7B F0 36 B7 33 3C C1 F0 5E 10 50 F3
 [wire_read]0030:  11 D3 3E 31 4A 95 AC AC 7B 0C 20 CB 57 B2 C8 1D

Re: [Spice-devel] RFC: Lightweight tracing mechanism

[Marc-André Lureau]

On Mon, Jun 12, 2017 at 12:40 AM Marc-André Lureau <
marcandre.lur...@gmail.com> wrote:

> Hi
>
> On Fri, Jun 9, 2017 at 10:08 PM Jonathon Jongsma 
> wrote:
>
>> On Fri, 2017-06-09 at 12:11 -0400, Marc-André Lureau wrote:
>> > >
>> >
>> > - Original Message -
>> > >
>> > > > On 9 Jun 2017, at 17:16, Jonathon Jongsma 
>> > > > wrote:
>> > > >
>> > > > On Fri, 2017-06-09 at 10:59 +0200, Christophe de Dinechin wrote:
>> > > > > > > What I see on the thread:
>> > > > > > > - log categorization. This was similar to Djasa bug but I
>> > > > > > > think
>> > > > > > > he just
>> > > > > > >   proposed to use domains in the glib log sense;
>> > > > >
>> > > > > Punchcard analogy: “Printer sheet categorization. This was
>> > > > > similar to
>> > > > > the report that Djisktra had taken McCarthy's listing by
>> > > > > mistake"
>> > > > >
>> > > > > I thought it was a good idea to derive glib log domains
>> > > > > automatically
>> > > > > from spice-traces.def. So it’s there in the branch now. That
>> > > > > being
>> > > > > said, as noted above, glib does linear searches on domain
>> > > > > names, so
>> > > > > this does not scale well. In the long term, we may want to have
>> > > > > a
>> > > > > separate field in a structured log.
>> > > >
>> > > >
>> > > > Responding only to this point for the moment: I don't think using
>> > > > multiple glib logging domains is necessarily desirable. We
>> > > > already use
>> > > > several logging domains, but the vast majority of logging
>> > > > statements
>> > > > within each project use a single domain. In spice-server, that
>> > > > primary
>> > > > log domain is "Spice", and in spice-gtk that domain is "GSpice".
>> > > > spice-
>> > > > server also has some additional domains like "SpiceWorker" and
>> > > > "SpiceDispatcher". spice-gtk also has GSpiceController (which
>> > > > isn't
>> > > > really used much these days).
>> > > >
>> > > > The problem is that both spice-server and spice-gtk have a way to
>> > > > enable debugging with an environment variable. But the code for
>> > > > enabling the debugging only actually enables the primary domain.
>> > >
>> > > The ‘traces’ branch enables all trace-related domains if you enable
>> > > debug.
>> > >
>> > > > So anything that is logged under a different domain does not get
>> > > > enabled.
>> > > > (In fact, spice-gtk has 2 ways to enable logging with an
>> > > > environment
>> > > > variable but one of the methods is the same one used for spice-
>> > > > server,
>> > > > but it doesn't work since it actually enables logging for the
>> > > > "Spice"
>> > > > domain which spice-gtk doesn't use.) I'm hoping to send some
>> > > > patches to
>> > > > clean up this mess soon.
>> > >
>> > > Ah, so I was not the only one thinking this was a mess :-)
>> >
>> > The mess comes because spice-gtk and spice server used different
>> > logging, when spice didn't depend on glib.
>> >
>> > The cleanup isn't over I suppose (Christophe F. did the move to glog
>> > in spice-common).
>> >
>> > I don't get the problem with spice-gtk logging though.
>> >
>>
>>
>> Yes, there are historical reasons. And "mess" was an exaggeration. But
>> in the process of consolidating the implementations, we seem to have
>> introduced some inconsistencies. I'll send more details soon, I hope.
>>
>
> Some of them I just found out by reading spice-common log.c, introduced
> when switching to glog:
>
> debug_env = (char *)g_getenv("G_MESSAGES_DEBUG");
> if (debug_env == NULL) {
> g_setenv("G_MESSAGES_DEBUG", SPICE_LOG_DOMAIN, FALSE);
> } else {
> debug_env = g_strconcat(debug_env, ":", SPICE_LOG_DOMAIN,
> NULL);
> g_setenv("G_MESSAGES_DEBUG", SPICE_LOG_DOMAIN, FALSE);
> g_free(debug_env);
> }
>
> - appending to G_MESSAGES_DEBUG is buggy, it's not using the newly built
> debug_env.
> - this will only append the default "Spice" SPICE_LOG_DOMAIN (not the
> other spice sub-domains),
> - the variable expects a space-seperated list (you sent a patch for that)
> (+ the unnecessary cast, could just use another variable...)
>

+  it doesn't overwrite the value! :)

-- 
Marc-André Lureau
___
Spice-devel mailing list
Spice-devel@lists.freedesktop.org
https://lists.freedesktop.org/mailman/listinfo/spice-devel

Re: [Spice-devel] RFC: Lightweight tracing mechanism

[Marc-André Lureau]

Hi

On Fri, Jun 9, 2017 at 10:08 PM Jonathon Jongsma 
wrote:

> On Fri, 2017-06-09 at 12:11 -0400, Marc-André Lureau wrote:
> > >
> >
> > - Original Message -
> > >
> > > > On 9 Jun 2017, at 17:16, Jonathon Jongsma 
> > > > wrote:
> > > >
> > > > On Fri, 2017-06-09 at 10:59 +0200, Christophe de Dinechin wrote:
> > > > > > > What I see on the thread:
> > > > > > > - log categorization. This was similar to Djasa bug but I
> > > > > > > think
> > > > > > > he just
> > > > > > >   proposed to use domains in the glib log sense;
> > > > >
> > > > > Punchcard analogy: “Printer sheet categorization. This was
> > > > > similar to
> > > > > the report that Djisktra had taken McCarthy's listing by
> > > > > mistake"
> > > > >
> > > > > I thought it was a good idea to derive glib log domains
> > > > > automatically
> > > > > from spice-traces.def. So it’s there in the branch now. That
> > > > > being
> > > > > said, as noted above, glib does linear searches on domain
> > > > > names, so
> > > > > this does not scale well. In the long term, we may want to have
> > > > > a
> > > > > separate field in a structured log.
> > > >
> > > >
> > > > Responding only to this point for the moment: I don't think using
> > > > multiple glib logging domains is necessarily desirable. We
> > > > already use
> > > > several logging domains, but the vast majority of logging
> > > > statements
> > > > within each project use a single domain. In spice-server, that
> > > > primary
> > > > log domain is "Spice", and in spice-gtk that domain is "GSpice".
> > > > spice-
> > > > server also has some additional domains like "SpiceWorker" and
> > > > "SpiceDispatcher". spice-gtk also has GSpiceController (which
> > > > isn't
> > > > really used much these days).
> > > >
> > > > The problem is that both spice-server and spice-gtk have a way to
> > > > enable debugging with an environment variable. But the code for
> > > > enabling the debugging only actually enables the primary domain.
> > >
> > > The ‘traces’ branch enables all trace-related domains if you enable
> > > debug.
> > >
> > > > So anything that is logged under a different domain does not get
> > > > enabled.
> > > > (In fact, spice-gtk has 2 ways to enable logging with an
> > > > environment
> > > > variable but one of the methods is the same one used for spice-
> > > > server,
> > > > but it doesn't work since it actually enables logging for the
> > > > "Spice"
> > > > domain which spice-gtk doesn't use.) I'm hoping to send some
> > > > patches to
> > > > clean up this mess soon.
> > >
> > > Ah, so I was not the only one thinking this was a mess :-)
> >
> > The mess comes because spice-gtk and spice server used different
> > logging, when spice didn't depend on glib.
> >
> > The cleanup isn't over I suppose (Christophe F. did the move to glog
> > in spice-common).
> >
> > I don't get the problem with spice-gtk logging though.
> >
>
>
> Yes, there are historical reasons. And "mess" was an exaggeration. But
> in the process of consolidating the implementations, we seem to have
> introduced some inconsistencies. I'll send more details soon, I hope.
>

Some of them I just found out by reading spice-common log.c, introduced
when switching to glog:

debug_env = (char *)g_getenv("G_MESSAGES_DEBUG");
if (debug_env == NULL) {
g_setenv("G_MESSAGES_DEBUG", SPICE_LOG_DOMAIN, FALSE);
} else {
debug_env = g_strconcat(debug_env, ":", SPICE_LOG_DOMAIN,
NULL);
g_setenv("G_MESSAGES_DEBUG", SPICE_LOG_DOMAIN, FALSE);
g_free(debug_env);
}

- appending to G_MESSAGES_DEBUG is buggy, it's not using the newly built
debug_env.
- this will only append the default "Spice" SPICE_LOG_DOMAIN (not the other
spice sub-domains),
- the variable expects a space-seperated list (you sent a patch for that)
(+ the unnecessary cast, could just use another variable...)

spice-gtk spice_util_enable_debug_messages() seems to be correct, also
handling the "all" case.

All of log.c is mostly to deal with deprecated stuff. I propose we switch
more effectively to glog, use a single domain and add some kind of
categories with structured logging (instead of extra glog domains) & remove
the deprecated code. I will work on a proposal, so we'll have alternatives
to discuss.
-- 
Marc-André Lureau
___
Spice-devel mailing list
Spice-devel@lists.freedesktop.org
https://lists.freedesktop.org/mailman/listinfo/spice-devel

Re: [Spice-devel] RFC: Lightweight tracing mechanism

[Jonathon Jongsma]

On Fri, 2017-06-09 at 12:11 -0400, Marc-André Lureau wrote:
> > 
> 
> - Original Message -
> > 
> > > On 9 Jun 2017, at 17:16, Jonathon Jongsma 
> > > wrote:
> > > 
> > > On Fri, 2017-06-09 at 10:59 +0200, Christophe de Dinechin wrote:
> > > > > > What I see on the thread:
> > > > > > - log categorization. This was similar to Djasa bug but I
> > > > > > think
> > > > > > he just
> > > > > >   proposed to use domains in the glib log sense;
> > > > 
> > > > Punchcard analogy: “Printer sheet categorization. This was
> > > > similar to
> > > > the report that Djisktra had taken McCarthy's listing by
> > > > mistake"
> > > > 
> > > > I thought it was a good idea to derive glib log domains
> > > > automatically
> > > > from spice-traces.def. So it’s there in the branch now. That
> > > > being
> > > > said, as noted above, glib does linear searches on domain
> > > > names, so
> > > > this does not scale well. In the long term, we may want to have
> > > > a
> > > > separate field in a structured log.
> > > 
> > > 
> > > Responding only to this point for the moment: I don't think using
> > > multiple glib logging domains is necessarily desirable. We
> > > already use
> > > several logging domains, but the vast majority of logging
> > > statements
> > > within each project use a single domain. In spice-server, that
> > > primary
> > > log domain is "Spice", and in spice-gtk that domain is "GSpice".
> > > spice-
> > > server also has some additional domains like "SpiceWorker" and
> > > "SpiceDispatcher". spice-gtk also has GSpiceController (which
> > > isn't
> > > really used much these days).
> > > 
> > > The problem is that both spice-server and spice-gtk have a way to
> > > enable debugging with an environment variable. But the code for
> > > enabling the debugging only actually enables the primary domain.
> > 
> > The ‘traces’ branch enables all trace-related domains if you enable
> > debug.
> > 
> > > So anything that is logged under a different domain does not get
> > > enabled.
> > > (In fact, spice-gtk has 2 ways to enable logging with an
> > > environment
> > > variable but one of the methods is the same one used for spice-
> > > server,
> > > but it doesn't work since it actually enables logging for the
> > > "Spice"
> > > domain which spice-gtk doesn't use.) I'm hoping to send some
> > > patches to
> > > clean up this mess soon.
> > 
> > Ah, so I was not the only one thinking this was a mess :-)
> 
> The mess comes because spice-gtk and spice server used different
> logging, when spice didn't depend on glib.
> 
> The cleanup isn't over I suppose (Christophe F. did the move to glog
> in spice-common). 
> 
> I don't get the problem with spice-gtk logging though.
> 


Yes, there are historical reasons. And "mess" was an exaggeration. But
in the process of consolidating the implementations, we seem to have
introduced some inconsistencies. I'll send more details soon, I hope.
___
Spice-devel mailing list
Spice-devel@lists.freedesktop.org
https://lists.freedesktop.org/mailman/listinfo/spice-devel

Re: [Spice-devel] RFC: Lightweight tracing mechanism

[Marc-André Lureau]

- Original Message -

> [drop_stats]id=0 #in-frames=99 #late=99 (100.00%, avg 2995.89 ms)
> #drop-on-playback=0 (0.00%)
> [drop_stats]id=0 #in-frames=198 #late=198 (100.00%, avg 2160.48 ms)
> #drop-on-playback=3 (1.52%)
> [drop_stats]id=0 #in-frames=297 #late=297 (100.00%, avg 1881.11 ms)
> #drop-on-playback=12 (4.04%)
> 
> But then:
> 
> Why 5? How much I want to put a tweak there and see what happens if I change
> that value.
> 
>   #define STREAM_PLAYBACK_SYNC_DROP_SEQ_LEN_LIMIT 5
> 
> Why 100? What happens if you change it?
> 
> op->multi_media_time = mmtime + 100; /* workaround... */
> 

I don't get your tweaks, they look specific to the problem at hand, I don't 
think such esoteric code should be checked in code, it will just decay.

> 
> Here is a more serious follow up with another tweaks I just pushed,
> latency_offset:
> 
> ddd@ptitpuce[traces] spice-gtk> spicy -t latency_offset=1900:drop_stats=25 -h
> turbo -p 5901
> [drop_stats]id=0 #in-frames=25 #late=0 (0.00%, avg 0.00 ms)
> #drop-on-playback=0 (0.00%)
> […]
> [drop_stats]id=0 #in-frames=225 #late=0 (0.00%, avg 0.00 ms)
> #drop-on-playback=14 (6.22%)
> [drop_stats]id=0 #in-frames=250 #late=17 (6.80%, avg 2027.82 ms)
> #drop-on-playback=15 (6.00%)
> [drop_stats]id=0 #in-frames=275 #late=36 (13.09%, avg 2353.86 ms)
> #drop-on-playback=26 (9.45%)
> [drop_stats]id=0 #in-frames=300 #late=58 (19.33%, avg 2445.26 ms)
> #drop-on-playback=50 (16.67%)
> [drop_stats]id=0 #in-frames=325 #late=58 (17.85%, avg 2445.26 ms)
> #drop-on-playback=50 (15.38%)
> 

same idea, this is playing with the code, not code that should remain.

> > 
> >> 
> >> 3. What is actually received during the early protocol exchange? That’s
> >> mostly for my curiosity, to see how chatty the protocol is, the size of
> >> packets it tends to exchange, etc. To answer a question from Marc André,
> >> this one and the next are tools that would immediately have shown me where
> >> the macOS version was goofing up.
> >> 
> >>> spicy -t wire_read -h turbo -p 5901
> >> [wire_read]Read 16 bytes in 0x7f8b150d85a8
> >> [wire_read]:  52 45 44 51 02 00 00 00 02 00 00 00 BA 00 00 00
> >> 
> >> [wire_read]Read 186 bytes in 0x7f8b141c6650
> >> [wire_read]:  00 00 00 00 30 81 9F 30 0D 06 09 2A 86 48 86 F7
> >> [wire_read]0010:  0D 01 01 01 05 00 03 81 8D 00 30 81 89 02 81 81
> >> [wire_read]0020:  00 D2 A9 FE 7B F0 36 B7 33 3C C1 F0 5E 10 50 F3
> >> [wire_read]0030:  11 D3 3E 31 4A 95 AC AC 7B 0C 20 CB 57 B2 C8 1D
> >> [wire_read]0040:  10 F1 E2 4A 1A F2 8F 2A 03 70 25 BB 63 C7 D6 51
> >> [wire_read]0050:  D4 DA 64 3C 95 0C B6 9E A7 4E B3 3F 65 12 83 86
> >> [wire_read]0060:  F4 35 F3 AC 3D C3 9A 6C C9 EE 34 D9 67 F0 8A 2D
> >> [wire_read]0070:  53 4D 73 46 06 CA 80 04 CF 7F 72 4A 8D 74 81 78
> >> [wire_read]0080:  E8 28 39 51 7C 9E 3B C2 19 D6 BD EC B4 F7 0A 68
> >> [wire_read]0090:  D3 AF D7 1F E6 93 E1 4C 23 F5 83 68 E1 7D 31 9A
> >> [wire_read]00A0:  53 02 03 01 00 01 01 00 00 00 01 00 00 00 B2 00
> >> [wire_read]00B0:  00 00 0B 00 00 00 09 00 00 00
> >> [wire_read]Read 4 bytes in 0x109478b44
> >> [wire_read]:  00 00 00 00
> >> ** Message: main channel: opened
> >> [wire_read]Read 6 bytes in 0x7f8b1274efb0
> >> [wire_read]:  67 00 20 00 00 00
> >> [wire_read]Read 32 bytes in 0x7f8b1274dff0
> >> [wire_read]:  31 AE 1E 5E 01 00 00 00 03 00 00 00 02 00 00 00
> >> [wire_read]0010:  01 00 00 00 0A 00 00 00 9B AF BE 0B 00 00 00 01
> >> 
> > 
> > This is so low-level than even debug log don't make much sense. Imho when
> > you need to read the byte-stream, you can just attach gdb and put a
> > breakpoint/command. Then GDB allows to do a lot more interesting stuff,
> > like conditional breakpoint, various print etc..
> 
> Valid opinion. Don’t like trace options, don’t have to use them. By why
> prevent me from using them?

Cluttering the code because you can't use proper tools is not acceptable imho. 

> 
> Please send me your GDB script for -t wire_read:marshall_read, which I use
> for LEB128 development, and for -t drop_stats=25:latency_offset=N, which I
> use to investigate where the latency is coming from. Please make it
> compatible with LLDB too, unless you know how to install GDB on macOS (read
> this first if you think I’m being silly
> https://stackoverflow.com/questions/33162757/how-to-install-gdb-debugger-in-mac-osx-el-capitan).

Well that looks like a general problem if you can't use debuggers on your 
platform. I don't own a mac to help you here, nor do I have much experience 
with it.

> > 
> >> 
> >> 4. A symbolic view of the initial exchange (not all cases are covered in
> >> marshal.py / demarshal.py yet, so some fields are likely missing).
> >> 
> >>> spicy -t marshall_read -h turbo -p 5901
> >> 
> >> [marshall_read]  SpiceMsgMainInit.session_id=1745897490
> >> [marshall_read]  SpiceMsgMainInit.display_channels_hint=1
> >> [marshall_read]  

Re: [Spice-devel] RFC: Lightweight tracing mechanism

[Christophe de Dinechin]

> On 9 Jun 2017, at 17:16, Jonathon Jongsma  wrote:
> 
> On Fri, 2017-06-09 at 10:59 +0200, Christophe de Dinechin wrote:
 What I see on the thread:
 - log categorization. This was similar to Djasa bug but I think
 he just
   proposed to use domains in the glib log sense;
>> 
>> Punchcard analogy: “Printer sheet categorization. This was similar to
>> the report that Djisktra had taken McCarthy's listing by mistake"
>> 
>> I thought it was a good idea to derive glib log domains automatically
>> from spice-traces.def. So it’s there in the branch now. That being
>> said, as noted above, glib does linear searches on domain names, so
>> this does not scale well. In the long term, we may want to have a
>> separate field in a structured log.
> 
> 
> Responding only to this point for the moment: I don't think using
> multiple glib logging domains is necessarily desirable. We already use
> several logging domains, but the vast majority of logging statements
> within each project use a single domain. In spice-server, that primary
> log domain is "Spice", and in spice-gtk that domain is "GSpice". spice-
> server also has some additional domains like "SpiceWorker" and
> "SpiceDispatcher". spice-gtk also has GSpiceController (which isn't
> really used much these days). 
> 
> The problem is that both spice-server and spice-gtk have a way to
> enable debugging with an environment variable. But the code for
> enabling the debugging only actually enables the primary domain.

The ‘traces’ branch enables all trace-related domains if you enable debug.

> So anything that is logged under a different domain does not get enabled.
> (In fact, spice-gtk has 2 ways to enable logging with an environment
> variable but one of the methods is the same one used for spice-server,
> but it doesn't work since it actually enables logging for the "Spice"
> domain which spice-gtk doesn't use.) I'm hoping to send some patches to
> clean up this mess soon. 

Ah, so I was not the only one thinking this was a mess :-)



> 
> But the upshot is that if we use multiple log domains we'll need to
> make sure that if we enable debug, we enable all domains that we're
> interested in. This will require a small maintenance burden (although
> Christophe's approach probably handles it automatically). Or we could
> use a single log domain and segment the different "categories" of log
> messages somehow within that domain.

I would switch to categories, but after we switch to structured logging. Which, 
once the “mess” is cleaned up, is relatively easy (one function called with 
consistent input).


> 
> Jonathon
> ___
> Spice-devel mailing list
> Spice-devel@lists.freedesktop.org
> https://lists.freedesktop.org/mailman/listinfo/spice-devel

___
Spice-devel mailing list
Spice-devel@lists.freedesktop.org
https://lists.freedesktop.org/mailman/listinfo/spice-devel

Re: [Spice-devel] RFC: Lightweight tracing mechanism

[Christophe de Dinechin]

> On 9 Jun 2017, at 11:48, Marc-André Lureau  
> wrote:
> 
> Hi
> 
> I'll focus on your examples, as I think it's the most relevant for the 
> discussion (let's avoid side-track).
> 
> - Original Message -
> 
>>> spicy -t drop_stats=100 -h turbo -p 5901
>> [drop_stats]id=0 #in-frames=100 #late=100 (100.00%, avg 1639.24 ms)
>> #drop-on-playback=8 (8.00%)
>> [drop_stats]id=0 #in-frames=200 #late=200 (100.00%, avg 1603.13 ms)
>> #drop-on-playback=8 (4.00%)
>> [drop_stats]id=0 #in-frames=300 #late=300 (100.00%, avg 1607.24 ms)
>> #drop-on-playback=20 (6.67%)
>> [drop_stats]id=0 #in-frames=400 #late=400 (100.00%, avg 1597.48 ms)
>> #drop-on-playback=20 (5.00%)
>> [drop_stats]id=0 #in-frames=500 #late=500 (100.00%, avg 1591.58 ms)
>> #drop-on-playback=20 (4.00%)
>> [drop_stats]id=0 #in-frames=600 #late=600 (100.00%, avg 1587.52 ms)
>> #drop-on-playback=20 (3.33%)
>> [drop_stats]id=0 #in-frames=700 #late=700 (100.00%, avg 1584.60 ms)
>> #drop-on-playback=20 (2.86%)
> 
> Could be in the debug log by default (I believe we have similar debug 
> already).

Only in destroy_display_stream at the moment. Uneasy to see impact of what the 
server sends on dropped frames (which is what I’m currently investigating).

Computation of num_out_frames in destroy_display_stream is wrong. Negative + 
unsigned + float = garbage. Don’t know what the fix is.

> 
>> 
>>> spicy -t drop_stats=100:trace_timestamp -h turbo -p 5901
>> 
>> 583120.963409:[drop_stats]id=0 #in-frames=100 #late=100 (100.00%, avg 1643.21
>> ms) #drop-on-playback=10 (10.00%)
>> 1.425560:[drop_stats]id=0 #in-frames=200 #late=200 (100.00%, avg 1605.57 ms)
>> #drop-on-playback=10 (5.00%)
>> 2.853841:[drop_stats]id=0 #in-frames=300 #late=300 (100.00%, avg 1592.95 ms)
>> #drop-on-playback=10 (3.33%)
>> 4.270006:[drop_stats]id=0 #in-frames=400 #late=400 (100.00%, avg 1587.17 ms)
>> #drop-on-playback=10 (2.50%)
>> 5.679986:[drop_stats]id=0 #in-frames=500 #late=500 (100.00%, avg 1583.45 ms)
>> #drop-on-playback=10 (2.00%)
>> 
> 
> 
> I don't see the point in tweaking the log with extra fields. If they are 
> generally useful, just have them by default.

No, not generally useful, not used in other examples. Less junk is better. Same 
as replacing display->priv->stuff with d->stuff.


> Secondly, what's the point of drop_stats=100 if you don't change it? Sounds 
> complicated to use for something we could just have by default in SPICE_DEBUG.

Are you really missing the point of interactivity? I can do that too. Here it 
is. The option works with drop_stats=99

[drop_stats]id=0 #in-frames=99 #late=99 (100.00%, avg 2995.89 ms) 
#drop-on-playback=0 (0.00%) 
[drop_stats]id=0 #in-frames=198 #late=198 (100.00%, avg 2160.48 ms) 
#drop-on-playback=3 (1.52%) 
[drop_stats]id=0 #in-frames=297 #late=297 (100.00%, avg 1881.11 ms) 
#drop-on-playback=12 (4.04%) 

But then:

Why 5? How much I want to put a tweak there and see what happens if I change 
that value.

#define STREAM_PLAYBACK_SYNC_DROP_SEQ_LEN_LIMIT 5

Why 100? What happens if you change it?

op->multi_media_time = mmtime + 100; /* workaround... */


Here is a more serious follow up with another tweaks I just pushed, 
latency_offset:

ddd@ptitpuce[traces] spice-gtk> spicy -t latency_offset=1900:drop_stats=25 -h 
turbo -p 5901 
[drop_stats]id=0 #in-frames=25 #late=0 (0.00%, avg 0.00 ms) #drop-on-playback=0 
(0.00%) 
[…]
[drop_stats]id=0 #in-frames=225 #late=0 (0.00%, avg 0.00 ms) 
#drop-on-playback=14 (6.22%) 
[drop_stats]id=0 #in-frames=250 #late=17 (6.80%, avg 2027.82 ms) 
#drop-on-playback=15 (6.00%) 
[drop_stats]id=0 #in-frames=275 #late=36 (13.09%, avg 2353.86 ms) 
#drop-on-playback=26 (9.45%) 
[drop_stats]id=0 #in-frames=300 #late=58 (19.33%, avg 2445.26 ms) 
#drop-on-playback=50 (16.67%) 
[drop_stats]id=0 #in-frames=325 #late=58 (17.85%, avg 2445.26 ms) 
#drop-on-playback=50 (15.38%)

> 
>> 
>> 3. What is actually received during the early protocol exchange? That’s
>> mostly for my curiosity, to see how chatty the protocol is, the size of
>> packets it tends to exchange, etc. To answer a question from Marc André,
>> this one and the next are tools that would immediately have shown me where
>> the macOS version was goofing up.
>> 
>>> spicy -t wire_read -h turbo -p 5901
>> [wire_read]Read 16 bytes in 0x7f8b150d85a8
>> [wire_read]:  52 45 44 51 02 00 00 00 02 00 00 00 BA 00 00 00
>> 
>> [wire_read]Read 186 bytes in 0x7f8b141c6650
>> [wire_read]:  00 00 00 00 30 81 9F 30 0D 06 09 2A 86 48 86 F7
>> [wire_read]0010:  0D 01 01 01 05 00 03 81 8D 00 30 81 89 02 81 81
>> [wire_read]0020:  00 D2 A9 FE 7B F0 36 B7 33 3C C1 F0 5E 10 50 F3
>> [wire_read]0030:  11 D3 3E 31 4A 95 AC AC 7B 0C 20 CB 57 B2 C8 1D
>> [wire_read]0040:  10 F1 E2 4A 1A F2 8F 2A 03 70 25 BB 63 C7 D6 51
>> [wire_read]0050:  D4 DA 64 3C 95 0C B6 9E A7 4E B3 3F 65 12 83 86
>> [wire_read]0060:  F4 35 F3 AC 3D C3 9A 6C C9 EE 34 D9 67 F0 8A 2D
>> [wire_read]0070:  53 4D 

Re: [Spice-devel] RFC: Lightweight tracing mechanism

[Jonathon Jongsma]

On Fri, 2017-06-09 at 10:59 +0200, Christophe de Dinechin wrote:
> > > What I see on the thread:
> > > - log categorization. This was similar to Djasa bug but I think
> > > he just
> > >   proposed to use domains in the glib log sense;
> 
> Punchcard analogy: “Printer sheet categorization. This was similar to
> the report that Djisktra had taken McCarthy's listing by mistake"
> 
> I thought it was a good idea to derive glib log domains automatically
> from spice-traces.def. So it’s there in the branch now. That being
> said, as noted above, glib does linear searches on domain names, so
> this does not scale well. In the long term, we may want to have a
> separate field in a structured log.


Responding only to this point for the moment: I don't think using
multiple glib logging domains is necessarily desirable. We already use
several logging domains, but the vast majority of logging statements
within each project use a single domain. In spice-server, that primary
log domain is "Spice", and in spice-gtk that domain is "GSpice". spice-
server also has some additional domains like "SpiceWorker" and
"SpiceDispatcher". spice-gtk also has GSpiceController (which isn't
really used much these days). 

The problem is that both spice-server and spice-gtk have a way to
enable debugging with an environment variable. But the code for
enabling the debugging only actually enables the primary domain. So
anything that is logged under a different domain does not get enabled.
(In fact, spice-gtk has 2 ways to enable logging with an environment
variable but one of the methods is the same one used for spice-server,
but it doesn't work since it actually enables logging for the "Spice"
domain which spice-gtk doesn't use.) I'm hoping to send some patches to
clean up this mess soon. 

But the upshot is that if we use multiple log domains we'll need to
make sure that if we enable debug, we enable all domains that we're
interested in. This will require a small maintenance burden (although
Christophe's approach probably handles it automatically). Or we could
use a single log domain and segment the different "categories" of log
messages somehow within that domain.

Jonathon
___
Spice-devel mailing list
Spice-devel@lists.freedesktop.org
https://lists.freedesktop.org/mailman/listinfo/spice-devel

Re: [Spice-devel] RFC: Lightweight tracing mechanism

[Frediano Ziglio]

> 
> Hi
> 
> I'll focus on your examples, as I think it's the most relevant for the
> discussion (let's avoid side-track).
> 
> - Original Message -
> 
> > > spicy -t drop_stats=100 -h turbo -p 5901
> > [drop_stats]id=0 #in-frames=100 #late=100 (100.00%, avg 1639.24 ms)
> > #drop-on-playback=8 (8.00%)
> > [drop_stats]id=0 #in-frames=200 #late=200 (100.00%, avg 1603.13 ms)
> > #drop-on-playback=8 (4.00%)
> > [drop_stats]id=0 #in-frames=300 #late=300 (100.00%, avg 1607.24 ms)
> > #drop-on-playback=20 (6.67%)
> > [drop_stats]id=0 #in-frames=400 #late=400 (100.00%, avg 1597.48 ms)
> > #drop-on-playback=20 (5.00%)
> > [drop_stats]id=0 #in-frames=500 #late=500 (100.00%, avg 1591.58 ms)
> > #drop-on-playback=20 (4.00%)
> > [drop_stats]id=0 #in-frames=600 #late=600 (100.00%, avg 1587.52 ms)
> > #drop-on-playback=20 (3.33%)
> > [drop_stats]id=0 #in-frames=700 #late=700 (100.00%, avg 1584.60 ms)
> > #drop-on-playback=20 (2.86%)
> 
> Could be in the debug log by default (I believe we have similar debug
> already).
> 

Yes, we have stream report debug.

> > 
> > > spicy -t drop_stats=100:trace_timestamp -h turbo -p 5901
> > 
> > 583120.963409:[drop_stats]id=0 #in-frames=100 #late=100 (100.00%, avg
> > 1643.21
> > ms) #drop-on-playback=10 (10.00%)
> > 1.425560:[drop_stats]id=0 #in-frames=200 #late=200 (100.00%, avg 1605.57
> > ms)
> > #drop-on-playback=10 (5.00%)
> > 2.853841:[drop_stats]id=0 #in-frames=300 #late=300 (100.00%, avg 1592.95
> > ms)
> > #drop-on-playback=10 (3.33%)
> > 4.270006:[drop_stats]id=0 #in-frames=400 #late=400 (100.00%, avg 1587.17
> > ms)
> > #drop-on-playback=10 (2.50%)
> > 5.679986:[drop_stats]id=0 #in-frames=500 #late=500 (100.00%, avg 1583.45
> > ms)
> > #drop-on-playback=10 (2.00%)
> > 
> 
> 
> I don't see the point in tweaking the log with extra fields. If they are
> generally useful, just have them by default.
> 
> Secondly, what's the point of drop_stats=100 if you don't change it? Sounds
> complicated to use for something we could just have by default in
> SPICE_DEBUG.
> 

you can specify a different value without having to change source,
compile and possible deploy. I think in this case drop_stats is the
number of statistic to collect before printing them.

> > 
> > 3. What is actually received during the early protocol exchange? That’s
> > mostly for my curiosity, to see how chatty the protocol is, the size of
> > packets it tends to exchange, etc. To answer a question from Marc André,
> > this one and the next are tools that would immediately have shown me where
> > the macOS version was goofing up.
> > 
> > > spicy -t wire_read -h turbo -p 5901
> > [wire_read]Read 16 bytes in 0x7f8b150d85a8
> > [wire_read]:  52 45 44 51 02 00 00 00 02 00 00 00 BA 00 00 00
> > 
> > [wire_read]Read 186 bytes in 0x7f8b141c6650
> > [wire_read]:  00 00 00 00 30 81 9F 30 0D 06 09 2A 86 48 86 F7
> > [wire_read]0010:  0D 01 01 01 05 00 03 81 8D 00 30 81 89 02 81 81
> > [wire_read]0020:  00 D2 A9 FE 7B F0 36 B7 33 3C C1 F0 5E 10 50 F3
> > [wire_read]0030:  11 D3 3E 31 4A 95 AC AC 7B 0C 20 CB 57 B2 C8 1D
> > [wire_read]0040:  10 F1 E2 4A 1A F2 8F 2A 03 70 25 BB 63 C7 D6 51
> > [wire_read]0050:  D4 DA 64 3C 95 0C B6 9E A7 4E B3 3F 65 12 83 86
> > [wire_read]0060:  F4 35 F3 AC 3D C3 9A 6C C9 EE 34 D9 67 F0 8A 2D
> > [wire_read]0070:  53 4D 73 46 06 CA 80 04 CF 7F 72 4A 8D 74 81 78
> > [wire_read]0080:  E8 28 39 51 7C 9E 3B C2 19 D6 BD EC B4 F7 0A 68
> > [wire_read]0090:  D3 AF D7 1F E6 93 E1 4C 23 F5 83 68 E1 7D 31 9A
> > [wire_read]00A0:  53 02 03 01 00 01 01 00 00 00 01 00 00 00 B2 00
> > [wire_read]00B0:  00 00 0B 00 00 00 09 00 00 00
> > [wire_read]Read 4 bytes in 0x109478b44
> > [wire_read]:  00 00 00 00
> > ** Message: main channel: opened
> > [wire_read]Read 6 bytes in 0x7f8b1274efb0
> > [wire_read]:  67 00 20 00 00 00
> > [wire_read]Read 32 bytes in 0x7f8b1274dff0
> > [wire_read]:  31 AE 1E 5E 01 00 00 00 03 00 00 00 02 00 00 00
> > [wire_read]0010:  01 00 00 00 0A 00 00 00 9B AF BE 0B 00 00 00 01
> > 
> 
> This is so low-level than even debug log don't make much sense. Imho when you
> need to read the byte-stream, you can just attach gdb and put a
> breakpoint/command. Then GDB allows to do a lot more interesting stuff, like
> conditional breakpoint, various print etc..
> 
> > 
> > 4. A symbolic view of the initial exchange (not all cases are covered in
> > marshal.py / demarshal.py yet, so some fields are likely missing).
> > 
> > > spicy -t marshall_read -h turbo -p 5901
> > 
> > [marshall_read]  SpiceMsgMainInit.session_id=1745897490
> > [marshall_read]  SpiceMsgMainInit.display_channels_hint=1
> > [marshall_read]  SpiceMsgMainInit.supported_mouse_modes=3
> > [marshall_read]  SpiceMsgMainInit.current_mouse_mode=2
> > [marshall_read]  SpiceMsgMainInit.agent_connected=1
> > [marshall_read]  SpiceMsgMainInit.agent_tokens=10
> > [marshall_read]  SpiceMsgMainInit.multi_media_time=226863047
> > [marshall_read] 

Re: [Spice-devel] RFC: Lightweight tracing mechanism

[Victor Toso]

Hi,

On Fri, Jun 09, 2017 at 11:25:15AM +0200, Christophe de Dinechin wrote:
> Some interesting stuff in there. Victor, do you have a repository /
> branch where I could fetch that (even if it’s stale)?

https://cgit.freedesktop.org/~victortoso/spice-common/log/?h=logs

It was far from what I intended to have but I stopped it as WIP due the
introduction of structured logging mechanism in glib (2.50+) which it
should be *easier* to implement in spice-common and less work to
introduce each domain (widgets, audio, video, channel, etc)

If you haven't check that yet (I just started reading this thread) you
can have a quick introduction to it at the link below
https://blog.gtk.org/2017/05/04/logging-and-more/

Cheers,

PS: I would love doing more/better logs/debug while not showing all of
it all the time! :)

>
> Thanks
> Christophe
> 
> > On 7 Jun 2017, at 17:39, Christophe Fergeau  wrote:
> > 
> > On Wed, Jun 07, 2017 at 11:30:24AM -0400, Marc-André Lureau wrote:
> >> Or it's not performance-sensitive, and can be in production builds and
> >> printf/structured logging & grep/query are your best friends.
> > 
> > Regarding structured logging, forgot if this old series from Victor has
> > been mentioned in this thread already or not
> > https://lists.freedesktop.org/archives/spice-devel/2016-January/025293.html
> > 
> > Christophe
> > ___
> > Spice-devel mailing list
> > Spice-devel@lists.freedesktop.org
> > https://lists.freedesktop.org/mailman/listinfo/spice-devel
> 


signature.asc
Description: PGP signature
___
Spice-devel mailing list
Spice-devel@lists.freedesktop.org
https://lists.freedesktop.org/mailman/listinfo/spice-devel

Re: [Spice-devel] RFC: Lightweight tracing mechanism

[Marc-André Lureau]

Hi

I'll focus on your examples, as I think it's the most relevant for the 
discussion (let's avoid side-track).

- Original Message -

> > spicy -t drop_stats=100 -h turbo -p 5901
> [drop_stats]id=0 #in-frames=100 #late=100 (100.00%, avg 1639.24 ms)
> #drop-on-playback=8 (8.00%)
> [drop_stats]id=0 #in-frames=200 #late=200 (100.00%, avg 1603.13 ms)
> #drop-on-playback=8 (4.00%)
> [drop_stats]id=0 #in-frames=300 #late=300 (100.00%, avg 1607.24 ms)
> #drop-on-playback=20 (6.67%)
> [drop_stats]id=0 #in-frames=400 #late=400 (100.00%, avg 1597.48 ms)
> #drop-on-playback=20 (5.00%)
> [drop_stats]id=0 #in-frames=500 #late=500 (100.00%, avg 1591.58 ms)
> #drop-on-playback=20 (4.00%)
> [drop_stats]id=0 #in-frames=600 #late=600 (100.00%, avg 1587.52 ms)
> #drop-on-playback=20 (3.33%)
> [drop_stats]id=0 #in-frames=700 #late=700 (100.00%, avg 1584.60 ms)
> #drop-on-playback=20 (2.86%)

Could be in the debug log by default (I believe we have similar debug already).

> 
> > spicy -t drop_stats=100:trace_timestamp -h turbo -p 5901
> 
> 583120.963409:[drop_stats]id=0 #in-frames=100 #late=100 (100.00%, avg 1643.21
> ms) #drop-on-playback=10 (10.00%)
> 1.425560:[drop_stats]id=0 #in-frames=200 #late=200 (100.00%, avg 1605.57 ms)
> #drop-on-playback=10 (5.00%)
> 2.853841:[drop_stats]id=0 #in-frames=300 #late=300 (100.00%, avg 1592.95 ms)
> #drop-on-playback=10 (3.33%)
> 4.270006:[drop_stats]id=0 #in-frames=400 #late=400 (100.00%, avg 1587.17 ms)
> #drop-on-playback=10 (2.50%)
> 5.679986:[drop_stats]id=0 #in-frames=500 #late=500 (100.00%, avg 1583.45 ms)
> #drop-on-playback=10 (2.00%)
> 


I don't see the point in tweaking the log with extra fields. If they are 
generally useful, just have them by default.

Secondly, what's the point of drop_stats=100 if you don't change it? Sounds 
complicated to use for something we could just have by default in SPICE_DEBUG.

> 
> 3. What is actually received during the early protocol exchange? That’s
> mostly for my curiosity, to see how chatty the protocol is, the size of
> packets it tends to exchange, etc. To answer a question from Marc André,
> this one and the next are tools that would immediately have shown me where
> the macOS version was goofing up.
> 
> > spicy -t wire_read -h turbo -p 5901
> [wire_read]Read 16 bytes in 0x7f8b150d85a8
> [wire_read]:  52 45 44 51 02 00 00 00 02 00 00 00 BA 00 00 00
> 
> [wire_read]Read 186 bytes in 0x7f8b141c6650
> [wire_read]:  00 00 00 00 30 81 9F 30 0D 06 09 2A 86 48 86 F7
> [wire_read]0010:  0D 01 01 01 05 00 03 81 8D 00 30 81 89 02 81 81
> [wire_read]0020:  00 D2 A9 FE 7B F0 36 B7 33 3C C1 F0 5E 10 50 F3
> [wire_read]0030:  11 D3 3E 31 4A 95 AC AC 7B 0C 20 CB 57 B2 C8 1D
> [wire_read]0040:  10 F1 E2 4A 1A F2 8F 2A 03 70 25 BB 63 C7 D6 51
> [wire_read]0050:  D4 DA 64 3C 95 0C B6 9E A7 4E B3 3F 65 12 83 86
> [wire_read]0060:  F4 35 F3 AC 3D C3 9A 6C C9 EE 34 D9 67 F0 8A 2D
> [wire_read]0070:  53 4D 73 46 06 CA 80 04 CF 7F 72 4A 8D 74 81 78
> [wire_read]0080:  E8 28 39 51 7C 9E 3B C2 19 D6 BD EC B4 F7 0A 68
> [wire_read]0090:  D3 AF D7 1F E6 93 E1 4C 23 F5 83 68 E1 7D 31 9A
> [wire_read]00A0:  53 02 03 01 00 01 01 00 00 00 01 00 00 00 B2 00
> [wire_read]00B0:  00 00 0B 00 00 00 09 00 00 00
> [wire_read]Read 4 bytes in 0x109478b44
> [wire_read]:  00 00 00 00
> ** Message: main channel: opened
> [wire_read]Read 6 bytes in 0x7f8b1274efb0
> [wire_read]:  67 00 20 00 00 00
> [wire_read]Read 32 bytes in 0x7f8b1274dff0
> [wire_read]:  31 AE 1E 5E 01 00 00 00 03 00 00 00 02 00 00 00
> [wire_read]0010:  01 00 00 00 0A 00 00 00 9B AF BE 0B 00 00 00 01
> 

This is so low-level than even debug log don't make much sense. Imho when you 
need to read the byte-stream, you can just attach gdb and put a 
breakpoint/command. Then GDB allows to do a lot more interesting stuff, like 
conditional breakpoint, various print etc..

> 
> 4. A symbolic view of the initial exchange (not all cases are covered in
> marshal.py / demarshal.py yet, so some fields are likely missing).
> 
> > spicy -t marshall_read -h turbo -p 5901
> 
> [marshall_read]  SpiceMsgMainInit.session_id=1745897490
> [marshall_read]  SpiceMsgMainInit.display_channels_hint=1
> [marshall_read]  SpiceMsgMainInit.supported_mouse_modes=3
> [marshall_read]  SpiceMsgMainInit.current_mouse_mode=2
> [marshall_read]  SpiceMsgMainInit.agent_connected=1
> [marshall_read]  SpiceMsgMainInit.agent_tokens=10
> [marshall_read]  SpiceMsgMainInit.multi_media_time=226863047
> [marshall_read]  SpiceMsgMainInit.ram_hint=16777216
> [marshall_read]  SpiceMsgMainName.name_len=10
> [marshall_read]  SpiceMsgPing.id=1
> [marshall_read]  SpiceMsgPing.timestamp=226863447500
> [marshall_read]  SpiceMsgPing.id=2
> [marshall_read]  SpiceMsgPing.timestamp=226863447502
> [marshall_read]  SpiceMsgPing.id=3
> [marshall_read]  SpiceMsgPing.timestamp=226863447503
> [marshall_read]  SpiceMsgChannels.num_of_channels=8
> [marshall_read]  

Re: [Spice-devel] RFC: Lightweight tracing mechanism

[Christophe de Dinechin]

Some interesting stuff in there. Victor, do you have a repository / branch 
where I could fetch that (even if it’s stale)?

Thanks
Christophe

> On 7 Jun 2017, at 17:39, Christophe Fergeau  wrote:
> 
> On Wed, Jun 07, 2017 at 11:30:24AM -0400, Marc-André Lureau wrote:
>> Or it's not performance-sensitive, and can be in production builds and
>> printf/structured logging & grep/query are your best friends.
> 
> Regarding structured logging, forgot if this old series from Victor has
> been mentioned in this thread already or not
> https://lists.freedesktop.org/archives/spice-devel/2016-January/025293.html
> 
> Christophe
> ___
> Spice-devel mailing list
> Spice-devel@lists.freedesktop.org
> https://lists.freedesktop.org/mailman/listinfo/spice-devel

___
Spice-devel mailing list
Spice-devel@lists.freedesktop.org
https://lists.freedesktop.org/mailman/listinfo/spice-devel

Re: [Spice-devel] RFC: Lightweight tracing mechanism

[Christophe de Dinechin]

This is a response to Christophe, Marc André and Frediano, but it starts with a 
top-post for context.

My intent should become clearer with actual examples. You can test the code and 
examples from the same location as before: 
https://github.com/c3d/spice-gtk/compare/master...c3d:traces and 
https://github.com/c3d/spice-common/compare/master...c3d:traces. Still very 
much WIP, but enough for demo / discussion.

Here are some tests I wanted to run for a while, and was frustrated not to be 
able to run so far.

1. Why do I drop so many frames?

> spicy -t drop_stats=100 -h turbo -p 5901 
[drop_stats]id=0 #in-frames=100 #late=100 (100.00%, avg 1639.24 ms) 
#drop-on-playback=8 (8.00%) 
[drop_stats]id=0 #in-frames=200 #late=200 (100.00%, avg 1603.13 ms) 
#drop-on-playback=8 (4.00%) 
[drop_stats]id=0 #in-frames=300 #late=300 (100.00%, avg 1607.24 ms) 
#drop-on-playback=20 (6.67%) 
[drop_stats]id=0 #in-frames=400 #late=400 (100.00%, avg 1597.48 ms) 
#drop-on-playback=20 (5.00%) 
[drop_stats]id=0 #in-frames=500 #late=500 (100.00%, avg 1591.58 ms) 
#drop-on-playback=20 (4.00%) 
[drop_stats]id=0 #in-frames=600 #late=600 (100.00%, avg 1587.52 ms) 
#drop-on-playback=20 (3.33%) 
[drop_stats]id=0 #in-frames=700 #late=700 (100.00%, avg 1584.60 ms) 
#drop-on-playback=20 (2.86%) 

This illustrates why the tweaks are an integral part of the mechanism, not just 
something entirely different that I shoehorn in.

BTW, the code in destroy_display_stream gives me a negative num_out_frames. It 
looks like the computation is invalid.


2. Follow up question to 1: does what is being reported make sense if I compare 
that to actual timing? (I’d say no…)

> spicy -t drop_stats=100:trace_timestamp -h turbo -p 5901 

583120.963409:[drop_stats]id=0 #in-frames=100 #late=100 (100.00%, avg 1643.21 
ms) #drop-on-playback=10 (10.00%) 
1.425560:[drop_stats]id=0 #in-frames=200 #late=200 (100.00%, avg 1605.57 ms) 
#drop-on-playback=10 (5.00%) 
2.853841:[drop_stats]id=0 #in-frames=300 #late=300 (100.00%, avg 1592.95 ms) 
#drop-on-playback=10 (3.33%) 
4.270006:[drop_stats]id=0 #in-frames=400 #late=400 (100.00%, avg 1587.17 ms) 
#drop-on-playback=10 (2.50%) 
5.679986:[drop_stats]id=0 #in-frames=500 #late=500 (100.00%, avg 1583.45 ms) 
#drop-on-playback=10 (2.00%) 

(The fact that the first time is absolute is not a bug, it’s in case you need 
the time of day when this happened, although this could probably be shown in a 
more friendly way)

What I don’t understand is how we can have 1.6 seconds average delay when the 
program ran for only 1.42 second… So I guess something is wrong in the way we 
exchange the initial multimedia times. I added some traces for related to 
mmtime, but I did not exploit them yet. To be investigated.


3. What is actually received during the early protocol exchange? That’s mostly 
for my curiosity, to see how chatty the protocol is, the size of packets it 
tends to exchange, etc. To answer a question from Marc André, this one and the 
next are tools that would immediately have shown me where the macOS version was 
goofing up.

> spicy -t wire_read -h turbo -p 5901 
[wire_read]Read 16 bytes in 0x7f8b150d85a8
[wire_read]:  52 45 44 51 02 00 00 00 02 00 00 00 BA 00 00 00

[wire_read]Read 186 bytes in 0x7f8b141c6650
[wire_read]:  00 00 00 00 30 81 9F 30 0D 06 09 2A 86 48 86 F7
[wire_read]0010:  0D 01 01 01 05 00 03 81 8D 00 30 81 89 02 81 81
[wire_read]0020:  00 D2 A9 FE 7B F0 36 B7 33 3C C1 F0 5E 10 50 F3
[wire_read]0030:  11 D3 3E 31 4A 95 AC AC 7B 0C 20 CB 57 B2 C8 1D
[wire_read]0040:  10 F1 E2 4A 1A F2 8F 2A 03 70 25 BB 63 C7 D6 51
[wire_read]0050:  D4 DA 64 3C 95 0C B6 9E A7 4E B3 3F 65 12 83 86
[wire_read]0060:  F4 35 F3 AC 3D C3 9A 6C C9 EE 34 D9 67 F0 8A 2D
[wire_read]0070:  53 4D 73 46 06 CA 80 04 CF 7F 72 4A 8D 74 81 78
[wire_read]0080:  E8 28 39 51 7C 9E 3B C2 19 D6 BD EC B4 F7 0A 68
[wire_read]0090:  D3 AF D7 1F E6 93 E1 4C 23 F5 83 68 E1 7D 31 9A
[wire_read]00A0:  53 02 03 01 00 01 01 00 00 00 01 00 00 00 B2 00
[wire_read]00B0:  00 00 0B 00 00 00 09 00 00 00
[wire_read]Read 4 bytes in 0x109478b44
[wire_read]:  00 00 00 00
** Message: main channel: opened
[wire_read]Read 6 bytes in 0x7f8b1274efb0
[wire_read]:  67 00 20 00 00 00
[wire_read]Read 32 bytes in 0x7f8b1274dff0
[wire_read]:  31 AE 1E 5E 01 00 00 00 03 00 00 00 02 00 00 00
[wire_read]0010:  01 00 00 00 0A 00 00 00 9B AF BE 0B 00 00 00 01


4. A symbolic view of the initial exchange (not all cases are covered in 
marshal.py / demarshal.py yet, so some fields are likely missing). 

> spicy -t marshall_read -h turbo -p 5901 

[marshall_read]  SpiceMsgMainInit.session_id=1745897490
[marshall_read]  SpiceMsgMainInit.display_channels_hint=1
[marshall_read]  SpiceMsgMainInit.supported_mouse_modes=3
[marshall_read]  SpiceMsgMainInit.current_mouse_mode=2
[marshall_read]  SpiceMsgMainInit.agent_connected=1
[marshall_read]  SpiceMsgMainInit.agent_tokens=10
[marshall_read]  

Re: [Spice-devel] RFC: Lightweight tracing mechanism

[Christophe Fergeau]

Hey,

I was about to send an email in the saim vein ;)

On Thu, Jun 08, 2017 at 10:55:55AM -0400, Frediano Ziglio wrote:
> Not much to add honestly. But maybe this thread is try to tackle too
> many things at the same time. What I see on the thread:
> - log categorization. This was similar to Djasa bug but I think he just
>   proposed to use domains in the glib log sense;
> - developer only logging/tracing/tweaks. This requiring a --enable-debug
>   option; I would agree with some additional debug code for instance to
>   check internal status or doing some test of functions or exposing some
>   code;
> - statistics. Like memory usage of different allocations. This make sense
>   if the statistics are trying to distinguish memory using application
>   level knowledge (Valgrind or other tools can distinguish using even
>   source files but can be hard to maintain such categories of memory);

> - tracing hot path code. I agree these should maybe treated in different
>   way. Honestly I fail to see these traces in spice-gtk as Marc-andre'
>   pointed out/ In the past I had done some logging were even a printf
>   was too expensive (or any formatted string by the way) but it was
>   really specific code not worth keeping at the end;

Imo systemtap or similar might be a good fit in such situations
( https://www.sourceware.org/systemtap/wiki/AddingUserSpaceProbingToApps
). Hopefully it's cheap enough.

> - internal tweaks. Tune different aspect. There are already some
>   environment variable to tweak some aspects. Not so extensive however
>   to see the introduction of a new layer of code.

I definitely would not tie this to the logging system, I think it's
marc-andré who pointed out this would get misused/confusing/...,
especially if exposed with the same commandline option as the debug
logs.


Gist of the thread to me seemed to be "do we want log
categories/filtering, and if yes, how do we do it?"

I would answer yes to the first question as Christophe is the second
person to send a patch adding this to spice-common (first attempt was
Victor's some time ago). This leaves the "how" as an open question ;)

I just wanted to note that this could be solved (on linux) with glib
structured logging and journald.
If we log using a SPICE_LOG_CATEGORY field, one can then use
"systemd-cat remote-viewer xxx", "journalctl --field SPICE_LOG_CATEGORY"
and "journalctl _COMM=remote-viewer SPICE_LOG_CATEGORY=display"
(not saying this is the perfect solution, just showing something with
minimum investment on our side).


Final note is that whichever way we decide to go, this is not going to
magically provide us with good debug log ;) And I don't think any of the
above is a prerequisite to improving that, it's easy enough to
categorize things right now with a prefix (or go through a
DEBUG(category, message..) macro if you prefer).

Christophe


signature.asc
Description: PGP signature
___
Spice-devel mailing list
Spice-devel@lists.freedesktop.org
https://lists.freedesktop.org/mailman/listinfo/spice-devel

Re: [Spice-devel] RFC: Lightweight tracing mechanism

[Frediano Ziglio]

> From: "Marc-André Lureau" 
> 
> Hi
> 
> - Original Message -
> > 
> > > On 7 Jun 2017, at 13:51, Marc-André Lureau 
> > > wrote:
> > > 
> > > Hi
> > > 
> > > - Original Message -
> > >> 
> > >>> On 6 Jun 2017, at 20:45, Marc-André Lureau
> > >>> 
> > >>> wrote:
> > >>> 
> > >>> I don't think any of these measurements couldn't be reported accurately
> > >>> with a regular log or structured log. Thus I don't understand what
> > >>> problem
> > >>> you try to solve.
> > >>> 
> > >>> Sorry, but I also have a hard time to understand what your tracing
> > >>> library
> > >>> does. Could you point to a simple example and short doc?
> > >> 
> > >> Probably should have started with that. I thought this was relatively
> > >> obvious
> > >> from the code and the comments I had put in the initial mail. Apparently
> > >> not, sorry.
> > >> 
> > >> Purpose: The tracing / tweaking mechanism (not a library, just a couple
> > >> of
> > >> macro and a multiply-included .def file) is to offer an easy, scalable,
> > >> consistent way to add debug code that is intended to stay in the code,
> > >> and
> > >> provides generally useful, yet focused information or program behavior
> > >> alterations. Examples include: showing information about a specific
> > >> subsystem (memory), showing a specific kind of frequently used
> > >> measurement
> > >> (FPS, network utilization), tweaking internal parameters eg. to make the
> > >> system more easily hit a corner case (e.g. put constrants on bandwidth
> > >> or
> > >> memory usage, tweak image compression parameters, etc.
> > >> 
> > >> This mechanism lets you add two categories of configurable values in the
> > >> code:
> > >> 1. “traces”, which are boolean flags, named “traces" because they are
> > >> most
> > >> often used to enable a specific set of runtime traces.
> > > 
> > > Ok, that's where the confusion came from. Your solution is not a a
> > > complete
> > > tracing solution (like dtrace, ust etc),
> > 
> > Those are not complete solutions for my purpose, otherwise I could use
> > them,
> > and they would have been used in Spice already.
> 
> They are not use because we don't have such problems in the first place.
> 
> > 
> > > but rather a way to have runtime debugging enabled/disabled/listed by
> > > categories, which can be used on top of glog/fprintf etc. However, it
> > > overlaps with other tracing solution that provides different means.
> > 
> > How does it overlap? If I can’t use your solutions for Spice code, then it
> > does not overlap. I think I demonstrated I can not use GTK flags, for
> > example, because they were not designed to be used outside of glib itself.
> > None of the suggestions you made so far solves my  problem. It’s not enough
> > for something to exist, be known, trusted, powerful, whatever. It first and
> > foremost has to be useful for what I want to do.
> > 
> > I have not ruled out the alternatives you talked about out of ignorance. I
> > want a scalpel to do some specific surgery, and shared the kind of surgery
> > I
> > had in mind. It’s not helpful to suggest I use a chainsaw (more powerful),
> > an ax (widely used), a Swiss army knife (standard), or a #ifdef hammer
> > (while at the same time warning me about hammer-based surgery leading to
> > dead code/patients…).
> > 
> > 
> > > As I said, I think filtering/greping log is actually more powerful, for
> > > the
> > > current logs. And structured logs will also improve the situation
> > > (query/filter on specific fields).
> > 
> > Logging everything and filtering with grep is not “powerful” at all. It’s
> > inefficient enough that in projects following that approach, most
> > developers
> > don’t leave their debug printfs in the code, no matter how useful they are.
> > I see some dead debug code in spice today for that very reason, like
> > CO_DEBUG…
> 
> CO_DEBUG can be enabled by tweaking the #if 0 line. In all cases, this code
> is unmaintained. I have put some effort in a gcoroutine library instead. But
> the thread coroutine implementation is quite useless, in fact it got removed
> in qemu recently (the origin of the implementation, they share the same
> author)
> 
> > 
> > 
> > > Now, for performance sensitive code, traditionally, #ifdef code is ok,
> > > but
> > > it tends to linger and become obsolete.
> > 
> > Which is exactly why I am not proposing #ifdef code.
> > 
> > 
> > > In spice-gtk, there is also spice_util_get_debug(), but that will enable
> > > all extra logging/measurements and may not optimal.
> > 
> > It’s very suboptimal, indeed.
> 
> It depends what for. You should first tell what you want to trace that is so
> performance sensitive that it wouldn't fit with the current log.
> 
> > 
> > > In all cases, I question the need for having such performance-sensitive
> > > code in releases, or even in upstream code, as it tends to become useless
> > > when the 

Re: [Spice-devel] RFC: Lightweight tracing mechanism

[Christophe Fergeau]

On Wed, Jun 07, 2017 at 11:30:24AM -0400, Marc-André Lureau wrote:
> Or it's not performance-sensitive, and can be in production builds and
> printf/structured logging & grep/query are your best friends.

Regarding structured logging, forgot if this old series from Victor has
been mentioned in this thread already or not
https://lists.freedesktop.org/archives/spice-devel/2016-January/025293.html

Christophe


signature.asc
Description: PGP signature
___
Spice-devel mailing list
Spice-devel@lists.freedesktop.org
https://lists.freedesktop.org/mailman/listinfo/spice-devel

Re: [Spice-devel] RFC: Lightweight tracing mechanism

[Christophe Fergeau]

On Tue, Jun 06, 2017 at 03:17:07PM +0200, Christophe de Dinechin wrote:
> >> On 23 May 2017, at 11:51, Christophe Fergeau  wrote:
> > 
> >> I think we have SPICE_DEBUG already which might make
> >> sense, another alternative would be to have a --enable-alignment-debug,
> >> or something like glib (SPICE_XXX_DEBUG=alignment:foo:bar)
> >> 
> 
> I did not find where the existing code does anything that would correspond to 
> this
> SPICE_XXX_DEBUG=alignment:foo:bar (I did ask). Any pointer? In any case,
> what I saw in glib did not respond to my needs.

There is no code for doing that, I was suggesting _adding_ such a
facility, but since one of your requirements was not to add runtime
tests in the logging path, it's probably not an option.

Christophe


signature.asc
Description: PGP signature
___
Spice-devel mailing list
Spice-devel@lists.freedesktop.org
https://lists.freedesktop.org/mailman/listinfo/spice-devel

Re: [Spice-devel] RFC: Lightweight tracing mechanism

[Marc-André Lureau]

Hi

- Original Message -
> 
> > On 7 Jun 2017, at 13:51, Marc-André Lureau 
> > wrote:
> > 
> > Hi
> > 
> > - Original Message -
> >> 
> >>> On 6 Jun 2017, at 20:45, Marc-André Lureau 
> >>> wrote:
> >>> 
> >>> I don't think any of these measurements couldn't be reported accurately
> >>> with a regular log or structured log. Thus I don't understand what
> >>> problem
> >>> you try to solve.
> >>> 
> >>> Sorry, but I also have a hard time to understand what your tracing
> >>> library
> >>> does. Could you point to a simple example and short doc?
> >> 
> >> Probably should have started with that. I thought this was relatively
> >> obvious
> >> from the code and the comments I had put in the initial mail. Apparently
> >> not, sorry.
> >> 
> >> Purpose: The tracing / tweaking mechanism (not a library, just a couple of
> >> macro and a multiply-included .def file) is to offer an easy, scalable,
> >> consistent way to add debug code that is intended to stay in the code, and
> >> provides generally useful, yet focused information or program behavior
> >> alterations. Examples include: showing information about a specific
> >> subsystem (memory), showing a specific kind of frequently used measurement
> >> (FPS, network utilization), tweaking internal parameters eg. to make the
> >> system more easily hit a corner case (e.g. put constrants on bandwidth or
> >> memory usage, tweak image compression parameters, etc.
> >> 
> >> This mechanism lets you add two categories of configurable values in the
> >> code:
> >> 1. “traces”, which are boolean flags, named “traces" because they are most
> >> often used to enable a specific set of runtime traces.
> > 
> > Ok, that's where the confusion came from. Your solution is not a a complete
> > tracing solution (like dtrace, ust etc),
> 
> Those are not complete solutions for my purpose, otherwise I could use them,
> and they would have been used in Spice already.

They are not use because we don't have such problems in the first place.

> 
> > but rather a way to have runtime debugging enabled/disabled/listed by
> > categories, which can be used on top of glog/fprintf etc. However, it
> > overlaps with other tracing solution that provides different means.
> 
> How does it overlap? If I can’t use your solutions for Spice code, then it
> does not overlap. I think I demonstrated I can not use GTK flags, for
> example, because they were not designed to be used outside of glib itself.
> None of the suggestions you made so far solves my  problem. It’s not enough
> for something to exist, be known, trusted, powerful, whatever. It first and
> foremost has to be useful for what I want to do.
> 
> I have not ruled out the alternatives you talked about out of ignorance. I
> want a scalpel to do some specific surgery, and shared the kind of surgery I
> had in mind. It’s not helpful to suggest I use a chainsaw (more powerful),
> an ax (widely used), a Swiss army knife (standard), or a #ifdef hammer
> (while at the same time warning me about hammer-based surgery leading to
> dead code/patients…).
> 
> 
> > As I said, I think filtering/greping log is actually more powerful, for the
> > current logs. And structured logs will also improve the situation
> > (query/filter on specific fields).
> 
> Logging everything and filtering with grep is not “powerful” at all. It’s
> inefficient enough that in projects following that approach, most developers
> don’t leave their debug printfs in the code, no matter how useful they are.
> I see some dead debug code in spice today for that very reason, like
> CO_DEBUG…

CO_DEBUG can be enabled by tweaking the #if 0 line. In all cases, this code is 
unmaintained. I have put some effort in a gcoroutine library instead. But the 
thread coroutine implementation is quite useless, in fact it got removed in 
qemu recently (the origin of the implementation, they share the same author)

> 
> 
> > Now, for performance sensitive code, traditionally, #ifdef code is ok, but
> > it tends to linger and become obsolete.
> 
> Which is exactly why I am not proposing #ifdef code.
> 
> 
> > In spice-gtk, there is also spice_util_get_debug(), but that will enable
> > all extra logging/measurements and may not optimal.
> 
> It’s very suboptimal, indeed.

It depends what for. You should first tell what you want to trace that is so 
performance sensitive that it wouldn't fit with the current log.

> 
> > In all cases, I question the need for having such performance-sensitive
> > code in releases, or even in upstream code, as it tends to become useless
> > when the performance problem is considered solved, or when the people
> > looking at the esoteric logs move to something else (based on my
> > experience).
> 
> There, your experience contradicts mine, but it’s entirely logical, because
> your experience seems to be based on using grep and #ifdef logs, which
> indeed suffers from the problems you point out, 

Re: [Spice-devel] RFC: Lightweight tracing mechanism

[Christophe de Dinechin]

> On 7 Jun 2017, at 13:51, Marc-André Lureau  
> wrote:
> 
> Hi
> 
> - Original Message -
>> 
>>> On 6 Jun 2017, at 20:45, Marc-André Lureau 
>>> wrote:
>>> 
>>> I don't think any of these measurements couldn't be reported accurately
>>> with a regular log or structured log. Thus I don't understand what problem
>>> you try to solve.
>>> 
>>> Sorry, but I also have a hard time to understand what your tracing library
>>> does. Could you point to a simple example and short doc?
>> 
>> Probably should have started with that. I thought this was relatively obvious
>> from the code and the comments I had put in the initial mail. Apparently
>> not, sorry.
>> 
>> Purpose: The tracing / tweaking mechanism (not a library, just a couple of
>> macro and a multiply-included .def file) is to offer an easy, scalable,
>> consistent way to add debug code that is intended to stay in the code, and
>> provides generally useful, yet focused information or program behavior
>> alterations. Examples include: showing information about a specific
>> subsystem (memory), showing a specific kind of frequently used measurement
>> (FPS, network utilization), tweaking internal parameters eg. to make the
>> system more easily hit a corner case (e.g. put constrants on bandwidth or
>> memory usage, tweak image compression parameters, etc.
>> 
>> This mechanism lets you add two categories of configurable values in the
>> code:
>> 1. “traces”, which are boolean flags, named “traces" because they are most
>> often used to enable a specific set of runtime traces.
> 
> Ok, that's where the confusion came from. Your solution is not a a complete 
> tracing solution (like dtrace, ust etc),

Those are not complete solutions for my purpose, otherwise I could use them, 
and they would have been used in Spice already.


> but rather a way to have runtime debugging enabled/disabled/listed by 
> categories, which can be used on top of glog/fprintf etc. However, it 
> overlaps with other tracing solution that provides different means.

How does it overlap? If I can’t use your solutions for Spice code, then it does 
not overlap. I think I demonstrated I can not use GTK flags, for example, 
because they were not designed to be used outside of glib itself. None of the 
suggestions you made so far solves my  problem. It’s not enough for something 
to exist, be known, trusted, powerful, whatever. It first and foremost has to 
be useful for what I want to do.

I have not ruled out the alternatives you talked about out of ignorance. I want 
a scalpel to do some specific surgery, and shared the kind of surgery I had in 
mind. It’s not helpful to suggest I use a chainsaw (more powerful), an ax 
(widely used), a Swiss army knife (standard), or a #ifdef hammer (while at the 
same time warning me about hammer-based surgery leading to dead code/patients…).


> As I said, I think filtering/greping log is actually more powerful, for the 
> current logs. And structured logs will also improve the situation 
> (query/filter on specific fields).

Logging everything and filtering with grep is not “powerful” at all. It’s 
inefficient enough that in projects following that approach, most developers 
don’t leave their debug printfs in the code, no matter how useful they are. I 
see some dead debug code in spice today for that very reason, like CO_DEBUG…


> Now, for performance sensitive code, traditionally, #ifdef code is ok, but it 
> tends to linger and become obsolete.

Which is exactly why I am not proposing #ifdef code.


> In spice-gtk, there is also spice_util_get_debug(), but that will enable all 
> extra logging/measurements and may not optimal.

It’s very suboptimal, indeed.

> In all cases, I question the need for having such performance-sensitive code 
> in releases, or even in upstream code, as it tends to become useless when the 
> performance problem is considered solved, or when the people looking at the 
> esoteric logs move to something else (based on my experience).

There, your experience contradicts mine, but it’s entirely logical, because 
your experience seems to be based on using grep and #ifdef logs, which indeed 
suffers from the problems you point out, whereas mine is based on using 
mechanisms similar to the one I just proposed, where whoever wants output X 
asks for output X and does not pollute anybody else.


> Imho, none your examples seem performance-sensitive to me, and could be in 
> the debug log by default.

I did not construct the examples to be performance-sensitive, but as 
pedagogical illustrations. But of course, the solution is specifically designed 
so that you can add fine-tuned instrumentation in performance-sensitive code. I 
hinted multiple times that this was one of the motivations for such a mechanism.

Instrumentation like this in the marshalling or read/write code would have 
helped me spot the reason the macOS client was not working, by the way.


> If you 

Re: [Spice-devel] RFC: Lightweight tracing mechanism

[Marc-André Lureau]

Hi

- Original Message -
> 
> > On 6 Jun 2017, at 20:45, Marc-André Lureau 
> > wrote:
> > 
> > I don't think any of these measurements couldn't be reported accurately
> > with a regular log or structured log. Thus I don't understand what problem
> > you try to solve.
> > 
> > Sorry, but I also have a hard time to understand what your tracing library
> > does. Could you point to a simple example and short doc?
> 
> Probably should have started with that. I thought this was relatively obvious
> from the code and the comments I had put in the initial mail. Apparently
> not, sorry.
> 
> Purpose: The tracing / tweaking mechanism (not a library, just a couple of
> macro and a multiply-included .def file) is to offer an easy, scalable,
> consistent way to add debug code that is intended to stay in the code, and
> provides generally useful, yet focused information or program behavior
> alterations. Examples include: showing information about a specific
> subsystem (memory), showing a specific kind of frequently used measurement
> (FPS, network utilization), tweaking internal parameters eg. to make the
> system more easily hit a corner case (e.g. put constrants on bandwidth or
> memory usage, tweak image compression parameters, etc.
> 
> This mechanism lets you add two categories of configurable values in the
> code:
> 1. “traces”, which are boolean flags, named “traces" because they are most
> often used to enable a specific set of runtime traces.

Ok, that's where the confusion came from. Your solution is not a a complete 
tracing solution (like dtrace, ust etc), but rather a way to have runtime 
debugging enabled/disabled/listed by categories, which can be used on top of 
glog/fprintf etc. However, it overlaps with other tracing solution that 
provides different means.

As I said, I think filtering/greping log is actually more powerful, for the 
current logs. And structured logs will also improve the situation (query/filter 
on specific fields).

Now, for performance sensitive code, traditionally, #ifdef code is ok, but it 
tends to linger and become obsolete. In spice-gtk, there is also 
spice_util_get_debug(), but that will enable all extra logging/measurements and 
may not optimal.

In all cases, I question the need for having such performance-sensitive code in 
releases, or even in upstream code, as it tends to become useless when the 
performance problem is considered solved, or when the people looking at the 
esoteric logs move to something else (based on my experience).

Imho, none your examples seem performance-sensitive to me, and could be in the 
debug log by default. If you would trace some value inside a tight loop, or hot 
path, for ex, that would be different. But who would really need it and be able 
to process that kind of data, without extra tools for analysis etc? That's 
where systemdtap/lttng etc are good at, I believe.

> 2. “tweaks”, which are integer values, used to tweak the behaviour of the
> code, e.g. to trigger rare / corner case behaviours.

Now this is even further away from tracing. Imho, existing argument parsing 
(for end-users) or environment parsing (mostly for devs, or global tweaks) are 
quite fine here. We could better document the existing environment variables, 
beside that, what does "tweaks" bring?

> 
> Traces and tweak can be configured wither using the command line, with the
> --spice-trace or -t option (e.g. -t foo, -t foo=0, -t foo:bar:baz), or using
> the SPICE_TRACES environment variable (similar syntax).
> 
> Traces and tweaks are defined in the spice-traces.def file using two macros,
> SPICE_TRACE and SPICE_TWEAK. in this .def file, you give the name of the
> trace or tweak, which must follow C syntax, the default / initial value for
> the trace or tweak, and a documentation string that will be shown by the -t
> list option.
> 
> Here are some usage models:
> 
> 1. Add focused printout (traces, probably the most frequent use case):
> 
>   a. Add a SPICE_TRACE entry in spice-traces.def, so that your traces can 
> be
>   activated with -t foo:
>   SPICE_TRACE(foo, 0, “Check for foos in the bar, and report how 
> many were
>   found”)
> 
>   b. Add the trace messages using spice_trace(foo, …):
>   spice_trace(foo, “Checked the presence of foos, found %d”, 
> foo_count());
> 
>   c. Activate the trace by giving the -t foo option to spice or setting
>   SPICE_TRACES=foo.
> 
> 2. Add a conditional behavior, e.g. report FPS statistics:
> 
>   a. Add a SPICE_TRACE entry:
>   SPICE_TRACE(fps, 0, “Report frames per second”)
> 
>   b. Add conditional code using IFTRACE:
>   IFTRACE(fps) {
>   frames++;
>   every (1 second) {
>   spice_trace(fps, “FPS=%d”, frames);
>   frames = 0;
>   }
>   }
> 
>   c. When you are 

Re: [Spice-devel] RFC: Lightweight tracing mechanism

[Christophe de Dinechin]

> On 6 Jun 2017, at 20:45, Marc-André Lureau  
> wrote:
> 
> I don't think any of these measurements couldn't be reported accurately with 
> a regular log or structured log. Thus I don't understand what problem you try 
> to solve.
> 
> Sorry, but I also have a hard time to understand what your tracing library 
> does. Could you point to a simple example and short doc?

Probably should have started with that. I thought this was relatively obvious 
from the code and the comments I had put in the initial mail. Apparently not, 
sorry.

Purpose: The tracing / tweaking mechanism (not a library, just a couple of 
macro and a multiply-included .def file) is to offer an easy, scalable, 
consistent way to add debug code that is intended to stay in the code, and 
provides generally useful, yet focused information or program behavior 
alterations. Examples include: showing information about a specific subsystem 
(memory), showing a specific kind of frequently used measurement (FPS, network 
utilization), tweaking internal parameters eg. to make the system more easily 
hit a corner case (e.g. put constraints on bandwidth or memory usage, tweak 
image compression parameters, etc).

This mechanism lets you add two categories of configurable values in the code:
1. “traces”, which are boolean flags, named “traces" because they are most 
often used to enable a specific set of runtime traces.
2. “tweaks”, which are integer values, used to tweak the behaviour of the code, 
e.g. to trigger rare / corner case behaviours.

Traces and tweak can be configured wither using the command line, with the 
--spice-trace or -t option (e.g. -t foo, -t foo=0, -t foo:bar:baz), or using 
the SPICE_TRACES environment variable (similar syntax).

Traces and tweaks are defined in the spice-traces.def file using two macros, 
SPICE_TRACE and SPICE_TWEAK. in this .def file, you give the name of the trace 
or tweak, which must follow C syntax, the default / initial value for the trace 
or tweak, and a documentation string that will be shown by the -t list option.

Here are some usage models:

1. Add focused printout (traces, probably the most frequent use case):

a. Add a SPICE_TRACE entry in spice-traces.def, so that your traces can 
be activated with -t foo:
SPICE_TRACE(foo, 0, “Check for foos in the bar, and report how 
many were found”)

b. Add the trace messages using spice_trace(foo, …):
spice_trace(foo, “Checked the presence of foos, found %d”, 
foo_count());

c. Activate the trace by giving the -t foo option to spice or setting 
SPICE_TRACES=foo.

2. Add a conditional behavior, e.g. report FPS statistics:

a. Add a SPICE_TRACE entry:
SPICE_TRACE(fps, 0, “Report frames per second”)

b. Add conditional code using IFTRACE:
IFTRACE(fps) {
frames++;
every (1 second) {
spice_trace(fps, “FPS=%d”, frames);
frames = 0;
}
}

c. When you are interested in getting the FPS stats from spice, just 
add the -t fps option or set SPICE_TRACES=fps

3. Add configurable conditional code (e.g. a fault injector)

a. Add the required SPICE_TRACE entries:
SPICE_TRACE(kaboom, 0, “Inject random errors while receiving 
packets”)
SPICE_TWEAK(kaboom_rate, 10, “Percentage of faulty packets 
triggered’”);

b. Add conditional code to trigger your fault, e.g.

fault = false;
IFTRACE(kaboom) {
if (lrand48() % 100 <= TRACE(kaboom_rate)) {
fault = true;
}
}

c. Activate the fault injector with 25% failure rate by giving the -t 
kaboom:kaboom_rate=25 option, or setting SPICE_TRACE=kaboom:kaboom_rate=25


Hope this helps.
Christophe

___
Spice-devel mailing list
Spice-devel@lists.freedesktop.org
https://lists.freedesktop.org/mailman/listinfo/spice-devel

Re: [Spice-devel] RFC: Lightweight tracing mechanism

[Marc-André Lureau]

Hi

- Original Message -
> >> 3. Scalable, and therefore as fine-grained as we need it to be. With a
> >> similar mechanism, Tao-3D has about 70 traces (see
> >> https://github.com/c3d/tao-3D/blob/master/tao/traces.tbl
> >>  for the
> >> graphic
> >> side traces), including in highly performance-sensitive paths.
> > 
> > I think we have few highly performance-sensitive paths in our code, and
> > before introducing facilities for tracing it, it would be interesting to
> > know what you want to have traced.
> 
> Let me take some examples straight from Tao3D, which I dearly miss in spice
> today (with actual output from Tao3D for the first two):
> 
> 1. fps: Report frames per second.
> 
> Time;PageNum;FPS;Exec;MaxExec;Draw;MaxDraw;GC;MaxGC;Select;MaxSelect;GCWait;MaxGCWait
> 1496761089.058;1;0.000;-1;0;-1;0;-1;0;-1;0;-1;0
> 1496761093.755;1;13.800;50;3217;9;482;1;13;0;0;0;9
> 1496761094.756;1;55.400;13;3217;3;482;0;13;0;0;0;12
> 1496761095.759;1;94.200;8;3217;2;482;0;13;0;0;0;12
> 1496761096.759;1;136.400;6;3217;2;482;0;13;0;0;0;12
> 
> 2. memory: Report memory usage on a regular basis (ideally, component by
> component, e.g. separate codecs from spice code)
> 
>NAMETOTALALLOCFREED
>  N2XL4TreeE000
>   N2XL7IntegerE 6132 1527  224
>  N2XL4RealE 4088  215 3478
>  N2XL4TextE 6132 1217  336
>  N2XL4NameE40880156640
> N2XL5InfixE3372610246  332
>N2XL6PrefixE12264 31770
>   N2XL7PostfixE 1022  2540
> N2XL5BlockE 5110 1017  112
>   N2XL7ContextE 1022   150
>   N2XL7SymbolsE 4088 14320
>   N2XL7RewriteE 9198 55190
>   ====
>   Kilobytes9820K3293K 223K
> [GCThread] Collect time 3 ms
> [GCThread] GC collect started
> [GCThread] Collect time 0 ms
> [GCThread] GC collect started
> 
> 3. bandwidth: Report network bandwidth usage (incoming and outcoming)
> 
> 4. latency: Report network observed latency
> 
> 
> > My feeling is that those performance traces don't need to be in public or
> > release code, since they are usually very specific to the problem you are
> > studying at hand, and don't need to remain checked in code.
> 
> My experience tells me the exact opposite. If you have a structure like this
> in place, you start putting a bit more investment in your traces, so that
> they can be reused later.

I would call it traces tbh, they are debug reports to me.

> 
> > 
> >> 4. Can be used to conditionally enable / disable code (other than
> >> tracing).
> >> For example, Frediano started chasing memory leaks. Let’s say he develops
> >> a
> >> nice way to track leaks. It’s an investment, we want to keep it. With this
> >> infrastructure, we could put that under -t leakcheck, and run that if we
> >> have a doubt about a memory leak.
> > 
> > Does tracing really helps with memory leak? when you have asan and
> > valgrind, really, no.
> 
> Valgrind? Running a heavily modified executable at a quarter of the speed on
> a good moon? And clearly, based on the massive memory leak I reported last
> week, such tools are not used on a regular basis.

Well, if running at quarter of the speed allows you to find the leak easily, I 
don't see much problem.

Yes, leaks often exist for a long time before they are discovered. I am not 
convinced adding yet another tool or debug info is going to help here, sadly.

> The purpose of something like -t memory is to give you a broad overview. Be
> able to say “we use 3G of memory, 1.5G of which is for graphics, 1G of which
> for cached images”. So that you know where to focus your effort. Using
> valgrind to give you that information? Tell me how.

This is typically a job for massif, and the performance hit of this tool isn't 
so bad. asan is also pretty good performance-wise.
 
> > 
> >> 5. Can be used for non-boolean values. It makes the code only marginally
> >> more
> >> complicated to add “tweaks”, i.e. integer values you can configure at
> >> run-time easily. Currently, you’d typically use environment variables or a
> >> configuration file for this, which expensive and not convenient. With this
> >> approach, add one tweak, say “max_mem”, and tweak with -t max_mem=100 to,
> >> say, limit allocations to 100M and detect leaks more easily.
> > 
> > What has this to do with tracing?
> 
> In both cases, it’s runtime configuration intended primarily for developers
>
> To better see the continuity between the two, imagine that we have a trace
> focusing on JPEG encoding. But now, if we focus on understanding JPEG
> quality, I can do something like -t jpeg -t jpeg_quality=50. So it’s really
> part of the same kind of usage patterns.

I still don't quite get why the tracing framework is involved here... aren't 
you trying to make a point for your 

Re: [Spice-devel] RFC: Lightweight tracing mechanism

[Christophe de Dinechin]

> On 6 Jun 2017, at 16:29, Marc-André Lureau  
> wrote:
> 
> Hi
> 
> - Original Message -
>> Answering two emails from Frediano and Marc-André that were asking closely
>> related questions, to avoid duplication…
>> 
>>> On 6 Jun 2017, at 13:28, Frediano Ziglio  wrote:
>>> 
>>> Would be helpful if you had recap Pavel problems. I don't remember.
>> 
>> I did not find it in email, so it was probably IRC. I remember something
>> about having to use --spice-debug for some debug messages, and glib
>> environment variables for others. Pavel, do you remember something like
>> that?
>> 
 Would you find this useful? The most difficult part being to connect that
 to existing tracing mechanisms to avoid replication of traces, while at
 the same time ensuring that the existing enabling mechanisms work as
 before.
>> 
>>> The main questions are:
>>> - what are the original problems exactly?
>> 
>> Getting focused debug output, which to me means “conditional, cheap, always
>> there". I don’t like having an “all-or-nothing” debug proposition for Spice.
>> Currently, we have SPICE_DEBUG=1 or SPICE_DEBUG=0. That’s too binary. I
>> would like SPICE_TRACES=channel:memory, for example.
>> 
>> 
>>> - why your solution is good in your opinion?
>> 
>> 1. Conditional tracing. Except by misusing domains to identify conditions, I
>> think it’s not easy to do with glib. I may be wrong, but did not find
>> anything here for example:
>> https://developer.gnome.org/glib/stable/glib-Message-Logging.html.
> 
> Personally, grep conditions covers 99% of my needs.

Not mine. If I’m investigating where some latency comes from, the last thing I 
want to is to have all-encompassing printouts that would themselves be a 
primary cause of latency.

> 
>> 
>> 2. Lightweight enough tracing that you can leave it there all the time. In
>> this implementation, adding a trace consumes one bit in memory, testing for
>> it is one memory access (plus the conditional jump, I know ;-). By contrast,
>> the cost of logging in glib is quite high, which makes little sense for
>> low-level debugging messages that are intended to be thrown away under
>> normal use.
>> 
> 
> Well, glib logging isn't meant for tracing. So it isn't used for that, and it 
> has no performance issue for regular debugging/logging.

Yes. But what I’m presently interested in are performance issues. And the 
messages I need are presently not in spice, nor is there a sufficient 
infrastructure to add them. Definitely, glib does not do what I want, see below 
for more details.


> 
>> 3. Scalable, and therefore as fine-grained as we need it to be. With a
>> similar mechanism, Tao-3D has about 70 traces (see
>> https://github.com/c3d/tao-3D/blob/master/tao/traces.tbl 
>>  for the graphic
>> side traces), including in highly performance-sensitive paths.
> 
> I think we have few highly performance-sensitive paths in our code, and 
> before introducing facilities for tracing it, it would be interesting to know 
> what you want to have traced.

Let me take some examples straight from Tao3D, which I dearly miss in spice 
today (with actual output from Tao3D for the first two):

1. fps: Report frames per second.

Time;PageNum;FPS;Exec;MaxExec;Draw;MaxDraw;GC;MaxGC;Select;MaxSelect;GCWait;MaxGCWait
1496761089.058;1;0.000;-1;0;-1;0;-1;0;-1;0;-1;0
1496761093.755;1;13.800;50;3217;9;482;1;13;0;0;0;9
1496761094.756;1;55.400;13;3217;3;482;0;13;0;0;0;12
1496761095.759;1;94.200;8;3217;2;482;0;13;0;0;0;12
1496761096.759;1;136.400;6;3217;2;482;0;13;0;0;0;12

2. memory: Report memory usage on a regular basis (ideally, component by 
component, e.g. separate codecs from spice code)

   NAMETOTALALLOCFREED
 N2XL4TreeE000
  N2XL7IntegerE 6132 1527  224
 N2XL4RealE 4088  215 3478
 N2XL4TextE 6132 1217  336
 N2XL4NameE40880156640
N2XL5InfixE3372610246  332
   N2XL6PrefixE12264 31770
  N2XL7PostfixE 1022  2540
N2XL5BlockE 5110 1017  112
  N2XL7ContextE 1022   150
  N2XL7SymbolsE 4088 14320
  N2XL7RewriteE 9198 55190
  ====
  Kilobytes9820K3293K 223K
[GCThread] Collect time 3 ms
[GCThread] GC collect started
[GCThread] Collect time 0 ms
[GCThread] GC collect started

3. bandwidth: Report network bandwidth usage (incoming and outcoming)

4. latency: Report network observed latency


> My feeling is that those performance traces don't need to be in public or 
> release code, since they are usually very specific to the problem you are 
> studying at hand, and don't need to remain checked in code.

My experience tells me the exact opposite. If you have a structure like this in 
place, you start putting a bit more 

Re: [Spice-devel] RFC: Lightweight tracing mechanism

[Pavel Grunt]

On Tue, 2017-06-06 at 15:17 +0200, Christophe de Dinechin wrote:
> Answering two emails from Frediano and Marc-André that were asking
> closely related questions, to avoid duplication…
> > On 6 Jun 2017, at 13:28, Frediano Ziglio 
> > wrote:
> > 
> > Would be helpful if you had recap Pavel problems. I don't
> > remember.
> 
> I did not find it in email, so it was probably IRC. I remember
> something about having to use --spice-debug for some debug messages,
> and glib environment variables for others. Pavel, do you remember
> something like that? 

mingw client has an issue with --spice-debug, it enables it only for
spice glib library, not for spice gtk lib. Using the envar avoids the
issue

> > > Would you find this useful? The most difficult part being to
> > > connect that to existing tracing mechanisms to avoid replication
> > > of traces, while at the same time ensuring that the existing
> > > enabling mechanisms work as before.
> > The main questions are:
> > - what are the original problems exactly?
> 
> Getting focused debug output, which to me means “conditional, cheap,
> always there". I don’t like having an “all-or-nothing” debug
> proposition for Spice. Currently, we have SPICE_DEBUG=1 or
> SPICE_DEBUG=0. That’s too binary. I would like
> SPICE_TRACES=channel:memory, for example.
> 
> 
> > - why your solution is good in your opinion?
> 
> 1. Conditional tracing. Except by misusing domains to identify
> conditions, I think it’s not easy to do with glib. I may be wrong,
> but did not find anything here for example: https://developer.gnome.
> org/glib/stable/glib-Message-Logging.html.
> 
> 2. Lightweight enough tracing that you can leave it there all the
> time. In this implementation, adding a trace consumes one bit in
> memory, testing for it is one memory access (plus the conditional
> jump, I know ;-). By contrast, the cost of logging in glib is quite
> high, which makes little sense for low-level debugging messages that
> are intended to be thrown away under normal use.
> 
> 3. Scalable, and therefore as fine-grained as we need it to be. With
> a similar mechanism, Tao-3D has about 70 traces (see https://github.
> com/c3d/tao-3D/blob/master/tao/traces.tbl for the graphic side
> traces), including in highly performance-sensitive paths.
> 
> 4. Can be used to conditionally enable / disable code (other than
> tracing). For example, Frediano started chasing memory leaks. Let’s
> say he develops a nice way to track leaks. It’s an investment, we
> want to keep it. With this infrastructure, we could put that under
> -t leakcheck, and run that if we have a doubt about a memory leak.
> 
> 5. Can be used for non-boolean values. It makes the code only
> marginally more complicated to add “tweaks”, i.e. integer values you
> can configure at run-time easily. Currently, you’d typically use
> environment variables or a configuration file for this, which
> expensive and not convenient. With this approach, add one tweak, say
> “max_mem”, and tweak with -t max_mem=100 to, say, limit allocations
> to 100M and detect leaks more easily.
> 
> 6. Self-documented. Using spicy -t list gives you a list of possible
> tweaks. And all messages come with a trace name prefix, so if you
> later want to get that specific message, you know what to pass to
> -t. 
> 
> I don’t think glib does any of these 6 points. I may be wrong, and I
> am willing to use glib instead where it provides a sufficiently good
> solution.
> 
> 
> > - did you try other options (like Marc-andre' suggested) ?
> 
> Yes. Christophe F already suggested them:
> 
> > > On 23 May 2017, at 11:51, Christophe Fergeau  > > m> wrote:
> > > I think we have SPICE_DEBUG already which might make
> > > sense, another alternative would be to have a --enable-
> > > alignment-debug,
> > > or something like glib (SPICE_XXX_DEBUG=alignment:foo:bar)
> > > 
> 
> I did not find where the existing code does anything that would
> correspond to this
> SPICE_XXX_DEBUG=alignment:foo:bar (I did ask). Any pointer? In any
> case,
> what I saw in glib did not respond to my needs.
> 
> 
> > Reading the code is not clear where exactly you implemented the
> > different domains
> > suggested by the bug report.
> 
> I didn’t. I propose that we do something finer-grained.
> 
> 
> > Did you just coded SSL as an example?
> 
> Yes. I don’t want to convert everything if I sense that the team
> does not like it at all.
> So I only did two in common (ssl and rect) and one in gtk (channel,
> by modifying CHANNEL_DEBUG)
> 
> > Also you introduced a new "TRACE" logging level; why DEBUG was not
> > enough?
> 
> This is transitional, to be able to distinguish preserve existing
> behavior for existing debug code
> (always go to the glib log) while TRACE code can also go to standard
> error.
> 
> 
> 
> 
> > On 6 Jun 2017, at 12:54, Marc-André Lureau  > t.com> wrote:
> > 
> > I would rather stick to glib structured logging (and have
> > 

Re: [Spice-devel] RFC: Lightweight tracing mechanism

[Marc-André Lureau]

Hi

- Original Message -
> Answering two emails from Frediano and Marc-André that were asking closely
> related questions, to avoid duplication…
> 
> > On 6 Jun 2017, at 13:28, Frediano Ziglio  wrote:
> > 
> > Would be helpful if you had recap Pavel problems. I don't remember.
> 
> I did not find it in email, so it was probably IRC. I remember something
> about having to use --spice-debug for some debug messages, and glib
> environment variables for others. Pavel, do you remember something like
> that?
>  
> >> Would you find this useful? The most difficult part being to connect that
> >> to existing tracing mechanisms to avoid replication of traces, while at
> >> the same time ensuring that the existing enabling mechanisms work as
> >> before.
> 
> > The main questions are:
> > - what are the original problems exactly?
> 
> Getting focused debug output, which to me means “conditional, cheap, always
> there". I don’t like having an “all-or-nothing” debug proposition for Spice.
> Currently, we have SPICE_DEBUG=1 or SPICE_DEBUG=0. That’s too binary. I
> would like SPICE_TRACES=channel:memory, for example.
> 
> 
> > - why your solution is good in your opinion?
> 
> 1. Conditional tracing. Except by misusing domains to identify conditions, I
> think it’s not easy to do with glib. I may be wrong, but did not find
> anything here for example:
> https://developer.gnome.org/glib/stable/glib-Message-Logging.html.

Personally, grep conditions covers 99% of my needs.

> 
> 2. Lightweight enough tracing that you can leave it there all the time. In
> this implementation, adding a trace consumes one bit in memory, testing for
> it is one memory access (plus the conditional jump, I know ;-). By contrast,
> the cost of logging in glib is quite high, which makes little sense for
> low-level debugging messages that are intended to be thrown away under
> normal use.
> 

Well, glib logging isn't meant for tracing. So it isn't used for that, and it 
has no performance issue for regular debugging/logging.

> 3. Scalable, and therefore as fine-grained as we need it to be. With a
> similar mechanism, Tao-3D has about 70 traces (see
> https://github.com/c3d/tao-3D/blob/master/tao/traces.tbl for the graphic
> side traces), including in highly performance-sensitive paths.

I think we have few highly performance-sensitive paths in our code, and before 
introducing facilities for tracing it, it would be interesting to know what you 
want to have traced. My feeling is that those performance traces don't need to 
be in public or release code, since they are usually very specific to the 
problem you are studying at hand, and don't need to remain checked in code.
 
> 4. Can be used to conditionally enable / disable code (other than tracing).
> For example, Frediano started chasing memory leaks. Let’s say he develops a
> nice way to track leaks. It’s an investment, we want to keep it. With this
> infrastructure, we could put that under -t leakcheck, and run that if we
> have a doubt about a memory leak.

Does tracing really helps with memory leak? when you have asan and valgrind, 
really, no.

> 5. Can be used for non-boolean values. It makes the code only marginally more
> complicated to add “tweaks”, i.e. integer values you can configure at
> run-time easily. Currently, you’d typically use environment variables or a
> configuration file for this, which expensive and not convenient. With this
> approach, add one tweak, say “max_mem”, and tweak with -t max_mem=100 to,
> say, limit allocations to 100M and detect leaks more easily.

What has this to do with tracing?

> 6. Self-documented. Using spicy -t list gives you a list of possible tweaks.
> And all messages come with a trace name prefix, so if you later want to get
> that specific message, you know what to pass to -t.
> 

I suppose it lists the various domains? or all trace points?

For the later, it's probably hard to keep it stable and without associated 
documentation, it isn't of much help imho.

In any case, I don't think it make sense to provide this in a user command 
line. Using environment variable allows to tweak any program using your library 
instead, and may be changed at run time.

> I don’t think glib does any of these 6 points. I may be wrong, and I am
> willing to use glib instead where it provides a sufficiently good solution.
> 
> 
> > - did you try other options (like Marc-andre' suggested) ?
> 
> Yes. Christophe F already suggested them:
> 
> >> On 23 May 2017, at 11:51, Christophe Fergeau  wrote:
> > 
> >> I think we have SPICE_DEBUG already which might make
> >> sense, another alternative would be to have a --enable-alignment-debug,
> >> or something like glib (SPICE_XXX_DEBUG=alignment:foo:bar)
> >> 
> 
> I did not find where the existing code does anything that would correspond to
> this
> SPICE_XXX_DEBUG=alignment:foo:bar (I did ask). Any pointer? In any case,
> what I saw in glib did not respond to my needs.
> 

Re: [Spice-devel] RFC: Lightweight tracing mechanism

[Christophe de Dinechin]

Answering two emails from Frediano and Marc-André that were asking closely 
related questions, to avoid duplication…

> On 6 Jun 2017, at 13:28, Frediano Ziglio  wrote:
> 
> Would be helpful if you had recap Pavel problems. I don't remember.

I did not find it in email, so it was probably IRC. I remember something about 
having to use --spice-debug for some debug messages, and glib environment 
variables for others. Pavel, do you remember something like that?
 
>> Would you find this useful? The most difficult part being to connect that to 
>> existing tracing mechanisms to avoid replication of traces, while at the 
>> same time ensuring that the existing enabling mechanisms work as before.

> The main questions are:
> - what are the original problems exactly?

Getting focused debug output, which to me means “conditional, cheap, always 
there". I don’t like having an “all-or-nothing” debug proposition for Spice. 
Currently, we have SPICE_DEBUG=1 or SPICE_DEBUG=0. That’s too binary. I would 
like SPICE_TRACES=channel:memory, for example.


> - why your solution is good in your opinion?

1. Conditional tracing. Except by misusing domains to identify conditions, I 
think it’s not easy to do with glib. I may be wrong, but did not find anything 
here for example: 
https://developer.gnome.org/glib/stable/glib-Message-Logging.html.

2. Lightweight enough tracing that you can leave it there all the time. In this 
implementation, adding a trace consumes one bit in memory, testing for it is 
one memory access (plus the conditional jump, I know ;-). By contrast, the cost 
of logging in glib is quite high, which makes little sense for low-level 
debugging messages that are intended to be thrown away under normal use.

3. Scalable, and therefore as fine-grained as we need it to be. With a similar 
mechanism, Tao-3D has about 70 traces (see 
https://github.com/c3d/tao-3D/blob/master/tao/traces.tbl for the graphic side 
traces), including in highly performance-sensitive paths.

4. Can be used to conditionally enable / disable code (other than tracing). For 
example, Frediano started chasing memory leaks. Let’s say he develops a nice 
way to track leaks. It’s an investment, we want to keep it. With this 
infrastructure, we could put that under -t leakcheck, and run that if we have a 
doubt about a memory leak.

5. Can be used for non-boolean values. It makes the code only marginally more 
complicated to add “tweaks”, i.e. integer values you can configure at run-time 
easily. Currently, you’d typically use environment variables or a configuration 
file for this, which expensive and not convenient. With this approach, add one 
tweak, say “max_mem”, and tweak with -t max_mem=100 to, say, limit allocations 
to 100M and detect leaks more easily.

6. Self-documented. Using spicy -t list gives you a list of possible tweaks. 
And all messages come with a trace name prefix, so if you later want to get 
that specific message, you know what to pass to -t. 

I don’t think glib does any of these 6 points. I may be wrong, and I am willing 
to use glib instead where it provides a sufficiently good solution.


> - did you try other options (like Marc-andre' suggested) ?

Yes. Christophe F already suggested them:

>> On 23 May 2017, at 11:51, Christophe Fergeau  wrote:
> 
>> I think we have SPICE_DEBUG already which might make
>> sense, another alternative would be to have a --enable-alignment-debug,
>> or something like glib (SPICE_XXX_DEBUG=alignment:foo:bar)
>> 

I did not find where the existing code does anything that would correspond to 
this
SPICE_XXX_DEBUG=alignment:foo:bar (I did ask). Any pointer? In any case,
what I saw in glib did not respond to my needs.


> 
> Reading the code is not clear where exactly you implemented the different 
> domains
> suggested by the bug report.

I didn’t. I propose that we do something finer-grained.


> Did you just coded SSL as an example?

Yes. I don’t want to convert everything if I sense that the team does not like 
it at all.
So I only did two in common (ssl and rect) and one in gtk (channel, by 
modifying CHANNEL_DEBUG)

> Also you introduced a new "TRACE" logging level; why DEBUG was not enough?

This is transitional, to be able to distinguish preserve existing behavior for 
existing debug code
(always go to the glib log) while TRACE code can also go to standard error.



> On 6 Jun 2017, at 12:54, Marc-André Lureau  
> wrote:
> 
> I would rather stick to glib structured logging (and have compatibility code 
> for glib < 2.50),

This does not address my problem. The structured logging is “how to log” (i.e. 
it is a replacement for “printf”). My patch set is intended to define *what* to 
log and *when* (i.e. it is a special form of command-line driven “if”). 
Ultimately, my implementation uses either stderr or glib old log or both, but 
adding a structured-log option would be relatively easy (although in a 
different 

Re: [Spice-devel] RFC: Lightweight tracing mechanism

[Frediano Ziglio]

> > On 23 May 2017, at 12:55, Victor Toso < victort...@redhat.com > wrote:
> 

> > On Tue, May 23, 2017 at 11:51:01AM +0200, Christophe Fergeau wrote:
> 

> > > or something like glib (SPICE_XXX_DEBUG=alignment:foo:bar)
> > 
> 

> > Just to point out that we have a bug for this [0] and IMHO it would be
> 
> > the best approach but it would take some effort to have it besides the
> 
> > glib that we would need is 2.50 (current required is 2.36)
> 
> > [0] https://bugs.freedesktop.org/show_bug.cgi?id=91838
> 

These seems to suggest the usage of glib for more refined control. 

> Pavel also recently commented on having some trouble with --spice-debug and
> SPICE_DEBUG and…

Would be helpful if you had recap Pavel problems. I don't remember. 

> For what it’s worth, I’ve implemented in several of my own projects a low-key
> tracing facility which for Spice would basically look like this:

> https://github.com/c3d/spice-common/compare/cast-warnings...c3d:traces
> https://github.com/c3d/spice-gtk/compare/cast-warnings...c3d:traces

> Specifically:

> - Define available traces in spice-traces.def file, e.g.:

> // SPICE_TRACE(name, default_value, info)
> SPICE_TRACE(foo, false, “Talk about foo")
> SPICE_TRACE(bar, true, “A bar is a good thing, enabled by default")
> #undef SPICE_TRACE

> - Declare a structure holding one bit per trace flag, as follows:

> extern struct spice_traces {
> #define SPICE_TRACE(name, init, info) bool name:1;
> #include “spice-traces.def”
> } spice_traces;

> - Initialize it in log.c, as follows:

> struct spice_traces spice_traces = {
> #define SPICE_TRACE(name, init, info) init,
> #include “spice-traces.def"
> };

> - In log.c, add a function to deal with passing trace options either from
> command-line or environemnt

> - In log.h, add macros to quickly test traces:

> #define TRACE(name) (spice_traces.name)
> #define IFTRACE(name) if (TRACE(name))
> #define spice_trace(name, …) IFTRACE(name) spice_debug(__VA_ARGS__)

> - In spice-option.c, add code to deal with testing the options.

> Would you find this useful? The most difficult part being to connect that to
> existing tracing mechanisms to avoid replication of traces, while at the
> same time ensuring that the existing enabling mechanisms work as before.

> Christophe

The main questions are: 
- what are the original problems exactly? 
- why your solution is good in your opinion? 
- did you try other options (like Marc-andre' suggested) ? 

Reading the code is not clear where exactly you implemented the different 
domains 
suggested by the bug report. Did you just coded SSL as an example? 
Also you introduced a new "TRACE" logging level; why DEBUG was not enough? 

Frediano 
___
Spice-devel mailing list
Spice-devel@lists.freedesktop.org
https://lists.freedesktop.org/mailman/listinfo/spice-devel

Re: [Spice-devel] RFC: Lightweight tracing mechanism

[Marc-André Lureau]

Hi

- Original Message -
> 
> 
> 
> 
> On 23 May 2017, at 12:55, Victor Toso < victort...@redhat.com > wrote:
> 
> On Tue, May 23, 2017 at 11:51:01AM +0200, Christophe Fergeau wrote:
> 
> 
> 
> or something like glib (SPICE_XXX_DEBUG=alignment:foo:bar)
> 
> Just to point out that we have a bug for this [0] and IMHO it would be
> the best approach but it would take some effort to have it besides the
> glib that we would need is 2.50 (current required is 2.36)
> [0] https://bugs.freedesktop.org/show_bug.cgi?id=91838
> 
> Pavel also recently commented on having some trouble with --spice-debug and
> SPICE_DEBUG and…
> 
> For what it’s worth, I’ve implemented in several of my own projects a low-key
> tracing facility which for Spice would basically look like this:
> 
> https://github.com/c3d/spice-common/compare/cast-warnings...c3d:traces
> https://github.com/c3d/spice-gtk/compare/cast-warnings...c3d:traces
> 
> Specifically:
> 
> - Define available traces in spice-traces.def file, e.g.:
> 
> // SPICE_TRACE(name, default_value, info)
> SPICE_TRACE(foo, false, “Talk about foo")
> SPICE_TRACE(bar, true, “A bar is a good thing, enabled by default")
> #undef SPICE_TRACE
> 
> - Declare a structure holding one bit per trace flag, as follows:
> 
> extern struct spice_traces {
> #define SPICE_TRACE(name, init, info) bool name:1;
> #include “spice-traces.def”
> } spice_traces;
> 
> - Initialize it in log.c, as follows:
> 
> struct spice_traces spice_traces = {
> #define SPICE_TRACE(name, init, info) init,
> #include “spice-traces.def"
> };
> 
> - In log.c, add a function to deal with passing trace options either from
> command-line or environemnt
> 
> - In log.h, add macros to quickly test traces:
> 
> #define TRACE(name) (spice_traces.name)
> #define IFTRACE(name) if (TRACE(name))
> #define spice_trace(name, …) IFTRACE(name) spice_debug(__VA_ARGS__)
> 
> - In spice-option.c, add code to deal with testing the options.
> 
> Would you find this useful? The most difficult part being to connect that to
> existing tracing mechanisms to avoid replication of traces, while at the
> same time ensuring that the existing enabling mechanisms work as before.
> 
> 

I would rather stick to glib structured logging (and have compatibility code 
for glib < 2.50), or try to find a way to use qemu tracing facility 
(ftrace/lttng etc).

Imho any improvement to logging & tracing should go to these respective 
projects if possible, since they have better chances to be common & maintain & 
with a set of tools to help you analyze with the rest of the system.
___
Spice-devel mailing list
Spice-devel@lists.freedesktop.org
https://lists.freedesktop.org/mailman/listinfo/spice-devel