gc inspectionlcg/gc-inspection

5 files changed, 105 insertions, 9 deletions

diff --git a/lib/chef/client.rb b/lib/chef/client.rb
index 621ce3d489..cc049ef6cc 100644
--- a/lib/chef/client.rb
+++ b/lib/chef/client.rb
@@ -1,4 +1,4 @@
-#
+##
 # Author:: Adam Jacob (<adam@opscode.com>)
 # Author:: Christopher Walters (<cw@opscode.com>)
 # Author:: Christopher Brown (<cb@opscode.com>)
@@ -232,6 +232,21 @@ class Chef
     # @return Always returns true.
     #
     def run
+
+      require 'objspace'
+
+      require 'gc_tracer'
+
+      #      ObjectSpace.trace_object_allocations_start
+
+      #      require 'ruby-prof'
+      #
+      #      RubyProf.start
+      #      report = MemoryProfiler.report(top:200) do
+
+      GC::Tracer.start_logging('/tmp/chef-gctrace.out') do
+
+
       run_error = nil
 
       runlock = RunLock.new(Chef::Config.lockfile)
@@ -248,26 +263,47 @@ class Chef
         Chef::Log.info "Chef-client pid: #{Process.pid}"
         Chef::Log.debug("Chef-client request_id: #{request_id}")
         enforce_path_sanity
+
+        GC::Tracer.custom_event_logging("before_run_ohai")
+
         run_ohai
 
+        GC::Tracer.custom_event_logging("before_register")
+
         register unless Chef::Config[:solo]
 
+        GC::Tracer.custom_event_logging("before_load_node")
+
         load_node
 
+        GC::Tracer.custom_event_logging("before_build_node")
+
         build_node
 
+        GC::Tracer.custom_event_logging("after_build_node")
+
         run_status.run_id = request_id
         run_status.start_clock
         Chef::Log.info("Starting Chef Run for #{node.name}")
         run_started
 
+        GC::Tracer.custom_event_logging("before_windows_admin_check")
+
         do_windows_admin_check
 
+        GC::Tracer.custom_event_logging("before_setup_run_context")
+
         run_context = setup_run_context
 
+        GC::Tracer.custom_event_logging("before_converge")
+
+        GC.start(full_mark: true)
         if Chef::Config[:audit_mode] != :audit_only
           converge_error = converge_and_save(run_context)
         end
+        GC.start(full_mark: true)
+
+        GC::Tracer.custom_event_logging("after_converge")
 
         if Chef::Config[:why_run] == true
           # why_run should probably be renamed to why_converge
@@ -286,6 +322,10 @@ class Chef
 
         # rebooting has to be the last thing we do, no exceptions.
         Chef::Platform::Rebooter.reboot_if_needed!(node)
+
+        GC::Tracer.custom_event_logging("before_main_loop_exit")
+
+        GC.start(full_mark: true)
       rescue Exception => run_error
         # CHEF-3336: Send the error first in case something goes wrong below and we don't know why
         Chef::Log.debug("Re-raising exception: #{run_error.class} - #{run_error.message}\n#{run_error.backtrace.join("\n  ")}")
@@ -297,13 +337,16 @@ class Chef
         end
         events.run_failed(run_error)
       ensure
-        Chef::RequestID.instance.reset_request_id
-        request_id = nil
-        @run_status = nil
-        run_context = nil
-        runlock.release
+        #Chef::RequestID.instance.reset_request_id
+        #request_id = nil
+        #@run_status = nil
+        #run_context = nil
+        #runlock.release
+        #GC.start
       end
 
+      GC::Tracer.custom_event_logging("after_main_loop_exit")
+
       # Raise audit, converge, and other errors here so that we exit
       # with the proper exit status code and everything gets raised
       # as a RunFailedWrappingError
@@ -324,6 +367,45 @@ class Chef
         raise error
       end
 
+      GC.start(full_mark: true)
+      end
+
+      system "ps uwwp `pgrep chef-client`"
+      ObjectSpace.dump_all(output: File.open("/tmp/chef-heap.json", "w"))
+      puts "MEMSIZE OF ALL: #{ObjectSpace.memsize_of_all}"
+      pp GC.stat
+      pp ObjectSpace.count_objects_size
+      pp ObjectSpace.count_tdata_objects
+      size = {}
+      gem = {}
+      ObjectSpace.each_object(RubyVM::InstructionSequence) do |iseq|
+        memsize = ObjectSpace.memsize_of(iseq)
+        path = iseq.absolute_path
+        if path =~ %r{/opt/chef/embedded/lib/ruby/gems/2.1.0/gems/(.*?)/}
+          gem[$1] ||= 0
+          gem[$1] += memsize
+        end
+        if path =~ %r{/opt/chef/embedded/apps/(.*?)/}
+          gem[$1] ||= 0
+          gem[$1] += memsize
+        end
+
+        size[path] = memsize
+      end
+      puts "FILES:"
+      size.sort_by { |key, value| value }.reverse.each do |h|
+        puts "#{h[0]}: #{h[1]}"
+      end
+      puts "GEMS:"
+      gem.sort_by { |key, value| value }.reverse.each do |h|
+        puts "#{h[0]}: #{h[1]}"
+      end
+
+#      result = RubyProf.stop
+#      RubyProf::GraphPrinter.new(result).print(STDOUT, {})
+
+      system "ps uwwp `pgrep chef-client`"
+
       true
     end
 
diff --git a/lib/chef/mixin/command/unix.rb b/lib/chef/mixin/command/unix.rb
index 2bad4e6bcf..5de0ffc670 100644
--- a/lib/chef/mixin/command/unix.rb
+++ b/lib/chef/mixin/command/unix.rb
@@ -30,7 +30,7 @@ class Chef
         def popen4(cmd, args={}, &b)
           # Ruby 1.8 suffers from intermittent segfaults believed to be due to GC while IO.select
           # See CHEF-2916 / CHEF-1305
-          GC.disable
+          #GC.disable
 
           # Waitlast - this is magic.
           #
@@ -211,7 +211,7 @@ class Chef
             [cid, pw.last, pr.first, pe.first]
           end
         ensure
-          GC.enable
+          #GC.enable
         end
 
       end
diff --git a/lib/chef/run_context.rb b/lib/chef/run_context.rb
index 0c8d3d1a48..57fa8c14ca 100644
--- a/lib/chef/run_context.rb
+++ b/lib/chef/run_context.rb
@@ -291,6 +291,8 @@ ERROR_MESSAGE
         node.loaded_recipe(cookbook_name, recipe_short_name)
         cookbook = cookbook_collection[cookbook_name]
         cookbook.load_recipe(recipe_short_name, self)
+        GC::Tracer.custom_event_logging("after #{recipe_name} compiled")
+        GC.start(full_mark: true)
       end
     end
 
diff --git a/lib/chef/run_context/cookbook_compiler.rb b/lib/chef/run_context/cookbook_compiler.rb
index abe5afa7ae..166423efc2 100644
--- a/lib/chef/run_context/cookbook_compiler.rb
+++ b/lib/chef/run_context/cookbook_compiler.rb
@@ -97,6 +97,8 @@ class Chef
         @events.library_load_start(count_files_by_segment(:libraries))
         cookbook_order.each do |cookbook|
           load_libraries_from_cookbook(cookbook)
+          GC::Tracer.custom_event_logging("after #{cookbook} libraries loaded")
+          GC.start(full_mark: true)
         end
         @events.library_load_complete
       end
@@ -108,6 +110,8 @@ class Chef
         @events.attribute_load_start(count_files_by_segment(:attributes))
         cookbook_order.each do |cookbook|
           load_attributes_from_cookbook(cookbook)
+          GC::Tracer.custom_event_logging("after #{cookbook} attributes loaded")
+          GC.start(full_mark: true)
         end
         @events.attribute_load_complete
       end
@@ -119,6 +123,8 @@ class Chef
         @events.lwrp_load_start(lwrp_file_count)
         cookbook_order.each do |cookbook|
           load_lwrps_from_cookbook(cookbook)
+          GC::Tracer.custom_event_logging("after #{cookbook} LWRPs loaded")
+          GC.start(full_mark: true)
         end
         @events.lwrp_load_complete
       end
@@ -128,6 +134,8 @@ class Chef
         @events.definition_load_start(count_files_by_segment(:definitions))
         cookbook_order.each do |cookbook|
           load_resource_definitions_from_cookbook(cookbook)
+          GC::Tracer.custom_event_logging("after #{cookbook} definitions loaded")
+          GC.start(full_mark: true)
         end
         @events.definition_load_complete
       end
diff --git a/lib/chef/runner.rb b/lib/chef/runner.rb
index 6125fe59e1..ca68d17f57 100644
--- a/lib/chef/runner.rb
+++ b/lib/chef/runner.rb
@@ -78,7 +78,11 @@ class Chef
 
       # Execute each resource.
       run_context.resource_collection.execute_each_resource do |resource|
-        Array(resource.action).each {|action| run_action(resource, action)}
+        Array(resource.action).each {|action|
+          run_action(resource, action)
+          GC::Tracer.custom_event_logging("after #{resource} #{action}")
+          GC.start(full_mark: true)
+        }
       end
 
     rescue Exception => e