Mercurial > piecrust2
changeset 415:0e9a94b7fdfa
bake: Improve bake record information.
* Store things in the bake record that require less interaction between the
master process and the workers. For instance, don't store the paginator
object in the render pass info -- instead, just store whether pagination
was used, and whether it had more items.
* Simplify information passing between workers and bake passes by saving the
rendering info to the JSON cache. This means the "render first sub" job
doesn't have to return anything except errors now.
* Add more performance counter info.
| author | Ludovic Chabant <ludovic@chabant.com> |
|---|---|
| date | Sat, 20 Jun 2015 19:23:16 -0700 |
| parents | c4b3a7fd2f87 |
| children | ff6cc43fb40c |
| files | piecrust/__init__.py piecrust/app.py piecrust/baking/baker.py piecrust/baking/records.py piecrust/baking/single.py piecrust/baking/worker.py piecrust/chefutil.py piecrust/commands/builtin/baking.py piecrust/data/assetor.py piecrust/data/base.py piecrust/rendering.py |
| diffstat | 11 files changed, 407 insertions(+), 266 deletions(-) [+] |
line wrap: on
line diff
--- a/piecrust/__init__.py Sat Jun 20 19:20:30 2015 -0700 +++ b/piecrust/__init__.py Sat Jun 20 19:23:16 2015 -0700 @@ -7,6 +7,7 @@ CONFIG_PATH = 'config.yml' THEME_CONFIG_PATH = 'theme_config.yml' THEME_INFO_PATH = 'theme_info.yml' +ASSET_DIR_SUFFIX = '-assets' DEFAULT_FORMAT = 'markdown' DEFAULT_TEMPLATE_ENGINE = 'jinja2'
--- a/piecrust/app.py Sat Jun 20 19:20:30 2015 -0700 +++ b/piecrust/app.py Sat Jun 20 19:23:16 2015 -0700 @@ -29,7 +29,7 @@ logger = logging.getLogger(__name__) -CACHE_VERSION = 19 +CACHE_VERSION = 20 class VariantNotFoundError(Exception): @@ -413,13 +413,8 @@ if self.env is None: self.env = StandardEnvironment() self.env.initialize(self) - self.env.registerTimer('SiteConfigLoad') self.env.registerTimer('PageLoad') - for engine in self.plugin_loader.getTemplateEngines(): - self.env.registerTimer(engine.__class__.__name__) - for fmt in self.plugin_loader.getFormatters(): - self.env.registerTimer(fmt.__class__.__name__) @cached_property def config(self):
--- a/piecrust/baking/baker.py Sat Jun 20 19:20:30 2015 -0700 +++ b/piecrust/baking/baker.py Sat Jun 20 19:23:16 2015 -0700 @@ -6,7 +6,7 @@ import logging import multiprocessing from piecrust.baking.records import ( - BakeRecordEntry, TransitionalBakeRecord, TaxonomyInfo, FirstRenderInfo) + BakeRecordEntry, TransitionalBakeRecord, TaxonomyInfo) from piecrust.baking.worker import ( BakeWorkerJob, LoadJobPayload, RenderFirstSubJobPayload, BakeJobPayload, @@ -40,6 +40,12 @@ self.taxonomy_pages.append(path) logger.debug(" - %s" % path) + # Register some timers. + self.app.env.registerTimer('LoadJob', raise_if_registered=False) + self.app.env.registerTimer('RenderFirstSubJob', + raise_if_registered=False) + self.app.env.registerTimer('BakeJob', raise_if_registered=False) + def bake(self): logger.debug(" Bake Output: %s" % self.out_dir) logger.debug(" Root URL: %s" % self.app.config.get('site/root')) @@ -108,7 +114,7 @@ logger.error("Didn't get timing information from all workers.") break - for name, val in timers.items(): + for name, val in timers['data'].items(): main_val = record.current.timers.setdefault(name, 0) record.current.timers[name] = main_val + val @@ -185,6 +191,8 @@ def _bakeRealm(self, record, pool, realm, srclist): start_time = time.perf_counter() try: + record.current.baked_count[realm] = 0 + all_factories = [] for source in srclist: factories = source.getPageFactories() @@ -193,18 +201,21 @@ self._loadRealmPages(record, pool, all_factories) self._renderRealmPages(record, pool, all_factories) - self._bakeRealmPages(record, pool, all_factories) + self._bakeRealmPages(record, pool, realm, all_factories) finally: - page_count = len(all_factories) + page_count = record.current.baked_count[realm] logger.info(format_timed( start_time, - "baked %d %s pages" % + "baked %d %s pages." % (page_count, REALM_NAMES[realm].lower()))) def _loadRealmPages(self, record, pool, factories): + logger.debug("Loading %d realm pages..." % len(factories)) with format_timed_scope(logger, "loaded %d pages" % len(factories), - level=logging.DEBUG, colored=False): + level=logging.DEBUG, colored=False, + timer_env=self.app.env, + timer_category='LoadJob'): for fac in factories: job = BakeWorkerJob( JOB_LOAD, @@ -218,6 +229,7 @@ if res.errors: record_entry.errors += res.errors record.current.success = False + self._logErrors(res.path, res.errors) record.addEntry(record_entry) self._waitOnWorkerPool( @@ -226,9 +238,12 @@ result_handler=_handler) def _renderRealmPages(self, record, pool, factories): + logger.debug("Rendering %d realm pages..." % len(factories)) with format_timed_scope(logger, "prepared %d pages" % len(factories), - level=logging.DEBUG, colored=False): + level=logging.DEBUG, colored=False, + timer_env=self.app.env, + timer_category='RenderFirstSubJob'): expected_result_count = 0 for fac in factories: record_entry = record.getCurrentEntry(fac.path) @@ -264,27 +279,23 @@ def _handler(res): entry = record.getCurrentEntry(res.path) - - entry.first_render_info = FirstRenderInfo() - entry.first_render_info.used_assets = res.used_assets - entry.first_render_info.used_pagination = \ - res.used_pagination - entry.first_render_info.pagination_has_more = \ - res.pagination_has_more - if res.errors: entry.errors += res.errors record.current.success = False + self._logErrors(res.path, res.errors) self._waitOnWorkerPool( pool, expected_result_count=expected_result_count, result_handler=_handler) - def _bakeRealmPages(self, record, pool, factories): + def _bakeRealmPages(self, record, pool, realm, factories): + logger.debug("Baking %d realm pages..." % len(factories)) with format_timed_scope(logger, "baked %d pages" % len(factories), - level=logging.DEBUG, colored=False): + level=logging.DEBUG, colored=False, + timer_env=self.app.env, + timer_category='BakeJob'): expected_result_count = 0 for fac in factories: if self._queueBakeJob(record, pool, fac): @@ -292,11 +303,15 @@ def _handler(res): entry = record.getCurrentEntry(res.path, res.taxonomy_info) - entry.bake_info = res.bake_info + entry.subs = res.sub_entries if res.errors: entry.errors += res.errors + self._logErrors(res.path, res.errors) if entry.has_any_error: record.current.success = False + if entry.was_any_sub_baked: + record.current.baked_count[realm] += 1 + record.dirty_source_names.add(entry.source_name) self._waitOnWorkerPool( pool, @@ -304,6 +319,7 @@ result_handler=_handler) def _bakeTaxonomies(self, record, pool): + logger.debug("Baking taxonomy pages...") with format_timed_scope(logger, 'built taxonomy buckets', level=logging.DEBUG, colored=False): buckets = self._buildTaxonomyBuckets(record) @@ -420,7 +436,7 @@ def _handler(res): entry = record.getCurrentEntry(res.path, res.taxonomy_info) - entry.bake_info = res.bake_info + entry.subs = res.sub_entries if res.errors: entry.errors += res.errors if entry.has_any_error: @@ -500,13 +516,13 @@ job = BakeWorkerJob( JOB_BAKE, BakeJobPayload(fac, route_metadata, prev_entry, - cur_entry.first_render_info, record.dirty_source_names, tax_info)) pool.queue.put_nowait(job) return True def _handleDeletetions(self, record): + logger.debug("Handling deletions...") for path, reason in record.getDeletions(): logger.debug("Removing '%s': %s" % (path, reason)) try: @@ -517,6 +533,12 @@ # by the user. pass + def _logErrors(self, path, errors): + rel_path = os.path.relpath(path, self.app.root_dir) + logger.error("Errors found in %s:" % rel_path) + for e in errors: + logger.error(" " + e) + def _createWorkerPool(self): from piecrust.baking.worker import BakeWorkerContext, worker_func @@ -527,6 +549,7 @@ pool.queue, pool.results, pool.abort_event, force=self.force, debug=self.app.debug) w = multiprocessing.Process( + name='Worker_%d' % i, target=worker_func, args=(i, ctx)) w.start() pool.workers.append(w) @@ -557,6 +580,12 @@ abort_with_exception = Exception("Worker time-out.") break + if isinstance(res, dict) and res.get('type') == 'error': + abort_with_exception = Exception( + 'Worker critical error:\n' + + '\n'.join(res['messages'])) + break + got_count += 1 result_handler(res) except KeyboardInterrupt as kiex:
--- a/piecrust/baking/records.py Sat Jun 20 19:20:30 2015 -0700 +++ b/piecrust/baking/records.py Sat Jun 20 19:23:16 2015 -0700 @@ -27,16 +27,11 @@ super(BakeRecord, self).__init__() self.out_dir = None self.bake_time = None + self.baked_count = {} self.timers = None self.success = True -class BakePassInfo(object): - def __init__(self): - self.used_source_names = set() - self.used_taxonomy_terms = set() - - class SubPageBakeInfo(object): FLAG_NONE = 0 FLAG_BAKED = 2**0 @@ -50,7 +45,7 @@ self.out_path = out_path self.flags = self.FLAG_NONE self.errors = [] - self.render_passes = {} + self.render_info = None @property def was_clean(self): @@ -64,23 +59,16 @@ def was_baked_successfully(self): return self.was_baked and len(self.errors) == 0 - def collapseRenderPasses(self, other): - for p, pinfo in self.render_passes.items(): - if p not in other.render_passes: - other.render_passes[p] = copy.deepcopy(pinfo) - + def anyPass(self, func): + assert self.render_info is not None + for p, pinfo in self.render_info.items(): + if func(pinfo): + return True + return False -class PageBakeInfo(object): - def __init__(self): - self.subs = [] - self.assets = [] - - -class FirstRenderInfo(object): - def __init__(self): - self.assets = [] - self.used_pagination = False - self.pagination_has_more = False + def copyRenderInfo(self): + assert self.render_info + return copy.deepcopy(self.render_info) class TaxonomyInfo(object): @@ -108,8 +96,7 @@ self.flags = self.FLAG_NONE self.config = None self.errors = [] - self.bake_info = None - self.first_render_info = None + self.subs = [] @property def path_mtime(self): @@ -121,58 +108,50 @@ @property def num_subs(self): - if self.bake_info is None: - return 0 - return len(self.bake_info.subs) + return len(self.subs) @property def was_any_sub_baked(self): - if self.bake_info is not None: - for o in self.bake_info.subs: - if o.was_baked: - return True + for o in self.subs: + if o.was_baked: + return True return False @property - def subs(self): - if self.bake_info is not None: - return self.bake_info.subs - return [] + def all_assets(self): + for sub in self.subs: + yield from sub.assets @property def has_any_error(self): if len(self.errors) > 0: return True - if self.bake_info is not None: - for o in self.bake_info.subs: - if len(o.errors) > 0: - return True + for o in self.subs: + if len(o.errors) > 0: + return True return False def getSub(self, sub_index): - if self.bake_info is None: - raise Exception("No bake info available on this entry.") - return self.bake_info.subs[sub_index - 1] + return self.subs[sub_index - 1] def getAllErrors(self): yield from self.errors - if self.bake_info is not None: - for o in self.bake_info.subs: - yield from o.errors + for o in self.subs: + yield from o.errors def getAllUsedSourceNames(self): res = set() - if self.bake_info is not None: - for o in self.bake_info.subs: - for p, pinfo in o.render_passes.items(): + for o in self.subs: + if o.render_info is not None: + for p, pinfo in o.render_info.items(): res |= pinfo.used_source_names return res def getAllUsedTaxonomyTerms(self): res = set() - if self.bake_info is not None: - for o in self.bake_info.subs: - for p, pinfo in o.render_passes.items(): + for o in self.subs: + if o.render_info is not None: + for p, pinfo in o.render_info.items(): res |= pinfo.used_taxonomy_terms return res
--- a/piecrust/baking/single.py Sat Jun 20 19:20:30 2015 -0700 +++ b/piecrust/baking/single.py Sat Jun 20 19:23:16 2015 -0700 @@ -3,8 +3,8 @@ import codecs import logging import urllib.parse -from piecrust.baking.records import ( - PageBakeInfo, SubPageBakeInfo, BakePassInfo) +from piecrust import ASSET_DIR_SUFFIX +from piecrust.baking.records import SubPageBakeInfo from piecrust.rendering import ( QualifiedPage, PageRenderingContext, render_page, PASS_FORMATTING) @@ -51,14 +51,14 @@ return os.path.normpath(os.path.join(*bake_path)) def bake(self, factory, route, route_metadata, prev_entry, - first_render_info, dirty_source_names, tax_info=None): + dirty_source_names, tax_info=None): # Get the page. page = factory.buildPage() # Start baking the sub-pages. cur_sub = 1 has_more_subs = True - report = PageBakeInfo() + sub_entries = [] while has_more_subs: # Get the URL and path for this sub-page. @@ -69,7 +69,7 @@ # Create the sub-entry for the bake record. sub_entry = SubPageBakeInfo(sub_uri, out_path) - report.subs.append(sub_entry) + sub_entries.append(sub_entry) # Find a corresponding sub-entry in the previous bake record. prev_sub_entry = None @@ -99,7 +99,7 @@ # If this page didn't bake because it's already up-to-date. # Keep trying for as many subs as we know this page has. if not do_bake: - prev_sub_entry.collapseRenderPasses(sub_entry) + sub_entry.render_info = prev_sub_entry.copyRenderInfo() sub_entry.flags = SubPageBakeInfo.FLAG_NONE if prev_entry.num_subs >= cur_sub + 1: @@ -123,35 +123,19 @@ logger.debug(" p%d -> %s" % (cur_sub, out_path)) qp = QualifiedPage(page, route, route_metadata) - ctx, rp = self._bakeSingle(qp, cur_sub, out_path, tax_info) + rp = self._bakeSingle(qp, cur_sub, out_path, tax_info) except Exception as ex: - if self.app.debug: - logger.exception(ex) page_rel_path = os.path.relpath(page.path, self.app.root_dir) raise BakingError("%s: error baking '%s'." % (page_rel_path, sub_uri)) from ex # Record what we did. sub_entry.flags |= SubPageBakeInfo.FLAG_BAKED - # self.record.dirty_source_names.add(record_entry.source_name) - for p, pinfo in ctx.render_passes.items(): - bpi = BakePassInfo() - bpi.used_source_names = set(pinfo.used_source_names) - bpi.used_taxonomy_terms = set(pinfo.used_taxonomy_terms) - sub_entry.render_passes[p] = bpi - if prev_sub_entry: - prev_sub_entry.collapseRenderPasses(sub_entry) - - # If this page has had its first sub-page rendered already, we - # have that information from the baker. Otherwise (e.g. for - # taxonomy pages), we have that information from the result - # of the render. - info = ctx - if cur_sub == 1 and first_render_info is not None: - info = first_render_info + sub_entry.render_info = rp.copyRenderInfo() # Copy page assets. - if cur_sub == 1 and self.copy_assets and info.used_assets: + if (cur_sub == 1 and self.copy_assets and + sub_entry.anyPass(lambda p: p.used_assets)): if self.pretty_urls: out_assets_dir = os.path.dirname(out_path) else: @@ -163,21 +147,23 @@ logger.debug("Copying page assets to: %s" % out_assets_dir) _ensure_dir_exists(out_assets_dir) - used_assets = info.used_assets - for ap in used_assets: - dest_ap = os.path.join(out_assets_dir, - os.path.basename(ap)) - logger.debug(" %s -> %s" % (ap, dest_ap)) - shutil.copy(ap, dest_ap) - report.assets.append(ap) + page_dirname = os.path.dirname(page.path) + page_pathname, _ = os.path.splitext(page.path) + in_assets_dir = page_pathname + ASSET_DIR_SUFFIX + for fn in os.listdir(in_assets_dir): + full_fn = os.path.join(page_dirname, fn) + if os.path.isfile(full_fn): + dest_ap = os.path.join(out_assets_dir, fn) + logger.debug(" %s -> %s" % (full_fn, dest_ap)) + shutil.copy(full_fn, dest_ap) # Figure out if we have more work. has_more_subs = False - if info.pagination_has_more: + if sub_entry.anyPass(lambda p: p.pagination_has_more): cur_sub += 1 has_more_subs = True - return report + return sub_entries def _bakeSingle(self, qualified_page, num, out_path, tax_info=None): ctx = PageRenderingContext(qualified_page, page_num=num) @@ -193,7 +179,7 @@ with codecs.open(out_path, 'w', 'utf8') as fp: fp.write(rp.content) - return ctx, rp + return rp def _compute_force_flags(prev_sub_entry, sub_entry, dirty_source_names): @@ -246,11 +232,11 @@ return force_this_sub, invalidate_formatting -def _get_dirty_source_names_and_render_passes( - sub_entry, dirty_source_names): +def _get_dirty_source_names_and_render_passes(sub_entry, dirty_source_names): dirty_for_this = set() invalidated_render_passes = set() - for p, pinfo in sub_entry.render_passes.items(): + assert sub_entry.render_info is not None + for p, pinfo in sub_entry.render_info.items(): for src_name in pinfo.used_source_names: is_dirty = (src_name in dirty_source_names) if is_dirty:
--- a/piecrust/baking/worker.py Sat Jun 20 19:20:30 2015 -0700 +++ b/piecrust/baking/worker.py Sat Jun 20 19:23:16 2015 -0700 @@ -64,6 +64,7 @@ app.env.registerTimer(type(jh).__name__) # Start working! + aborted_with_exception = None while not self.ctx.abort_event.is_set(): try: with app.env.timerScope('JobReceive'): @@ -77,19 +78,23 @@ handler.handleJob(job) except Exception as ex: self.ctx.abort_event.set() - self.abort_exception = ex - self.success = False + aborted_with_exception = ex logger.debug("[%d] Critical error, aborting." % self.wid) - if self.ctx.app.debug: + if self.ctx.debug: logger.exception(ex) break finally: self.ctx.work_queue.task_done() + if aborted_with_exception is not None: + msgs = _get_errors(aborted_with_exception) + self.ctx.results.put_nowait({'type': 'error', 'messages': msgs}) + # Send our timers to the main process before exiting. app.env.stepTimer("Worker_%d" % self.wid, time.perf_counter() - work_start_time) - self.ctx.results.put_nowait(app.env._timers) + self.ctx.results.put_nowait({ + 'type': 'timers', 'data': app.env._timers}) class JobHandler(object): @@ -141,20 +146,16 @@ class RenderFirstSubJobResult(object): def __init__(self, path): self.path = path - self.used_assets = None - self.used_pagination = None - self.pagination_has_more = False self.errors = None class BakeJobPayload(object): def __init__(self, fac, route_metadata, previous_entry, - first_render_info, dirty_source_names, tax_info=None): + dirty_source_names, tax_info=None): self.factory_info = PageFactoryInfo(fac) self.route_metadata = route_metadata self.previous_entry = previous_entry self.dirty_source_names = dirty_source_names - self.first_render_info = first_render_info self.taxonomy_info = tax_info @@ -162,7 +163,7 @@ def __init__(self, path, tax_info=None): self.path = path self.taxonomy_info = tax_info - self.bake_info = None + self.sub_entries = None self.errors = None @@ -177,7 +178,10 @@ page._load() result.config = page.config.get() except Exception as ex: + logger.debug("Got loading error. Sending it to master.") result.errors = _get_errors(ex) + if self.ctx.debug: + logger.exception(ex) self.ctx.results.put_nowait(result) @@ -201,13 +205,11 @@ logger.debug("Preparing page: %s" % fac.ref_spec) try: render_page_segments(ctx) - result.used_assets = ctx.used_assets - result.used_pagination = ctx.used_pagination is not None - if result.used_pagination: - result.pagination_has_more = ctx.used_pagination.has_more except Exception as ex: logger.debug("Got rendering error. Sending it to master.") result.errors = _get_errors(ex) + if self.ctx.debug: + logger.exception(ex) self.ctx.results.put_nowait(result) @@ -233,18 +235,19 @@ result = BakeJobResult(fac.path, tax_info) previous_entry = job.payload.previous_entry - first_render_info = job.payload.first_render_info dirty_source_names = job.payload.dirty_source_names logger.debug("Baking page: %s" % fac.ref_spec) try: - report = self.page_baker.bake(fac, route, route_metadata, - previous_entry, first_render_info, - dirty_source_names, tax_info) - result.bake_info = report + sub_entries = self.page_baker.bake( + fac, route, route_metadata, previous_entry, + dirty_source_names, tax_info) + result.sub_entries = sub_entries except BakingError as ex: logger.debug("Got baking error. Sending it to master.") result.errors = _get_errors(ex) + if self.ctx.debug: + logger.exception(ex) self.ctx.results.put_nowait(result)
--- a/piecrust/chefutil.py Sat Jun 20 19:20:30 2015 -0700 +++ b/piecrust/chefutil.py Sat Jun 20 19:23:16 2015 -0700 @@ -5,10 +5,13 @@ @contextlib.contextmanager -def format_timed_scope(logger, message, *, level=logging.INFO, colored=True): +def format_timed_scope(logger, message, *, level=logging.INFO, colored=True, + timer_env=None, timer_category=None): start_time = time.perf_counter() yield logger.log(level, format_timed(start_time, message, colored=colored)) + if timer_env is not None and timer_category is not None: + timer_env.stepTimer(timer_category, time.perf_counter() - start_time) def format_timed(start_time, message, indent_level=0, colored=True):
--- a/piecrust/commands/builtin/baking.py Sat Jun 20 19:20:30 2015 -0700 +++ b/piecrust/commands/builtin/baking.py Sat Jun 20 19:23:16 2015 -0700 @@ -9,12 +9,13 @@ BakeRecord, BakeRecordEntry, SubPageBakeInfo) from piecrust.chefutil import format_timed from piecrust.commands.base import ChefCommand -from piecrust.processing.base import ProcessorPipeline +from piecrust.processing.pipeline import ProcessorPipeline from piecrust.processing.records import ( ProcessorPipelineRecord, - FLAG_PREPARED, FLAG_PROCESSED, FLAG_OVERRIDEN, + FLAG_PREPARED, FLAG_PROCESSED, FLAG_BYPASSED_STRUCTURED_PROCESSING) -from piecrust.rendering import PASS_FORMATTING, PASS_RENDERING +from piecrust.rendering import ( + PASS_FORMATTING, PASS_RENDERING) logger = logging.getLogger(__name__) @@ -45,7 +46,7 @@ action='store_true') parser.add_argument( '--html-only', - help="Only bake HTML files (don't run the asset pipeline).", + help="Only bake the pages (don't run the asset pipeline).", action='store_true') parser.add_argument( '--show-timers', @@ -57,6 +58,7 @@ os.path.join(ctx.app.root_dir, '_counter')) success = True + ctx.timers = {} start_time = time.perf_counter() try: # Bake the site sources. @@ -67,6 +69,17 @@ if not ctx.args.html_only: success = success & self._bakeAssets(ctx, out_dir) + # Show merged timers. + if ctx.args.show_timers: + from colorama import Fore + logger.info("-------------------") + logger.info("Timing information:") + for name in sorted(ctx.timers.keys()): + val_str = '%8.1f s' % ctx.timers[name] + logger.info( + "[%s%s%s] %s" % + (Fore.GREEN, val_str, Fore.RESET, name)) + # All done. logger.info('-------------------------') logger.info(format_timed(start_time, 'done baking')) @@ -85,20 +98,7 @@ ctx.app, out_dir, force=ctx.args.force) record = baker.bake() - - if ctx.args.show_timers: - if record.timers: - from colorama import Fore - logger.info("-------------------") - logger.info("Timing information:") - for name in sorted(record.timers.keys()): - val_str = '%8.1f s' % record.timers[name] - logger.info( - "[%s%s%s] %s" % - (Fore.GREEN, val_str, Fore.RESET, name)) - else: - logger.warning("Timing information is not available.") - + _merge_timers(record.timers, ctx.timers) return record.success def _bakeAssets(self, ctx, out_dir): @@ -106,9 +106,20 @@ ctx.app, out_dir, force=ctx.args.force) record = proc.run() + _merge_timers(record.timers, ctx.timers) return record.success +def _merge_timers(source, target): + if source is None: + return + + for name, val in source.items(): + if name not in target: + target[name] = 0 + target[name] += val + + class ShowRecordCommand(ChefCommand): def __init__(self): super(ShowRecordCommand, self).__init__() @@ -135,6 +146,15 @@ type=int, default=0, help="Show the last Nth bake record.") + parser.add_argument( + '--html-only', + action='store_true', + help="Only show records for pages (not from the asset " + "pipeline).") + parser.add_argument( + '--assets-only', + action='store_true', + help="Only show records for assets (not from pages).") def run(self, ctx): out_dir = ctx.args.output or os.path.join(ctx.app.root_dir, '_counter') @@ -150,12 +170,18 @@ if ctx.args.out: out_pattern = '*%s*' % ctx.args.out.strip('*') + if not ctx.args.assets_only: + self._showBakeRecord(ctx, record_name, pattern, out_pattern) + if not ctx.args.html_only: + self._showProcessingRecord(ctx, record_name, pattern, out_pattern) + + def _showBakeRecord(self, ctx, record_name, pattern, out_pattern): + # Show the bake record. record_cache = ctx.app.cache.getCache('baker') if not record_cache.has(record_name): raise Exception("No record has been created for this output path. " "Did you bake there yet?") - # Show the bake record. record = BakeRecord.load(record_cache.getCachePath(record_name)) logging.info("Bake record for: %s" % record.out_dir) logging.info("From: %s" % record_name) @@ -167,69 +193,90 @@ logging.error("Status: failed") logging.info("Entries:") for entry in record.entries: - if pattern and not fnmatch.fnmatch(entry.rel_path, pattern): + if pattern and not fnmatch.fnmatch(entry.path, pattern): continue if out_pattern and not ( any([o for o in entry.out_paths if fnmatch.fnmatch(o, out_pattern)])): continue - flags = [] - if entry.flags & BakeRecordEntry.FLAG_OVERRIDEN: - flags.append('overriden') - - passes = {PASS_RENDERING: 'render', PASS_FORMATTING: 'format'} + flags = _get_flag_descriptions( + entry.flags, + { + BakeRecordEntry.FLAG_NEW: 'new', + BakeRecordEntry.FLAG_SOURCE_MODIFIED: 'modified', + BakeRecordEntry.FLAG_OVERRIDEN: 'overriden'}) logging.info(" - ") - logging.info(" path: %s" % entry.rel_path) - logging.info(" spec: %s:%s" % (entry.source_name, - entry.rel_path)) + + rel_path = os.path.relpath(entry.path, ctx.app.root_dir) + logging.info(" path: %s" % rel_path) + logging.info(" source: %s" % entry.source_name) if entry.taxonomy_info: - tax_name, term, source_name = entry.taxonomy_info - logging.info(" taxonomy: %s (%s:%s)" % - (term, source_name, tax_name)) + ti = entry.taxonomy_info + logging.info(" taxonomy: %s = %s (in %s)" % + (ti.taxonomy_name, ti.term, ti.source_name)) else: logging.info(" taxonomy: <none>") - logging.info(" flags: %s" % ', '.join(flags)) + logging.info(" flags: %s" % _join(flags)) logging.info(" config: %s" % entry.config) + if entry.errors: + logging.error(" errors: %s" % entry.errors) + logging.info(" %d sub-pages:" % len(entry.subs)) for sub in entry.subs: + sub_flags = _get_flag_descriptions( + sub.flags, + { + SubPageBakeInfo.FLAG_BAKED: 'baked', + SubPageBakeInfo.FLAG_FORCED_BY_SOURCE: + 'forced by source', + SubPageBakeInfo.FLAG_FORCED_BY_NO_PREVIOUS: + 'forced by missing previous record entry', + SubPageBakeInfo.FLAG_FORCED_BY_PREVIOUS_ERRORS: + 'forced by previous errors', + SubPageBakeInfo.FLAG_FORMATTING_INVALIDATED: + 'formatting invalidated'}) + logging.info(" - ") logging.info(" URL: %s" % sub.out_uri) - logging.info(" path: %s" % os.path.relpath(sub.out_path, - out_dir)) - logging.info(" baked?: %s" % sub.was_baked) + logging.info(" path: %s" % os.path.relpath( + sub.out_path, record.out_dir)) + logging.info(" flags: %s" % _join(sub_flags)) - sub_flags = [] - if sub.flags & SubPageBakeInfo.FLAG_FORCED_BY_SOURCE: - sub_flags.append('forced by source') - if sub.flags & SubPageBakeInfo.FLAG_FORCED_BY_NO_PREVIOUS: - sub_flags.append('forced by missing previous record entry') - if sub.flags & SubPageBakeInfo.FLAG_FORCED_BY_PREVIOUS_ERRORS: - sub_flags.append('forced by previous errors') - logging.info(" flags: %s" % ', '.join(sub_flags)) - - for p, pi in sub.render_passes.items(): - logging.info(" %s pass:" % passes[p]) - logging.info(" used srcs: %s" % - ', '.join(pi.used_source_names)) - logging.info(" used terms: %s" % - ', '.join( - ['%s (%s:%s)' % (t, sn, tn) - for sn, tn, t in - pi.used_taxonomy_terms])) + if sub.render_info: + pass_names = { + PASS_FORMATTING: 'formatting pass', + PASS_RENDERING: 'rendering pass'} + for p, ri in sub.render_info.items(): + logging.info(" - %s" % pass_names[p]) + logging.info(" used sources: %s" % + _join(ri.used_source_names)) + pgn_info = 'no' + if ri.used_pagination: + pgn_info = 'yes' + if ri.pagination_has_more: + pgn_info += ', has more' + logging.info(" used pagination: %s", pgn_info) + logging.info(" used assets: %s", + 'yes' if ri.used_assets else 'no') + logging.info(" used terms: %s" % + _join( + ['%s=%s (%s)' % (tn, t, sn) + for sn, tn, t in + ri.used_taxonomy_terms])) + else: + logging.info(" no render info") if sub.errors: logging.error(" errors: %s" % sub.errors) - logging.info(" assets: %s" % ', '.join(entry.assets)) - if entry.errors: - logging.error(" errors: %s" % entry.errors) - + def _showProcessingRecord(self, ctx, record_name, pattern, out_pattern): record_cache = ctx.app.cache.getCache('proc') if not record_cache.has(record_name): - return + raise Exception("No record has been created for this output path. " + "Did you bake there yet?") # Show the pipeline record. record = ProcessorPipelineRecord.load( @@ -244,37 +291,51 @@ logging.error("Status: failed") logging.info("Entries:") for entry in record.entries: - if pattern and not fnmatch.fnmatch(entry.rel_input, pattern): + rel_path = os.path.relpath(entry.path, ctx.app.root_dir) + if pattern and not fnmatch.fnmatch(rel_path, pattern): continue if out_pattern and not ( any([o for o in entry.rel_outputs if fnmatch.fnmatch(o, out_pattern)])): continue - flags = [] - if entry.flags & FLAG_PREPARED: - flags.append('prepared') - if entry.flags & FLAG_PROCESSED: - flags.append('processed') - if entry.flags & FLAG_OVERRIDEN: - flags.append('overriden') - if entry.flags & FLAG_BYPASSED_STRUCTURED_PROCESSING: - flags.append('external') + flags = _get_flag_descriptions( + entry.flags, + { + FLAG_PREPARED: 'prepared', + FLAG_PROCESSED: 'processed', + FLAG_BYPASSED_STRUCTURED_PROCESSING: 'external'}) + logger.info(" - ") - logger.info(" path: %s" % entry.rel_input) + logger.info(" path: %s" % rel_path) logger.info(" out paths: %s" % entry.rel_outputs) - logger.info(" flags: %s" % flags) - logger.info(" proc tree: %s" % format_proc_tree( + logger.info(" flags: %s" % _join(flags)) + logger.info(" proc tree: %s" % _format_proc_tree( entry.proc_tree, 14*' ')) + if entry.errors: logger.error(" errors: %s" % entry.errors) -def format_proc_tree(tree, margin='', level=0): +def _join(items, sep=', ', text_if_none='none'): + if items: + return sep.join(items) + return text_if_none + + +def _get_flag_descriptions(flags, descriptions): + res = [] + for k, v in descriptions.items(): + if flags & k: + res.append(v) + return res + + +def _format_proc_tree(tree, margin='', level=0): name, children = tree res = '%s%s+ %s\n' % (margin if level > 0 else '', level * ' ', name) if children: for c in children: - res += format_proc_tree(c, margin, level + 1) + res += _format_proc_tree(c, margin, level + 1) return res
--- a/piecrust/data/assetor.py Sat Jun 20 19:20:30 2015 -0700 +++ b/piecrust/data/assetor.py Sat Jun 20 19:23:16 2015 -0700 @@ -1,6 +1,7 @@ import os import os.path import logging +from piecrust import ASSET_DIR_SUFFIX from piecrust.uriutil import multi_replace @@ -31,8 +32,6 @@ class Assetor(object): - ASSET_DIR_SUFFIX = '-assets' - debug_render_doc = """Helps render URLs to files in the current page's asset folder.""" debug_render = [] @@ -58,6 +57,10 @@ self._cacheAssets() return map(lambda i: i[0], self._cache.values()) + def _getFilenames(self): + assert self._cache is not None + return map(lambda i: i[1], self._cache.values()) + def _debugRenderAssetNames(self): self._cacheAssets() return list(self._cache.keys()) @@ -68,7 +71,7 @@ self._cache = {} name, ext = os.path.splitext(self._page.path) - assets_dir = name + Assetor.ASSET_DIR_SUFFIX + assets_dir = name + ASSET_DIR_SUFFIX if not os.path.isdir(assets_dir): return @@ -88,6 +91,5 @@ cpi = self._page.app.env.exec_info_stack.current_page_info if cpi is not None: - used_assets = list(map(lambda i: i[1], self._cache.values())) - cpi.render_ctx.used_assets = used_assets + cpi.render_ctx.used_assets = True
--- a/piecrust/data/base.py Sat Jun 20 19:20:30 2015 -0700 +++ b/piecrust/data/base.py Sat Jun 20 19:23:16 2015 -0700 @@ -196,7 +196,8 @@ qp = QualifiedPage(self._page, self._route, self._route_metadata) ctx = PageRenderingContext(qp) - segs = render_page_segments(ctx) + render_result = render_page_segments(ctx) + segs = render_result.segments except Exception as e: raise Exception( "Error rendering segments for '%s'" % uri) from e
--- a/piecrust/rendering.py Sat Jun 20 19:20:30 2015 -0700 +++ b/piecrust/rendering.py Sat Jun 20 19:23:16 2015 -0700 @@ -1,5 +1,6 @@ import re import os.path +import copy import logging from werkzeug.utils import cached_property from piecrust.data.builder import ( @@ -40,6 +41,18 @@ return getattr(self.page, name) +class RenderedSegments(object): + def __init__(self, segments, render_pass_info): + self.segments = segments + self.render_pass_info = render_pass_info + + +class RenderedLayout(object): + def __init__(self, content, render_pass_info): + self.content = content + self.render_pass_info = render_pass_info + + class RenderedPage(object): def __init__(self, page, uri, num=1): self.page = page @@ -47,11 +60,15 @@ self.num = num self.data = None self.content = None + self.render_info = None @property def app(self): return self.page.app + def copyRenderInfo(self): + return copy.deepcopy(self.render_info) + PASS_NONE = 0 PASS_FORMATTING = 1 @@ -65,6 +82,41 @@ def __init__(self): self.used_source_names = set() self.used_taxonomy_terms = set() + self.used_pagination = False + self.pagination_has_more = False + self.used_assets = False + + def merge(self, other): + self.used_source_names |= other.used_source_names + self.used_taxonomy_terms |= other.used_taxonomy_terms + self.used_pagination = self.used_pagination or other.used_pagination + self.pagination_has_more = (self.pagination_has_more or + other.pagination_has_more) + self.used_assets = self.used_assets or other.used_assets + + def _toJson(self): + data = { + 'used_source_names': list(self.used_source_names), + 'used_taxonomy_terms': list(self.used_taxonomy_terms), + 'used_pagination': self.used_pagination, + 'pagination_has_more': self.pagination_has_more, + 'used_assets': self.used_assets} + return data + + @staticmethod + def _fromJson(data): + assert data is not None + rpi = RenderPassInfo() + rpi.used_source_names = set(data['used_source_names']) + for i in data['used_taxonomy_terms']: + terms = i[2] + if isinstance(terms, list): + terms = tuple(terms) + rpi.used_taxonomy_terms.add((i[0], i[1], terms)) + rpi.used_pagination = data['used_pagination'] + rpi.pagination_has_more = data['pagination_has_more'] + rpi.used_assets = data['used_assets'] + return rpi class PageRenderingContext(object): @@ -78,8 +130,6 @@ self._current_pass = PASS_NONE self.render_passes = {} - self.used_pagination = None - self.used_assets = None @property def app(self): @@ -94,12 +144,6 @@ return self.page.getUri(self.page_num) @property - def pagination_has_more(self): - if self.used_pagination is None: - return False - return self.used_pagination.has_more - - @property def current_pass_info(self): return self.render_passes.get(self._current_pass) @@ -110,15 +154,18 @@ def setPagination(self, paginator): self._raiseIfNoCurrentPass() - if self.used_pagination is not None: + pass_info = self.current_pass_info + if pass_info.used_pagination: raise Exception("Pagination has already been used.") - self.used_pagination = paginator + assert paginator.is_loaded + pass_info.used_pagination = True + pass_info.pagination_has_more = paginator.has_more self.addUsedSource(paginator._source) def addUsedSource(self, source): self._raiseIfNoCurrentPass() if isinstance(source, PageSource): - pass_info = self.render_passes[self._current_pass] + pass_info = self.current_pass_info pass_info.used_source_names.add(source.name) def setTaxonomyFilter(self, taxonomy, term_value): @@ -150,15 +197,8 @@ eis = ctx.app.env.exec_info_stack eis.pushPage(ctx.page, ctx) try: - page = ctx.page - # Build the data for both segment and layout rendering. - data_ctx = DataBuildingContext(page, page_num=ctx.page_num) - data_ctx.pagination_source = ctx.pagination_source - data_ctx.pagination_filter = ctx.pagination_filter - page_data = build_page_data(data_ctx) - if ctx.custom_data: - page_data.update(ctx.custom_data) + page_data = _build_render_data(ctx) # Render content segments. ctx.setCurrentPass(PASS_FORMATTING) @@ -167,31 +207,40 @@ if ctx.app.env.fs_cache_only_for_main_page and not eis.is_main_page: save_to_fs = False if repo and not ctx.force_render: - contents = repo.get( + render_result = repo.get( ctx.uri, - lambda: _do_render_page_segments(page, page_data), - fs_cache_time=page.path_mtime, + lambda: _do_render_page_segments(ctx.page, page_data), + fs_cache_time=ctx.page.path_mtime, save_to_fs=save_to_fs) else: - contents = _do_render_page_segments(page, page_data) + render_result = _do_render_page_segments(ctx.page, page_data) if repo: - repo.put(ctx.uri, contents, save_to_fs) + repo.put(ctx.uri, render_result, save_to_fs) # Render layout. + page = ctx.page ctx.setCurrentPass(PASS_RENDERING) layout_name = page.config.get('layout') if layout_name is None: layout_name = page.source.config.get('default_layout', 'default') null_names = ['', 'none', 'nil'] if layout_name not in null_names: - build_layout_data(page, page_data, contents) - output = render_layout(layout_name, page, page_data) + build_layout_data(page, page_data, render_result['segments']) + layout_result = _do_render_layout(layout_name, page, page_data) else: - output = contents['content'] + layout_result = { + 'content': render_result['segments']['content'], + 'pass_info': None} rp = RenderedPage(page, ctx.uri, ctx.page_num) rp.data = page_data - rp.content = output + rp.content = layout_result['content'] + rp.render_info = { + PASS_FORMATTING: RenderPassInfo._fromJson( + render_result['pass_info'])} + if layout_result['pass_info'] is not None: + rp.render_info[PASS_RENDERING] = RenderPassInfo._fromJson( + layout_result['pass_info']) return rp finally: ctx.setCurrentPass(PASS_NONE) @@ -199,38 +248,59 @@ def render_page_segments(ctx): - repo = ctx.app.env.rendered_segments_repository - if repo: - cache_key = ctx.uri - return repo.get( - cache_key, - lambda: _do_render_page_segments_from_ctx(ctx), - fs_cache_time=ctx.page.path_mtime) - - return _do_render_page_segments_from_ctx(ctx) - - -def _do_render_page_segments_from_ctx(ctx): eis = ctx.app.env.exec_info_stack eis.pushPage(ctx.page, ctx) - ctx.setCurrentPass(PASS_FORMATTING) try: - data_ctx = DataBuildingContext(ctx.page, page_num=ctx.page_num) - page_data = build_page_data(data_ctx) - return _do_render_page_segments(ctx.page, page_data) + page_data = _build_render_data(ctx) + + ctx.setCurrentPass(PASS_FORMATTING) + repo = ctx.app.env.rendered_segments_repository + save_to_fs = True + if ctx.app.env.fs_cache_only_for_main_page and not eis.is_main_page: + save_to_fs = False + if repo and not ctx.force_render: + render_result = repo.get( + ctx.uri, + lambda: _do_render_page_segments(ctx.page, page_data), + fs_cache_time=ctx.page.path_mtime, + save_to_fs=save_to_fs) + else: + render_result = _do_render_page_segments(ctx.page, page_data) + if repo: + repo.put(ctx.uri, render_result, save_to_fs) finally: ctx.setCurrentPass(PASS_NONE) eis.popPage() + rs = RenderedSegments( + render_result['segments'], + RenderPassInfo._fromJson(render_result['pass_info'])) + return rs + + +def _build_render_data(ctx): + data_ctx = DataBuildingContext(ctx.page, page_num=ctx.page_num) + data_ctx.pagination_source = ctx.pagination_source + data_ctx.pagination_filter = ctx.pagination_filter + page_data = build_page_data(data_ctx) + if ctx.custom_data: + page_data.update(ctx.custom_data) + return page_data + def _do_render_page_segments(page, page_data): app = page.app + + cpi = app.env.exec_info_stack.current_page_info + assert cpi is not None + assert cpi.page == page + engine_name = page.config.get('template_engine') format_name = page.config.get('format') engine = get_template_engine(app, engine_name) - formatted_content = {} + formatted_segments = {} for seg_name, seg in page.raw_content.items(): seg_text = '' for seg_part in seg.parts: @@ -246,19 +316,27 @@ part_text = format_text(app, part_format, part_text) seg_text += part_text - formatted_content[seg_name] = seg_text + formatted_segments[seg_name] = seg_text if seg_name == 'content': m = content_abstract_re.search(seg_text) if m: offset = m.start() content_abstract = seg_text[:offset] - formatted_content['content.abstract'] = content_abstract + formatted_segments['content.abstract'] = content_abstract - return formatted_content + pass_info = cpi.render_ctx.render_passes.get(PASS_FORMATTING) + res = { + 'segments': formatted_segments, + 'pass_info': pass_info._toJson()} + return res -def render_layout(layout_name, page, layout_data): +def _do_render_layout(layout_name, page, layout_data): + cpi = page.app.env.exec_info_stack.current_page_info + assert cpi is not None + assert cpi.page == page + names = layout_name.split(',') default_template_engine = get_template_engine(page.app, None) default_exts = ['.' + e.lstrip('.') @@ -281,7 +359,10 @@ msg = "Can't find template for page: %s\n" % page.path msg += "Looked for: %s" % ', '.join(full_names) raise Exception(msg) from ex - return output + + pass_info = cpi.render_ctx.render_passes.get(PASS_RENDERING) + res = {'content': output, 'pass_info': pass_info._toJson()} + return res def get_template_engine(app, engine_name):