[ruby-core:115403] [Ruby master Bug#7968] Poor UDPSocket#send performance in ruby 2.0.0 on windows

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/
 ______________________________________________
 ruby-core mailing list -- [e-mail]
 To unsubscribe send an email to [e-mail]
 ruby-core info -- https://ml.ruby-lang.org/mailman3/postorius/lists/ruby-core.ml.ruby-lang.org/