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

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

commit 845f16f587a16f971188052ed529cf1e1234b6d3
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 0506e04..20e4a1c 100644
--- a/gspell/gspell-inline-checker-text-buffer.c
+++ b/gspell/gspell-inline-checker-text-buffer.c
@@ -144,9 +144,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)
        {
@@ -177,14 +193,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;
 
@@ -194,13 +208,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;
 
@@ -215,8 +227,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);
 
@@ -233,9 +254,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);
 
@@ -245,32 +263,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;
@@ -286,7 +299,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
@@ -424,7 +452,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
@@ -450,6 +488,7 @@ static void
 check_visible_region (GspellInlineCheckerTextBuffer *spell)
 {
        GSList *l;
+       GTimer *timer;
 
        if (spell->scan_region == NULL)
        {
@@ -462,11 +501,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