@@ -1,29 +1,32 @@ +# This isn't technically a Bundler gemfile anymore... +# To install these gems, run bin/install_gems + merb_gems_version = "1.1" dm_gems_version = "0.10.1" do_gems_version = "0.10.0" # Set bundle path to ./gems. use the "gem bundle" command to generate the bundle -bundle_path("tmp/" + RUBY_RELEASE_DATE) -source "http://edge.merbivore.com" - -gem "merb-core", merb_gems_version -gem "merb-assets", merb_gems_version -gem "merb-cache", merb_gems_version -gem "merb-haml", merb_gems_version -gem "merb-mailer", merb_gems_version -gem "merb-exceptions", merb_gems_version +#bundle_path("tmp/" + RUBY_RELEASE_DATE) +#source "http://edge.merbivore.com" gem "memcache-client", "1.7.5", :require_as => [] gem "curb", "0.5.4.0" gem "nokogiri", "1.3.3" -gem "gchartrb", :require_as => "google_chart" +gem "gchartrb", nil, :require_as => "google_chart" gem "sinatra", "0.9.4" -gem "mime-types", :require_as => "mime/types" +gem "mime-types", nil, :require_as => "mime/types" gem "moneta", "0.6.0" -only :test do +gem "merb-core", merb_gems_version, :source => "http://edge.merbivore.com" +gem "merb-assets", merb_gems_version, :source => "http://edge.merbivore.com" +gem "merb-cache", merb_gems_version, :source => "http://edge.merbivore.com" +gem "merb-haml", merb_gems_version, :source => "http://edge.merbivore.com" +gem "merb-mailer", merb_gems_version, :source => "http://edge.merbivore.com" +gem "merb-exceptions", merb_gems_version, :source => "http://edge.merbivore.com" + +#only :test do gem "thin" gem "rake" gem "webrat" - gem "rspec", :require_as => [] -end + gem "rspec" +#end Gemfile @@ -7,16 +7,16 @@ class Application < Merb::Controller before :no_language_domain include ControllerExtensions::Logging include ControllerExtensions::Accessors - + protected - + def no_language_domain if request.language_code == "m" language_code = (request.env["HTTP_ACCEPT_LANGUAGE"] || "en")[0..1] || "en" throw :halt, redirect("http://#{language_code}.#{request.host}") end end - + # Override in each controller for better control def current_name @title || "Wikipedia" app/controllers/application.rb @@ -71,7 +71,8 @@ class Articles < Application private def format_display_with_data(html = nil, &block) - Merb.logger.debug("CTYPE: #{content_type}") + Merb.logger[:content_type] = content_type + case content_type when :json json = JSON.dump(block.call) @@ -101,7 +102,7 @@ class Articles < Application Merb.logger.debug("KEY: #{key}") if html - Merb.logger.debug("CACHE HIT") + Merb.logger[:cache_hit] = true return html else html = block.call @@ -110,7 +111,7 @@ class Articles < Application Cache.store(key, html, :expires_in => 60 * 60 * 12) end - Merb.logger.debug("CACHE MISS") + Merb.logger[:cache_hit] = false end html end app/controllers/articles.rb @@ -1,24 +1,42 @@ module ControllerExtensions module Logging def self.included(klass) - klass.before :logger_output + klass.before :start_timer + klass.after :logger_output # DEVELOPMENT if Merb.env == "development" - klass.before :debug_output klass.before :clear_cache end end + + def start_timer + @timer = Time.now + end def logger_output - Merb.logger.info("ReqLogger #{Time.now.to_s} (#{request.language_code}) #{params[:controller]}/#{params[:action]} | #{request.user_agent} | #{request.device.format_name} | #{request.remote_ip} | #{request.referer}") - end - - def debug_output - Merb.logger.debug("User Agent: " + request.user_agent) - Merb.logger.debug("Format: " + request.device.format_name.to_s) - Merb.logger.debug("Language Code: " + request.language_code) - Merb.logger.debug("Accepts: " + request.accept) + logged_data = {:time => Time.now.to_s, + :action_time => (Time.now - @timer), + :language_code => request.language_code, + :country_code => request.country_code, + :user_agent => request.user_agent, + :referer => request.referer, + :format_name => request.device.format_name, + :was_redirected => params[:wasRedirected], + :was_home_page => (params[:action] == "home") + } + + if @article + logged_data[:article_title] = @article.title + end + + # This is an extension that we added to logger + logged_data.merge!(Merb.logger.dump_logger_hash) + + # Dump it out! + yaml = logged_data.to_yaml + yaml_flat = yaml.gsub("\n", "\\n") + Merb.logger.warn("~~~~" + yaml_flat) end def clear_cache app/controllers/extensions/logging.rb @@ -21,7 +21,7 @@ class Article < Wikipedia::Resource def has_search_results? if (@html = Cache[key]) Merb.logger.debug("KEY: #{key}") - Merb.logger.debug("CACHE HIT") + Merb.logger[:cache_hit] = true return false else fetch! if raw_html.nil? @@ -50,17 +50,17 @@ class Article < Wikipedia::Resource time_to "lookup in cache" do Merb.logger.debug("KEY: #{key}") if (@html = Cache[key]) - Merb.logger.debug("CACHE HIT") + Merb.logger[:cache_hit] = true return @html.force_encoding("UTF-8") else - Merb.logger.debug("CACHE MISS") + Merb.logger[:cache_hit] = false end end # Grab the html from the server object fetch! if raw_html.nil? - time_to "parse #{device}" do + time_to "parse and modify xml" do # Figure out if we need to do extra formatting... case device.parser when "html" app/models/article.rb @@ -38,28 +38,25 @@ class Server paths.each do |path| result = nil - Merb.logger.debug("loading... " + base_url + path) - result = fetch_from_web(path) compressed_size = result.downloaded_content_length - Merb.logger.debug("loaded #{result.downloaded_content_length} compressed characters") + Merb.logger[:gzipped_raw_article_content_length] = result.downloaded_content_length if result.response_code == 200 if result.header_str.include?("Cache-Lookup: HIT") - Merb.logger.debug("Spider HIT") + Merb.logger[:wikipedia_cache_hit] = true else - Merb.logger.debug("Spider MISS") + Merb.logger[:wikipedia_cache_hit] = false end body = nil - - - time_to "decompress" do - + + time_to "decompress downloaded article" do + begin gz = Zlib::GzipReader.new( StringIO.new( result.body_str ) ) body = gz.read @@ -71,7 +68,7 @@ class Server body = body.force_encoding("UTF-8") end - Merb.logger.debug("Decompressed to #{body.size} characters") + Merb.logger[:raw_article_content_length] = body.size return {:url => result.last_effective_url, :body => body} end @@ -84,7 +81,7 @@ class Server # :api: private def fetch_from_web(path) - time_to "fetch" do + time_to "download article from web" do if defined?(Curl) begin Curl::Easy.perform(base_url + path) do |curl| app/models/server.rb @@ -1,3 +1,3 @@ .message.notice - Wikipedia Mobile needs your help--- + US-Users %a{:href => "/donate"} find out how you can help! app/views/notices/_donate.html.haml @@ -2,7 +2,7 @@ Merb.logger.info("Loaded PRODUCTION Environment...") Merb::Config.use { |c| c[:exception_details] = false c[:reload_classes] = false - c[:log_level] = :debug + c[:log_level] = :warn c[:default_cookie_domain] = ".wikipedia.org" c[:log_file] = Merb.root / "log" / "production.log" config/environments/production.rb @@ -2,7 +2,8 @@ class Object def time_to(thing, &block) start_time = Time.now result = block.call - Merb.logger.debug("#{thing} took " + (Time.now - start_time).to_s + " seconds") + Merb.logger[:time_to] ||= {} + Merb.logger[:time_to][thing] = (Time.now - start_time) return result end end \ No newline at end of file lib/object.rb @@ -14,8 +14,8 @@ class StatSegment extend StatMerging::ClassMethods property :id, Serial - property :time, Time, :indexed => true - property :time_length, String, :indexed => true + property :time, Time, :index => true + property :time_length, String, :index => true property :cache_hit_ratio, Float property :spider_cache_hit_ratio, Float property :hits, Integer @@ -28,6 +28,9 @@ class StatSegment property :median_action_time, Float, :default => 0.0 property :language_hits, Object, :lazy => false property :format_hits, Object, :lazy => false + property :country_hits, Object, :lazy => false + property :user_agent_hits, Object, :lazy => false + property :content_type_hits, Object, :lazy => false property :cache_size, Integer property :load_average, Float stats/models/stat.rb @@ -5,121 +5,127 @@ trap("USR1") { def run_parser(path) log_file = File::join(path, "log", "production.log") - file = log_file + "." + Time.now.to_i.to_s + file = log_file #+ "." + Time.now.to_i.to_s - `mv #{log_file} #{file}` - `pkill -USR1 thin` + #{}`mv #{log_file} #{file}` + #{}`pkill -USR1 thin` - stats = StatSegment.new(:time => Time.now, :time_length => "minute") + stat = Stat.new(:time => Time.now, :time_length => "minute") ## ====================== LANGUAGE AND FORMAT ================================= - languages = {} - formats = {} - hits = `cat #{file} | grep ReqLogger | wc`.split(" ").first.to_i + languages = {} + formats = {} + countries = {} + user_agents = {} + content_types = {} + hits = 0 + cache_hit_count = 0 + spider_cache_hits = 0 + home_page_views = 0 + redirects = 0 + + fastest_hit = 1000000000000000000000000 + slowest_hit = 0 + total_hit_time = 0.0 + all_times = [] begin - `cat #{file} | grep ReqLogger`.split("\n").each do |line| + `cat #{file} | grep ~~~~`.split("\n").each do |line| begin - format = line.split("|")[2].strip - language = line.scan(/\((..)\)/).first.first + yaml = line.split("~~~~")[1].gsub("\\n", "\n") + d = YAML.load(yaml) + + hits += 1 + + + ## RATIOS + + if d[:cache_hit] + cache_hit_count += 1 + end + + if d[:wikipedia_cache_hit] + spider_cache_hits += 1 + end + + # Counters + + if d[:was_home_page] + home_page_views += 1 + end + + if d[:was_redirected] + redirects += 1 + end + + + ## VARIOUS HIT COUNTERS + + format = d[:format_name].to_s + language = d[:language_code] + country = d[:country_code] + user_agent = d[:user_agent] + content_type = d[:content_type] formats[format] ||= 0 formats[format] += 1 + + countries[country] ||= 0 + countries[country] += 1 languages[language] ||= 0 languages[language] += 1 + + user_agents[user_agent] ||= 0 + user_agents[user_agent] += 1 + + content_types[content_type] ||= 0 + content_types[content_type] += 1 + + # Action Speed + + time = d[:action_time] + total_hit_time += time + all_times << time + if time < fastest_hit + fastest_hit = time + end + if time > slowest_hit + slowest_hit = time + end rescue puts "problem with line" end end rescue - puts "problem with line #{line}" - end - - stats.language_hits = languages - stats.format_hits = formats - stats.hits = hits - - ## ======================= LOCAL CACHE HIT RATIO ================================= - - cache_hit_count = 0 - cache_miss_count = 0 - - `cat #{file} | grep CACHE`.split("\n").each do |line| - if line.include?("HIT") - cache_hit_count += 1 - elsif line.include?("MISS") - cache_miss_count += 1 - end - end - - stats.cache_hit_ratio = cache_hit_count.to_f / (cache_hit_count + cache_miss_count) - - ## ======================= WIKIPEDIA CACHE HIT RATIO ================================= - - cache_hit_count = 0 - cache_miss_count = 0 - - `cat #{file} | grep Spider`.split("\n").each do |line| - if line.include?("HIT") - cache_hit_count += 1 - elsif line.include?("MISS") - cache_miss_count += 1 - end + puts "problem with line #{line}" end - stats.spider_cache_hit_ratio = cache_hit_count.to_f / (cache_hit_count + cache_miss_count) + stat.language_hits = languages + stat.format_hits = formats + stat.country_hits = countries + stat.user_agent_hits = user_agents + stat.content_type_hits = content_types + stat.hits = hits + stat.cache_hit_ratio = cache_hit_count.to_f / hits + stat.spider_cache_hit_ratio = spider_cache_hits.to_f / hits + stat.redirects = redirects + stat.home_page_views = home_page_views + + stat.slowest_action_time = slowest_hit + stat.fastest_action_time = fastest_hit + stat.average_action_time = (total_hit_time / stat.hits) + stat.median_action_time = all_times.sort[(all_times.size / 2)] - ## =========================== REDIRECTS ==================================== - - stats.redirects = `cat #{file} | grep Params | grep wasRedirected`.split("\n").size - - ## ======================== HOME PAGE VIEWS ================================= - - stats.home_page_views = `cat #{file} | grep Params | grep \"home\"`.split("\n").size - - ## ============================= ERRORS ====================================== - - stats.error_count = `cat #{file} | grep "/usr/bin/thin" | grep main`.split("\n").size - - ## ========================== ACTION SPEED ================================== - - fastest_hit = 1000000000000000000000000 - slowest_hit = 0 - total_hit_time = 0.0 - all_times = [] + stat.cache_size = ((`ps -eO rss | grep memcache`.split("\n").select {|a| a.include?("11211") }).first.split(" ")[1].to_i / 1024) + stat.load_average = `uptime`.scan(/[0-9.]+$/).first.to_f - `cat #{file} | grep action_time`.split("\n").each do |line| - begin - time = line.scan(/:action_time=>([0-9.]+)/).first.first.to_f - total_hit_time += time - all_times << time - if time < fastest_hit - fastest_hit = time - end - if time > slowest_hit - slowest_hit = time - end - rescue NoMethodError - puts "problem with line #{line}" - end + if stat.save + `rm #{file}` + else + puts "problem with #{stat.inspect}" end - - stats.slowest_action_time = slowest_hit - stats.fastest_action_time = fastest_hit - stats.average_action_time = (total_hit_time / stats.hits) - stats.median_action_time = all_times.sort[(all_times.size / 2)] - - ## ======================= CACHE SIZE ================================ - stats.cache_size = ((`ps -eO rss | grep memcache`.split("\n").select {|a| a.include?("11211") }).first.split(" ")[1].to_i / 1024) - - ## ======================= SERVER LOAD ================================ - stats.load_average = `uptime`.scan(/[0-9.]+$/).first.to_f - - puts stats.save.to_s + " " + Time.now.to_s - - `rm #{file}` end run_parser(ARGV[0]) stats/parse.rb @@ -2,6 +2,6 @@ trap("USR1") do end loop do - `ruby parse.rb #{ARGV[0]} &` + `ruby /srv/mobile/current/stats/parse.rb #{ARGV[0]} &` sleep(60) end stats/run.rb eaecba1bf89dca11d60e662a76f429f104cc6fed Hampton Catlin hcatlin@gmail.com http://github.com/hcatlin/wikimedia-mobile/commit/7e41da874c13356b8845887061e753b0e75f3e92 7e41da874c13356b8845887061e753b0e75f3e92 2009-10-27T06:45:15-07:00 2009-10-27T06:45:15-07:00 more changes to the logging system ab1be9c052a727606b8fcbd2cc730eb19f64e610 Hampton Catlin hcatlin@gmail.com