[Texmacs-dev] Cache profiling of TeXmacs 1.0.3.9

[David MENTRE]

Hello,

Following David advice, I have done some cache profiling of texmacs
using OProfile.

Kernel 2.6.5 on an AMD Athlon 1.8 GHz, 1 GB ram, gcc 3.3.3, TeXmacs
1.0.3.9.

In the following, '$' is for user command and '#' for root commands.

* Procedure followed
  ------------------

untar TeXmacs-1.0.3.9-src.tar.gz

$ ./configure --prefix=/home/david/00-poubelle/texmacs --enable-debug


$ make && make install

# opcontrol --setup --no-vmlinux --event=DATA_CACHE_MISSES:2000 
--event=DATA_CACHE_ACCESSES:2000 --event=DATA_CACHE_REFILLS_FROM_L2:2000:0x1f 
--event=DATA_CACHE_REFILLS_FROM_SYSTEM:2000:0x1f

(please notice that those events are Athlon specific, they might be
different on another CPU)

# opcontrol --start

$ bin/texmacs -q  (or other use of texmacs)


# opcontrol --dump

$ opreport -l event:DATA_CACHE_MISSES,DATA_CACHE_ACCESSES 
image:*texmacs.bin,*guile*|less


$ opreport -l event:DATA_CACHE_MISSES image:*texmacs.bin,*guile*|less


* Some results
  ------------

I have launched texmacs and also generated the user manual (same
procedure as in my first post on gprof). Here are some results found
after those tests.

 1. Overall cache accesses. Good locality for
    "char_bitstream::write(int, int, int)". Bad locality for Guile. Not
    so good locality for "operator new(unsigned int)" and
    "tree::~tree()".

$ opreport -l event:DATA_CACHE_MISSES,DATA_CACHE_ACCESSES 
image:*texmacs.bin,*guile*|head -n 30
CPU: Athlon, speed 1826.62 MHz (estimated)
Counted DATA_CACHE_ACCESSES events (Data cache accesses) with a unit mask of 
0x00 (No unit mask) count 2000
Counted DATA_CACHE_MISSES events (Data cache misses) with a unit mask of 0x00 
(No unit mask) count 2000
samples  %        samples  %        app name                 symbol name
317779   10.1917  23        0.3588  texmacs.bin              
char_bitstream::write(int, int, int)
245469    7.8726  23        0.3588  texmacs.bin              round_length(int)
240929    7.7270  2939     45.8502  libguile.so.12.3.0       (no symbols)
84597     2.7132  28        0.4368  texmacs.bin              
string::operator[](int)
80384     2.5781  52        0.8112  texmacs.bin              
string::string(string const&)
77534     2.4866  93        1.4509  texmacs.bin              string::~string()
75955     2.4360  178       2.7769  texmacs.bin              operator 
new(unsigned int)
75226     2.4126  4         0.0624  texmacs.bin              glyph::operator->()
60624     1.9443  19        0.2964  texmacs.bin              
string::operator->()
60504     1.9405  67        1.0452  texmacs.bin              tree::tree(tree 
const&)
57992     1.8599  124       1.9345  texmacs.bin              tree::~tree()
52046     1.6692  19        0.2964  texmacs.bin              operator 
delete(void*)
48042     1.5408  2         0.0312  texmacs.bin              
glyph_rep::get_1(int, int)
46911     1.5045  7         0.1092  texmacs.bin              
operator<<(string&, char)
46231     1.4827  29        0.4524  texmacs.bin              hash(string)
45173     1.4488  58        0.9048  texmacs.bin              
string::operator==(string)
41546     1.3325  61        0.9516  texmacs.bin              
string::operator==(char*)
40857     1.3104  19        0.2964  texmacs.bin              N(string)
39805     1.2766  45        0.7020  texmacs.bin              
string_rep::resize(int)
35723     1.1457  26        0.4056  texmacs.bin              list<int>::~list()
33193     1.0646  43        0.6708  texmacs.bin              
hashmap_rep<string, string>::bracket_ro(string)
32078     1.0288  16        0.2496  texmacs.bin              
string::string(char*)
29427     0.9438  19        0.2964  texmacs.bin              
list<int>::list(list<int> const&)
28973     0.9292  14        0.2184  texmacs.bin              operator 
new[](unsigned int)
26416     0.8472  23        0.3588  texmacs.bin              operator*(string, 
string)
24681     0.7916  97        1.5133  texmacs.bin              
concrete_struct::~concrete_struct()


 2. Guile generates a lot of cache misses. Otherwise, string and tree
    operator account for a small percentage of cache misses.

$ opreport -l event:DATA_CACHE_MISSES image:*texmacs*,*guile*|head -n 30
CPU: Athlon, speed 1826.62 MHz (estimated)
Counted DATA_CACHE_MISSES events (Data cache misses) with a unit mask of 0x00 
(No unit mask) count 2000
samples  %        app name                 symbol name
2939     45.8502  libguile.so.12.3.0       (no symbols)
178       2.7769  texmacs.bin              operator new(unsigned int)
124       1.9345  texmacs.bin              tree::~tree()
97        1.5133  texmacs.bin              concrete_struct::~concrete_struct()
93        1.4509  texmacs.bin              string::~string()
92        1.4353  texmacs.bin              L(tree)
89        1.3885  texmacs.bin              string::operator!=(string)
77        1.2012  texmacs.bin              list<hashentry<string, string> 
>::operator->()
68        1.0608  texmacs.bin              operator!=(tree, tree)
67        1.0452  texmacs.bin              tree::tree(tree const&)
61        0.9516  texmacs.bin              string::operator==(char*)
61        0.9516  texmacs.bin              string_rep::string_rep()
58        0.9048  texmacs.bin              string::operator==(string)
53        0.8268  texmacs.bin              destroy_tree_rep(tree_rep*)
52        0.8112  texmacs.bin              string::string(string const&)
50        0.7800  texmacs.bin              concrete_struct::concrete_struct()
49        0.7644  texmacs.bin              list<hashentry<string, string> 
>::operator=(list<hashentry<string, string> >)
45        0.7020  texmacs.bin              string_rep::resize(int)
43        0.6708  texmacs.bin              hashmap_rep<string, 
string>::bracket_ro(string)
39        0.6084  texmacs.bin              array<tree>::~array()
39        0.6084  texmacs.bin              string_rep::~string_rep()
37        0.5772  texmacs.bin              array_rep<tree>::~array_rep()
34        0.5304  texmacs.bin              operator==(tree, char*)
33        0.5148  texmacs.bin              list<hashentry<string, string> 
>::list(list<hashentry<string, string> > const&)
30        0.4680  texmacs.bin              N(tree)
30        0.4680  texmacs.bin              is_atomic(tree)
29        0.4524  texmacs.bin              hash(string)


 3. The most costly cache refills (refill from main memory) come from
    Guile, "composite_box_rep::collect_page_numbers(hashmap<string,
    tree>&, tree)", "tree::tree(tree const&)",
    "concrete_struct::~concrete_struct()" and "operator new(unsigned
    int)".


$ opreport -l event:DATA_CACHE_REFILLS_FROM_SYSTEM -c 
image:*texmacs.bin,*guile*|head -n 30
CPU: Athlon, speed 1826.62 MHz (estimated)
Counted DATA_CACHE_REFILLS_FROM_SYSTEM events (Data cache refills from system) 
with a unit mask of 0x1f (All cache states) count 2000
samples  cum. samples  %        cum. %     app name                 symbol name
1016     1016          49.6579  49.6579    libguile.so.12.3.0       (no symbols)
63       1079           3.0792  52.7370    texmacs.bin              
composite_box_rep::collect_page_numbers(hashmap<string, tree>&, tree)
49       1128           2.3949  55.1320    texmacs.bin              
tree::tree(tree const&)
44       1172           2.1505  57.2825    texmacs.bin              
concrete_struct::~concrete_struct()
38       1210           1.8573  59.1398    texmacs.bin              operator 
new(unsigned int)
30       1240           1.4663  60.6061    texmacs.bin              
string::~string()
30       1270           1.4663  62.0723    texmacs.bin              
tree::~tree()
26       1296           1.2708  63.3431    texmacs.bin              
string_rep::~string_rep()
23       1319           1.1241  64.4673    texmacs.bin              
destroy_tree_rep(tree_rep*)
22       1341           1.0753  65.5425    texmacs.bin              
string::operator!=(string)
20       1361           0.9775  66.5200    texmacs.bin              
list<hashentry<string, string> >::list(list<hashentry<string, string> > const&)
18       1379           0.8798  67.3998    texmacs.bin              
concrete_struct::concrete_struct()
18       1397           0.8798  68.2796    texmacs.bin              operator 
delete[](void*)
17       1414           0.8309  69.1105    texmacs.bin              
list<int>::~list()
15       1429           0.7331  69.8436    texmacs.bin              
array<box>::array(array<box> const&)
15       1444           0.7331  70.5767    texmacs.bin              
string::operator==(string)
14       1458           0.6843  71.2610    texmacs.bin              
array<tree>::~array()
14       1472           0.6843  71.9453    texmacs.bin              
string::operator==(char*)
14       1486           0.6843  72.6295    texmacs.bin              
string::string(string const&)
13       1499           0.6354  73.2649    texmacs.bin              
array_rep<tree>::~array_rep()
12       1511           0.5865  73.8514    texmacs.bin              L(tree)
12       1523           0.5865  74.4379    texmacs.bin              
atomic_rep::atomic_rep(string)
10       1533           0.4888  74.9267    texmacs.bin              
box_rep::collect_page_numbers(hashmap<string, tree>&, tree)
10       1543           0.4888  75.4154    texmacs.bin              
list<int>::list(list<int> const&)
10       1553           0.4888  75.9042    texmacs.bin              tree::tree()
10       1563           0.4888  76.3930    texmacs.bin              
url::url(tree)
9        1572           0.4399  76.8328    texmacs.bin              
string_rep::string_rep()



David, tell me if you want more precise or different results.


BTW, a side note I forgot in my first post. Before optimizing, it is
good to know what to optimize. This is the intent of my posts.

Yours,
david
-- 
 David Mentré <address@hidden>