[gspell/wip/fix-responsiveness-problem] timing debug messages

[Sébastien Wilmet <swilmet src gnome org>]

commit 0b72f242a8405a6f9648c3b3fede874d9f5d2b4e
Author: Sébastien Wilmet <swilmet gnome org>
Date:   Fri Mar 31 07:50:44 2017 +0200

    timing debug messages

 gspell/gspell-inline-checker-text-buffer.c |   98 +++++++++++++++++++++-------
 1 files changed, 73 insertions(+), 25 deletions(-)
---
diff --git a/gspell/gspell-inline-checker-text-buffer.c b/gspell/gspell-inline-checker-text-buffer.c
index 73997e4..a5b7121 100644
--- a/gspell/gspell-inline-checker-text-buffer.c
+++ b/gspell/gspell-inline-checker-text-buffer.c
@@ -161,9 +161,25 @@ check_word (GspellInlineCheckerTextBuffer *spell,
 
        word = gtk_text_buffer_get_text (spell->buffer, start, end, FALSE);
 
-       correctly_spelled = gspell_checker_check_word (spell->spell_checker,
-                                                      word, -1,
-                                                      &error);
+       {
+#if 0
+               GTimer *timer;
+
+               timer = g_timer_new ();
+#endif
+
+               correctly_spelled = gspell_checker_check_word (spell->spell_checker,
+                                                              word, -1,
+                                                              &error);
+
+#if 0
+               /* The problem is not here, it doesn't take a lot of time. */
+               g_timer_stop (timer);
+               g_print ("check_word() took %lf ms.\n",
+                        1000 * g_timer_elapsed (timer, NULL));
+               g_timer_destroy (timer);
+#endif
+       }
 
        if (error != NULL)
        {
@@ -194,14 +210,12 @@ adjust_iters (GtkTextIter *start,
                            !_gspell_text_iter_starts_word (start))
                        {
                                _gspell_text_iter_backward_word_start (start);
-                               g_assert (_gspell_text_iter_starts_word (start));
                        }
 
                        if (_gspell_text_iter_inside_word (end) &&
                            !_gspell_text_iter_starts_word (end))
                        {
                                _gspell_text_iter_forward_word_end (end);
-                               g_assert (_gspell_text_iter_ends_word (end));
                        }
                        break;
 
@@ -211,13 +225,11 @@ adjust_iters (GtkTextIter *start,
                             !_gspell_text_iter_starts_word (start)))
                        {
                                _gspell_text_iter_backward_word_start (start);
-                               g_assert (_gspell_text_iter_starts_word (start));
                        }
 
                        if (_gspell_text_iter_inside_word (end))
                        {
                                _gspell_text_iter_forward_word_end (end);
-                               g_assert (_gspell_text_iter_ends_word (end));
                        }
                        break;
 
@@ -232,8 +244,17 @@ check_subregion (GspellInlineCheckerTextBuffer *spell,
                 GtkTextIter                   *end)
 {
        GtkTextIter word_start;
+       GTimer *timer;
+       gint iteration_num;
+
+       g_print ("%s(): [line=%d,offset=%d ; line=%d,offset=%d]\n",
+                G_STRFUNC,
+                gtk_text_iter_get_line (start),
+                gtk_text_iter_get_line_offset (start),
+                gtk_text_iter_get_line (end),
+                gtk_text_iter_get_line_offset (end));
 
-       g_assert_cmpint (gtk_text_iter_compare (start, end), <=, 0);
+       timer = g_timer_new ();
 
        adjust_iters (start, end, ADJUST_MODE_STRICTLY_INSIDE_WORD);
 
@@ -250,9 +271,6 @@ check_subregion (GspellInlineCheckerTextBuffer *spell,
        {
                GtkTextIter next_word_end;
 
-               /* Based on adjust_iters() code. */
-               g_assert (!_gspell_text_iter_inside_word (start));
-
                next_word_end = *start;
                _gspell_text_iter_forward_word_end (&next_word_end);
 
@@ -262,32 +280,27 @@ check_subregion (GspellInlineCheckerTextBuffer *spell,
                        return;
                }
 
-               g_assert (_gspell_text_iter_ends_word (&next_word_end));
-               g_assert_cmpint (gtk_text_iter_compare (start, &next_word_end), <, 0);
-
                word_start = next_word_end;
                _gspell_text_iter_backward_word_start (&word_start);
-               g_assert (_gspell_text_iter_starts_word (&word_start));
-
-               /* This assertion has failed in some cases, see:
-                * https://bugzilla.gnome.org/show_bug.cgi?id=778883
-                */
-               g_assert_cmpint (gtk_text_iter_compare (start, &word_start), <, 0);
        }
 
+       g_timer_stop (timer);
+       g_print ("%s(): %lf ms: before loop.\n",
+                G_STRFUNC,
+                1000 * g_timer_elapsed (timer, NULL));
+
+       g_timer_start (timer);
+
+       iteration_num = 0;
        while (_gspell_utils_skip_no_spell_check (spell->no_spell_check_tag, &word_start, end) &&
               gtk_text_iter_compare (&word_start, end) < 0)
        {
                GtkTextIter word_end;
                GtkTextIter next_word_start;
 
-               g_assert (_gspell_text_iter_starts_word (&word_start));
-
                word_end = word_start;
                _gspell_text_iter_forward_word_end (&word_end);
 
-               g_assert_cmpint (gtk_text_iter_compare (&word_end, end), <=, 0);
-
                check_word (spell, &word_start, &word_end);
 
                next_word_start = word_end;
@@ -303,7 +316,22 @@ check_subregion (GspellInlineCheckerTextBuffer *spell,
                }
 
                word_start = next_word_start;
+
+               /* The problem is this loop when it is executed on a long line,
+                * containing e.g. 200 words.
+                */
+#if 0
+               g_print ("%s(): %lf ms: loop iteration %d.\n",
+                        G_STRFUNC,
+                        1000 * g_timer_elapsed (timer, NULL),
+                        iteration_num);
+#endif
+               g_timer_start (timer);
+
+               iteration_num++;
        }
+
+       g_timer_destroy (timer);
 }
 
 static void
@@ -441,7 +469,17 @@ check_visible_region_in_view (GspellInlineCheckerTextBuffer *spell,
                orig_start = start;
                orig_end = end;
 
-               check_subregion (spell, &start, &end);
+               {
+                       GTimer *timer;
+
+                       timer = g_timer_new ();
+                       check_subregion (spell, &start, &end);
+                       g_timer_stop (timer);
+                       g_print ("%s(): %lf ms: check subregion\n",
+                                G_STRFUNC,
+                                1000 * g_timer_elapsed (timer, NULL));
+                       g_timer_destroy (timer);
+               }
 
                /* Ensure that we don't have an infinite loop. We must subtract
                 * from scan_region at least [start, end], otherwise we will
@@ -469,6 +507,7 @@ static void
 check_visible_region (GspellInlineCheckerTextBuffer *spell)
 {
        GSList *l;
+       GTimer *timer;
 
        if (spell->scan_region == NULL)
        {
@@ -481,11 +520,20 @@ check_visible_region (GspellInlineCheckerTextBuffer *spell)
                return;
        }
 
+       g_print ("%s(): start.\n", G_STRFUNC);
+       timer = g_timer_new ();
+
        for (l = spell->views; l != NULL; l = l->next)
        {
                GtkTextView *view = GTK_TEXT_VIEW (l->data);
                check_visible_region_in_view (spell, view);
        }
+
+       g_timer_stop (timer);
+       g_print ("%s(): took %lf ms.\n\n",
+                G_STRFUNC,
+                1000 * g_timer_elapsed (timer, NULL));
+       g_timer_destroy (timer);
 }
 
 static gboolean