Server slower for each successive request

Question

Application stack (all using latest stable releases):

Ubuntu
Apache
Passenger
Ruby
Ruby on Rails

After restarting apache (apache2ctl graceful) a page request is pretty fast, some 600 ms. Then, for every request (same page still, just reloading), the page load time goes up with 250-500 ms per request. So after 20 something requests I'm at about 10 seconds loading the same page.

Looking at the load times both in the rails log and webkit inspector they go up. The page loads are simple GETs, i.e. no additional data.

Any thoughts on what could be the reason for this? Also, let me know if I should elaborate on anything.

Second pageload:

Rails log excerpt

Started GET "/categories" for 214.200.52.199 at Mon Oct 25 20:38:02 +0000 2010
  Processing by CategoriesController#index as HTML
Rendered shared/sections/_settings.html.haml (101.6ms)
Rendered layouts/_header.html.haml (172.0ms)
Rendered layouts/_footer.html.haml (2.8ms)
Rendered categories/index.html.haml within layouts/application (319.3ms)
Completed 200 OK in 339ms (Views: 320.1ms)

Top

top - 20:54:46 up 1 day,  1:17,  5 users,  load average: 0.24, 0.09, 0.06
Tasks:  41 total,   3 running,  38 sleeping,   0 stopped,   0 zombie
Cpu(s):  0.0%us,  0.3%sy,  0.3%ni, 99.3%id,  0.0%wa,  0.0%hi,  0.0%si,  0.0%stMem:   1048576k total,   638576k used,   410000k free,        0k buffers
Swap:        0k total,        0k used,        0k free,        0k cached



PID USER      PR  NI  VIRT  RES  SHR S %CPU %MEM    TIME+  COMMAND                                                                                          32602 root      21   0 32152 2284 1904 S  0.3  0.2   0:00.01 PassengerHelper                                                                                   
    1 root      15   0 23300 1580 1264 S  0.0  0.2   0:02.25 init                                                                                               2024 alexande  25   0  172m  97m 3028 S  0.0  9.5   0:04.35 ruby1.8                                                                                           
 3317 alexande  18   0  176m 100m 1956 S  0.0  9.8   0:00.90 ruby1.8                                                                                            3348 root      15   0 47704 1792 1396 S  0.0  0.2   0:00.01 su                                                                                                 3460 root      15   0 75600 4140 2672 S  0.0  0.4   0:00.23 apache2                                                                                           
 3570 root      15   0 19436 2216 1612 S  0.0  0.2   0:00.00 bash                                                                                               7519 root      16   0 79120 3472 2708 S  0.0  0.3   0:00.01 sshd                                                                                              
 7663 alexande  15   0 79260 1784  900 S  0.0  0.2   0:00.14 sshd                                                                                               7664 alexande  15   0 19424 2224 1632 S  0.0  0.2   0:00.13 bash                                                                                               8103 root      16   0 79120 3476 2708 S  0.0  0.3   0:00.01 sshd                                                                                              
 8156 alexande  15   0 79120 1676  888 R  0.0  0.2   0:01.57 sshd                                                                                               8157 alexande  16   0 19416 2204 1624 S  0.0  0.2   0:00.00 bash                                                                                               9273 root      16   0 79124 3492 2720 S  0.0  0.3   0:00.01 sshd                                                                                              
 9426 root      15   0 47704 1792 1396 S  0.0  0.2   0:00.00 su                                                                                                 9515 alexande  15   0 79124 1656  856 S  0.0  0.2   0:00.00 sshd                                                                                               9517 alexande  15   0 19416 2212 1628 S  0.0  0.2   0:00.01 bash                                                                                              
 9550 root      16   0 19508 2272 1620 S  0.0  0.2   0:00.03 bash                                                                                              11660 mongodb   17   0  193m  23m  20m R  0.0  2.3   0:09.26 mongod                                                                                            11747 root      15   0  9744  872  704 S  0.0  0.1   0:00.02 tail                                                                                              
13349 alexande  15   0  9744  864  704 S  0.0  0.1   0:00.06 tail                                                                                              15560 root      15   0 47704 1796 1396 S  0.0  0.2   0:00.00 su                                                                                                15622 root      15   0 19612 2376 1620 S  0.0  0.2   0:00.24 bash                                                                                              
15660 root      15   0 19076 1316 1048 R  0.0  0.1   0:05.07 top                                                                                               19754 root      15   0 49248 1080  540 S  0.0  0.1   0:00.24 sshd                                                                                              19755 messageb  15   0 23540 1168  792 S  0.0  0.1   0:00.44 dbus-daemon                                                                                       
19769 root      15   0 21064  888  680 S  0.0  0.1   0:00.32 cron                                                                                              19770 root      15   0 20392 1636  816 S  0.0  0.2   0:00.21 syslog-ng                                                                                         20465 root      15   0 58520 5136 2432 S  0.0  0.5   0:02.75 console-kit-dae                                                                                   
22385 root      16   0 79120 3476 2708 S  0.0  0.3   0:00.02 sshd                                                                                              22440 alexande  15   0 79120 1692  888 S  0.0  0.2   0:00.54 sshd                                                                                              22441 alexande  15   0 19416 2204 1624 S  0.0  0.2   0:00.00 bash                                                                                              
32126 root      16   0 79120 3476 2708 S  0.0  0.3   0:00.01 sshd                                                                                              32204 alexande  15   0 79120 1688  888 S  0.0  0.2   0:00.04 sshd                                                                                              32205 alexande  15   0 19420 2224 1632 S  0.0  0.2   0:00.06 bash                                                                                              
32323 alexande  15   0  9744  868  704 S  0.0  0.1   0:00.29 tail                                                                                              32598 www-data  15   0 75600 1984  508 S  0.0  0.2   0:00.00 apache2                                                                                           32599 root      20   0 23224 1860 1584 S  0.0  0.2   0:00.00 PassengerWatchd                                                                                   
32603 root      17   0 53944  16m 1588 S  0.0  1.6   0:00.21 ruby1.8                                                                                           32606 nobody    18   0 71976 3696 2920 S  0.0  0.4   0:00.00 PassengerLoggin                                                                                   
32613 www-data  17   0  290m 3668 1756 S  0.0  0.3   0:00.00 apache2

Fifteenth pageload:

Rails log excerpt

Started GET "/categories" for 214.200.52.199 at Mon Oct 25 20:44:59 +0000 2010
  Processing by CategoriesController#index as HTML
Rendered shared/sections/_settings.html.haml (4554.7ms)
Rendered layouts/_header.html.haml (1718.4ms)
Rendered layouts/_footer.html.haml (2.8ms)
Rendered categories/index.html.haml within layouts/application (6446.8ms)
Completed 200 OK in 6821ms (Views: 6447.6ms)

Top

top - 20:48:22 up 1 day,  1:11,  5 users,  load average: 0.02, 0.10, 0.08
Tasks:  40 total,   2 running,  38 sleeping,   0 stopped,   0 zombie
Cpu(s):  0.3%us,  0.3%sy,  0.0%ni, 99.3%id,  0.0%wa,  0.0%hi,  0.0%si,  0.0%stMem:   1048576k total,   548404k used,   500172k free,        0k buffers
Swap:        0k total,        0k used,        0k free,        0k cached
  PID USER      PR  NI  VIRT  RES  SHR S %CPU %MEM    TIME+  COMMAND                                                                                          11660 mongodb   15   0  193m  23m  20m S  0.3  2.3   0:08.98 mongod                                                                                            
    1 root      15   0 23300 1580 1264 S  0.0  0.2   0:02.25 init                                                                                               3348 root      15   0 47704 1792 1396 S  0.0  0.2   0:00.01 su                                                                                                
 3460 root      15   0 75600 4136 2672 S  0.0  0.4   0:00.22 apache2                                                                                            3570 root      15   0 19436 2216 1612 S  0.0  0.2   0:00.00 bash                                                                                               7519 root      16   0 79120 3472 2708 S  0.0  0.3   0:00.01 sshd                                                                                              
 7663 alexande  15   0 79260 1784  900 S  0.0  0.2   0:00.14 sshd                                                                                               7664 alexande  15   0 19424 2224 1632 S  0.0  0.2   0:00.13 bash                                                                                              
 8103 root      16   0 79120 3476 2708 S  0.0  0.3   0:00.01 sshd                                                                                               8156 alexande  15   0 79120 1676  888 R  0.0  0.2   0:01.54 sshd                                                                                               8157 alexande  16   0 19416 2204 1624 S  0.0  0.2   0:00.00 bash                                                                                              
 9273 root      16   0 79124 3492 2720 S  0.0  0.3   0:00.01 sshd                                                                                               9426 root      15   0 47704 1792 1396 S  0.0  0.2   0:00.00 su                                                                                                 9515 alexande  15   0 79124 1656  856 S  0.0  0.2   0:00.00 sshd                                                                                              
 9517 alexande  15   0 19416 2212 1628 S  0.0  0.2   0:00.01 bash                                                                                               9550 root      16   0 19508 2272 1620 S  0.0  0.2   0:00.03 bash                                                                                               9574 www-data  15   0 75600 1980  508 S  0.0  0.2   0:00.00 apache2                                                                                           
 9575 root      20   0 23224 1856 1584 S  0.0  0.2   0:00.00 PassengerWatchd                                                                                    9577 root      22   0 33308 3012 1904 S  0.0  0.3   0:00.40 PassengerHelper                                                                                    9578 root      15   0 53944  16m 1588 S  0.0  1.6   0:00.60 ruby1.8                                                                                           
 9582 nobody    15   0 71976 3696 2920 S  0.0  0.4   0:00.00 PassengerLoggin                                                                                    9593 www-data  17   0  290m 4540 1812 S  0.0  0.4   0:00.04 apache2                                                                                           11401 alexande  18   0  176m 100m 1956 S  0.0  9.8   0:48.31 ruby1.8                                                                                           
11747 root      15   0  9744  872  704 S  0.0  0.1   0:00.02 tail                                                                                              13349 alexande  15   0  9744  864  704 S  0.0  0.1   0:00.06 tail                                                                                              15560 root      15   0 47704 1796 1396 S  0.0  0.2   0:00.00 su                                                                                                
15622 root      15   0 19612 2376 1620 S  0.0  0.2   0:00.24 bash                                                                                              15660 root      15   0 19076 1316 1048 R  0.0  0.1   0:04.84 top                                                                                               19754 root      15   0 49248 1080  540 S  0.0  0.1   0:00.24 sshd                                                                                              
19755 messageb  15   0 23540 1168  792 S  0.0  0.1   0:00.44 dbus-daemon                                                                                       19769 root      15   0 21064  888  680 S  0.0  0.1   0:00.32 cron                                                                                              19770 root      15   0 20392 1636  816 S  0.0  0.2   0:00.21 syslog-ng                                                                                         
20465 root      19   0 58520 5124 2432 S  0.0  0.5   0:02.73 console-kit-dae                                                                                   22385 root      16   0 79120 3476 2708 S  0.0  0.3   0:00.02 sshd                                                                                              22440 alexande  15   0 79120 1692  888 S  0.0  0.2   0:00.53 sshd                                                                                              
22441 alexande  15   0 19416 2204 1624 S  0.0  0.2   0:00.00 bash                                                                                              32126 root      16   0 79120 3476 2708 S  0.0  0.3   0:00.01 sshd                                                                                              32204 alexande  15   0 79120 1688  888 S  0.0  0.2   0:00.04 sshd                                                                                              
32205 alexande  15   0 19420 2224 1632 S  0.0  0.2   0:00.06 bash                                                                                              32323 alexande  15   0  9744  868  704 S  0.0  0.1   0:00.28 tail

*code blocks are bugged, don't know why.

score 1 · Answer 1 · answered Oct 25 '10 at 21:19

1

Memory leak(s) would probably be the first suspect.

answered Oct 25 '10 at 21:19

user48838

7,393
2
17
14

Looking at memory used in top there is a slight increase, 20%, but still 500 mb free and the 20% increase is far from the ~900% increase in load times. However, I'm no expert at this (hence my question), so I will look into memory leaks. Would they be in apache or rails? What is the main reason why you suspect memory leaks? – sandstrom Oct 25 '10 at 21:37
1

I'd assume the leaks are in rails or the ruby VM; older versions had known memory leaks (leading to suggestions of restarting apache every few minutes to work around them); apache doesn't have significant memory leaks for most usage. – James Polley Oct 25 '10 at 22:01
1

Memory leaks are a common cause of performance degradation. Even if your system's ram isn't full, it's possible the increase in RAM (wait - you said 20% increase in usage after 15 page loads? Ouch!) is causing other issues - possibly hitting some limit in the Ruby VM, possibly robbing the system of sufficient space to cache files. – James Polley Oct 25 '10 at 22:03
1

It could be some other kind of leak though: maybe your app isn't releasing database connections, or isn't closing sockets or files. You could even just have some logic bug that's causing it to iterate over a loop the number of pages it has loaded, and doing something time-consuming inside that loop – James Polley Oct 25 '10 at 22:04
James Polley is all over this and on track! Another type/source of leaks may be intrinsic to the code/application itself where variables or heap space (compiler memory model) is overrunning what was originally intended (or its possible occurrence was overlooked/unanticipated). One possible approach is to track the running/operating history of when the difficulties started and what may have changed last - prior the first occurrence. – user48838 Oct 26 '10 at 00:11
How would I detect the memory leak? Since top still shows 500mb of free ram and the ruby process only use about 9-10% (CPU is maxed out during a request though). I thought the sign of a memory leak would be that memory usage up to maximum memory available. Also, although memory free decreased in top (above) memory free still increased. Is that reasonable? – sandstrom Oct 26 '10 at 07:40
"One possible approach is to track the running/operating history of when the difficulties started and what may have changed last - prior the first occurrence." – user48838 Oct 26 '10 at 08:02

score 0 · Accepted Answer · answered Nov 02 '10 at 19:46

0

Memory bloat the second suspect: http://www.engineyard.com/blog/2009/thats-not-a-memory-leak-its-bloat/

Since your uri is /categories, I suppose that you are displaying all the categories. If there's a huge pile of them and you're querying them all it could result in a lot of active record objects in you memory (but that's just a guess) and keep the process size growing.

You can have a look at http://github.com/noahd1/oink to track which object are the most instanciated

answered Nov 02 '10 at 19:46

hellvinz

2,886
2
16
8

Thanks, found it a few days ago and it was memory bloat. I was loading settings data into an array on every request (which should have loaded only once). – sandstrom Nov 04 '10 at 15:03

Server slower for each successive request

Second pageload:

Rails log excerpt

Top

Fifteenth pageload:

Rails log excerpt

Top

2 Answers2