GNU bug report logs - #4222
calls to char_table_ref slow down 23.1 (vs 22.3)

Previous Next

To add a comment to this bug, you must first unarchive it, by sending
a message to control AT debbugs.gnu.org, with unarchive 4222 in the body.
You can then email your comments to 4222 AT debbugs.gnu.org in the normal way.

Toggle the display of automated, internal messages from the tracker.

Message #3 received at submit <at> emacsbugs.donarmstrong.com (full text, mbox):

From: Dan Nicolaescu <dann <at> ics.uci.edu>
To: bug-gnu-emacs <bug-gnu-emacs <at> gnu.org>
Subject: calls to char_table_ref slow down 23.1 (vs 22.3)
Date: Thu, 20 Aug 2009 22:18:10 -0700 (PDT)

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?

Message #8 received at 4222 <at> emacsbugs.donarmstrong.com (full text, mbox):

From: Kenichi Handa <handa <at> m17n.org>
To: Dan Nicolaescu <dann <at> ics.uci.edu>, 4222 <at> debbugs.gnu.org
Subject: Re: bug#4222: calls to char_table_ref slow down 23.1 (vs 22.3)
Date: Fri, 21 Aug 2009 15:34:10 +0900

> 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 <at> m17n.org

Message #11 received at 4222 <at> emacsbugs.donarmstrong.com (full text, mbox):

From: Dan Nicolaescu <dann <at> ics.uci.edu>
To: Kenichi Handa <handa <at> m17n.org>
Cc: 4222 <at> debbugs.gnu.org
Subject: Re: bug#4222: calls to char_table_ref slow down 23.1 (vs 22.3)
Date: Fri, 21 Aug 2009 00:08:17 -0700 (PDT)

Kenichi Handa <handa <at> 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

Message #16 received at 4222 <at> emacsbugs.donarmstrong.com (full text, mbox):

From: Chong Yidong <cyd <at> stupidchicken.com>
To: Dan Nicolaescu <dann <at> ics.uci.edu>
Cc: Kenichi Handa <handa <at> m17n.org>, 4222 <at> debbugs.gnu.org
Subject: Re: calls to char_table_ref slow down 23.1 (vs 22.3)
Date: Fri, 18 Sep 2009 19:30:57 -0400

> 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?

Message #19 received at 4222 <at> emacsbugs.donarmstrong.com (full text, mbox):

From: Dan Nicolaescu <dann <at> ics.uci.edu>
To: Chong Yidong <cyd <at> stupidchicken.com>
Cc: 4222 <at> debbugs.gnu.org
Subject: Re: bug#4222: calls to char_table_ref slow down 23.1 (vs 22.3)
Date: Fri, 18 Sep 2009 21:43:11 -0700 (PDT)

Chong Yidong <cyd <at> 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.

Message #24 received at 4222 <at> emacsbugs.donarmstrong.com (full text, mbox):

From: Kenichi Handa <handa <at> m17n.org>
To: Dan Nicolaescu <dann <at> ics.uci.edu>, 4222 <at> debbugs.gnu.org
Cc: cyd <at> stupidchicken.com, 4222 <at> debbugs.gnu.org
Subject: Re: bug#4222: calls to char_table_ref slow down 23.1 (vs 22.3)
Date: Sat, 19 Sep 2009 14:37:28 +0900

In article <200909190443.n8J4hBNM011012 <at> godzilla.ics.uci.edu>, Dan Nicolaescu <dann <at> 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 <at> m17n.org

Message #29 received at 4222 <at> emacsbugs.donarmstrong.com (full text, mbox):

From: Kenichi Handa <handa <at> m17n.org>
To: 4222 <at> debbugs.gnu.org
Cc: dann <at> ics.uci.edu, cyd <at> stupidchicken.com
Subject: Re: bug#4222: calls to char_table_ref slow down 23.1 (vs 22.3)
Date: Thu, 24 Sep 2009 13:05:18 +0900

In article <tl7tyyzlckn.fsf <at> m17n.org>, Kenichi Handa <handa <at> 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 <at> godzilla.ics.uci.edu>, Dan Nicolaescu <dann <at> 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 <at> m17n.org

Previous Next

GNU bug tracking system
Copyright (C) 1999 Darren O. Benham, 1997,2003 nCipher Corporation Ltd, 1994-97 Ian Jackson.