http://researchr.org/profile/guwac/contributions?logsql

First request on these contribution pages are expensive. Subsequent requests are fast, probably due to caching.

Expensive query:

Longest query: time=22056ms, hydrated=20, template=listChangesProfile(user : User, index : Int)

select
    changereco0_.id as id16_,
    changereco0_.`ChangeRecord_cp` as ChangeR11_16_,
    changereco0_.`_created` as column3_16_,
    changereco0_.`_date` as column4_16_,
    changereco0_.`_description` as column5_16_,
    changereco0_.`_downVotes` as column6_16_,
    changereco0_.`_modified` as column7_16_,
    changereco0_.`_spamVotes` as column8_16_,
    changereco0_.`_upVotes` as column9_16_,
    changereco0_.`ChangeRecord_user` as ChangeR12_16_,
    changereco0_.version_opt_lock as version10_16_,
    changereco0_.`BibliographyChangeRecord_Bibliography` as Bibliog13_16_,
    changereco0_.`ConferenceChangeRecord_conference` as Confere14_16_,
    changereco0_.`PersonChangeRecord_person` as PersonC15_16_,
    changereco0_.`PublicationChangeRecord_publication` as Publica16_16_,
    changereco0_.DISCRIMINATOR as DISCRIMI1_16_ 
from
    _ChangeRecord changereco0_ 
where
    changereco0_.`ChangeRecord_user`='50a0f8093748420ebef3a41eb921971d' 
order by
    changereco0_.`_date` desc limit ?

Submitted by Eelco Visser on 11 June 2013 at 14:32

We tried this query on the test server, with a restart of Mysql and no query cache. It turns out to be caused by the sorting.

mysql> set profiling=1;
Query OK, 0 rows affected (0.00 sec)

mysql> select SQL_NO_CACHE changereco0_.id as id16_, changereco0_.ChangeRecord_cp as ChangeR11_16_, changereco0_._created as column3_16_, changereco0_._date as column4_16_, changereco0_._description as column5_16_, changereco0_._downVotes as column6_16_, changereco0_._modified as column7_16_, changereco0_._spamVotes as column8_16_, changereco0_._upVotes as column9_16_, changereco0_.ChangeRecord_user as ChangeR12_16_, changereco0_.version_opt_lock as version10_16_, changereco0_.BibliographyChangeRecord_Bibliography as Bibliog13_16_, changereco0_.ConferenceChangeRecord_conference as Confere14_16_, changereco0_.PersonChangeRecord_person as PersonC15_16_, changereco0_.PublicationChangeRecord_publication as Publica16_16_, changereco0_.DISCRIMINATOR as DISCRIMI1_16_ from ChangeRecord changereco0 where changereco0_.ChangeRecord_user=‘50a0f8093748420ebef3a41eb921971d’ order by changereco0_._date desc limit 20;

mysql> show profile;
+——————–+———–+
| Status | Duration |
+——————–+———–+
| starting | 0.000157 |
| Opening tables | 1.112428 |
| System lock | 0.000011 |
| Table lock | 0.000014 |
| init | 0.000050 |
| optimizing | 0.000025 |
| statistics | 0.038778 |
| preparing | 0.000051 |
| executing | 0.000004 |
| Sorting result | 21.612401 |
| Sending data | 0.000491 |
| end | 0.000006 |
| query end | 0.000004 |
| freeing items | 0.000065 |
| logging slow query | 0.000004 |
| logging slow query | 0.000006 |
| cleaning up | 0.000009 |
+——————–+———–+

subsequent requests:

mysql> show profile;
| Status | Duration |
+——————–+———-+
| starting | 0.000114 |
| Opening tables | 0.000014 |
| System lock | 0.000004 |
| Table lock | 0.000007 |
| init | 0.000036 |
| optimizing | 0.000010 |
| statistics | 0.000082 |
| preparing | 0.000020 |
| executing | 0.000017 |
| Sorting result | 0.022860 |
| Sending data | 0.000669 |
| end | 0.000007 |
| query end | 0.000003 |
| freeing items | 0.000043 |
| logging slow query | 0.000003 |
| cleaning up | 0.000006 |
+——————–+———-+

The table is quite large

mysql> select count() from _ChangeRecord;
+———-+
| count() |
+———-+
| 3449148 |

The caching effect is likely related to the sort buffer http://ronaldbradford.com/blog/more-on-understanding-sort_buffer_size-2010-05-10/ http://www.mysqlperformanceblog.com/2010/10/25/impact-of-the-sort-buffer-size-in-mysql/

The fix is adding an index, which unfortunately will lock the table for both reads and writes while it’s being created http://dev.mysql.com/doc/refman/5.0/en/create-index.html