Hi ----- Original Message ----- > >> 3. Scalable, and therefore as fine-grained as we need it to be. With a > >> similar mechanism, Tao-3D has about 70 traces (see > >> https://github.com/c3d/tao-3D/blob/master/tao/traces.tbl > >> <https://github.com/c3d/tao-3D/blob/master/tao/traces.tbl> for the > >> graphic > >> side traces), including in highly performance-sensitive paths. > > > > I think we have few highly performance-sensitive paths in our code, and > > before introducing facilities for tracing it, it would be interesting to > > know what you want to have traced. > > Let me take some examples straight from Tao3D, which I dearly miss in spice > today (with actual output from Tao3D for the first two): > > 1. fps: Report frames per second. > > Time;PageNum;FPS;Exec;MaxExec;Draw;MaxDraw;GC;MaxGC;Select;MaxSelect;GCWait;MaxGCWait > 1496761089.058;1;0.000;-1;0;-1;0;-1;0;-1;0;-1;0 > 1496761093.755;1;13.800;50;3217;9;482;1;13;0;0;0;9 > 1496761094.756;1;55.400;13;3217;3;482;0;13;0;0;0;12 > 1496761095.759;1;94.200;8;3217;2;482;0;13;0;0;0;12 > 1496761096.759;1;136.400;6;3217;2;482;0;13;0;0;0;12 > > 2. memory: Report memory usage on a regular basis (ideally, component by > component, e.g. separate codecs from spice code) > > NAME TOTAL ALLOC FREED > N2XL4TreeE 0 0 0 > N2XL7IntegerE 6132 1527 224 > N2XL4RealE 4088 215 3478 > N2XL4TextE 6132 1217 336 > N2XL4NameE 40880 15664 0 > N2XL5InfixE 33726 10246 332 > N2XL6PrefixE 12264 3177 0 > N2XL7PostfixE 1022 254 0 > N2XL5BlockE 5110 1017 112 > N2XL7ContextE 1022 15 0 > N2XL7SymbolsE 4088 1432 0 > N2XL7RewriteE 9198 5519 0 > ===== ===== ===== ===== > Kilobytes 9820K 3293K 223K > [GCThread] Collect time 3 ms > [GCThread] GC collect started > [GCThread] Collect time 0 ms > [GCThread] GC collect started > > 3. bandwidth: Report network bandwidth usage (incoming and outcoming) > > 4. latency: Report network observed latency > > > > My feeling is that those performance traces don't need to be in public or > > release code, since they are usually very specific to the problem you are > > studying at hand, and don't need to remain checked in code. > > My experience tells me the exact opposite. If you have a structure like this > in place, you start putting a bit more investment in your traces, so that > they can be reused later.
I would call it traces tbh, they are debug reports to me. > > > > >> 4. Can be used to conditionally enable / disable code (other than > >> tracing). > >> For example, Frediano started chasing memory leaks. Let’s say he develops > >> a > >> nice way to track leaks. It’s an investment, we want to keep it. With this > >> infrastructure, we could put that under -t leakcheck, and run that if we > >> have a doubt about a memory leak. > > > > Does tracing really helps with memory leak? when you have asan and > > valgrind, really, no. > > Valgrind? Running a heavily modified executable at a quarter of the speed on > a good moon? And clearly, based on the massive memory leak I reported last > week, such tools are not used on a regular basis. Well, if running at quarter of the speed allows you to find the leak easily, I don't see much problem. Yes, leaks often exist for a long time before they are discovered. I am not convinced adding yet another tool or debug info is going to help here, sadly. > The purpose of something like -t memory is to give you a broad overview. Be > able to say “we use 3G of memory, 1.5G of which is for graphics, 1G of which > for cached images”. So that you know where to focus your effort. Using > valgrind to give you that information? Tell me how. This is typically a job for massif, and the performance hit of this tool isn't so bad. asan is also pretty good performance-wise. > > > >> 5. Can be used for non-boolean values. It makes the code only marginally > >> more > >> complicated to add “tweaks”, i.e. integer values you can configure at > >> run-time easily. Currently, you’d typically use environment variables or a > >> configuration file for this, which expensive and not convenient. With this > >> approach, add one tweak, say “max_mem”, and tweak with -t max_mem=100 to, > >> say, limit allocations to 100M and detect leaks more easily. > > > > What has this to do with tracing? > > In both cases, it’s runtime configuration intended primarily for developers > > To better see the continuity between the two, imagine that we have a trace > focusing on JPEG encoding. But now, if we focus on understanding JPEG > quality, I can do something like -t jpeg -t jpeg_quality=50. So it’s really > part of the same kind of usage patterns. I still don't quite get why the tracing framework is involved here... aren't you trying to make a point for your tracing framework? Wouldn't you be able to adjust the runtime configuration with any other logging facility? > > > > >> 6. Self-documented. Using spicy -t list gives you a list of possible > >> tweaks. > >> And all messages come with a trace name prefix, so if you later want to > >> get > >> that specific message, you know what to pass to -t. > >> > > > > I suppose it lists the various domains? or all trace points? > > The domains if you want to call them that. But I’d rather leave “domain” for > glib domains, and traces / tweaks for what I’m proposing here. It’s > different concepts, much like domains and command-line options are > different, even if you may use a domain name as a grep argument. > > > > > For the later, it's probably hard to keep it stable and without associated > > documentation, it isn't of much help imho. > > This is exactly why in this implementation, the macros in spice-traces.def > mandate an “info” field for self-documentation. > > > > > In any case, I don't think it make sense to provide this in a user command > > line. Using environment variable allows to tweak any program using your > > library instead, and may be changed at run time. > > The SPICE_TRACE environment variable can be used to configure that if that’s > what you prefer. I personally prefer a short command-line option. > > > > >> I don’t think glib does any of these 6 points. I may be wrong, and I am > >> willing to use glib instead where it provides a sufficiently good > >> solution. > >> > >> > >>> - did you try other options (like Marc-andre' suggested) ? > >> > >> Yes. Christophe F already suggested them: > >> > >>>> On 23 May 2017, at 11:51, Christophe Fergeau <cferg...@redhat.com> > >>>> wrote: > >>> > >>>> I think we have SPICE_DEBUG already which might make > >>>> sense, another alternative would be to have a --enable-alignment-debug, > >>>> or something like glib (SPICE_XXX_DEBUG=alignment:foo:bar) > >>>> > >> > >> I did not find where the existing code does anything that would correspond > >> to > >> this > >> SPICE_XXX_DEBUG=alignment:foo:bar (I did ask). Any pointer? In any case, > >> what I saw in glib did not respond to my needs. > >> > >> > >>> > >>> Reading the code is not clear where exactly you implemented the different > >>> domains > >>> suggested by the bug report. > >> > >> I didn’t. I propose that we do something finer-grained. > >> > >> > >>> Did you just coded SSL as an example? > >> > >> Yes. I don’t want to convert everything if I sense that the team does not > >> like it at all. > >> So I only did two in common (ssl and rect) and one in gtk (channel, by > >> modifying CHANNEL_DEBUG) > >> > >>> Also you introduced a new "TRACE" logging level; why DEBUG was not > >>> enough? > >> > >> This is transitional, to be able to distinguish preserve existing behavior > >> for existing debug code > >> (always go to the glib log) while TRACE code can also go to standard > >> error. > >> > >> > >> > >>> On 6 Jun 2017, at 12:54, Marc-André Lureau <marcandre.lur...@redhat.com> > >>> wrote: > >>> > >>> I would rather stick to glib structured logging (and have compatibility > >>> code for glib < 2.50), > >> > >> This does not address my problem. The structured logging is “how to log” > >> (i.e. it is a replacement for “printf”). My patch set is intended to > >> define > > > > "structured logging" is not about "how" or "where" to log. It is about > > "structured" logs, that is having named fields & value that you can later > > filter/query. One way is through the journal, but you can implement other > > handlers. > > I stand by my comment that it’s about how and where to log things. How: using > named fields instead of pure ASCII text. Where: in a shared log, that can be > merged between applications, with the benefits you listed, namely that it > can be queried. > > > I don't know if your solution could fit. If it does, it would be great to > > propose it to glib instead. > > > I could probably make conditional tracing part of glib, but only with a much > more expensive implementation. In what I proposed, each flag is a bit in a > structure. So when you write IFTRACE(foo), it translates to nothing more > than if (spice_traces.foo). This relies on the compiler and linker doing the > lookup job at compile-time. A library implementation would have to do a > run-time lookup of the trace name, making it much more expensive. > > Alternatively, a header-only implementation is feasible, but that makes it > much more difficult to statically define where flags are stored. For > instance, say glib started using it, then glib would for example need a > “glib” set of flags, and a “spicy” set of flags. Let’s say two structures. > An implementation of IFTRACE(flag) would have to somehow remember if “flag” > was defined in “glib” or in “spicy”. So you end up with a much more complex > implementation. At some point, we did something like that for XL vs Tao3D, > but that used some C++ trickery that I don’t know how to replicate in C > (using namespace lookup IIRC, I’d have to check the code). > > Or you could forget about being smart, and just write something like > IFTRACE(glib.flag) and IFTRACE(spicy.flag), with possibly appropriate > macros. Hmm. Thinking aloud here. Why not… > > > > > >> *what* to log and *when* (i.e. it is a special form of command-line driven > >> “if”). Ultimately, my implementation uses either stderr or glib old log or > >> both, but adding a structured-log option would be relatively easy > >> (although > >> in a different patch series). > >> > >> I don’t think glib has command-line driven conditional logging today, > >> beyond > >> the debug, info, warning and error levels. Christophe F’s message (quoted > >> above) hints at such a facility, but I did not find it. > >> > > > > gtk+ has probably more debug and tracing needs than spice-gtk (and perhaps > > spice-server), yet they seem to be fine with glib facilities for now. > > At the moment, I care more about instrumenting Spice to understand its > behavior. > > But for what it’s worth, the current GTK implementation does not make any use > of anything in glib to implement its conditional tracing code. What they > have is a more naive version of what I did. It’s more naive because it’s not > scalable (limited to 64 flags on a 64-bit system), and you have to hand-edit > flags, options, etc. So it’s complicated to add a new trace. Here is for > example what it takes to add a “snapshot” trace: > https://github.com/GNOME/gtk/commit/def94f03e240babfd589c8ba8e7cc4961a3d6aab not so complicated.. > > Contrast with what it would take with my implementation: > https://github.com/c3d/spice-common/commit/5b2919615c0f55f05a0e1ec6c1a5f238e97b00f8. > > The combination of “not scalable” and “complicated to add a trace” probably > explains why there are presently only 20 traces active in the whole code. > It's also unnecessarily slow, since it goes through a loop iterating over > displays in gtk_get_display_debug_flags() to find display-specific flags, a > non-requirement for spice (and if it became a requirement, looping over all > displays would probably the last thing on my mind to implement it). If it would have been a problem, I don't think they would have left it there for ~20y. My point was that the gtk+ conditional debug fits with glib logging. But apparently your solution too. > > > > > fwiw, gtk+ uses a simple bitflag and a macro GDK_DEBUG_CHECK() / > > GTK_DEBUG_CHECK() to provide conditional debugging information (only with > > --enable-debug iirc). > > Yes. Using a manual bitflag is what I called a “naive” implementation. My use > of the pre-processor allows the code to generate option parsing to be > generated automatically. So you change one file and only one file. And you > don’t need to manually write things like 1<<19 when you add a trace. > > > > >> > >>> or try to find a way to use qemu tracing facility (ftrace/lttng etc). > >> > >> While it does offer some (ultra-complicated) way to do conditional > >> logging, > > > > but problably more powerful :) > > Well, the kernel tracing infrastructure is intended to trace stuff inside a > kernel. That a system using kernel facilities extensively like KVM/QEMU uses > the kernel tracing facilities makes quite a bit of sense. That’s one case > where you want to see events in the proper sequence between kernel and > user-space operations. An argument could be made for tracing infrastructure > in, say, the QXL driver. But for spicy, it does not make any sense to me. Those system-wide tracing facilities come with powerful tools, though like systemtap. > > > and more importantly commonly available, used and maintained. > > For the kernel, yes. Do you know of any purely user-space program that uses > ftrace for their own internal state? Except qemu, no. More projects I know have dtrace/systemtap probes (including glib, and libvirt). I don't know if they are bridges between ftrace & dtrace, and why qemu didn't pick dtrace. As you can see, it's just full of tracing tools already, a disparity which contributes to the lack of their usage, which makes it quite hard to take again one more. > > > > So there are probably more documentation available for those than a new > > solution. > > As I wrote earlier, that kernel infrastructure is much closer to the > “recorder” I talked about earlier. The recorder is *much* simpler than the > kernel trace API. Two headers (ring buffer and recorder), one C file, 1262 > LOCs with comments. By comparison, last time I checked, the kernel tracing > code was 51308 lines of code, 8 headers, automatic code-generation tools, > etc. And unlike the kernel tracing subsystem, the recorder is specifically > designed to integrate non-intrusively in a user-space program. > > There’s something to be said for simplicity. So far, I have integrated “my” > recorder in Mesa, Spice or BTRFS in a couple of hours each time. There’s no > way to do that with the kernel infrastructure IMO. > > But again, this has absolutely nothing to do with conditional tracing code. > This is yet another case a “where do I store stuff and how” (e.g. for the > recorder in a ring buffer). This has nothing to do with enabling / disabling > specific debug code (although, granted, the ftrace interface does have this > capability, but in a way that only applies to the kernel, i.e. writing to > /sys files, not command-line options or environment variables). > > > > Also, when tracing, you often need to consider what's happening outside of > > your domain, so it's quite important that the tracing facility is used by > > others. > > Actually, the purpose of this kind of tracing is to offer domain-specific, > focused tracing. So in the majority fo cases, you don’t need to consider > what is happening outside of the domain, on the contrary, you really want it > out of the way. And if/when you do care about it, then you get that data in > your instrumentation, not by activating some tracing in another domain. For > example, for Tao3D, number of polygons is important, but the -t polygons > does not give you that information by activating some polygon tracing in the > OpenGL domain. Instead, it collects statistics relevant to Tao3D from > OpenGL, and presents them in a usable form. > > > > This is a great argument to keep using glog/glib, obviously for the gtk+ > > client, but also for the server that uses more and more glib/gobject/gst > > etc. ftrace/lttng is quite more low level and linux-specific, so probably > > not the best userspace solution. > > Agreed, ftrace is definitely not a solution to my problem, let alone the best > one. > > I can consider making a glib version of spice_trace(). But I think it will be > unnecessarily complicated to get it accepted. And I don’t see what we’d gain > from it. Perhaps for me to understand what you propose, you'd need to explain better the different for you between a trace and a debug log, and how a debug log can effectively affect whatever you measure. > > > > > >> this is a kernel / server-side logging facility. I want to instrument > >> spice > >> itself (client also, not just server). I think using this kind of > >> infrastructure could be done, but we are talking about something that, at > >> first sight, looks two orders of magnitude more complicated to write and > >> to > >> use, only addresses some of my use-cases, and probably several times > >> slower. > >> > >> BTW, these tools also address post-mortem logging. I also have something > >> in > >> the pipe, see > >> https://github.com/c3d/spice-gtk/compare/master...c3d:recorder > >> and the associated submodule https://github.com/c3d/recorder/. But that’s > >> for a later RFC. If only Linux had control-T, you would know the joy of > >> hitting Control-T at your terminal window right after Spicy does something > >> funny, and getting a dump of what it just did, as if you had SPICE_DEBUG > >> to > >> start with :-) > >> > >> (that other patch series has a problem, that the recorder does not like > >> dynamic strings, so batch-converting existing messages is more > >> challenging). > > > > As you can see, I am quite reluctant to adding yet another logging/tracing > > framework to our already (very) long list of tools/libraries. In fact, I > > am very happy that we killed a dependency on log4cpp some time ago in > > favour of glib (we were the only users in rhel at that time, and it was > > quite a pain to use tbh :). > > Well, we may have a long list of tools and libraries, but right now, prying > even what I consider the most basic information out of Spice is a real pain > IMO. If you have a nice grep for the use cases I listed above (e.g. FPS, > network bandwidth, memory usage, etc), let me know. For now, to me, this is > a problem that is not solved. And that I believe my proposal would solve > relatively elegantly. I don't think any of these measurements couldn't be reported accurately with a regular log or structured log. Thus I don't understand what problem you try to solve. Sorry, but I also have a hard time to understand what your tracing library does. Could you point to a simple example and short doc? _______________________________________________ Spice-devel mailing list Spice-devel@lists.freedesktop.org https://lists.freedesktop.org/mailman/listinfo/spice-devel
