Changeset 2101 in kBuild

Timestamp:

Nov 24, 2008 11:35:56 PM (16 years ago)

Author:

bird

Message:

kmk: Implemented new switch --print-time. Fixes #65.

Location:

trunk/src/kmk

Files:

• Makefile.am (modified) (1 diff)
• Makefile.kmk (modified) (1 diff)
• function.c (modified) (2 diffs)
• job.c (modified) (5 diffs)
• job.h (modified) (1 diff)
• main.c (modified) (6 diffs)
• make.h (modified) (3 diffs)
• misc.c (modified) (3 diffs)

trunk/src/kmk/Makefile.am

@@ -144 +144 @@
         -DCONFIG_PRETTY_COMMAND_PRINTING \
         -DCONFIG_WITH_PRINT_STATS_SWITCH \
+        -DCONFIG_WITH_PRINT_TIME_SWITCH \
         -DCONFIG_WITH_RDONLY_VARIABLE_VALUE \
         -DCONFIG_WITH_LAZY_DEPS_VARS \

trunk/src/kmk/Makefile.kmk

@@ -170 +170 @@
         CONFIG_PRETTY_COMMAND_PRINTING \
         CONFIG_WITH_PRINT_STATS_SWITCH \
+        CONFIG_WITH_PRINT_TIME_SWITCH \
         CONFIG_WITH_RDONLY_VARIABLE_VALUE \
         CONFIG_WITH_LAZY_DEPS_VARS \

trunk/src/kmk/function.c

@@ -45 +45 @@
 #if defined (CONFIG_WITH_MATH) || defined (CONFIG_WITH_NANOTS) || defined (CONFIG_WITH_FILE_SIZE) /* bird */
 # include <ctype.h>
-# ifdef _MSC_VER
-typedef __int64 math_int;
-# else
-#  include <stdint.h>
-typedef int64_t math_int;
-# endif
+typedef big_int math_int;
 static char *math_int_to_variable_buffer (char *, math_int);
 #endif
@@ -4102 +4097 @@
 func_nanots (char *o, char **argv, const char *funcname)
 {
-  math_int ts;
-
-#if defined (WINDOWS32)
-  static int s_state = -1;
-  static LARGE_INTEGER s_freq;
-
-  if (s_state == -1)
-    s_state = QueryPerformanceFrequency (&s_freq);
-  if (s_state)
-    {
-      LARGE_INTEGER pc;
-      if (!QueryPerformanceCounter (&pc))
-        {
-          s_state = 0;
-          return func_nanots (o, argv, funcname);
-        }
-      ts = (math_int)((long double)pc.QuadPart / (long double)s_freq.QuadPart * 1000000000);
-    }
-  else
-    {
-      /* fall back to low resolution system time. */
-      LARGE_INTEGER bigint;
-      FILETIME ft = {0,0};
-      GetSystemTimeAsFileTime (&ft);
-      bigint.u.LowPart = ft.dwLowDateTime;
-      bigint.u.HighPart = ft.dwLowDateTime;
-      ts = bigint.QuadPart * 100;
-    }
-
-/* FIXME: Linux and others have the realtime clock_* api, detect and use it. */
-
-#elif HAVE_GETTIMEOFDAY
-  struct timeval tv;
-  if (!gettimeofday (&tv, NULL))
-    ts = (math_int)tv.tv_sec * 1000000000
-       + tv.tv_usec * 1000;
-  else
-    {
-      error (NILF, _("$(nanots): gettimeofday failed"));
-      ts = 0;
-    }
-
-#else
-# error "PORTME"
-#endif
-
-  return math_int_to_variable_buffer (o, ts);
+  return math_int_to_variable_buffer (o, nano_timestamp ());
 }
 #endif

trunk/src/kmk/job.c

@@ -209 +209 @@
 static int job_next_command (struct child *);
 static int start_waiting_job (struct child *);
+#ifdef CONFIG_WITH_PRINT_TIME_SWITCH
+static void print_job_time (struct child *);
+#endif
 
 
@@ -901 +904 @@
 free_child (struct child *child)
 {
+#ifdef CONFIG_WITH_PRINT_TIME_SWITCH
+  print_job_time (child);
+#endif
   if (!jobserver_tokens)
     fatal (NILF, "INTERNAL: Freeing child 0x%08lx (%s) but no tokens left!\n",
@@ -1064 +1070 @@
   if (!child->command_ptr)
     goto next_command;
+
+#ifdef CONFIG_WITH_PRINT_TIME_SWITCH
+  if (child->start_ts == -1)
+    child->start_ts = nano_timestamp ();
+#endif
 
   /* Combine the flags parsed for the line itself with
@@ -1821 +1832 @@
   c->command_lines = lines;
   c->sh_batch_file = NULL;
+#ifdef CONFIG_WITH_PRINT_TIME_SWITCH
+  c->start_ts = -1;
+#endif
 
   /* Cache dontcare flag because file->dontcare can be changed once we
@@ -3422 +3436 @@
 #endif /* !HAPE_DUP2 && !_AMIGA */
 
+#ifdef CONFIG_WITH_PRINT_TIME_SWITCH
+/* Prints the time elapsed while executing the commands for the given job. */
+void print_job_time (struct child *c)
+{
+  if (   !handling_fatal_signal
+      && print_time_min != -1
+      && c->start_ts != -1)
+    {
+      big_int elapsed = nano_timestamp () - c->start_ts;
+      if (elapsed >= print_time_min * BIG_INT_C(1000000000))
+        {
+          char buf[64];
+          int len = format_elapsed_nano (buf, sizeof (buf), elapsed);
+          if (len > print_time_width)
+            print_time_width = len;
+          message (1, _("%*s - %s"), print_time_width, buf, c ->file->name);
+        }
+    }
+}
+#endif
+
 /* On VMS systems, include special VMS functions.  */
 

trunk/src/kmk/job.h

@@ -67 +67 @@
     unsigned int deleted:1;     /* Nonzero if targets have been deleted.  */
     unsigned int dontcare:1;    /* Saved dontcare flag.  */
+#ifdef CONFIG_WITH_PRINT_TIME_SWITCH
+    big_int start_ts;           /* nano_timestamp of the first command.  */
+#endif
   };
 

trunk/src/kmk/main.c

@@ -183 +183 @@
 
 int print_stats_flag;
+#endif
+
+#ifdef CONFIG_WITH_PRINT_TIME_SWITCH
+/* Minimum number of seconds to report, -1 if disabled. */
+
+int print_time_min = -1;
+static int default_print_time_min = -1;
+static int no_val_print_time_min = 0;
+static big_int make_start_ts = -1;
+int print_time_width = 5;
 #endif
 
@@ -491 +501 @@
        "print-stats" },
 #endif
+#ifdef CONFIG_WITH_PRINT_TIME_SWITCH
+    { CHAR_MAX+12, positive_int, (char *) &print_time_min, 1, 1, 0,
+      (char *) &no_val_print_time_min, (char *) &default_print_time_min,
+      "print-time" },
+#endif
 #ifdef KMK
-    { CHAR_MAX+12, positive_int, (char *) &process_priority, 1, 1, 0,
+    { CHAR_MAX+14, positive_int, (char *) &process_priority, 1, 1, 0,
       (char *) &process_priority, (char *) &process_priority, "priority" },
-    { CHAR_MAX+14, positive_int, (char *) &process_affinity, 1, 1, 0,
+    { CHAR_MAX+15, positive_int, (char *) &process_affinity, 1, 1, 0,
       (char *) &process_affinity, (char *) &process_affinity, "affinity" },
 #endif
@@ -505 +520 @@
       "no-keep-going" },
 #if defined (CONFIG_WITH_MAKE_STATS) || defined (CONFIG_WITH_MINIMAL_STATS)
-    { CHAR_MAX+15, flag, (char *) &make_expensive_statistics, 1, 1, 1, 0, 0,
+    { CHAR_MAX+16, flag, (char *) &make_expensive_statistics, 1, 1, 1, 0, 0,
        "statistics" },
 #endif
@@ -1313 +1328 @@
   SetUnhandledExceptionFilter(handle_runtime_exceptions);
 #endif /* !ELECTRIC_HEAP */
+
+#ifdef CONFIG_WITH_PRINT_TIME_SWITCH
+  make_start_ts = nano_timestamp ();
+#endif
 
   /* start off assuming we have no shell */
@@ -3566 +3585 @@
                      make_expensive_statistics ? "1" : "0", o_default, 1);
 # endif
+#ifdef CONFIG_WITH_PRINT_TIME_SWITCH
+    sprintf (val, "%u", print_time_min);
+    define_variable ("KMK_OPTS_PRINT_TIME", sizeof("KMK_OPTS_PRINT_TIME") - 1,
+                     val, o_default, 1);
+#endif
   }
 #endif
@@ -3811 +3835 @@
       if (directory_before_chdir != 0)
         chdir (directory_before_chdir);
+
+#ifdef CONFIG_WITH_PRINT_TIME_SWITCH
+      if (print_time_min != -1)
+        {
+          big_int elapsed = nano_timestamp () - make_start_ts;
+          if (elapsed >= print_time_min * BIG_INT_C(1000000000))
+            {
+              char buf[64];
+              format_elapsed_nano (buf, sizeof (buf), elapsed);
+              message (1, _("%*s"), print_time_width, buf);
+            }
+        }
+#endif
 
       log_working_directory (0);

trunk/src/kmk/make.h

@@ -442 +442 @@
 
 #define STRING_SIZE_TUPLE(_s) (_s), (sizeof (_s)-1)
+
+#if defined (CONFIG_WITH_MATH) \
+ || defined (CONFIG_WITH_NANOTS) \
+ || defined (CONFIG_WITH_FILE_SIZE) \
+ || defined (CONFIG_WITH_PRINT_TIME_SWITCH) /* bird */
+# ifdef _MSC_VER
+typedef __int64 big_int;
+#  define BIG_INT_C(c)      (c ## LL)
+typedef unsigned __int64 big_uint;
+#  define BIG_UINT_C(c)     (c ## ULL)
+# else
+#  include <stdint.h>
+typedef int64_t big_int;
+#  define BIG_INT_C(c)      INT64_C(c)
+typedef uint64_t big_uint;
+#  define BIG_UINT_C(c)     UINT64_C(c)
+# endif
+#endif
 
 
@@ -691 +709 @@
 #ifdef CONFIG_PRETTY_COMMAND_PRINTING
 extern int pretty_command_printing;
+#endif
+#ifdef CONFIG_WITH_PRINT_TIME_SWITCH
+extern int print_time_min, print_time_width;
 #endif
 #if defined (CONFIG_WITH_MAKE_STATS) || defined (CONFIG_WITH_MINIMAL_STATS)
@@ -896 +917 @@
 extern char *func_breakpoint(char *o, char **argv, const char *funcname);
 #endif
+
+#if defined (CONFIG_WITH_NANOTS) || defined (CONFIG_WITH_PRINT_TIME_SWITCH)
+/* misc.c */
+extern big_int nano_timestamp (void);
+extern int format_elapsed_nano (char *buf, size_t size, big_int ts);
+#endif
+

trunk/src/kmk/misc.c

@@ -29 +29 @@
 # if defined(__GLIBC__) || defined(HAVE_MALLINFO)
 #  include <malloc.h>
+# endif
+#endif
+
+#if defined (CONFIG_WITH_NANOTS) || defined (CONFIG_WITH_PRINT_TIME_SWITCH)
+# ifdef WINDOWS32
+#  include <Windows.h>
 # endif
 #endif
@@ -1164 +1170 @@
 #ifdef CONFIG_WITH_PRINT_STATS_SWITCH
 /* Print heap statistics if supported by the platform. */
-void print_heap_stats (void)
+void
+print_heap_stats (void)
 {
   /* Darwin / Mac OS X */
@@ -1251 +1258 @@
 #endif /* CONFIG_WITH_PRINT_STATS_SWITCH */
 
+#ifdef CONFIG_WITH_PRINT_TIME_SWITCH
+/* Get a nanosecond timestamp, from a monotonic time source if
+   possible.  Returns -1 after calling error() on failure.  */
+
+big_int
+nano_timestamp (void)
+{
+  big_int ts;
+#if defined (WINDOWS32)
+  static int s_state = -1;
+  static LARGE_INTEGER s_freq;
+
+  if (s_state == -1)
+    s_state = QueryPerformanceFrequency (&s_freq);
+  if (s_state)
+    {
+      LARGE_INTEGER pc;
+      if (!QueryPerformanceCounter (&pc))
+        {
+          s_state = 0;
+          return nano_timestamp ();
+        }
+      ts = (big_int)((long double)pc.QuadPart / (long double)s_freq.QuadPart * 1000000000);
+    }
+  else
+    {
+      /* fall back to low resolution system time. */
+      LARGE_INTEGER bigint;
+      FILETIME ft = {0,0};
+      GetSystemTimeAsFileTime (&ft);
+      bigint.u.LowPart = ft.dwLowDateTime;
+      bigint.u.HighPart = ft.dwLowDateTime;
+      ts = bigint.QuadPart * 100;
+    }
+
+#elif HAVE_GETTIMEOFDAY
+/* FIXME: Linux and others have the realtime clock_* api, detect and use it. */
+  struct timeval tv;
+  if (!gettimeofday (&tv, NULL))
+    ts = (big_int)tv.tv_sec * 1000000000
+       + tv.tv_usec * 1000;
+  else
+    {
+      error (NILF, _("gettimeofday failed"));
+      ts = -1;
+    }
+
+#else
+# error "PORTME"
+#endif
+
+  return ts;
+}
+
+/* Formats the elapsed time (nano seconds) in the manner easiest
+   to read, with millisecond percision for larger numbers.  */
+
+int
+format_elapsed_nano (char *buf, size_t size, big_int ts)
+{
+  int sz;
+  if (ts < 1000)
+    sz = sprintf (buf, "%uns", (unsigned)ts);
+  else if (ts < 100000)
+    sz = sprintf (buf, "%u.%03uus",
+                  (unsigned)(ts / 1000),
+                  (unsigned)(ts % 1000));
+  else
+    {
+      ts /= 1000;
+      if (ts < 1000)
+        sz = sprintf (buf, "%uus", (unsigned)ts);
+      else if (ts < 100000)
+        sz = sprintf (buf, "%u.%03ums",
+                      (unsigned)(ts / 1000),
+                      (unsigned)(ts % 1000));
+      else
+        {
+          ts /= 1000;
+          if (ts < BIG_INT_C(60000))
+            sz = sprintf (buf,
+                          "%u.%03us",
+                          (unsigned)(ts / 1000),
+                          (unsigned)(ts % 1000));
+          else
+            sz = sprintf (buf,
+                          "%um%u.%03us",
+                          (unsigned)( ts / BIG_INT_C(60000)),
+                          (unsigned)((ts % BIG_INT_C(60000)) / 1000),
+                          (unsigned)((ts % BIG_INT_C(60000)) % 1000));
+        }
+    }
+  if (sz >= size)
+    fatal (NILF, _("format_elapsed_nano buffer overflow: %d written, %d buffer"),
+           sz, size);
+  return sz;
+}
+#endif /* CONFIG_WITH_PRINT_TIME_SWITCH */