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

[Jonathon Jongsma]

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