doc/book/en/development/profiling.rst
author Aurelien Campeas <aurelien.campeas@logilab.fr>
Thu, 08 Apr 2010 17:50:37 +0200
branchstable
changeset 5189 84d4587a92bc
parent 5150 7a9e71ee5671
permissions -rw-r--r--
[doc/book] rql/dbapi cleanup, rip cachekey (prematurely ?)
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:
2546
df456fa1b053 [doc] more improvements
Nicolas Chauvat <nicolas.chauvat@logilab.fr>
parents: 2544
diff changeset
    26
df456fa1b053 [doc] more improvements
Nicolas Chauvat <nicolas.chauvat@logilab.fr>
parents: 2544
diff changeset
    27
.. sourcecode:: sh
df456fa1b053 [doc] more improvements
Nicolas Chauvat <nicolas.chauvat@logilab.fr>
parents: 2544
diff changeset
    28
2536
88595be9087d [doc] #306434: say a word about optimization
Nicolas Chauvat <nicolas.chauvat@logilab.fr>
parents:
diff changeset
    29
    $ cubicweb-ctl exlog < ~/myapp-rql.log
88595be9087d [doc] #306434: say a word about optimization
Nicolas Chauvat <nicolas.chauvat@logilab.fr>
parents:
diff changeset
    30
    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
    31
    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
    32
    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
    33
    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
    34
    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
    35
    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
    36
88595be9087d [doc] #306434: say a word about optimization
Nicolas Chauvat <nicolas.chauvat@logilab.fr>
parents:
diff changeset
    37
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
    38
is the hot spot that needs optimization.
88595be9087d [doc] #306434: say a word about optimization
Nicolas Chauvat <nicolas.chauvat@logilab.fr>
parents:
diff changeset
    39
2546
df456fa1b053 [doc] more improvements
Nicolas Chauvat <nicolas.chauvat@logilab.fr>
parents: 2544
diff changeset
    40
Do not neglect to set the **fetch_attrs** attribute you can define in your
df456fa1b053 [doc] more improvements
Nicolas Chauvat <nicolas.chauvat@logilab.fr>
parents: 2544
diff changeset
    41
entity classes because it can greatly reduce the number of queries executed (see
df456fa1b053 [doc] more improvements
Nicolas Chauvat <nicolas.chauvat@logilab.fr>
parents: 2544
diff changeset
    42
:ref:`FetchAttrs`).
2536
88595be9087d [doc] #306434: say a word about optimization
Nicolas Chauvat <nicolas.chauvat@logilab.fr>
parents:
diff changeset
    43
88595be9087d [doc] #306434: say a word about optimization
Nicolas Chauvat <nicolas.chauvat@logilab.fr>
parents:
diff changeset
    44
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
    45
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
    46
store the results in the specified file.
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
.. _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
    49
88595be9087d [doc] #306434: say a word about optimization
Nicolas Chauvat <nicolas.chauvat@logilab.fr>
parents:
diff changeset
    50
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
    51
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
    52
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
    53
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
    54
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
    55
the documentation of your database for more information.