415306 - Log out takes a long time

Status: VERIFIED FIXED

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

Description

[Jason Barnabe (np)]

Log out takes over a minute sometimes. Not sure what's taking so long.

Comment 1

[Chris Ilias [:cilias]]

I was experiencing this a few days ago, but since the sync on Thursday, the delay is around 5 seconds.

Comment 2

[Jason Barnabe (np)]

I haven't noticed any improvement lately. It's not consistent, sometimes it's fast, sometimes it's slow.

Comment 3

[Jason Barnabe (np)]

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.

Comment 4

[Michael Morgan [:morgamic]]

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'

Comment 5

[Nelson Ko [:nkoth]]

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]

Comment 6

[Michael Morgan [:morgamic]]

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?

Comment 7

[Michael Morgan [:morgamic]]

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.

Comment 8

[Nelson Ko [:nkoth]]

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?

Comment 9

[Nelson Ko [:nkoth]]

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?

Comment 10

[Michael Morgan [:morgamic]]

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.

Comment 11

[Nelson Ko [:nkoth]]

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.

Comment 12

[Nelson Ko [:nkoth]]

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?

Comment 13

[Michael Morgan [:morgamic]]

Yeah, or I could also get you access to a dump of the database as well.

Comment 14

[Nelson Ko [:nkoth]]

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.

Comment 15

[Michael Morgan [:morgamic]]

Alright, workin on getting that db dump.

Comment 16

[Nelson Ko [:nkoth]]

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)

Comment 17

[Nelson Ko [:nkoth]]

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 18

[Nelson Ko [:nkoth]]

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)

Comment 19

[Nelson Ko [:nkoth]]

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.

Comment 20

[Majken Connor [:Kensie]]

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?

Comment 21

[Michael Morgan [:morgamic]]

What?

Comment 22

[Nelson Ko [:nkoth]]

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.

Comment 23

[Laura Thomson :laura]

This seems to be solved, closing.

Comment 24

[Chris Ilias [:cilias]]

-->0.7

Comment 25

[Laura Thomson :laura]

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.

Comment 26

[Laura Thomson :laura]

When I say we, of course I mean xb95 ;)

Comment 27

[Mark Smith [: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...)

Comment 28

[David Tenser [:djst]]

Wow, I can really confirm the difference now that the sessions table is purged!

Comment 29

[David Tenser [:djst]]

Mass-moving P1 bugs to 0.6.1.

Comment 31

[Mark Smith [:xb95]]

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!

Comment 32

[Laura Thomson :laura]

Attachment: Take the BINARY out of the session

Nelson, do you see any reason not to do this?

Comment 33

[Nelson Ko [:nkoth]]

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?

Comment 34

[Laura Thomson :laura]

Attachment: revised patch, missed some binaries

Comment 35

[Laura Thomson :laura]

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.

Comment 36

[Mark Smith [:xb95]]

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.

Comment 37

[Laura Thomson :laura]

Patch committed in trunk in r17373, branch in r17374.

Database change info is in the push bug, bug 447901.

Comment 38

[Stephen Donner [:stephend] Not actively reading bugmail]

Verified FIXED; I haven't seen this since, I don't think.