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

[Frediano Ziglio]

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

Frediano