doc/book/en/development/profiling/index.rst
author Nicolas Chauvat <nicolas.chauvat@logilab.fr>
Tue, 28 Jul 2009 23:48:19 +0200
changeset 2544 282261b26774
parent 2539 0f26a76b0348
child 2546 df456fa1b053
permissions -rw-r--r--
[doc] fixed some dangling internal links
Ignore whitespace changes - Everywhere: Within whitespace: At end of lines:
2536
88595be9087d [doc] #306434: say a word about optimization
Nicolas Chauvat <nicolas.chauvat@logilab.fr>
parents:
diff changeset
     1
Profiling and performance
88595be9087d [doc] #306434: say a word about optimization
Nicolas Chauvat <nicolas.chauvat@logilab.fr>
parents:
diff changeset
     2
=========================
88595be9087d [doc] #306434: say a word about optimization
Nicolas Chauvat <nicolas.chauvat@logilab.fr>
parents:
diff changeset
     3
88595be9087d [doc] #306434: say a word about optimization
Nicolas Chauvat <nicolas.chauvat@logilab.fr>
parents:
diff changeset
     4
If you feel that one of your pages takes more time than it should to be
88595be9087d [doc] #306434: say a word about optimization
Nicolas Chauvat <nicolas.chauvat@logilab.fr>
parents:
diff changeset
     5
generated, chances are that you're making too many RQL queries.  Obviously,
88595be9087d [doc] #306434: say a word about optimization
Nicolas Chauvat <nicolas.chauvat@logilab.fr>
parents:
diff changeset
     6
there are other reasons but experience tends to show this is the first thing to
88595be9087d [doc] #306434: say a word about optimization
Nicolas Chauvat <nicolas.chauvat@logilab.fr>
parents:
diff changeset
     7
track down. Luckily, CubicWeb provides a configuration option to log RQL
88595be9087d [doc] #306434: say a word about optimization
Nicolas Chauvat <nicolas.chauvat@logilab.fr>
parents:
diff changeset
     8
queries. In your ``all-in-one.conf`` file, set the **query-log-file** option::
88595be9087d [doc] #306434: say a word about optimization
Nicolas Chauvat <nicolas.chauvat@logilab.fr>
parents:
diff changeset
     9
88595be9087d [doc] #306434: say a word about optimization
Nicolas Chauvat <nicolas.chauvat@logilab.fr>
parents:
diff changeset
    10
    # web application query log file
88595be9087d [doc] #306434: say a word about optimization
Nicolas Chauvat <nicolas.chauvat@logilab.fr>
parents:
diff changeset
    11
    query-log-file=~/myapp-rql.log
88595be9087d [doc] #306434: say a word about optimization
Nicolas Chauvat <nicolas.chauvat@logilab.fr>
parents:
diff changeset
    12
88595be9087d [doc] #306434: say a word about optimization
Nicolas Chauvat <nicolas.chauvat@logilab.fr>
parents:
diff changeset
    13
Then restart your application, reload your page and stop your application.
88595be9087d [doc] #306434: say a word about optimization
Nicolas Chauvat <nicolas.chauvat@logilab.fr>
parents:
diff changeset
    14
The file ``myapp-rql.log`` now contains the list of RQL queries that were
88595be9087d [doc] #306434: say a word about optimization
Nicolas Chauvat <nicolas.chauvat@logilab.fr>
parents:
diff changeset
    15
executed during your test. It's a simple text file containing lines such as::
88595be9087d [doc] #306434: say a word about optimization
Nicolas Chauvat <nicolas.chauvat@logilab.fr>
parents:
diff changeset
    16
88595be9087d [doc] #306434: say a word about optimization
Nicolas Chauvat <nicolas.chauvat@logilab.fr>
parents:
diff changeset
    17
    Any A WHERE X eid %(x)s, X lastname A {'x': 448} -- (0.002 sec, 0.010 CPU sec)
88595be9087d [doc] #306434: say a word about optimization
Nicolas Chauvat <nicolas.chauvat@logilab.fr>
parents:
diff changeset
    18
    Any A WHERE X eid %(x)s, X firstname A {'x': 447} -- (0.002 sec, 0.000 CPU sec)
88595be9087d [doc] #306434: say a word about optimization
Nicolas Chauvat <nicolas.chauvat@logilab.fr>
parents:
diff changeset
    19
88595be9087d [doc] #306434: say a word about optimization
Nicolas Chauvat <nicolas.chauvat@logilab.fr>
parents:
diff changeset
    20
The structure of each line is::
88595be9087d [doc] #306434: say a word about optimization
Nicolas Chauvat <nicolas.chauvat@logilab.fr>
parents:
diff changeset
    21
88595be9087d [doc] #306434: say a word about optimization
Nicolas Chauvat <nicolas.chauvat@logilab.fr>
parents:
diff changeset
    22
    <RQL QUERY> <QUERY ARGS IF ANY> -- <TIME SPENT>
88595be9087d [doc] #306434: say a word about optimization
Nicolas Chauvat <nicolas.chauvat@logilab.fr>
parents:
diff changeset
    23
88595be9087d [doc] #306434: say a word about optimization
Nicolas Chauvat <nicolas.chauvat@logilab.fr>
parents:
diff changeset
    24
CubicWeb also provides the **exlog** command to examine and summarize data found
2544
282261b26774 [doc] fixed some dangling internal links
Nicolas Chauvat <nicolas.chauvat@logilab.fr>
parents: 2539
diff changeset
    25
in such a file:
282261b26774 [doc] fixed some dangling internal links
Nicolas Chauvat <nicolas.chauvat@logilab.fr>
parents: 2539
diff changeset
    26
::
2536
88595be9087d [doc] #306434: say a word about optimization
Nicolas Chauvat <nicolas.chauvat@logilab.fr>
parents:
diff changeset
    27
    $ cubicweb-ctl exlog < ~/myapp-rql.log
88595be9087d [doc] #306434: say a word about optimization
Nicolas Chauvat <nicolas.chauvat@logilab.fr>
parents:
diff changeset
    28
    0.07 50 Any A WHERE X eid %(x)s, X firstname A {}
88595be9087d [doc] #306434: say a word about optimization
Nicolas Chauvat <nicolas.chauvat@logilab.fr>
parents:
diff changeset
    29
    0.05 50 Any A WHERE X eid %(x)s, X lastname A {}
88595be9087d [doc] #306434: say a word about optimization
Nicolas Chauvat <nicolas.chauvat@logilab.fr>
parents:
diff changeset
    30
    0.01 1 Any X,AA ORDERBY AA DESC WHERE E eid %(x)s, E employees X, X modification_date AA {}
88595be9087d [doc] #306434: say a word about optimization
Nicolas Chauvat <nicolas.chauvat@logilab.fr>
parents:
diff changeset
    31
    0.01 1 Any X WHERE X eid %(x)s, X owned_by U, U eid %(u)s {, }
88595be9087d [doc] #306434: say a word about optimization
Nicolas Chauvat <nicolas.chauvat@logilab.fr>
parents:
diff changeset
    32
    0.01 1 Any B,T,P ORDERBY lower(T) WHERE B is Bookmark,B title T, B path P, B bookmarked_by U, U eid %(x)s {}
88595be9087d [doc] #306434: say a word about optimization
Nicolas Chauvat <nicolas.chauvat@logilab.fr>
parents:
diff changeset
    33
    0.01 1 Any A,B,C,D WHERE A eid %(x)s,A name B,A creation_date C,A modification_date D {}
88595be9087d [doc] #306434: say a word about optimization
Nicolas Chauvat <nicolas.chauvat@logilab.fr>
parents:
diff changeset
    34
88595be9087d [doc] #306434: say a word about optimization
Nicolas Chauvat <nicolas.chauvat@logilab.fr>
parents:
diff changeset
    35
This command sorts and uniquifies queries so that it's easy to see where
88595be9087d [doc] #306434: say a word about optimization
Nicolas Chauvat <nicolas.chauvat@logilab.fr>
parents:
diff changeset
    36
is the hot spot that needs optimization.
88595be9087d [doc] #306434: say a word about optimization
Nicolas Chauvat <nicolas.chauvat@logilab.fr>
parents:
diff changeset
    37
88595be9087d [doc] #306434: say a word about optimization
Nicolas Chauvat <nicolas.chauvat@logilab.fr>
parents:
diff changeset
    38
Having said all this, it would probably be worth talking about the **fetch_attrs** attribute
88595be9087d [doc] #306434: say a word about optimization
Nicolas Chauvat <nicolas.chauvat@logilab.fr>
parents:
diff changeset
    39
you can define in your entity classes because it can greatly reduce the
88595be9087d [doc] #306434: say a word about optimization
Nicolas Chauvat <nicolas.chauvat@logilab.fr>
parents:
diff changeset
    40
number of queries executed. XXX say more about it XXX
88595be9087d [doc] #306434: say a word about optimization
Nicolas Chauvat <nicolas.chauvat@logilab.fr>
parents:
diff changeset
    41
88595be9087d [doc] #306434: say a word about optimization
Nicolas Chauvat <nicolas.chauvat@logilab.fr>
parents:
diff changeset
    42
You should also know about the **profile** option in the ``all-in-on.conf``. If
88595be9087d [doc] #306434: say a word about optimization
Nicolas Chauvat <nicolas.chauvat@logilab.fr>
parents:
diff changeset
    43
set, this option will make your application run in an `hotshot`_ session and
88595be9087d [doc] #306434: say a word about optimization
Nicolas Chauvat <nicolas.chauvat@logilab.fr>
parents:
diff changeset
    44
store the results in the specified file.
88595be9087d [doc] #306434: say a word about optimization
Nicolas Chauvat <nicolas.chauvat@logilab.fr>
parents:
diff changeset
    45
88595be9087d [doc] #306434: say a word about optimization
Nicolas Chauvat <nicolas.chauvat@logilab.fr>
parents:
diff changeset
    46
.. _hotshot: http://docs.python.org/library/hotshot.html#module-hotshot
88595be9087d [doc] #306434: say a word about optimization
Nicolas Chauvat <nicolas.chauvat@logilab.fr>
parents:
diff changeset
    47
88595be9087d [doc] #306434: say a word about optimization
Nicolas Chauvat <nicolas.chauvat@logilab.fr>
parents:
diff changeset
    48
Last but no least, if you're using the PostgreSQL database backend, VACUUMing
88595be9087d [doc] #306434: say a word about optimization
Nicolas Chauvat <nicolas.chauvat@logilab.fr>
parents:
diff changeset
    49
your database can significantly improve the performance of the queries (by
88595be9087d [doc] #306434: say a word about optimization
Nicolas Chauvat <nicolas.chauvat@logilab.fr>
parents:
diff changeset
    50
updating the statistics used by the query optimizer). Nowadays, this is done
88595be9087d [doc] #306434: say a word about optimization
Nicolas Chauvat <nicolas.chauvat@logilab.fr>
parents:
diff changeset
    51
automatically from time to time, but if you've just imported a large amount of
88595be9087d [doc] #306434: say a word about optimization
Nicolas Chauvat <nicolas.chauvat@logilab.fr>
parents:
diff changeset
    52
data in your db, you will want to vacuum it (with the analyse option on). Read
88595be9087d [doc] #306434: say a word about optimization
Nicolas Chauvat <nicolas.chauvat@logilab.fr>
parents:
diff changeset
    53
the documentation of your database for more information.