CSC/ECE 517 Fall 2007/wiki1b 5 b4

Hold for Robin Yehle Wiki Assignment 1b AspectR is a very useful Ruby module, but it is not easy to find documentation on it that is appropriate for students taking this class. Find, or construct, documentation that explains what it does without presuming previous knowledge of AspectJ, that describes many or all methods of the module and how they work. Also find or produce an easy-to-understand example that does not involve logging.

Example: Profiler Aspect

One common use of AOP is profiling. Profiling refers to the collection of data about the dynamic behavior of a system. It is done to determine a breakdown of where time and memory are being consumed at runtime and make optimizations based on the results. In the example below, which is based off a sample found in make a link -- Ruby Developer's Guide, we create an aspect that will determine the number of (milli)seconds spent in a single method. It is kept very simple to clearly illustrate the functionality of AspectR; a full-featured profiler would need to account for non-serialized and nested method invocations, aggregate the results, etc.

The Profiler class, which inherits Aspect, contains two methods: profiler_enter and profiler_exit. The before advice, profiler_enter, records the time immediately before the method is invoked. The after advice, profiler_exit, records the time immediately after the method exits and prints out the duration of the method invocation.

require 'aspectr'
include AspectR
class Profiler < Aspect
   
  def profiler_enter(method, object, exitstatus, *args) 
    @enter_time = Time.now
    puts "#{@enter_time.strftime('%Y-%m-%d %X')} #{self.class}##{method}: #{args.inspect}" 
   end
   
  def profiler_exit(method, object, exitstatus, *args) 
    @exit_time = Time.now
    print "#{@exit_time.strftime('%Y-%m-%d %X')} #{self.class}##{method}: exited " 
    if exitstatus.kind_of?(Array) 
      print "normally returning #{exitstatus[0].inspect} " 
    elsif exitstatus == true 
      print "with exception '#{$!}' " 
    else 
      print "normally " 
    end 
    puts "after #{@exit_time.to_f - @enter_time.to_f} seconds"
  end
end

A user of Profiler would need to wrap all methods that she is interested in profiling. The program below uses the Profiler aspect to calculate the amount of time spent in the SomeClass.method1 method call.

class SomeClass
  def method1(str)
    puts "entering SomeClass.method1 #{str}"
    sleep 5.3
    puts "exiting SomeClass.method1"
  end
end

Profiler.new.wrap(SomeClass, :profiler_enter, :profiler_exit, :method1)
SomeClass.new.method1 "test"

This program generates the following output:

2007-09-30 22:05:51 Profiler#method1: ["test"]
entering SomeClass.method1 test
exiting SomeClass.method1
2007-09-30 22:05:56 Profiler#method1: exited normally returning nil after 5.29699993133545 seconds

You can see from the Profiler output that SomeClass.method1 took approximately 5.3 seconds to execute, as expected.