doc/book/en/devrepo/profiling.rst
author Yann Voté <yann.vote@logilab.fr>
Fri, 26 Jun 2015 16:09:27 +0200
changeset 10460 d260722f2453
parent 9739 5efd4a1abc66
permissions -rw-r--r--
[dataimport] introduce the importer and extentity classes This introduces the ``ExtEntity`` class which is a transitional state between data at external source and the actual CubicWeb entities. ``ExtEntitiesImporter`` is then in charge to turn a bunch of ext entities into CW entities in repository, using a given store. This changeset also introduces ``SimpleImportLog`` and ``HTMLImportLog`` which implement the CW DataImportLog interface in order to show log messages in UI using simple text and HTML formats respectively, instead of storing these messages in database. Both have mostly been backported from cubes.skos.dataimport. Closes #5414753.
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.