[Spice-devel] RFC: Lightweight tracing mechanism
Christophe de Dinechin
dinechin at redhat.com
Fri Jun 9 08:59:56 UTC 2017
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 at 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 at 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 <cfergeau at 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
More information about the Spice-devel
mailing list