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]00000000:  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]00000000:  00 00 00 00 30 81 9F 30 0D 06 09 2A 86 48 86 F7
[wire_read]00000010:  0D 01 01 01 05 00 03 81 8D 00 30 81 89 02 81 81
[wire_read]00000020:  00 D2 A9 FE 7B F0 36 B7 33 3C C1 F0 5E 10 50 F3
[wire_read]00000030:  11 D3 3E 31 4A 95 AC AC 7B 0C 20 CB 57 B2 C8 1D
[wire_read]00000040:  10 F1 E2 4A 1A F2 8F 2A 03 70 25 BB 63 C7 D6 51
[wire_read]00000050:  D4 DA 64 3C 95 0C B6 9E A7 4E B3 3F 65 12 83 86
[wire_read]00000060:  F4 35 F3 AC 3D C3 9A 6C C9 EE 34 D9 67 F0 8A 2D
[wire_read]00000070:  53 4D 73 46 06 CA 80 04 CF 7F 72 4A 8D 74 81 78
[wire_read]00000080:  E8 28 39 51 7C 9E 3B C2 19 D6 BD EC B4 F7 0A 68
[wire_read]00000090:  D3 AF D7 1F E6 93 E1 4C 23 F5 83 68 E1 7D 31 9A
[wire_read]000000A0:  53 02 03 01 00 01 01 00 00 00 01 00 00 00 B2 00
[wire_read]000000B0:  00 00 0B 00 00 00 09 00 00 00
[wire_read]Read 4 bytes in 0x109478b44
[wire_read]00000000:  00 00 00 00
** Message: main channel: opened
[wire_read]Read 6 bytes in 0x7f8b1274efb0
[wire_read]00000000:  67 00 20 00 00 00
[wire_read]Read 32 bytes in 0x7f8b1274dff0
[wire_read]00000000:  31 AE 1E 5E 01 00 00 00 03 00 00 00 02 00 00 00
[wire_read]00000010:  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]  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]  SpiceChannelId.type=2
[marshall_read]  SpiceChannelId.id=0
[marshall_read]  SpiceChannelId.type=4
[marshall_read]  SpiceChannelId.id=0
[marshall_read]  SpiceChannelId.type=9
[marshall_read]  SpiceChannelId.id=1
[marshall_read]  SpiceChannelId.type=9
[marshall_read]  SpiceChannelId.id=0
[marshall_read]  SpiceChannelId.type=6
[marshall_read]  SpiceChannelId.id=0
[marshall_read]  SpiceChannelId.type=5
[marshall_read]  SpiceChannelId.id=0
[marshall_read]  SpiceChannelId.type=2
[marshall_read]  SpiceChannelId.id=1
[marshall_read]  SpiceChannelId.type=3
[marshall_read]  SpiceChannelId.id=0

I believe this example illustrates well the kind of instrumentation that is 
useful and convenient to have there all the time, but that we don’t want to 
send to a debug log if not explicitly requested. I see no reason to pollute 
even a structured log with that stuff, unless I actually need it. One line per 
field with a common structure on purpose, to make it easy to grep / awk the 
data you want.


5. Mouse movements, with timing and modifiers:

I think that something similar to this may be useful in understanding the 
recent caps-lock bug.

ddd@ptitpuce[traces] spice-gtk> spicy -t mouse_move:trace_timestamp -h turbo -p 
5901 

0.000035:[mouse_move]inputs-3:0: pos=505,299 delta=0,0 btn=0 dpy=0 cnt=0 
mod=0x0 lck=0x0
0.024286:[mouse_move]inputs-3:0: pos=482,257 delta=0,0 btn=0 dpy=0 cnt=1 mod=0 
lck=0
0.024299:[mouse_move]inputs-3:0: pos=482,257 delta=0,0 btn=0 dpy=0 cnt=1 
mod=0x0 lck=0x0
0.032647:[mouse_move]inputs-3:0: pos=439,182 delta=0,0 btn=0 dpy=0 cnt=2 mod=0 
lck=0
0.032658:[mouse_move]inputs-3:0: pos=439,182 delta=0,0 btn=0 dpy=0 cnt=2 
mod=0x0 lck=0x0
0.068790:[mouse_move]inputs-3:0: pos=401,129 delta=0,0 btn=0 dpy=0 cnt=3 mod=0 
lck=0
0.068804:[mouse_move]inputs-3:0: pos=401,129 delta=0,0 btn=0 dpy=0 cnt=3 
mod=0x0 lck=0x0
0.097703:[mouse_move]inputs-3:0: pos=392,115 delta=0,0 btn=0 dpy=0 cnt=0 mod=0 
lck=0
0.097716:[mouse_move]inputs-3:0: pos=392,115 delta=0,0 btn=0 dpy=0 cnt=0 
mod=0x0 lck=0x0
0.118830:[mouse_move]inputs-3:0: pos=379,95 delta=0,0 btn=0 dpy=0 cnt=1 mod=0 
lck=0
0.118842:[mouse_move]inputs-3:0: pos=379,95 delta=0,0 btn=0 dpy=0 cnt=1 mod=0x0 


6. Using the standard glib log in addition to stdout (showing that trace name 
are visible as Spice[x] domains)
Note that after exploring the glib logging code, I am relatively concerned 
about the performance if there are very large numbers of domains, since they 
seem to be doing linear searches everywhere… You can of course set 
trace_stdout=0 if you only want the glib log. Permanently in SPICE_TRACES in 
your .bashrc if that’s your preference.

ddd@ptitpuce[traces] spice-gtk> G_MESSAGES_DEBUG=all spicy -t 
mouse_move:trace_stdlog -h turbo -p 5901 

[mouse_move]inputs-3:0: pos=330,166 delta=0,0 btn=0 dpy=0 cnt=0 mod=0 lck=0
(spicy:57464): Spice[mouse_move]-DEBUG: 
channel-inputs.c:346:spice_inputs_position: inputs-3:0: pos=330,166 delta=0,0 
btn=0 dpy=0 cnt=0 mod=0 lck=0
[mouse_move]inputs-3:0: pos=330,166 delta=0,0 btn=0 dpy=0 cnt=0 mod=0x0 lck=0x0
(spicy:57464): Spice[mouse_move]-DEBUG: channel-inputs.c:188:mouse_position: 
inputs-3:0: pos=330,166 delta=0,0 btn=0 dpy=0 cnt=0 mod=0x0 lck=0x0
[mouse_move]inputs-3:0: pos=322,155 delta=0,0 btn=0 dpy=0 cnt=1 mod=0 lck=0
(spicy:57464): Spice[mouse_move]-DEBUG: 
channel-inputs.c:346:spice_inputs_position: inputs-3:0: pos=322,155 delta=0,0 
btn=0 dpy=0 cnt=1 mod=0 lck=0
[mouse_move]inputs-3:0: pos=322,155 delta=0,0 btn=0 dpy=0 cnt=1 mod=0x0 lck=0x0
(spicy:57464): Spice[mouse_move]-DEBUG: channel-inputs.c:188:mouse_position: 
inputs-3:0: pos=322,155 delta=0,0 btn=0 dpy=0 cnt=1 mod=0x0 lck=0x0
[mouse_move]inputs-3:0: pos=308,139 delta=0,0 btn=0 dpy=0 cnt=2 mod=0 lck=0
(spicy:57464): Spice[mouse_move]-DEBUG: 
channel-inputs.c:346:spice_inputs_position: inputs-3:0: pos=308,139 delta=0,0 
btn=0 dpy=0 cnt=2 mod=0 lck=0
[mouse_move]inputs-3:0: pos=308,139 delta=0,0 btn=0 dpy=0 cnt=2 mod=0x0 lck=0x0


7. List of the current traces. This is basically from looking at the various 
CHANNEL_DEBUG statements and splitting them into subcategories, plus a few 
additional instrumentations I had put in place over time but, until now, had to 
cherry pick every time I wanted it. Looks better with a fixed font.

List of available traces
            canvas: Canvas-related information
      capabilities: Channel capabilities
           channel: Channel debug (CHANNEL_DEBUG macro)
   channel_connect: Channel connection / disconnection
    channel_cursor: Channel cursor information
    channel_notify: Channel notifications
      channel_read: Reading data from channels
      channel_wait: Channel waits
     channel_write: Writing data to channels
         clipboard: Clipboard-related information
             debug: General debug (SPICE_DEBUG macro)
           display: Display-related information
        drop_stats: Show drop statistics every N input frame
              init: Initialization
                gl: OpenGL-related information
     marshall_read: De-marshalling data for reading
    marshall_write: Marshalling data for writing
         migration: Migration events
            mmtime: Multimedia time measurements
          monitors: Monitor-related information
             mouse: Mouse-related information, except moves
        mouse_move: Individual mouse movements (chatty)
              port: Channel port information
              rect: Rectangles debug
         smartcard: Smartcard data
             sound: Sound playback
        sound_data: Sound data hex dump
        sound_mode: Sound mode hex dump
               ssl: SSL verification
              sasl: SASL verification
           surface: Surface-related information
    trace_function: Show function in trace output
    trace_location: Show code location in trace output
        trace_name: Show trace names in trace output
         trace_set: Show which traces are being set
      trace_stdlog: Send traces to glib logging facility
      trace_stdout: Send traces to standard output
   trace_timestamp: Show time stamp in trace output
               usb: USB redirection
               tls: TLS negociations
            webdav: WebDAV (directory redirection)
       webdav_data: WebDAV hex dump
         wire_read: Hex dump of data read on the wire
        wire_write: Hex dump of data read on the wire

8. Performance testing:

All numbers in seconds for 1M iterations, showing a counter, best of 3 runs on 
a non-loaded machine. The bottom line is that this approach beats the crap out 
of the existing code, by a factor of 500+ for non-used trace code (I also tried 
g_debug, it’s somewhere in the middle, closer to spice_log).

Trace inactive:
spice_trace: 0.0021
spice_log: 1.26

Trace shown on console:
spice_trace: 2.11
spice_log: 8.07

Active trace, grep filtering 20 “relevant" entries
spice_trace: 0.36
spice_log: 4.37

Sending to file in /tmp:
spice_trace: 0.31, file is 29M
spice_log: 4.31, file is 79M


That being exposed, I can answer the questions with I hope a common 
understanding of what this is about.


> On 8 Jun 2017, at 17:38, Christophe Fergeau <cferg...@redhat.com> wrote:
> 
> 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.

Dissenting opinion: I don’t see value in artificially separating the input and 
output sides of program analysis. It’s like saying “we don’t need input and 
output in the same device, it makes more sense to have people who want to feed 
the computer with data in the punchcard room, and people who want to get the 
results in the printer room.”. Problem is: it’s not really good for 
interactivity.

This is why I will reuse the punchcard analogy below. Please do not read this 
as sarcastic. I’m trying to make you smile and understand my point of view at 
the same time. If you feel it is condescending or something like that, please 
realize that this is the exact opposite of what I’m trying to do (humor is a 
difficult thing, humor that comes with a warning is generally terrible :-)


>> 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.


>> - 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;

Punchcard analogy: “Program configuration. This requiring a special 
configuration section in punchcards. I would agree with some additional 
guidelines for instance to declare the maximum time a program is expected to 
run, or the number of lines it should send to the printer."

We may decide to put some of the traces or tweak under a --enable-debug. This 
only requires to have some traces under #ifdef DEBUG, since spice-traces.def is 
really an include file. But given the low cost, I recommend we do not do that 
unless it’s required for security or stability reasons.


>> - 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);

Punchcard analogy: “it makes sense to have a program writing CPU usage 
statistics on the terminal if you are trying to distinguish what each program 
does. A perfectly standard ampere-meter and other tools can help you see power 
usage if your programs run in batch, but it can be hard to see usage by a 
specific program when time sharing.”

What would be the value of having an entirely different interface for 
statistics?

> 
>> - 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;

Punchcard analogy: “I agree finding where the CPU is spending time should be 
treated in a different way than having yet another program using CPU time to 
usage statistics to a terminal. In the past, I used an oscilloscope to know 
which program was hogging the CPU, but it was not worth leaving in the system."

For hot paths, I would make a distinction between live tracing and dead tracing:

- live tracing hot path code means recording stuff all the time, and be able to 
dump it later, e.g. for post-mortem or on-demand dumps. For this kind of use 
cases, I developed a simple flight recorder that I already talked about, 
https://github.com/c3d/recorder. Connecting it to spice is relatively easy. On 
macOS, I even have the ability to get a dump at any time hitting Control-T 
(sorry, not on Linux, I recently discovered, to my dismay, that it’s a BSD-only 
thing). While you can do that with dtrace or systemtap, for that specific use, 
it’s extremely slow, and useless in crash dumps (whereas the flight recorder is 
designed among other things to dump stuff in response to signals).

- Having instrumentation that you can leave in hot path because it’s cheap 
enough if not active. That’s what the proposed approach here offers. So I can 
have expensive hex dumps or time-stamped marshaller dumps which obviously we 
don’t want to have all the time, but which can be handy to figure out a 
particular problem. Or, if we are willing to invest the time and willing to 
give up any kind of prortability, write systemtap scripts, but it’s more 
complicated and since it’s not in one place, you have more chances of script 
and code diverging.



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

Punchcard analogy: "Maybe installing a phone line between the punchcard reader 
room and the printer room would be a good fit in such situations. Hopefully, 
it’s cheap enough."

I am not against implementing something using systemtap, but it’s an entirely 
different problem IMO. A good thing about dtrace is that it's truly zero-cost 
when not used (IF you do it right, see caveats below). It’s somewhat standard 
(although not really portable), and it’s quite powerful, since you can write 
scripts that do bar charts, etc (well, at least with the original dtrace, did 
not check with systemtap).

With respect to my requirements, here are a few issues I can think of in a 
couple of minutes:

1. It’s Linux only. The macOS “original” dtrace does not have the -G option, so 
you’ll have to tweak the makefiles to get something that works. But definitely, 
the makefile rules from your page won’t work as is. I have not looked into 
Windows, but my guess is it’s even worse.

2. It’s very cheap if not used. BUT you have to be careful about the evaluation 
of arguments. dtrace needs to expose the values given as parameters to the 
probes, so are always be computed. For example, let’s say we create a “spice” 
provider with a “foo” probe taking two arguments. If you compare:
        SPICE_FOO(i, foo(i))
vs
        spice_trace(foo, “for i=%d, foo=%d”, i, foo(i))

in the first case, foo(i) is called every time. In the second case it is not. 
So you have to remember doing something like (entirely doable and can be 
macro-ified, but tedious):
        if (SPICE_FOO_ENABLED())
                SPICE_FOO(i, foo(i))

3. Any probe is useless without the associated dtrace scripts. So you need to 
write and maintain these scripts. They live in a different location, not being 
written in C. You need to learn a new language, accessing C data is more 
complicated, etc. It’s very easy for the code to be changed without the 
instrumentation script being updated, since they don’t live at the same place. 
As an aside, most of HP-UX debugging was done with a precursor of dtrace called 
p4. It was extremely powerful, but writing p4 scripts was an art. So I think a 
fair question would be: who in the team has years of experience with C? Who has 
years of experience with dtrace?

4. I see no obvious equivalent of my ‘drop_stats=100’ example, i.e. dealing 
with the ‘input’ side of interactivity. You have SPICE_FOO_ENABLED() and I 
believe that’s about it. Anybody more familiar with systemtap knows otherwise?

5. It’s not self-documented. So you can’t just pick a version of spice and do 
something that will easily tell you “here is the useful information you can get 
from that version”.


>> - 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.

Punchcard analogy: “There are already some switches and knobs on the 
front-panel of the computer. Not so extensive however to see the introduction 
of a new layer of code dealing with command-line switches."

In my implementation, the "new layer of code" is one global structure, plus 
preprocessor-generated code to parse environment variables or command-line 
options and modify that structure. It’s not even a tenth of the complication of 
adding systemtap or structured logging. There is no change required to the 
makefiles, and no need for any new tool, since we were already using #define 
and #include before…


> 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.

Punchcard analogy: “I would not tie command-line options to a terminal, which 
should remain primarily an output device. I think it would be confusing, 
especially since user input could mix up with the output of other programs."

If you look at things as “tweaking the program” and “printing stuff”, then it’s 
hard to see why it makes sense to put them together. If you see this as 
“studying what the program is doing”, then it all makes sense. Understanding 
what the program is doing includes the ability to see what is going on, but is 
made much easier if you can also twist knobs and flip switches to observe the 
impact. Whether you want to do that with command-line options or environment 
variables is a matter of preference and use cases, which is why my approach 
supports both.


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

Punchcard analogy: “Gist of the thread seemed to be: do we want listing 
filtering for different users, and if yes, how do we do it?"

It’s one of the problems solved, yes. But, by far, not the only one. That being 
said, solving that problem alone would be enough to consider the suggestion.

> 
> 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 ;)

Feel free to offer functional alternatives, a branch I can test. But so far, I 
got some pushback on code that actually works and solves the problem, without 
more than handwaving arguments about “you should use this or that other tool”. 
As I wrote in an earlier response, it is not enough that the tool exists, it 
has to solve my "interactive debugging that also works on macOS" problem. An 
aspect which, I’m sorry to say, seems to have been very low priority in the 
alternatives proposed so far. This may be entirely my fault, since I assumed 
incorrectly that seeing a few examples would make it clear why I need this. But 
that’s the primary requirement here.

> 
> I just wanted to note that this could be solved (on linux) with glib
> structured logging and journald.

Punchcard analogy: “I just wanted to note that this could be solved (at least 
on IBM computers) by appropriate use of cover letter pages for batch jobs."

Your definition of “solved” clearly does not match mine. The “on linux” is one 
part of why this is not a solution. The 600 times slower is another. The “not 
interactive” is a third. Not self-documenting either. I can probably find more 
if you ask.


> 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).

Punchcard analogy: “If we send a page-feed character at the end of every job, 
then print a USER: line at the top of a blank page, our secretary can then look 
for pages that are almost blank except for the USER line, staple together the 
printouts with the cover letter on top, and put them in the user's mailbox. … 
minimum investment on our side)"

Define “minimum investment”. My investment so far is:

 common/log.c                | 171 ++++++++++++++++++++++++++++++++++++++++++--
 common/log.h                |  45 ++++++++++++
 common/rect.h               |   2 +-
 common/spice-traces.def     |  89 +++++++++++++++++++++++
 common/ssl_verify.c         |  52 +++++++-------
 python_modules/demarshal.py |  13 ++++
 python_modules/marshal.py   |  15 ++++
 7 files changed, 354 insertions(+), 33 deletions(-)

 spice-common             |   2 +-
 src/channel-base.c       |  26 ++++++----
 src/channel-cursor.c     |   9 ++--
 src/channel-display.c    | 130 +++++++++++++++++++++++++++++------------------
 src/channel-inputs.c     |  17 +++++--
 src/channel-main.c       |  72 ++++++++++++++++++--------
 src/channel-playback.c   |  19 ++++---
 src/channel-port.c       |   7 +--
 src/channel-record.c     |   5 +-
 src/channel-smartcard.c  |   8 +--
 src/channel-usbredir.c   |  12 +++--
 src/channel-webdav.c     |  20 +++++---
 src/spice-channel-priv.h |   7 ++-
 src/spice-channel.c      | 113 +++++++++++++++++++++++++---------------
 src/spice-glib-sym-file  |   4 ++
 src/spice-option.c       |  40 +++++++++++++++
 src/spice-session.c      |  20 +++++---
 src/spice-util.c         |  19 ++++++-
 src/spice-util.h         |   7 +--
 tools/spicy.c            |   8 +++
 20 files changed, 372 insertions(+), 173 deletions(-)

So it’s not tiny, but it’s not that big either, and the vast majority is the 
categorization work. No change to tools, build system, etc. No additional 
dependency. Portable. Higher performance than what we have today by a factor 
500 in the common case. Given that I shared it, that’s the standard by which 
alternatives should be evaluated as being truly a “minimum investment”.

Regarding “investment”, there is also the investment you have in analyzing log 
output. Since people were talking freely about structured logging, I assumed 
the exact output format did not matter much. I fixed a few typos, changed the 
order in some messages, etc. In short, I assumed nobody relies on a specific 
format for one of our debug messages. Let me know if you have cases you care 
about.


> Final note is that whichever way we decide to go, this is not going to
> magically provide us with good debug log ;)

No, which is why I spent a lot of time yesterday categorizing existing debug 
output. Now, I’m going to add some instrumentation that I find sorely missing.

> 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).

This is what I did, I think. It’s called spice_trace(category, …) and not 
DEBUG(category, …), but that part is that part I really don’t care about. 
Except that everybody defines DEBUG…


Thanks
Christophe



> 
> Christophe

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

Reply via email to