keystone.token.backends.sql uses a single delete command to flush expired tokens causing replication lag and potential deadlocks

Bug #1188378 reported by Clint Byrum
34
This bug affects 6 people
Affects Status Importance Assigned to Milestone
OpenStack Identity (keystone)
Fix Released
Medium
Clayton O'Neill

Bug Description

    def flush_expired_tokens(self):
        session = self.get_session()

        query = session.query(TokenModel)
        query = query.filter(TokenModel.expires < timeutils.utcnow())
        query.delete(synchronize_session=False)

        session.flush()

This will basically result in this command being run (for MySQL anyway):

DELETE FROM token WHERE expires < '2013-06-05 21:02:00';

If there are millions of rows to delete, this will take a long time, which in turn will translate into replication lag if there is an active replication slave.

Also, because the keystone tokens are somewhat random 64 byte strings, there will be gaps in the InnoDB key storage. In order to preserve transactional integrity while deleting these rows, InnoDB has to lock these gaps. So new tokens that fit into these gaps will have to wait for the entire delete to finish to be inserted.

A much more healthy approach is to walk through the table deleting in small batches:

q = session.query(TokenModel).filter_by(TokenModel.expires < timeutils.utcnow())).limit(10).subquery()
while(session.query(TokenModel).filter(TokenModel.id.in_(q)).delete())
    pass

Dolph Mathews (dolph)
Changed in keystone:
importance: Undecided → Medium
status: New → Triaged
Revision history for this message
OpenStack Infra (hudson-openstack) wrote : Fix proposed to keystone (master)

Fix proposed to branch: master
Review: https://review.openstack.org/32044

Changed in keystone:
assignee: nobody → Clint Byrum (clint-fewbar)
status: Triaged → In Progress
Revision history for this message
Dolph Mathews (dolph) wrote :

Unassigning due to inactivity.

Changed in keystone:
assignee: Clint Byrum (clint-fewbar) → nobody
status: In Progress → Triaged
Revision history for this message
deactivateduser (deactivateduser-deactivatedaccount) wrote :

Is the bug still relevant?

Revision history for this message
Clint Byrum (clint-fewbar) wrote : Re: [Bug 1188378] Re: keystone.token.backends.sql uses a single delete command to flush expired tokens causing replication lag and potential deadlocks

Yes it is still relevant. In TripleO we still rely on pt-archiver rather
than the flush command to delete tokens, otherwise we see massive stalls
in token creation while tokens are flushed.

Excerpts from Ivan Kliuk's message of 2014-05-21 22:34:48 UTC:
> Is the bug still relevant?
>
> --
> You received this bug notification because you are subscribed to the bug
> report.
> https://bugs.launchpad.net/bugs/1188378
>
> Title:
> keystone.token.backends.sql uses a single delete command to flush
> expired tokens causing replication lag and potential deadlocks
>
> Status in OpenStack Identity (Keystone):
> Triaged
>
> Bug description:
> def flush_expired_tokens(self):
> session = self.get_session()
>
> query = session.query(TokenModel)
> query = query.filter(TokenModel.expires < timeutils.utcnow())
> query.delete(synchronize_session=False)
>
> session.flush()
>
>
> This will basically result in this command being run (for MySQL anyway):
>
> DELETE FROM token WHERE expires < '2013-06-05 21:02:00';
>
> If there are millions of rows to delete, this will take a long time,
> which in turn will translate into replication lag if there is an
> active replication slave.
>
> Also, because the keystone tokens are somewhat random 64 byte strings,
> there will be gaps in the InnoDB key storage. In order to preserve
> transactional integrity while deleting these rows, InnoDB has to lock
> these gaps. So new tokens that fit into these gaps will have to wait
> for the entire delete to finish to be inserted.
>
> A much more healthy approach is to walk through the table deleting in
> small batches:
>
> q = session.query(TokenModel).filter_by(TokenModel.expires < timeutils.utcnow())).limit(10).subquery()
> while(session.query(TokenModel).filter(TokenModel.id.in_(q)).delete())
> pass
>
> To manage notifications about this bug go to:
> https://bugs.launchpad.net/keystone/+bug/1188378/+subscriptions

Changed in keystone:
assignee: nobody → Clayton O'Neill (clayton-oneill)
status: Triaged → In Progress
Revision history for this message
OpenStack Infra (hudson-openstack) wrote : Fix merged to keystone (master)

Reviewed: https://review.openstack.org/101726
Committed: https://git.openstack.org/cgit/openstack/keystone/commit/?id=465debfa760901f3309fd83b30d796ee6282430b
Submitter: Jenkins
Branch: master

commit 465debfa760901f3309fd83b30d796ee6282430b
Author: Clayton O'Neill <email address hidden>
Date: Tue Jun 17 01:34:18 2014 +0000

    Add pluggable range functions for token flush

    This patch refactors the flush tokens functionality to have a pluggable
    expiration range strategy that can be customized based on database
    backend. The batch size method has been replaced with a method that
    will return an appropriate iterator for choosing expiration ranges.

    This patch also allows MySQL to use the batch flush functionality to
    alleviate problems with Galera replication and large write sets. Galera
    has a modest size limit (1GB) on how large write sets can grow and this
    can be reached fairly easily if you run expiration infrequently, or just
    have a high token issue rate.

    This also changes the mechanism to do batch flushes to a more portable
    mechanism that does not require subquery support w/LIMIT. MySQL does
    not support DELETE with a subquery that uses LIMIT.

    The batch expiration strategy will return a timestamp each time it's
    called. The flush function will then delete all expired tokens up to
    that timestamp. It is possible that this will delete somewhat more than
    the `batch_size` number of rows, but it is expected that it will
    typically be close to that number, and will effectively chunk the work
    into roughly equal size batches.

    Closes-Bug: 1188378
    Change-Id: I2df68a35691e001083f41f43e9c325bd687f7ec8

Changed in keystone:
status: In Progress → Fix Committed
Thierry Carrez (ttx)
Changed in keystone:
milestone: none → juno-3
status: Fix Committed → Fix Released
Thierry Carrez (ttx)
Changed in keystone:
milestone: juno-3 → 2014.2
To post a comment you must log in.
This report contains Public information  
Everyone can see this information.

Other bug subscribers

Remote bug watches

Bug watches keep track of this bug in other bug trackers.