Feature #11725: debugging support for frozen string literal

• Status: Closed
• Assignee: ko1 (Koichi Sasada)
• Target version: -

[ko1 (Koichi Sasada)]

Background

Debug frozen string literal is difficult because frozen string can be modified at far from created locations. For example, library X creates one string and modify this string is common situation. Also library X can pass the created string to library Y and also Y passes it to library Z. Clients receives a string from Z, then clients can not understand where the created location and can not debug it.

To help such situation, I introduced --enable-frozen-string-literal-debug option (a command line option and a compile option). This option enable to embed created location information into frozen string and to display RuntimeError message with this location information such as:

../../trunk/test.rb:21:in `<main>': can't modify frozen String, created at ../../trunk/test.rb:17 (RuntimeError)

(maybe only few people knows about this feature because NEWS doesn't describe it)

Proposal: Make it as default behavior

At first, I introduced this option as an optional feature because this option seems slow down applications.

However, including this information for sting literals is not so big impact because adding information for each string literal only at compile time. Another drawback is that we can't de-duplicate same frozen strings, but it is trivial issue.

One problem is string interpolation. Adding debug information for such dynamically created strings is not so easy. So I leave --enable-frozen-string-literal-debug for this type of strings. It is too long to use it, so -d or --debug option should enable this feature.

Conclusion:

• adding string literals as default.
• --enable-frozen-string-literal-debug for string interpolation. -d or --debug also enable this feature.

I hope we can change every string literals to frozen strings.

Any comments are welcome.

Naming

Now, I prefer --debug-frozen-string-literal than --enable-frozen-string-literal-debug.

Misc: benchmark script and result

require 'benchmark'
N = 5_000_000

def static_test1
  "foo"
end

def static_test2
  "foo".freeze
end

line = __LINE__ + 1
RubyVM::InstructionSequence.compile(%q{
  def static_test3
    "foo"
  end
}, __FILE__, __FILE__, line, {frozen_string_literal: true}).eval

line = __LINE__ + 1
RubyVM::InstructionSequence.compile(%q{
  def static_test4
    "foo"
  end
}, __FILE__, __FILE__, line, {frozen_string_literal: true, frozen_string_literal_debug: true}).eval

S = 'baz'
def dynamic_test1
  "foo#{S}bar"
end

def dynamic_test2
  "foo#{S}bar".freeze
end

line = __LINE__ + 1
RubyVM::InstructionSequence.compile(%q{
  def dynamic_test3
    "foo#{S}bar"
  end
}, __FILE__, __FILE__, line, {frozen_string_literal: true}).eval

line = __LINE__ + 1
RubyVM::InstructionSequence.compile(%q{
  def dynamic_test4
    "foo#{S}bar"
  end
}, __FILE__, __FILE__, line, {frozen_string_literal: true, frozen_string_literal_debug: true}).eval

Benchmark.bmbm{|x|
  x.report('STATIC: without freeze'  ){N.times{static_test1}}
  x.report('STATIC: freeze by method'){N.times{static_test2}}
  x.report('STATIC: freeze by pragma'){N.times{static_test3}}
  x.report('STATIC: freeze by pragma/debug'){N.times{static_test3}}
  x.report('DYNAMIC:without freeze'  ){N.times{dynamic_test1}}
  x.report('DYNAMIC:freeze by method'){N.times{dynamic_test2}}
  x.report('DYNAMIC:freeze by pragma'){N.times{dynamic_test3}}
  x.report('DYNAMIC:freeze by pragma/debug'){N.times{dynamic_test4}}
}

# error message check
['static', 'dynamic'].each{|feature|
  (1..4).each{|type|
    begin
      m = "#{feature}_test#{type}"
      send(m) << "str"
    rescue RuntimeError => e
      p [m, e]
    else
      p [m, nil]
    end
  }
}

                                     user     system      total        real
STATIC: without freeze           0.550000   0.000000   0.550000 (  0.545465)
STATIC: freeze by method         0.330000   0.000000   0.330000 (  0.337528)
STATIC: freeze by pragma         0.360000   0.000000   0.360000 (  0.366031)
STATIC: freeze by pragma/debug   0.360000   0.000000   0.360000 (  0.353534)
DYNAMIC:without freeze           1.230000   0.000000   1.230000 (  1.230027)
DYNAMIC:freeze by method         1.580000   0.000000   1.580000 (  1.585025)
DYNAMIC:freeze by pragma         1.420000   0.000000   1.420000 (  1.424006)
DYNAMIC:freeze by pragma/debug   3.510000   0.000000   3.510000 (  3.510279)

# error message check results
["static_test1", nil]
["static_test2", #<RuntimeError: can't modify frozen String>]
["static_test3", #<RuntimeError: can't modify frozen String, created at ../../trunk/test.rb:15>]
["static_test4", #<RuntimeError: can't modify frozen String, created at ../../trunk/test.rb:22>]
["dynamic_test1", nil]
["dynamic_test2", #<RuntimeError: can't modify frozen String>]
["dynamic_test3", #<RuntimeError: can't modify frozen String>]
["dynamic_test4", #<RuntimeError: can't modify frozen String, created at ../../trunk/test.rb:45>]

[ko1 (Koichi Sasada)]

• Status changed from Open to Closed

Applied in changeset r52688.

---

• compile.c (iseq_compile_each): add debug information to NODE_STR
  strings as default.
  [Feature #11725]

• insns.def (freezestring): add new instruction to support adding
  debug information for dynamically constracted strings.

• compile.c (iseq_compile_each): support adding debug information
  for NODE_DSTR with freezestring instruction.

• error.c (rb_error_frozen): change the debug information ID name
  id_debug_created_info and this field should have a 2 element array
  containing path and line information.

• defs/id.def: ditto.

• test/ruby/test_rubyoptions.rb: catch up this fix.

• test/ruby/test_iseq.rb: now frozen strings are not same.

[nobu (Nobuyoshi Nakada)]

You run static_test3 twice, not static_test4.

[ko1 (Koichi Sasada)]

• Status changed from Closed to Assigned

We found performance regression with this feature.
"foo".dup with frozen literal also copy location information.

Quoted from https://bugs.ruby-lang.org/issues/11782#change-55313

# frozen-string-literal: true
       user     system      total        real
   5.850000   0.010000   5.860000 (  5.858450)
   0.780000   0.000000   0.780000 (  0.780911)
   0.340000   0.000000   0.340000 (  0.351072)
   0.530000   0.000000   0.530000 (  0.529234)

Too slow on "'foo'.dup" (a result on first line).
Nobu found the reason why it is slow.
And reason is implicit debug information.
String#dup copys with such debug information.

So I decide to withdraw the proposal of debugging support by default.
Same as dynamically created string, debug information is added for static string literal
iff --debug or --debug=frozen-string-literal is specified.

$ ./miniruby -I../../trunk/lib -I. -I.ext/common   ../../trunk/test.rb
Rehearsal -------------------------------------------
.dup      2.280000   0.000000   2.280000 (  2.280500)
+@        0.770000   0.000000   0.770000 (  0.767608)
.freeze   0.340000   0.000000   0.340000 (  0.343781)
-@        0.480000   0.000000   0.480000 (  0.479379)
---------------------------------- total: 3.870000sec

              user     system      total        real
.dup      2.260000   0.000000   2.260000 (  2.260352)
+@        0.770000   0.000000   0.770000 (  0.771664)
.freeze   0.350000   0.000000   0.350000 (  0.345739)
-@        0.470000   0.000000   0.470000 (  0.471908)

$ ./miniruby --debug -I../../trunk/lib -I. -I.ext/common   ../../trunk/test.rb
Rehearsal -------------------------------------------
.dup      5.470000   0.000000   5.470000 (  5.483195)
+@        0.790000   0.000000   0.790000 (  0.789157)
.freeze   0.340000   0.000000   0.340000 (  0.342538)
-@        0.470000   0.000000   0.470000 (  0.473341)
---------------------------------- total: 7.070000sec

              user     system      total        real
.dup      5.510000   0.010000   5.520000 (  5.519788)
+@        0.770000   0.000000   0.770000 (  0.767551)
.freeze   0.340000   0.000000   0.340000 (  0.342797)
-@        0.470000   0.000000   0.470000 (  0.473512)

Benchmark program:

# frozen-string-literal: true

require 'benchmark'

N = 10_000_000
Benchmark.bmbm{|x|
  x.report('.dup'){
    N.times{ 'foo'.dup }
  }
  x.report('+@'){
    N.times{ +'foo' }
  }
  x.report('.freeze'){
    N.times{ 'foo'.freeze }
  }
  x.report('-@'){
    N.times{ -'foo' }
  }
}

[ko1 (Koichi Sasada)]

• Status changed from Assigned to Closed

Applied in changeset r53009.

---

• compile.c (iseq_compile_each): do not add debug information
  without --debug or --debug=frozen-string-literal option
  because String#dup slows down with debug information.
  [Feature #11725]

• NEWS: apply about it.

• test/ruby/test_rubyoptions.rb: catch up this fix with refactoring.