[m-dev.] for review: improve profiling of HO and method calls

[Fergus Henderson]

On 13-Sep-2000, Fergus Henderson <fjh at cs.mu.OZ.AU> wrote:
> 
> Fix some bugs in my previous change to profiling for do_call_closure
> and do_call_class_method.

Testing revealed that some further fixes were required.
For `if_val' llds instructions, we were outputting
a C `if' statement without any braces; this assumed
that `output_goto' always output a single C statement.
My change required output two macro calls for some gotos.
I tried to ensure that it still worked by using commas rather than
semicolons to separate the two macro calls, but (as testing
revealed) that didn't work since one of the macros concerned
expanded to a statement rather than an expression.
So I fixed this by changing what we do for `if_val' llds
instructions -- it now outputs the braces.

Here's a relative diff (and a new full diff, in case anyone is
interested).  I'll go ahead and commit this one now.

--- compiler/llds_out.m
+++ compiler/llds_out.m
@@ -1650,2 +1650,3 @@
-	io__write_string(")\n\t\t"),
-	output_goto(Target, CallerLabel).
+	io__write_string(") {\n\t\t"),
+	output_goto(Target, CallerLabel),
+	io__write_string("\t}\n").
@@ -3076 +3077 @@
-	io__write_string("),\n\t"),
+	io__write_string(");\n\t\t"),
@@ -3079 +3080 @@
-output_goto(do_call_class_method, _CallerLabel) -->
+output_goto(do_call_class_method, CallerLabel) -->
@@ -3083 +3084 @@
-	io__write_string("),\n\t"),
+	io__write_string(");\n\t\t"),
@@ -3139,0 +3141,3 @@
+	% But if we do use a noprof_call, we need to set
+	% MR_prof_ho_caller_proc, so that the callee knows
+	% which proc it has been called from.
@@ -3148 +3152 @@
-		io__write_string("),\n\t"),
+		io__write_string(");\n\t"),

Estimated hours taken: 2

Fix some bugs in my previous change to profiling for do_call_closure
and do_call_class_method.

runtime/mercury_calls.h:
	Change the definition of the noprof_* macros
	so that they don't do any of the profiling work.
	Previous the noprof_* macros omitted the PROFILE() call,
	but contrary to their names, they _did_ include the
	set_prof_current_proc() call.  I've moved those calls to
	set_prof_current_proc() into the ordinary (not noprof_)
	versions.
	This change is needed because my earlier change to
	compiler/llds_out.m and runtime/mercury_ho_call.c was assuming
	it -- without this change, time spent in do_call_closure would
	get credited to do_call_closure rather than the caller.

runtime/mercury_wrapper.c:
	Add a call to set_prof_current_proc(program_entry_point).
	This is needed now that noprof_call() doesn't do that.
	Furthermore it should be done before enabling profiling,
	otherwise there is a small window during which a profiling
	interrupt might occur before set_prof_current_proc() has been
	called.

runtime/mercury_prof.h:
runtime/mercury_prof.c:
	Add global var `MR_prof_ho_caller_proc' and macro
	MR_prof_set_ho_caller_proc().

compiler/llds_out.m:
	Call MR_prof_set_ho_caller_proc() before calling
	do_call_closure or do_call_class_method.

runtime/mercury_ho_call.c:
	Fix an XXX: pass MR_prof_ho_caller_proc rather than
	MR_prof_current_proc, since the former is meaningful even
	when PROFILE_TIME is not defined (e.g. for memory profiling),
	and since as described above MR_prof_current_proc is not
	longer set by noprof_call().

Workspace: /home/pgrad/fjh/ws/hg
Index: compiler/llds_out.m
===================================================================
RCS file: /home/mercury1/repository/mercury/compiler/llds_out.m,v
retrieving revision 1.153
diff -u -d -r1.153 llds_out.m
--- compiler/llds_out.m	2000/09/11 17:04:42	1.153
+++ compiler/llds_out.m	2000/09/13 02:17:54
@@ -1647,8 +1647,9 @@
 	{ ProfInfo = CallerLabel - _ },
 	io__write_string("\tif ("),
 	output_rval_as_type(Rval, bool),
-	io__write_string(")\n\t\t"),
-	output_goto(Target, CallerLabel).
+	io__write_string(") {\n\t\t"),
+	output_goto(Target, CallerLabel),
+	io__write_string("\t}\n").
 
 output_instruction(incr_hp(Lval, MaybeTag, Rval, TypeMsg), ProfInfo) -->
 	(
@@ -3069,12 +3070,20 @@
 	io__write_string("GOTO(ENTRY(MR_do_trace_redo_fail_shallow));\n").
 output_goto(do_trace_redo_fail_deep, _) -->
 	io__write_string("GOTO(ENTRY(MR_do_trace_redo_fail_deep));\n").
-output_goto(do_call_closure, _CallerLabel) -->
-	% see comment in output_call for why we use `noprof_' here
-	io__write_string("noprof_tailcall(ENTRY(mercury__do_call_closure));\n").
-output_goto(do_call_class_method, _CallerLabel) -->
-	% see comment in output_call for why we use `noprof_' here
-	io__write_string("noprof_tailcall(ENTRY(mercury__do_call_class_method));\n").
+output_goto(do_call_closure, CallerLabel) -->
+	% see comment in output_call for why we use `noprof_' etc. here
+	io__write_string("MR_set_prof_ho_caller_proc("),
+	output_label_as_code_addr(CallerLabel),
+	io__write_string(");\n\t\t"),
+	io__write_string(
+		"noprof_tailcall(ENTRY(mercury__do_call_closure));\n").
+output_goto(do_call_class_method, CallerLabel) -->
+	% see comment in output_call for why we use `noprof_' etc. here
+	io__write_string("MR_set_prof_ho_caller_proc("),
+	output_label_as_code_addr(CallerLabel),
+	io__write_string(");\n\t\t"),
+	io__write_string(
+		"noprof_tailcall(ENTRY(mercury__do_call_class_method));\n").
 output_goto(do_det_aditi_call, CallerLabel) -->
 	io__write_string("tailcall(ENTRY(do_det_aditi_call),\n\t\t"),
 	output_label_as_code_addr(CallerLabel),
@@ -3129,12 +3138,18 @@
 	% a `call', we ensure that time spent inside those
 	% routines is credited to the caller, rather than to
 	% do_call_closure or do_call_class_method itself.
+	% But if we do use a noprof_call, we need to set
+	% MR_prof_ho_caller_proc, so that the callee knows
+	% which proc it has been called from.
 	(
 		{ Target = do_call_closure
 		; Target = do_call_class_method
 		}
 	->
 		{ ProfileCall = no },
+		io__write_string("MR_set_prof_ho_caller_proc("),
+		output_label_as_code_addr(CallerLabel),
+		io__write_string(");\n\t"),
 		io__write_string("noprof_")
 	;
 		{ ProfileCall = yes }
Index: runtime/mercury_calls.h
===================================================================
RCS file: /home/mercury1/repository/mercury/runtime/mercury_calls.h,v
retrieving revision 1.7
diff -u -d -r1.7 mercury_calls.h
--- runtime/mercury_calls.h	2000/09/11 08:49:43	1.7
+++ runtime/mercury_calls.h	2000/09/12 20:08:43
@@ -18,7 +18,6 @@
 		do {						\
 			debugcall(LABEL(label), (succ_cont));	\
 			MR_succip = (succ_cont);			\
-			set_prof_current_proc(LABEL(label));	\
 			GOTO_LABEL(label);			\
 		} while (0)
 
@@ -46,7 +45,6 @@
 			__label__ fixup_gp;			\
 			debugcall((proc), (succ_cont));		\
 			MR_succip = (&&fixup_gp);		\
-			set_prof_current_proc(proc);		\
 			GOTO(proc);				\
 		fixup_gp:					\
 			ASM_FIXUP_REGS				\
@@ -58,7 +56,6 @@
 			__label__ fixup_gp;			\
 			debugcall((proc), (succ_cont));		\
 			MR_succip = (&&fixup_gp);		\
-			set_prof_current_proc(proc);		\
 			GOTO(proc);				\
 		fixup_gp:					\
 			ASM_FIXUP_REGS				\
@@ -69,7 +66,6 @@
 		do {						\
 			debugcall((proc), (succ_cont));		\
 			MR_succip = (succ_cont);		\
-			set_prof_current_proc(proc);		\
 			GOTO(proc);				\
 		} while (0)
   #define noprof_call_localret(proc, succ_cont) 		\
@@ -88,12 +84,14 @@
 #define	call(proc, succ_cont, current_label)			\
 		do {						\
 			PROFILE((proc), (current_label));	\
+			set_prof_current_proc(proc);		\
 			noprof_call((proc), (succ_cont));	\
 		} while (0)
 
 #define	call_localret(proc, succ_cont, current_label)		\
 		do {						\
 			PROFILE((proc), (current_label));	\
+			set_prof_current_proc(proc);		\
 			noprof_call_localret(proc, succ_cont);	\
 		} while (0)
 
Index: runtime/mercury_ho_call.c
===================================================================
RCS file: /home/mercury1/repository/mercury/runtime/mercury_ho_call.c,v
retrieving revision 1.36
diff -u -d -r1.36 mercury_ho_call.c
--- runtime/mercury_ho_call.c	2000/09/11 08:49:43	1.36
+++ runtime/mercury_ho_call.c	2000/09/12 20:20:51
@@ -126,16 +126,11 @@
 	restore_registers();
 
 	/*
-	** Note that we pass MR_prof_current_proc rather than
+	** Note that we pass MR_prof_ho_caller_proc rather than
 	** LABEL(do_call_closure), so that the call gets recorded
 	** as having come from our caller.
-	** XXX This won't do the right thing if PROFILE_CALLS is
-	** defined but PROFILE_TIME isn't, since MR_prof_current_proc
-	** will be NULL in that case.  But that combination of
-	** configuration parameters isn't really supported.
 	*/
-	tailcall(closure->MR_closure_code,
-		MR_prof_current_proc);
+	tailcall(closure->MR_closure_code, MR_prof_ho_caller_proc);
 }
 
 	/*
@@ -189,15 +184,11 @@
 	restore_registers();
 
 	/*
-	** Note that we pass MR_prof_current_proc rather than
+	** Note that we pass MR_prof_ho_caller_proc rather than
 	** LABEL(do_call_class_method), so that the call gets recorded
 	** as having come from our caller.
-	** XXX This won't do the right thing if PROFILE_CALLS is
-	** defined but PROFILE_TIME isn't, since MR_prof_current_proc
-	** will be NULL in that case.  But that combination of
-	** configuration parameters isn't really supported.
 	*/
-	tailcall(destination, MR_prof_current_proc);
+	tailcall(destination, MR_prof_ho_caller_proc);
 }
 
 /*
Index: runtime/mercury_prof.c
===================================================================
RCS file: /home/mercury1/repository/mercury/runtime/mercury_prof.c,v
retrieving revision 1.12
diff -u -d -r1.12 mercury_prof.c
--- runtime/mercury_prof.c	2000/08/10 10:44:21	1.12
+++ runtime/mercury_prof.c	2000/09/12 20:29:15
@@ -93,6 +93,11 @@
 
 MR_Code *		volatile	MR_prof_current_proc;
 
+#ifdef PROFILE_CALLS
+  MR_Code *		MR_prof_ho_caller_proc;
+#endif
+
+
 /* 
 ** Private global variables
 */
Index: runtime/mercury_prof.h
===================================================================
RCS file: /home/mercury1/repository/mercury/runtime/mercury_prof.h,v
retrieving revision 1.9
diff -u -d -r1.9 mercury_prof.h
--- runtime/mercury_prof.h	2000/08/10 10:44:22	1.9
+++ runtime/mercury_prof.h	2000/09/12 20:19:28
@@ -26,7 +26,7 @@
 
 /*
 ** The following two macros are used to ensure that the profiler can
-** use `prof_current_proc' to determine what procedure is currently
+** use `MR_prof_current_proc' to determine what procedure is currently
 ** being executed when a profiling interrupt occurs.
 */
 
@@ -39,6 +39,21 @@
 #else
   #define set_prof_current_proc(target)		((void)0)
   #define update_prof_current_proc(target)	((void)0)
+#endif
+
+
+/*
+** This variable holds the address of the calling procedure
+** for a call to do_call_closure or do_call_class_method.
+*/
+#ifdef PROFILE_CALLS
+  extern MR_Code *	MR_prof_ho_caller_proc;
+#endif
+#ifdef PROFILE_CALLS
+  #define MR_set_prof_ho_caller_proc(target) \
+  		(MR_prof_ho_caller_proc = (target))
+#else
+  #define MR_set_prof_ho_caller_proc(target)	((void)0)
 #endif
 
 /*
Index: runtime/mercury_wrapper.c
===================================================================
RCS file: /home/mercury1/repository/mercury/runtime/mercury_wrapper.c,v
retrieving revision 1.70
diff -u -d -r1.70 mercury_wrapper.c
--- runtime/mercury_wrapper.c	2000/08/26 04:34:01	1.70
+++ runtime/mercury_wrapper.c	2000/09/12 19:48:16
@@ -1242,6 +1242,7 @@
 	}
 
 #ifdef  PROFILE_TIME
+	set_prof_current_proc(program_entry_point);
 	if (MR_profiling) MR_prof_turn_on_time_profiling();
 #endif
 
-- 
Fergus Henderson <fjh at cs.mu.oz.au>  |  "I have always known that the pursuit
WWW: <http://www.cs.mu.oz.au/~fjh>  |  of excellence is a lethal habit"
PGP: finger fjh at 128.250.37.3        |     -- the last words of T. S. Garp.
--------------------------------------------------------------------------
mercury-developers mailing list
Post messages to:       mercury-developers at cs.mu.oz.au
Administrative Queries: owner-mercury-developers at cs.mu.oz.au
Subscriptions:          mercury-developers-request at cs.mu.oz.au
--------------------------------------------------------------------------