doc/book/en/devrepo/profiling.rst
author Sylvain Thénault <sylvain.thenault@logilab.fr>
Tue, 28 Jun 2011 17:59:31 +0200
changeset 7570 648bf83945a5
parent 5924 b218df942dd4
child 9739 5efd4a1abc66
permissions -rw-r--r--
[etwist] log missing file even in debug mode
Ignore whitespace changes - Everywhere: Within whitespace: At end of lines:
5924
b218df942dd4 [book] update rql documentation and some erroneous/deprecated examples
Julien Jehannet <julien.jehannet@logilab.fr>
parents: 5755
diff changeset
     1
.. _PROFILING:
b218df942dd4 [book] update rql documentation and some erroneous/deprecated examples
Julien Jehannet <julien.jehannet@logilab.fr>
parents: 5755
diff changeset
     2
2536
88595be9087d [doc] #306434: say a word about optimization
Nicolas Chauvat <nicolas.chauvat@logilab.fr>
parents:
diff changeset
     3
Profiling and performance
88595be9087d [doc] #306434: say a word about optimization
Nicolas Chauvat <nicolas.chauvat@logilab.fr>
parents:
diff changeset
     4
=========================
88595be9087d [doc] #306434: say a word about optimization
Nicolas Chauvat <nicolas.chauvat@logilab.fr>
parents:
diff changeset
     5
88595be9087d [doc] #306434: say a word about optimization
Nicolas Chauvat <nicolas.chauvat@logilab.fr>
parents:
diff changeset
     6
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
     7
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
     8
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
     9
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
    10
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
    11
88595be9087d [doc] #306434: say a word about optimization
Nicolas Chauvat <nicolas.chauvat@logilab.fr>
parents:
diff changeset
    12
    # web application query log file
88595be9087d [doc] #306434: say a word about optimization
Nicolas Chauvat <nicolas.chauvat@logilab.fr>
parents:
diff changeset
    13
    query-log-file=~/myapp-rql.log
88595be9087d [doc] #306434: say a word about optimization
Nicolas Chauvat <nicolas.chauvat@logilab.fr>
parents:
diff changeset
    14
88595be9087d [doc] #306434: say a word about optimization
Nicolas Chauvat <nicolas.chauvat@logilab.fr>
parents:
diff changeset
    15
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
    16
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
    17
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
    18
88595be9087d [doc] #306434: say a word about optimization
Nicolas Chauvat <nicolas.chauvat@logilab.fr>
parents:
diff changeset
    19
    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
    20
    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
    21
88595be9087d [doc] #306434: say a word about optimization
Nicolas Chauvat <nicolas.chauvat@logilab.fr>
parents:
diff changeset
    22
The structure of each line is::
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
    <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
    25
88595be9087d [doc] #306434: say a word about optimization
Nicolas Chauvat <nicolas.chauvat@logilab.fr>
parents:
diff changeset
    26
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
    27
in such a file:
2546
df456fa1b053 [doc] more improvements
Nicolas Chauvat <nicolas.chauvat@logilab.fr>
parents: 2544
diff changeset
    28
df456fa1b053 [doc] more improvements
Nicolas Chauvat <nicolas.chauvat@logilab.fr>
parents: 2544
diff changeset
    29
.. sourcecode:: sh
df456fa1b053 [doc] more improvements
Nicolas Chauvat <nicolas.chauvat@logilab.fr>
parents: 2544
diff changeset
    30
5755
ca9e1c9123d7 [c-c exlog] fix code and documentation
Stephanie Marcu <stephanie.marcu@logilab.fr>
parents: 5394
diff changeset
    31
    $ cubicweb-ctl exlog ~/myapp-rql.log
2536
88595be9087d [doc] #306434: say a word about optimization
Nicolas Chauvat <nicolas.chauvat@logilab.fr>
parents:
diff changeset
    32
    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
    33
    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
    34
    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
    35
    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
    36
    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
    37
    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
    38
88595be9087d [doc] #306434: say a word about optimization
Nicolas Chauvat <nicolas.chauvat@logilab.fr>
parents:
diff changeset
    39
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
    40
is the hot spot that needs optimization.
88595be9087d [doc] #306434: say a word about optimization
Nicolas Chauvat <nicolas.chauvat@logilab.fr>
parents:
diff changeset
    41
2546
df456fa1b053 [doc] more improvements
Nicolas Chauvat <nicolas.chauvat@logilab.fr>
parents: 2544
diff changeset
    42
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
    43
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
    44
:ref:`FetchAttrs`).
2536
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
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
    47
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
    48
store the results in the specified file.
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
.. _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
    51
88595be9087d [doc] #306434: say a word about optimization
Nicolas Chauvat <nicolas.chauvat@logilab.fr>
parents:
diff changeset
    52
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
    53
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
    54
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
    55
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
    56
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
    57
the documentation of your database for more information.