Bug #7968
open
Poor UDPSocket#send performance in ruby 2.0.0 on windows
Added by cs96and (Alan Davies) over 11 years ago. Updated about 1 year ago.
Description
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) socketsendtest.rb | Script to test UDPSocket#send | cs96and (Alan Davies), 02/26/2013 08:55 PM |
Updated by drbrain (Eric Hodel) over 11 years ago
- Status changed from Open to Closed
- % Done changed from 0 to 100
This issue was solved with changeset r39542.
Alan, thank you for reporting this issue.
Your contribution to Ruby is greatly appreciated.
May Ruby be with you.
-
lib/rubygems/ext/builder.rb: Fix incompatibilities when installing
extensions. Patch by Nobu.
[ruby-trunk - Bug #7968] [ruby-trunk - Bug #7971] -
lib/rubygems/ext/ext_conf_builder.rb: ditto.
-
lib/rubygems/installer.rb: ditto.
-
test/rubygems/test_gem_ext_ext_conf_builder.rb: Test for the above.
-
test/rubygems/test_gem_installer.rb: ditto.
-
lib/rubygems/commands/sources_command.rb: Prefer HTTPS over HTTP.
-
lib/rubygems/defaults.rb: ditto
-
lib/rubygems/dependency_resolver.rb: Ditto.
-
lib/rubygems/source.rb: ditto.
-
lib/rubygems/spec_fetcher.rb: ditto.
-
lib/rubygems/specification.rb: ditto.
-
lib/rubygems/test_utilities.rb: ditto.
-
test/rubygems/test_gem.rb: Test for the above.
-
test/rubygems/test_gem_commands_sources_command.rb: ditto.
-
test/rubygems/test_gem_dependency_resolver_api_set.rb: ditto.
-
test/rubygems/test_gem_remote_fetcher.rb: ditto.
-
test/rubygems/test_gem_source.rb: ditto.
-
test/rubygems/test_gem_spec_fetcher.rb: ditto.
Updated by nagachika (Tomoyuki Chikanaga) over 11 years ago
- % Done changed from 100 to 0
- Status changed from Closed to Open
Updated by cs96and (Alan Davies) over 11 years ago
I see the %Done went up to 100 and back down to zero. Is this fixed or not now?
Thanks
Alan.
Updated by nagachika (Tomoyuki Chikanaga) over 11 years ago
Hello, Alan.
I re-open this ticket because it was accidentally closed by wrong commit message.
This issue is not fixed yet.
BTW, in socketsendtest.rb UDPSocket#bind and #connect receive different port number. Is it right?
On my environment, I've got an exception.
socketsendtest.rb:9:in `send': Connection refused - send(2) (Errno::ECONNREFUSED)
Thanks
Updated by cs96and (Alan Davies) over 11 years ago
The bind and connect can be different. The bind specifies what port you are sending from, and connect specifies the port you are sending to (the ip address can be a different box too). It runs fine for me with different ports, but you can make them the same if you want.
Updated by cs96and (Alan Davies) over 11 years ago
Any update on this?
Thanks
Alan
Updated by luislavena (Luis Lavena) over 11 years ago
- Status changed from Open to Assigned
- Assignee changed from windows to usa (Usaku NAKAMURA)
Any suggestion about this?
Updated by cs96and (Alan Davies) almost 11 years ago
This is still a problem in 2.0.0-p353 on windows. Is there any update?
Thanks
Alan.
Updated by cs96and (Alan Davies) almost 11 years ago
Issue #7968 has been updated by Alan Davies.
This is still a problem in 2.0.0-p353 on windows. Is there any update?
Thanks
Alan.
Bug #7968: Poor UDPSocket#send performance in ruby 2.0.0 on windows
https://bugs.ruby-lang.org/issues/7968#change-44343
- Author: Alan Davies
- Status: Assigned
- Priority: Normal
- Assignee: Usaku NAKAMURA
- Category: platform/windows
- Target version:
- ruby -v: ruby 2.0.0p0 (2013-02-24) [x64-mingw32]
- Backport:
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)
Updated by usa (Usaku NAKAMURA) about 7 years ago
- Assignee changed from usa (Usaku NAKAMURA) to windows
Updated by MSP-Greg (Greg L) about 7 years ago
I ran this up on Appveyor using all minor versions 1.9.3 thru trunk. The code loop is one of two:
100000.times { s.send(str, 0) }
100000.times { s.print(str) }
One set was run with str.length = 10, the other with str.length = 2000. String length didn't really affect test times...
When using send, 1.9.3 is fastest, 2.0.0 is slowest, others were in between. When using print, 1.9.3 thru 2.1.9 are faster by approx 2x compared to 2.2.6 thru trunk.
Anyway, not that well versed in all the uses of sockets, so I can't judge whether these time differences are 'real world' significant. Also, not a terribly scientific test...
10 Characters Send
0.56247 ruby 1.9.3p551 (2014-11-13) [i386-mingw32]
1.70312 ruby 2.0.0p648 (2015-12-16) [x64-mingw32]
1.00000 ruby 2.1.9p490 (2016-03-30 revision 54437) [x64-mingw32]
0.98534 ruby 2.2.6p396 (2016-11-15 revision 56800) [x64-mingw32]
0.93747 ruby 2.3.3p222 (2016-11-21 revision 56859) [x64-mingw32]
0.95312 ruby 2.4.1p111 (2017-03-22 revision 58053) [x64-mingw32]
0.90446 ruby 2.5.0dev (2017-10-23 trunk 60368) [x64-mingw32]
10 Characters Print
0.59375 ruby 1.9.3p551 (2014-11-13) [i386-mingw32]
0.46878 ruby 2.0.0p648 (2015-12-16) [x64-mingw32]
0.48440 ruby 2.1.9p490 (2016-03-30 revision 54437) [x64-mingw32]
1.01562 ruby 2.2.6p396 (2016-11-15 revision 56800) [x64-mingw32]
0.98440 ruby 2.3.3p222 (2016-11-21 revision 56859) [x64-mingw32]
1.01565 ruby 2.4.1p111 (2017-03-22 revision 58053) [x64-mingw32]
0.98707 ruby 2.5.0dev (2017-10-23 trunk 60368) [x64-mingw32]
2000 Characters Send
0.56253 ruby 1.9.3p551 (2014-11-13) [i386-mingw32]
1.75003 ruby 2.0.0p648 (2015-12-16) [x64-mingw32]
1.03125 ruby 2.1.9p490 (2016-03-30 revision 54437) [x64-mingw32]
1.01565 ruby 2.2.6p396 (2016-11-15 revision 56800) [x64-mingw32]
1.03124 ruby 2.3.3p222 (2016-11-21 revision 56859) [x64-mingw32]
1.00002 ruby 2.4.1p111 (2017-03-22 revision 58053) [x64-mingw32]
0.95394 ruby 2.5.0dev (2017-10-23 trunk 60368) [x64-mingw32]
2000 Characters Print
0.60941 ruby 1.9.3p551 (2014-11-13) [i386-mingw32]
0.50001 ruby 2.0.0p648 (2015-12-16) [x64-mingw32]
0.51566 ruby 2.1.9p490 (2016-03-30 revision 54437) [x64-mingw32]
1.03125 ruby 2.2.6p396 (2016-11-15 revision 56800) [x64-mingw32]
1.01562 ruby 2.3.3p222 (2016-11-21 revision 56859) [x64-mingw32]
1.04689 ruby 2.4.1p111 (2017-03-22 revision 58053) [x64-mingw32]
1.00382 ruby 2.5.0dev (2017-10-23 trunk 60368) [x64-mingw32]
Updated by JesseJohnson (Jesse Johnson) about 1 year ago
Can anyone replicate this on Ruby 3 or later?
Updated by cs96and (Alan Davies) about 1 year ago
JesseJohnson (Jesse Johnson) wrote in #note-12:
Can anyone replicate this on Ruby 3 or later?
Still poor performance in 3.1.3 and 3.2.2...
1.9.3 send()
$ ./ruby-1.9.3-p551-i386-mingw32/bin/ruby.exe --version
ruby 1.9.3p551 (2014-11-13) [i386-mingw32]
$ time ./ruby-1.9.3-p551-i386-mingw32/bin/ruby.exe d:/socketsendtest.rb
real 0m1.086s
user 0m0.000s
sys 0m0.000s
1.9.3 print()
$ time ./ruby-1.9.3-p551-i386-mingw32/bin/ruby.exe d:/socketsendtest.rb
real 0m1.108s
user 0m0.000s
sys 0m0.000s
3.1.3 send()
$ /c/tools/ruby31/bin/ruby --version
ruby 3.1.3p185 (2022-11-24 revision 1a6b16756e) [x64-mingw-ucrt]
$ time /c/tools/ruby31/bin/ruby d:/socketsendtest.rb
real 0m1.927s
user 0m0.000s
sys 0m0.015s
3.1.3 print()
$ time /c/tools/ruby31/bin/ruby d:/socketsendtest.rb
real 0m1.273s
user 0m0.000s
sys 0m0.015s
3.2.2 send()
$ ./rubyinstaller-3.2.2-1-x64/bin/ruby.exe --version
ruby 3.2.2 (2023-03-30 revision e51014f9c0) [x64-mingw-ucrt]
$ time ./rubyinstaller-3.2.2-1-x64/bin/ruby.exe d:/socketsendtest.rb
real 0m2.044s
user 0m0.000s
sys 0m0.000s
3.2.2 print()
$ time ./rubyinstaller-3.2.2-1-x64/bin/ruby.exe d:/socketsendtest.rb
real 0m1.338s
user 0m0.000s
sys 0m0.000s
Updated by k0kubun (Takashi Kokubun) about 1 year ago
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.
Updated by cs96and (Alan Davies) about 1 year ago
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
timecommand would benchmark that as well. You can just callTime.newbefore 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.