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

[Marc-André Lureau]

Hi

----- Original Message -----
> 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.

Well, the macro did hide this minor optimization.

But I agree, it's probably useless. I would rather take the argument that it is potentially harmful if the code within debug has side effect. But the harm is negligible, enabling debug could have side effects anyway :)

> 
> 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.

Afaik, modern compilers/linkers can do inline across compilation units.  In all cases, I wouldn't worry about the cost of a function call.