[gimp] app: allow recording GLIB log messages in performance logs

[Ell <ell src gnome org>]

commit 9e0fdc8e2c0fcb8d714aa220caf76207032cdc53
Author: Ell <ell_se yahoo com>
Date:   Sun Aug 2 10:55:02 2020 +0300

    app: allow recording GLIB log messages in performance logs
    
    Add a new "Messages" boolean parameter to performance logs, which,
    when set, records GLIB log messages in the performance log as
    markers, with an accompanying sample capturing their backtrace.
    This option is enabled by default.

 app/actions/dashboard-commands.c |  19 +++++-
 app/widgets/gimpdashboard.c      | 135 +++++++++++++++++++++++++++++++--------
 app/widgets/gimpdashboard.h      |   1 +
 3 files changed, 125 insertions(+), 30 deletions(-)
---
diff --git a/app/actions/dashboard-commands.c b/app/actions/dashboard-commands.c
index a9d3ac4b34..fa902fb769 100644
--- a/app/actions/dashboard-commands.c
+++ b/app/actions/dashboard-commands.c
@@ -212,9 +212,24 @@ dashboard_log_record_cmd_callback (GimpAction *action,
                             G_CALLBACK (gimp_toggle_button_update),
                             &info->params.backtrace);
 
+          toggle = gtk_check_button_new_with_mnemonic (_("_Messages"));
+          gimp_help_set_help_data (toggle,
+                                   _("Include diagnostic messages in log"),
+                                   NULL);
+          gtk_box_pack_start (GTK_BOX (hbox), toggle, FALSE, FALSE, 0);
+          gtk_widget_show (toggle);
+
+          gtk_toggle_button_set_active (GTK_TOGGLE_BUTTON (toggle),
+                                        info->params.messages);
+
+          g_signal_connect (toggle, "toggled",
+                            G_CALLBACK (gimp_toggle_button_update),
+                            &info->params.messages);
+
           toggle = gtk_check_button_new_with_mnemonic (_("Progressi_ve"));
-          gimp_help_set_help_data (toggle, _("Produce complete log "
-                                             "even if not properly terminated"),
+          gimp_help_set_help_data (toggle,
+                                   _("Produce complete log "
+                                     "even if not properly terminated"),
                                    NULL);
           gtk_box_pack_start (GTK_BOX (hbox), toggle, FALSE, FALSE, 0);
           gtk_widget_show (toggle);
diff --git a/app/widgets/gimpdashboard.c b/app/widgets/gimpdashboard.c
index af2c82fd7e..b2af1b3891 100644
--- a/app/widgets/gimpdashboard.c
+++ b/app/widgets/gimpdashboard.c
@@ -80,6 +80,7 @@
 #include "gimpwindowstrategy.h"
 
 #include "gimp-intl.h"
+#include "gimp-log.h"
 #include "gimp-version.h"
 
 
@@ -98,6 +99,7 @@
 #define LOG_SAMPLE_FREQUENCY_MAX       1000 /* samples per second */
 #define LOG_DEFAULT_SAMPLE_FREQUENCY   10 /* samples per second */
 #define LOG_DEFAULT_BACKTRACE          TRUE
+#define LOG_DEFAULT_MESSAGES           TRUE
 #define LOG_DEFAULT_PROGRESSIVE        FALSE
 
 
@@ -322,6 +324,7 @@ struct _GimpDashboardPrivate
   VariableData                  log_variables[N_VARIABLES];
   GimpBacktrace                *log_backtrace;
   GHashTable                   *log_addresses;
+  GimpLogHandler                log_log_handler;
 
   GtkWidget                    *log_record_button;
   GtkLabel                     *log_add_marker_label;
@@ -430,7 +433,10 @@ static gboolean   gimp_dashboard_log_print_escaped              (GimpDashboard
                                                                  const gchar         *string);
 static gint64     gimp_dashboard_log_time                       (GimpDashboard       *dashboard);
 static void       gimp_dashboard_log_sample                     (GimpDashboard       *dashboard,
-                                                                 gboolean             variables_changed);
+                                                                 gboolean             variables_changed,
+                                                                 gboolean             
include_current_thread);
+static void       gimp_dashboard_log_add_marker_unlocked        (GimpDashboard       *dashboard,
+                                                                 const gchar         *description);
 static void       gimp_dashboard_log_update_highlight           (GimpDashboard       *dashboard);
 static void       gimp_dashboard_log_update_n_markers           (GimpDashboard       *dashboard);
 
@@ -440,6 +446,10 @@ static void       gimp_dashboard_log_write_address_map          (GimpDashboard
                                                                  GimpAsync           *async);
 static void       gimp_dashboard_log_write_global_address_map   (GimpAsync           *async,
                                                                  GimpDashboard       *dashboard);
+static void       gimp_dashboard_log_log_func                   (const gchar         *log_domain,
+                                                                 GLogLevelFlags       log_levels,
+                                                                 const gchar         *message,
+                                                                 GimpDashboard       *dashboard);
 
 static gboolean   gimp_dashboard_field_use_meter_underlay       (Group                group,
                                                                  gint                 field);
@@ -1802,7 +1812,7 @@ gimp_dashboard_sample (GimpDashboard *dashboard)
 
           /* log sample */
           if (priv->log_output)
-            gimp_dashboard_log_sample (dashboard, variables_changed);
+            gimp_dashboard_log_sample (dashboard, variables_changed, FALSE);
 
           /* update gui */
           if (priv->update_now   ||
@@ -3527,7 +3537,8 @@ gimp_dashboard_log_time (GimpDashboard *dashboard)
 
 static void
 gimp_dashboard_log_sample (GimpDashboard *dashboard,
-                           gboolean       variables_changed)
+                           gboolean       variables_changed,
+                           gboolean       include_current_thread)
 {
   GimpDashboardPrivate *priv      = dashboard->priv;
   GimpBacktrace        *backtrace = NULL;
@@ -3664,7 +3675,7 @@ gimp_dashboard_log_sample (GimpDashboard *dashboard,
     }
 
   if (priv->log_params.backtrace)
-    backtrace = gimp_backtrace_new (FALSE);
+    backtrace = gimp_backtrace_new (include_current_thread);
 
   if (backtrace)
     {
@@ -3922,6 +3933,38 @@ gimp_dashboard_log_sample (GimpDashboard *dashboard,
   priv->log_n_samples++;
 }
 
+static void
+gimp_dashboard_log_add_marker_unlocked (GimpDashboard *dashboard,
+                                        const gchar   *description)
+{
+  GimpDashboardPrivate *priv = dashboard->priv;
+
+  priv->log_n_markers++;
+
+  gimp_dashboard_log_printf (dashboard,
+                             "\n"
+                             "<marker id=\"%d\" t=\"%lld\"",
+                             priv->log_n_markers,
+                             (long long) gimp_dashboard_log_time (dashboard));
+
+  if (description && description[0])
+    {
+      gimp_dashboard_log_printf (dashboard,
+                                 ">\n");
+      gimp_dashboard_log_print_escaped (dashboard, description);
+      gimp_dashboard_log_printf (dashboard,
+                                 "\n"
+                                 "</marker>\n");
+    }
+  else
+    {
+      gimp_dashboard_log_printf (dashboard,
+                                 " />\n");
+    }
+
+  gimp_dashboard_log_update_n_markers (dashboard);
+}
+
 static void
 gimp_dashboard_log_update_highlight (GimpDashboard *dashboard)
 {
@@ -4166,6 +4209,40 @@ gimp_dashboard_log_write_global_address_map (GimpAsync     *async,
   gimp_async_finish (async, NULL);
 }
 
+static void
+gimp_dashboard_log_log_func (const gchar    *log_domain,
+                             GLogLevelFlags  log_levels,
+                             const gchar    *message,
+                             GimpDashboard  *dashboard)
+{
+  GimpDashboardPrivate *priv      = dashboard->priv;
+  const gchar          *log_level = NULL;
+  gchar                *description;
+
+  g_mutex_lock (&priv->mutex);
+
+  switch (log_levels & G_LOG_LEVEL_MASK)
+    {
+    case G_LOG_LEVEL_ERROR:    log_level = "ERROR";    break;
+    case G_LOG_LEVEL_CRITICAL: log_level = "CRITICAL"; break;
+    case G_LOG_LEVEL_WARNING:  log_level = "WARNING";  break;
+    case G_LOG_LEVEL_MESSAGE:  log_level = "MESSAGE";  break;
+    case G_LOG_LEVEL_INFO:     log_level = "INFO";     break;
+    case G_LOG_LEVEL_DEBUG:    log_level = "DEBUG";    break;
+    default:                   log_level = "UNKNOWN";  break;
+    }
+
+  description = g_strdup_printf ("[%s] %s: %s", log_domain, log_level, message);
+
+  gimp_dashboard_log_add_marker_unlocked (dashboard, description);
+
+  gimp_dashboard_log_sample (dashboard, FALSE, TRUE);
+
+  g_free (description);
+
+  g_mutex_unlock (&priv->mutex);
+}
+
 static gboolean
 gimp_dashboard_field_use_meter_underlay (Group group,
                                          gint  field)
@@ -4349,6 +4426,12 @@ gimp_dashboard_log_start_recording (GimpDashboard                 *dashboard,
         atoi (g_getenv ("GIMP_PERFORMANCE_LOG_BACKTRACE")) ? 1 : 0;
     }
 
+  if (g_getenv ("GIMP_PERFORMANCE_LOG_MESSAGES"))
+    {
+      priv->log_params.messages =
+        atoi (g_getenv ("GIMP_PERFORMANCE_LOG_MESSAGES")) ? 1 : 0;
+    }
+
   if (g_getenv ("GIMP_PERFORMANCE_LOG_PROGRESSIVE"))
     {
       priv->log_params.progressive =
@@ -4403,10 +4486,12 @@ gimp_dashboard_log_start_recording (GimpDashboard                 *dashboard,
                              "<params>\n"
                              "<sample-frequency>%d</sample-frequency>\n"
                              "<backtrace>%d</backtrace>\n"
+                             "<messages>%d</messages>\n"
                              "<progressive>%d</progressive>\n"
                              "</params>\n",
                              priv->log_params.sample_frequency,
                              has_backtrace,
+                             priv->log_params.messages,
                              priv->log_params.progressive);
 
   gimp_dashboard_log_printf (dashboard,
@@ -4574,6 +4659,15 @@ gimp_dashboard_log_start_recording (GimpDashboard                 *dashboard,
 
   gimp_dashboard_reset_unlocked (dashboard);
 
+  if (priv->log_params.messages)
+    {
+      priv->log_log_handler = gimp_log_set_handler (
+        TRUE,
+        G_LOG_LEVEL_MASK | G_LOG_FLAG_FATAL | G_LOG_FLAG_RECURSION,
+        (GLogFunc) gimp_dashboard_log_log_func,
+        dashboard);
+    }
+
   priv->update_now = TRUE;
   g_cond_signal (&priv->cond);
 
@@ -4610,6 +4704,13 @@ gimp_dashboard_log_stop_recording (GimpDashboard  *dashboard,
 
   g_mutex_lock (&priv->mutex);
 
+  if (priv->log_log_handler)
+    {
+      gimp_log_remove_handler (priv->log_log_handler);
+
+      priv->log_log_handler = 0;
+    }
+
   gimp_dashboard_log_printf (dashboard,
                              "\n"
                              "</samples>\n");
@@ -4695,6 +4796,7 @@ gimp_dashboard_log_get_default_params (GimpDashboard *dashboard)
   {
     .sample_frequency = LOG_DEFAULT_SAMPLE_FREQUENCY,
     .backtrace        = LOG_DEFAULT_BACKTRACE,
+    .messages         = LOG_DEFAULT_MESSAGES,
     .progressive      = LOG_DEFAULT_PROGRESSIVE
   };
 
@@ -4716,32 +4818,9 @@ gimp_dashboard_log_add_marker (GimpDashboard *dashboard,
 
   g_mutex_lock (&priv->mutex);
 
-  priv->log_n_markers++;
-
-  gimp_dashboard_log_printf (dashboard,
-                             "\n"
-                             "<marker id=\"%d\" t=\"%lld\"",
-                             priv->log_n_markers,
-                             (long long) gimp_dashboard_log_time (dashboard));
-
-  if (description && description[0])
-    {
-      gimp_dashboard_log_printf (dashboard,
-                                 ">\n");
-      gimp_dashboard_log_print_escaped (dashboard, description);
-      gimp_dashboard_log_printf (dashboard,
-                                 "\n"
-                                 "</marker>\n");
-    }
-  else
-    {
-      gimp_dashboard_log_printf (dashboard,
-                                 " />\n");
-    }
+  gimp_dashboard_log_add_marker_unlocked (dashboard, description);
 
   g_mutex_unlock (&priv->mutex);
-
-  gimp_dashboard_log_update_n_markers (dashboard);
 }
 
 void
diff --git a/app/widgets/gimpdashboard.h b/app/widgets/gimpdashboard.h
index 136b39e86e..5d8a73f63c 100644
--- a/app/widgets/gimpdashboard.h
+++ b/app/widgets/gimpdashboard.h
@@ -29,6 +29,7 @@ struct _GimpDashboardLogParams
 {
   gint     sample_frequency;
   gboolean backtrace;
+  gboolean messages;
   gboolean progressive;
 };