Aug 14, 2011
tom

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 cachedPID 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.

Answer

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

Related posts:

  1. Only 192.168.0.3 can request most files, but anyone can request /public/file.html
  2. Apache config to direct all request to one virtual host, except request on direct IP or specified
  3. Slower response time on server caused by CentOS version
  4. IIS Request Filtering blocks Application Request Routing
  5. Facing error: “Could not open a connection to your authentication agent.”; trying to add ssh-key

Leave a comment