diff piecrust/commands/builtin/baking.py @ 989:8adc27285d93

bake: Big pass on bake performance. - Reduce the amount of data passed between processes. - Make inter-process data simple objects to make it easier to test with alternatives to pickle. - Make sources have the basic requirement to be able to find a content item from an item spec (path). - Make Hoedown the default Markdown formatter.
author Ludovic Chabant <ludovic@chabant.com>
date Sun, 19 Nov 2017 14:29:17 -0800
parents f83ae0a5d793
children 3c669bb9498e
line wrap: on
line diff
--- a/piecrust/commands/builtin/baking.py	Fri Nov 03 23:14:56 2017 -0700
+++ b/piecrust/commands/builtin/baking.py	Sun Nov 19 14:29:17 2017 -0800
@@ -48,33 +48,60 @@
             '--show-stats',
             help="Show detailed information about the bake.",
             action='store_true')
+        parser.add_argument(
+            '--profile',
+            help="Run the bake several times, for profiling.",
+            type=int, default=-1)
 
     def run(self, ctx):
         from piecrust.chefutil import format_timed
+        from piecrust.environment import ExecutionStats
 
         out_dir = (ctx.args.output or
                    os.path.join(ctx.app.root_dir, '_counter'))
 
+        success = True
+        avg_stats = ExecutionStats()
+        avg_stats.registerTimer('Total')
         start_time = time.perf_counter()
-        try:
-            records = self._doBake(ctx, out_dir)
 
-            # Show merged stats.
-            if ctx.args.show_stats:
-                logger.info("-------------------")
-                logger.info("Timing information:")
-                _show_stats(records.stats)
+        num_iter = 1
+        if ctx.args.profile > 0:
+            num_iter = ctx.args.profile
+
+        for i in range(num_iter):
+            iter_start_time = time.perf_counter()
+            if num_iter > 1:
+                import gc
+                gc.collect()
+                logger.info("---- %d/%d ----" % (i + 1, num_iter))
 
-            # All done.
-            logger.info('-------------------------')
-            logger.info(format_timed(start_time, 'done baking'))
-            return 0 if records.success else 1
-        except Exception as ex:
-            if ctx.app.debug:
-                logger.exception(ex)
-            else:
-                logger.error(str(ex))
-            return 1
+            try:
+                records = self._doBake(ctx, out_dir)
+            except Exception as ex:
+                if ctx.app.debug:
+                    logger.exception(ex)
+                else:
+                    logger.error(str(ex))
+                return 1
+
+            success = success and records.success
+            avg_stats.mergeStats(records.stats)
+            avg_stats.stepTimerSince('Total', iter_start_time)
+
+        # Show merged stats.
+        if ctx.args.show_stats:
+            if num_iter > 1:
+                _average_stats(avg_stats, num_iter)
+
+            logger.info("-------------------")
+            logger.info("Timing information:")
+            _show_stats(avg_stats)
+
+        # All done.
+        logger.info('-------------------------')
+        logger.info(format_timed(start_time, 'done baking'))
+        return 0 if success else 1
 
     def _doBake(self, ctx, out_dir):
         from piecrust.baking.baker import Baker
@@ -251,6 +278,13 @@
                     logger.info("Record: %s" % rec.name)
                     logger.info("Status: %s" % ('SUCCESS' if rec.success
                                                 else 'FAILURE'))
+                    logger.info("User Data:")
+                    if not rec.user_data:
+                        logger.info("  <empty>")
+                    else:
+                        for k, v in rec.user_data.items():
+                            logger.info("  %s: %s" % (k, v))
+
                     for e in entries_to_show:
                         _print_record_entry(e)
                     logger.info("")
@@ -270,6 +304,13 @@
                         logger.info("      - %s" % v)
 
 
+def _average_stats(stats, cnt):
+    for name in stats.timers:
+        stats.timers[name] /= cnt
+    for name in stats.counters:
+        stats.counters[name] /= cnt
+
+
 def _show_stats(stats, *, full=False):
     indent = '    '