Author: dmacvicar Date: Thu Nov 1 17:46:55 2007 New Revision: 7735 URL: http://svn.opensuse.org/viewcvs/zypp?rev=7735&view=rev Log: log statistics without drawing a timeline Modified: trunk/scripts/zypp-log-timeline.rb Modified: trunk/scripts/zypp-log-timeline.rb URL: http://svn.opensuse.org/viewcvs/zypp/trunk/scripts/zypp-log-timeline.rb?rev=7735&r1=7734&r2=7735&view=diff ============================================================================== --- trunk/scripts/zypp-log-timeline.rb (original) +++ trunk/scripts/zypp-log-timeline.rb Thu Nov 1 17:46:55 2007 @@ -3,6 +3,7 @@ require 'rubygems' require 'getoptlong' require 'logger' +require 'time' opts = GetoptLong.new( [ '--help', '-h', GetoptLong::NO_ARGUMENT ] @@ -66,6 +67,183 @@ LOG_MARKER_WIDTH = 20 BACKGROUND_COLOR = :black +class Statistic + attr_accessor :text + attr_accessor :number + attr_accessor :tmin + attr_accessor :tmax + attr_accessor :tavg +end + +class EventCollection < Array + + attr_accessor :average_duration + + UPDATE_STATUS = /START update\-status/ + QUERY_SYSTEM = /START query\-system/ + PARSE_METADATA = /START parse\-metadata/ + DOWNLOAD = /MediaCurl\.cc\(doGetFileCopy\):(.+) temp/ + APPLY_DELTA = /applydeltarpm' '-p' '-p'/ + RPM_INSTALL = /Executing 'rpm' '--root'/ + + def size_for_pattern(pattern) + count = 0 + self.each_with_pattern(pattern) do |e| + count += 1 + end + end + + def longest(pattern=nil) + elongest = first + self.each_with_pattern(pattern) do |e| + if (e.estimated_duration > elongest.estimated_duration) + elongest = e + end + end + return elongest + end + + def average_duration(pattern=nil) + return (total_duration(pattern) / self.size) + end + + def total_duration(pattern=nil) + d = 0 + self.each_with_pattern(pattern) do |e| + d += e.estimated_duration + end + return d + end + + def estimated_duration_default(index, offset=1) + if (! self[index+offset].nil?) + return self[index+offset].time - self[index].time + end + return 0 + end + + def estimated_duration_for(index) + return estimated_duration_until_pattern(index, /END update\-status/) if ( self[index].text =~ UPDATE_STATUS ) + return estimated_duration_until_pattern(index, /END parse\-metadata/) if ( self[index].text =~ PARSE_METADATA ) + return estimated_duration_until_pattern(index, /END query\-system/) if ( self[index].text =~ QUERY_SYSTEM ) + return estimated_duration_until_pattern(index, /ExternalProgram.cc\(checkStatus\)/) if ( self[index].text =~ RPM_INSTALL ) + return estimated_duration_until_pattern(index, /successfully completed/) if ( self[index].text =~ APPLY_DELTA ) + return estimated_duration_default(index) if ( self[index].text =~ DOWNLOAD ) + return estimated_duration_default(index) + end + + def estimated_duration_until_pattern(index, pattern) + k = index + duration = 0 + while ( ! (self[k].text =~ pattern) ) + k += 1 + end + return self[k].time - self[index].time + end + + # calculates the estimated durations + # by looking the difference witht the next + # events (set by offset), normally, a offset of + # 1 is enough, except for external programs which + # receive a log line inmediately saying pid launched, + # then you want to compare with the next next one. + def calculate! + #normalize + first = self.first.time + self.each do |e| + #e.time = e.time - first + end + + self.each_with_index do |e, i| + e.estimated_duration = estimated_duration_for(i) + end + end + + def each_update_status(&block) + self.each_with_pattern(UPDATE_STATUS) do |e| + yield e + end + end + + def each_query_system(&block) + self.each_with_pattern(QUERY_SYSTEM) do |e| + yield e + end + end + + def each_parse_metadata(&block) + self.each_with_pattern(PARSE_METADATA) do |e| + yield e + end + end + + def each_rpm_install(&block) + self.each_with_pattern(RPM_INSTALL) do |e| + yield e + end + end + + def each_apply_delta(&block) + self.each_with_pattern(APPLY_DELTA) do |e| + yield e + end + end + + def each_download(&block) + self.each_with_pattern(DOWNLOAD) do |e| + yield e + end + end + + def each_with_pattern(pattern, &block) + self.each do |e| + #puts e.text + if pattern.nil? + yield e + else + if e.text =~ pattern + yield(e) + end + end + end + end + + def print_all_statistics + puts "Total events: #{self.size}" + self.calculate! + puts "Downloads:" + self.each_download do |e| + #puts e + end + self.print_statistics(EventCollection::DOWNLOAD) + puts "Deltas:" + self.print_statistics(EventCollection::APPLY_DELTA) + puts "RPM Install:" + self.print_statistics(EventCollection::RPM_INSTALL) + puts "query-system:" + self.print_statistics(EventCollection::QUERY_SYSTEM) + puts "update-status:" + self.print_statistics(EventCollection::UPDATE_STATUS) + puts "parse-metadata:" + self.print_statistics(EventCollection::PARSE_METADATA) + end + + def print_statistics(pattern) + if self.empty? + puts "[empty collection]" + return + end + l = longest(pattern) + if l.nil? + puts "[No longest]" + return + end + puts "Total: #{total_duration(pattern)} | Max: #{l.estimated_duration} | Average #{average_duration(pattern)}" + puts "Longest was: #{l}" + end + +end + class Event attr_accessor :time attr_accessor :text @@ -73,6 +251,8 @@ attr_accessor :text_ypos attr_accessor :color + attr_accessor :estimated_duration + def initialize(time, text) @color = :white @time = time @@ -82,7 +262,8 @@ end def to_s - "#{time.strftime('%H:%M:%S')} #{text}" + "(#{estimated_duration} s) #{time.strftime('%H:%M:%S')} #{text}" + #"#{estimated_duration} s) #{text}" end end @@ -181,7 +362,7 @@ # scalable_surface_output("SVGSurface", "svg") -events = Array.new +events = EventCollection.new f = File.open(logfile, 'r') f.each_line do | l | @@ -190,12 +371,6 @@ host = $7 event = Event.new(time, $8) - begin - break if (events.last.time.to_i - events.first.time.to_i) > 10 - rescue - puts l - end - if not events.empty? if ( event.text =~ /update-status/ ) @@ -211,9 +386,8 @@ next elsif (event.time.to_i - events.last.time.to_i) == 0 # mark this as a collection of lot of events - events.last.color = :yellow - events.last.text = "(...) #{event.text}" - next + #events.last.color = :yellow + #events.last.text = "(...) #{event.text}" # last element is the same time to this one so remove it #events.pop else @@ -223,7 +397,8 @@ events << event else - raise "invalid log line [#{l}]" + #raise "invalid log line [#{l}]" + puts "Ignore: [#{l}]" end end @@ -231,11 +406,21 @@ $log.datetime_format = "%Y-%m-%d %H:%M:%S" $log.level = Logger::INFO -first = events.first.time -events.each do |e| - e.time = e.time - first -end + +#events.calculate! + + +puts "Total events: #{events.size}" +events.calculate! + +events.print_all_statistics + +#e = events.longest +#puts "[#{e.estimated_duration}] #{events.average_duration} #{e} " + + +exit metrics = Metrics.new(events) $log.info metrics.height $log.info "events: #{events.size} seconds: #{(events.last.time - events.first.time).to_i}" -- To unsubscribe, e-mail: zypp-commit+unsubscribe@opensuse.org For additional commands, e-mail: zypp-commit+help@opensuse.org