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

[Jonathon Jongsma]

On Fri, 2017-06-09 at 12:41 -0400, Marc-André Lureau wrote:
> Hi
> 
> ----- Original Message -----
> > 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>
> > ---
> > Changes since v2:
> >  - fix outdated comment
> > 
> >  src/spice-util.c | 28 +++++++++-------------------
> >  src/spice-util.h |  7 ++-----
> >  2 files changed, 11 insertions(+), 24 deletions(-)
> > 
> > diff --git a/src/spice-util.c b/src/spice-util.c
> > index 86377b6..5bce262 100644
> > --- a/src/spice-util.c
> > +++ b/src/spice-util.c
> > @@ -24,6 +24,7 @@
> >  #include <glib.h>
> >  #include <glib-object.h>
> >  #include <spice/macros.h>
> > +#include "common/macros.h"
> >  #include "spice-util-priv.h"
> >  #include "spice-util.h"
> >  #include "spice-util-priv.h"
> > @@ -39,7 +40,7 @@
> >   * Various functions for debugging and informational purposes.
> >   */
> >  
> > -static GOnce debug_once = G_ONCE_INIT;
> > +static gboolean debug_enabled = FALSE;
> >  
> >  static void spice_util_enable_debug_messages(void)
> >  {
> > @@ -63,36 +64,25 @@ 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();
> >      }
> >  
> > -    debug_once.retval = GINT_TO_POINTER(enabled);
> > +    debug_enabled = enabled;
> >  }
> >  
> > -static gpointer getenv_debug(gpointer data)
> > +/* Make sure debug_enabled has been initialised with the value of
> > SPICE_DEBUG
> > + * at startup */
> > +SPICE_CONSTRUCTOR_FUNC(spice_log_init)
> >  {
> > -    gboolean debug;
> > -
> > -    debug = (g_getenv("SPICE_DEBUG") != NULL);
> > -    if (debug)
> > +    debug_enabled = (g_getenv("SPICE_DEBUG") != NULL);
> > +    if (debug_enabled)
> >          spice_util_enable_debug_messages();
> > -
> > -    return GINT_TO_POINTER(debug);
> >  }
> >  
> >  gboolean spice_util_get_debug(void)
> >  {
> > -    g_once(&debug_once, getenv_debug, NULL);
> > -
> > -    return GPOINTER_TO_INT(debug_once.retval);
> > +    return debug_enabled;
> >  }
> >  
> >  /**
> > 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*))
> >  
> 
> This patch gives me the weird feeling that the existing code is
> better:
> 
> - constructor attribute is less portable and racier than existing
> code 
> - we didn't have to evaluate the arguments or call g_debug() if
> !spice_util_get_debug)
> 
> What does this patch actually improves?
> 


If I was reading the code of a project and noticed that they checked a
global variable every time before calling g_debug(), I would find that
very odd. For example:

void foo(void)
{
    if (foo_get_debug()) {
        g_debug("something happened");
    }
    ...
}

Nobody does this. They just call g_debug() directly because glib
already has a mechanism for specifying what level log messages will be
printed. So adding a duplicate test is unnecessary unless you can show
that the overhead of a function call has significant impact on the
behavior. The fact that our additional flag check is hidden inside of a
macro doesn't make it any less unnecessary. 

And now I notice that spice_util_get_debug() is not even inlined, so we
weren't actually saving a function call anyway. The only optimization
here was the G_UNLIKELY.

Jonathon