Virtual Memory size of ApplicationPoolServerExecutable

[TonyLa]

We have a phusion passenger instance running on a production server
right now. It was running fine for about a week before something went
wrong. Apache was still serving static assets properly but passenger
was not able to spawn any new child processes. We never discovered
the root of the issue but instead we reboot Apache and setup hourly
emails of the passenger status command.

What I have found curious is that the VM size of the
ApplicationPoolServerExecutable continues to grow every hour. I have
read about how VM Size is not a good indicator of how much memory an
application is using. But as I write ApplicationPoolServerExecutable
VM size is 2727.4 MB. This is a 32 bit box so soon it will run out of
address space. I think this may have caused our error.

Here are 2 snapshots
Fri Jul 4 21:08:43 UTC 2008
-------------- Apache processes --------------
PID PPID Threads VMSize Private Name
----------------------------------------------
25324 31111 1 9.8 MB 0.6 MB /opt/httpd/bin/httpd -k start
25427 31111 1 9.7 MB 0.5 MB /opt/httpd/bin/httpd -k start
25430 31111 1 10.2 MB 0.8 MB /opt/httpd/bin/httpd -k start
25431 31111 1 9.8 MB 0.5 MB /opt/httpd/bin/httpd -k start
25434 31111 1 9.8 MB 0.6 MB /opt/httpd/bin/httpd -k start
25448 31111 1 9.6 MB 0.3 MB /opt/httpd/bin/httpd -k start
31111 1 1 9.5 MB 0.4 MB /opt/httpd/bin/httpd -k start
### Processes: 7
### Total private dirty RSS: 3.68 MB

---------- Passenger processes -----------
PID Threads VMSize Private Name
------------------------------------------
16261 1 186.8 MB 165.7 MB Rails: /deployment/releases/
20080626171805
16283 1 184.8 MB 162.9 MB Rails: /deployment/releases/
20080626171805
16918 1 132.1 MB 115.1 MB Rails: /deployment/releases/
20080626171805
22363 1 90.9 MB 74.2 MB Rails: /deployment/releases/
20080626171805
23035 1 85.8 MB 69.2 MB Rails: /deployment./releases/
20080626171805
31112 9 1091.5 MB 135.2 MB /opt/ruby-
enterprise-1.8.6-20080624/lib/ruby/gems/1.8/gems/passenger-2.0.1/ext/
apache2/ApplicationPoolServerExecutable 0 /opt/ruby-
enterprise-1.8.6-20080624/lib/ruby/gems/1.8/gems/passenger-2.0.1/bin/
passenger-spawn-server /opt/ruby-enterprise-1.8.6-20080624/bin/ruby /
tmp/passenger_status.31111.fifo
31115 1 9.5 MB 4.4 MB Passenger spawn server
### Processes: 7
### Total private dirty RSS: 726.75 MB
----------- General information -----------
max = 8
count = 5
active = 0
inactive = 5

----------- Applications -----------
/deployment/releases/20080626171805:
PID: 23035 Sessions: 0
PID: 16283 Sessions: 0
PID: 22363 Sessions: 0
PID: 16261 Sessions: 0
PID: 16918 Sessions: 0

Second one:

Mon Jul 7 13:01:01 UTC 2008
------------- Apache processes --------------
PID PPID Threads VMSize Private Name
---------------------------------------------
31111 1 1 9.5 MB 0.4 MB /opt/httpd/bin/httpd -k start
31335 31111 1 9.9 MB 0.7 MB /opt/httpd/bin/httpd -k start
31339 31111 1 9.7 MB 0.5 MB /opt/httpd/bin/httpd -k start
31340 31111 1 9.8 MB 0.5 MB /opt/httpd/bin/httpd -k start
31347 31111 1 9.7 MB 0.5 MB /opt/httpd/bin/httpd -k start
31371 31111 1 9.8 MB 0.6 MB /opt/httpd/bin/httpd -k start
31383 31111 1 9.8 MB 0.5 MB /opt/httpd/bin/httpd -k start
31385 31111 1 9.6 MB 0.3 MB /opt/httpd/bin/httpd -k start
### Processes: 8
### Total private dirty RSS: 3.89 MB

---------- Passenger processes -----------
PID Threads VMSize Private Name
------------------------------------------
11148 1 133.1 MB 115.6 MB Rails: /deployment/releases/
20080626171805
28722 1 86.7 MB 56.3 MB Rails: /deployment/releases/
20080626171805
28724 1 87.7 MB 57.2 MB Rails: /deployment/releases/
20080626171805
29489 1 75.7 MB 54.5 MB Rails: /deployment/releases/
20080626171805
29491 1 128.9 MB 108.0 MB Rails: /deployment/releases/
20080626171805
31112 10 2727.4 MB 338.4 MB /opt/ruby-
enterprise-1.8.6-20080624/lib/ruby/gems/1.8/gems/passenger-2.0.1/ext/
apache2/ApplicationPoolServerExecutable 0 /opt/ruby-
enterprise-1.8.6-20080624/lib/ruby/gems/1.8/gems/passenger-2.0.1/bin/
passenger-spawn-server /opt/ruby-enterprise-1.8.6-20080624/bin/ruby /
tmp/passenger_status.31111.fifo
31115 1 11.5 MB 6.6 MB Passenger spawn server
### Processes: 7
### Total private dirty RSS: 736.66 MB
----------- General information -----------
max = 8
count = 5
active = 1
inactive = 4

----------- Applications -----------
/deployment/releases/20080626171805:
PID: 28722 Sessions: 0
PID: 29491 Sessions: 0
PID: 29489 Sessions: 0
PID: 11148 Sessions: 0
PID: 28724 Sessions: 1

[Hongli Lai]

TonyLa wrote:
> We have a phusion passenger instance running on a production server
> right now. It was running fine for about a week before something went
> wrong. Apache was still serving static assets properly but passenger
> was not able to spawn any new child processes. We never discovered
> the root of the issue but instead we reboot Apache and setup hourly
> emails of the passenger status command.
>
> What I have found curious is that the VM size of the
> ApplicationPoolServerExecutable continues to grow every hour. I have
> read about how VM Size is not a good indicator of how much memory an
> application is using. But as I write ApplicationPoolServerExecutable
> VM size is 2727.4 MB. This is a 32 bit box so soon it will run out of
> address space. I think this may have caused our error.

Something is definitely wrong. The private dirty RSS should never be
larger than 1 MB, but in your case it's already more than 100 MB.

Which operating system is your production server running?

Regards,
Hongli Lai
--
Phusion | The Computer Science Company

Web: http://www.phusion.nl/
E-mail: in...@phusion.nl
Chamber of commerce no: 08173483 (The Netherlands)

[TonyLa]

We are running Red Hat Enterprise Linux Server release 5.2 (Tikanga)
on the production servers.

As another data point I dug up the error messages in our logs that
Passenger was reporting when it became unresponsive

[ pid=3838 file=ApplicationPoolServerExecutable.cpp:469 time=06/29/08
13:03:42.208 ]:
Cannot create a thread: Cannot allocate memory (12)
[Sun Jun 29 13:03:43 2008] [warn] long lost child came home! (pid
3838)
[ pid=13609 file=Hooks.cpp:624 time=06/29/08 13:03:48.165 ]:
Cannot initialize Passenger in an Apache child process: Could not
connect to the ApplicationPool server: Broken pipe (32) (this warning
is harmless if you're
currently restarting or shutting down Apache)

> E-mail: i...@phusion.nl

[TonyLa]

My colleagues and I have done some more investigation and debugging
into why this is happening. We have been able to reproduce it and
find a possible solution.

The problem stems from GET requests from Passenger that are not
completed. The connection on the client side is abruptly disconnected
before the entire request is served.

The attached files are:
test404_controller.rb
This is a simple rails controller that serves up an image on request.

class Test404Controller < ApplicationController
session :off

def image_404
#fiel should be at least 200K size
send_file(
'/home/epirogov/41406-20080418200531-715212-6861112.pdf.jpg',
:status => '404',
:disposition => 'inline',
:type => 'image/jpeg'
)
end



def exit_me
render :text => "Watch me #{$$}"
Process.kill('KILL',$$)
end
end

post.rb
This is the script that generates requests to the rails controller but
closes the connection before the entire request can be processed.

require 'socket'
include Socket::Constants

n = 2000
while (n -= 1) > 0 do
socket = Socket.new( AF_INET, SOCK_STREAM, 0 )
sockaddr = Socket.pack_sockaddr_in( 80, '127.0.0.1' )
socket.connect( sockaddr )
socket.write 'GET /test404/image_404 HTTP/1.1
Host: pingg.crococat.com
User-Agent: Mozilla/5.0 (X11; U; Linux i686; en-US; rv:1.8.1.14) Gecko/
20080404 Iceweasel/2.0.0.14 (Debian-2.0.0.14-0etch1)
Accept: text/xml,application/xml,application/xhtml+xml,text/
html;q=0.9,text/plain;q=0.8,image/png,*/*;q=0.5
Accept-Language: en-us,en;q=0.5
Accept-Encoding: gzip,deflate
Accept-Charset: ISO-8859-1,utf-8;q=0.7,*;q=0.7
Keep-Alive: 300
Connection: keep-alive
Referer: http://pingg.crococat.com/account/contacts?event_id=ZQzZ0QF-zZ0lx


'
puts Time.now.to_s + 'closing'
socket.close
puts Time.now.to_s + 'closed'

# socket.write 'POST / HTTP/1.1
#Host: pingg.crococat.com
#User-Agent: Mozilla/5.0 (X11; U; Linux i686; en-US; rv:1.8.1.14)
Gecko/20080404 Iceweasel/2.0.0.14 (Debian-2.0.0.14-0etch1)
#Accept: text/xml,application/xml,application/xhtml+xml,text/
html;q=0.9,text/plain;q=0.8,image/png,*/*;q=0.5
#Accept-Language: en-us,en;q=0.5
#Accept-Encoding: gzip,deflate
#Accept-Charset: ISO-8859-1,utf-8;q=0.7,*;q=0.7
#Keep-Alive: 300
#Connection: keep-alive
#Referer: http://pingg.crococat.com/account/contacts?event_id=ZQzZ0QF-zZ0lx
#Content-Type: multipart/form-data;
boundary=---------------------------12522529243572361591714635364
#Content-Length: 144863
#
#-----------------------------12522529243572361591714635364
#Content-Disposition: form-data; name="long_op_id"
#
#4760
#-----------------------------12522529243572361591714635364
#'
# puts Time.now.to_s + 'closing'
# socket.close
# puts Time.now.to_s + 'closed'
sleep 0.1
end


When these are run against a Passenger instance the VM size of the
ApplicationPoolServerExecutable grows with every request
indefinitely. It also results in at least one of the spawned
Passenger processes to be blocking on a write to a unix socket. As a
control the same test was run against a static asset that is served by
only Apache and nothing occurs.

Looking into the Passenger code we found one area of concern.

722 session->shutdownWriter();
723
724 apr_file_t *readerPipe = NULL;
725 int reader = session->getStream();
726 apr_os_pipe_put(&readerPipe, &reader, r-
>pool);
727
728 bb = apr_brigade_create(r->connection-
>pool, r->connection->bucket_alloc);
729 b = apr_bucket_pipe_create(readerPipe, r-
>connection->bucket_alloc);
730 APR_BRIGADE_INSERT_TAIL(bb, b);
731
732 b = apr_bucket_eos_create(r->connection-
>bucket_alloc);
733 APR_BRIGADE_INSERT_TAIL(bb, b);
734
735 ap_scan_script_header_err_brigade(r, bb,
NULL);
736 ap_pass_brigade(r->output_filters, bb);
737
738 Container *container = new Container();
739 container->session = session;
740 apr_pool_cleanup_register(r->pool,
container, Container::cleanup, apr_pool_cleanup_null);
741
742 // Apparently apr_bucket_pipe or
apr_brigade closes the
743 // file descriptor for us.
744 session->discardStream();
745
746 return OK;

It looks like there is an assumption that the file descriptor "reader"
is closed by a previous function. This maybe true in the non-error
case but in this case it seems like reader is not closed and could
cause the code on the other end sit and wait. When we added a
"close(reader)" @ live 745 and re-ran our test the VM size did grow a
slight bit 4mb -> 8mb but it never grew any more then that.

[rrwhite]

I'm having the same problem (ApplicationPoolServerExecutable VMSize is
2.35 GB and private is 146MB).

The section of code you referenced in your last post seems to be in
Hooks.cpp, is that correct? Would you advise people having this
problem to add close(reader) and recompile or is there a patch
forthcoming?

Thanks

Rich

[Tomislav Filipčić]

I have the same problem. VM Size keeps growing until it hangs Apache,
then a restart fixes it... until a few hours later.

Ubuntu 8.04 LTS

[TonyLa]

Sorry I forgot to mention that the Passenger code that I posted was
from Hooks.cpp

I wouldn't recommend just adding that line in to fix the issue. There
maybe other side effects to doing that. I am waiting for Hongli to
give his feedback on what I posted.

[Hongli Lai]

TonyLa wrote:
> My colleagues and I have done some more investigation and debugging
> into why this is happening. We have been able to reproduce it and
> find a possible solution.
>
> The problem stems from GET requests from Passenger that are not
> completed. The connection on the client side is abruptly disconnected
> before the entire request is served.
>

> [...]

>
> It looks like there is an assumption that the file descriptor "reader"
> is closed by a previous function. This maybe true in the non-error
> case but in this case it seems like reader is not closed and could
> cause the code on the other end sit and wait. When we added a
> "close(reader)" @ live 745 and re-ran our test the VM size did grow a
> slight bit 4mb -> 8mb but it never grew any more then that.

Nice job with tracking down this bug!

The reason why discardStream() is called, is to avoid
double-file-descriptor-closing bugs. If you're using Apache with the
prefork MPM, then you can solve this bug by commenting out the
discardStream() call. This will cause the socket with the Rails
application to be closed twice, but that's OK.
If you're using Apache with the worker MPM however, then closing file
descriptors twice can cause strange problems. I'll look into this today.

Regards,
Hongli Lai
--
Phusion | The Computer Science Company

Web: http://www.phusion.nl/
E-mail: in...@phusion.nl

[Hongli Lai]

The issue should be fixed in commit
77734f68d59520a21e39dd7f76433a48b52f5494. Could you verify it?

[Tomislav Filipčić]

Still leaking for me :/

--------- Passenger processes ----------

PID Threads VMSize Private Name
----------------------------------------

29709 97 358.3 MB 27.8 MB /home/tomislav/src/FooBarWidget-
passenger-60862bb4e71aa6edca811e067e0da5c5ef7501df/ext/apache2/
ApplicationPoolServerExecutable 0 /home/tomislav/src/FooBarWidget-
passenger-60862bb4e71aa6edca811e067e0da5c5ef7501df/bin/passenger-spawn-
server /usr/bin/ruby1.8 /tmp/passenger_status.29707.fifo
29711 2 40.1 MB 8.3 MB Passenger spawn server
30178 1 130.9 MB 47.3 MB Rails: /var/www/missautoklub.com/
releases/20080701211830
30285 1 131.1 MB 45.4 MB Rails: /home/tomislav/vred/releases/
20080613184955
### Processes: 4
### Total private dirty RSS: 128.82 MB

On Jul 9, 12:00 pm, Hongli Lai <hon...@phusion.nl> wrote:
> The issue should be fixed in commit
> 77734f68d59520a21e39dd7f76433a48b52f5494. Could you verify it?
>
> Regards,
> Hongli Lai
> --
> Phusion | The Computer Science Company
>
> Web:http://www.phusion.nl/

> E-mail: i...@phusion.nl

[Hongli Lai]

Tomislav Filip?i? wrote:
> Still leaking for me :/

I tried TonyLa's test script, and I could not reproduce the problem.
Interestingly I couldn't reproduce the problem with the 2.0.1 codebase
either. :-|

I'm running Ubuntu Linux 8.04 here.

Regards,
Hongli Lai
--
Phusion | The Computer Science Company

Web: http://www.phusion.nl/
E-mail: in...@phusion.nl

[Tomislav Filipčić]

My apache server gets about 40 requests per second (peak), but most of
that is PHP5 sites. My rails applications get about 100 pageviews per
day. The two rails applications are really small sites, with very
little funcionality. But Passenger's VMSize keeps growing constantly.

This is my munin graph for memory usage:
http://dl.getdropbox.com/u/701/conan.ephdev.com-memory-week.png

Monit monitors apache and restarts it when it hangs (once a day
mostly). Everything works fine if I remove passenger. I'm using the
pre-fork MPM, everything is standard out of the box Ubuntu server
8.04. These are the settings

<IfModule mpm_prefork_module>
StartServers 50
MinSpareServers 5
MaxSpareServers 10
ServerLimit 250
MaxClients 250
MaxRequestsPerChild 0
</IfModule>

On Jul 9, 2:43 pm, Hongli Lai <hon...@phusion.nl> wrote:
> Tomislav Filip?i? wrote:
> > Still leaking for me :/
>
> I tried TonyLa's test script, and I could not reproduce the problem.
> Interestingly I couldn't reproduce the problem with the 2.0.1 codebase
> either. :-|
>
> I'm running Ubuntu Linux 8.04 here.
>
> Regards,
> Hongli Lai
> --
> Phusion | The Computer Science Company
>
> Web:http://www.phusion.nl/

> E-mail: i...@phusion.nl

[TonyLa]

We just did some preliminary testing with the patch and it looks to
solve the issue with the VM size growing.

Thanks!

[TonyLa]

So with more testing (including our production server) the patch above
does resolve the specific issue of partial GET requests with
Passenger. But the larger underlying problem still persists, though
the VM grows at a slightly slower pace. Over the past 8 hours after
deploying the fix our production server
ApplicationPoolServerExecutable continues to grow with no upper bound.

[Hongli Lai]

TonyLa wrote:
> So with more testing (including our production server) the patch above
> does resolve the specific issue of partial GET requests with
> Passenger. But the larger underlying problem still persists, though
> the VM grows at a slightly slower pace. Over the past 8 hours after
> deploying the fix our production server
> ApplicationPoolServerExecutable continues to grow with no upper bound.

Could you try to debug this with Valgrind? You can start the application
pool server by editing ext/apache2/ApplicationPoolServer.h, line 487. If
you change the "#if 0" there to "#if 1" then it'll be started in
Valgrind. You may want to add "--leak-check=yes" to Valgrind as parameter.

--
Phusion | The Computer Science Company

Web: http://www.phusion.nl/
E-mail: in...@phusion.nl

[TonyLa]

Ok I have done some more investigation via Valgrind. The output can
be found as follows
http://dpaste.com/hold/62752/

The most interesting portion is this

==16292== 8,580 bytes in 195 blocks are definitely lost in loss record
31 of 33
==16292== at 0x4005B65: operator new(unsigned) (vg_replace_malloc.c:
163)
==16292== by 0x806C060: Client::start(boost::weak_ptr<Client>)
(ApplicationPoolServerExecutable.cpp:441)
==16292== by 0x804C085: Server::start()
(ApplicationPoolServerExecutable.cpp:515)
==16292== by 0x804C762: main (ApplicationPoolServerExecutable.cpp:
528)

I have done some tracing through the code and think I have found the
problem. The problem lives in ApplicationPoolServerExecutable.cpp.
It has to do with how the Client object is destroyed/cleaned up.

So when a request comes in inside the server main loop Server::start a
new Client object is created and Client::start is called. Then inside
Client::start a new thread (call it thread B) is created to run
threadMain (ApplicationPoolServerExecutable.cpp:339). Thread B does
the heavy lifting of serving the request and once it completes there
is this piece of code:

401 UPDATE_TRACE_POINT();
402 boost::mutex::scoped_lock l(server.lock);
403 ClientPtr myself(self.lock());
404 if (myself != NULL) {
405 server.clients.erase(myself);
406 }

The line server.clients.erase(myself); will call the destructor on the
current Client object that created thread B.

444 ~Client() {
445 TRACE_POINT();
446 this_thread::disable_syscall_interruption dsi;
447 this_thread::disable_interruption di;
448
449 if (thr != NULL && thr->get_id() !=
this_thread::get_id()) {
450 thr->interrupt_and_join();
451 delete thr;
452 }
453 syscalls::close(fd);
454 }

The problem with this destructor is thr->get_id() !=
this_thread::get_id() thr will always be equal to this_thread because
the destructor is being called from thread B. So when the Client
object is being destroyed thr will not be cleaned up and will leak
memory. It looks like the destructor was at one time ment to be
called from the original thread A rather then the created thread B.

I modified the code to look like:

444 ~Client() {
445 TRACE_POINT();
446 this_thread::disable_syscall_interruption dsi;
447 this_thread::disable_interruption di;
448
449 if (thr != NULL && thr->get_id() ==
this_thread::get_id()) {
450 //thr->interrupt_and_join(); //removed
this because it caused everything to hang
451 delete thr;
452 }
453 syscalls::close(fd);
454 }

With this the code ApplicationServerPoolExecutable does not leak when
I run our test scripts. So this means that the leaking memory was thr
not being deleted.

Following is how we reproduced the leak:


Run harvest.rb to have it start hammering the server.

harvest.rb
http://dpaste.com/hold/62775/

multiplex.rb - have this in the same folder as harvest.rb
http://dpaste.com/hold/62776/

> E-mail: i...@phusion.nl

[TonyLa]

Just some additional information.

Valgrind output with the previous patch applied
http://dpaste.com/hold/62822/

==12175== LEAK SUMMARY:
==12175== definitely lost: 44 bytes in 1 blocks.
==12175== possibly lost: 709 bytes in 9 blocks.
==12175== still reachable: 2,246 bytes in 39 blocks.
==12175== suppressed: 0 bytes in 0 blocks.

Also to reproduce/exaggerate the problem our PreFork configuration is
as follows

<IfModule prefork.c>
StartServers 10
MinSpareServers 1
MaxSpareServers 1
MaxClients 50
MaxRequestsPerChild 1
</IfModule>

On Jul 11, 10:29 am, TonyLa <gonepos...@gmail.com> wrote:
> Ok I have done some more investigation via Valgrind.  The output can

> be found as followshttp://dpaste.com/hold/62752/

> harvest.rbhttp://dpaste.com/hold/62775/
>
> multiplex.rb - have this in the same folder as harvest.rbhttp://dpaste.com/hold/62776/

[Hongli Lai]

TonyLa wrote:
> The problem with this destructor is thr->get_id() !=
> this_thread::get_id() thr will always be equal to this_thread because
> the destructor is being called from thread B. So when the Client
> object is being destroyed thr will not be cleaned up and will leak
> memory. It looks like the destructor was at one time ment to be
> called from the original thread A rather then the created thread B.
>
> I modified the code to look like:
>
> 444 ~Client() {
> 445 TRACE_POINT();
> 446 this_thread::disable_syscall_interruption dsi;
> 447 this_thread::disable_interruption di;
> 448
> 449 if (thr != NULL && thr->get_id() ==
> this_thread::get_id()) {
> 450 //thr->interrupt_and_join(); //removed
> this because it caused everything to hang
> 451 delete thr;
> 452 }

The bug has been confirmed.

Your fix is not entirely correct however. If the server's shutting down
(i.e. received SIGINT) while there are still client threads running,
then Server will attempt to gracefully shutdown all threads, so
thr->interrupt_and_join() is necessary. I've decoupled the 'delete thr'
statement from the 'thr->interrupt_and_join()' statement, like this:

if (thr != NULL) {
if (thr->get_id() != this_thread::get_id()) {
thr->interrupt_and_join();
}
delete thr;
}

Thanks for the awesome analysis. :) The problem should be fixed in
commit 9cc8ee3a8eb23ff630173b12361fde6bb1fc2d5f. Please verify.

Regards,
Hongli Lai

--
Phusion | The Computer Science Company

Web: http://www.phusion.nl/
E-mail: in...@phusion.nl

[Tomislav Filipčić]

This fixed the problem for me. Thank you

[TonyLa]

Just as a followup we have deployed Passenger 2.0.2 to production and
VM size no longer increases at such a rapid pace and with no upper
bound. Thank you Hongli for the awesome support!