Changeset 3170 in kBuild

Timestamp:

Mar 21, 2018 12:32:27 PM (7 years ago)

Author:

bird

Message:

kmkbuiltin: stats

Location:

trunk/src/kmk

Files:

• Makefile.kmk (modified) (2 diffs)
• kmkbuiltin.c (modified) (8 diffs)
• kmkbuiltin.h (modified) (1 diff)
• main.c (modified) (4 diffs)
• makeint.h (modified) (1 diff)
• misc.c (modified) (2 diffs)

trunk/src/kmk/Makefile.kmk

@@ -225 +225 @@
  kmk_DEFS += CONFIG_WITH_MAKE_STATS
 endif
+ifdef CONFIG_WITH_KMK_BUILTIN_STATS
+ kmk_DEFS += CONFIG_WITH_KMK_BUILTIN_STATS
+endif
 ifdef CONFIG_WITH_EVAL_COMPILER
  kmk_DEFS += CONFIG_WITH_EVAL_COMPILER
@@ -231 +234 @@
  kmk_DEFS += CONFIG_WITH_COMPILE_EVERYTHING
 endif
+
 #ifeq ($(KBUILD_TYPE).$(USERNAME),debug.bird)
 # kmk_DEFS += CONFIG_WITH_COMPILER CONFIG_WITH_EVAL_COMPILER CONFIG_WITH_COMPILE_EVERYTHING

trunk/src/kmk/kmkbuiltin.c

@@ -36 +36 @@
 # include <io.h>
 #endif
+
+#include "makeint.h"
+#include "job.h"
 #if defined(KBUILD_OS_WINDOWS) && defined(CONFIG_NEW_WIN_CHILDREN)
-# include "makeint.h"
-# include "job.h"
 # include "w32/winchildren.h"
 #endif
@@ -231 +232 @@
  * kmk built command.
  */
-static const KMKBUILTINENTRY g_aBuiltins[] =
+static const KMKBUILTINENTRY g_aBuiltIns[] =
 {
 #define BUILTIN_ENTRY(a_fn, a_sz, a_uFnSignature, fMpSafe, fNeedEnv) \
@@ -266 +267 @@
 };
 
+#ifdef CONFIG_WITH_KMK_BUILTIN_STATS
+/** Statistics running in parallel to g_aBuiltIns. */
+struct
+{
+    big_int         cNs;
+    unsigned        cTimes;
+    unsigned        cAsyncTimes;
+} g_aBuiltInStats[sizeof(g_aBuiltIns) / sizeof(g_aBuiltIns[0])];
+#endif
+
 
 int kmk_builtin_command_parsed(int argc, char **argv, struct child *pChild, char ***ppapszArgvToSpawn, pid_t *pPidSpawned)
@@ -325 +336 @@
          * Look up the builtin command in the table.
          */
-        pEntry  = &g_aBuiltins[0];
-        cLeft   = sizeof(g_aBuiltins) / sizeof(g_aBuiltins[0]);
+        pEntry  = &g_aBuiltIns[0];
+        cLeft   = sizeof(g_aBuiltIns) / sizeof(g_aBuiltIns[0]);
         while (cLeft-- > 0)
             if (   pEntry->uName.cchAndStart != cchAndStart
@@ -340 +351 @@
 #if defined(KBUILD_OS_WINDOWS) && defined(CONFIG_NEW_WIN_CHILDREN)
                 if (pEntry->fMpSafe)
+                {
                     rc = MkWinChildCreateBuiltIn(pEntry, argc, argv, pEntry->fNeedEnv ? pChild->environment : NULL,
                                                  pChild, pPidSpawned);
+# ifdef CONFIG_WITH_KMK_BUILTIN_STATS
+                    g_aBuiltInStats[pEntry - &g_aBuiltIns[0]].cAsyncTimes++;
+# endif
+                }
                 else
 #endif
@@ -350 +366 @@
                      * Call the worker function, making sure to preserve umask.
                      */
+#ifdef CONFIG_WITH_KMK_BUILTIN_STATS
+                    big_int nsStart = nano_timestamp();
+#endif
                     int const iUmask = umask(0);        /* save umask */
                     umask(iUmask);
@@ -386 +405 @@
                     else
                         rc = 99;
+
                     g_progname = "kmk";                 /* paranoia, make sure it's not pointing at a freed argv[0]. */
                     umask(iUmask);                      /* restore it */
+
+#ifdef CONFIG_WITH_KMK_BUILTIN_STATS
+                    g_aBuiltInStats[pEntry - &g_aBuiltIns[0]].cTimes++;
+                    g_aBuiltInStats[pEntry - &g_aBuiltIns[0]].cNs += nano_timestamp() - nsStart;
+#endif
                 }
                 return rc;
@@ -411 +436 @@
 #endif
 
+#ifdef CONFIG_WITH_KMK_BUILTIN_STATS
+/**
+ * Prints the statistiscs to the given output stream.
+ */
+int kmk_builtin_print_stats(FILE *pOutput, const char *pszPrefix)
+{
+    const unsigned  cEntries = sizeof(g_aBuiltInStats) / sizeof(g_aBuiltInStats[0]);
+    unsigned i;
+    fprintf(pOutput, "\n%skmk built-in command statistics:\n", pszPrefix);
+    for (i = 0; i < cEntries; i++)
+        if (g_aBuiltInStats[i].cTimes > 0)
+        {
+            char szTotal[64];
+            char szAvg[64];
+            format_elapsed_nano(szTotal, sizeof(szTotal), g_aBuiltInStats[i].cNs);
+            format_elapsed_nano(szAvg, sizeof(szAvg), g_aBuiltInStats[i].cNs / g_aBuiltInStats[i].cTimes);
+            fprintf(pOutput, "%s kmk_builtin_%-9s: %4lu times, %9s total, %9s/call\n",
+                    pszPrefix, g_aBuiltIns[i].uName.s.sz, g_aBuiltInStats[i].cTimes, szTotal, szAvg);
+        }
+        else if (g_aBuiltInStats[i].cAsyncTimes > 0)
+            fprintf(pOutput, "%s kmk_builtin_%-9s: %4lu times in worker thread\n",
+                    pszPrefix, g_aBuiltIns[i].uName.s.sz, g_aBuiltInStats[i].cAsyncTimes);
+}
+#endif
+

trunk/src/kmk/kmkbuiltin.h

@@ -139 +139 @@
 extern int kBuiltinOptChDir(char *pszCwd, size_t cbCwdBuf, const char *pszValue);
 
+#ifdef CONFIG_WITH_KMK_BUILTIN_STATS
+int kmk_builtin_print_stats(FILE *pOutput, const char *pszPrefix);
 #endif
 
+#endif
+

trunk/src/kmk/main.c

@@ -27 +27 @@
 #ifdef KMK
 # include "kbuild.h"
+#endif
+#ifdef CONFIG_WITH_KMK_BUILTIN_STATS
+# include "kmkbuiltin.h"
 #endif
 
@@ -4174 +4177 @@
 
   /* Allocators: */
-#ifdef CONFIG_WITH_COMPILER
+# ifdef CONFIG_WITH_COMPILER
   kmk_cc_print_stats ();
-#endif
+# endif
 # ifndef CONFIG_WITH_STRCACHE2
   strcache_print_stats ("#");
@@ -4194 +4197 @@
   print_kbuild_define_stats ();
 # endif
+# ifdef CONFIG_WITH_KMK_BUILTIN_STATS
+  kmk_builtin_print_stats (stdout, "# ");
+# endif
 # ifdef CONFIG_WITH_COMPILER
   kmk_cc_print_stats ();
@@ -4201 +4207 @@
   printf (_("\n# Finished Make statistics on %s\n"), ctime (&when));
 }
-#endif
+#endif /* CONFIG_WITH_PRINT_STATS_SWITCH */
 
 static void

trunk/src/kmk/makeint.h

@@ -1176 +1176 @@
 #endif
 
-#if defined (CONFIG_WITH_NANOTS) || defined (CONFIG_WITH_PRINT_TIME_SWITCH)
+#if defined (CONFIG_WITH_NANOTS) || defined (CONFIG_WITH_PRINT_TIME_SWITCH) || defined(CONFIG_WITH_KMK_BUILTIN_STATS)
 /* misc.c */
 extern big_int nano_timestamp (void);

trunk/src/kmk/misc.c

@@ -1152 +1152 @@
 #endif /* CONFIG_WITH_PRINT_STATS_SWITCH */
 
-#ifdef CONFIG_WITH_PRINT_TIME_SWITCH
+#if defined(CONFIG_WITH_PRINT_TIME_SWITCH) || defined(CONFIG_WITH_KMK_BUILTIN_STATS)
 /* Get a nanosecond timestamp, from a monotonic time source if
    possible.  Returns -1 after calling error() on failure.  */
@@ -1249 +1249 @@
   return sz;
 }
-#endif /* CONFIG_WITH_PRINT_TIME_SWITCH */
-
+#endif /* CONFIG_WITH_PRINT_TIME_SWITCH || defined(CONFIG_WITH_KMK_BUILTIN_STATS) */
+