Ticket Navigation

Ticket #1131 (closed defect: fixed)

Opened 8 months ago

Last modified 8 months ago

puppetmaster memory leak

Reported by:	descala	Assigned to:	adamhjk
Priority:	normal	Milestone:	0.24.4
Component:	library	Version:	0.24.2
Severity:	normal	Keywords:
Cc:		Triage Stage:	Accepted
Attached Patches:	None	Complexity:	Unknown

Attachments

puppetmaster-memory-week.png (62.1 kB) - added by descala on 03/12/08 17:57:18.
memory-month-puppet.png (62.2 kB) - added by adamhjk on 03/14/08 01:42:10.: A memory graph showing the puppet master growth, leading up to #1131
diff (327 bytes) - added by descala on 03/14/08 19:53:34.: lib/puppet/util/loadedfile.rb
memory_profiler.rb (2.8 kB) - added by luke on 03/17/08 00:06:23.: A library you can load to profile memory growth somewhat.

Change History

(in reply to: ↑ 5 ) 03/14/08 00:15:04 changed by descala

Replying to adamhjk:

Replying to descala:

yes. it also replaced some files with empty directories in one of its crisis.

Did it do that under 0.24.2? If, so, we have a larger problem on our hands, since that means the work-around that caused #1010 to be closed doesn't work.

yes. 0.24.2 on server and clients.

after puppetmaster restart got this kind of report in 4 nodes out of 40. puppet trying to set files right:

Wed Mar 12 09:30:07 +0100 2008 //rubygems/File[rubygems_fact] (notice): Recursively backing up to filebucket
Wed Mar 12 09:30:07 +0100 2008 //rubygems/File[rubygems_fact] (notice): Not removing directory; use 'force' to override
Wed Mar 12 09:30:07 +0100 2008 //rubygems/File[rubygems_fact] (notice): Recursively backing up to filebucket
Wed Mar 12 09:30:07 +0100 2008 //rubygems/File[rubygems_fact] (notice): Not removing directory; use 'force' to override
Wed Mar 12 09:30:07 +0100 2008 //rubygems/File[rubygems_fact] (err): Could not rename tmp /usr/local/lib/ruby/site_ruby/1.8/facter/rubygems_version.rb for replacing: Is a directory - /usr/local/lib/ruby/site_ruby/1.8/facter/rubygems_version.rb.puppettmp or /usr/local/lib/ruby/site_ruby/1.8/facter/rubygems_version.rb

no files were corrupted. only changed to an empty directory.

03/14/08 01:51:35 changed by shadoi

Here's a curious log snippet from a machine that got corrupted files (client and server both running 0.23.2):

Tue Mar 11 14:29:51 -0700 2008 /Main[top]/Node[basenode]/Node[os]/Node[os::redhat]/File[/etc/filter-syslog/redhat]/source (err): Could not describe /os/Redhat/filter-syslog: can't modify frozen object
Tue Mar 11 14:29:51 -0700 2008 /Main[top]/Node[basenode]/Node[newsyslog]/File[/etc/filter-syslog.conf]/source (err): Could not describe /newsyslog/filter-syslog.conf: wrong status line: "<!DOCTYPE HTML PUBLIC \"-//IETF//DTD HTML 2.0//EN\">"
Tue Mar 11 14:29:51 -0700 2008 /Main[top]/Node[basenode]/Node[postfix]/File[/etc/filter-syslog/postfix]/source (err): Could not describe /postfix/filter-syslog: wrong status line: "<html><head>"
Tue Mar 11 14:29:51 -0700 2008 /Main[top]/Node[basenode]/Node[afs]/File[/usr/vice/etc/CellServDB]/source (err): Could not describe /afs/CellServDB: wrong status line: "<title>400 Bad Request</title>"
Tue Mar 11 14:29:51 -0700 2008 /Main[top]/Node[basenode]/Node[afs]/File[/etc/filter-syslog/afs]/source (err): Could not describe /afs/filter-syslog: wrong status line: "</head><body>"
Tue Mar 11 14:29:51 -0700 2008 /Main[top]/Node[basenode]/Node[ntp]/File[/etc/ntp/ntpservers]/source (err): Could not describe /ntp/ntpservers: wrong status line: "<h1>Bad Request</h1>"
Tue Mar 11 14:29:51 -0700 2008 /Main[top]/Node[basenode]/Node[os]/Node[os::redhat]/File[/etc/profile.d/usrlocal.sh]/source (err): Could not describe /os/Redhat/profile.d/usrlocal.sh: wrong status line: "<p>Your browser sent a request that this server could not understand.<br />"
Tue Mar 11 14:29:51 -0700 2008 /Main[top]/Node[basenode]/Node[ntp]/File[/etc/filter-syslog/ntp]/source (err): Could not describe /ntp/filter-syslog: wrong status line: "Reason: You're speaking plain HTTP to an SSL-enabled server port.<br />"
Tue Mar 11 14:29:52 -0700 2008 /Main[top]/Node[basenode]/Node[tmpclean]/File[/etc/cron.daily/tmpwatch]/source (err): Could not describe /tmpclean/tmpwatch: wrong status line: "Instead use the HTTPS scheme to access this URL, please.<br />"
Tue Mar 11 14:29:52 -0700 2008 /Main[top]/Node[basenode]/Node[virt_all_users]/Node[client_gsbweb]/Remotefile[/usr/share/ssl/openssl.cnf]/File[/usr/share/ssl/openssl.cnf]/source (err): Could not describe /dist/clients/gsbweb/usr/share/ssl/openssl.cnf: wrong status line: "<blockquote>Hint: <a href=\"https://henson.stanford.edu:8140/\"><b>https://henson.stanford.edu:8140/</b></a></blockquote></p>"
Tue Mar 11 14:29:53 -0700 2008 /Main[top]/Node[basenode]/Node[gsb-vatuqa]/Node[client_gsbweb_gsb-vatuqa]/Node[client_gsbweb_gsb-vatu-common]/Remotefile[/etc/newsyslog.monthly/tomcat]/File[/etc/newsyslog.monthly/tomcat]/source (err): Could not describe /dist/clients/gsbweb/etc/newsyslog.monthly/tomcat.gsb-vatuqa: wrong status line: "<hr>"
Tue Mar 11 14:29:53 -0700 2008 /Main[top]/Node[basenode]/Node[postfix]/Postmap[/etc/postfix/transport]/Remotefile[/etc/postfix/transport]/File[/etc/postfix/transport]/source (err): Could not describe /postfix/transport: wrong status line: "<address>Apache/2.2.3 (Debian) proxy_html/2.5 mod_ssl/2.2.3 OpenSSL/0.9.8c WebAuth/3.5.3 Server at henson.stanford.edu Port 8140</address>"
Tue Mar 11 14:29:53 -0700 2008 /Main[top]/Node[basenode]/Node[user_root]/Remotefile[/root/.bashrc]/File[/root/.bashrc]/source (err): Could not describe /dist/users/rootuser/bashrc: wrong status line: "</body></html>"
Tue Mar 11 14:29:55 -0700 2008 /Main[top]/Node[basenode]/Node[xinetd]/Service[xinetd] (notice): Triggering 'refresh' from 2 dependencies
Tue Mar 11 14:30:03 -0700 2008 /Main[top]/Node[basenode]/Node[virt_all_users]/Node[client_gsbweb]/Node[apache]/Exec[apache-reload] (notice): Triggering 'refresh' from 1 dependencies
Tue Mar 11 14:30:05 -0700 2008 /Main[top]/Node[basenode]/Node[iptables]/Exec[rebuild_iptables] (notice): Triggering 'refresh' from 4 dependencies

Specifically it looks like things start going south with "can't modify frozen object", maybe a red herring?

03/16/08 22:15:23 changed by luke

milestone changed from 0.24.3 to elmo.

I spent all day Friday and Saturday trying to reproduce this and was not able to.

If you would like to do stand-alone testing, it's very easy using tools I've already written (ext/puppet-test, in the repository. You can specify as many repetitions as you want with --repeat N, and as many forks as you want with --fork (although I've had more luck using separate processes).

It accepts any normal Puppet argument (e.g., server, certname).

To test configuration compiling, use:

sudo puppet-test

To test file retrieving, use:

# Note that you should leave off the "puppet://" here.
sudo puppet-test --retrieve "/path/to/file"

To test file describing, use:

sudo puppet-test --describe "/path/to/file"

You can peruse the file and see what other suites are available. I'll be making a commit today that adds the ability to repeat the server-side tasks, like compiling and parsing.

03/17/08 00:10:43 changed by luke

I've added a library that I was using to try to track memory growth. To use it, stick it in your RUBYLIB somewhere, then add this to your puppetmasterd:

require 'memory_profiler'
MemoryProfiler.start(:deltas => false)

Add it around line 281 -- right before start/join stuff done on webrick/mongrel.

This file will create /tmp/memory_log and update a file in there with info on what instances it thinks are being retained across GC runs. Basically, you get a ratio of current instances to the number of those that were also present 10 seconds ago. It's sorted by total instances, so String always shows up first, but you should be able to see anything that grows quickly based on memory leakage. (Assuming the memory leakage is of Ruby objects, not leakage in Ruby C libraries.

03/17/08 03:16:19 changed by Fujin

14:56 < fujin> lak: 180MB ram usage 14:56 < fujin> Top 20 retained 14:56 < fujin> Array: 362/31875 (0.01) 14:56 < fujin> String: 2/159653 (0.00) 14:56 < lak> any puppet classes showing up in the list? 14:57 < lak> if you want better data, it's probably more useful to sort by the ratio 14:57 < fujin> That's it 14:57 < fujin> (with no active connections) 14:57 < lak> i thought about adding it, but it was like 11pm last night (sat night for me) and i

just couldn't convince myself to

14:57 < fujin> Just those two :0 14:57 < fujin> when a node connects, more things happen 14:57 < lak> really? 14:57 < lak> ah, ok 14:57 < lak> but then it's all reclaimed 14:57 < lak> ok 14:57 < fujin> all of your Puppet magical classes are instantiated, then GC'd correctly 14:57 < lak> so that pretty clearly indicates it's a ruby leak, not a puppet leak

Valgrinding it now, It's obviously an Array of some-sort somewhere in Puppet which is causing this leak - None of the puppet classes are the leaky ones. I'm hoping the valgrind information will be helpful.

03/17/08 03:20:51 changed by Fujin

What a fail.

14:56 < fujin> lak: 180MB ram usage
14:56 < fujin> Top 20 retained
14:56 < fujin> Array: 362/31875 (0.01)
14:56 < fujin> String: 2/159653 (0.00)
14:56 < lak> any puppet classes showing up in the list?
14:57 < lak> if you want better data, it's probably more useful to sort by the ratio
14:57 < fujin> That's it
14:57 < fujin> (with no active connections)
14:57 < lak> i thought about adding it, but it was like 11pm last night (sat night for me) and i
             just couldn't convince myself to
14:57 < fujin> Just those two :0
14:57 < fujin> when a node connects, more things happen
14:57 < lak> really?
14:57 < lak> ah, ok
14:57 < lak> but then it's all reclaimed
14:57 < lak> ok
14:57 < fujin> all of your Puppet magical classes are instantiated, then GC'd correctly
14:57 < lak> so that pretty clearly indicates it's a ruby leak, not a puppet leak

03/17/08 23:34:40 changed by adamhjk

Okay. If you have an actively flakey puppet master, here are the steps you can follow to attach to it with GDB and do some introspection (in Ruby, no less!)

Attaching to puppetmasterd with GDB

Install GDB

Follow whatever steps make sense for your platform. Something like:

$ yum install gdb

$ apt-get install gdb

Would work just fine.

Populate your .gdbinit and .gdb directories

In ~/.gbinit:

define session-ruby
  source ~/.gdb/ruby
end

Next, you need to download http://eigenclass.org/hiki.rb?c=plugin;plugin=attach_download;p=ruby+live+process+introspection;file_name=ruby

And place it in ~/.gdb/ruby.

$ mkdir -p ~/.gdb
$ wget 'http://eigenclass.org/hiki.rb?c=plugin;plugin=attach_download;p=ruby+live+process+introspection;file_name=ruby'
$ mv ruby ~/.gdb

Attach to the puppetmaster process, load the ruby helpers, and redirect stdout:

$ ps ax | grep puppemasterd
21170 ttyp5    S+     0:02 /usr/bin/ruby /srv/ruby/1.8.6/bin/puppetmasterd --no-daemonize --debug --trace

The important part here is the very first segment of the line (the PID).

$ gdb /usr/bin/ruby 21170

The first argument to gdb should be the full path to the ruby executable that is running your puppetmasterd.

Start your debug session

From above, you should see a bunch of output like this:

...
Loaded symbols for /srv/ruby/1.8.6/lib/ruby/1.8/i686-linux/nkf.so
0xbfffe402 in __kernel_vsyscall ()

And then you'll wind up at...

(gdb)

First things first, load up the ruby helpers.

(gdb) session-ruby

Then, redirect stdout to a file, so we can capture the output for later.

(gdb) redirect_stdout

Open up a second terminal, and you can watch the output from your debug session:

$ tail -f /tmp/ruby-debug.PID

Where PID above is equal to the PID you attached to with gdb.

Now that you are watching, flip back to your gdb session and..

Get some data

(gdb) eval "caller"
(gdb) rb_object_counts
(gdb) eval "total = ObjectSpace.each_object(Array){|x| puts '---'; puts x.inspect }; puts \"---\nTotal Arrays: #{total}\""

You should see a stack trace, a long count of the number of objects in the system. The last line is important, was Luke and Fujin think they are leaking Array's specifically. That will print the value of every array the puppetmasterd has, separated by ---.

It should be a huge amount of data, but it ought to get us pointed in a more specific direction regarding the source of the Array's.

03/18/08 10:49:57 changed by adamhjk

Okay, some more updates.

We discovered a very large (9K+ entries) array that seems to be related to the tagging of Puppet::Parser::Resources. You can see the array by doing something like:

(gdb) eval "by_size = Hash.new; total = ObjectSpace.each_object(Array){|x| by_size[x.object_id] = x }; by_size.sort { |a,b| a[1].length <=> b[1].length }.each { |elem| puts \"OBJ #{elem[1]}: #{elem[0].inspect}\" }; nil"

That will print the object ID: size for every array. I've been doing something like:

(gdb) eval "ObjectSpace.each_object(Array){|x| puts x.inspect if x.length == LENGTH}; nil"

Where LENGTH is the output after the colon from above. That'll show you the actual array contents that have grown so large.

Then:

(gdb) eval "total = ObjectSpace.each_object(Puppet::Parser::Resource){|x| puts '---'; puts x.inspect }; puts \"---\nTotal Parser::Resource: #{total}\""

Will print out all the Puppet::Parser::Resource objects, which I believe is where that array is hiding. Track that guy down, and I think you'll have all you need to figure this out.

Unless your Luke, at which point you might have enough to figure that leak out by poking around the tag stuff got implemented in the parser. :)

More to come.

Download in other formats:

Ticket Navigation

Ticket #1131 (closed defect: fixed)

puppetmaster memory leak

Description

Attachments

Change History

03/12/08 17:57:18 changed by descala

03/13/08 15:15:44 changed by luke

03/13/08 21:00:41 changed by descala

(follow-up: ↓ 4 ) 03/13/08 21:14:29 changed by Fujin

(in reply to: ↑ 3 ; follow-up: ↓ 5 ) 03/13/08 22:11:11 changed by descala

(in reply to: ↑ 4 ; follow-up: ↓ 6 ) 03/13/08 23:26:21 changed by adamhjk

(in reply to: ↑ 5 ) 03/14/08 00:15:04 changed by descala

03/14/08 01:07:52 changed by adamhjk

03/14/08 01:26:22 changed by luke

03/14/08 01:42:10 changed by adamhjk

03/14/08 01:51:35 changed by shadoi

03/14/08 19:53:34 changed by descala

03/16/08 22:15:23 changed by luke

03/17/08 00:06:23 changed by luke

03/17/08 00:10:43 changed by luke

03/17/08 00:57:53 changed by Fujin

03/17/08 03:16:19 changed by Fujin

03/17/08 03:20:51 changed by Fujin

03/17/08 03:28:47 changed by Fujin

03/17/08 03:38:14 changed by Fujin

03/17/08 23:34:40 changed by adamhjk

Attaching to puppetmasterd with GDB

Install GDB

Populate your .gdbinit and .gdb directories

Attach to the puppetmaster process, load the ruby helpers, and redirect stdout:

Start your debug session

Get some data

03/18/08 01:18:09 changed by jamtur01

03/18/08 02:02:39 changed by luke

03/18/08 10:49:57 changed by adamhjk

03/18/08 10:54:13 changed by adamhjk

03/21/08 06:04:55 changed by luke

03/21/08 06:11:16 changed by luke

03/21/08 06:27:58 changed by luke

03/21/08 06:40:59 changed by luke

03/21/08 23:24:45 changed by Fujin

03/21/08 23:32:27 changed by luke

Download in other formats: