[Texmacs-dev] A first attempt to analyze TeXmacs performance behavior

[David MENTRE]

Hello,

I tried to understand the performance of TeXmacs. So I compiled texmacs,
ran it and then analyzed the result using gprof.

I compiled texmacs with following command:
./configure --prefix=/home/david/00-poubelle/texmacs --enable-debug CXX='g++ 
-pg -fprofile-arcs'

I used gcc suite 3.3.3 and TeXmacs 1.0.3.9.

I ran two test cases:

 1. - Launch texmacs

    - Run Help>Complete manuals>User manual

    - Run File>New

    - enter: a=b²+c²
             Bienvenu sur TeXmacs.

    - save the buffer

    - quit texmacs


 2. - Launch texmacs

    - Insert>Session>Shell

    - enter: env 

    - quit texmacs


I have put complete gprof outputs at:
  http://www.linux-france.org/~dmentre/texmacs/perf-texmacs/

For the first test case, here is the list of functions taking more than
0.5% of computation time:

Each sample counts as 0.01 seconds.
  %   cumulative   self              self     total           
 time   seconds   seconds    calls   s/call   s/call  name    
  3.66      8.08     8.08 33425247     0.00     0.00  operator new(unsigned int)
  3.35     15.49     7.41  1676626     0.00     0.00  
char_bitstream::write(int, int, int)
  2.90     21.89     6.40 92307243     0.00     0.00  string::~string()
  2.75     27.97     6.08 16071386     0.00     0.00  string::operator==(string)
  2.61     33.74     5.77 46621670     0.00     0.00  tree::tree(tree const&)
  2.56     39.39     5.65 79977389     0.00     0.00  string::string(string 
const&)
  2.49     44.90     5.51 122381456     0.00     0.00  string::operator[](int)
  2.35     50.10     5.20 61385517     0.00     0.00  list<int>::~list()
  1.99     54.50     4.40 52989004     0.00     0.00  tree::~tree()
  1.92     58.75     4.25  2809959     0.00     0.00  hashmap_rep<string, 
string>::bracket_ro(string)
  1.82     62.76     4.01  5726754     0.00     0.00  hash(string)
  1.78     66.68     3.93 32818897     0.00     0.00  operator delete(void*)
  1.72     70.48     3.80 55222457     0.00     0.00  list<int>::list(list<int> 
const&)
  1.53     73.87     3.39 11408388     0.00     0.00  operator new[](unsigned 
int)
  1.49     77.16     3.29 87740663     0.00     0.00  string::operator->()
  1.39     80.22     3.06 17381497     0.00     0.00  round_length(int)
  1.14     82.74     2.52 28558477     0.00     0.00  list<hashentry<string, 
string> >::list(list<hashentry<string, string> > const&)
  1.03     85.02     2.28  1306372     0.00     0.00  operator*(string, string)
  0.99     87.21     2.20 11211262     0.00     0.00  operator delete[](void*)
  0.97     89.36     2.15  9474403     0.00     0.00  string::operator==(char*)
  0.91     91.38     2.02  3999542     0.00     0.00  string::operator()(int, 
int)
  0.89     93.35     1.97  3064592     0.00     0.00  string::string(char*)
  0.89     95.31     1.96 12346047     0.00     0.00  string_rep::~string_rep()
  0.86     97.20     1.90 65814214     0.00     0.00  glyph::operator->()
  0.84     99.07     1.87 31200332     0.00     0.00  N(string)
  0.84    100.92     1.85  7348705     0.00     0.00  list<hashentry<string, 
tree> >::list(list<hashentry<string, tree> > const&)
  0.70    102.47     1.55  5504571     0.00     0.00  string::string(int)
  0.70    104.01     1.55 28603120     0.00     0.00  list<hashentry<string, 
string> >::~list()
  0.68    105.52     1.51    49227     0.00     0.00  get_hyphens(string, 
hashmap<string, string>)
  0.65    106.96     1.44   220590     0.00     0.00  
tex_font_rep::get_extents(string, metric_struct (&) [1])
  0.64    108.38     1.42 11359441     0.00     0.00  list<hashentry<string, 
string> >::operator=(list<hashentry<string, string> >)
  0.63    109.78     1.40 10560244     0.00     0.00  
array<tree>::array(array<tree> const&)
  0.57    111.03     1.25 32893045     0.00     0.00  
concrete_struct::concrete_struct()
  0.54    112.23     1.20 32412254     0.00     0.00  
concrete_struct::~concrete_struct()
  0.54    113.42     1.19  1081044     0.00     0.00  string::operator!=(string)
  0.53    114.60     1.18  8700562     0.00     0.00  
string_rep::string_rep(int)
  0.52    115.74     1.14 17174406     0.00     0.00  glyph_rep::get_1(int, int)
  0.51    116.86     1.12  4005109     0.00     0.00  operator<<(string&, char)
  0.50    117.97     1.11 22100742     0.00     0.00  bool nil<int>(list<int>)



Here is the same result for the second test case:

Each sample counts as 0.01 seconds.
  %   cumulative   self              self     total           
 time   seconds   seconds    calls   s/call   s/call  name    
  4.18      1.43     1.43  7904070     0.00     0.00  operator new(unsigned int)
  4.13      2.83     1.41 19805035     0.00     0.00  tree::~tree()
  2.99      3.85     1.02 17253973     0.00     0.00  tree::tree(tree const&)
  2.99      4.87     1.02 12411144     0.00     0.00  string::~string()
  2.54      5.74     0.87  7825656     0.00     0.00  operator delete(void*)
  1.85      6.37     0.63  1110861     0.00     0.00  string::string(char*)
  1.79      6.98     0.61  1218298     0.00     0.00  string::operator==(char*)
  1.76      7.58     0.60  9763807     0.00     0.00  string::string(string 
const&)
  1.76      8.18     0.60  2377123     0.00     0.00  operator new[](unsigned 
int)
  1.70      8.76     0.58  2652146     0.00     0.00  string_rep::~string_rep()
  1.66      9.32     0.57 15547477     0.00     0.00  string::operator[](int)
  1.61      9.87     0.55  3361743     0.00     0.00  round_length(int)
  1.53     10.39     0.52   740342     0.00     0.00  operator==(tree, tree)
  1.47     10.89     0.50   643656     0.00     0.00  
array_rep<tree>::array_rep(int)
  1.47     11.39     0.50     2358     0.00     0.00  
popup_button_rep::handle_mouse(event_ptr<mouse_event_rep>)
  1.35     11.85     0.46  2019029     0.00     0.00  texmacs_time()
  1.35     12.31     0.46  4061749     0.00     0.00  url::~url()
  1.26     12.74     0.43                             __store_gcov_type
  1.20     13.15     0.41    84995     0.00     0.00  operator*(url, url)
  1.16     13.55     0.40  9284216     0.00     0.00  string::operator->()
  1.15     13.94     0.39  2341565     0.00     0.00  operator delete[](void*)
  1.12     14.32     0.38   193484     0.00     0.00  operator*(string, string)
  1.09     14.69     0.37      425     0.00     0.00  shrink(glyph, int, int, 
int, int, int, int, int&, int&)
  1.03     15.04     0.35   128735     0.00     0.00  
char_bitstream::write(int, int, int)
  1.00     15.38     0.34  1606692     0.00     0.00  
string_rep::string_rep(int)
  0.97     15.71     0.33                             __fetch_gcov_type
  0.91     16.02     0.31  2584483     0.00     0.00  url::url(url const&)
  0.88     16.32     0.30  4114515     0.00     0.00  array<tree>::~array()
  0.85     16.61     0.29  7663828     0.00     0.00  
concrete_struct::concrete_struct()
  0.85     16.90     0.29  2002003     0.00     0.00  
x_drawable_rep::check_event(int)
  0.82     17.18     0.28  1025606     0.00     0.00  string::operator==(string)
  0.79     17.45     0.27  2554120     0.00     0.00  tree_rep::~tree_rep()
  0.79     17.72     0.27  1928522     0.00     0.00  
atomic_rep::atomic_rep(string)
  0.79     17.99     0.27   901815     0.00     0.00  string_rep::resize(int)
  0.76     18.25     0.26   879879     0.00     0.00  is_tuple(tree, char*, int)
  0.70     18.49     0.24  2719071     0.00     0.00  glyph_rep::get_1(int, int)
  0.70     18.73     0.24  1917805     0.00     0.00  atomic_rep::~atomic_rep()
  0.69     18.96     0.24  6492484     0.00     0.00  glyph::operator->()
  0.68     19.19     0.23                             __bb_exit_func
  0.65     19.41     0.22  1477300     0.00     0.00  url_rep::url_rep(tree)
  0.65     19.63     0.22    15998     0.00     0.00  array<int>::operator->()
  0.65     19.85     0.22  2572092     0.00     0.00  
tree_rep::tree_rep(tree_label)
  0.65     20.07     0.22   636372     0.00     0.00  
array_rep<tree>::~array_rep()
  0.63     20.29     0.22  3478143     0.00     0.00  
array<tree>::array(array<tree> const&)
  0.59     20.49     0.20  2554120     0.00     0.00  
destroy_tree_rep(tree_rep*)
  0.59     20.69     0.20  1470977     0.00     0.00  url::url(tree)
  0.59     20.89     0.20   274401     0.00     0.00  hash(string)
  0.56     21.08     0.19  1477267     0.00     0.00  url_rep::~url_rep()
  0.56     21.27     0.19    21691     0.00     0.00  
tex_font_rep::get_extents(string, metric_struct (&) [1])
  0.53     21.45     0.18  7587339     0.00     0.00  
concrete_struct::~concrete_struct()
  0.53     21.63     0.18   901237     0.00     0.00  operator<<(string&, char)
  0.51     21.80     0.18  4144999     0.00     0.00  N(string)
  0.50     21.97     0.17  1069651     0.00     0.00  url::operator[](int)
  0.50     22.14     0.17   471445     0.00     0.00  is_none(url)



It appears that those functions would have to be optimized in priority
in order to improve the speed of TeXmacs. I don't know much about C++
but I think that unfortunately some time consuming functions belong to
the C++ language, like "operator new(unsigned int)" or
"string::operator==(char*)".

I did not tried to analyze the breakout per function. It is more
difficult to analyze without knowing texmacs internals. And the output
of the analysis should be taken with care (gprof makes some assumptions
about subfunctions taking the same time each time they are called that
can be wrong).


In the long term, I think it would be necessary to have a systematic way
to check those performance issues. The best way would be to write Scheme
scripts that are launched at texmacs start, do some user behavior and
then quit texmacs. Unfortunalty, I don't know how to write such a scheme
script (however, if anybody on this list can help...).

Moreover, in the above results, the guile library is not instrumented. I
would probably be necessary to compile guile with the -pg option and
include it statically in TeXmacs (I don't know how to do that).

Yours,
d.
-- 
 David Mentré <address@hidden>