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

Have you found the cause? I'm seeing the same issue. – konung Dec 04 '13 at 22:01 — konung, Dec 04 '13 at 22:01

score 3 · Accepted Answer · edited May 23 '17 at 11:51

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

score 0 · Answer 2 · answered Apr 14 '22 at 06:38

If you don't need to know the last time a user requested a page, you can simply remove the database field and Authlogic won't do anything.

Every time a session is found the last_request_at field for that record is updated with the current time, if that field exists. https://github.com/binarylogic/authlogic/blob/0c9da9db0cafd28c8abe5528549dac6c639a0dbd/lib/authlogic/session/base.rb#L828-L829

For example to generate a rails migration:

rails generate migration RemoveLastRequestAtFromUsers last_request_at:datetime

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

2 Answers2