author | Aurelien Campeas <aurelien.campeas@logilab.fr> |
Thu, 08 Apr 2010 17:50:37 +0200 | |
branch | stable |
changeset 5189 | 84d4587a92bc |
parent 5150 | 7a9e71ee5671 |
permissions | -rw-r--r-- |
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. |