[Catalyst] DProf
Octavian Rasnita
orasnita at gmail.com
Sat Nov 3 09:39:03 GMT 2007
From: "Jon Schutz" <jon+catalyst at youramigo.com>
> Hi Octavian,
>
> As useful as DProf is, it's giving you a global picture and not
> localising the parts of your app which are chewing up the time.
>
> Is TT really the problem? Have you seen a big difference in times
> reported against View::TT->process in the stats summary (seen with debug
> on) since introducing I18N?
Well, I have started Apache with a single process and I put apache bench
(ab) to make requests to the server, but when testing it, the processor
doesn't become very occupied.
But if I let the server work in its normal way, after a few hours I see that
there are very many tasks running, many apache processes, and the processor
becomes very used.
I also see that the memory usage increases even if in the moment I check
there are no many visitors for sure, and if I do an apache restart, the
memory usage and the processor usage problems are solved temporarily.
> If the TT render times are not substantially different, then your
> problem lies elsewhere and you might benefit from grabbing the current
> svn version of Catalyst with the new $c->profile() method, which would
> allow you to narrow down which parts of your code are taking the time.
>
> If it is TT, then I would take the approach of systematically removing
> parts of the template to isolate the cause.
>
> Have your response times changed substantially, or is it just more CPU
> being used for the same response time?
The response time also increases, and sometimes the server doesn't restart
because the processor is very used that I can connect very hard with ssh to
the server in some cases.
So I think I might have a memory leak in the program, and it might also
affect the processor usage... I don't know, and I don't know how to check if
I have a memory leak somewhere.
Here is the result of the top command when the processor is very used, and
then below it is the result of the same command after doing a service apache
restart:
top - 10:13:05 up 102 days, 21:55, 2 users, load average: 50.84, 51.63,
52.75
Tasks: 172 total, 51 running, 121 sleeping, 0 stopped, 0 zombie
Cpu(s): 99.9%us, 0.1%sy, 0.0%ni, 0.0%id, 0.0%wa, 0.0%hi, 0.0%si,
0.0%st
Mem: 8099328k total, 7988468k used, 110860k free, 222800k buffers
Swap: 8707220k total, 104352k used, 8602868k free, 1676436k cached
PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
26626 apache 25 0 494m 158m 3948 R 10 2.0 61:04.35 httpd
26716 apache 25 0 527m 190m 3980 R 10 2.4 46:21.67 httpd
26770 apache 25 0 493m 157m 3972 R 10 2.0 52:21.82 httpd
27110 apache 25 0 492m 156m 3980 R 10 2.0 49:22.97 httpd
28415 apache 25 0 479m 142m 3944 R 10 1.8 18:11.57 httpd
28458 apache 25 0 477m 141m 3944 R 10 1.8 17:36.15 httpd
28471 apache 25 0 477m 141m 3948 R 10 1.8 15:40.51 httpd
28474 apache 25 0 477m 141m 4024 R 10 1.8 14:23.98 httpd
28510 apache 25 0 477m 140m 3916 R 10 1.8 15:48.10 httpd
28532 apache 25 0 493m 157m 4024 R 10 2.0 10:07.61 httpd
28649 apache 25 0 482m 146m 4028 R 10 1.9 7:57.07 httpd
28667 apache 25 0 485m 149m 3944 R 10 1.9 9:09.52 httpd
28678 apache 25 0 483m 147m 3952 R 10 1.9 8:31.92 httpd
28720 apache 25 0 452m 116m 4048 R 10 1.5 1:56.92 httpd
28771 apache 25 0 472m 136m 3980 R 10 1.7 5:53.55 httpd
28772 apache 25 0 474m 138m 3908 R 10 1.8 6:42.63 httpd
27118 apache 25 0 525m 188m 4024 R 10 2.4 50:12.74 httpd
26906 apache 25 0 492m 156m 3968 R 9 2.0 55:05.21 httpd
27060 apache 25 0 493m 156m 3936 R 9 2.0 59:29.47 httpd
27087 apache 25 0 493m 156m 3960 R 9 2.0 49:26.85 httpd
28761 apache 25 0 475m 140m 3944 R 8 1.8 6:56.73 httpd
26894 apache 25 0 492m 155m 3952 R 8 2.0 56:00.53 httpd
26710 apache 25 0 493m 157m 3948 R 8 2.0 58:12.01 httpd
28581 apache 25 0 482m 146m 4020 R 7 1.9 7:56.28 httpd
24833 apache 25 0 506m 168m 4628 R 7 2.1 83:55.63 httpd
24919 apache 25 0 535m 175m 5596 R 7 2.2 88:26.80 httpd
26666 apache 25 0 491m 154m 3964 R 7 2.0 65:27.91 httpd
26673 apache 25 0 481m 145m 4064 R 7 1.8 63:37.92 httpd
26810 apache 25 0 494m 157m 3944 R 7 2.0 51:05.43 httpd
27055 apache 25 0 493m 156m 3980 R 7 2.0 53:40.21 httpd
27140 apache 25 0 479m 143m 4024 R 7 1.8 33:50.50 httpd
28404 apache 25 0 478m 142m 3948 R 7 1.8 19:32.12 httpd
28427 apache 25 0 478m 141m 3528 R 7 1.8 20:59.61 httpd
And after service apache restart after a few tens of seconds:
top - 10:14:35 up 102 days, 21:57, 2 users, load average: 17.20, 41.46,
49.13
Tasks: 120 total, 1 running, 119 sleeping, 0 stopped, 0 zombie
Cpu(s): 0.0%us, 0.1%sy, 0.0%ni, 99.9%id, 0.0%wa, 0.0%hi, 0.0%si,
0.0%st
Mem: 8099328k total, 2425352k used, 5673976k free, 222860k buffers
Swap: 8707220k total, 104352k used, 8602868k free, 1678760k cached
PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
29094 root 15 0 12612 1052 788 R 0 0.0 0:00.04 top
1 root 15 0 10316 552 520 S 0 0.0 0:41.94 init
2 root RT 0 0 0 0 S 0 0.0 0:01.61 migration/0
3 root 34 19 0 0 0 S 0 0.0 0:00.24 ksoftirqd/0
4 root RT 0 0 0 0 S 0 0.0 0:00.00 watchdog/0
5 root RT 0 0 0 0 S 0 0.0 0:01.52 migration/1
6 root 34 19 0 0 0 S 0 0.0 0:00.31 ksoftirqd/1
7 root RT 0 0 0 0 S 0 0.0 0:00.00 watchdog/1
8 root RT 0 0 0 0 S 0 0.0 0:02.11 migration/2
9 root 34 19 0 0 0 S 0 0.0 0:00.25 ksoftirqd/2
10 root RT 0 0 0 0 S 0 0.0 0:00.00 watchdog/2
11 root RT 0 0 0 0 S 0 0.0 0:01.73 migration/3
12 root 34 19 0 0 0 S 0 0.0 0:00.16 ksoftirqd/3
13 root RT 0 0 0 0 S 0 0.0 0:00.00 watchdog/3
14 root 10 -5 0 0 0 S 0 0.0 0:00.17 events/0
15 root 10 -5 0 0 0 S 0 0.0 0:00.11 events/1
16 root 10 -5 0 0 0 S 0 0.0 0:00.24 events/2
17 root 10 -5 0 0 0 S 0 0.0 0:00.22 events/3
18 root 10 -5 0 0 0 S 0 0.0 0:00.00 khelper
19 root 11 -5 0 0 0 S 0 0.0 0:00.00 kthread
67 root 10 -5 0 0 0 S 0 0.0 0:01.78 kblockd/0
68 root 10 -5 0 0 0 S 0 0.0 0:00.89 kblockd/1
69 root 10 -5 0 0 0 S 0 0.0 0:00.81 kblockd/2
70 root 10 -5 0 0 0 S 0 0.0 0:00.44 kblockd/3
71 root 11 -5 0 0 0 S 0 0.0 0:00.00 kacpid
156 root 11 -5 0 0 0 S 0 0.0 0:00.00 cqueue/0
157 root 13 -5 0 0 0 S 0 0.0 0:00.00 cqueue/1
158 root 13 -5 0 0 0 S 0 0.0 0:00.00 cqueue/2
159 root 15 -5 0 0 0 S 0 0.0 0:00.00 cqueue/3
160 root 14 -5 0 0 0 S 0 0.0 0:00.00 ksuspend_usbd
163 root 10 -5 0 0 0 S 0 0.0 0:00.00 khubd
165 root 10 -5 0 0 0 S 0 0.0 0:00.00 kseriod
214 root 10 -5 0 0 0 S 0 0.0 7:10.11 kswapd0
So there is only 1 task running, and not over 50 as before....
Thank you for any idea.
Octavian
More information about the Catalyst
mailing list