doc/book/devrepo/profiling.rst
author Denis Laxalde <denis.laxalde@logilab.fr>
Mon, 06 Mar 2017 14:19:20 +0100
changeset 12008 7694dcf5ad30
parent 10491 c67bcee93248
permissions -rw-r--r--
[etwist] Do not call repository's start_looping_tasks anymore and warn about this We are about to drop this method from Repository class and replace it by a blocking alternative. This is not compatible with how things currently work in a Twisted server implementation. So do not start repository "looping tasks" in Twisted server anymore and issue a warning about this. If someone is interested in restoring the "all-in-one" behavior where the repository runs within a Twisted server, they may start by implementing repository looping tasks using a Twisted mechanism such as, e.g., http://twistedmatrix.com/documents/current/core/howto/time.html and eventually provide the repository with a compatible scheduler instance so that is can register its periodic tasks. At the moment, we lack resources to do this (and maintain the Twisted server of CubicWeb in general). Related to #17057223.
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
9739
5efd4a1abc66 [book] avoid '~' in all-in-one.conf, it is not expanded
Julien Cristau <julien.cristau@logilab.fr>
parents: 5924
diff changeset
    13
    query-log-file=/home/user/myapp-rql.log
2536
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
9739
5efd4a1abc66 [book] avoid '~' in all-in-one.conf, it is not expanded
Julien Cristau <julien.cristau@logilab.fr>
parents: 5924
diff changeset
    31
    $ cubicweb-ctl exlog /home/user/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.