[Catalyst] DProf

Jon Schutz jon+catalyst at youramigo.com
Sat Nov 3 11:47:56 GMT 2007


If benchmark testing isn't showing the fault, it's likely that it is
data-dependent, i.e. it depends on something in the request or response
- something that the benchmark doesn't trigger.

Perhaps clients are left lingering - an incorrect Content-Length could
cause that.  I've also seen apache get stuck in busy wait states when
proxying through to a remote site that is not responding correctly.
Your top output is very likely an indication that some requests are not
being served to completion.  You could try (as root)

netstat -nap | grep http

to see what network connections the httpd processes are holding open.

lsof may also tell you something useful.

Try attaching an strace to one of the busy httpds to see what system
calls it is doing.

The difficulty with the mod_perl environment is that your httpd
processes are polluted with everything else that is happening on your
server - PHP etc - so what perl is responsible for is obscured.  Testing
in a fastcgi environment is better in this respect since perl and apache
are separated.  If you are able to try fastcgi, it might reveal some
further insights.

On Sat, 2007-11-03 at 11:39 +0200, Octavian Rasnita wrote:
> 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
> 
> 
> _______________________________________________
> List: Catalyst at lists.scsys.co.uk
> Listinfo: http://lists.scsys.co.uk/cgi-bin/mailman/listinfo/catalyst
> Searchable archive: http://www.mail-archive.com/catalyst@lists.rawmode.org/
> Dev site: http://dev.catalyst.perl.org/



More information about the Catalyst mailing list