Warning: Can't synchronize with repository "(default)" (Unsupported version control system "svn": No module named svn). Look in the Trac log for more information.

Ticket #2175 (closed enhancement: fixed)

Opened 10 years ago

Last modified 10 years ago

mako template performance problems

Reported by: tvrtko.sokolovski Owned by: faide
Priority: high Milestone: 2.0b6
Component: Documentation Version: trunk
Severity: normal Keywords: mako cache profiling
Cc:

Description

There is a potential problem with mako template caching the way it is used by TG2. If you expose a controller method and decorate it with mako template it gets served 2 or 3 times slower than when you expose a "raw" method which uses mako.lookup.TemplateLookup? to rended template directly.

For example:

class MyController(object)
    @expose('mako:proj.templates.mako_speed')
    def automatic(self):
        return dict()

is 3 times slower than

from mako.template import Template
from mako.lookup import TemplateLookup

templates = '...full path...'
mylookup = TemplateLookup(
    directories=[templates],
    # same difference with and without next line:
    #module_directory=templates, 
    output_encoding='utf-8')

def serve_template(templatename, **kwargs):
    mytemplate = mylookup.get_template(templatename)
    return mytemplate.render(**kwargs)

class MyController(object)
    @expose()
    def manual(self):
        return serve_template('mako_speed.mak')

There is an example attached to this ticket. Put mako_speed.mak into your templates directory, and mako_speed.py into controllers directory. Expose MakoSpeedController? as "mako_speed" in your root controller.

Attachments

mako_speed.py Download (1.4 KB) - added by tvrtko.sokolovski 10 years ago.
controller
mako_speed.mak Download (1.4 KB) - added by tvrtko.sokolovski 10 years ago.
template
dottednamesfinder.diff Download (11.8 KB) - added by faide 10 years ago.
A new patch for optimization with test_stack passing ... :)

Change History

Changed 10 years ago by tvrtko.sokolovski

controller

Changed 10 years ago by tvrtko.sokolovski

template

comment:1 Changed 10 years ago by jorge.vargas

  • Priority changed from normal to high
  • Keywords profiling added

I think we should profile this, IMO it is a good task for tg2.0rc1

comment:2 Changed 10 years ago by mramm

  • Milestone changed from 2.0 to 2.0b6

comment:3 Changed 10 years ago by mramm

  • Summary changed from mako template caching problem to mako template performance problems

comment:4 Changed 10 years ago by kikidonk

I can reproduce the problem, and it lies in the Dotted-template lookup loader.

If you use use_dotted_templatenames = False, mako will be very fast (modulo bug #2192).

The problem seems to be:

I guess DottedTemplateLookup? should inherit from mako's TemplateLookup? and override only the needed parts to transform the dotted name in file name

comment:5 Changed 10 years ago by kikidonk

I can reproduce the problem, and it lies in the Dotted-template lookup loader.

If you use use_dotted_templatenames = False, mako will be very fast (modulo bug #2192).

The problem seems to be:

  • http://trac.turbogears.org/browser/trunk/tg/configuration.py#L292 The DottedTemplateLookup does an open().read() each time a template is invoked via get_template which can happen a lot (via includes/inherits, etc)
  • DottedTemplateLookup doesn't implement the same caching mechanism as the Mako's TemplateLookup (which has a TemplateCollection, and doesn't actually read the template content until needed, and also uses the precompiled template). I beleive DottedTemplateLookup never actually compiles and re-uses compiled templates.

I guess DottedTemplateLookup should inherit from mako's TemplateLookup and override only the needed parts to transform the dotted name in file name

comment:6 Changed 10 years ago by faide

  • Status changed from new to assigned

I was sure it was something like this but was too busy to search in details for the last few weeks.

Thanks for your work and tickets! I'll see what I can do about this ASAP.

Best regards, Florent.

comment:7 Changed 10 years ago by faide

I committed a first fix in r6275 that implements a cache for the template lookup. I'll add another cache to the get_dotted_filename function to speed things a little bit more.

Could you already test if it is better now ?

It successfully passes the tests on my machine but I unfortunately have no real Mako usage anywhere so I cannot be 100% sure of what I do :)

Florent.

comment:8 Changed 10 years ago by faide

Added some more caching (get_dotted_filenames) in r6276.

Please comment here with your benchmarks results... if we get nice results we can close that ticket. Else I have some more ideas to shave some more cycles.

Florent.

comment:9 Changed 10 years ago by faide

As you can see we cannot inherit from the Mako TemplateLookup?, because this template lookup implies that your project is installed in an unzipped fashion which is not always the case. This led to this particular implementation.

If for any reason you want raw speed and don't care about zip safe-ness of your resulting application then you should certainly not use dotted names in templates anyway.

Thanks to both people who reported and added info about this issue. Please give us benchmark feedback here and happy TG'ing :)

Florent.

comment:10 Changed 10 years ago by tvrtko.sokolovski

It certainly helped, the numbers are:

  • manually: 0.8 sec
  • old mako: 4.2 sec
  • new mako: 1.4 sec

But, this is a mixed blessing, because now I have to restart server each time I change a mako template, because it doesn't know how to reload changed template.

I'm going to try use_dotted_templatenames flag to use TemplateLookup?. How exactly do you enable it (which config file/section I have to modify).

comment:11 Changed 10 years ago by kikidonk

The same kind of caching logic that is applied in the original loader:  http://www.makotemplates.org/trac/browser/mako/trunk/lib/mako/lookup.py should be re-implemented then, it seems quite a burden...

comment:12 Changed 10 years ago by faide

well in fact this kind of reloading based on mtime (os.stat(fname)) is quite difficult to emulate if not using file system based... But on the other hand if you are in production you won't need that time checking.

So this means we could add the same time-checking mechanism based on the environment we are in:

  • in development: use the os.stat(templanefilename) to determine mtime and maybe reload from file
  • in production: just ignore the time check and use only the cache...

comment:13 Changed 10 years ago by faide

as per this flag you can edit your application's config/app_cfg.py and add a line like this:

base_config.use_dotted_templatenames = False

if nothing is set in your file the default is True

WARNING: if you do this, you'll have to change the names of your templates in the controllers, but also in the templates themselves when using inheritance.

comment:14 Changed 10 years ago by faide

in r6288 I just added a system that allows you to reload your mako templates from the disk if they were modified... This will work by adding a config entry in the development.ini file:

templating.mako.reloadfromdisk = true

in the app:main section of this config file.

I recommend you do not use this option in production. And be warned this option is untested and may break badly if you use zipped egg deployment.

If you test and are happy with it I'll just update the templates for quickstart to add this option in the config template and add some docs about it.

Once this works we can begin to shave some CPU cycles here and there.

Waiting for your feedback....

comment:15 Changed 10 years ago by faide

added the config option in the default template: r6328

Please review the comments and rephrase if you think the explanations are not correct, because being the one who coded the stuff I don't see the thing as someone reading the comment for the first time and trying to figure what the option does.

If this is correct we'll close that issue and open a less urgent ticket to try and optimize the cache (we could easily shave some cycles...)

comment:16 Changed 10 years ago by faide

  • Component changed from TurboGears to Documentation

putting this ticket in the documentation component so that it can be found during next Doc sprint...

comment:17 Changed 10 years ago by mramm

  • Milestone changed from 2.0b6 to 2.0 RC 1

comment:18 Changed 10 years ago by faide

The attached optimization gives (on my machine in my tests) 1,6 % more speed for dotted names support with Mako (and certainly with others because it is an optimization for name lookups)

I did my test with "ab -n 10000 -c 1 ..." with and without the patch and I did the measures multiple times to make sure the measured made sense, shutting down the paste server between each measure.

1,6 % can be seen as not so much... or a lot depending on the POV.

comment:19 Changed 10 years ago by faide

For a reason I cannot explain my patch (in -u format) is not displayed correcly by trac, please click on the download original format link if you want to read it.

Changed 10 years ago by faide

A new patch for optimization with test_stack passing ... :)

comment:20 Changed 10 years ago by faide

I just changed my patch to fix the test_stack so that it passes all the tests :)

comment:21 Changed 10 years ago by mramm

  • Status changed from assigned to closed
  • Resolution set to fixed
  • Milestone changed from 2.0rc1 to 2.0b6
Note: See TracTickets for help on using tickets.