Edgewall Software
Modify

Opened 3 years ago

Closed 3 years ago

Last modified 14 months ago

#12953 closed defect (fixed)

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

Reported by: Jun Omae Owned by: Jun Omae
Priority: normal Milestone: 1.0.17
Component: general Version: 1.0.15
Severity: normal Keywords: mysql
Cc: Branch:
Release Notes:

Add [trac] anonymous_session_lifetime option which allows controlling the expiration of anonymous session.

API Changes:
Internal Changes:

Description

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)

Attachments (0)

Change History (6)

comment:1 by Jun Omae, 3 years ago

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

    diff --git a/trac/env.py b/trac/env.py
    index 3b7a4e16f..034847aee 100644
    a b class Environment(Component, ComponentManager):  
    192192        your Trac instance is only accessible through HTTPS. (''since
    193193        0.11.2'')""")
    194194
     195    anonymous_session_lifetime = IntOption(
     196        'trac', 'anonymous_session_lifetime', '90',
     197        """Lifetime of the anonymous session, in days.
     198
     199        Set the option to 0 to disable purging old anonymous sessions.""")
     200
    195201    project_name = Option('project', 'name', 'My Project',
    196202        """Name of the project.""")
    197203
  • trac/web/session.py

    diff --git a/trac/web/session.py b/trac/web/session.py
    index 103c22c4a..2b6fa2a8f 100644
    a b class DetachedSession(dict):  
    169169
    170170        if session_saved and now - self.last_visit > UPDATE_INTERVAL:
    171171            self.last_visit = now
    172             mintime = now - PURGE_AGE
     172            lifetime = self.env.anonymous_session_lifetime
     173            mintime = now - lifetime * 86400 if lifetime > 0 else None
    173174
    174175            with self.env.db_transaction as db:
    175176                # Update the session last visit time if it is over an
    class DetachedSession(dict):  
    178179                db("""UPDATE session SET last_visit=%s
    179180                      WHERE sid=%s AND authenticated=%s
    180181                      """, (self.last_visit, self.sid, authenticated))
    181                 self.env.log.debug('Purging old, expired, sessions.')
    182                 db("""DELETE FROM session_attribute
    183                       WHERE authenticated=0 AND sid IN (
    184                           SELECT sid FROM session
    185                           WHERE authenticated=0 AND last_visit < %s
    186                       )
    187                       """, (mintime,))
     182                if mintime:
     183                    self.env.log.debug('Purging old, expired, sessions.')
     184                    db("""DELETE FROM session_attribute
     185                          WHERE authenticated=0 AND sid IN (
     186                              SELECT sid FROM session
     187                              WHERE authenticated=0 AND last_visit < %s
     188                          )
     189                          """, (mintime,))
    188190
    189191            # Avoid holding locks on lot of rows on both session_attribute
    190192            # and session tables
    191             with self.env.db_transaction as db:
    192                 db("""
    193                     DELETE FROM session
    194                     WHERE authenticated=0 AND last_visit < %s
    195                     """, (mintime,))
     193            if mintime:
     194                with self.env.db_transaction as db:
     195                    db("""
     196                        DELETE FROM session
     197                        WHERE authenticated=0 AND last_visit < %s
     198                        """, (mintime,))
    196199
    197200
    198201class Session(DetachedSession):

comment:2 by Ryan J Ollos, 3 years ago

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.

comment:3 by Jun Omae, 3 years ago

Milestone: next-stable-1.2.x1.0.17
Owner: set to Jun Omae
Status: newassigned

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.

comment:4 by Ryan J Ollos, 3 years ago

Changes look good to me.

comment:5 by Jun Omae, 3 years ago

Release Notes: modified (diff)
Resolution: fixed
Status: assignedclosed

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

comment:6 by Jun Omae, 14 months ago

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

CREATE INDEX idx_session_attribute_authenticated ON session_attribute (authenticated)

Modify Ticket

Change Properties
Set your email in Preferences
Action
as closed The owner will remain Jun Omae.
The resolution will be deleted. Next status will be 'reopened'.
to The owner will be changed from Jun Omae to the specified user.

Add Comment


E-mail address and name can be saved in the Preferences .
 
Note: See TracTickets for help on using tickets.