GNOME Bugzilla – Bug 745213
Shorten __FILE__ in gst_debug_log output on all platforms.
Last modified: 2015-03-12 13:52:27 UTC
Created attachment 297983 [details] [review] Patch to shorten __FILE__ on all platforms. On WIN32 the file argument to gst_debug_log_valist is shortened to represent just the filename. This is useful not only for MSVC, but also with gcc/Linux when doing cross-compilation builds and out-of-tree builds. The attached patch removes the OS check for WIN32 so that the logs are more legible on all platforms. For example: 0:00:00.294828704 13842 0x53cf20 DEBUG avidemux /home/peteru/Source/T3/build-enviroment-core-24/builds/beyonwiz/inihdp/tmp-glibc/work/mips32el-oe-linux/gstreamer1.0-plugins-good/gstreamer1.0-plugins-good-git-r0/git/gst/avi/gstavidemux.c:253:gst_avi_demux_reset: AVI: reset becomes 0:00:02.439104406 17590 0x5c8720 DEBUG avidemux gstavidemux.c:253:gst_avi_demux_reset: AVI: reset This also saves a serious amount of bandwidth when debugging target systems over a serial console.
Isn't it just because your comiler has a broken __FILE__ ? It works fine on linux, android, ...
I think this happens with out-of-tree builds
Nope, gcc-4.9.2 on Linux is not broken in that respect. When you do out-of-tree cross compile builds (for example with openembedded), you will end up with the full absolute pathname in __FILE__ because that is what the build system gives to the compiler. gcc has no support for transforming the full path to just the file name component. Both the C99 and C++98 standards specify that the __FILE__ macro is implementation defined and should indicate the source file. The standard does not say anything about whether the __FILE__ should contain just the file name component or the full path, so technically a compiler does not have a broken __FILE__ implementation if it returns a full path name. GStreamer already has a workable solution to the problem. This patch just makes the solution available to all platforms, instead of limiting it to only WIN32.
Fair enough, but in that case let's just enabled it when we *know* __FILE__ will return an absolute path. Solutions: 1) detect it at configure time (is there already a m4 macro for that ?) 2) detect at runtime (with a global atomic which is checked the very first time) I'd prefer solution 1 (zero cost at runtime), but 2 is acceptable also
Theoretically there's also a 'mixed' case, right? e.g. a plugin/app that was cross-compiled vs. natively compiled GStreamer.
I don't think you can detect this reliably. You won't know at compile time or at run time. Consider the case where you have built gstreamer1.0 in the source directory / natively. You then deploy a plugin that has been cross-compiled or built out-of-tree. The compile time test has no chance in this scenario. A run time test will also have difficulty, since there is every chance that the first few (hundred/thousand) calls will come from the code that uses only file name for __FILE__ and then you start seeing calls from the plugin that has absolute path names. In this scenario there's no benefit in doing any dynamic checks, all you are doing is slowing down the code path. On the other hand, just using the base name in every call to gst_debug_log_valist will work fairly reliably. When called by the native, in-source-tree code, there will be no transformation of __FILE__. When called by the cross-compiled / out-of-tree plugin, the build environment path will be stripped and the debug output will be a lot more legible. Or, if you would like to take another point of view... It works just fine on WIN32 and improves the quality of the debug output. Why deny the same benefit to Linux users that happen to use embedded systems?
I think it's a good idea and I agree that this can't be detected once and for all as you might have both variants in different plugins / libraries.
my point is that debugging already takes a certain cpu toll, I'm not at all in favor of slapping even more cpu usage in it when it's not needed
The I/O cost of outputting those extra characters will be far, far greater than shortening the string.
I'll put the last part of my sentence here so you understand: ==> "when it's not needed" <== Sure, you can have mixes of core compiled one way, and plugins compiled another way. But can we assume that in 99.99999% of the cases you're going to be compiling both in the same way and therefore you can just put a simple check once in ? Furthermore, you do realize that that method is called *before* the message handler ? Therefore if you don't use it (such as with "onecategory:9"), it will be called for aaaaaaall categories/levels and not just for that specific category. No, please, I'm fine with slapping a runtime check in, but let's not do that all the time.
Created attachment 298150 [details] [review] micro-optimisation: skip basename string ops if it doesn't look like a string that needs shortening Two suggestions: a) above patch, which only calls the basename function if the string looks like a path string that needs shortening. b) as Edward noted, this code is called in all cases where the threshold filtering in the macros doesn't avoid the call already (e.g. all categories at all debug levels if we use GST_DEBUG=foo:9). Perhaps we should just move the shortening into the default print function, so it's only actually done if something gets printed. As this bug demonstrates, there has never been any guarantee that a custom handler would always get a basename so far anyway, so might as well move it IMHO.
I've always wondered. Why don't we check whether the category/level is activated as early as possible (i.e. before calling gst_debug_log_valist) ?
b) sounds good, but also what Edward said in comment 12.
commit 5764316a8e5ee227fbd1255927bbe5d3f9ab3b4a Author: Tim-Philipp Müller <tim@centricular.com> Date: Thu Mar 5 17:54:04 2015 +0000 info: move __FILE__ path shortening into default log handler Instead of always shortening the __FILE__ path, even if the log message is not actually printed, which might happen if the log level is activated but the category is not, only shorten the path if we're actually going to output it and if it looks like it needs shortening. Log handlers had no guarantee that they would get a name instead of a path anyway on any architecture, so it shouldn't be a problem. https://bugzilla.gnome.org/show_bug.cgi?id=745213 commit 6cbe86dc589d381a324a05c522096c38f73608a1 Author: Peter Urbanec <git.user@urbanec.net> Date: Fri Feb 27 01:16:58 2015 +1100 info: shorten __FILE__ on all platforms This is useful not only for MSVC, but also with gcc/Linux when doing cross-compilation builds and out-of-tree builds. https://bugzilla.gnome.org/show_bug.cgi?id=745213 Keeping open for the other checks.
Comment on attachment 297983 [details] [review] Patch to shorten __FILE__ on all platforms. Committed with minor changes (minimal change leaving the comment untouched)
Should we close this bug then or do something else here?
I moved the check a bit earlier now to avoid the args copying etc., not sure if we want to replicate it in all the macros? commit 2d92f5e6d87b5ce92794137e2b389f6cedd7cdae Author: Tim-Philipp Müller <tim@centricular.com> Date: Thu Mar 12 13:14:52 2015 +0000 info: move category level threshold check into log function dispatcher Minor optimisation: check category log level earlier in the log function dispatcher and not only in the default log function. https://bugzilla.gnome.org/show_bug.cgi?id=745213
I wouldn't be against moving it in the macros also. Enables bypassing the function call altogether
I think for backwards compatibility reasons (compiled against older gstinfo headers, running on upgraded libgstreamer) we can't remove the check in the functions. I don't know how the cost of the functional call compares to checking it twice (getting the threshold from the category is an atomic get). Also increases binary size a bit (couple of bytes each, but multiplied by N debug log statements). Dunno.