Created
May 17, 2012 19:29
-
-
Save todb-r7/2721110 to your computer and use it in GitHub Desktop.
Troubleshooting some rails memory leak
This file contains bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
| The problem: the first seven hosts of the poisoned nmap file gets you to 10.3 to 10.5% mem usage (for 8gb memory) from the sample file. | |
| The first order of business is to get a sample file to be usable for test cases without actually crashing ruby, and to make the host info more useful for debugging (sequential IPs, fake target domain and names, basic attempts at anonymizing the real data). | |
| top - 10:51:26 up 59 min, 7 users, load average: 0.46, 0.57, 0.47 | |
| Tasks: 1 total, 0 running, 1 sleeping, 0 stopped, 0 zombie | |
| Cpu(s): 3.8%us, 4.0%sy, 0.0%ni, 92.1%id, 0.0%wa, 0.0%hi, 0.2%si, 0.0%st | |
| Mem: 8161728k total, 3880048k used, 4281680k free, 341184k buffers | |
| Swap: 9535480k total, 0k used, 9535480k free, 1092928k cached | |
| PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND | |
| 6697 todb 20 0 1046m 829m 6060 S 0 10.4 1:41.13 ruby | |
| Importing off of Metasploit 4.2.0 (svn r14791 updated 85 days ago (2012.02.22)) has no such problem: | |
| top - 10:54:07 up 1:01, 8 users, load average: 0.37, 0.50, 0.45 | |
| Tasks: 1 total, 0 running, 1 sleeping, 0 stopped, 0 zombie | |
| Cpu(s): 3.5%us, 0.8%sy, 0.0%ni, 95.7%id, 0.0%wa, 0.0%hi, 0.0%si, 0.0%st | |
| Mem: 8161728k total, 3236764k used, 4924964k free, 351060k buffers | |
| Swap: 9535480k total, 0k used, 9535480k free, 1119124k cached | |
| PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND | |
| 7244 todb 20 0 366m 153m 6084 S 0 1.9 0:24.63 ruby | |
| First WAG: Just garbage collect after every host by adding a GC.new into the report_host() call. This has no effect. | |
| Research attempt: Put together an ObjectSpace checker | |
| Rails3 metasploit: | |
| [*] resource (/home/todb/rc/nmap.rc)> Ruby Code (33 bytes) | |
| String 3246022 | |
| RubyVM::InstructionSequence 33178 | |
| Array 15609 | |
| Hash 7151 | |
| Regexp 4855 | |
| Class 4590 | |
| Module 2684 | |
| RubyVM::Env 2338 | |
| Proc 2101 | |
| Msf::OptBool 515 | |
| Rails2 metasploit: | |
| [*] resource (/home/todb/rc/nmap.rc)> Ruby Code (33 bytes) | |
| String 304973 | |
| RubyVM::InstructionSequence 28968 | |
| Array 13479 | |
| Hash 4935 | |
| Regexp 4606 | |
| Class 4338 | |
| Module 2466 | |
| Proc 1566 | |
| RubyVM::Env 1282 | |
| Msf::OptBool 501 | |
| So there are 11x the strings in Rails3. Wow. Wonder what those are. | |
| Let's take a look at what the ObjectSpace looks like after importing each host. Adding | |
| diff --git a/lib/msf/core/db.rb b/lib/msf/core/db.rb | |
| index a3065aa..124ec15 100644 | |
| --- a/lib/msf/core/db.rb | |
| +++ b/lib/msf/core/db.rb | |
| @@ -347,6 +347,9 @@ class DBManager | |
| host.save! | |
| end | |
| + # XXX Delete this debug stuff | |
| + load '/tmp/ospace.rb' | |
| + ::DebugTodb.count_objs | |
| host | |
| } | |
| end | |
| After every host, you add something like 800,000 strings to the heap. wow! | |
| [*] Importing 'Nmap XML' data | |
| [*] Import: Parsing with 'Nokogiri v1.5.2' | |
| String 390522 | |
| RubyVM::InstructionSequence 33095 | |
| Array 15560 | |
| Hash 5609 | |
| Regexp 4854 | |
| Class 4592 | |
| Module 2684 | |
| RubyVM::Env 2320 | |
| Proc 2087 | |
| Msf::OptBool 515 | |
| [*] Importing host 118.21.1.1 | |
| String 1322786 | |
| Hash 307942 | |
| Mdm::Service 49138 | |
| Array 33694 | |
| RubyVM::InstructionSequence 33219 | |
| Regexp 4855 | |
| Class 4592 | |
| Module 2685 | |
| RubyVM::Env 2379 | |
| Proc 2140 | |
| [*] Importing host 118.21.1.2 | |
| String 2209456 | |
| Hash 609595 | |
| Mdm::Service 98276 | |
| Array 44338 | |
| RubyVM::InstructionSequence 33215 | |
| Regexp 4855 | |
| Class 4592 | |
| Time 3271 | |
| Module 2685 | |
| RubyVM::Env 2352 | |
| [*] Importing host 118.21.1.3 | |
| String 3096813 | |
| Hash 912149 | |
| Mdm::Service 147414 | |
| Array 57831 | |
| RubyVM::InstructionSequence 33215 | |
| Regexp 4855 | |
| Time 4839 | |
| Class 4592 | |
| ActiveRecord::Relation 2867 | |
| Arel::Table 2845 | |
| [*] Importing host 118.21.1.4 | |
| String 4016862 | |
| Hash 1214644 | |
| Mdm::Service 196552 | |
| Array 71959 | |
| RubyVM::InstructionSequence 33215 | |
| Time 6427 | |
| Regexp 4855 | |
| Class 4592 | |
| ActiveRecord::Relation 3816 | |
| Arel::Table 3785 | |
| [*] Importing host 118.21.1.5 | |
| String 4911826 | |
| Hash 1517046 | |
| Mdm::Service 245690 | |
| Array 85596 | |
| RubyVM::InstructionSequence 33215 | |
| Time 7995 | |
| Regexp 4855 | |
| ActiveRecord::Relation 4750 | |
| Arel::Table 4725 | |
| Arel::Attributes::Attribute 4721 | |
| [*] Importing host 118.21.1.6 | |
| String 5815178 | |
| Hash 1819520 | |
| Mdm::Service 294828 | |
| Array 98979 | |
| RubyVM::InstructionSequence 33215 | |
| Time 9569 | |
| ActiveRecord::Relation 5684 | |
| Arel::Table 5665 | |
| Arel::Attributes::Attribute 5659 | |
| Arel::Nodes::Equality 5647 | |
| [*] Importing host 118.21.1.7 | |
| [*] Successfully imported /tmp/nmap.pro.poison.xml | |
| Compare to 4.2.0: | |
| [*] Importing 'Nmap XML' data | |
| [*] Import: Parsing with 'Nokogiri v1.5.2' | |
| String 340666 | |
| RubyVM::InstructionSequence 28905 | |
| Array 13606 | |
| Hash 5298 | |
| Regexp 4607 | |
| Class 4338 | |
| Module 2467 | |
| Proc 1570 | |
| RubyVM::Env 1288 | |
| Msf::OptBool 501 | |
| [*] Importing host 118.21.1.1 | |
| String 394339 | |
| RubyVM::InstructionSequence 28975 | |
| Array 13574 | |
| Hash 5309 | |
| Regexp 4607 | |
| Class 4338 | |
| Module 2467 | |
| Proc 1573 | |
| RubyVM::Env 1302 | |
| Msf::OptBool 501 | |
| [*] Importing host 118.21.1.2 | |
| String 398396 | |
| RubyVM::InstructionSequence 28970 | |
| Array 13523 | |
| Hash 5307 | |
| Regexp 4606 | |
| Class 4338 | |
| Module 2467 | |
| Proc 1570 | |
| RubyVM::Env 1288 | |
| Msf::OptBool 501 | |
| [*] Importing host 118.21.1.3 | |
| String 397932 | |
| RubyVM::InstructionSequence 28970 | |
| Array 13520 | |
| Hash 5314 | |
| Regexp 4606 | |
| Class 4338 | |
| Module 2467 | |
| Proc 1570 | |
| RubyVM::Env 1288 | |
| Msf::OptBool 501 | |
| [*] Importing host 118.21.1.4 | |
| String 397920 | |
| RubyVM::InstructionSequence 28970 | |
| Array 13512 | |
| Hash 5319 | |
| Regexp 4607 | |
| Class 4338 | |
| Module 2467 | |
| Proc 1570 | |
| RubyVM::Env 1288 | |
| Msf::OptBool 501 | |
| [*] Importing host 118.21.1.5 | |
| String 398585 | |
| RubyVM::InstructionSequence 28970 | |
| Array 13502 | |
| Hash 5327 | |
| Regexp 4606 | |
| Class 4338 | |
| Module 2467 | |
| Proc 1570 | |
| RubyVM::Env 1288 | |
| Msf::OptBool 501 | |
| [*] Importing host 118.21.1.6 | |
| String 398459 | |
| RubyVM::InstructionSequence 28970 | |
| Array 13507 | |
| Hash 5323 | |
| Regexp 4607 | |
| Class 4338 | |
| Module 2467 | |
| Proc 1570 | |
| RubyVM::Env 1288 | |
| Msf::OptBool 501 | |
| [*] Importing host 118.21.1.7 | |
| So, wrote a string inspector: | |
| def eyeball_strings | |
| @strings = {} | |
| ObjectSpace.each_object do |o| | |
| next unless o.kind_of? String | |
| @strings[o[0,60]] ||= 0 | |
| @strings[o[0,60]] += 1 | |
| end | |
| i = 0 | |
| @strings.sort {|a,b| b[1] <=> a[1]}.each do |k,v| | |
| i += 1 | |
| puts "*%-60s* %d" % [k,v] | |
| break if i >= 20 | |
| end | |
| end | |
| You can see that all these strings are getting created as part of Mdm::Service. | |
| Not super surprising, but now we know for sure. Yay? | |
| resource (/home/todb/rc/nmap.rc)> db_import /tmp/nmap.pro.poison.xml | |
| [*] Importing 'Nmap XML' data | |
| [*] Import: Parsing with 'Nokogiri v1.5.2' | |
| * * 4518 | |
| */home/todb/git/rapid7/metasploit-framework/modules/exploits/* 4323 | |
| */home/todb/git/rapid7/metasploit-framework/modules/auxiliary* 3663 | |
| *initialize * 3072 | |
| *Payload * 2863 | |
| */home/todb/git/rapid7/metasploit-framework/lib/gemcache/ruby* 2712 | |
| *Name * 2447 | |
| *Description * 2441 | |
| *Author * 2385 | |
| *License * 2281 | |
| *Version * 2245 | |
| */home/todb/svn/msf3/modules * 2178 | |
| *Type * 2086 | |
| *FileNames * 2030 | |
| *FilePaths * 2028 | |
| *$Revision$ * 1988 | |
| *FilePaths=/home/todb/svn/msf3/modules * 1893 | |
| *Platform * 1813 | |
| *: * 1777 | |
| *V * 1621 | |
| [*] Importing host 118.21.1.1 | |
| * * 63081 | |
| *847 * 59297 | |
| *tcp * 59069 | |
| *created_at * 58638 | |
| *updated_at * 58609 | |
| *id * 58402 | |
| *host_id * 57903 | |
| *name * 57465 | |
| *info * 57384 | |
| *state * 57370 | |
| *port * 57056 | |
| *proto * 56983 | |
| *open * 55304 | |
| */home/todb/git/rapid7/metasploit-framework/modules/exploits/* 4232 | |
| *unknown * 3615 | |
| */home/todb/git/rapid7/metasploit-framework/lib/gemcache/ruby* 2805 | |
| *initialize * 2805 | |
| *Payload * 2512 | |
| *filtered * 2416 | |
| */home/todb/git/rapid7/metasploit-framework/modules/auxiliary* 2382 | |
| [*] Importing host 118.21.1.2 | |
| * * 107421 | |
| *id * 106336 | |
| *updated_at * 105922 | |
| *created_at * 105894 | |
| *host_id * 104845 | |
| *info * 103832 | |
| *name * 103817 | |
| *state * 103804 | |
| *port * 103147 | |
| *proto * 103094 | |
| *tcp * 102709 | |
| *open * 96670 | |
| *848 * 52463 | |
| *847 * 51736 | |
| *unknown * 5901 | |
| *filtered * 4289 | |
| */home/todb/git/rapid7/metasploit-framework/modules/exploits/* 4231 | |
| */home/todb/git/rapid7/metasploit-framework/lib/gemcache/ruby* 2810 | |
| *initialize * 2722 | |
| *Payload * 2511 | |
| [*] Importing host 118.21.1.3 | |
| * * 159556 | |
| *updated_at * 156016 | |
| *created_at * 156002 | |
| *id * 155124 | |
| *tcp * 154262 | |
| *host_id * 154022 | |
| *info * 152362 | |
| *state * 152354 | |
| *name * 152287 | |
| *port * 151425 | |
| *proto * 151383 | |
| *open * 145660 | |
| *849 * 54075 | |
| *848 * 51592 | |
| *847 * 50676 | |
| *unknown * 9053 | |
| *filtered * 6245 | |
| */home/todb/git/rapid7/metasploit-framework/modules/exploits/* 4232 | |
| *workspace_id * 3654 | |
| *57 * 3588 | |
| [*] Importing host 118.21.1.4 | |
| *created_at * 207581 | |
| *updated_at * 207564 | |
| * * 207131 | |
| *id * 206433 | |
| *host_id * 204962 | |
| *info * 202567 | |
| *state * 202519 | |
| *name * 202416 | |
| *port * 201323 | |
| *proto * 201252 | |
| *tcp * 201155 | |
| *open * 190157 | |
| *849 * 52196 | |
| *850 * 51059 | |
| *848 * 50602 | |
| *847 * 50502 | |
| *unknown * 11578 | |
| *filtered * 8044 | |
| *workspace_id * 5069 | |
| *57 * 4994 | |
| [*] Importing host 118.21.1.5 | |
| * * 259356 | |
| *created_at * 257859 | |
| *updated_at * 257849 | |
| *id * 256396 | |
| *host_id * 254633 | |
| *tcp * 252845 | |
| *state * 251698 | |
| *info * 251669 | |
| *name * 251479 | |
| *port * 250157 | |
| *proto * 250100 | |
| *open * 238993 | |
| *851 * 53639 | |
| *850 * 51711 | |
| *849 * 50607 | |
| *847 * 50443 | |
| *848 * 50433 | |
| *unknown * 14612 | |
| *filtered * 10203 | |
| *workspace_id * 6194 | |
| [*] Importing host 118.21.1.6 | |
| *updated_at * 310623 | |
| *created_at * 310602 | |
| *id * 308631 | |
| * * 307420 | |
| *host_id * 306574 | |
| *state * 302894 | |
| *info * 302893 | |
| *name * 302576 | |
| *port * 300991 | |
| *proto * 300976 | |
| *tcp * 300276 | |
| *open * 283848 | |
| *851 * 51773 | |
| *852 * 51750 | |
| *850 * 50489 | |
| *848 * 50435 | |
| *849 * 50420 | |
| *847 * 50415 | |
| *unknown * 17248 | |
| *filtered * 12214 | |
| [*] Importing host 118.21.1.7 | |
| [*] Successfully imported /tmp/nmap.pro.poison.xml | |
| [*] resource (/home/todb/rc/nmap.rc)> Ruby Code (45 bytes) | |
| String 3842247 | |
| RubyVM::InstructionSequence 33220 | |
| Array 15626 | |
| Hash 7154 | |
| Regexp 4855 | |
| Class 4592 | |
| Module 2685 | |
| RubyVM::Env 2333 | |
| Proc 2097 | |
| Msf::OptBool 515 | |
| msf > irb | |
| [*] Starting IRB shell... | |
| >> DebugTodb.eyeball_strings | |
| */home/todb/git/rapid7/metasploit-framework/modules/exploits/* 101355 | |
| *Payload * 27897 | |
| *Platform * 26389 | |
| *Name * 24779 | |
| *Author * 24773 | |
| *Description * 24697 | |
| *Version * 24010 | |
| *Ret * 23701 | |
| *License * 23451 | |
| * * 23038 | |
| */home/todb/git/rapid7/metasploit-framework/modules/payloads/* 22757 | |
| *initialize * 20430 | |
| *$Revision$ * 19908 | |
| *V * 17218 | |
| *win * 17218 | |
| *References * 14836 | |
| */home/todb/git/rapid7/metasploit-framework/lib/gemcache/ruby* 14716 | |
| *Targets * 14511 | |
| *URL * 14301 | |
| *DisclosureDate * 14038 | |
| => nil | |
| >> | |
| Noticed that I have no idea how to actually work on MDM, because that's where the problem is. Futzed around with bundler for a bit, then just started editing in the local gemcache. | |
| Found that the problem is isolated to normalize_host_os -- commenting that out (by inserting a return before info_changed?) solved the problem. Let's dig there now. | |
| Found the problem is in the host.services.each block of normalize_os. Still have too many strings when that whole block is commented out, but it's better. By a lot. | |
| Tried ActiveRecord::Base.uncached {} block around everything in normalize_os. nope. | |
| At this point, went back to Port 80 Engineering, found that ObjectSpace already has count_objects. Mine's a wee bit nicer, though much slower. Whatever. Let's give gdb.rb a shot. | |
| Minor problems with gem install, fixed. Getting a feel for the interface. | |
| Turns out that ruby eval works, but ruby objects does not. So... kinda useless? The eval is nice but not what I want. | |
| It's getting late, so let's just avoid the problem for now. Think about how to make normalize_os switchable. It's okay to renormalize after one or two services are added, but not after every service is added and we have 100s to go through. | |
| Okay so never mind on that! CHanged normalize_os to this: | |
| finger_services = self.services.find(:all, :conditions => [ "name is not null and name != ''" ]) | |
| finger_services.each do |s| | |
| ... | |
| end | |
| and now no memory leak. let's see if the services are actually being queried tho... yep! Fingerprints are definitely still happening: | |
| address mac name os_name os_flavor os_sp purpose info comments | |
| ------- --- ---- ------- --------- ----- ------- ---- -------- | |
| 118.21.1.1 118-021-235-1.jp.synacktrap.net Apple embedded server | |
| 118.21.1.2 118-021-235-2.jp.synacktrap.net Apple embedded server | |
| 118.21.1.3 118-021-235-3.jp.synacktrap.net Linksys embedded server | |
| 118.21.1.4 118-021-235-4.jp.synacktrap.net Apple embedded server | |
| 118.21.1.5 118-021-235-5.jp.synacktrap.net Apple embedded server | |
| 118.21.1.6 118-021-235-6.jp.synacktrap.net Linksys embedded server | |
| 118.21.1.7 118-021-235-7.jp.synacktrap.net Apple embedded server | |
| This matches the 4.2.0 results. Let's import something a little more exciting... | |
| msf > db_import /home/todb/git/rapid7/qa/sample_data/msfxv3.zip | |
| msf > hosts | |
| Lookin good! This matches all the OS fingerprints from 4.2.0. There are slight differences between the device types, but that's certainly unrelated to this. | |
| Create a diff of my hacks to the local gemcache so I can get them committed proper: | |
| $ diff -Naur ../metasploit_data_models/lib/metasploit_data_models/active_record_models/host.rb lib/gemcache/ruby/1.9.1/gems/metasploit_data_models-0.0.2.43DEV/lib/metasploit_data_models/active_record_models/host.rb > /tmp/out.diff | |
| $ cd ../metasploit_data_models | |
| $ patch -p0 -i /tmp/out.diff | |
| And commit and stick this in a pastie so I don't forget how I did all this. | |
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
I've been troubleshooting some memory issues in an app that seem to have appeared since upgrading from Rails 2.3 to 3.x. I found this gist in my Google searches, and I am seeing similarly large object counts when I dump my ObjectSpace.
Your gist implies that you found a fix:
Which is a tantalizing detail.
Did you ever determine what the root cause of the memory bloat was?
Thanks in advance
Found the associated commit here:
rapid7/metasploit_data_models@5032377