[m-rev.] for review: report real times in benchmarking.report_stats

Peter Wang wangp at students.cs.mu.oz.au
Mon Aug 7 15:45:01 AEST 2006


Estimated hours taken: 1
Branches: main

Let benchmark.report_stats/0 report real times on POSIX platforms.

configure.in:
	Check for time.h and gettimeofday().

runtime/mercury_conf.h.in:
	Add MR_HAVE_TIME_H, MR_HAVE_GETTIMEOFDAY.

	Unrelated change: add MR_HAVE_PTHREAD_H.

runtime/mercury_timing.c:
runtime/mercury_timing.h:
	Add `MR_get_real_milliseconds'.

runtime/mercury_wrapper.c:
runtime/mercury_wrapper.h:
	Rename MR_time_* globals to MR_user_time_*.

	Add and initialise MR_real_time_* globals.

library/benchmarking.m:
	Output real times in ML_report_stats().

	Correct spelling of milliseconds.

java/runtime/Native.c:
java/runtime/Native.java.in:
trace/mercury_trace_declarative.c:
	Correct spelling of milliseconds.


Index: configure.in
===================================================================
RCS file: /home/mercury1/repository/mercury/configure.in,v
retrieving revision 1.460
diff -u -r1.460 configure.in
--- configure.in	4 Aug 2006 04:30:35 -0000	1.460
+++ configure.in	7 Aug 2006 04:57:47 -0000
@@ -920,7 +920,8 @@
 		open close dup dup2 fdopen fileno fstat stat lstat isatty \
 		getpid setpgid fork execlp wait kill \
 		grantpt unlockpt ptsname tcgetattr tcsetattr ioctl \
-		access sleep opendir readdir closedir mkdir symlink readlink
+		access sleep opendir readdir closedir mkdir symlink readlink \
+		gettimeofday
 
 #-----------------------------------------------------------------------------#
 MERCURY_CHECK_FOR_HEADERS( \
@@ -928,7 +929,7 @@
 		asm/sigcontext.h sys/param.h sys/time.h sys/times.h \
 		sys/types.h sys/stat.h fcntl.h termios.h sys/ioctl.h \
 		sys/stropts.h windows.h dirent.h getopt.h malloc.h \
-		semaphore.h pthread.h)
+		semaphore.h pthread.h time.h)
 
 if test "$MR_HAVE_GETOPT_H" = 1; then
 	GETOPT_H_AVAILABLE=yes
Index: java/runtime/Native.c
===================================================================
RCS file: /home/mercury1/repository/mercury/java/runtime/Native.c,v
retrieving revision 1.2
diff -u -r1.2 Native.c
--- java/runtime/Native.c	12 Feb 2004 02:24:35 -0000	1.2
+++ java/runtime/Native.c	7 Aug 2006 04:57:47 -0000
@@ -42,10 +42,10 @@
 
 /*
  * Class:     Native
- * Method:    get_user_cpu_miliseconds
+ * Method:    get_user_cpu_milliseconds
  * Signature: ()I
  */
-JNIEXPORT jint JNICALL Java_mercury_runtime_Native_get_1user_1cpu_1miliseconds(
+JNIEXPORT jint JNICALL Java_mercury_runtime_Native_get_1user_1cpu_1milliseconds(
 		JNIEnv *, jclass);
 
 #include "mercury_imp.h"
@@ -108,9 +108,9 @@
 }
 
 JNIEXPORT jint JNICALL
-Java_mercury_runtime_Native_get_1user_1cpu_1miliseconds(
+Java_mercury_runtime_Native_get_1user_1cpu_1milliseconds(
 		JNIEnv *env, jclass obj)
 {
-	return MR_get_user_cpu_miliseconds();
+	return MR_get_user_cpu_milliseconds();
 }
 
Index: java/runtime/Native.java.in
===================================================================
RCS file: /home/mercury1/repository/mercury/java/runtime/Native.java.in,v
retrieving revision 1.4
diff -u -r1.4 Native.java.in
--- java/runtime/Native.java.in	12 Feb 2004 02:24:35 -0000	1.4
+++ java/runtime/Native.java.in	7 Aug 2006 04:58:12 -0000
@@ -138,10 +138,10 @@
 	public static native int clk_tck();
 
 	/*
-	** get_user_cpu_miliseconds():
+	** get_user_cpu_milliseconds():
 	**	Native method to return the CPU time consumed by the process,
-	**	in miliseconds, from an arbitrary initial time.
+	**	in milliseconds, from an arbitrary initial time.
 	*/
-	public static native int get_user_cpu_miliseconds();
+	public static native int get_user_cpu_milliseconds();
 }
 
Index: library/benchmarking.m
===================================================================
RCS file: /home/mercury1/repository/mercury/library/benchmarking.m,v
retrieving revision 1.69
diff -u -r1.69 benchmarking.m
--- library/benchmarking.m	19 Apr 2006 05:17:49 -0000	1.69
+++ library/benchmarking.m	7 Aug 2006 04:57:47 -0000
@@ -123,7 +123,7 @@
 #include <stdlib.h>
 #include ""mercury_prof_mem.h""
 #include ""mercury_heap_profile.h""
-#include ""mercury_wrapper.h""      /* for MR_time_at_last_stat */
+#include ""mercury_wrapper.h""      /* for MR_user_time_at_last_stat */
 
 #ifdef MR_MPROF_PROFILE_MEMORY
 
@@ -178,7 +178,8 @@
 void
 ML_report_stats(void)
 {
-    int                 time_at_prev_stat;
+    int                 user_time_at_prev_stat;
+    int                 real_time_at_prev_stat;
 #if !defined(MR_HIGHLEVEL_CODE) || !defined(MR_CONSERVATIVE_GC)
     MercuryEngine       *eng;
 #endif
@@ -191,16 +192,24 @@
     ** Print timing and stack usage information
     */
 
-    time_at_prev_stat = MR_time_at_last_stat;
-    MR_time_at_last_stat = MR_get_user_cpu_miliseconds();
+    user_time_at_prev_stat = MR_user_time_at_last_stat;
+    MR_user_time_at_last_stat = MR_get_user_cpu_milliseconds();
+
+    real_time_at_prev_stat = MR_real_time_at_last_stat;
+    MR_real_time_at_last_stat = MR_get_real_milliseconds();
 
 #if !defined(MR_HIGHLEVEL_CODE) || !defined(MR_CONSERVATIVE_GC)
     eng = MR_get_engine();
 #endif
 
-    fprintf(stderr, ""[Time: +%.3fs, %.3fs,"",
-        (MR_time_at_last_stat - time_at_prev_stat) / 1000.0,
-        (MR_time_at_last_stat - MR_time_at_start) / 1000.0
+    fprintf(stderr, ""[User time: +%.3fs, %.3fs,"",
+        (MR_user_time_at_last_stat - user_time_at_prev_stat) / 1000.0,
+        (MR_user_time_at_last_stat - MR_user_time_at_start) / 1000.0
+    );
+
+    fprintf(stderr, "" Real time: +%.3fs, %.3fs,"",
+        (MR_real_time_at_last_stat - real_time_at_prev_stat) / 1000.0,
+        (MR_real_time_at_last_stat - MR_real_time_at_start) / 1000.0
     );
 
 #ifndef MR_HIGHLEVEL_CODE
@@ -602,7 +611,7 @@
 
 static {
     if (mercury.runtime.Native.isAvailable()) {
-        time_at_start = mercury.runtime.Native.get_user_cpu_miliseconds();
+        time_at_start = mercury.runtime.Native.get_user_cpu_milliseconds();
         time_at_last_stat = time_at_start;
     }
 }
@@ -610,7 +619,7 @@
 private static void
 ML_report_stats() {
     int time_at_prev_stat = time_at_last_stat;
-    time_at_last_stat = get_user_cpu_miliseconds_1_p_0();
+    time_at_last_stat = get_user_cpu_milliseconds_1_p_0();
 
     System.err.print(""[Time: "" +
         ((time_at_last_stat - time_at_prev_stat) / 1000.0) +
@@ -644,9 +653,9 @@
 
 :- pragma promise_pure(benchmark_det/5).
 benchmark_det(Pred, In, Out, Repeats, Time) :-
-    impure get_user_cpu_miliseconds(StartTime),
+    impure get_user_cpu_milliseconds(StartTime),
     impure benchmark_det_loop(Pred, In, Out, Repeats),
-    impure get_user_cpu_miliseconds(EndTime),
+    impure get_user_cpu_milliseconds(EndTime),
     Time0 = EndTime - StartTime,
     cc_multi_equal(Time0, Time).
 
@@ -668,9 +677,9 @@
 :- pragma promise_pure(benchmark_func/5).
 
 benchmark_func(Func, In, Out, Repeats, Time) :-
-    impure get_user_cpu_miliseconds(StartTime),
+    impure get_user_cpu_milliseconds(StartTime),
     impure benchmark_func_loop(Func, In, Out, Repeats),
-    impure get_user_cpu_miliseconds(EndTime),
+    impure get_user_cpu_milliseconds(EndTime),
     Time0 = EndTime - StartTime,
     cc_multi_equal(Time0, Time).
 
@@ -691,9 +700,9 @@
 :- pragma promise_pure(benchmark_det_io/7).
 
 benchmark_det_io(Pred, InA, OutA, InB, OutB, Repeats, Time) :-
-    impure get_user_cpu_miliseconds(StartTime),
+    impure get_user_cpu_milliseconds(StartTime),
     impure benchmark_det_loop_io(Pred, InA, OutA, InB, OutB, Repeats),
-    impure get_user_cpu_miliseconds(EndTime),
+    impure get_user_cpu_milliseconds(EndTime),
     Time = EndTime - StartTime.
     % XXX cc_multi_equal(Time0, Time).
 
@@ -717,9 +726,9 @@
 :- pragma promise_pure(benchmark_nondet/5).
 
 benchmark_nondet(Pred, In, Count, Repeats, Time) :-
-    impure get_user_cpu_miliseconds(StartTime),
+    impure get_user_cpu_milliseconds(StartTime),
     impure benchmark_nondet_loop(Pred, In, Count, Repeats),
-    impure get_user_cpu_miliseconds(EndTime),
+    impure get_user_cpu_milliseconds(EndTime),
     Time0 = EndTime - StartTime,
     cc_multi_equal(Time0, Time).
 
@@ -746,19 +755,19 @@
     N > 0,
     ( true ; impure repeat(N - 1) ).
 
-:- impure pred get_user_cpu_miliseconds(int::out) is det.
+:- impure pred get_user_cpu_milliseconds(int::out) is det.
 
 :- pragma foreign_proc("C",
-    get_user_cpu_miliseconds(Time::out),
+    get_user_cpu_milliseconds(Time::out),
     [will_not_call_mercury],
 "
-    Time = MR_get_user_cpu_miliseconds();
+    Time = MR_get_user_cpu_milliseconds();
 ").
 
 % XXX Can't seem to get this to work -- perhaps Diagnostics isn't yet
 % available in Beta 1 of the .NET framework.
 % :- pragma foreign_proc("MC++",
-%     get_user_cpu_miliseconds(_Time::out),
+%     get_user_cpu_milliseconds(_Time::out),
 %     [will_not_call_mercury],
 % "
 %     // This won't return the elapsed time since program start,
@@ -768,14 +777,14 @@
 % ").
 
 :- pragma foreign_proc("Java",
-    get_user_cpu_miliseconds(Time::out),
+    get_user_cpu_milliseconds(Time::out),
     [will_not_call_mercury],
 "
     if (mercury.runtime.Native.isAvailable()) {
-        Time = mercury.runtime.Native.get_user_cpu_miliseconds();
+        Time = mercury.runtime.Native.get_user_cpu_milliseconds();
     } else {
         throw new java.lang.RuntimeException(
-            ""get_user_cpu_miliseconds is not implemented in pure Java."" +
+            ""get_user_cpu_milliseconds is not implemented in pure Java."" +
             ""Native dynamic link library is required."");
     }
 ").
Index: runtime/mercury_conf.h.in
===================================================================
RCS file: /home/mercury1/repository/mercury/runtime/mercury_conf.h.in,v
retrieving revision 1.55
diff -u -r1.55 mercury_conf.h.in
--- runtime/mercury_conf.h.in	4 Jul 2006 04:46:38 -0000	1.55
+++ runtime/mercury_conf.h.in	7 Aug 2006 04:57:47 -0000
@@ -153,6 +153,8 @@
 #undef	MR_HAVE_DIRENT_H
 #undef	MR_HAVE_MALLOC_H
 #undef	MR_HAVE_SEMAPHORE_H
+#undef	MR_HAVE_PTHREAD_H
+#undef	MR_HAVE_TIME_H
 
 /*
 ** MR_HAVE_POSIX_TIMES is defined if we have the POSIX
@@ -240,6 +242,7 @@
 **	MR_HAVE_MKDIR		we have the mkdir function.
 **	MR_HAVE_SYMLINK		we have the symlink function.
 **	MR_HAVE_READLINK	we have the readlink function.
+**	MR_HAVE_GETTIMEOFDAY	we have the gettimeofday function.
 */
 #undef	MR_HAVE_GETPID
 #undef	MR_HAVE_SETPGID
@@ -295,6 +298,7 @@
 #undef	MR_HAVE_MKDIR
 #undef	MR_HAVE_SYMLINK
 #undef	MR_HAVE_READLINK
+#undef	MR_HAVE_GETTIMEOFDAY
 
 /*
 ** We use mprotect() and signals to catch stack and heap overflows.
Index: runtime/mercury_timing.c
===================================================================
RCS file: /home/mercury1/repository/mercury/runtime/mercury_timing.c,v
retrieving revision 1.9
diff -u -r1.9 mercury_timing.c
--- runtime/mercury_timing.c	4 May 2005 07:42:17 -0000	1.9
+++ runtime/mercury_timing.c	7 Aug 2006 04:57:47 -0000
@@ -17,6 +17,14 @@
   #include <sys/times.h>		/* for times() and `struct tms' */
 #endif
 
+#ifdef MR_HAVE_SYS_TIME_H
+  #include <sys/time.h>
+#endif
+
+#ifdef MR_HAVE_TIME_H
+  #include <time.h>
+#endif
+
 #ifdef MR_WIN32_GETPROCESSTIMES
   #include <windows.h>
 #endif
@@ -24,7 +32,7 @@
 #include "mercury_timing.h"
 
 int
-MR_get_user_cpu_miliseconds(void)
+MR_get_user_cpu_milliseconds(void)
 {
 #if defined(MR_WIN32_GETPROCESSTIMES)
 	#define FILETIME_TO_MILLISEC(time, msec)			\
@@ -50,13 +58,13 @@
 	return user_msec + kernel_msec;
 #elif defined(MR_HAVE_SYS_TIMES_H)
   #ifdef MR_CLOCK_TICKS_PER_SECOND
-	const double ticks_per_milisecond = MR_CLOCK_TICKS_PER_SECOND / 1000.0;
+	const double ticks_per_millisecond = MR_CLOCK_TICKS_PER_SECOND / 1000.0;
 	struct tms t;
 
 	if (times(&t) == -1) {
 		return -1;
 	}
-	return (int) (t.tms_utime / ticks_per_milisecond);
+	return (int) (t.tms_utime / ticks_per_millisecond);
   #else
 	return -1;
   #endif
@@ -64,3 +72,18 @@
 	return -1;
 #endif
 }
+
+int
+MR_get_real_milliseconds(void)
+{
+#if defined(MR_HAVE_GETTIMEOFDAY)
+	struct timeval tv;
+
+	if (gettimeofday(&tv, NULL) == -1) {
+		return -1;
+	}
+	return (tv.tv_sec * 1000) + (tv.tv_usec / 1000);
+#else
+	return -1;
+#endif
+}
Index: runtime/mercury_timing.h
===================================================================
RCS file: /home/mercury1/repository/mercury/runtime/mercury_timing.h,v
retrieving revision 1.4
diff -u -r1.4 mercury_timing.h
--- runtime/mercury_timing.h	13 Feb 2002 09:56:42 -0000	1.4
+++ runtime/mercury_timing.h	7 Aug 2006 04:57:47 -0000
@@ -7,7 +7,7 @@
 /*
 ** mercury_timing.h - interface to timing routines.
 **	Defines `MR_CLOCK_TICKS_PER_SECOND'
-**	and `MR_get_user_cpu_miliseconds()'.
+**	and `MR_get_user_cpu_milliseconds()'.
 */
 
 #ifndef MERCURY_TIMING_H
@@ -42,9 +42,15 @@
 #endif
 
 /*
-** MR_get_user_cpu_miliseconds() returns the CPU time consumed by the
-** process, in miliseconds, from an arbitrary initial time.
+** MR_get_user_cpu_milliseconds() returns the CPU time consumed by the
+** process, in milliseconds, from an arbitrary initial time.
 */
-int MR_get_user_cpu_miliseconds(void);
+int MR_get_user_cpu_milliseconds(void);
+
+/*
+** MR_get_real_milliseconds() returns the real time
+** in milliseconds, from an arbitrary initial time.
+*/
+int MR_get_real_milliseconds(void);
 
 #endif /* MERCURY_TIMING_H */
Index: runtime/mercury_wrapper.c
===================================================================
RCS file: /home/mercury1/repository/mercury/runtime/mercury_wrapper.c,v
retrieving revision 1.162
diff -u -r1.162 mercury_wrapper.c
--- runtime/mercury_wrapper.c	5 Jul 2006 03:00:44 -0000	1.162
+++ runtime/mercury_wrapper.c	7 Aug 2006 04:57:47 -0000
@@ -261,9 +261,12 @@
 static  MR_bool     MR_print_table_statistics = MR_FALSE;
 
 /* timing */
-int                 MR_time_at_last_stat;
-int                 MR_time_at_start;
-static  int         MR_time_at_finish;
+int                 MR_user_time_at_last_stat;
+int                 MR_user_time_at_start;
+static  int         MR_user_time_at_finish;
+
+int                 MR_real_time_at_last_stat;
+int                 MR_real_time_at_start;
 
 /* time profiling */
 enum MR_TimeProfileMethod
@@ -1845,8 +1848,11 @@
         MR_CONTEXT(MR_ctxt_nondetstack_zone)->MR_zone_min;
 #endif
 
-    MR_time_at_start = MR_get_user_cpu_miliseconds();
-    MR_time_at_last_stat = MR_time_at_start;
+    MR_user_time_at_start = MR_get_user_cpu_milliseconds();
+    MR_user_time_at_last_stat = MR_user_time_at_start;
+
+    MR_real_time_at_start = MR_get_real_milliseconds();
+    MR_real_time_at_last_stat = MR_real_time_at_start;
 
     for (repcounter = 0; repcounter < repeats; repcounter++) {
 #ifdef  MR_DEEP_PROFILING
@@ -1870,7 +1876,7 @@
     }
 
     if (use_own_timer) {
-        MR_time_at_finish = MR_get_user_cpu_miliseconds();
+        MR_user_time_at_finish = MR_get_user_cpu_milliseconds();
     }
 
 #if defined(MR_USE_GCC_NONLOCAL_GOTOS) && defined(MR_LOWLEVEL_DEBUG)
@@ -1925,9 +1931,9 @@
     }
 #endif
 
-        if (use_own_timer) {
+    if (use_own_timer) {
         printf("%8.3fu ",
-            ((double) (MR_time_at_finish - MR_time_at_start)) / 1000);
+            ((double) (MR_user_time_at_finish - MR_user_time_at_start)) / 1000);
     }
 
 #ifdef  MR_TYPE_CTOR_STATS
Index: runtime/mercury_wrapper.h
===================================================================
RCS file: /home/mercury1/repository/mercury/runtime/mercury_wrapper.h,v
retrieving revision 1.73
diff -u -r1.73 mercury_wrapper.h
--- runtime/mercury_wrapper.h	24 Feb 2006 07:11:20 -0000	1.73
+++ runtime/mercury_wrapper.h	7 Aug 2006 04:57:47 -0000
@@ -268,8 +268,10 @@
 extern	char		*MR_lld_print_more_min_max;
 
 /* timing */
-extern	int		MR_time_at_start;
-extern	int		MR_time_at_last_stat;
+extern	int		MR_user_time_at_start;
+extern	int		MR_user_time_at_last_stat;
+extern	int		MR_real_time_at_start;
+extern	int		MR_real_time_at_last_stat;
 
 /* time profiling */
 enum MR_TimeProfileMethod {
Index: trace/mercury_trace_declarative.c
===================================================================
RCS file: /home/mercury1/repository/mercury/trace/mercury_trace_declarative.c,v
retrieving revision 1.100
diff -u -r1.100 mercury_trace_declarative.c
--- trace/mercury_trace_declarative.c	13 Jun 2006 09:49:03 -0000	1.100
+++ trace/mercury_trace_declarative.c	7 Aug 2006 04:57:47 -0000
@@ -1759,7 +1759,7 @@
     MR_edt_inside = MR_FALSE;
     MR_edt_building_supertree = create_supertree;
     MR_edt_suspicion_accumulator = 0;
-    MR_edt_start_time = MR_get_user_cpu_miliseconds();
+    MR_edt_start_time = MR_get_user_cpu_milliseconds();
     MR_edt_first_event = event_info->MR_event_number;
 
     /*
@@ -2307,7 +2307,7 @@
     if (event_number != MR_edt_last_event &&
         MR_edt_progress_last_tick == 0 &&
         (MR_edt_start_time + MR_DECL_DISPLAY_PROGRESS_DELAY
-        < MR_get_user_cpu_miliseconds()))
+        < MR_get_user_cpu_milliseconds()))
     {
         fprintf(MR_mdb_out, MR_DECL_PROGRESS_MESSAGE_SUBTREE);
         fflush(MR_mdb_out);
@@ -2343,7 +2343,7 @@
     */
     if (MR_edt_progress_last_tick == 0 &&
         (MR_edt_start_time + MR_DECL_DISPLAY_PROGRESS_DELAY
-        < MR_get_user_cpu_miliseconds()))
+        < MR_get_user_cpu_milliseconds()))
     {
         fprintf(MR_mdb_out, MR_DECL_PROGRESS_MESSAGE_SUPERTREE);
         fflush(MR_mdb_out);
@@ -2351,7 +2351,7 @@
     } else if ((MR_edt_start_time
         + (MR_edt_progress_last_tick + 1)
         * MR_DECL_DISPLAY_PROGRESS_DELAY)
-        < MR_get_user_cpu_miliseconds())
+        < MR_get_user_cpu_milliseconds())
     {
         MR_edt_progress_last_tick++;
         fprintf(MR_mdb_out, MR_DECL_PROGRESS_TICK_STRING);
@@ -2430,7 +2430,7 @@
         MR_edt_stats_total_constructed_nodes);
     fprintf(stderr, "Current event = %i\n", MR_trace_event_number);
     fprintf(stderr, "Total CPU time = %.2f\n",
-        MR_get_user_cpu_miliseconds() / 1000.0);
+        MR_get_user_cpu_milliseconds() / 1000.0);
     pid = getpid();
     sprintf(cmdstr, "ps -p %i -o rss,vsz | tail -1 |"
     	"awk '{print \"RSS = \" $1 \"\\nVSZ = \" $2}' 1>&2", pid);
--------------------------------------------------------------------------
mercury-reviews mailing list
Post messages to:       mercury-reviews at csse.unimelb.edu.au
Administrative Queries: owner-mercury-reviews at csse.unimelb.edu.au
Subscriptions:          mercury-reviews-request at csse.unimelb.edu.au
--------------------------------------------------------------------------



More information about the reviews mailing list