Issue #7968 has been updated by cs96and (Alan Davies). k0kubun (Takashi Kokubun) wrote in #note-14:
Just in case, could you measure the time spent on the loop instead of a whole Ruby command? The prelude script sometimes takes a lot of time, the performance varies across different versions, and `time` command would benchmark that as well. You can just call `Time.new` before and after the loop, subtract them, and report the result for each version.
I also increased the loop by a factor of 10 (to 1,000,000) so it runs for longer. Times are in seconds... **1.9.3 send:** ``` ruby-1.9.3\bin\ruby.exe socketsendtest.rb 10.495193 ``` **1.9.3 print:** ``` ruby-1.9.3\bin\ruby.exe socketsendtest.rb 10.384035 ``` **3.2.2 send** ``` ruby-3.2.2\bin\ruby.exe socketsendtest.rb 17.3447397 ``` **3.2.2 print** ``` ruby-3.2.2\bin\ruby.exe socketsendtest.rb 9.8053804 ``` Out of interest I ran the code through the profile module as well... **1.9.3 send** ``` ruby-1.9.3\bin\ruby.exe -rprofile socketsendtest.rb 19.520433 % cumulative self self total time seconds seconds calls ms/call ms/call name 56.95 6.03 6.03 1000000 0.01 0.01 UDPSocket#send 43.05 10.59 4.56 1 4561.00 10594.00 Integer#times 0.00 10.59 0.00 1 0.00 0.00 UDPSocket#bind 0.00 10.59 0.00 10 0.00 0.00 Class#inherited 0.00 10.59 0.00 40 0.00 0.00 BasicObject#singleton_method_added 0.00 10.59 0.00 104 0.00 0.00 Module#method_added 0.00 10.59 0.00 2 0.00 0.00 Kernel.gem_original_require 0.00 10.59 0.00 2 0.00 0.00 Kernel.require 0.00 10.59 0.00 4 0.00 0.00 Module#private 0.00 10.59 0.00 2 0.00 0.00 Module#attr_reader 0.00 10.59 0.00 1 0.00 0.00 UDPSocket#initialize 0.00 10.59 0.00 1 0.00 0.00 IO#new 0.00 10.59 0.00 2 0.00 0.00 Hash#empty? 0.00 10.59 0.00 1 0.00 0.00 UDPSocket#connect 0.00 10.59 0.00 2 0.00 0.00 Time#initialize 0.00 10.59 0.00 2 0.00 0.00 Class#new 0.00 10.59 0.00 4 0.00 0.00 IO#set_encoding 0.00 10.59 0.00 2 0.00 0.00 Gem.unresolved_deps 0.00 10.59 0.00 1 0.00 0.00 Float#/ 0.00 10.59 0.00 1 0.00 0.00 Float#quo 0.00 10.59 0.00 1 0.00 0.00 Time#- 0.00 10.59 0.00 1 0.00 0.00 Float#to_s 0.00 10.59 0.00 2 0.00 0.00 IO#write 0.00 10.59 0.00 1 0.00 0.00 IO#puts 0.00 10.59 0.00 1 0.00 0.00 Kernel.puts 0.00 10.59 0.00 1 0.00 10594.00 #toplevel ``` **1.9.3 print** ``` ruby-1.9.3\bin\ruby.exe -rprofile socketsendtest.rb 25.818462 % cumulative self self total time seconds seconds calls ms/call ms/call name 38.19 6.18 6.18 1000000 0.01 0.01 IO#print 33.27 11.56 5.38 1000002 0.01 0.01 IO#write 28.45 16.16 4.60 1 4600.00 16156.00 Integer#times 0.09 16.17 0.01 2 7.50 15.00 Kernel.require 0.00 16.17 0.00 1 0.00 0.00 UDPSocket#bind 0.00 16.17 0.00 104 0.00 0.00 Module#method_added 0.00 16.17 0.00 2 0.00 7.50 Kernel.gem_original_require 0.00 16.17 0.00 4 0.00 0.00 IO#set_encoding 0.00 16.17 0.00 4 0.00 0.00 Module#private 0.00 16.17 0.00 2 0.00 0.00 Module#attr_reader 0.00 16.17 0.00 1 0.00 0.00 UDPSocket#initialize 0.00 16.17 0.00 1 0.00 0.00 IO#new 0.00 16.17 0.00 40 0.00 0.00 BasicObject#singleton_method_added 0.00 16.17 0.00 1 0.00 0.00 UDPSocket#connect 0.00 16.17 0.00 2 0.00 0.00 Time#initialize 0.00 16.17 0.00 2 0.00 0.00 Class#new 0.00 16.17 0.00 10 0.00 0.00 Class#inherited 0.00 16.17 0.00 2 0.00 0.00 Hash#empty? 0.00 16.17 0.00 2 0.00 0.00 Gem.unresolved_deps 0.00 16.17 0.00 1 0.00 0.00 Float#/ 0.00 16.17 0.00 1 0.00 0.00 Float#quo 0.00 16.17 0.00 1 0.00 0.00 Time#- 0.00 16.17 0.00 1 0.00 0.00 Float#to_s 0.00 16.17 0.00 1 0.00 0.00 IO#puts 0.00 16.17 0.00 1 0.00 0.00 Kernel.puts 0.00 16.17 0.00 1 0.00 16171.00 #toplevel ``` **3.2.2 send** ``` ruby-3.2.2\bin\ruby.exe -rprofile socketsendtest.rb 32.9209883 % cumulative self self total time seconds seconds calls ms/call ms/call name 39.03 7.72 7.72 1000000 0.01 0.02 nil# 38.17 15.27 7.55 1000000 0.01 0.01 UDPSocket#send 22.72 19.77 4.50 1 4495.00 19766.00 Integer#times 0.08 19.78 0.02 4 4.00 16.00 Kernel#require 0.00 19.78 0.00 2 0.00 0.00 Kernel#respond_to? 0.00 19.78 0.00 2 0.00 0.00 Hash#[] 0.00 19.78 0.00 2 0.00 0.00 Gem.find_unresolved_default_spec 0.00 19.78 0.00 2 0.00 0.00 Gem::Specification.unresolved_deps 0.00 19.78 0.00 2 0.00 0.00 Hash#empty? 0.00 19.78 0.00 2 0.00 0.00 Monitor#exit 0.00 19.78 0.00 378 0.00 0.00 Module#const_added 0.00 19.78 0.00 13 0.00 0.00 Class#inherited 0.00 19.78 0.00 50 0.00 0.00 BasicObject#singleton_method_added 0.00 19.78 0.00 141 0.00 0.00 Module#method_added 0.00 19.78 0.00 2 0.00 0.00 Monitor#enter 0.00 19.78 0.00 1 0.00 0.00 Module#method_defined? 0.00 19.78 0.00 1 0.00 0.00 Module#protected 0.00 19.78 0.00 1 0.00 0.00 String#=~ 0.00 19.78 0.00 3 0.00 0.00 Module#private 0.00 19.78 0.00 2 0.00 0.00 Module#attr_reader 0.00 19.78 0.00 1 0.00 0.00 UDPSocket#initialize 0.00 19.78 0.00 1 0.00 0.00 IO.new 0.00 19.78 0.00 1 0.00 0.00 UDPSocket#bind 0.00 19.78 0.00 1 0.00 0.00 UDPSocket#connect 0.00 19.78 0.00 2 0.00 0.00 Time#initialize 0.00 19.78 0.00 2 0.00 0.00 Class#new 0.00 19.78 0.00 2 0.00 0.00 Gem.discover_gems_on_require 0.00 19.78 0.00 4 0.00 0.00 IO#set_encoding 0.00 19.78 0.00 1 0.00 0.00 TracePoint#enable 0.00 19.78 0.00 1 0.00 0.00 Float#/ 0.00 19.78 0.00 1 0.00 0.00 Float#fdiv 0.00 19.78 0.00 1 0.00 0.00 Time#- 0.00 19.78 0.00 1 0.00 0.00 Float#to_s 0.00 19.78 0.00 1 0.00 0.00 IO#write 0.00 19.78 0.00 1 0.00 0.00 IO#puts 0.00 19.78 0.00 1 0.00 0.00 Kernel#puts 0.00 19.78 0.00 1 0.00 0.00 TracePoint#disable 0.00 19.78 0.00 1 0.00 19782.00 #toplevel ``` **3.2.2 print** ``` ruby-3.2.2\bin\ruby.exe -rprofile socketsendtest.rb 29.3270973 % cumulative self self total time seconds seconds calls ms/call ms/call name 33.07 6.50 6.50 1000000 0.01 0.01 IO#print 27.12 11.84 5.34 1000000 0.01 0.02 nil# 21.52 16.08 4.23 1 4234.00 19672.00 Integer#times 18.28 19.67 3.60 1000001 0.00 0.00 IO#write 0.00 19.67 0.00 2 0.00 0.00 Kernel#respond_to? 0.00 19.67 0.00 2 0.00 0.00 Hash#[] 0.00 19.67 0.00 2 0.00 0.00 Gem.find_unresolved_default_spec 0.00 19.67 0.00 2 0.00 0.00 Gem::Specification.unresolved_deps 0.00 19.67 0.00 2 0.00 0.00 Hash#empty? 0.00 19.67 0.00 2 0.00 0.00 Monitor#exit 0.00 19.67 0.00 378 0.00 0.00 Module#const_added 0.00 19.67 0.00 13 0.00 0.00 Class#inherited 0.00 19.67 0.00 50 0.00 0.00 BasicObject#singleton_method_added 0.00 19.67 0.00 141 0.00 0.00 Module#method_added 0.00 19.67 0.00 2 0.00 0.00 Gem.discover_gems_on_require 0.00 19.67 0.00 1 0.00 0.00 Module#method_defined? 0.00 19.67 0.00 1 0.00 0.00 Module#protected 0.00 19.67 0.00 1 0.00 0.00 String#=~ 0.00 19.67 0.00 3 0.00 0.00 Module#private 0.00 19.67 0.00 2 0.00 0.00 Module#attr_reader 0.00 19.67 0.00 1 0.00 0.00 UDPSocket#initialize 0.00 19.67 0.00 1 0.00 0.00 IO.new 0.00 19.67 0.00 1 0.00 0.00 UDPSocket#bind 0.00 19.67 0.00 1 0.00 0.00 UDPSocket#connect 0.00 19.67 0.00 2 0.00 0.00 Time#initialize 0.00 19.67 0.00 2 0.00 0.00 Class#new 0.00 19.67 0.00 2 0.00 0.00 Monitor#enter 0.00 19.67 0.00 4 0.00 0.00 IO#set_encoding 0.00 19.67 0.00 4 0.00 0.00 Kernel#require 0.00 19.67 0.00 1 0.00 0.00 TracePoint#enable 0.00 19.67 0.00 1 0.00 0.00 Float#/ 0.00 19.67 0.00 1 0.00 0.00 Float#fdiv 0.00 19.67 0.00 1 0.00 0.00 Time#- 0.00 19.67 0.00 1 0.00 0.00 Float#to_s 0.00 19.67 0.00 1 0.00 0.00 IO#puts 0.00 19.67 0.00 1 0.00 0.00 Kernel#puts 0.00 19.67 0.00 1 0.00 0.00 TracePoint#disable 0.00 19.67 0.00 1 0.00 19672.00 #toplevel ``` 3.2.2 seems to be spending a fair amount of time in a function called `nil#`. Though the 3.2.2 print() version does as well, but doesn't suffer the slowdown. ---------------------------------------- Bug #7968: Poor UDPSocket#send performance in ruby 2.0.0 on windows https://bugs.ruby-lang.org/issues/7968#change-105341 * Author: cs96and (Alan Davies) * Status: Assigned * Priority: Normal * Assignee: windows * ruby -v: ruby 2.0.0p0 (2013-02-24) [x64-mingw32] ---------------------------------------- I have noticed that the performance of UDPSocket#send on ruby 2.0.0 on windows is much poorer than that of 1.9.3 or 1.8.7. Running the attahced script on 2.0.0 gives the following... d:\scripts>bash -c "ruby --version" ruby 2.0.0p0 (2013-02-24) [x64-mingw32] d:\scripts>bash -c "time ruby socketsendtest.rb" real 0m2.572s user 0m0.000s sys 0m0.016s However, running the same test with 1.9.3 is much faster... d:\scripts>pik 193 d:\scripts>bash -c "ruby --version" ruby 1.9.3p374 (2013-01-15) [i386-mingw32] d:\scripts>bash -c "time ruby socketsendtest.rb" real 0m0.993s user 0m0.015s sys 0m0.016s Additionally, if I change the send call to a print (commented out in the script), then the performance is fine on 2.0.0.... d:\scripts>pik 200 d:\scripts>bash -c "ruby --version" ruby 2.0.0p0 (2013-02-24) [x64-mingw32] d:\scripts>bash -c "time ruby socketsendtest.rb" real 0m0.907s user 0m0.000s sys 0m0.015s What is send() doing that print() doesn't do that is causing the massive performance drop? Thanks Alan. ---Files-------------------------------- socketsendtest.rb (266 Bytes) -- https://bugs.ruby-lang.org/