CS312 - Spring 2012 - Class 18

  • profilers
       - profiler (aka code profilers) are a way for understanding what your program is doing
          - in particular where it is spending most of its time
          - where it is allocating the most memory
          - etc.
       - a profiling program runs your code and monitors where your program spends its time, relative to the code
       - almost all languages have profilers of varying quality and complexity
       - if your programming is taking too long or using too much memory, a profiler is a good place to start

  • ruby profiling example
       - ruby has a built in profiler (though many external ones also exist)
       - to run it, you add "-r profile" after the ruby call, e.g.:

          ruby -r profile test.rb

       - look at test.rb in the ProfileExamples code
          - if we run this program, where will it spend the majority of its time?
          - we could guess at it, but let's run the profiler instead
       - after running we get a lot of output:

    % cumulative self self total
    time seconds seconds calls ms/call ms/call name
    46.54 4.44 4.44 502502 0.01 0.01 BasicObject#!=
    38.05 8.07 3.63 1000 3.63 9.44 LinkedList#add
    14.47 9.45 1.38 503502 0.00 0.00 BasicObject#==
    0.31 9.48 0.03 2 15.00 30.00 LinkedList#each
    0.31 9.51 0.03 1001 0.03 0.03 Class#new
    0.21 9.53 0.02 1 20.00 40.00 Integer#times
    0.10 9.54 0.01 1000 0.01 0.02 LinkedList#remove
    0.00 9.54 0.00 1 0.00 0.00 Float#/
    0.00 9.54 0.00 1 0.00 0.00 Kernel.require_relative
    0.00 9.54 0.00 1000 0.00 0.00 Node#initialize
    0.00 9.54 0.00 1 0.00 0.00 Module#attr_reader
    0.00 9.54 0.00 1 0.00 0.00 Module#attr_accessor
    0.00 9.54 0.00 1 0.00 9440.00 Integer#upto
    0.00 9.54 0.00 1000 0.00 0.00 Float#+
    0.00 9.54 0.00 1001 0.00 0.00 Fixnum#+
    0.00 9.54 0.00 12 0.00 0.00 Module#method_added
    0.00 9.54 0.00 1 0.00 0.00 BasicObject#initialize
    0.00 9.54 0.00 1 0.00 30.00 Object#average
    0.00 9.54 0.00 2 0.00 0.00 Float#to_s
    0.00 9.54 0.00 4 0.00 0.00 IO#write
    0.00 9.54 0.00 2 0.00 0.00 IO#puts
    0.00 9.54 0.00 2 0.00 0.00 Kernel.puts
    0.00 9.54 0.00 1000 0.00 0.00 Array#<<
    0.00 9.54 0.00 1 0.00 0.00 Array#sort
    0.00 9.54 0.00 2 0.00 0.00 Array#length
    0.00 9.54 0.00 2 0.00 0.00 Fixnum#/
    0.00 9.54 0.00 1 0.00 0.00 Fixnum#even?
    0.00 9.54 0.00 2 0.00 0.00 Array#[]
    0.00 9.54 0.00 1 0.00 0.00 Fixnum#-
    0.00 9.54 0.00 1 0.00 30.00 Object#median
    0.00 9.54 0.00 2 0.00 0.00 Class#inherited
    0.00 9.54 0.00 4 0.00 0.00 IO#set_encoding
    0.00 9.54 0.00 1 0.00 9540.00 #toplevel

          - each row in the output is a particular function (operators count as functions in ruby)
          - the output is sorted from most expensive to least
          - % time is the overall percentage of the program execution that was spent in this function
          - cumulative seconds is the total time spent doing this function AND ALL ABOVE
          - self-seconds is the total time spent in this funcion
          - calls is the number of calls
          - self ms/call is the time per call
       - looking at this where is the most time being spent?

  • profile data
       - different profilers give you differing amounts of information
          - for this one, all we have are the different functions
          - some, will give you a line-by-line allotment and will allow you to drill down into the data
       - BasicObject#!= and BasicObject#== are just checking for inequality/equality
       - LinkedList#add seems to be using a lot of time relative to everything else
          - this could be a hint to look into this more
          - if we look into it, we see that whoever implemented this, is added to the tail end of the linked list, but without a tail pointer!
             - every time the code has to traverse the linked list
          - if we change this to add to the front (or add a tail pointer) then the performance changes drastically

  • how do profilers work?
       - a number of different approaches
       - sampling: sample the program regularly and see where the program is and tally based on this
       - instrumentation: modify the source code to put in calls to profile code

  • look at faster.rb in ProfileExample code
       - which is faster, test1 or test2?
       - use the ruby profiler to figure it out
    •