[Spice-devel] RFC: Lightweight tracing mechanism
Marc-André Lureau
marcandre.lureau at redhat.com
Fri Jun 9 09:48:18 UTC 2017
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]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..
>
> 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. This is really just useful to developpers, no one else could make sense of these internal stuff.
>
> 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.
I don't think you make a good point about the "log tweaks" either.
>
> 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.
>
> 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.
>
> 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 :).
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.
More information about the Spice-devel
mailing list