AuthLogic seems to update the user record multiple times for one request

Question

For one action request I see about 6 counts of what seems to be AuthLogic related record updates for the User model. I am wondering if this is normal, or if anyone else has encountered this and what can I do about it. I'm still trying to track down the cause of this, but I highly suspect it's AuthLogic related.

As you can see the updates to the record are quite slow and having all of these happen within one request is worrisome!

SQL (0.1ms)  BEGIN
  AREL (0.6ms)  UPDATE `users` SET `last_request_at` = '2012-06-22 22:02:43', `perishable_token` = 'rGvsUjfDYw4lrFk6bYJu', `updated_at` = '2012-06-22 22:02:43' WHERE `users`.`id` = 6697
  SQL (91.8ms)  COMMIT
  User Load (0.7ms)  SELECT `users`.* FROM `users` WHERE `users`.`id` = 6697 LIMIT 1
  SQL (0.2ms)  BEGIN
  AREL (0.5ms)  UPDATE `users` SET `last_request_at` = '2012-06-22 22:02:43', `perishable_token` = 'CHSKWhMmNHB5h8HeAWI', `updated_at` = '2012-06-22 22:02:43' WHERE `users`.`id` = 6697
  SQL (43.2ms)  COMMIT
  User Load (0.7ms)  SELECT `users`.* FROM `users` WHERE `users`.`id` = 6697 LIMIT 1
  SQL (0.2ms)  BEGIN
  AREL (0.5ms)  UPDATE `users` SET `last_request_at` = '2012-06-22 22:02:44', `perishable_token` = 'yDEGFCy4JrKrLVOKhwP', `updated_at` = '2012-06-22 22:02:44' WHERE `users`.`id` = 6697
  SQL (43.4ms)  COMMIT

User Load (0.7ms)  SELECT `users`.* FROM `users` WHERE `users`.`id` = 6697 LIMIT 1
  SQL (0.1ms)  BEGIN
  AREL (0.3ms)  UPDATE `users` SET `last_request_at` = '2012-06-22 22:02:44', `perishable_token` = 'TSrzZCKL2C0R5BPJAkVA', `updated_at` = '2012-06-22 22:02:44' WHERE `users`.`id` = 6697
  SQL (36.6ms)  COMMIT
  User Load (0.7ms)  SELECT `users`.* FROM `users` WHERE `users`.`id` = 6697 LIMIT 1
  SQL (0.1ms)  BEGIN
  AREL (0.3ms)  UPDATE `users` SET `last_request_at` = '2012-06-22 22:02:44', `perishable_token` = 'hfRuoHYvIQZCdd8obtA', `updated_at` = '2012-06-22 22:02:44' WHERE `users`.`id` = 6697
  SQL (38.4ms)  COMMIT

Answer 1

I dug around and found a solution:

UserSession.last_request_at_threshold = 10.minutes

As I understand the place to set this - is in UserSession. ( This can be set in initalizer as well, like authlogic.rb)

The reason there are multiple updates is that it updates last_request_at EVERY time you do some kind of check against current_user. For instance when you use sign in status for some kind of work flow - i.e. to display menu items or parts of the page only for the users that are logged in.

Once you set last_request_at to a larger threshold - you get rid of these updates. For me that gets rid of about 10 update statements - each was taking about 0.5 ms - not a big his, but considering that I have 100 users ( internal app) - using this app all the time, and I don't need to track their last requests ( they are either in the building or not), I can limit it or even stop tracking it altogether - over the course of the day that's a 10's of thousands of extra updates to the db I don't need to make - and makes reading logs easier.

UPDATE

Even if you set it to just 1 second - that will still help - because now it will only update once of every request ( assuming your app doesn't have requests that take longer than a second - if you do that maybe a sign of another problem) Even if you check against current_user multiple times in the same request. I doubt there are any humans that can do multiple different requests at the same second.

Hope this helps

P.S.: Here is the q that started me on the right path: AuthLogic perishable_token resets on every request