[Spice-devel] RFC: Lightweight tracing mechanism

Fri Jun 9 15:34:27 UTC 2017

> On 9 Jun 2017, at 11:48, Marc-André Lureau <marcandre.lureau at redhat.com> 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 at 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]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
>> 
> 
> 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?

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

> 
>> 
>> 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
> 
> Same here, this is so verbose and low-level than you can simply attach gdb and pretty-print the structure you are interested in.

Possible ≠ easy. You can also simply edit source code with sed. That does not make it a good idea.

> This is really just useful to developpers, no one else could make sense of these internal stuff.

Asking a customer to send the output of spicy -t magic_trace seems easier than asking them to run a gdb script.

> 
>> 
>> 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.
>> 
> 
> No, I don't think we need this available "all the time" or put differently, in the code. We need useful debug log, but when it comes to internal data structure dump or byte stream analaysis, use proper tools: gdb & tcpdump/wireshark for ex. 

Use what you want. But why prevent me from using tools I find less primitive for the task?

> 
> I don't think you make a good point about the "log tweaks" either.

I don’t see you having made any good point against them, only suggesting purely theoretical alternatives that would turn minutes of work into days.

> 
>> 
>> 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
>> 
> 
> Regular debug log.

Not today. Annoyingly chatty.

> 
>> 
>> 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
>> 
> 
> Useless tweak imho, glog has no performance issue for debugging logs.

It’s there to revert to old behaviour if you use —spice-debug or SPICE_DEBUG=1 (sets trace_stdout=0:trace_stdlog=1).

> 
>> 
>> 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
> 
> Looks nice, not sure this should be exposed to the user by default though (nothing more useless than a user thinking he isolated a problem in a category and you have to ask him for a full log again, and he disappears :).

That ever happened to you?

There’s more useless: a log that contains all mouse movements, but not a single line of protocol information because that’s only available by attaching GDB and pretty-printing internal structures…

> 
> I think this is a worthy goal, not sure how yet though.
> 
>> 
>> 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.
>> 
>> 
> 
> Quite pointless benchmark, glog is not meant to be a fast "tracer". As already discussed, if you need such hot "traces", then you use other tools. 

Circular logic: the existing tracing mechanism is slow, therefore we can’t use it for hot code, therefore a fast mechanism that can be used in hot code is pointless.

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