[23/49] analyzer: logging support

This patch adds a logging framework to the analyzer which handles
hierarchical messages (showing the nested structure of the calls).

This code is largely based on that in the "jit" subdirectory (with
a few changes).  An alternative would be to generalize that code
and move it to the gcc parent directory.

gcc/ChangeLog:
	* analyzer/analyzer-logging.cc: New file.
	* analyzer/analyzer-logging.h: New file.
---
 gcc/analyzer/analyzer-logging.cc | 220 +++++++++++++++++++++++++++++++++
 gcc/analyzer/analyzer-logging.h  | 256 +++++++++++++++++++++++++++++++++++++++
 2 files changed, 476 insertions(+)
 create mode 100644 gcc/analyzer/analyzer-logging.cc
 create mode 100644 gcc/analyzer/analyzer-logging.h

On 11/15/19 6:23 PM, David Malcolm wrote:
> This patch adds a logging framework to the analyzer which handles
> hierarchical messages (showing the nested structure of the calls).
> 
> This code is largely based on that in the "jit" subdirectory (with
> a few changes).  An alternative would be to generalize that code
> and move it to the gcc parent directory.
> 
> gcc/ChangeLog:
> 	* analyzer/analyzer-logging.cc: New file.
> 	* analyzer/analyzer-logging.h: New file.
> ---
>   gcc/analyzer/analyzer-logging.cc | 220 +++++++++++++++++++++++++++++++++
>   gcc/analyzer/analyzer-logging.h  | 256 +++++++++++++++++++++++++++++++++++++++
>   2 files changed, 476 insertions(+)
>   create mode 100644 gcc/analyzer/analyzer-logging.cc
>   create mode 100644 gcc/analyzer/analyzer-logging.h
> 
> diff --git a/gcc/analyzer/analyzer-logging.cc b/gcc/analyzer/analyzer-logging.cc
> new file mode 100644
> index 0000000..575435c
> --- /dev/null
> +++ b/gcc/analyzer/analyzer-logging.cc
> @@ -0,0 +1,220 @@
> +/* Hierarchical log messages for the analyzer.
> +   Copyright (C) 2014-2019 Free Software Foundation, Inc.
> +   Contributed by David Malcolm <dmalcolm@redhat.com>.
> +
> +This file is part of GCC.
> +
> +GCC is free software; you can redistribute it and/or modify it
> +under the terms of the GNU General Public License as published by
> +the Free Software Foundation; either version 3, or (at your option)
> +any later version.
> +
> +GCC is distributed in the hope that it will be useful, but
> +WITHOUT ANY WARRANTY; without even the implied warranty of
> +MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the GNU
> +General Public License for more details.
> +
> +You should have received a copy of the GNU General Public License
> +along with GCC; see the file COPYING3.  If not see
> +<http://www.gnu.org/licenses/>.  */
> +
> +#include "config.h"
> +#include "system.h"
> +#include "coretypes.h"
> +#include "toplev.h" /* for print_version */
> +#include "pretty-print.h" /* for print_version */
> +#include "diagnostic.h"
> +#include "tree-diagnostic.h"
> +
> +#include "analyzer/analyzer-logging.h"
> +
> +/* Implementation of class logger.  */
> +
> +/* ctor for logger.  */
> +
> +logger::logger (FILE *f_out,
> +		int, /* flags */
> +		int /* verbosity */,
> +		const pretty_printer &reference_pp) :
> +  m_refcount (0),
> +  m_f_out (f_out),
> +  m_indent_level (0),
> +  m_log_refcount_changes (false),
> +  m_pp (reference_pp.clone ())
> +{
> +  pp_show_color (m_pp) = 0;
> +  pp_buffer (m_pp)->stream = f_out;
> +
> +  /* %qE in logs for SSA_NAMEs should show the ssa names, rather than
> +     trying to prettify things by showing the underlying var.  */
> +  pp_format_decoder (m_pp) = default_tree_printer;
> +
> +  /* Begin the log by writing the GCC version.  */
> +  print_version (f_out, "", false);
> +}
> +
> +/* The destructor for logger, invoked via
> +   the decref method when the refcount hits zero.
> +   Note that we do not close the underlying FILE * (m_f_out).  */
> +
> +logger::~logger ()
> +{
> +  /* This should be the last message emitted.  */
> +  log ("%s", __PRETTY_FUNCTION__);
> +  gcc_assert (m_refcount == 0);
> +  delete m_pp;
> +}
> +
> +/* Increment the reference count of the logger.  */
> +
> +void
> +logger::incref (const char *reason)
> +{
> +  m_refcount++;
> +  if (m_log_refcount_changes)
> +    log ("%s: reason: %s refcount now %i ",
> +	 __PRETTY_FUNCTION__, reason, m_refcount);
> +}
> +
> +/* Decrement the reference count of the logger,
> +   deleting it if nothing is referring to it.  */
> +
> +void
> +logger::decref (const char *reason)
> +{
> +  gcc_assert (m_refcount > 0);
> +  --m_refcount;
> +  if (m_log_refcount_changes)
> +    log ("%s: reason: %s refcount now %i",
> +	 __PRETTY_FUNCTION__, reason, m_refcount);
> +  if (m_refcount == 0)
> +    delete this;
> +}
> +
> +/* Write a formatted message to the log, by calling the log_va method.  */
> +
> +void
> +logger::log (const char *fmt, ...)
> +{
> +  va_list ap;
> +  va_start (ap, fmt);
> +  log_va (fmt, &ap);
> +  va_end (ap);
> +}
> +
> +/* Write an indented line to the log file.
> +
> +   We explicitly flush after each line: if something crashes the process,
> +   we want the logfile/stream to contain the most up-to-date hint about the
> +   last thing that was happening, without it being hidden in an in-process
> +   buffer.  */
> +
> +void
> +logger::log_va (const char *fmt, va_list *ap)
> +{
> +  start_log_line ();
> +  log_va_partial (fmt, ap);
> +  end_log_line ();
> +}
> +
> +void
> +logger::start_log_line ()
> +{
> +  for (int i = 0; i < m_indent_level; i++)
> +    fputc (' ', m_f_out);
> +}
> +
> +void
> +logger::log_partial (const char *fmt, ...)
> +{
> +  va_list ap;
> +  va_start (ap, fmt);
> +  log_va_partial (fmt, &ap);
> +  va_end (ap);
> +}
> +
> +void
> +logger::log_va_partial (const char *fmt, va_list *ap)
> +{
> +  text_info text;
> +  text.format_spec = fmt;
> +  text.args_ptr = ap;
> +  text.err_no = 0;
> +  pp_format (m_pp, &text);
> +  pp_output_formatted_text (m_pp);
> +}
> +
> +void
> +logger::end_log_line ()
> +{
> +  pp_flush (m_pp);
> +  pp_clear_output_area (m_pp);
> +  fprintf (m_f_out, "\n");
> +  fflush (m_f_out);
> +}
> +
> +/* Record the entry within a particular scope, indenting subsequent
> +   log lines accordingly.  */
> +
> +void
> +logger::enter_scope (const char *scope_name)
> +{
> +  log ("entering: %s", scope_name);
> +  m_indent_level += 1;
> +}
> +
> +void
> +logger::enter_scope (const char *scope_name, const char *fmt, va_list *ap)
> +{
> +  start_log_line ();
> +  log_partial ("entering: %s: ", scope_name);
> +  log_va_partial (fmt, ap);
> +  end_log_line ();
> +
> +  m_indent_level += 1;
> +}
> +
> +
> +/* Record the exit from a particular scope, restoring the indent level to
> +   before the scope was entered.  */
> +
> +void
> +logger::exit_scope (const char *scope_name)
> +{
> +  if (m_indent_level)
> +    m_indent_level -= 1;
> +  else
> +    log ("(mismatching indentation)");
> +  log ("exiting: %s", scope_name);
> +}
> +
> +/* Implementation of class log_user.  */
> +
> +/* The constructor for log_user.  */
> +
> +log_user::log_user (logger *logger) : m_logger (logger)
> +{
> +  if (m_logger)
> +    m_logger->incref("log_user ctor");
> +}
> +
> +/* The destructor for log_user.  */
> +
> +log_user::~log_user ()
> +{
> +  if (m_logger)
> +    m_logger->decref("log_user dtor");
> +}
> +
> +/* Set the logger for a log_user, managing the reference counts
> +   of the old and new logger (either of which might be NULL).  */
> +
> +void
> +log_user::set_logger (logger *logger)
> +{
> +  if (logger)
> +    logger->incref ("log_user::set_logger");
> +  if (m_logger)
> +    m_logger->decref ("log_user::set_logger");
> +  m_logger = logger;
> +}
> diff --git a/gcc/analyzer/analyzer-logging.h b/gcc/analyzer/analyzer-logging.h
> new file mode 100644
> index 0000000..3e000b6
> --- /dev/null
> +++ b/gcc/analyzer/analyzer-logging.h
> @@ -0,0 +1,256 @@
> +/* Hierarchical log messages for the analyzer.
> +   Copyright (C) 2014-2019 Free Software Foundation, Inc.
> +   Contributed by David Malcolm <dmalcolm@redhat.com>.
> +
> +This file is part of GCC.
> +
> +GCC is free software; you can redistribute it and/or modify it
> +under the terms of the GNU General Public License as published by
> +the Free Software Foundation; either version 3, or (at your option)
> +any later version.
> +
> +GCC is distributed in the hope that it will be useful, but
> +WITHOUT ANY WARRANTY; without even the implied warranty of
> +MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the GNU
> +General Public License for more details.
> +
> +You should have received a copy of the GNU General Public License
> +along with GCC; see the file COPYING3.  If not see
> +<http://www.gnu.org/licenses/>.  */
> +
> +/* Adapted from jit-logging.h.  */
> +
> +#ifndef ANALYZER_LOGGING_H
> +#define ANALYZER_LOGGING_H
> +
> +#include "diagnostic-core.h"
> +
> +/* A logger encapsulates a logging stream: a way to send
> +   lines of pertinent information to a FILE *.  */
> +
> +class logger
> +{
> + public:
> +  logger (FILE *f_out, int flags, int verbosity, const pretty_printer &reference_pp);
> +  ~logger ();
> +
> +  void incref (const char *reason);
> +  void decref (const char *reason);
> +
> +  void log (const char *fmt, ...)
> +    ATTRIBUTE_GCC_DIAG(2, 3);
> +  void log_va (const char *fmt, va_list *ap)
> +    ATTRIBUTE_GCC_DIAG(2, 0);
> +  void start_log_line ();
> +  void log_partial (const char *fmt, ...)
> +    ATTRIBUTE_GCC_DIAG(2, 3);
> +  void log_va_partial (const char *fmt, va_list *ap)
> +    ATTRIBUTE_GCC_DIAG(2, 0);
> +  void end_log_line ();
> +
> +  void enter_scope (const char *scope_name);
> +  void enter_scope (const char *scope_name, const char *fmt, va_list *ap)
> +    ATTRIBUTE_GCC_DIAG(3, 0);
> +  void exit_scope (const char *scope_name);
> +
> +  pretty_printer *get_printer () const { return m_pp; }
> +  FILE *get_file () const { return m_f_out; }
> +
> +private:
> +  int m_refcount;
> +  FILE *m_f_out;
> +  int m_indent_level;
> +  bool m_log_refcount_changes;
> +  pretty_printer *m_pp;

Some of the members here looks self-explanatory but others less
so.  For instance, I'm not sure what m_refcount is for or
m_log_refcount_changes.  I would welcome at least brief comments
explaining what they're for.


> +};
> +
> +/* The class log_scope is an RAII-style class intended to make
> +   it easy to notify a logger about entering and exiting the body of a
> +   given function.  */

Sorry to be a nag about this but I have been burned recently
(and many times before) by this and it's still very fresh in
my mind.  Is the class meant to be copyable/assignable?  (With
what semantics?)  If not, I suggest declaring its copy ctor
and assignment private/deleted.

> +
> +class log_scope
> +{
> +public:
> +  log_scope (logger *logger, const char *name);
> +  log_scope (logger *logger, const char *name, const char *fmt, ...)
> +    ATTRIBUTE_GCC_DIAG(4, 5);
> +  ~log_scope ();
> +
> + private:
> +  logger *m_logger;
> +  const char *m_name;
> +};
> +
> +/* The constructor for log_scope.
> +
> +   The normal case is that the logger is NULL, in which case this should
> +   be largely a no-op.
> +
> +   If we do have a logger, notify it that we're entering the given scope.
> +   We also need to hold a reference on it, to avoid a use-after-free
> +   when logging the cleanup of the owner of the logger.  */
> +
> +inline
> +log_scope::log_scope (logger *logger, const char *name) :
> + m_logger (logger),
> + m_name (name)
> +{
> +  if (m_logger)
> +    {
> +      m_logger->incref ("log_scope ctor");
> +      m_logger->enter_scope (m_name);
> +    }
> +}
> +
> +inline
> +log_scope::log_scope (logger *logger, const char *name, const char *fmt, ...):
> + m_logger (logger),
> + m_name (name)
> +{
> +  if (m_logger)
> +    {
> +      m_logger->incref ("log_scope ctor");
> +      va_list ap;
> +      va_start (ap, fmt);
> +      m_logger->enter_scope (m_name, fmt, &ap);
> +      va_end (ap);
> +    }
> +}
> +
> +
> +/* The destructor for log_scope; essentially the opposite of
> +   the constructor.  */
> +
> +inline
> +log_scope::~log_scope ()
> +{
> +  if (m_logger)
> +    {
> +      m_logger->exit_scope (m_name);
> +      m_logger->decref ("log_scope dtor");
> +    }
> +}
> +
> +/* A log_user is something that potentially uses a logger (which could be NULL).
> +
> +   The log_user class keeps the reference-count of a logger up-to-date.  

Just the same high-level comment about copying: it's not obvious
to me if this class is or isn't safe to copy or assign.  If it
is despite the absence of copy ctor/assignment I'd suggest to
mention it in a comment.  If it isn't meant to be copied then
declaring its copy ctor and assignment private or delete would
prevent accidentally using it unsafely.

*/
> +
> +class log_user
> +{
> + public:
> +  log_user (logger *logger);
> +  ~log_user ();
> +
> +  logger * get_logger () const { return m_logger; }
> +  void set_logger (logger * logger);
> +
> +  void log (const char *fmt, ...) const
> +    ATTRIBUTE_GCC_DIAG(2, 3);
> +
> +  void start_log_line () const;
> +  void end_log_line () const;
> +
> +  void enter_scope (const char *scope_name);
> +  void exit_scope (const char *scope_name);
> +
> +  pretty_printer *get_logger_pp () const
> +  {
> +    gcc_assert (m_logger);
> +    return m_logger->get_printer ();
> +  }
> +
> +  FILE *get_logger_file () const
> +  {
> +    if (m_logger == NULL)
> +      return NULL;
> +    return m_logger->get_file ();
> +  }
> +
> + private:
> +  logger *m_logger;
> +};
> +
> +/* A shortcut for calling log from a log_user, handling the common
> +   case where the underlying logger is NULL via a no-op.  */
> +
> +inline void
> +log_user::log (const char *fmt, ...) const
> +{
> +  if (m_logger)
> +    {
> +      va_list ap;
> +      va_start (ap, fmt);
> +      m_logger->log_va (fmt, &ap);
> +      va_end (ap);
> +    }
> +}
> +
> +/* A shortcut for starting a log line from a log_user,
> +   handling the common case where the underlying logger is NULL via
> +   a no-op.  */
> +
> +inline void
> +log_user::start_log_line () const
> +{
> +  if (m_logger)
> +    m_logger->start_log_line ();
> +}
> +
> +/* A shortcut for ending a log line from a log_user,
> +   handling the common case where the underlying logger is NULL via
> +   a no-op.  */
> +
> +inline void
> +log_user::end_log_line () const
> +{
> +  if (m_logger)
> +    m_logger->end_log_line ();
> +}
> +
> +/* A shortcut for recording entry into a scope from a log_user,
> +   handling the common case where the underlying logger is NULL via
> +   a no-op.  */
> +
> +inline void
> +log_user::enter_scope (const char *scope_name)
> +{
> +  if (m_logger)
> +    m_logger->enter_scope (scope_name);
> +}
> +
> +/* A shortcut for recording exit from a scope from a log_user,
> +   handling the common case where the underlying logger is NULL via
> +   a no-op.  */
> +
> +inline void
> +log_user::exit_scope (const char *scope_name)
> +{
> +  if (m_logger)
> +    m_logger->exit_scope (scope_name);
> +}
> +
> +/* If the given logger is non-NULL, log entry/exit of this scope to
> +   it, identifying it using __PRETTY_FUNCTION__.  */
> +
> +#define LOG_SCOPE(LOGGER)		\
> +  log_scope s (LOGGER, __PRETTY_FUNCTION__)

's' seems like a poor choice for the name of a local variable hidden
behind a macro (due to the risk of collision with other variables of
the same name).  I usually use a token pasting trick to avoid this
risk, along these lines:

   #define CAT(a, b) a ## b
   #define CONCAT(a, b) CAT (a, b)
   #define UNIQUE_NAME(name) CAT (name, __LINE__)

   #define LOG_SCOPE(LOGGER)		\
     log_scope UNIQUE_NAME (local_logger) (LOGGER, __PRETTY_FUNCTION__)

> +
> +/* If the given logger is non-NULL, log entry/exit of this scope to
> +   it, identifying it using __func__.  */
> +
> +#define LOG_FUNC(LOGGER) \
> +  log_scope s (LOGGER, __func__)
> +
> +#define LOG_FUNC_1(LOGGER, FMT, A0)	\
> +  log_scope s (LOGGER, __func__, FMT, A0)
> +
> +#define LOG_FUNC_2(LOGGER, FMT, A0, A1)		\
> +  log_scope s (LOGGER, __func__, FMT, A0, A1)
> +
> +#define LOG_FUNC_3(LOGGER, FMT, A0, A1, A2)	\
> +  log_scope s (LOGGER, __func__, FMT, A0, A1, A2)
> +
> +#define LOG_FUNC_4(LOGGER, FMT, A0, A1, A2, A3) \
> +  log_scope s (LOGGER, __func__, FMT, A0, A1, A2, A3)

Same comment as above about the name.  I assume the "overloads"
re necessary because variadic macros are off-limits?  (Isn't
there some C++ 98 trick to make this work without the macros?)

Martin

> +
> +#endif /* ANALYZER_LOGGING_H */
>