[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 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%)
> 

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]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?

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]  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 never said you have to ask customer for running gdb. At this point, the developper should have enough information to reproduce the problem. I happened very seldomly that you have to provide the user with a custom binary for testing, which may provide additional log (a good indication that this log should be upstream this time)
 
> 
> > 
> >> 
> >> 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?

We don't have the same perception of primitive tools.

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

You won't be surprised that I think quite the contrary.

I'd simply like to:
- not make needless tweaks available in production builds
- not clutter the code with logging very specific to a bug (just imagine if everybody added its own bug-specific log in upstream code)
- not reinvent the wheel (like parsing etc)
- use existing logging infrastructure to be coherent with the rest of the system, and stay familiar to the developer/admin of that system 
- use existing, powerful tools and framework, familiar to existing developers

What I consider useful in what you propose, is to add more debug and add log categories. The rest fits a poor-man way of debugging, imho, and doesn't match well with common practices and tools. I will study your patches in more details when I have time to see if I missed something.