Lock wait timeout and Get_Lock slow queries

Lock wait timeout and Get_Lock slow queries

by KK. Morrissey -
Number of replies: 4

We have recently upgraded to Moodle 3.2.4+ (Build: 20170824) from 3.1 and have since been experiencing the following errors frequently,  with normal to very little load (less than 140 users). The error happens for basic navigation through the site and is not related to a specific activity like quizzes. I am not sure what could be causing it and am hoping someone can shed some light.


------------------------------
Default exception handler: Error writing to database Debug: Lock wait timeout exceeded; try restarting transaction\nUPDATE mdl_user SET lastlogin = ?,currentlogin = ?,lastaccess = ?,lastip = ? WHERE id=?\n[array (\n  0 => '1506432126',\n  1 => 1506503289,\n  2 => 1506503289,\n  3 => 'xx.xxx.xxx.xx',\n  4 => '3242',\n)]\nError code: dmlwriteexception\n* line 482 of /lib/dml/moodle_database.php: dml_write_exception thrown\n* line 1502 of /lib/dml/mysqli_native_moodle_database.php: call to moodle_database->query_end()\n* line 1534 of /lib/dml/mysqli_native_moodle_database.php: call to mysqli_native_moodle_database->update_record_raw()\n* line 3219 of /lib/moodlelib.php: call to mysqli_native_moodle_database->update_record()\n* line 4427 of /lib/moodlelib.php: call to update_user_login_times()\n* line 195 of /login/index.php: call to complete_user_login()\n, referer: 
-------------------------------


We are running Moodle with the application+webserver on a different server from the database server in a VMWare environment. The hardware details are:

-------------------------------

DB Server

CentOS release 6.9 (Final)
mysql  Ver 15.1 Distrib 5.5.57-MariaDB, for Linux (x86_64) using readline 5.1
Intel(R) Xeon(R) CPU E5-2640 0 @ 2.50GHz
Memory:
             total       used       free     shared    buffers     cached
-/+ buffers/cache:    2304220    5756860
Swap:      8208380      40844    8167536
Mem:       8061080    4991944    3069136          8     162472    2525252



Application+Web

CentOS release 6.9 (Final)
Server version: Apache/2.2.15 (Unix)
PHP 5.6.31 (cli) (built: Jul  7 2017 08:12:50)
Copyright (c) 1997-2016 The PHP Group
Zend Engine v2.6.0, Copyright (c) 1998-2016 Zend Technologies
    with Zend OPcache v7.0.6-dev, Copyright (c) 1999-2016, by Zend Technologies
Intel(R) Xeon(R) CPU E5-2640 v3 @ 2.60GHz
Memory 
             total       used       free     shared    buffers     cached
Mem:       8061080    6448624    1612456     131416     539320    3873432
-/+ buffers/cache:    2035872    6025208
Swap:      3145724      57932    3087792



I have enabled slow queries and have noticed that the Get_Lock for sessions take a long time; we are getting many of the following where the time take upwards of 120s. Each slow query log below is followed by a "Lock wait timeout" error in the Moodle Application. 


-------------------------------
# Time: 170927 10:09:03
# User@Host: xxxxxxxxxx[xxxxxxxxxx] @ xxxxxxxxxx [xxxxxxxxxx]
# Thread_id: 17004  Schema: xxxxxxxxxx  QC_hit: No
# Query_time: 120.000135  Lock_time: 0.000000  Rows_sent: 1  Rows_examined: 0
SET timestamp=1506503343;
SELECT GET_LOCK('xxxxxxxxxx-mdl_-session-6390663', 120);
# Time: 170927 10:09:06
# User@Host: xxxxxxxxxx[xxxxxxxxxx] @ xxxxxxxxxx [xxxxxxxxxx]
# Thread_id: 17012  Schema: xxxxxxxxxx  QC_hit: No
# Query_time: 120.000242  Lock_time: 0.000000  Rows_sent: 1  Rows_examined: 0
SET timestamp=1506503346;
SELECT GET_LOCK('xxxxxxxxxx-mdl_-session-6390663', 120);
# User@Host: xxxxxxxxxx[xxxxxxxxxx] @ xxxxxxxxxx [xxxxxxxxxx]
# Thread_id: 17013  Schema: xxxxxxxxxx  QC_hit: No
# Query_time: 120.000169  Lock_time: 0.000000  Rows_sent: 1  Rows_examined: 0
SET timestamp=1506503346;
-------------------------------


The DB variables set at startup are attached as are the top largest tables (>10MB). The mdl_logstore_standard_log table is quite large but I am not sure whether this is related to the timeout while updating the mdl_user table. 


Can anyone help please?


Many thanks.



Average of ratings: -
In reply to KK. Morrissey

Re: Lock wait timeout and Get_Lock slow queries

by Ken Task -
Picture of Particularly helpful Moodlers

Is there a reason to use the DB for sessions?  

See config of sessions your server

http://yourserver/admin/settings.php?section=sessionhandling

and the comment for use database for sessions.

If not, turn off using DB for sessions from config.php file as a test by adding:

$CFG->dbsession='0';

A 'sessions' directory should be created in moodledata and moodle should begin to create/check/update files for sessions of users in that directory upon the next users access (no need to restart any services).

'spirit of sharing', Ken




Average of ratings: -
In reply to Ken Task

Re: Lock wait timeout and Get_Lock slow queries

by KK. Morrissey -

Hi Ken,

I have changed the session handling in the Moodle front end by disabling (unchecking):

Dashboard / ► Site administration / ► Server / ► Session handling / ► Use database for session information
There are now no more slow queries being logged however, the error is still happening. 

When we look at the full process list we can see the updates queuing and when it reaches the innodb_lock_wait_timeout (set at 90s) the error starts being generated as each in the queue reaches a time of 90s [ see below]. A count of the sessions folder shows 1515 which I am assuming maps to a unique session...?


MariaDB [(none)]> show full processlist;
+-------+-----------+-----------------+-------------+---------+------+----------+-------------------------------------------------------------------------------------------+----------+
| Id    | User      | Host            | db          | Command | Time | State    | Info                                                                                      | Progress |
+-------+-----------+-----------------------------+-------------+---------+------+----------+-------------------------------------------------------------------------------------------+----------+
|   384 | root      | localhost       | NULL        | Query   |    0 | NULL     | show full processlist                                                                     |    0.000 |
| 15288 | user1     | moodleapp:43418 | moodledbase | Sleep   |    0 |          | NULL                                                                                      |    0.000 |
| 16368 | user2     | oapp.com:62207  | moodledbase | Sleep   |   85 |          | NULL                                                                                      |    0.000 |
| 17606 | user1     | moodleapp:48374 | moodledbase | Query   |   87 | Updating | UPDATE mdl_user SET lastip = '127.0.1.1',lastaccess = '1506519743' WHERE id='98989'       |    0.000 |
| 17734 | user1     | moodleapp:48684 | moodledbase | Sleep   |   78 |          | NULL                                                                                      |    0.000 |
| 17793 | user1     | moodleapp:48814 | moodledbase | Query   |   10 | Updating | UPDATE mdl_user SET lastip = '127.0.1.2',lastaccess = '1506519820' WHERE id='99011'       |    0.000 |
| 17866 | user1     | moodleapp:48978 | moodledbase | Sleep   |   73 |          | NULL                                                                                      |    0.000 |
| 17987 | user1     | moodleapp:49238 | moodledbase | Query   |   18 | Updating | UPDATE mdl_user SET lastip = '127.0.1.3',lastaccess = '1506519812' WHERE id='99008'       |    0.000 |
| 18057 | user1     | moodleapp:49378 | moodledbase | Sleep   |   62 |          | NULL                                                                                      |    0.000 |
| 18112 | user1     | moodleapp:49488 | moodledbase | Sleep   |   60 |          | NULL                                                                                      |    0.000 |
| 18290 | user1     | moodleapp:49848 | moodledbase | Sleep   |   56 |          | NULL                                                                                      |    0.000 |
| 18366 | user1     | moodleapp:50010 | moodledbase | Query   |   50 | Updating | UPDATE mdl_user SET lastip = '127.0.1.4',lastaccess = '1506519780' WHERE id='94947'       |    0.000 |
| 18443 | user1     | moodleapp:50174 | moodledbase | Sleep   |   44 |          | NULL                                                                                      |    0.000 |
| 18479 | user1     | moodleapp:50256 | moodledbase | Query   |   37 | Updating | UPDATE mdl_user SET lastip = '127.0.1.5',lastaccess = '1506519793' WHERE id='100826'      |    0.000 |
| 18573 | user1     | moodleapp:50460 | moodledbase | Sleep   |   30 |          | NULL                                                                                      |    0.000 |
| 18587 | user1     | moodleapp:50488 | moodledbase | Sleep   |   30 |          | NULL                                                                                      |    0.000 |
| 18616 | user1     | moodleapp:50546 | moodledbase | Query   |    0 | Updating | UPDATE mdl_user SET lastip = '127.0.1.6',lastaccess = '1506519830' WHERE id='98987'       |    0.000 |
| 18617 | user1     | moodleapp:50548 | moodledbase | Sleep   |   25 |          | NULL                                                                                      |    0.000 |
| 18621 | user1     | moodleapp:50556 | moodledbase | Sleep   |   25 |          | NULL                                                                                      |    0.000 |
| 18637 | user1     | moodleapp:50588 | moodledbase | Sleep   |   23 |          | NULL                                                                                      |    0.000 |
| 18748 | user1     | moodleapp:50818 | moodledbase | Sleep   |    9 |          | NULL                                                                                      |    0.000 |
| 18752 | user1     | moodleapp:50826 | moodledbase | Query   |    8 | Updating | UPDATE mdl_user SET lastip = '127.0.1.6',lastaccess = '1506519822' WHERE id='99047'       |    0.000 |
| 18763 | user1     | moodleapp:50848 | moodledbase | Query   |    5 | Updating | UPDATE mdl_user SET lastip = '127.0.1.7',lastaccess = '1506519825' WHERE id='99032'       |    0.000 |
| 18783 | user1     | moodleapp:50888 | moodledbase | Sleep   |    3 |          | NULL                                                                                      |    0.000 |
| 18787 | user1     | moodleapp:50896 | moodledbase | Query   |    2 | Updating | UPDATE mdl_user SET lastip = '127.0.1.8',lastaccess = '1506519828' WHERE id='8973'        |    0.000 |
| 18799 | user1     | moodleapp:50920 | moodledbase | Sleep   |    0 |          | NULL                                                                                      |    0.000 |
| 18800 | user1     | moodleapp:50922 | moodledbase | Sleep   |    0 |          | NULL                                                                                      |    0.000 |
| 18805 | user1     | moodleapp:50932 | moodledbase | Sleep   |    0 |          | NULL                                                                                      |    0.000 |
| 18806 | user1     | moodleapp:50934 | moodledbase | Sleep   |    0 |          | NULL                                                                                      |    0.000 |
+-------+----------------+-----------------------------+-------------+---------+------+----------+-------------------------------------------------------------------------------------------+----------+
29 rows in set (0.00 sec)


I am at a loss as to what could be causing the queuing and and subsequent "Error writing to database Debug: Lock wait timeout exceeded;".


Any other ideas? Anything that can help.


Many thanks.

Average of ratings: -
In reply to KK. Morrissey

Re: Lock wait timeout and Get_Lock slow queries

by Ken Task -
Picture of Particularly helpful Moodlers

I thought that any change like that would affect users upon their *next* login.  For users that were already logged on when the change was made, don't think Moodle attempts to kill their session and re-establish via session files.

There is a line in config-dist.php for extending the time outs for locks - guess that shows recommended default.   Otherwise, it's 90?

I run CentOS 6 and 7 servers ... don't think I've ever seen the error before but then again, usage of your system and those that I admin probably not the same.

Let's give a day?

'spirit of sharing', Ken


Average of ratings: -
In reply to Ken Task

Re: Lock wait timeout and Get_Lock slow queries

by Ken Task -
Picture of Particularly helpful Moodlers

A correction and follow up ...

That variable in config.php should be dbsessions (ending with an 's' ... not ending with an 'n' as previously poted.

Follow up ... more info ... in setup of sessions in the Moodle, one can see a recommendation that max_allowed_packet be ste higher than default IF using DB for sessions.

And ... in the config-dist.php file there is a setting for locks ...

//      $CFG->session_database_acquire_lock_timeout = 120;

You might explore config-dist.php for other related settings to include in your config.php.

Again, most additions/changes to config.php don't require restart of services.   Next hit by any user, those additions should be in place.    Nice thing about using config.php flie in this case is simple ... if what you add doesn't fix but causes other problems, one can quickly edit the config.php file again and comment out what one added.  Any users that were affected adversly by the change might have to log out then back in again.

'spirit of sharing', Ken


Average of ratings: -