[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