“Garbage collection occurs too frequently on high traffic sites, no column index” – Issues – Discuss

3 users online. Create an account or sign in to join them.Users

Garbage collection occurs too frequently on high traffic sites, no column index

A bug in 2.2.2, submitted by nickdunn on 08 June 2011

Announcement

Symphony's issue tracker has been moved to Github.

Issues are displayed here for reference only and cannot be created or edited.

Browse

Closed#649: Garbage collection occurs too frequently on high traffic sites, no column index

- nickdunn
- Comment #1
- 08 Jun 11, 7:14 pm

We've found that PHP's session garbage collection occurs very frequently on large sites. This is down to the value of session.gc_divisor that is set in class.session.php. On the site in question this was set to 3, meaning that the garbage collector runs in every 1 in 3 processes. I believe this was running a couple of times per second and peak times.

2.2.2 seems to have a value of 10 hard coded into the file. Is there a chance this could be moved to a config value instead? PHP's default is 100, which is more like what we need for this site.

Secondly it was noted that the sessions table did not have an index for the session_data column. Is there a reason why not, is it memory-intensive to maintain an index on a table of this potential size? I wonder if a FULLTEXT index on this might improve performance when running the REGEXP query against this column. A quick test with 15,000 rows yielded no performance difference with and without the index, but thought it worth mentioning.

The full comment from the site's DBA:

==========

Today I've noticed problems with a high number of concurrent sessions, nearly all connected to [sitename] database. The majority of sessions are waiting on locked objects. In this case, I believe it's the entire table that's locked. Here's an excerpt from the MySQL processlist:

| 9763949 | web_sitename | 10.45.13.110:33225 | sitename | Query | 5 | Locked | INSERT INTO `sym_sessions` (`session`, `session_expires`, `session_data`) VALUES ('hrbgujae459jb9mc1 | 
| 9763952 | web_sitename | 10.45.13.110:33227 | sitename | Query | 6 | Locked | INSERT INTO `sym_sessions` (`session`, `session_expires`, `session_data`) VALUES ('oh1uov0pa4ths18n7 | 
| 9763953 | web_sitename | 10.45.13.110:33228 | sitename | Query | 5 | Locked | INSERT INTO `sym_sessions` (`session`, `session_expires`, `session_data`) VALUES ('qsemcve0aeg4ank7g | 
| 9763954 | web_sitename | 10.45.13.110:33230 | sitename | Query | 3 | Locked | INSERT INTO `sym_sessions` (`session`, `session_expires`, `session_data`) VALUES ('fc8mm3ncls4ame7hb | 
| 9763956 | web_sitename | 10.45.13.110:33231 | sitename | Query | 5 | Locked | INSERT INTO `sym_sessions` (`session`, `session_expires`, `session_data`) VALUES ('14qa8o5m7c7vjvad2 | 
| 9763958 | web_sitename | 10.45.13.110:33232 | sitename | Query | 4 | Locked | INSERT INTO `sym_sessions` (`session`, `session_expires`, `session_data`) VALUES ('mqscoepmlrd09pqte | 
| 9763959 | web_sitename | 10.45.13.110:33234 | sitename | Query | 5 | Locked | INSERT INTO `sym_sessions` (`session`, `session_expires`, `session_data`) VALUES ('hrbgujae459jb9mc1 | 
| 9763960 | web_sitename | 10.45.13.110:33236 | sitename | Query | 4 | Locked | INSERT INTO `sym_sessions` (`session`, `session_expires`, `session_data`) VALUES ('45v74t9gff3n25uov | 
| 9763961 | web_sitename | 10.45.13.110:33238 | sitename | Query | 6 | updating | DELETE FROM `sym_sessions` WHERE `session_expires` <= '1305721678' OR `session_data` REGEXP '^([^}]+ | 
| 9763962 | web_sitename | 10.45.13.110:33239 | sitename | Query | 3 | Locked | INSERT INTO `sym_sessions` (`session`, `session_expires`, `session_data`) VALUES ('toisccl6inhi6q7qk | 
| 9763963 | web_sitename | 10.45.13.110:33240 | sitename | Query | 1 | Locked | INSERT INTO `sym_sessions` (`session`, `session_expires`, `session_data`) VALUES ('h3jnrh2lee0vtu9fk | 
| 9763964 | web_sitename | 10.45.13.110:33241 | sitename | Query | 5 | Locked | INSERT INTO `sym_sessions` (`session`, `session_expires`, `session_data`) VALUES ('052mfcudt8ch23h0j | 
| 9763966 | web_sitename | 10.45.13.110:33242 | sitename | Query | 5 | Locked | INSERT INTO `sym_sessions` (`session`, `session_expires`, `session_data`) VALUES ('oh1uov0pa4ths18n7 | 
| 9763967 | web_sitename | 10.45.13.110:33243 | sitename | Query | 5 | Locked | INSERT INTO `sym_sessions` (`session`, `session_expires`, `session_data`) VALUES ('dhhuol2n2r0fvsuvk | 
| 9763968 | web_sitename | 10.45.13.110:33244 | sitename | Query | 5 | Locked | INSERT INTO `sym_sessions` (`session`, `session_expires`, `session_data`) VALUES ('j7mhsv82vpiegtvje | 
| 9763969 | web_sitename | 10.45.13.110:33245 | sitename | Query | 5 | Locked | INSERT INTO `sym_sessions` (`session`, `session_expires`, `session_data`) VALUES ('mr20hubecijqb9ak3 | 
| 9763971 | web_sitename | 10.45.13.110:33246 | sitename | Query | 4 | Locked | INSERT INTO `sym_sessions` (`session`, `session_expires`, `session_data`) VALUES ('mkb4akkpmbri847ju | 
| 9763972 | web_sitename | 10.45.13.110:33247 | sitename | Query | 5 | Locked | INSERT INTO `sym_sessions` (`session`, `session_expires`, `session_data`) VALUES ('7m75ebvnfvr45scms |

The problem is the "Delete" operation, e.g.:

9781542 Query DELETE FROM `sym_sessions` WHERE `session_expires` <= '1305723076' OR `session_data` REGEXP '^([^}]+\|a:0:{})+$' 
9781559 Query DELETE FROM `sym_sessions` WHERE `session_expires` <= '1305723076' OR `session_data` REGEXP '^([^}]+\|a:0:{})+$' 
9781561 Query DELETE FROM `sym_sessions` WHERE `session_expires` <= '1305723076' OR `session_data` REGEXP '^([^}]+\|a:0:{})+$'

It's doing a table scan each time it runs and locking the table for its duration, I believe. Hence any "select" against the sym_sessions table is queued on a lock wait for the duration.

There are perhaps three problems as I see it with this piece of SQL:

the regular expression in the conditions means an index can't be used - resulting in a table scan
the statement itself is running too frequently - more than twice a second according to the latest instance log
the statement is being issued containing identical timestamps in sequence - the logs shows an example of 15 identical DELETEs; this seems unnecessary

- brendo
- Comment #2
- 08 Jun 11, 9:52 pm

Spoken directly to Nick about this. The site in question in a 2.1.1 build, so the majority of the issue has been solved in more recent versions.

The one thing I would like to take from this is adding the Session gc as a Configuration option, so that sites with a lot of traffic can adjust the value as necessary.

- brendo
- Comment #3
- 12 Jun 11, 11:07 pm

Added a new configuration setting, session_gc_divisor in this commit

This issue is closed.

Symphony.