author | Sylvain Thénault <sylvain.thenault@logilab.fr> |
Tue, 15 Nov 2011 22:22:18 +0100 | |
changeset 8083 | 3db2f3317d15 |
parent 5924 | b218df942dd4 |
child 9739 | 5efd4a1abc66 |
permissions | -rw-r--r-- |
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. |