After an evaluation, GNOME has moved from Bugzilla to GitLab. Learn more about GitLab.
No new issues can be reported in GNOME Bugzilla anymore.
To report an issue in a GNOME project, go to GNOME GitLab.
Do not go to GNOME Gitlab for: Bluefish, Doxygen, GnuCash, GStreamer, java-gnome, LDTP, NetworkManager, Tomboy.
Bug 745213 - Shorten __FILE__ in gst_debug_log output on all platforms.
Shorten __FILE__ in gst_debug_log output on all platforms.
Status: RESOLVED FIXED
Product: GStreamer
Classification: Platform
Component: gstreamer (core)
git master
Other Linux
: Normal enhancement
: 1.5.1
Assigned To: GStreamer Maintainers
GStreamer Maintainers
Depends on:
Blocks:
 
 
Reported: 2015-02-26 14:21 UTC by Peter Urbanec
Modified: 2015-03-12 13:52 UTC
See Also:
GNOME target: ---
GNOME version: ---


Attachments
Patch to shorten __FILE__ on all platforms. (1.73 KB, patch)
2015-02-26 14:21 UTC, Peter Urbanec
committed Details | Review
micro-optimisation: skip basename string ops if it doesn't look like a string that needs shortening (1.37 KB, patch)
2015-02-28 10:49 UTC, Tim-Philipp Müller
committed Details | Review

Description Peter Urbanec 2015-02-26 14:21:10 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.
Comment 1 Edward Hervey 2015-02-27 08:56:56 UTC
Isn't it just because your comiler has a broken __FILE__ ? It works fine on linux, android, ...
Comment 2 Sebastian Dröge (slomo) 2015-02-27 09:12:24 UTC
I think this happens with out-of-tree builds
Comment 3 Peter Urbanec 2015-02-27 10:26:22 UTC
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.
Comment 4 Edward Hervey 2015-02-27 11:35:35 UTC
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
Comment 5 Tim-Philipp Müller 2015-02-27 11:44:52 UTC
Theoretically there's also a 'mixed' case, right? e.g. a plugin/app that was cross-compiled vs. natively compiled GStreamer.
Comment 6 Peter Urbanec 2015-02-27 11:55:43 UTC
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?
Comment 7 Sebastian Dröge (slomo) 2015-02-27 12:02:21 UTC
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.
Comment 8 Edward Hervey 2015-02-27 13:13:40 UTC
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
Comment 9 Peter Urbanec 2015-02-27 13:59:29 UTC
The I/O cost of outputting those extra characters will be far, far greater than shortening the string.
Comment 10 Edward Hervey 2015-02-27 14:07:52 UTC
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.
Comment 11 Tim-Philipp Müller 2015-02-28 10:49:31 UTC
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.
Comment 12 Edward Hervey 2015-02-28 11:21:07 UTC
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) ?
Comment 13 Sebastian Dröge (slomo) 2015-03-04 09:12:28 UTC
b) sounds good, but also what Edward said in comment 12.
Comment 14 Tim-Philipp Müller 2015-03-05 18:03:19 UTC
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 15 Tim-Philipp Müller 2015-03-05 18:04:23 UTC
Comment on attachment 297983 [details] [review]
Patch to shorten __FILE__ on all platforms.

Committed with minor changes (minimal change leaving the comment untouched)
Comment 16 Sebastian Dröge (slomo) 2015-03-11 15:20:59 UTC
Should we close this bug then or do something else here?
Comment 17 Tim-Philipp Müller 2015-03-12 13:18:25 UTC
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
Comment 18 Edward Hervey 2015-03-12 13:31:21 UTC
I wouldn't be against moving it in the macros also. Enables bypassing the function call altogether
Comment 19 Tim-Philipp Müller 2015-03-12 13:52:27 UTC
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.