Fix SourceForge bug report #129892, "profiler map__lookup failed

Estimated hours taken: 3

Fix SourceForge bug report #129892, "profiler map__lookup failed
in grade hlc.gc.memprof".

The remaining problem that was still causing failures for this
test case was that demangling isn't implemented for the MLDS
back-end.  When symbols that the MLDS back end generates are
fed through the demangler, it demangles some distinct symbols
to the same name.  This causes the profiler to abort, because
it assumes that each distinct symbol demangles to a different
name.

The fix is to turn off demangling when profiling programs
built in MLDS grades.

NEWS:
	Mention that we haven't implemented symbol demangling
	in the profiler for the MLDS back-end yet.

doc/user_guide.texi:
	Document that for profiling of programs built with
	`--high-level-code' you need to use the `--no-demangle'
	option.

tools/test_mercury:
	When testing the profiler in hl* grades,
	pass `--no-demangle' to mprof, and compare with
	*.mprof-exp2 rather than *.mprof-exp.

tests/benchmarks/poly.mprof-exp2:
	New file.  Contains alternative expected output for this test
	case, to match what is output for grade hlc.gc.memprof (at -O2).

profiler/options.m:
	The `--(no-)demangle' option is not a filename option,
	so document it under the "Profiler options" section,
	rather than the "Filename options" section.
	Also fix a typo (s/Ouput/Output/) and a thinko
	(s/unmangled/mangled/) in the description of that option.
This commit is contained in:
Fergus Henderson
2001-02-06 07:11:48 +00:00
parent 3528bed5b2
commit cf99344e4a
5 changed files with 357 additions and 7 deletions

1
NEWS
View File

@@ -239,6 +239,7 @@ Changes to the Mercury implementation:
- calling copy/2 on higher-order terms
It also does not support the following implemention-specific
features that the old back-end supports:
- demangling of symbol names in the profiler
- fact tables for procedures with determinism `nondet' or `multi'
- the Mercury debugger (mdb)
- the Morphine trace analysis system

View File

@@ -48,7 +48,7 @@ into another language, under the above conditions for modified versions.
@author Peter Ross
@page
@vskip 0pt plus 1filll
Copyright @copyright{} 1995-1999 The University of Melbourne.
Copyright @copyright{} 1995-2001 The University of Melbourne.
Permission is granted to make and distribute verbatim copies of
this manual provided the copyright notice and this permission notice
@@ -2620,6 +2620,9 @@ usually produce quite a lot of output, so you will usually want to
redirect the output into a file with a command such as
@samp{mprof > mprof.out}.
For programs built with @samp{--high-level-code}, you need to also
pass the @samp{--no-demangle} option to @samp{mprof}.
@node Analysis of results
@section Analysis of results

View File

@@ -1,5 +1,5 @@
%-----------------------------------------------------------------------------%
% Copyright (C) 1995-1997,2000 The University of Melbourne.
% Copyright (C) 1995-1997, 2000-2001 The University of Melbourne.
% This file may only be copied under the terms of the GNU General
% Public License - see the file COPYING in the Mercury distribution.
%-----------------------------------------------------------------------------%
@@ -27,11 +27,12 @@
; profile_time
; profile_memory_words
; profile_memory_cells
; demangle
% Filename options
; countfile
; pairfile
; declfile
; libraryfile
; demangle
% Miscellaneous Options
; help.
@@ -157,6 +158,8 @@ options_help -->
io__write_string("\t\tSame as `--profile memory-cells'.\n"),
io__write_string("\t-t\n"),
io__write_string("\t\tSame as `--profile time'.\n"),
io__write_string("\t--no-demangle\n"),
io__write_string("\t\tOutput the mangled predicate and function names.\n"),
io__write_string("\nFilename Options:\n"),
io__write_string("\t-C <file>, --count-file <file>\n"),
@@ -169,8 +172,6 @@ options_help -->
io__write_string("\t-L <file>, --library-callgraph <file>\n"),
io__write_string("\t\tName of the file which contains the call graph for\n"),
io__write_string("\t\tthe library modules.\n"),
io__write_string("\t--no-demangle\n"),
io__write_string("\t\tOuput the unmangled predicate and function names.\n"),
io__write_string("\nVerbosity Options:\n"),

View File

@@ -0,0 +1,332 @@
% Processing input files... done
% Building call graph... done
% Propagating counts... done
% Generating output... done
*** profiling memory-words ***
call graph profile:
Sorted on the %mem field.
procedure entries:
index the index number of the procedure in the call graph
listing.
%mem the percentage of the total allocated memory of
the program allocated by this procedure and its
descendents.
self the number of kilowords actually allocated by
the procedure's own code.
descendents the number of kilowords allocated by the
descendents of the current procedure.
called the number of times the current procedure is
called (not counting self recursive calls).
self the number of self recursive calls.
name the name of the current procedure.
index an index number to locate the function easily.
parent listings:
self* the number of kilowords of the current procedure's self
memory due to calls from this parent.
descendents* the number of kilowords of the current procedure's descendent
memory which is due to calls from this parent.
called* the number of times the current procedure is called
by this parent.
total the number of times this procedure is called by its parents.
parents the name of this parent.
index the index number of the parent procedure
children listings:
self* the number of kilowords of this child's self memory which is
due to being called by the current procedure.
descendent* the number of kilowords of this child's descendent memory which
is due to the current procedure.
called* the number of times this child is called by the current
procedure.
total* the number of times this child is called by all procedures.
children the name of this child.
index the index number of the child.
called/total parents
index %mem self descendents called+self name index
called/total children
0.00 39.05 1/1 main_2_p_0 [2]
[1] 99.9 0.00 39.05 1 poly__main1_1_p_0 [1]
0.00 0.00 2/3433 poly__poly_add_3_p_0 <cycle 4> [8]
0.00 39.01 1/1 poly__poly_exp_3_p_0 [3]
-----------------------------------------------
<spontaneous>
[2] 99.9 0.00 39.05 0 main_2_p_0 [2]
0.00 0.00 1/2307 mercury__io__write_string_3_p_0 [22]
0.00 39.05 1/1 poly__main1_1_p_0 [1]
0.00 0.00 1/352 poly__print_poly_3_p_0 <cycle 2> [20]
-----------------------------------------------
5 poly__poly_exp_3_p_0 [3]
0.00 39.01 1/1 poly__main1_1_p_0 [1]
[3] 99.8 0.00 39.01 1+5 poly__poly_exp_3_p_0 [3]
0.01 0.01 5/3930 poly__poly_mul_3_p_0 <cycle 3> [7]
5 poly__poly_exp_3_p_0 [3]
-----------------------------------------------
932 poly__term_mul_3_p_0 <cycle 3> [4]
283 poly__poly_mul_3_p_0 <cycle 3> [7]
[4] 48.2 0.00 18.85 283+932 poly__term_mul_3_p_0 <cycle 3> [4]
10.32 10.32 932/1355 poly__term_add_3_p_0 <cycle 4> [5]
932 poly__single_term_mul_3_p_0 <cycle 3> [6]
932 poly__term_mul_3_p_0 <cycle 3> [4]
-----------------------------------------------
4077 poly__term_add_3_p_0 <cycle 4> [5]
423 poly__poly_add_3_p_0 <cycle 4> [8]
15.01 15.01 932/1355 poly__term_mul_3_p_0 <cycle 3> [4]
[5] 38.4 15.01 15.01 1355+4077 poly__term_add_3_p_0 <cycle 4> [5]
3428 poly__poly_add_3_p_0 <cycle 4> [8]
4077 poly__term_add_3_p_0 <cycle 4> [5]
-----------------------------------------------
3129 poly__single_term_mul_3_p_0 <cycle 3> [6]
932 poly__term_mul_3_p_0 <cycle 3> [4]
[6] 32.0 12.52 12.52 932+3129 poly__single_term_mul_3_p_0 <cycle 3> [6]
3129 poly__poly_mul_3_p_0 <cycle 3> [7]
3129 poly__single_term_mul_3_p_0 <cycle 3> [6]
-----------------------------------------------
796 poly__mul_through_3_p_0 <cycle 3> [9]
3129 poly__single_term_mul_3_p_0 <cycle 3> [6]
4.46 4.46 5/3930 poly__poly_exp_3_p_0 [3]
[7] 11.4 4.46 4.46 3930 poly__poly_mul_3_p_0 <cycle 3> [7]
251 poly__mul_through_3_p_0 <cycle 3> [9]
283 poly__term_mul_3_p_0 <cycle 3> [4]
-----------------------------------------------
3 poly__add_to_order_zero_term_3_p_0 <cycle 4> [13]
3428 poly__term_add_3_p_0 <cycle 4> [5]
3.86 3.86 2/3433 poly__main1_1_p_0 [1]
[8] 9.9 3.86 3.86 3433 poly__poly_add_3_p_0 <cycle 4> [8]
5 poly__add_to_order_zero_term_3_p_0 <cycle 4> [13]
423 poly__term_add_3_p_0 <cycle 4> [5]
-----------------------------------------------
796 poly__mul_through_3_p_0 <cycle 3> [9]
251 poly__poly_mul_3_p_0 <cycle 3> [7]
[9] 8.1 3.18 3.18 251+796 poly__mul_through_3_p_0 <cycle 3> [9]
796 poly__poly_mul_3_p_0 <cycle 3> [7]
796 poly__mul_through_3_p_0 <cycle 3> [9]
-----------------------------------------------
<spontaneous>
[10] 0.1 0.00 0.02 0 mercury__io__init_state_2_p_0 [10]
0.00 0.02 1/1 mercury__io__insert_std_stream_names_2_p_0 [11]
0.00 0.00 1/1 mercury__std_util__type_to_univ_2_p_0 [16]
0.00 0.00 1/1 mercury__tree234__init_1_p_0 [23]
-----------------------------------------------
0.00 0.02 1/1 mercury__io__init_state_2_p_0 [10]
[11] 0.1 0.00 0.02 1 mercury__io__insert_std_stream_names_2_p_0 [11]
0.00 0.02 3/3 mercury__tree234__set_4_p_1 [12]
-----------------------------------------------
0.00 0.02 3/3 mercury__io__insert_std_stream_names_2_p_0 [11]
[12] 0.1 0.00 0.02 3 mercury__tree234__set_4_p_1 [12]
0.01 0.01 1/1 mercury__tree234__set2__ua1_4_p_0 [15]
0.01 0.01 1/1 mercury__tree234__set3__ua1_4_p_0 [14]
-----------------------------------------------
5 poly__poly_add_3_p_0 <cycle 4> [8]
[13] 0.1 0.02 0.02 5 poly__add_to_order_zero_term_3_p_0 <cycle 4> [13]
3 poly__poly_add_3_p_0 <cycle 4> [8]
-----------------------------------------------
0.01 0.01 1/1 mercury__tree234__set_4_p_1 [12]
[14] 0.0 0.01 0.01 1 mercury__tree234__set3__ua1_4_p_0 [14]
0.00 0.00 2/3 mercury__builtin__compare_3_p_0 [24]
-----------------------------------------------
0.01 0.01 1/1 mercury__tree234__set_4_p_1 [12]
[15] 0.0 0.01 0.01 1 mercury__tree234__set2__ua1_4_p_0 [15]
0.00 0.00 1/3 mercury__builtin__compare_3_p_0 [24]
-----------------------------------------------
0.00 0.00 1/1 mercury__io__init_state_2_p_0 [10]
[16] 0.0 0.00 0.00 1 mercury__std_util__type_to_univ_2_p_0 [16]
-----------------------------------------------
351 poly__print_terms_2_3_p_0 <cycle 2> [18]
[17] 0.0 0.00 0.00 351 poly__print_term_3_p_0 <cycle 2> [17]
0.00 0.00 351/637 mercury__io__write_int_3_p_0 [21]
0.00 0.00 1053/2307 mercury__io__write_string_3_p_0 [22]
351 poly__print_poly_3_p_0 <cycle 2> [20]
-----------------------------------------------
66 poly__print_terms_3_p_0 <cycle 2> [19]
[18] 0.0 0.00 0.00 66 poly__print_terms_2_3_p_0 <cycle 2> [18]
0.00 0.00 285/2307 mercury__io__write_string_3_p_0 [22]
351 poly__print_term_3_p_0 <cycle 2> [17]
-----------------------------------------------
66 poly__print_poly_3_p_0 <cycle 2> [20]
[19] 0.0 0.00 0.00 66 poly__print_terms_3_p_0 <cycle 2> [19]
0.00 0.00 132/2307 mercury__io__write_string_3_p_0 [22]
66 poly__print_terms_2_3_p_0 <cycle 2> [18]
-----------------------------------------------
351 poly__print_term_3_p_0 <cycle 2> [17]
0.00 0.00 1/352 main_2_p_0 [2]
[20] 0.0 0.00 0.00 352 poly__print_poly_3_p_0 <cycle 2> [20]
0.00 0.00 286/637 mercury__io__write_int_3_p_0 [21]
0.00 0.00 836/2307 mercury__io__write_string_3_p_0 [22]
66 poly__print_terms_3_p_0 <cycle 2> [19]
-----------------------------------------------
0.00 0.00 286/637 poly__print_poly_3_p_0 <cycle 2> [20]
0.00 0.00 351/637 poly__print_term_3_p_0 <cycle 2> [17]
[21] 0.0 0.00 0.00 637 mercury__io__write_int_3_p_0 [21]
-----------------------------------------------
0.00 0.00 1/2307 main_2_p_0 [2]
0.00 0.00 836/2307 poly__print_poly_3_p_0 <cycle 2> [20]
0.00 0.00 1053/2307 poly__print_term_3_p_0 <cycle 2> [17]
0.00 0.00 285/2307 poly__print_terms_2_3_p_0 <cycle 2> [18]
0.00 0.00 132/2307 poly__print_terms_3_p_0 <cycle 2> [19]
[22] 0.0 0.00 0.00 2307 mercury__io__write_string_3_p_0 [22]
-----------------------------------------------
0.00 0.00 1/1 mercury__io__init_state_2_p_0 [10]
[23] 0.0 0.00 0.00 1 mercury__tree234__init_1_p_0 [23]
-----------------------------------------------
0.00 0.00 1/3 mercury__tree234__set2__ua1_4_p_0 [15]
0.00 0.00 2/3 mercury__tree234__set3__ua1_4_p_0 [14]
[24] 0.0 0.00 0.00 3 mercury__builtin__compare_3_p_0 [24]
-----------------------------------------------
flat profile:
% the percentage of total allocated memory of the program
mem used by this procedure.
cumulative the total number of kilowords for the current procedure and
k-words the ones listed above it.
self the number of kilowords accounted for by this procedure alone.
k-words The listing is sorted on this row.
calls the number of times this procedure was called.
self the average number of words allocated by
wds/call this procedure per call.
total the average number of words allocated by this procedure and its
wds/call descendents per call.
name the name of the procedure followed by its index number.
% cumulative self self total
mem k-words k-words calls wds/call wds/call name
38.4 15.01 15.01 5432 2.76 2.76 poly__term_add_3_p_0 <cycle 4> [5]
32.0 27.53 12.52 4061 3.08 3.08 poly__single_term_mul_3_p_0 <cycle 3> [6]
11.4 31.99 4.46 3930 1.14 1.14 poly__poly_mul_3_p_0 <cycle 3> [7]
9.9 35.85 3.86 3433 1.12 1.12 poly__poly_add_3_p_0 <cycle 4> [8]
8.1 39.03 3.18 1047 3.04 3.04 poly__mul_through_3_p_0 <cycle 3> [9]
0.1 39.05 0.02 5 4.00 4.00 poly__add_to_order_zero_term_3_p_0 <cycle 4> [13]
0.0 39.06 0.01 1 10.00 10.00 mercury__tree234__set3__ua1_4_p_0 [14]
0.0 39.07 0.01 1 7.00 7.00 mercury__tree234__set2__ua1_4_p_0 [15]
0.0 39.08 0.00 3 1.33 7.00 mercury__tree234__set_4_p_1 [12]
0.0 39.08 0.00 1 2.00 2.00 mercury__std_util__type_to_univ_2_p_0 [16]
0.0 39.08 0.00 2307 0.00 0.00 mercury__io__write_string_3_p_0 [22]
0.0 39.08 0.00 637 0.00 0.00 mercury__io__write_int_3_p_0 [21]
0.0 39.08 0.00 352 0.00 0.00 poly__print_poly_3_p_0 <cycle 2> [20]
0.0 39.08 0.00 351 0.00 0.00 poly__print_term_3_p_0 <cycle 2> [17]
0.0 39.08 0.00 1215 0.00 15.51 poly__term_mul_3_p_0 <cycle 3> [4]
0.0 39.08 0.00 66 0.00 0.00 poly__print_terms_2_3_p_0 <cycle 2> [18]
0.0 39.08 0.00 66 0.00 0.00 poly__print_terms_3_p_0 <cycle 2> [19]
0.0 39.08 0.00 3 0.00 0.00 mercury__builtin__compare_3_p_0 [24]
0.0 39.08 0.00 6 0.00 6502.42 poly__poly_exp_3_p_0 [3]
0.0 39.08 0.00 1 0.00 39055.00 poly__main1_1_p_0 [1]
0.0 39.08 0.00 1 0.00 21.00 mercury__io__insert_std_stream_names_2_p_0 [11]
0.0 39.08 0.00 1 0.00 0.00 mercury__tree234__init_1_p_0 [23]
0.0 39.08 0.00 0 0.00 0.00 main_2_p_0 [2]
0.0 39.08 0.00 0 0.00 0.00 mercury__io__init_state_2_p_0 [10]
alphabetic listing:
[2] main_2_p_0
[24] mercury__builtin__compare_3_p_0
[10] mercury__io__init_state_2_p_0
[11] mercury__io__insert_std_stream_names_2_p_0
[21] mercury__io__write_int_3_p_0
[22] mercury__io__write_string_3_p_0
[16] mercury__std_util__type_to_univ_2_p_0
[23] mercury__tree234__init_1_p_0
[15] mercury__tree234__set2__ua1_4_p_0
[14] mercury__tree234__set3__ua1_4_p_0
[12] mercury__tree234__set_4_p_1
[13] poly__add_to_order_zero_term_3_p_0
[1] poly__main1_1_p_0
[9] poly__mul_through_3_p_0
[8] poly__poly_add_3_p_0
[3] poly__poly_exp_3_p_0
[7] poly__poly_mul_3_p_0
[20] poly__print_poly_3_p_0
[17] poly__print_term_3_p_0
[18] poly__print_terms_2_3_p_0
[19] poly__print_terms_3_p_0
[6] poly__single_term_mul_3_p_0
[5] poly__term_add_3_p_0
[4] poly__term_mul_3_p_0

View File

@@ -622,8 +622,21 @@ do
EXTRA_CFLAGS="$TEST_CFLAGS" \
EXTRA_MLFLAGS="$TEST_MLFLAGS" &&
LD_BIND_NOW=1 ./poly > poly.$grade.out &&
mprof -v -m -c > poly.$grade.mprof 2>&1 &&
{ diff -u poly.mprof-exp poly.$grade.mprof || true; } &&
case $grade in
*hl*)
# for --high-level-code, we need to
# pass --no-demangle to mprof
mprof --no-demangle -v -m -c \
> poly.$grade.mprof 2>&1 &&
{ diff -u poly.mprof-exp2 poly.$grade.mprof ||
true; }
;;
*)
mprof -v -m -c > poly.$grade.mprof 2>&1 &&
{ diff -u poly.mprof-exp poly.$grade.mprof ||
true; }
;;
esac &&
cp Prof.CallPair poly.$grade.CallPair &&
cp Prof.MemoryWords poly.$grade.MemoryWords &&
cp Prof.MemoryCells poly.$grade.MemoryCells &&