Flask Mega-Tutorial, Part 16: Debugging, Testing and Profiling

This is the sixteenth article in the series, where I describe my experience of writing a Python web application using the Flask mic framework.

The purpose of this guide is to develop a fairly functional microblog application, which I decided to call microblog, in the absence of originality.



Our humble application is starting to show signs of release readiness, so it's time to put it in order as much as possible. Not so long ago, one of the readers of this blog (hello, George!) Reported a strange database behavior, which we will try to debug today. This should help us realize that no matter how carefully we wrote the code and how often we tested it, some errors sometimes go unnoticed. Unfortunately, they are usually detected by the end users.
')
Instead of simply correcting this error and waiting for the next one to be discovered, we will take some preventive measures to be ready to detect possible errors.

In the first part of this article, we will look at debugging and I will show you some of the techniques and techniques that I use to debug complex problems.

Later, we will see how we can evaluate the effectiveness of our testing strategy. We measure what part of our code our unit tests cover, this is what is called test coverage .

And finally, we will reflect on another class of problems that many applications often encounter — the lack of performance. We will look at the profiling techniques to find the slow parts of our application.

Sounds good? Then let's get started.

Mistake

The problem was discovered by the reader of this blog, after he implemented a new feature that allows users to delete their posts. The official version of microblog does not include this function, so we will implement it quickly so that we can debug it.
View function that removes posts (file app / views.py):

@app.route('/delete/<int:id>') @login_required def delete(id): post = Post.query.get(id) if post == None: flash('Post not found.') return redirect(url_for('index')) if post.author.id != g.user.id: flash('You cannot delete this post.') return redirect(url_for('index')) db.session.delete(post) db.session.commit() flash('Your post has been deleted.') return redirect(url_for('index')) 

To enable this feature, we will add a delete link to all posts owned by the current user (file app / templates / post.html):

 {% if post.author.id == g.user.id %} <div><a href="{{ url_for('delete', id = post.id) }}">{{ _('Delete') }}</a></div> {% endif %} 

There is nothing new for us, we have done this many times before.

Let's move on and run our application with debug mode turned off (debug = False) to view it with the user's eyes.
Linux and Mac users, run in the console:

 $ ./runp.py 

Windows users, run this command in a command shell:

 flask/Scripts/python runp.py 

Now, as a user, create a post, and then try to delete it. And as soon as you click on the delete link ... Wham!

We received a brief message that some error occurred and the administrator will be notified about it. In fact, this message is our 500.html template. With debug mode disabled, Flask returns this pattern to all errors that occurred during the processing of a request. Since we are in "production" mode, we will not see either the real error message or the call stack.

Debugging problems "in the field"

If you remember the article on unit testing, we activated several debugging services to run in the production version of our application. Then we created a logger that writes errors and diagnostic messages to the log file while the application is running. Flask itself records the stack of calls for any incident and not processed, until the request is completed, an exception. In addition, we have configured a logger that sends all members of the list of administrators emails when writing errors to the log.

So, in the event of an error like what happened above, we will have some information about its nature in two places at once: in the log file and in the email.

The contents of the call stack may not be enough to correct the error, but this is in any case better than nothing. Suppose we know nothing about an existing problem. And now we need to determine what happened, based only on the printout of the call stack. Here is the call stack:

 127.0.0.1 - - [03/Mar/2013 23:57:39] "GET /delete/12 HTTP/1.1" 500 - Traceback (most recent call last): File "/home/microblog/flask/lib/python2.7/site-packages/flask/app.py", line 1701, in __call__ return self.wsgi_app(environ, start_response) File "/home/microblog/flask/lib/python2.7/site-packages/flask/app.py", line 1689, in wsgi_app response = self.make_response(self.handle_exception(e)) File "/home/microblog/flask/lib/python2.7/site-packages/flask/app.py", line 1687, in wsgi_app response = self.full_dispatch_request() File "/home/microblog/flask/lib/python2.7/site-packages/flask/app.py", line 1360, in full_dispatch_request rv = self.handle_user_exception(e) File "/home/microblog/flask/lib/python2.7/site-packages/flask/app.py", line 1358, in full_dispatch_request rv = self.dispatch_request() File "/home/microblog/flask/lib/python2.7/site-packages/flask/app.py", line 1344, in dispatch_request return self.view_functions[rule.endpoint](**req.view_args) File "/home/microblog/flask/lib/python2.7/site-packages/flask_login.py", line 496, in decorated_view return fn(*args, **kwargs) File "/home/microblog/app/views.py", line 195, in delete db.session.delete(post) File "/home/microblog/flask/lib/python2.7/site-packages/sqlalchemy/orm/scoping.py", line 114, in do return getattr(self.registry(), name)(*args, **kwargs) File "/home/microblog/flask/lib/python2.7/site-packages/sqlalchemy/orm/session.py", line 1400, in delete self._attach(state) File "/home/microblog/flask/lib/python2.7/site-packages/sqlalchemy/orm/session.py", line 1656, in _attach state.session_id, self.hash_key)) InvalidRequestError: Object '<Post at 0xff35e7ac>' is already attached to session '1' (this is '3') 

If you have already engaged in reading similar error messages when using other programming languages, then keep in mind that Python shows the call stack in reverse order, that is, the frame that caused the error is at the bottom.

How are we going to figure this out now?

Judging by the printout of the call stack, the exception was thrown by the SQLAlchemy session processing code in the sqlalchemy / orm / session.py file.

When working with a call stack, it is always helpful to find the last expression executed from our own code. If we start at the bottom and gradually, frame by frame, go up the track, we find the fourth frame in our app / views.py file, or rather, in the expression db.session.delete (post) of our view function delete ().

Now we know that SQLAlchemy cannot delete this post in the current database session. But we still do not know why.

If you look at the text of the exception at the very bottom, it seems that the problem is that the Post object belongs to session "1", and we are trying to attach the same object to another session "3".

If you ask Google for help, you will find that most of these problems occur when using multi-threaded web servers that perform two requests trying to attach an object to two different sessions at the same time. But we are using a single-threaded Python debug server, so this is not our case. So there is some other problem that creates two active sessions instead of one.

To learn more about the problem, we must try to repeat the mistake in a more controlled environment. Fortunately, this error manifests itself in the “development” version of our application, which is somewhat better, since it gives us access to the web version of the call stack provided by Flask itself instead of the 500.html template.

The web version of the call stack is noteworthy in that it allows us to see the code and immediately look at the result of the expressions and all this right from the browser. Not having a sufficiently deep understanding of what is happening in the code, we guess that there is a session '1' (we can only assume that this is the very first session created) which, for some reason, was not deleted like any normal session when the request that created this session. So, to move forward in solving a problem, it would be nice to know who is creating this unclosed session.

Using the Python Debugger

The easiest way to find out who creates an object is to set a breakpoint in the object's constructor. A breakpoint is a command that suspends program execution when a certain condition is met. And then at this point there is an opportunity to explore the program, view the call stack at this particular point of execution, view and even change the contents of variables, etc. Breakpoints are one of the basic features of debuggers . This time we use the debugger that comes with the Python interpreter, called pdb.

But what class are we looking for? Let's go back to the web version of the track and look around. At the bottom of each frame of the route there are links to the code viewer and to the Python console (the icons are located on the right and become visible when you hover the mouse over the frame) with which we can find the class that uses the session. In the code panel, we see that we are inside the Session class, which, apparently, is the base class for SQLAlchemy database sessions. Since the context of the lower frame stack is inside the session object, we can get the actual session class in the console:

 >>> print self <flask_sqlalchemy._SignallingSession object at 0xff34914c> 

Now we know that the sessions we use are defined in Flask-SQLAlchemy, because it looks like this extension defines its own session class, which inherits the SQLAlchemy Session class.

Now we can explore the source code for the Flask-SQLAlchemy extension located in the flask / lib / python2.7 / site-packages / flask_sqlalchemy.py file and find the __init __ () constructor of the _SignallingSession class. Now we are fully ready to debug.

There are several ways to set a breakpoint in a python application. The simplest is to add the following code in the place where we want to stop the program:

 import pdb; pdb.set_trace() 

Which we will do by temporarily adding a breakpoint to the _SignallingSession class constructor (flask / lib / python2.7 / site-packages / flask_sqlalchemy.py):

 class _SignallingSession(Session): def __init__(self, db, autocommit=False, autoflush=False, **options): import pdb; pdb.set_trace() # <-- this is temporary! self.app = db.get_app() self._model_changes = {} Session.__init__(self, autocommit=autocommit, autoflush=autoflush, extension=db.session_extensions, bind=db.engine, binds=db.get_binds(self.app), **options) # ... 

Now let's run the application again and see what happens:

 $ ./run.py > /home/microblog/flask/lib/python2.7/site-packages/flask_sqlalchemy.py(198)__init__() -> self.app = db.get_app() (Pdb) 

Since the message “Running on ...” did not appear, we understand that the server did not start up to the end. The execution of the program was interrupted, because in some part of the code someone requested the creation of our "mysterious" session!

The most important question we must answer immediately is where we are now in the application, since this should tell us who requested the creation of the very session '1' which we can’t get rid of later in the course of the program. We use the bt command (abbreviation for backtrace) to get the contents of the call stack:

 (Pdb) bt /home/microblog/run.py(2)<module>() -> from app import app /home/microblog/app/__init__.py(44)<module>() -> from app import views, models /home/microblog/app/views.py(6)<module>() -> from forms import LoginForm, EditForm, PostForm, SearchForm /home/microblog/app/forms.py(4)<module>() -> from app.models import User /home/microblog/app/models.py(92)<module>() -> whooshalchemy.whoosh_index(app, Post) /home/microblog/flask/lib/python2.6/site-packages/flask_whooshalchemy.py(168)whoosh_index() -> _create_index(app, model)) /home/microblog/flask/lib/python2.6/site-packages/flask_whooshalchemy.py(199)_create_index() -> model.query = _QueryProxy(model.query, primary_key, /home/microblog/flask/lib/python2.6/site-packages/flask_sqlalchemy.py(397)__get__() -> return type.query_class(mapper, session=self.sa.session()) /home/microblog/flask/lib/python2.6/site-packages/sqlalchemy/orm/scoping.py(54)__call__() -> return self.registry() /home/microblog/flask/lib/python2.6/site-packages/sqlalchemy/util/_collections.py(852)__call__() -> return self.registry.setdefault(key, self.createfunc()) > /home/microblog/flask/lib/python2.6/site-packages/flask_sqlalchemy.py(198)__init__() -> self.app = db.get_app() (Pdb) 

As before, we start from the bottom and move upwards in search of our code. And this turns out to be line 92 in our models.py models file, in which our full-text search is initialized:

 whooshalchemy.whoosh_index(app, Post) 

Strange. We are not creating a database session and are not doing anything that should create this session, but it seems that the initialization of Flask-WhooshAlchemy itself creates a session.

It seems that this is not our mistake, but rather some kind of conflict between the wrapper extensions for SQLAlchemy and Whoosh. We could stop here and just ask for help from the developers of these two great extensions or from their communities. Or we can continue debugging and see if we can solve the problem here and now. So, I will continue debugging, and you, if you are not interested, can freely proceed to the next section.

Let's take another look at the call stack. We call call whoosh_index (), which, in turn, calls _create_index (). The specific _create_index () line looks like this:

 model.query = _QueryProxy(model.query, primary_key, searcher, model) 

The model variable in this context represents our Post class, and we pass it as an argument to the whoosh_index () function. Given this, it appears that Flask-WhooshAlchemy creates a Post.query wrapper that accepts the original Post.query as an argument, plus some Whoosh-specific content. But this is already interesting. Judging by the route presented above, the next function in the queue is __get __ (), one of the methods-descriptors of the python language.

The __get __ () method is used to implement descriptors that are attributes that have a specific behavior besides the value. Each time a descriptor is mentioned, the function __get __ () is called. Then the function should return the value of the attribute. The only attribute mentioned in this line of code is query, so now we know that the seemingly simple attribute that we previously used to generate queries to the database is actually a descriptor and not an attribute. The remainder of the call stack is responsible for calculating the value of the model.query expression, preparing to create the constructor for the _QueryProxy object.

Now let's go down the stack a little lower to see what happens next. The instruction from the __get __ () method is presented below:

return type.query_class (mapper, session = self.sa.session ())

And this is a pretty curious piece of code. When we call, for example, User.query.get (id), we indirectly call the __get __ () method to get the request object, and with it we get the session!

When Flask-WhooshAlchemy executes model.query, a session is created and bound to the request object. But the request object requested by Flask-WhooshAlchemy is not as short-lived as the ones we run inside our presentation functions. Flask-WhooshAlchemy wraps this request object in its own request object, which is saved back to model.query. Since The __set __ () method does not exist, the new object is saved as an attribute. For our Post class, this means that after the completion of the Flask-WhooshAlchemy initialization, we will have a descriptor and an attribute with the same name. In accordance with the priority, in this case the attribute wins, which is quite expected, because if this were not the case, our search for Whoosh would not work.

An important detail of this is that the above code establishes a permanent attribute that contains the session '1' inside the session. Even in spite of the fact that the first request processed by the application uses this session and forgets about it immediately upon completion, the session itself is not going anywhere since the Post.query attribute continues to refer to it. This is the very mistake!
This error is caused by the confusing (in my opinion) nature of the descriptors. They look like ordinary attributes and people use them. The developer of Flask-WhooshAlchemy just wanted to create an extended request object to store some useful information to fulfill its requests, but did not fully realize that using the attribute of the query model does a little more than it seems because it has hidden session opening behavior. with a database.

Regression tests

For many, most likely, the most logical step in this situation seems to correct the error Flask-WhooshAlchemy and move on. But if we do that, which guarantees us the absence of such an error in the future? For example, what happens if in a year we decide to update Flask-WhooshAlchemy to the new version and forget about our editing?

The best way to detect any error is to create a unit test for it in order to prevent the occurrence of an error (the so-called regression ) in the future.

However, there is some difficulty in creating a test for this error, since we have to emulate two queries inside one test. The first request will refer to the Post object, emulating the request we make to display data on the page. And since this is the first request, it will use the session '1'. Then we have to forget this session and create a new one exactly as Flask-SQLAlchemy does. Attempting to delete the Post object in the second session should raise this error again, since the first session is not over as expected.

Looking back at the Flask-SQLAlchemy source code again, we see that new sessions are created with the db.create_scoped_session () function, and after the request is completed, the session is destroyed by calling the db.session.remove () function. Knowing this, it is quite simple to write a test for this error:

 def test_delete_post(self): # create a user and a post u = User(nickname = 'john', email = 'john@example.com') p = Post(body = 'test post', author = u, timestamp = datetime.utcnow()) db.session.add(u) db.session.add(p) db.session.commit() # query the post and destroy the session p = Post.query.get(1) db.session.remove() # delete the post using a new session db.session = db.create_scoped_session() db.session.delete(p) db.session.commit() 

And, of course, when running the tests, we will receive a message about the failed test:

 $ ./tests.py .E.... ====================================================================== ERROR: test_delete_post (__main__.TestCase) ---------------------------------------------------------------------- Traceback (most recent call last): File "./tests.py", line 133, in test_delete_post db.session.delete(p) File "/home/microblog/flask/lib/python2.7/site-packages/sqlalchemy/orm/scoping.py", line 114, in do return getattr(self.registry(), name)(*args, **kwargs) File "/home/microblog/flask/lib/python2.7/site-packages/sqlalchemy/orm/session.py", line 1400, in delete self._attach(state) File "/home/microblog/flask/lib/python2.7/site-packages/sqlalchemy/orm/session.py", line 1656, in _attach state.session_id, self.hash_key)) InvalidRequestError: Object '<Post at 0xff09b7ac>' is already attached to session '1' (this is '3') ---------------------------------------------------------------------- Ran 6 tests in 3.852s FAILED (errors=1) 

Correction

To solve this problem, we must find an alternative way to bind the Flask-WhooshAlchemy query object to the model.

The Flask-SQLAlchemy documentation mentions the model.query_class attribute, which contains the class used to execute queries. In fact, this is a much more transparent and straightforward way to force Flask-SQLAlchemy to use a modified query class than the Flask-WhooshAlchemy used. If we set up Flask-SQLAlchemy to create queries using the Whoosh query class (which inherits the BaseQuery class from Flask-SQLAlchemy), then the result does not change, but the error disappears.

I created a fork of the Flask-WhooshAlchemy project on github where I implemented these changes. If you want to review the changes, you can look at my commit's github diff , or you can download the whole of the fixed extension and replace it with the original flask_whooshalchemy.py file.

I sent the changes I made to the developer Flask-WhooshAlchemy, and now I dare to hope that in time they will be included in the official version.

Test coverage

One way to critically reduce the likelihood of an error after deploying our application on a server is dense test coverage. We already have a testing framework, but how do we know which part of the application is actually being tested when it is used?

The test coverage measurement tool is able to examine the running application and mark running and non-running lines of code. After the execution is complete, it issues a report showing the lines of code that did not run. Having received such a report for our tests, we would be able to determine exactly which part of our code remained unaffected by the executed tests.

Python has its own test coverage measurement tool, simply named coverage . Let's install it:

 flask/bin/pip install coverage 

You can use this tool from the command line or embed the call directly into the script. In order to accidentally forget to run it, we will choose the last option.

Here are the changes that need to be added to our tests to generate a report (tests.py file):

 from coverage import coverage cov = coverage(branch = True, omit = ['flask/*', 'tests.py']) cov.start() # ... if __name__ == '__main__': try: unittest.main() except: pass cov.stop() cov.save() print "\n\nCoverage Report:\n" cov.report() print "HTML version: " + os.path.join(basedir, "tmp/coverage/index.html") cov.html_report(directory = 'tmp/coverage') cov.erase() 

We start by initializing the coverage module at the beginning of the script. The branch = True parameter indicates the need to analyze the execution branches in addition to the usual line-by-line verification of coverage. The omit parameter is necessary to exclude from the test all third-party modules installed in our virtual environment and the testing framework itself, since we are only interested in analyzing the code of our application.

, cov.start(), unit . , . , coverage cov.stop(), cov.save(). , cov.report() , cov.html_report() HTML , cov.erase() .

(, ):

 $ ./tests.py .....F ====================================================================== FAIL: test_translation (__main__.TestCase) ---------------------------------------------------------------------- Traceback (most recent call last): File "./tests.py", line 143, in test_translation assert microsoft_translate(u'English', 'en', 'es') == u'Inglés' AssertionError ---------------------------------------------------------------------- Ran 6 tests in 3.981s FAILED (failures=1) Coverage Report: Name Stmts Miss Branch BrMiss Cover Missing ------------------------------------------------------------ app/__init__ 39 0 6 3 93% app/decorators 6 2 0 0 67% 5-6 app/emails 14 6 0 0 57% 9, 12-15, 21 app/forms 30 14 8 8 42% 15-16, 19-30 app/models 63 8 10 1 88% 32, 37, 47, 50, 53, 56, 78, 90 app/momentjs 12 5 0 0 58% 5, 8, 11, 14, 17 app/translate 33 24 4 3 27% 10-36, 39-56 app/views 169 124 46 46 21% 16, 20, 24-30, 34-37, 41, 45-46, 53-67, 75-81, 88-109, 113-114, 120-125, 132-143, 149-164, 169-183, 188-198, 203-205, 210-211, 218 config 22 0 0 0 100% ------------------------------------------------------------ TOTAL 388 183 74 61 47% HTML version: /home/microblog/tmp/coverage/index.html 

, 47% . , , , .

, app/models.py (88%), . . . app/views.py (21%) . . .

, Branch BrMiss. :

 def f(x): if x >= 0: x = x + 1 return x f(1) 

coverage , 100% , . . 1, 3 . 0, . , .

, , , .

coverage HTML , .

, , app/models.py . , HTML , :

• User.make_valid_nickname()
• User.is_authenticated()
• User.is_active()
• User.is_anonymous()
• User.get_id()
• User.__repr__()
• Post.__repr__()

User.make_unique_nickname() ( , )

:

 def test_user(self): # make valid nicknames n = User.make_valid_nickname('John_123') assert n == 'John_123' n = User.make_valid_nickname('John_[123]\n') assert n == 'John_123' # create a user u = User(nickname = 'john', email = 'john@example.com') db.session.add(u) db.session.commit() assert u.is_authenticated() == True assert u.is_active() == True assert u.is_anonymous() == False assert u.id == int(u.get_id()) 

__repr__() , . , :

 def __repr__(self): # pragma: no cover return '<User %r>' % (self.nickname) 

, make_unique_nickname() , . :

 def test_make_unique_nickname(self): # create a user and write it to the database u = User(nickname = 'john', email = 'john@example.com') db.session.add(u) db.session.commit() nickname = User.make_unique_nickname('susan') assert nickname == 'susan' nickname = User.make_unique_nickname('john') assert nickname != 'john' #... 

, 100% models.py.

. , - , , , .

. , . , , .

. , coverage, , . , . , .

Python cProfile . , , . «Flask profiler» , Werkzeug, Flask-, , .

Werkzeug, run.py. profile.py:

 #!flask/bin/python from werkzeug.contrib.profiler import ProfilerMiddleware from app import app app.config['PROFILE'] = True app.wsgi_app = ProfilerMiddleware(app.wsgi_app, restrictions = [30]) app.run(debug = True) 

30 ( restrictions ).

, . Here is an example:

 -------------------------------------------------------------------------------- PATH: '/' 95477 function calls (89364 primitive calls) in 0.202 seconds Ordered by: internal time, call count List reduced from 1587 to 30 due to restriction <30> ncalls tottime percall cumtime percall filename:lineno(function) 1 0.061 0.061 0.061 0.061 {method 'commit' of 'sqlite3.Connection' objects} 1 0.013 0.013 0.018 0.018 flask/lib/python2.7/site-packages/sqlalchemy/dialects/sqlite/pysqlite.py:278(dbapi) 16807 0.006 0.000 0.006 0.000 {isinstance} 5053 0.006 0.000 0.012 0.000 flask/lib/python2.7/site-packages/jinja2/nodes.py:163(iter_child_nodes) 8746/8733 0.005 0.000 0.005 0.000 {getattr} 817 0.004 0.000 0.011 0.000 flask/lib/python2.7/site-packages/jinja2/lexer.py:548(tokeniter) 1 0.004 0.004 0.004 0.004 /usr/lib/python2.7/sqlite3/dbapi2.py:24(<module>) 4 0.004 0.001 0.015 0.004 {__import__} 1 0.004 0.004 0.009 0.009 flask/lib/python2.7/site-packages/sqlalchemy/dialects/sqlite/__init__.py:7(<module>) 1808/8 0.003 0.000 0.033 0.004 flask/lib/python2.7/site-packages/jinja2/visitor.py:34(visit) 9013 0.003 0.000 0.005 0.000 flask/lib/python2.7/site-packages/jinja2/nodes.py:147(iter_fields) 2822 0.003 0.000 0.003 0.000 {method 'match' of '_sre.SRE_Pattern' objects} 738 0.003 0.000 0.003 0.000 {method 'split' of 'str' objects} 1808 0.003 0.000 0.006 0.000 flask/lib/python2.7/site-packages/jinja2/visitor.py:26(get_visitor) 2862 0.003 0.000 0.003 0.000 {method 'append' of 'list' objects} 110/106 0.002 0.000 0.008 0.000 flask/lib/python2.7/site-packages/jinja2/parser.py:544(parse_primary) 11 0.002 0.000 0.002 0.000 {posix.stat} 5 0.002 0.000 0.010 0.002 flask/lib/python2.7/site-packages/sqlalchemy/engine/base.py:1549(_execute_clauseelement) 1 0.002 0.002 0.004 0.004 flask/lib/python2.7/site-packages/sqlalchemy/dialects/sqlite/base.py:124(<module>) 1229/36 0.002 0.000 0.008 0.000 flask/lib/python2.7/site-packages/jinja2/nodes.py:183(find_all) 416/4 0.002 0.000 0.006 0.002 flask/lib/python2.7/site-packages/jinja2/visitor.py:58(generic_visit) 101/10 0.002 0.000 0.003 0.000 flask/lib/python2.7/sre_compile.py:32(_compile) 15 0.002 0.000 0.003 0.000 flask/lib/python2.7/site-packages/sqlalchemy/schema.py:1094(_make_proxy) 8 0.002 0.000 0.002 0.000 {method 'execute' of 'sqlite3.Cursor' objects} 1 0.002 0.002 0.002 0.002 flask/lib/python2.7/encodings/base64_codec.py:8(<module>) 2 0.002 0.001 0.002 0.001 {method 'close' of 'sqlite3.Connection' objects} 1 0.001 0.001 0.001 0.001 flask/lib/python2.7/site-packages/sqlalchemy/dialects/sqlite/pysqlite.py:215(<module>) 2 0.001 0.001 0.002 0.001 flask/lib/python2.7/site-packages/wtforms/form.py:162(__call__) 980 0.001 0.000 0.001 0.000 {id} 936/127 0.001 0.000 0.008 0.000 flask/lib/python2.7/site-packages/jinja2/visitor.py:41(generic_visit) -------------------------------------------------------------------------------- 127.0.0.1 - - [09/Mar/2013 19:35:49] "GET / HTTP/1.1" 200 - 

:

• ncalls: .
• tottime: , .
• percall: tottime ncalls.
• cumtime: .
• percall: cumtime ncalls.
• filename:lineno(function): .

, . , Jinja2 Python. , , !

, , . , , sqlite3 Jinja2, . , , 0.2 , .. .

, , .

, . , , ( ) .

Flask-SQLAlchemy get_debug_queries , .

. — , - , , .

, ( config.py):

 SQLALCHEMY_RECORD_QUERIES = True 

, , , «» ( config.py):

 # slow database query threshold (in seconds) DATABASE_QUERY_TIMEOUT = 0.5 

, . Flask , after_request ( app/views.py):

 from flask.ext.sqlalchemy import get_debug_queries from config import DATABASE_QUERY_TIMEOUT @app.after_request def after_request(response): for query in get_debug_queries(): if query.duration >= DATABASE_QUERY_TIMEOUT: app.logger.warning("SLOW QUERY: %s\nParameters: %s\nDuration: %fs\nContext: %s\n" % (query.statement, query.parameters, query.duration, query.context)) return response 

, , . SQL , , , .

, , , , , . , - .

Conclusion

, , . :

microblog-0.16.zip .

GitHub, .

, , . . . , , .
, , .

See you later!

Miguel