1

I've been fighting my problem for the whole last week, studying stackexchange threads with similar issues in the first place.

The main problem is that after switching from MyISAM to InnoDB (transactions became mandatory, with the ability to roll back complex inserts/updates at certain conditions) some simple update queries became extremely slow at random occurrence - 0.5-2% of all similar requests.

I haven't come to a solution yet and am seeking your advice.

The database:

1) simple table with userdata

CREATE TABLE `users` (
  `id` int(11) NOT NULL AUTO_INCREMENT,
  `first_name` varchar(255) NOT NULL DEFAULT '',
  `last_name` varchar(255) NOT NULL DEFAULT '',
... similar data fields ...
...
PRIMARY KEY (`id`) ) ENGINE=InnoDB AUTO_INCREMENT=15 DEFAULT CHARSET=utf8; 

2) and simple table with users coordinates and update time

CREATE TABLE `users_geo` (
  `user_id` int(11) NOT NULL DEFAULT '0',
  `lat` float DEFAULT NULL,
  `lng` float DEFAULT NULL,
  `update_time` datetime DEFAULT NULL,
  UNIQUE KEY `user_id` (`user_id`),
  KEY `update_time` (`update_time`) ) ENGINE=InnoDB DEFAULT CHARSET=utf8

There are only ~20 records in both table, this is development/testing machine, CentOS 7, 1 GB RAM and MariaDB, few settings in my.cnf:

innodb_buffer_pool_size=480M
innodb_log_file_size=64M
innodb_flush_log_at_trx_commit=0
innodb_flush_method=O_DIRECT
innodb_locks_unsafe_for_binlog=1 # even this is enabled

In this situation nginx is serving 1-2 requests per each 5 seconds, they are fast and simple:

    [2016-04-22 22:10:18]: [0.042] /search.php?position=&show_offline=1&category=&company=&skip_contact_list=1&distance=-1&user_id=2&lat=00.2083816&lng=00.2031555
    [2016-04-22 22:10:22]: [0.041] /update_geo.php?user_id=2&show_offline=1&lat=00.2083816&lng=00.2031555
    [2016-04-22 22:10:27]: [0.037] /update_geo.php?user_id=2&show_offline=1&lat=00.2083816&lng=00.2031555
    [2016-04-22 22:10:28]: [0.034] /search.php?position=&show_offline=1&category=&company=&skip_contact_list=1&distance=-1&user_id=2&lat=00.2083816&lng=00.2031555
    [2016-04-22 22:10:32]: [0.040] /update_geo.php?user_id=2&show_offline=1&lat=00.2083816&lng=00.2031555
    [2016-04-22 22:10:37]: [0.037] /update_geo.php?user_id=2&show_offline=1&lat=00.2083816&lng=00.2031555
    [2016-04-22 22:10:38]: [0.034] /search.php?position=&show_offline=1&category=&company=&skip_contact_list=1&distance=-1&user_id=2&lat=00.2083816&lng=00.2031555
    [2016-04-22 22:10:43]: [0.058] /update_geo.php?user_id=2&show_offline=1&lat=00.2083816&lng=00.2031555
    [2016-04-22 22:10:47]: [0.042] /update_geo.php?user_id=2&show_offline=1&lat=00.2083816&lng=00.2031555
    [2016-04-22 22:10:48]: [0.036] /search.php?position=&show_offline=1&category=&company=&skip_contact_list=1&distance=-1&user_id=2&lat=00.2083816&lng=00.2031555
    [2016-04-22 22:10:52]: [0.036] /update_geo.php?user_id=2&show_offline=1&lat=00.2083816&lng=00.2031555
    [2016-04-22 22:10:57]: [0.038] /update_geo.php?user_id=2&show_offline=1&lat=00.2083816&lng=00.2031555
    [2016-04-22 22:10:58]: [0.038] /search.php?position=&show_offline=1&category=&company=&skip_contact_list=1&distance=-1&user_id=2&lat=00.2083816&lng=00.2031555
    [2016-04-22 22:11:02]: [0.038] /update_geo.php?user_id=2&show_offline=1&lat=00.2083816&lng=00.2031555
    [2016-04-22 22:11:07]: [0.037] /update_geo.php?user_id=2&show_offline=1&lat=00.2083816&lng=00.2031555
    [2016-04-22 22:11:08]: [0.035] /search.php?position=&show_offline=1&category=&company=&skip_contact_list=1&distance=-1&user_id=2&lat=00.2083816&lng=00.2031555
    [2016-04-22 22:11:13]: [0.036] /update_geo.php?user_id=2&show_offline=1&lat=00.2083816&lng=00.2031555
    [2016-04-22 22:12:02]: [0.089] /search.php?position=&show_offline=1&category=&company=&skip_contact_list=1&distance=-1&user_id=2&lat=00.2083816&lng=00.2031555
    [2016-04-22 22:12:02]: [0.063] /update_geo.php?user_id=2&show_offline=1&lat=00.2083816&lng=00.2031555
    [2016-04-22 22:12:15]: [0.048] /update_geo.php?user_id=2&show_offline=1&lat=00.2083816&lng=00.2031555
    [2016-04-22 22:12:36]: [0.087] /search.php?position=&show_offline=1&category=&company=&skip_contact_list=1&distance=-1&user_id=2&lat=00.2083816&lng=00.2031555
    [2016-04-22 22:12:37]: [0.036] /update_geo.php?user_id=2&show_offline=1&lat=00.2083816&lng=00.2031555
    [2016-04-22 22:12:42]: [0.092] /update_geo.php?user_id=2&show_offline=1&lat=00.2083816&lng=00.2031555
    [2016-04-22 22:12:46]: [0.037] /search.php?position=&show_offline=1&category=&company=&skip_contact_list=1&distance=-1&user_id=2&lat=00.2083816&lng=00.2031555
    [2016-04-22 22:12:47]: [0.039] /update_geo.php?user_id=2&show_offline=1&lat=00.2083816&lng=00.2031555
    [2016-04-22 22:12:52]: [0.074] /update_geo.php?user_id=2&show_offline=1&lat=00.2083816&lng=00.2031555
    [2016-04-22 22:12:56]: [0.042] /search.php?position=&show_offline=1&category=&company=&skip_contact_list=1&distance=-1&user_id=2&lat=00.2083816&lng=00.2031555

update_geo.php is doing something like that according to SHOW PROFILES:

date: [2016-04-23 08:47:54], span: [0.009], request: [/update_geo.php?user_id=2&show_offline=1&lat=00.2083816&lng=00.2031555], tracing queries:
1: [0.000];SET SESSION TRANSACTION ISOLATION LEVEL READ UNCOMMITTED
2: [0.001];SELECT users.*, users_geo.* FROM users LEFT JOIN users_geo ON users_geo.user_id=users.id WHERE users.id=2
3: [0.003];SET SESSION TRANSACTION ISOLATION LEVEL REPEATABLE READ
4: [0.000];SET SESSION TRANSACTION ISOLATION LEVEL READ UNCOMMITTED
5: [0.001];SELECT ...
6: [0.000];SELECT ...
7: [0.000];SELECT ...
8: [0.000];SELECT ...
9: [0.001];SELECT ...
10: [0.001];SELECT ...
11: [0.000];SET SESSION TRANSACTION ISOLATION LEVEL REPEATABLE READ
12: [0.002];UPDATE users_geo SET update_time="2016-04-23 08:47:54"  WHERE user_id=2

So i see the UPDATE is basically fast and pretty simple query, BUT! One of 50-150 requests of the like are very slow, VERY slow i'd say.

Here's profiling for example:

date: [2016-04-24 15:00:45], span: [5.281], request: [/update_geo.php?user_id=3&show_offline=1&lat=00.2196689&lng=00.2213793], tracing queries:
1: [0.000];SET SESSION TRANSACTION ISOLATION LEVEL READ UNCOMMITTED
2: [0.001];SELECT users.*, users_geo.* FROM users LEFT JOIN users_geo ON users_geo.user_id=users.id WHERE users.id=3
3: [0.003];SET SESSION TRANSACTION ISOLATION LEVEL REPEATABLE READ
4: [0.000];SET SESSION TRANSACTION ISOLATION LEVEL READ UNCOMMITTED
5: [0.000];SELECT ...
6: [0.000];SELECT ...
7: [0.000];SELECT ...
8: [0.000];SELECT ...
9: [0.000];SELECT ...
10: [0.000];SELECT ...
11: [0.000];SELECT ...
12: [0.000];SELECT ...
13: [0.000];SELECT ...
14: [0.001];SELECT ...
15: [0.001];SELECT ...
16: [0.000];SELECT ...
17: [0.000];SELECT ...
18: [0.001];SELECT ...
19: [0.001];SELECT ...
20: [0.001];SELECT ...
21: [0.001];SELECT ...
22: [0.000];SET SESSION TRANSACTION ISOLATION LEVEL REPEATABLE READ
23: [5.270];UPDATE users_geo SET update_time="2016-04-24 15:00:39"  WHERE user_id=3
tracing profile:
starting                    : 0.000018
checking permissions        : 0.000003
Opening tables              : 0.000007
After opening tables        : 0.000003
System lock                 : 0.000002
Table lock                  : 0.000002
After table lock            : 0.000002
init                        : 0.000021
Updating                    : 5.269439
end                         : 0.000012
query end                   : 0.000020
closing tables              : 0.000010
freeing items               : 0.000006
updating status             : 0.000554
cleaning up                 : 0.000003
---

A whopping 5 seconds for a simple update, that executing instantly in 99% cases, how is it possible?

These are very random situations, I can't see any regularity, and even more, these hangs don't have any concurrent requests at the same time. They're all hanging in "updating" state.

Before I ask, I'd like to explain that isolation session level for reading before update was set to "read uncommitted" because we don't really care if some data changes in the meantime and to avoid any locks that might be imposed on reading queries. This was explained in the similar thread here on stackexchange.

So I'm struggling to find the answers for 2 main questions:

1. What mechanism/process of the database engine causes "update" to last that long? Is it lock acquisition (if so, what is locking the table as there are no any other update/select queries, nothing)? Or is it IO operation (if so, what is the reason of such a long writing)?

2. What can I do to get rid of such "hangs"? Converting this one table back to MyISAM is not good option.

Thank you much in advance, I hope I was able to put all the necessary info for this puzzle.

  • Try READ COMMITTED for all of your transactions - it's the default and you might have hit some wierd bug in MariaDB? Have you tried going back to MySQL? The MariaDB lists? Why did you pick MariaDB? You can always spot the pioneers by the arrows sticking out of their chests! :-) – Vérace Apr 26 '16 at 14:30
  • @Vérace thank you for your advice. just tried to put SET SESSION TRANSACTION ISOLATION LEVEL READ COMMITTED at the top of each call, removing previous "uncommited" manipulations, but unfortunately i still see hangups of the same nature in the logfile. It could seem to me, they're rarely seen now, but i'm not completely sure, need more time to analyze. Thanks though! – N A Apr 26 '16 at 19:06

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service, privacy policy and cookie policy

Browse other questions tagged or ask your own question.