Closed Bug 415306 Opened 13 years ago Closed 13 years ago

Log out takes a long time

Categories

(support.mozilla.org :: General, defect)

defect
Not set
major

Tracking

(Not tracked)

VERIFIED FIXED

People

(Reporter: jason.barnabe, Assigned: laura)

References

Details

(Whiteboard: tiki_test)

Attachments

(1 file, 1 obsolete file)

Log out takes over a minute sometimes. Not sure what's taking so long.
I was experiencing this a few days ago, but since the sync on Thursday, the delay is around 5 seconds.
I haven't noticed any improvement lately. It's not consistent, sometimes it's fast, sometimes it's slow.
Since the update, this takes an incredibly long time. Also, after checking with people on IRC, it makes sumo not load for *everybody*, not just the user trying to log out.
Context:
File	tiki-logout.php
Url	tiki-logout.php
Query:
select `groupName` from `users_usergroups` where `userId`=?
Values:
0	1417
Message:
MySQL server has gone away
Built query was probably:
select `groupName` from `users_usergroups` where `userId`='1417'
I have been aware of it and had the intention to investigate further. I think this happened after I added garbage collection of db sessions, but left that in there because I was not comfortable with the db growing with sessions. But that query to remove sessions can't take that long that the MySQL server times out, can it? 

refer to [change to tikilib.php revision 9302 and 9303]

Pretty sure this is caused in lib/adodb/session/adodb-session.php:
$sql = "UPDATE $table SET expiry = $expiry, $data = $lob_value, expireref=$expiryref WHERE  sesskey = $qkey";

But that's probably a level too high.  I need to find where we are setting data = 'everything ever seen in the universe'.  Example of this is here:
http://pastebin.mozilla.org/323632

Nelson, any ideas?  Think we could cut down on how much crap gets thrown into the adodb sessions table?

It's more the UPDATE causing table locks that backs things up server-wide.  If we figure out where the query in the pastebin link is coming from and either eliminate it or control it, we'll be in better shape.
my 	$query = "delete from `sessions` where `expiry`<?";

causes table lock on sessions right? If so, then it will explain why noone else can connect because they need to create something in this table. Is there a way to do this delete without locking the table, since it is just garbage collection anyway?
I am thinking also that non-logged in users don't really need adodb sessions, right? If that is the case, we totally bypass the use adodb sessions until a user logs in?
You could opt to delete sessions by ID, or do a query for all session IDs with expiry < now() then do a delete from sessions where id in(....stuff....) but not sure if that'd avoid the lock.

But yeah, I agree more with comment #9 -- if we can eliminate that, I think the query volume would be cut quite a bit.  We lose a lot in tiki-setup.php + adodb sessions on every request.
Severity: normal → major
changes made to:
1) give adodb session only on captcha and attempt to login
2) remove individual adodb session on logout
3) clean up rest of adodb sessions by individual deletes instead of one big delete to try and avoid lock

The other thing we could do is to convert the sessions table to InnoDB form MyISAM as InnoDB (but not MyISAM) supports row level locking vs. table level locking. But InnoDB uses much more memory, apparently. We could also memcached of course.

The changes seem to help only a little. I'm going to have to try and reproduce this problem on my machine (since I have no access to the db on the server). Another way is to schedule some time with IT to work on this.

morgamic, can that be done?
Yeah, or I could also get you access to a dump of the database as well.
yes, get me access to a dump first. I can then use that db on my server and see what happens before actually arranging a session. Thanks.
Alright, workin on getting that db dump.
I have removed the extra code that I have in tikilib.php (comment #8 and #12 above). After the next push, we will see if this solves the problem. If not, we have to hunt the problem down elsewhere.

(BTW, still unable to reproduce problem on my server, even with db dump)
I have also added a button in the admin...general panel to manually garbage collection the sessions (for debugging purposes, to see if this is the problem). This button causes a printout of the number if records in the table, and the number deleted when this is pressed.
Comment #16 did not work. So now another theory is that the following query might be the cause of db queries being blocked because of need to lock: delete `tiki_user_preferences` where `prefName`='cookie' and `user`=<user login>

fyi, this "cookie" that is referred to here is not the usual PHP session cookie, but actually the "Remember me" feature cookie, so I can't just remove it without breaking the remember me feature. There are ways to fix that, but first it will be necessary to find out if this is the cause. (The problem does not appear to be reproducable without simulating production load conditions)
I have made a change to not run this query when user is not using remember me.

So there are now no DELETE queries on logout anymore. But the problem still exists.

I'm out of ideas.


Hrm is this possibly similar to bugzilla's issue before it asynced the email notifications?  Maybe the logged out page is loading later in the process than necessary?
Priority: -- → P1
Target Milestone: --- → 0.6
This appears to be OK after sumo was taken off the netapp as per recommendations in bug 425134. Could it be that sessions_destroy required access to the netapp disk before? If so, we can conclude that that could have been the issue.
This seems to be solved, closing.
Status: NEW → RESOLVED
Closed: 13 years ago
Resolution: --- → FIXED
Status: RESOLVED → REOPENED
Resolution: FIXED → ---
-->0.7
Target Milestone: 0.6 → 0.7
Tonight we purged the sessions table, and boom, lightning fast.  The table was up to 2G, so I think that these are not getting purged correctly.

Next task: making sure the sessions table gets cleaned out appropriately.
When I say we, of course I mean xb95 ;)
It's also InnoDB now.

Is there a reason you have /*! BINARY */ in the queries?  That column you are using as an index is a VARCHAR or CHAR or something text, not a binary column.  Could you remove that?  It may be causing issues.

I'm trying to sort out what's causing the database not to use the index on the backup slave.  (It seems fine in production...)

(This might need to be a different bug, but I think it may be related to why it's taking so long...)
Wow, I can really confirm the difference now that the sessions table is purged!
Mass-moving P1 bugs to 0.6.1.
Priority: P1 → --
Target Milestone: 0.7 → 0.6.1
Assignee: nobody → laura
Status: REOPENED → NEW
Duplicate of this bug: 410098
mysql> explain select * from sessions WHERE /*! BINARY */ sesskey = '8mdm8ju3tfk35nla6jf88m68o4'   ;
+----+-------------+----------+------+---------------+------+---------+------+--------+-------------+
| id | select_type | table    | type | possible_keys | key  | key_len | ref  | rows   | Extra       |
+----+-------------+----------+------+---------------+------+---------+------+--------+-------------+
|  1 | SIMPLE      | sessions | ALL  | NULL          | NULL | NULL    | NULL | 368985 | Using where | 
+----+-------------+----------+------+---------------+------+---------+------+--------+-------------+
1 row in set (0.00 sec)

mysql> explain select * from sessions WHERE  sesskey = '8mdm8ju3tfk35nla6jf88m68o4'   ;
+----+-------------+----------+-------+---------------+---------+---------+-------+------+-------+
| id | select_type | table    | type  | possible_keys | key     | key_len | ref   | rows | Extra |
+----+-------------+----------+-------+---------------+---------+---------+-------+------+-------+
|  1 | SIMPLE      | sessions | const | PRIMARY       | PRIMARY | 34      | const |    1 |       | 
+----+-------------+----------+-------+---------------+---------+---------+-------+------+-------+
1 row in set (0.00 sec)

The column is VARCHAR, not sure why there's a BINARY flag there.  But if this is fixed, then logout and other session related work would be really fast.  Thanks!
Nelson, do you see any reason not to do this?
Attachment #331199 - Flags: review?(nelson)
According to ADODB changelogs:

The new code includes several bug fixes and enhancements:

* sesskey is compared in BINARY mode for MySQL, to avoid problems with
session keys that differ only by case.
  Of course, the user should define the sesskey field as BINARY, to
correctly fix this problem, otherwise performance will suffer.

What do you think?
In addition to this patch, xb95 says we need to convert the sesskey column to binary.   To do this we should truncate the table first, so it should be done in the maintenance window associated with this push.
Attachment #331199 - Attachment is obsolete: true
Attachment #331199 - Flags: review?(nelson)
Attachment #331225 - Flags: review?(nelson)
Attachment #331225 - Flags: review?(nelson) → review+
Just for background, converting to binary will give us the same benefit as using BINARY on the query - case sensitivity.  But it will allow us to use the index, instead of the index being discarded which is what happens when you force the query to BINARY.
Patch committed in trunk in r17373, branch in r17374.

Database change info is in the push bug, bug 447901.
Status: NEW → RESOLVED
Closed: 13 years ago13 years ago
Resolution: --- → FIXED
Verified FIXED; I haven't seen this since, I don't think.
Status: RESOLVED → VERIFIED
Whiteboard: tiki_triage
Whiteboard: tiki_triage → tiki_test
You need to log in before you can comment on or make changes to this bug.