diff: profiling real time

Fergus Henderson fjh at cs.mu.oz.au
Wed Nov 19 10:28:47 AEDT 1997


Estimated hours taken: 4

Add support for using ITIMER_REAL or ITIMER_VIRTUAL rather than ITIMER_PROF.
This is useful on Unix because it lets you profile elapsed (real time)
or just user time rather than user+system time.
It is also essential on Windows because gnu-win32 only supports
ITIMER_REAL (for the other two, setitimer() just returns an error).

runtime/wrapper.h:
runtime/wrapper.mod:
	Add new options for selecting the time profiling method.

runtime/prof.c:
	Use the new option settings to control the argument passed to
	setitimer(), and (since that in turn affects which signal will
	be sent) the argument to signal().

doc/user_guide.texi:
	Document the above changes.

cvs diff  doc/user_guide.texi runtime/prof.c runtime/wrapper.h runtime/wrapper.mod
Index: doc/user_guide.texi
===================================================================
RCS file: /home/staff/zs/imp/mercury/doc/user_guide.texi,v
retrieving revision 1.102
diff -u -r1.102 user_guide.texi
--- user_guide.texi	1997/10/16 04:59:52	1.102
+++ user_guide.texi	1997/11/18 23:10:39
@@ -864,6 +864,7 @@
 @menu
 * Profiling introduction::          What is profiling useful for?
 * Building profiled applications::  How to enable profiling.
+* Time profiling methods::          Choose user, user + system, or real time.
 * Creating the profile::            How to create profile data.
 * Displaying the profile::          How to display the profile data.
 * Analysis of results::             How to interpret the output.
@@ -905,6 +906,33 @@
 with versions of the library and runtime that were compiled with
 profiling enabled.  (It also has the effect for each source file the compiler
 generates the static call graph for that file in @samp{@var{module}.prof}.)
+
+ at node Time profiling methods
+ at section Time profiling methods
+
+By setting the environment variable MERCURY_OPTIONS,
+which is used for passing options to the Mercury runtime system,
+you can control how the Mercury profiler measures the time spent.
+The default (@samp{-Tp}) is to count time spent executing the process,
+including time spent by the system performing operations on behalf of
+the process, but not including time that the process was suspended
+(e.g. due to time slicing, or while waiting for input).
+Using @samp{-Tv} counts only time spent executing the process.
+Using @samp{-Tr} counts all elapsed time, even including time that
+the process was suspended.
+
+ at table @asis
+ at item @samp{-Tr}
+Profile real (elapsed) time (using ITIMER_REAL).
+ at item @samp{-Tv}
+Profile user time (using ITIMER_VIRTUAL).
+ at item @samp{-Tp}
+Profile user time plus system time (using ITIMER_PROF).
+This is the default.
+ at end table
+
+Currently, the @samp{-Tv} and @samp{-Tp} options don't work on Windows,
+so on Windows you must explicitly specify @samp{-Tr}.
 
 @node Creating the profile
 @section Creating the profile
Index: runtime/prof.c
===================================================================
RCS file: /home/staff/zs/imp/mercury/runtime/prof.c,v
retrieving revision 1.32
diff -u -r1.32 prof.c
--- prof.c	1997/07/27 15:08:35	1.32
+++ prof.c	1997/11/18 22:29:23
@@ -32,11 +32,15 @@
 #endif
 
 #if !defined(MR_CLOCK_TICKS_PER_SECOND) \
-	|| !defined(SIGPROF) \
 	|| !defined(HAVE_SETITIMER)
   #error "Time profiling not supported on this system"
 #endif
 
+typedef void (*MR_Sighandler)(int);
+
+static MR_Sighandler	MR_itimer_sig;
+static int		MR_itimer_type;
+
 #endif	/* PROFILE_TIME */
 
 /*
@@ -44,7 +48,7 @@
 */
 #define CALL_TABLE_SIZE 4096
 #define TIME_TABLE_SIZE 4096
-#define MR_CLOCK_TICKS_PER_SIGPROF	5
+#define MR_CLOCK_TICKS_PER_PROF_SIG	5
 
 #define MR_USEC_PER_SEC            	1000000
 
@@ -232,33 +236,35 @@
 
 #ifdef PROFILE_TIME
 
-static void 
-prof_time_profile(int);
+static void prof_init_time_profile_method(void);
+static void prof_time_profile(int);
 
 /*
 **	prof_init_time_profile:
 **		Writes the value of MR_CLOCK_TICKS_PER_SECOND and
-**		MR_CLOCK_TICKS_PER_SIGPROF at the start of the file
+**		MR_CLOCK_TICKS_PER_PROF_SIG at the start of the file
 **		'Prof.Counts'.
 **		Then sets up the profiling timer and starts it up. 
-**		At the moment it is after every MR_CLOCK_TICKS_PER_SIGPROF
+**		At the moment it is after every MR_CLOCK_TICKS_PER_PROF_SIG
 **		ticks of the clock.
 **
-**		SYSTEM SPECIFIC CODE
+**		WARNING: SYSTEM SPECIFIC CODE.  
+**		This code is not very portable, because it uses setitimer(),
+**		which is not part of POSIX.1 or ANSI C.
 */
 
 void
-prof_init_time_profile()
+prof_init_time_profile(void)
 {
 	FILE 	*fptr;
 	struct itimerval itime;
-	const long sigprof_interval_in_usecs = MR_CLOCK_TICKS_PER_SIGPROF *
+	const long prof_sig_interval_in_usecs = MR_CLOCK_TICKS_PER_PROF_SIG *
 		(MR_USEC_PER_SEC / MR_CLOCK_TICKS_PER_SECOND);
 
 	/* output the value of MR_CLOCK_TICKS_PER_SECOND */
 	fptr = checked_fopen("Prof.Counts", "create", "w");
 	fprintf(fptr, "%d %d\n",
-		MR_CLOCK_TICKS_PER_SECOND, MR_CLOCK_TICKS_PER_SIGPROF);
+		MR_CLOCK_TICKS_PER_SECOND, MR_CLOCK_TICKS_PER_PROF_SIG);
 	checked_fclose(fptr, "Prof.Counts");
 
 	checked_atexit(prof_finish);
@@ -266,15 +272,47 @@
 	profiling_on = TRUE;
 
 	itime.it_value.tv_sec = 0;
-	itime.it_value.tv_usec = sigprof_interval_in_usecs;
+	itime.it_value.tv_usec = prof_sig_interval_in_usecs;
 	itime.it_interval.tv_sec = 0;
-	itime.it_interval.tv_usec = sigprof_interval_in_usecs;
+	itime.it_interval.tv_usec = prof_sig_interval_in_usecs;
 
-	checked_signal(SIGPROF, prof_time_profile);
-	checked_setitimer(ITIMER_PROF, &itime);
+	init_time_profile_method();
 
+	checked_signal(MR_itimer_sig, prof_time_profile);
+	checked_setitimer(MR_itimer_type, &itime);
 }
 
+/*
+**	prof_init_time_profile_method:
+**		initializes MR_itimer_type and MR_itimer_sig
+**		based on the setting of MR_time_profile_method.
+*/
+static void
+prof_init_time_profile_method(void)
+{
+	switch (MR_time_profile_method) {
+#if defined(ITIMER_REAL) && defined(SIGALRM)
+		case MR_profile_elapsed_time:
+			MR_itimer_type = ITIMER_REAL;
+			MR_itimer_sig  = SIGALRM;
+			break;
+#endif
+#if defined(ITIMER_VIRTUAL) && defined(SIGVTALRM)
+		case MR_profile_user_time:
+			MR_itimer_type = ITIMER_VIRTUAL;
+			MR_itimer_sig  = SIGVTALRM;
+			break;
+#endif
+#if defined(ITIMER_VIRTUAL) && defined(SIGVTALRM)
+		case MR_profile_user_plus_system_time:
+			MR_itimer_type = ITIMER_PROF;
+			MR_itimer_sig  = SIGPROF;
+			break;
+#endif
+		default:
+			fatal_error("invalid time profile method");
+	}
+}
 #endif /* PROFILE_TIME */
 
 /* ======================================================================== */
@@ -334,9 +372,9 @@
 
 /*
 **	prof_time_profile:
-**		Signal handler to be called when ever a SIGPROF is received.
-**		Saves the current code address into a hash table. If the
-**		address already exists, it increments its count.
+**		Signal handler to be called whenever a profiling signal is
+**		received. Saves the current code address into a hash table.
+**		If the address already exists, it increments its count.
 */
 
 static void
@@ -386,7 +424,7 @@
 */
 
 void
-prof_turn_off_time_profiling()
+prof_turn_off_time_profiling(void)
 {
 	struct itimerval itime;
 
@@ -398,7 +436,7 @@
 	itime.it_interval.tv_sec = 0;
 	itime.it_interval.tv_usec = 0;
 
-	checked_setitimer(ITIMER_PROF, &itime);
+	checked_setitimer(MR_itimer_type, &itime);
 }
 	
 #endif /* PROFILE_TIME */
@@ -477,14 +515,14 @@
 
 /*
 **	prof_output_addr_table:
-**		Outputs the addresses saved whenever SIGPROF is received to
+**		Outputs the addresses saved whenever PROF_SIG is received to
 **		the file "Prof.Counts"
 */
 
 static	void	print_time_node(FILE *fptr, prof_time_node *node);
 
 void
-prof_output_addr_table()
+prof_output_addr_table(void)
 {
 	static	bool	addr_table_written = FALSE;
 	FILE *fptr;
@@ -517,7 +555,7 @@
 
 #endif /* PROFILE_TIME */
 
-void prof_finish()
+void prof_finish(void)
 {
 
 #ifdef PROFILE_TIME
Index: runtime/wrapper.h
===================================================================
RCS file: /home/staff/zs/imp/mercury/runtime/wrapper.h,v
retrieving revision 1.21
diff -u -r1.21 wrapper.h
--- wrapper.h	1997/10/01 13:22:26	1.21
+++ wrapper.h	1997/11/18 23:15:13
@@ -82,7 +82,17 @@
 
 extern	bool		check_space;
 
+/* timing */
 extern	int		time_at_start;
 extern	int		time_at_last_stat;
+
+/* time profiling */
+enum MR_TimeProfileMethod {
+	MR_profile_real_time,			/* i.e. ITIMER_REAL */
+	MR_profile_user_time,			/* i.e. ITIMER_VIRTUAL */
+	MR_profile_user_plus_system_time	/* i.e. ITIMER_PROF */
+};
+extern	enum MR_TimeProfileMethod
+			MR_time_profile_method;
 
 #endif /* not WRAPPER_H */
Index: runtime/wrapper.mod
===================================================================
RCS file: /home/staff/zs/imp/mercury/runtime/wrapper.mod,v
retrieving revision 1.81
diff -u -r1.81 wrapper.mod
--- wrapper.mod	1997/10/01 13:22:27	1.81
+++ wrapper.mod	1997/11/18 23:23:04
@@ -75,6 +75,10 @@
 int		time_at_start;
 static	int	time_at_finish;
 
+/* time profiling */
+enum MR_TimeProfileMethod
+		MR_time_profile_method = MR_profile_user_plus_system_time;
+
 const char *	progname;
 int		mercury_argc;	/* not counting progname */
 char **		mercury_argv;
@@ -564,6 +568,19 @@
 			finaldebug     = FALSE;
 			break;
 
+		case 'T':
+			if (streq(optarg, "r")) {
+				MR_time_profile_method = MR_profile_real_time;
+			} else if (streq(optarg, "v")) {
+				MR_time_profile_method = MR_profile_user_time;
+			} else if (streq(optarg, "p")) {
+				MR_time_profile_method =
+					MR_profile_user_plus_system_time;
+			} else {
+				usage();
+			}
+			break;
+
 		case 'w': {
 			Label *which_label;
 
@@ -641,7 +658,10 @@
 		"-c \t\tcheck cross-function stack usage\n"
 		"-l \t\tprint all labels\n"
 		"-L \t\tcheck for duplicate labels\n"
-		"-t \t\tuse own timer\n"
+		"-t \t\ttime program execution\n"
+		"-Tr \t\tprofile real time (using ITIMER_REAL)\n"
+		"-Tv \t\tprofile user time (using ITIMER_VIRTUAL)\n"
+		"-Tp \t\tprofile user + system time (using ITIMER_PROF)\n"
 		"-x \t\tdisable garbage collection\n"
 		"-dg \t\tdebug gotos\n"
 		"-dc \t\tdebug calls\n"
-- 
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.



More information about the developers mailing list