Deadlock on MySQL when purging old anonymous sessions in Session.save()

[Jun Omae]

I've got deadlocks with MySQL under production environment.

Traceback (most recent call last):
  File "/venv/lib/python2.6/site-packages/trac/web/main.py", line 567, in _dispatch_request
    dispatcher.dispatch(req)
  File "/venv/lib/python2.6/site-packages/trac/web/main.py", line 270, in dispatch
    req.send(output, content_type or 'text/html')
  File "/venv/lib/python2.6/site-packages/trac/web/api.py", line 550, in send
    self.send_response(status)
  File "/venv/lib/python2.6/site-packages/trac/web/main.py", line 102, in send_response
    self.session.save()
  File "/venv/lib/python2.6/site-packages/trac/web/session.py", line 187, in save
    """, (mintime,))
  File "/venv/lib/python2.6/site-packages/trac/db/util.py", line 128, in execute
    cursor.execute(query, params if params is not None else [])
  File "/venv/lib/python2.6/site-packages/trac/db/util.py", line 72, in execute
    return self.cursor.execute(sql_escape_percent(sql), args)
  File "/venv/lib/python2.6/site-packages/MySQLdb/cursors.py", line 205, in execute
    self.errorhandler(self, exc, value)
  File "/venv/lib/python2.6/site-packages/MySQLdb/connections.py", line 36, in defaulterrorhandler
    raise errorclass, errorvalue
OperationalError: (1213, 'Deadlock found when trying to get lock; try restarting transaction')

Deleting old anonymous sessions between 2 transactions in the same time leads the deadlock.

*** (1) TRANSACTION:
TRANSACTION 0 813950056, ACTIVE 0 sec, process no 9791, OS thread id 139812286813952 starting index read
mysql tables in use 2, locked 2
LOCK WAIT 6 lock struct(s), heap size 1216, 4 row lock(s), undo log entries 3
MySQL thread id 15761050, query id 1582491217 10.0.1.30 tracuser updating
DELETE FROM session_attribute
                      WHERE authenticated=0 AND sid IN (
                          SELECT sid FROM session
                          WHERE authenticated=0 AND last_visit < 1502759550
                      )

*** (2) TRANSACTION:
TRANSACTION 0 813950055, ACTIVE 0 sec, process no 9791, OS thread id 139812289476352 fetching rows, thread declared inside InnoDB 80
mysql tables in use 2, locked 2
50 lock struct(s), heap size 6752, 3474 row lock(s), undo log entries 3
MySQL thread id 15761048, query id 1582491213 10.0.1.30 tracuser updating
DELETE FROM session_attribute
                      WHERE authenticated=0 AND sid IN (
                          SELECT sid FROM session
                          WHERE authenticated=0 AND last_visit < 1502759550
                      )

The delete query is full scan on session_attribute table.

mysql> EXPLAIN DELETE FROM session_attribute
    -> WHERE authenticated=0 AND sid IN (
    ->   SELECT sid FROM session
    ->   WHERE authenticated=0
    ->   AND last_visit < 1502759550);
+----+--------------------+-------------------+-----------------+----------------------------------------------------------+---------+---------+------------+--------+-------------+
| id | select_type        | table             | type            | possible_keys                                            | key     | key_len | ref        | rows   | Extra       |
+----+--------------------+-------------------+-----------------+----------------------------------------------------------+---------+---------+------------+--------+-------------+
|  1 | PRIMARY            | session_attribute | ALL             | NULL                                                     | NULL    | NULL    | NULL       | 232569 | Using where |
|  2 | DEPENDENT SUBQUERY | session           | unique_subquery | PRIMARY,session_last_visit_idx,session_authenticated_idx | PRIMARY | 506     | func,const |      1 | Using where |
+----+--------------------+-------------------+-----------------+----------------------------------------------------------+---------+---------+------------+--------+-------------+
2 rows in set (0.00 sec)

[Jun Omae]

I consider that we shouldn't automatically purge expired anonymous sessions in web request for public Trac site which many users access because the delete query is full scan, long and possibly concurrent.

How about adding option to configure lifetime of the anonymous session (0 to disable the purging)?

trac/env.py

@@ -192 +192 @@
         your Trac instance is only accessible through HTTPS. (''since
         0.11.2'')""")
 
+    anonymous_session_lifetime = IntOption(
+        'trac', 'anonymous_session_lifetime', '90',
+        """Lifetime of the anonymous session, in days.
+
+        Set the option to 0 to disable purging old anonymous sessions.""")
+
     project_name = Option('project', 'name', 'My Project',
         """Name of the project.""")
 

trac/web/session.py

@@ -169 +169 @@
 
         if session_saved and now - self.last_visit > UPDATE_INTERVAL:
             self.last_visit = now
-            mintime = now - PURGE_AGE
+            lifetime = self.env.anonymous_session_lifetime
+            mintime = now - lifetime * 86400 if lifetime > 0 else None
 
             with self.env.db_transaction as db:
                 # Update the session last visit time if it is over an
@@ -178 +179 @@
                 db("""UPDATE session SET last_visit=%s
                       WHERE sid=%s AND authenticated=%s
                       """, (self.last_visit, self.sid, authenticated))
-                self.env.log.debug('Purging old, expired, sessions.')
-                db("""DELETE FROM session_attribute
-                      WHERE authenticated=0 AND sid IN (
-                          SELECT sid FROM session
-                          WHERE authenticated=0 AND last_visit < %s
-                      )
-                      """, (mintime,))
+                if mintime:
+                    self.env.log.debug('Purging old, expired, sessions.')
+                    db("""DELETE FROM session_attribute
+                          WHERE authenticated=0 AND sid IN (
+                              SELECT sid FROM session
+                              WHERE authenticated=0 AND last_visit < %s
+                          )
+                          """, (mintime,))
 
             # Avoid holding locks on lot of rows on both session_attribute
             # and session tables
-            with self.env.db_transaction as db:
-                db("""
-                    DELETE FROM session
-                    WHERE authenticated=0 AND last_visit < %s
-                    """, (mintime,))
+            if mintime:
+                with self.env.db_transaction as db:
+                    db("""
+                        DELETE FROM session
+                        WHERE authenticated=0 AND last_visit < %s
+                        """, (mintime,))
 
 
 class Session(DetachedSession):

[Ryan J Ollos]

Looks reasonable to me.

It looks like PURGE_AGE is also used for the cookie lifetime​. The PURGE_AGE comment​ could be revised after your change: Purge session Expire cookie after 90 days.

[Jun Omae]

Thanks for the reviewing.

Proposed changes with suggestions and unit tests in [524dadd9a/jomae.git] (jomae.git@t12953). Also, I'd like to push the changes to 1.0-stable. I need the option for 1.0-stable on my production environment.

[Ryan J Ollos]

Changes look good to me.

[Jun Omae]

Thanks for the reviewing. Committed in [16415] and merged in [16416-16417].

[Jun Omae]

Workaround is to create an index on session_attribute (authenticated).

CREATE INDEX idx_session_attribute_authenticated ON session_attribute (authenticated)