bug#4222: calls to char_table_ref slow down 23.1 (vs 22.3)

bug#4222: calls to char_table_ref slow down 23.1 (vs 22.3)

[Dan Nicolaescu]

Take src/config.h run C-x r t on it to insert a space in front of each
line.

Then build both emacs-23.1 and 22.3 with profiling enabled (-O2 -g -pg).
Then run:

emacs -Q -nw config.h
M-: (indent-region (point-min)(point-max)) RET
C-x C-c

The 22.3 gprof results:

Flat profile:

Each sample counts as 0.01 seconds.
  %   cumulative   self              self     total           
 time   seconds   seconds    calls  ms/call  ms/call  name    
 41.29      7.13     7.13  4653244     0.00     0.00  forw_comment
 16.10      9.91     2.78    32473     0.09     0.31  scan_sexps_forward
  9.09     11.48     1.57    15132     0.10     0.15  re_search_2
  5.62     12.45     0.97    17286     0.06     0.15  scan_lists
  5.59     13.41     0.96 33462255     0.00     0.00  lookup_char_property
  3.36     13.99     0.58 18478958     0.00     0.00  next_interval
  2.14     14.37     0.37   129733     0.00     0.00  mark_object
  1.80     14.68     0.31   137020     0.00     0.00  skip_chars
  1.74     14.97     0.30 14459993     0.00     0.00  previous_interval
  1.62     15.26     0.28 57446793     0.00     0.00  Fcdr
  1.36     15.49     0.23  2156082     0.00     0.00  update_syntax_table
  1.27     15.71     0.22  3315615     0.00     0.00  re_match_2_internal
  1.19     15.91     0.20 23687203     0.00     0.00  Fassq
  0.87     16.07     0.15    13478     0.01     0.06  Fprevious_single_property_change
  0.75     16.20     0.13 33462255     0.00     0.00  textget
  0.75     16.32     0.13   228439     0.00     0.00  Fbyte_code
  0.52     16.41     0.09  1978403     0.00     0.00  update_interval
  0.46     16.50     0.08  1101056     0.00     0.00  find_interval
  0.29     16.55     0.05  3613429     0.00     0.00  buf_bytepos_to_charpos
  0.26     16.59     0.04 10137050     0.00     0.00  Fcar
  0.26     16.64     0.04  1154883     0.00     0.00  balance_an_interval
  0.23     16.68     0.04   579275     0.00     0.00  unbind_to



The 23.1 gprof results:

Flat profile:

Each sample counts as 0.01 seconds.
  %   cumulative   self              self     total           
 time   seconds   seconds    calls   s/call   s/call  name    
 29.60      7.03     7.03 406111658     0.00     0.00  char_table_ref
 26.72     13.37     6.34  4653244     0.00     0.00  forw_comment
 11.80     16.17     2.80    32121     0.00     0.00  scan_sexps_forward
  5.98     17.59     1.42    23271     0.00     0.00  re_search_2
  5.27     18.84     1.25    17289     0.00     0.00  scan_lists
  4.13     19.82     0.98 33439981     0.00     0.00  lookup_char_property
  1.94     20.28     0.46 18488739     0.00     0.00  next_interval
  1.73     20.69     0.41 10038210     0.00     0.00  mark_object
  1.26     20.99     0.30  2156799     0.00     0.00  update_syntax_table
  1.20     21.27     0.29                             sub_char_table_ref
  1.10     21.53     0.26 14455134     0.00     0.00  previous_interval
  0.88     21.74     0.21 57391428     0.00     0.00  Fcdr
  0.88     21.95     0.21  3318263     0.00     0.00  re_match_2_internal
  0.72     22.12     0.17 23671456     0.00     0.00  Fassq
  0.67     22.28     0.16   196373     0.00     0.00  Fbyte_code
  0.59     22.42     0.14    13478     0.00     0.00  Fprevious_single_property_change
  0.51     22.54     0.12       38     0.00     0.02  Fgarbage_collect
  0.38     22.63     0.09 33439981     0.00     0.00  textget
  0.38     22.72     0.09 10115583     0.00     0.00  Fcar
[snip]

-----------------------------------------------
                0.05    0.22     612/32121       back_comment [28]
                2.75   11.33   31509/32121       Fparse_partial_sexp [6]
[5]     60.5    2.80   11.55   32121         scan_sexps_forward [5]
                5.17    3.76 3796695/4653244     forw_comment [7]
                1.62    0.00 93379139/406111658     char_table_ref [8]
                0.15    0.86 1092890/2156799     update_syntax_table [11]
                0.00    0.00    5096/10115583     Fcar [46]
                0.00    0.00    6552/57391428     Fcdr [33]
                0.00    0.00     147/952550      Fcons [105]

It can be seen that 23.1 is quite a bit slower, and that it has a lot of
extra calls to char_table_ref.  

Is there some easy way to reduce the number of those calls?

bug#4222: calls to char_table_ref slow down 23.1 (vs 22.3)

[Kenichi Handa]

> Take src/config.h run C-x r t on it to insert a space in front of each
> line.

> Then build both emacs-23.1 and 22.3 with profiling enabled (-O2 -g -pg).
> Then run:

> emacs -Q -nw config.h
> M-: (indent-region (point-min)(point-max)) RET
> C-x C-c
[...]
> It can be seen that 23.1 is quite a bit slower, and that it has a lot of
> extra calls to char_table_ref.  

> Is there some easy way to reduce the number of those calls?

Please find which char-table is referred so many times.

---
Kenichi Handa
handa@m17n.org

bug#4222: calls to char_table_ref slow down 23.1 (vs 22.3)

[Dan Nicolaescu]

Kenichi Handa <handa@m17n.org> writes:

  > > Take src/config.h run C-x r t on it to insert a space in front of each
  > > line.
  > 
  > > Then build both emacs-23.1 and 22.3 with profiling enabled (-O2 -g -pg).
  > > Then run:
  > 
  > > emacs -Q -nw config.h
  > > M-: (indent-region (point-min)(point-max)) RET
  > > C-x C-c
  > [...]
  > > It can be seen that 23.1 is quite a bit slower, and that it has a lot of
  > > extra calls to char_table_ref.  
  > 
  > > Is there some easy way to reduce the number of those calls?
  > 
  > Please find which char-table is referred so many times.

Unfortunately I am not familiar with this code at all...
Setting a breakpoint in char_table_ref and examining `table' there show
this:
 (struct Lisp_Char_Table *) 0x8863fb0
Purpose: "syntax-table"  0 extra slots

bug#4222: calls to char_table_ref slow down 23.1 (vs 22.3)

[Chong Yidong]

> Take src/config.h run C-x r t on it to insert a space in front of each
> line.
>
> Then build both emacs-23.1 and 22.3 with profiling enabled (-O2 -g -pg).
> Then run:
>
> emacs -Q -nw config.h
> M-: (indent-region (point-min)(point-max)) RET
> C-x C-c
>
> The 23.1 gprof results:
>
> Each sample counts as 0.01 seconds.
>   %   cumulative   self              self     total
>  time   seconds   seconds    calls   s/call   s/call  name
>  29.60      7.03     7.03 406111658     0.00     0.00  char_table_ref
>  26.72     13.37     6.34  4653244     0.00     0.00  forw_comment

I can't reproduce this problem now.  Following your recipe, I do observe
the indentation taking a looong time, but char_table_ref is not called.
Presumably, Handa-san's 2009-08-25 and 2009-08-27 changes fixed this.
Should I close the bug, or is there still a problem?

bug#4222: calls to char_table_ref slow down 23.1 (vs 22.3)

[Dan Nicolaescu]

Chong Yidong <cyd@stupidchicken.com> writes:

  > > Take src/config.h run C-x r t on it to insert a space in front of each
  > > line.
  > >
  > > Then build both emacs-23.1 and 22.3 with profiling enabled (-O2 -g -pg).
  > > Then run:
  > >
  > > emacs -Q -nw config.h
  > > M-: (indent-region (point-min)(point-max)) RET
  > > C-x C-c
  > >
  > > The 23.1 gprof results:
  > >
  > > Each sample counts as 0.01 seconds.
  > >   %   cumulative   self              self     total
  > >  time   seconds   seconds    calls   s/call   s/call  name
  > >  29.60      7.03     7.03 406111658     0.00     0.00  char_table_ref
  > >  26.72     13.37     6.34  4653244     0.00     0.00  forw_comment
  > 
  > I can't reproduce this problem now.  Following your recipe, I do observe
  > the indentation taking a looong time, but char_table_ref is not called.
  > Presumably, Handa-san's 2009-08-25 and 2009-08-27 changes fixed this.
  > Should I close the bug, or is there still a problem?

There still is a problem, but it is not caused by char_table_ref, that
part was fixed by Handa-san.
It's up to you if you want to keep this bug, just retitle it, or close it.

bug#4222: calls to char_table_ref slow down 23.1 (vs 22.3)

[Kenichi Handa]

In article <200909190443.n8J4hBNM011012@godzilla.ics.uci.edu>, Dan Nicolaescu <dann@ics.uci.edu> writes:

> I can't reproduce this problem now.  Following your recipe, I do observe
> the indentation taking a looong time, but char_table_ref is not called.
> Presumably, Handa-san's 2009-08-25 and 2009-08-27 changes fixed this.
> Should I close the bug, or is there still a problem?

> There still is a problem, but it is not caused by char_table_ref, that
> part was fixed by Handa-san.
> It's up to you if you want to keep this bug, just retitle it, or close it.

We still have a problem of slow GC caused by many elements
of char-tables (mostly because of charset encoders).  My
idea for fixing it is to somehow distinguish a char-table
that has only integer or (interned) symbol elements from the
other normal char-tables, and optimize mark_char_table for
it.  But, at the moment, I don't have a time to work on it.

Perhaps we should open a new bug for that.

---
Kenichi Handa
handa@m17n.org

bug#4222: calls to char_table_ref slow down 23.1 (vs 22.3)

[Kenichi Handa]

In article <tl7tyyzlckn.fsf@m17n.org>, Kenichi Handa <handa@m17n.org> writes:

> We still have a problem of slow GC caused by many elements
> of char-tables (mostly because of charset encoders).  My
> idea for fixing it is to somehow distinguish a char-table
> that has only integer or (interned) symbol elements from the
> other normal char-tables, and optimize mark_char_table for
> it.  But, at the moment, I don't have a time to work on it.

I tried to implement a new function mark_charsets that marks
encoder char-tables of charsets in a special way, but it
improved the performance only a few percent.  It means that
the current loop in mark_char_table is fast enough.

By the way, I've misunderstood the output of gprof.

In article <200908240807.n7O87ubg024643@godzilla.ics.uci.edu>, Dan Nicolaescu <dann@ics.uci.edu> writes:

> One big difference is then time/number of calls to mark_objects 
> 129733 vs 18834514, so 145 times more calls to mark_object.
> Do you know where do those come from?

Emacs 22 didn't have the function mark_vectorlike and
mark_object directly handled the marking of Lisp_Vectorlike
by recursive call.  And the number 129733 doesn't include
the number of such recursive calls.  The result of profiling
this execution:

% time LANG=C emacs-22/src/emacs -Q -batch --eval '(dotimes (i 100) (garbage-collect))'

shows this:
[8]     82.9    1.35    0.01  183705+25673200 mark_object <cycle 2> [8]

So the total number of calls is 25856905.  The similar tries
with Emacs 23 and the trunk are:

Emacs-23:
[12]    76.6    1.64    0.00 28911397+8925193 mark_object <cycle 2> [12]
Total number of calls is 37836590.

The trunk:
[12]    64.2    1.13    0.00 14102473+8981954 mark_object <cycle 2> [12]
Total number of calls is 23084427.

It seems that mark_char_table introduced in the trunk works
effectively and leads to less object marking than Emacs 22.

So, I think we can close this thread.

---
Kenichi Handa
handa@m17n.org