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.
Memory leak(s) would probably be the first suspect.
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