[Spice-devel] [PATCH spice-gtk] Remove unnecessary debug check from SPICE_DEBUG

[Frediano Ziglio]

> > On 9 Jun 2017, at 17:47, Frediano Ziglio < fziglio at redhat.com > wrote:
> 

> > > On Fri, 2017-06-09 at 05:47 -0400, Frediano Ziglio wrote:
> > 
> 

> > > > > Calling spice_util_get_debug() from the SPICE_DEBUG() macro is
> > > > 
> > > 
> > 
> 
> > > > > unnecessary since g_log() will already check whether the message
> > > > 
> > > 
> > 
> 
> > > > > will
> > > > 
> > > 
> > 
> 
> > > > > actually be printed. The only benefit to calling this function from
> > > > 
> > > 
> > 
> 
> > > > > SPICE_DEBUG() is that it ensures that the SPICE_DEBUG environment
> > > > 
> > > 
> > 
> 
> > > > > variable gets read the very first time we try to log something with
> > > > 
> > > 
> > 
> 
> > > > > this macro. To solve this problem we instead use a constructor
> > > > 
> > > 
> > 
> 
> > > > > function
> > > > 
> > > 
> > 
> 
> > > > > to ensure that the env var is read at startup.
> > > > 
> > > 
> > 
> 

> > > > > Signed-off-by: Jonathon Jongsma < jjongsma at redhat.com >
> > > > 
> > > 
> > 
> 
> > > > > ---
> > > > 
> > > 
> > 
> 
> > > > > src/spice-util.c | 17 ++++++++++-------
> > > > 
> > > 
> > 
> 
> > > > > src/spice-util.h | 7 ++-----
> > > > 
> > > 
> > 
> 
> > > > > 2 files changed, 12 insertions(+), 12 deletions(-)
> > > > 
> > > 
> > 
> 

> > > > > diff --git a/src/spice-util.c b/src/spice-util.c
> > > > 
> > > 
> > 
> 
> > > > > index 86377b6..848f20a 100644
> > > > 
> > > 
> > 
> 
> > > > > --- a/src/spice-util.c
> > > > 
> > > 
> > 
> 
> > > > > +++ b/src/spice-util.c
> > > > 
> > > 
> > 
> 
> > > > > @@ -18,6 +18,7 @@
> > > > 
> > > 
> > 
> 
> > > > > */
> > > > 
> > > 
> > 
> 
> > > > > #include "config.h"
> > > > 
> > > 
> > 
> 

> > > > > +#include <common/macros.h>
> > > > 
> > > 
> > 
> 
> > > > > #include <stdbool.h>
> > > > 
> > > 
> > 
> 
> > > > > #include <stdlib.h>
> > > > 
> > > 
> > 
> 
> > > > > #include <string.h>
> > > > 
> > > 
> > 
> 

> > > > I would prefer the include after system includes, like spice-server
> > > 
> > 
> 
> > > > rules.
> > > 
> > 
> 

> > > > > @@ -63,13 +64,6 @@ static void
> > > > 
> > > 
> > 
> 
> > > > > spice_util_enable_debug_messages(void)
> > > > 
> > > 
> > 
> 
> > > > > **/
> > > > 
> > > 
> > 
> 
> > > > > void spice_util_set_debug(gboolean enabled)
> > > > 
> > > 
> > 
> 
> > > > > {
> > > > 
> > > 
> > 
> 
> > > > > - /* Make sure debug_once has been initialised
> > > > 
> > > 
> > 
> 
> > > > > - * with the value of SPICE_DEBUG already, otherwise
> > > > 
> > > 
> > 
> 
> > > > > - * spice_util_get_debug() may overwrite the value
> > > > 
> > > 
> > 
> 
> > > > > - * that was just set using spice_util_set_debug()
> > > > 
> > > 
> > 
> 
> > > > > - */
> > > > 
> > > 
> > 
> 
> > > > > - spice_util_get_debug();
> > > > 
> > > 
> > 
> 
> > > > > -
> > > > 
> > > 
> > 
> 
> > > > > if (enabled) {
> > > > 
> > > 
> > 
> 
> > > > > spice_util_enable_debug_messages();
> > > > 
> > > 
> > 
> 
> > > > > }
> > > > 
> > > 
> > 
> 
> > > > > @@ -88,6 +82,15 @@ static gpointer getenv_debug(gpointer data)
> > > > 
> > > 
> > 
> 
> > > > > return GINT_TO_POINTER(debug);
> > > > 
> > > 
> > 
> 
> > > > > }
> > > > 
> > > 
> > 
> 

> > > > > +/* Make sure debug_once has been initialised with the value of
> > > > 
> > > 
> > 
> 
> > > > > SPICE_DEBUG
> > > > 
> > > 
> > 
> 
> > > > > at
> > > > 
> > > 
> > 
> 
> > > > > + * startup, otherwise spice_util_get_debug() may overwrite the
> > > > 
> > > 
> > 
> 
> > > > > value that is
> > > > 
> > > 
> > 
> 
> > > > > + * set using spice_util_set_debug() */
> > > > 
> > > 
> > 
> 
> > > > > +SPICE_CONSTRUCTOR_FUNC(spice_log_init)
> > > > 
> > > 
> > 
> 
> > > > > +{
> > > > 
> > > 
> > 
> 
> > > > > + /* ensure that we enable debugging if the SPICE_DEBUG variable
> > > > 
> > > 
> > 
> 
> > > > > is set */
> > > > 
> > > 
> > 
> 
> > > > > + spice_util_get_debug();
> > > > 
> > > 
> > 
> 
> > > > > +}
> > > > 
> > > 
> > 
> 
> > > > > +
> > > > 
> > > 
> > 
> 
> > > > > gboolean spice_util_get_debug(void)
> > > > 
> > > 
> > 
> 
> > > > > {
> > > > 
> > > 
> > 
> 
> > > > > g_once(&debug_once, getenv_debug, NULL);
> > > > 
> > > 
> > 
> 

> > > > the g_once/GOnce is redundant with constructors. Constructors are
> > > 
> > 
> 
> > > > called in a single thread environment so don't need any serialization
> > > 
> > 
> 
> > > > (note: destructors don't follow this rule).
> > > 
> > 
> 

> > > Right.
> > 
> 

> > > > You could then use a simpler variable and write all SPICE_DEBUG check
> > > 
> > 
> 
> > > > in the constructor.
> > > 
> > 
> 
> > > > At this point you could use the new variable instead of
> > > 
> > 
> 
> > > > spice_util_get_debug (maybe using a static inline function to keep
> > > 
> > 
> 
> > > > API/flexibility).
> > > 
> > 
> 

> > > > > diff --git a/src/spice-util.h b/src/spice-util.h
> > > > 
> > > 
> > 
> 
> > > > > index a2a7683..7a95a9e 100644
> > > > 
> > > 
> > 
> 
> > > > > --- a/src/spice-util.h
> > > > 
> > > 
> > 
> 
> > > > > +++ b/src/spice-util.h
> > > > 
> > > 
> > 
> 
> > > > > @@ -32,11 +32,8 @@ gulong spice_g_signal_connect_object(gpointer
> > > > 
> > > 
> > 
> 
> > > > > instance,
> > > > 
> > > 
> > 
> 
> > > > > GConnectFlags connect_flags);
> > > > 
> > > 
> > 
> 
> > > > > gchar* spice_uuid_to_string(const guint8 uuid[16]);
> > > > 
> > > 
> > 
> 

> > > > > -#define SPICE_DEBUG(fmt, ...) \
> > > > 
> > > 
> > 
> 
> > > > > - do { \
> > > > 
> > > 
> > 
> 
> > > > > - if (G_UNLIKELY(spice_util_get_debug())) \
> > > > 
> > > 
> > 
> 
> > > > > - g_debug(G_STRLOC " " fmt, ## __VA_ARGS__); \
> > > > 
> > > 
> > 
> 
> > > > > - } while (0)
> > > > 
> > > 
> > 
> 
> > > > > +#define SPICE_DEBUG(fmt, ...) \
> > > > 
> > > 
> > 
> 
> > > > > + g_debug(G_STRLOC " " fmt, ## __VA_ARGS__)
> > > > 
> > > 
> > 
> 

> > > > > #define SPICE_RESERVED_PADDING (10 * sizeof(void*))
> > > > 
> > > 
> > 
> 

> > > > I think the unlikely here is an optimization we want avoiding the
> > > 
> > 
> 
> > > > expensive g_debug call. And would be even better with my variable
> > > 
> > 
> 
> > > > proposal.
> > > 
> > 
> 

> > > Hmm. This seems like unnecessary optimization to me. The glib logging
> > 
> 
> > > functions already have a check to see whether the message should be
> > 
> 
> > > printed. So adding our own (possibly out-of-sync) check around the call
> > 
> 
> > > seems unnecessary. Essentially:
> > 
> 

> > > if (spice_debug_enabled) {
> > 
> 
> > > // function call to g_logv() which contains pseudo-code like:
> > 
> 
> > > if (glib_debug_enabled) {
> > 
> 
> > > // log the message
> > 
> 
> > > }
> > 
> 
> > > }
> > 
> 

> > > I think if the debug function call overhead really is expensive enough
> > 
> 
> > > that it starts affecting the behavior of the program, then enabling
> > 
> 
> > > logging we will *definitely* affect the behavior of the program. I'd
> > 
> 
> > > rather to see evidence that it's a problem before we optimize it.
> > 
> 

> > > Jonathon
> > 
> 

> > Yes, but you are removing an optimization without evidence too.
> 

> > The change was introduced by f7daf5a4987af3fc8f8a15d1e1655995ff610009:
> 

> > commit f7daf5a4987af3fc8f8a15d1e1655995ff610009
> 
> > Author: Marc-André Lureau < marcandre.lureau at redhat.com >
> 
> > Date: Wed Nov 17 22:14:15 2010 +0100
> 

> > gtk: add a flag to turn debug off, SPICE_DEBUG=1 to override
> 

> > No rationale or explanation precisely if the G_UNLIKELY optimization
> 
> > was intentional.
> 

> About intentional or not, why this:

> #define spice_warn_if_fail(x) G_STMT_START { \
> if G_LIKELY(x) { } else { \
> spice_warning("condition `%s' failed", #x); \
> } \
> } G_STMT_END

> instead of G_UNLIKELY(!(x)) ?

I think the code came from GLib headers (see glib/gmessages.h). 
Maybe initially only G_LIKELY was available. 
Or maybe the G_STMT_START was not used and they wanted to avoid 
somebody put an else after the code (but the do {} while(0) trick is really 
old...). 

> I see nothing “bad” in that code, it just looks weird.

Frediano 
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <https://lists.freedesktop.org/archives/spice-devel/attachments/20170609/ae230417/attachment-0001.html>