Closed JasonBarnabe closed 9 years ago
Profile of qbxml parsing a 500-invoice XML document:
Thread ID: 7009080 Fiber ID: 11106080 Total: 42.675820 Sort by: self_time %self total self wait child calls name 76.46 32.736 32.628 0.000 0.107 17658 Nokogiri::XML::XPathContext#evaluate 2.69 2.596 1.148 0.000 1.448 20169 ActiveSupport::Inflector#underscore 2.52 1.079 1.074 0.000 0.004 83176 String#gsub! 2.16 0.920 0.920 0.000 0.000 17657 Nokogiri::XML::Node#path 1.18 0.503 0.503 0.000 0.000 17658 <Class::Nokogiri::XML::XPathContext>#new 0.67 0.285 0.285 0.000 0.000 17657 String#gsub 0.62 0.986 0.265 0.000 0.721 17658 Nokogiri::XML::Node#extract_params 0.62 36.457 0.263 0.000 36.194 17657 <Class::Qbxml::Hash>#typecast 0.61 36.784 0.260 0.000 36.524 35317 Array#map 0.55 0.235 0.235 0.000 0.000 35317 Nokogiri::XML::Document#root 0.50 0.215 0.215 0.000 0.000 76705 Nokogiri::XML::Document#decorate 0.40 34.925 0.170 0.000 34.755 17658 Nokogiri::XML::Node#xpath 0.34 0.220 0.145 0.000 0.075 55982 Nokogiri::XML::NodeSet#[] 0.34 0.145 0.145 0.000 0.000 17657 String#=~ 0.33 0.141 0.141 0.000 0.000 17657 Nokogiri::XML::Node#text 0.27 0.149 0.116 0.000 0.033 20668 Nokogiri::XML::Node#children 0.26 0.187 0.112 0.000 0.075 38326 Array#each 0.25 0.370 0.105 0.000 0.265 17657 Object#try 0.23 0.096 0.096 0.000 0.000 96325 Module#=== 0.23 0.345 0.096 0.000 0.249 35314 Object#present? 0.22 0.534 0.096 0.000 0.438 17657 Proc#[] 0.20 0.117 0.084 0.000 0.033 38324 Nokogiri::XML::Node#element? 0.18 0.109 0.075 0.000 0.034 40838 Array#include? 0.17 0.071 0.071 0.000 0.000 52974 Nokogiri::XML::Document#document 0.16 0.077 0.070 0.000 0.007 1 <Class::Nokogiri::XML::Document>#read_io 0.16 0.170 0.068 0.000 0.102 17658 <Module::Nokogiri>#uses_libxml? 0.15 0.142 0.066 0.000 0.077 17658 Nokogiri::XML::Node#namespaces 0.15 0.063 0.063 0.000 0.000 20169 Regexp#to_s 0.14 0.060 0.060 0.000 0.000 17664 Kernel#respond_to? 0.14 0.193 0.060 0.000 0.133 20169 ActiveSupport::Inflector#inflections 0.13 0.220 0.057 0.000 0.162 17658 Enumerable#find 0.13 0.056 0.056 0.000 0.000 17658 Nokogiri::VersionInfo#libxml2? 0.12 0.080 0.052 0.000 0.028 20169 ThreadSafe::Cache#[] 0.12 0.051 0.051 0.000 0.000 17657 Nokogiri::XML::Node#content 0.12 0.051 0.051 0.000 0.000 10000 Regexp#match 0.12 0.191 0.050 0.000 0.141 17657 Kernel#public_send 0.12 0.117 0.049 0.000 0.068 1000 <Class::Date>#_parse 0.11 0.083 0.049 0.000 0.035 17658 Nokogiri::XML::NodeSet#first 0.11 0.046 0.046 0.000 0.000 17658 <Class::Nokogiri::VersionInfo>#instance 0.11 0.046 0.046 0.000 0.000 55981 Nokogiri::XML::Node#type 0.11 0.093 0.045 0.000 0.047 1500 <Class::Date>#parse 0.11 2.640 0.045 0.000 2.596 20169 String#underscore 0.10 0.044 0.044 0.000 0.000 20668 Nokogiri::XML::Node#name 0.10 0.231 0.044 0.000 0.187 17657 String#blank? 0.10 0.187 0.043 0.000 0.145 17657 Kernel#!~ 0.10 0.041 0.041 0.000 0.000 20668 Nokogiri::XML::Node#attribute_nodes 0.09 0.120 0.040 0.000 0.080 20169 <Class::ActiveSupport::Inflector::Inflections>#instance 0.09 0.064 0.040 0.000 0.024 17658 Nokogiri::XML::XPathContext#register_namespaces 0.09 0.038 0.038 0.000 0.000 35316 Array#first 0.09 0.037 0.037 0.000 0.000 23180 Hash#[]= 0.09 0.080 0.037 0.000 0.044 20169 Kernel#dup 0.09 0.049 0.037 0.000 0.012 17657 Nokogiri::XML::Node#text? 0.08 0.034 0.034 0.000 0.000 46349 String#to_s 0.08 0.042 0.034 0.000 0.008 1000 <Class::Time>#utc 0.08 0.033 0.033 0.000 0.000 17658 <Class::Hash>#[] 0.07 0.031 0.031 0.000 0.000 20668 Hash#delete 0.07 0.031 0.031 0.000 0.000 20169 String#tr! 0.07 0.030 0.030 0.000 0.000 35316 Array#last 0.07 0.028 0.028 0.000 0.000 41340 Kernel#block_given? 0.07 0.028 0.028 0.000 0.000 20169 ThreadSafe::NonConcurrentCacheBackend#[] 0.06 0.028 0.028 0.000 0.000 17658 Nokogiri::XML::Node#namespace_scopes 0.06 0.044 0.026 0.000 0.018 20169 Kernel#initialize_dup 0.06 3.079 0.024 0.000 3.055 20670 *Hash#each 0.05 0.023 0.023 0.000 0.000 1 <Class::Nokogiri::XML::Document>#read_memory 0.05 0.023 0.023 0.000 0.000 20668 Nokogiri::XML::NodeSet#length 0.05 0.020 0.020 0.000 0.000 17658 Array#reverse 0.05 0.020 0.020 0.000 0.000 17658 Module#== 0.05 0.023 0.020 0.000 0.003 2000 Time#strftime 0.04 0.119 0.019 0.000 0.100 1000 <Class::Time>#make_time 0.04 0.024 0.018 0.000 0.005 1000 <Class::Time>#apply_offset 0.04 0.022 0.018 0.000 0.004 1000 <Class::Time>#zone_offset 0.04 0.018 0.018 0.000 0.000 20169 String#initialize_copy 0.04 0.017 0.017 0.000 0.000 17657 Hash#blank? 0.04 0.017 0.017 0.000 0.000 17660 Kernel#nil? 0.04 0.016 0.016 0.000 0.000 9157 Kernel#String 0.04 0.016 0.016 0.000 0.000 20169 String#downcase! 0.04 0.015 0.015 0.000 0.000 3500 MatchData#begin 0.04 0.015 0.015 0.000 0.000 17658 Kernel#class 0.03 0.014 0.014 0.000 0.000 20169 String#== 0.03 0.013 0.013 0.000 0.000 1500 Date#strftime 0.03 0.012 0.012 0.000 0.000 3500 String#[]= 0.03 0.011 0.011 0.000 0.000 5502 String#downcase 0.03 0.011 0.011 0.000 0.000 2500 Kernel#Float 0.02 0.035 0.010 0.000 0.024 1000 Time#xmlschema 0.02 0.246 0.010 0.000 0.237 1000 <Class::Time>#parse 0.02 0.010 0.010 0.000 0.000 9000 Fixnum#divmod 0.02 0.007 0.007 0.000 0.000 514 IO#read 0.02 0.090 0.007 0.000 0.084 3015 *Class#new 0.02 0.006 0.006 0.000 0.000 3012 Hash#initialize 0.01 0.007 0.006 0.000 0.001 1000 Time#localtime 0.01 0.006 0.006 0.000 0.000 1000 <Class::Time>#zone_utc? 0.01 0.010 0.005 0.000 0.005 1000 <Class::Time>#now 0.01 0.004 0.004 0.000 0.000 2500 String#to_i 0.01 0.004 0.004 0.000 0.000 5000 Fixnum#+ 0.01 0.005 0.004 0.000 0.001 1000 Time#initialize 0.01 0.003 0.003 0.000 0.000 3500 MatchData#end 0.01 0.002 0.002 0.000 0.000 3000 Fixnum#<=> 0.01 0.002 0.002 0.000 0.000 3000 Fixnum#* 0.00 0.002 0.002 0.000 0.000 1000 String#upcase 0.00 0.002 0.002 0.000 0.000 1500 Fixnum#div 0.00 0.002 0.002 0.000 0.000 1000 Hash#[] 0.00 0.002 0.002 0.000 0.000 2000 Fixnum#-@ 0.00 0.001 0.001 0.000 0.000 1004 NilClass#to_s 0.00 0.001 0.001 0.000 0.000 1000 Time#utc? 0.00 0.001 0.001 0.000 0.000 1000 Integer#round 0.00 0.001 0.001 0.000 0.000 1000 Integer#to_i 0.00 0.001 0.001 0.000 0.000 500 Kernel#Integer 0.00 0.000 0.000 0.000 0.000 500 Kernel#is_a? 0.00 0.000 0.000 0.000 0.000 16 <Class::Time>#month_days 0.00 0.100 0.000 0.000 0.100 2 <Class::Nokogiri::XML::Document>#parse 0.00 39.517 0.000 0.000 39.517 20668 *<Class::Qbxml::Hash>#xml_to_hash 0.00 42.676 0.000 0.000 42.676 1 Global#[No method] 0.00 0.000 0.000 0.000 0.000 1 File#initialize 0.00 0.000 0.000 0.000 0.000 1 IO#eof? 0.00 0.000 0.000 0.000 0.000 1 IO#close 0.00 0.000 0.000 0.000 0.000 2 Nokogiri::XML::Document#initialize 0.00 0.077 0.000 0.000 0.077 1 <Class::IO>#open 0.00 0.000 0.000 0.000 0.000 2 <Class::Nokogiri::XML::Document>#empty_doc? 0.00 0.000 0.000 0.000 0.000 5 Nokogiri::XML::Node#value 0.00 3.055 0.000 0.000 3.055 1 <Class::Qbxml::Hash>#from_hash 0.00 42.599 0.000 0.000 42.599 1 Qbxml#from_qbxml 0.00 42.595 0.000 0.000 42.595 1 <Class::Qbxml::Hash>#from_xml 0.00 0.004 0.000 0.000 0.004 1 Qbxml#describe 0.00 0.000 0.000 0.000 0.000 5 Nokogiri::XML::Node#node_name 0.00 0.000 0.000 0.000 0.000 2 Nokogiri::XML::ParseOptions#xinclude? 0.00 39.517 0.000 0.000 39.517 20668 *Integer#upto 0.00 0.004 0.000 0.000 0.004 1 Qbxml#namespace_qbxml_hash 0.00 0.100 0.000 0.000 0.100 2 <Module::Nokogiri>#XML 0.00 0.000 0.000 0.000 0.000 2 Nokogiri::XML::ParseOptions#initialize 0.00 3.055 0.000 0.000 3.055 3012 *<Class::Qbxml::Hash>#deep_convert 0.00 0.077 0.000 0.000 0.077 1 Qbxml#parse_schema 0.00 0.000 0.000 0.000 0.000 4 Fixnum#& 0.00 0.077 0.000 0.000 0.077 1 Qbxml#initialize 0.00 0.000 0.000 0.000 0.000 1 File#path 0.00 0.000 0.000 0.000 0.000 2 Nokogiri::XML::ParseOptions#strict? 0.00 0.000 0.000 0.000 0.000 1 Kernel#lambda 0.00 39.517 0.000 0.000 39.517 20668 *Nokogiri::XML::NodeSet#each 0.00 3.055 0.000 0.000 3.055 3012 *Enumerable#inject 0.00 0.000 0.000 0.000 0.000 3 Kernel#respond_to_missing? 0.00 0.000 0.000 0.000 0.000 1 Qbxml#select_schema 0.00 0.000 0.000 0.000 0.000 1 Hash#keys 0.00 0.000 0.000 0.000 0.000 1 IO#closed? * indicates recursively called methods
This PR caches types Hash.typecast's xpath lookup. After these changes, it takes 1/8 of the time!
Thread ID: 10482480 Fiber ID: 14582620 Total: 5.119874 Sort by: self_time %self total self wait child calls name 20.20 2.367 1.034 0.000 1.333 20169 ActiveSupport::Inflector#underscore 18.82 0.967 0.964 0.000 0.004 83176 String#gsub! 5.55 0.284 0.284 0.000 0.000 17657 Nokogiri::XML::Node#path 2.57 0.131 0.131 0.000 0.000 17657 String#gsub 1.87 0.096 0.096 0.000 0.000 49 Nokogiri::XML::XPathContext#evaluate 1.81 0.635 0.093 0.000 0.542 17657 <Class::Qbxml::Hash>#typecast 1.63 0.110 0.084 0.000 0.026 20668 Nokogiri::XML::Node#children 1.62 0.134 0.083 0.000 0.051 38373 Nokogiri::XML::NodeSet#[] 1.50 0.077 0.077 0.000 0.000 59096 Nokogiri::XML::Document#decorate 1.39 0.076 0.071 0.000 0.005 1 <Class::Nokogiri::XML::Document>#read_io 1.23 0.063 0.063 0.000 0.000 20169 Regexp#to_s 1.22 0.088 0.062 0.000 0.025 38324 Nokogiri::XML::Node#element? 1.14 0.178 0.058 0.000 0.120 35314 Object#present? 1.14 0.058 0.058 0.000 0.000 17657 String#=~ 1.10 0.056 0.056 0.000 0.000 78716 Module#=== 1.05 0.172 0.054 0.000 0.118 20169 ActiveSupport::Inflector#inflections 0.98 0.310 0.050 0.000 0.260 17657 Proc#[] 0.91 0.070 0.047 0.000 0.024 20169 ThreadSafe::Cache#[] 0.85 0.082 0.044 0.000 0.039 20169 Kernel#dup 0.85 0.084 0.043 0.000 0.040 1000 <Class::Date>#_parse 0.72 0.037 0.037 0.000 0.000 20668 Nokogiri::XML::Node#name 0.70 0.036 0.036 0.000 0.000 55981 Nokogiri::XML::Node#type 0.70 0.106 0.036 0.000 0.070 20169 <Class::ActiveSupport::Inflector::Inflections>#instance 0.68 2.401 0.035 0.000 2.367 20169 String#underscore 0.67 0.034 0.034 0.000 0.000 23180 Hash#[]= 0.61 0.031 0.031 0.000 0.000 10000 Regexp#match 0.60 0.043 0.030 0.000 0.012 23229 Array#include? 0.59 0.030 0.030 0.000 0.000 17657 Nokogiri::XML::Node#content 0.56 0.029 0.029 0.000 0.000 46349 String#to_s 0.55 0.028 0.028 0.000 0.000 20169 String#tr! 0.52 0.037 0.027 0.000 0.011 17657 Nokogiri::XML::Node#text? 0.52 0.110 0.027 0.000 0.083 17657 String#blank? 0.52 0.026 0.026 0.000 0.000 20668 Nokogiri::XML::Node#attribute_nodes 0.52 0.026 0.026 0.000 0.000 41340 Kernel#block_given? 0.49 0.083 0.025 0.000 0.058 17657 Kernel#!~ 0.48 0.044 0.025 0.000 0.019 1500 <Class::Date>#parse 0.47 0.024 0.024 0.000 0.000 20169 ThreadSafe::NonConcurrentCacheBackend#[] 0.45 0.039 0.023 0.000 0.016 20169 Kernel#initialize_dup 0.43 0.022 0.022 0.000 0.000 1 <Class::Nokogiri::XML::Document>#read_memory 0.35 0.024 0.018 0.000 0.006 1000 <Class::Time>#utc 0.34 0.018 0.018 0.000 0.000 20668 Hash#delete 0.31 0.016 0.016 0.000 0.000 20169 String#downcase! 0.31 0.016 0.016 0.000 0.000 20169 String#initialize_copy 0.27 0.075 0.014 0.000 0.061 1000 <Class::Time>#make_time 0.26 0.013 0.013 0.000 0.000 20668 Nokogiri::XML::NodeSet#length 0.26 0.013 0.013 0.000 0.000 20717 Array#each 0.24 0.012 0.012 0.000 0.000 20169 String#== 0.23 0.014 0.012 0.000 0.002 2000 Time#strftime 0.20 0.015 0.010 0.000 0.004 1000 <Class::Time>#apply_offset 0.20 0.013 0.010 0.000 0.003 1000 <Class::Time>#zone_offset 0.20 0.010 0.010 0.000 0.000 17657 Hash#blank? 0.16 0.008 0.008 0.000 0.000 9000 Fixnum#divmod 0.14 0.023 0.007 0.000 0.016 1000 Time#xmlschema 0.14 0.007 0.007 0.000 0.000 9157 Kernel#String 0.14 0.007 0.007 0.000 0.000 3500 MatchData#begin 0.13 0.166 0.007 0.000 0.160 1000 <Class::Time>#parse 0.12 0.006 0.006 0.000 0.000 5502 String#downcase 0.12 0.006 0.006 0.000 0.000 3500 String#[]= 0.10 0.005 0.005 0.000 0.000 1500 Date#strftime 0.10 0.087 0.005 0.000 0.081 3015 *Class#new 0.10 0.005 0.005 0.000 0.000 3012 Hash#initialize 0.10 0.005 0.005 0.000 0.000 514 IO#read 0.08 0.005 0.004 0.000 0.001 1000 Time#localtime 0.08 0.004 0.004 0.000 0.000 1000 <Class::Time>#zone_utc? 0.07 0.004 0.004 0.000 0.000 2500 Kernel#Float 0.07 0.003 0.003 0.000 0.000 5000 Fixnum#+ 0.05 0.002 0.002 0.000 0.000 2500 String#to_i 0.05 2.868 0.002 0.000 2.866 99 Array#map 0.05 0.005 0.002 0.000 0.003 1000 <Class::Time>#now 0.05 0.002 0.002 0.000 0.000 3500 MatchData#end 0.04 0.002 0.002 0.000 0.000 49 <Class::Nokogiri::XML::XPathContext>#new 0.04 0.002 0.002 0.000 0.000 3000 Fixnum#* 0.04 0.003 0.002 0.000 0.001 1000 Time#initialize 0.04 0.002 0.002 0.000 0.000 3000 Fixnum#<=> 0.03 0.001 0.001 0.000 0.000 1500 Fixnum#div 0.02 0.001 0.001 0.000 0.000 1000 String#upcase 0.02 0.001 0.001 0.000 0.000 2000 Fixnum#-@ 0.02 0.001 0.001 0.000 0.000 1000 Hash#[] 0.02 0.001 0.001 0.000 0.000 1004 NilClass#to_s 0.02 0.001 0.001 0.000 0.000 1000 Time#utc? 0.01 0.001 0.001 0.000 0.000 99 Nokogiri::XML::Document#root 0.01 0.001 0.001 0.000 0.000 1000 Integer#round 0.01 0.001 0.001 0.000 0.000 1000 Integer#to_i 0.01 0.003 0.001 0.000 0.002 49 Nokogiri::XML::Node#extract_params 0.01 0.102 0.000 0.000 0.102 49 Nokogiri::XML::Node#xpath 0.01 0.000 0.000 0.000 0.000 500 Kernel#Integer 0.01 0.000 0.000 0.000 0.000 500 Kernel#is_a? 0.01 0.000 0.000 0.000 0.000 48 Nokogiri::XML::Node#text 0.01 0.001 0.000 0.000 0.001 48 Object#try 0.00 0.000 0.000 0.000 0.000 49 <Module::Nokogiri>#uses_libxml? 0.00 0.000 0.000 0.000 0.000 49 Nokogiri::XML::Node#namespaces 0.00 0.000 0.000 0.000 0.000 147 Nokogiri::XML::Document#document 0.00 0.001 0.000 0.000 0.000 49 Enumerable#find 0.00 0.000 0.000 0.000 0.000 55 Kernel#respond_to? 0.00 0.000 0.000 0.000 0.000 49 Nokogiri::VersionInfo#libxml2? 0.00 0.000 0.000 0.000 0.000 49 <Class::Nokogiri::VersionInfo>#instance 0.00 0.000 0.000 0.000 0.000 49 Nokogiri::XML::NodeSet#first 0.00 0.000 0.000 0.000 0.000 49 Nokogiri::XML::XPathContext#register_namespaces 0.00 0.000 0.000 0.000 0.000 48 Kernel#public_send 0.00 0.000 0.000 0.000 0.000 98 Array#first 0.00 0.000 0.000 0.000 0.000 49 <Class::Hash>#[] 0.00 0.000 0.000 0.000 0.000 98 Array#last 0.00 2.770 0.000 0.000 2.770 3061 *Hash#each 0.00 0.000 0.000 0.000 0.000 49 Nokogiri::XML::Node#namespace_scopes 0.00 0.000 0.000 0.000 0.000 16 <Class::Time>#month_days 0.00 0.000 0.000 0.000 0.000 49 Module#== 0.00 0.000 0.000 0.000 0.000 49 Kernel#class 0.00 0.000 0.000 0.000 0.000 51 Kernel#nil? 0.00 0.000 0.000 0.000 0.000 49 Array#reverse 0.00 0.099 0.000 0.000 0.098 2 <Class::Nokogiri::XML::Document>#parse 0.00 2.248 0.000 0.000 2.248 20668 *<Class::Qbxml::Hash>#xml_to_hash 0.00 5.120 0.000 0.000 5.120 1 Global#[No method] 0.00 0.000 0.000 0.000 0.000 1 File#initialize 0.00 0.000 0.000 0.000 0.000 1 IO#eof? 0.00 0.000 0.000 0.000 0.000 1 IO#close 0.00 0.000 0.000 0.000 0.000 2 <Class::Nokogiri::XML::Document>#empty_doc? 0.00 0.076 0.000 0.000 0.076 1 <Class::IO>#open 0.00 0.000 0.000 0.000 0.000 2 Nokogiri::XML::Document#initialize 0.00 5.044 0.000 0.000 5.044 1 Qbxml#from_qbxml 0.00 5.040 0.000 0.000 5.040 1 <Class::Qbxml::Hash>#from_xml 0.00 0.000 0.000 0.000 0.000 2 Nokogiri::XML::ParseOptions#xinclude? 0.00 2.248 0.000 0.000 2.248 20668 *Integer#upto 0.00 0.003 0.000 0.000 0.003 1 Qbxml#describe 0.00 0.003 0.000 0.000 0.003 1 Qbxml#namespace_qbxml_hash 0.00 0.099 0.000 0.000 0.099 2 <Module::Nokogiri>#XML 0.00 2.770 0.000 0.000 2.770 1 <Class::Qbxml::Hash>#from_hash 0.00 0.076 0.000 0.000 0.076 1 Qbxml#initialize 0.00 0.000 0.000 0.000 0.000 5 Nokogiri::XML::Node#value 0.00 0.000 0.000 0.000 0.000 2 Nokogiri::XML::ParseOptions#strict? 0.00 0.000 0.000 0.000 0.000 2 Nokogiri::XML::ParseOptions#initialize 0.00 0.000 0.000 0.000 0.000 4 Fixnum#& 0.00 0.076 0.000 0.000 0.076 1 Qbxml#parse_schema 0.00 0.000 0.000 0.000 0.000 5 Nokogiri::XML::Node#node_name 0.00 2.248 0.000 0.000 2.248 20668 *Nokogiri::XML::NodeSet#each 0.00 2.770 0.000 0.000 2.770 3012 *<Class::Qbxml::Hash>#deep_convert 0.00 0.000 0.000 0.000 0.000 1 File#path 0.00 0.000 0.000 0.000 0.000 3 Kernel#respond_to_missing? 0.00 2.770 0.000 0.000 2.770 3012 *Enumerable#inject 0.00 0.000 0.000 0.000 0.000 1 Hash#keys 0.00 0.000 0.000 0.000 0.000 1 Qbxml#select_schema 0.00 0.000 0.000 0.000 0.000 1 IO#closed? 0.00 0.000 0.000 0.000 0.000 1 Kernel#lambda * indicates recursively called methods
Test document: https://gist.github.com/JasonBarnabe/b614e2110aa0491e8772
Profile of qbxml parsing a 500-invoice XML document:
This PR caches types Hash.typecast's xpath lookup. After these changes, it takes 1/8 of the time!