[ruby-trunk - Bug #9090][Open] [BUG] object allocation during garbage collection phase

Detlef_R · November 7, 2013, 1:54am

Issue #9090 has been reported by akr (Akira T.).

Bug #9090: [BUG] object allocation during garbage collection phase

Author: akr (Akira T.)
Status: Open
Priority: Normal
Assignee:
Category:
Target version:
ruby -v: ruby 2.1.0dev (2013-11-06 trunk 43558) [x86_64-linux]
Backport: 1.9.3: UNKNOWN, 2.0.0: UNKNOWN

昨日の夜、r43558 で make check を 300回動かしてみたところ、
なんかずいぶんと [BUG] が出ました。

% ./ruby -v
ruby 2.1.0dev (2013-11-06 trunk 43558) [x86_64-linux]
% fgrep ‘[BUG]’ zd10/*/log
zd10/1/log:TestGem#test_looks_for_gemdeps_files_automatically_on_start =
/home/akr/tst1/ruby/lib/rinda/tuplespace.rb:325: [BUG] object allocation
during garbage collection phase
zd10/27/log:TestGem#test_gem_path_ordering =
/home/akr/tst1/ruby/lib/rinda/tuplespace.rb:325: [BUG] object allocation
during garbage collection phase
zd10/34/log:TestGemDependencyInstaller#test_install_version =
/home/akr/tst1/ruby/lib/rinda/tuplespace.rb:325: [BUG] object allocation
during garbage collection phase
zd10/45/log:TestGemSourceInstalled#test_spaceship =
/home/akr/tst1/ruby/lib/rubygems/package.rb:419: [BUG] rb_gc_mark():
0x002b969501c870 is T_ZOMBIE
zd10/51/log:TestWeakRef#test_weakref_finalize =
/home/akr/tst1/ruby/lib/rinda/tuplespace.rb:325: [BUG] object allocation
during garbage collection phase
zd10/52/log:TestGem#test_looks_for_gemdeps_files_automatically_on_start
= /home/akr/tst1/ruby/lib/rinda/tuplespace.rb:325: [BUG] object
allocation during garbage collection phase
zd10/56/log:TestGemInstaller#test_generate_bin_symlink_update_older =
/home/akr/tst1/ruby/lib/rinda/tuplespace.rb:325: [BUG] object allocation
during garbage collection phase
zd10/73/log:TestCSV::Features#test_gzip_writer_bug_fix =
/home/akr/tst1/ruby/lib/rinda/tuplespace.rb:325: [BUG] object allocation
during garbage collection phase
zd10/74/log:TestGemDependencyInstaller#test_install_minimal_deps =
/home/akr/tst1/ruby/lib/rinda/tuplespace.rb:325: [BUG] object allocation
during garbage collection phase
zd10/88/log:TestGemDependencyInstaller#test_install_dependency_old =
/home/akr/tst1/ruby/lib/rinda/tuplespace.rb:325: [BUG] object allocation
during garbage collection phase
zd10/99/log:TestGemCommandsInstallCommand#test_execute_prerelease_skipped_when_non_pre_available
= /home/akr/tst1/ruby/lib/rinda/tuplespace.rb:325: [BUG] object
allocation during garbage collection phase
zd10/102/log:TestGemUninstaller#test_uninstall_doesnt_prompt_when_other_gem_satifies_requirement
= /home/akr/tst1/ruby/lib/rinda/tuplespace.rb:325: [BUG] object
allocation during garbage collection phase
zd10/104/log:TestWeakRef#test_weakref_finalize =
/home/akr/tst1/ruby/lib/webrick/utils.rb:165: [BUG] object allocation
during garbage collection phase
zd10/120/log:TestGemSpecFetcher#test_available_specs_prerelease =
/home/akr/tst1/ruby/lib/rinda/tuplespace.rb:325: [BUG] object allocation
during garbage collection phase
zd10/127/log:TestGemDependencyInstaller#test_install_dependency_development_shallow
= /home/akr/tst1/ruby/lib/rinda/tuplespace.rb:325: [BUG] object
allocation during garbage collection phase
zd10/132/log:TestGemSourceSpecificFile#test_spec =
/home/akr/tst1/ruby/lib/rinda/tuplespace.rb:325: [BUG] object allocation
during garbage collection phase
zd10/157/log:TestGemUninstaller#test_remove_executables_user_format =
/home/akr/tst1/ruby/lib/rinda/tuplespace.rb:325: [BUG] object allocation
during garbage collection phase
zd10/172/log:TestGemSourceLocal#test_find_gem_prerelease =
/home/akr/tst1/ruby/lib/webrick/utils.rb:165: [BUG] Segmentation fault
zd10/173/log:TestGem#test_looks_for_gemdeps_files_automatically_on_start
= /home/akr/tst1/ruby/lib/rinda/tuplespace.rb:325: [BUG] object
allocation during garbage collection phase
zd10/193/log:TestGemSourceLocal#test_find_gem_prerelease =
/home/akr/tst1/ruby/lib/rinda/tuplespace.rb:325: [BUG] object allocation
during garbage collection phase
zd10/195/log:TestGem#test_looks_for_gemdeps_files_automatically_on_start
= /home/akr/tst1/ruby/lib/rinda/tuplespace.rb:325: [BUG] object
allocation during garbage collection phase
zd10/196/log:TestGemUninstaller#test_remove_executables_user =
/home/akr/tst1/ruby/lib/rinda/tuplespace.rb:325: [BUG] object allocation
during garbage collection phase
zd10/197/log:TestGemUninstaller#test_uninstall_prompt_includes_dep_type
= /home/akr/tst1/ruby/lib/rinda/tuplespace.rb:325: [BUG] object
allocation during garbage collection phase
zd10/215/log:TestWeakRef#test_weakref_finalize =
/home/akr/tst1/ruby/lib/rinda/tuplespace.rb:325: [BUG] object allocation
during garbage collection phase
zd10/216/log:TestGem#test_looks_for_gemdeps_files_automatically_on_start
= /home/akr/tst1/ruby/lib/rinda/tuplespace.rb:325: [BUG] object
allocation during garbage collection phase
zd10/217/log:TestGemDependencyInstaller#test_install_dependency_development_deep
= /home/akr/tst1/ruby/lib/rinda/tuplespace.rb:325: [BUG] object
allocation during garbage collection phase
zd10/227/log:TestGemCommandsCleanupCommand#test_handle_options_dry_run =
/home/akr/tst1/ruby/lib/rinda/tuplespace.rb:325: [BUG] object allocation
during garbage collection phase
zd10/234/log:TestGemInstaller#test_install_extension_flat =
/home/akr/tst1/ruby/lib/rinda/tuplespace.rb:325: [BUG] object allocation
during garbage collection phase
zd10/239/log:TestGemUninstaller#test_uninstall_only_lists_unsatified_deps
= /home/akr/tst1/ruby/lib/rinda/tuplespace.rb:325: [BUG] object
allocation during garbage collection phase
zd10/246/log:TestGemDependencyInstaller#test_install_install_dir =
/home/akr/tst1/ruby/lib/rinda/tuplespace.rb:325: [BUG] object allocation
during garbage collection phase
zd10/255/log:TestWeakRef#test_weakref_finalize =
/home/akr/tst1/ruby/lib/rinda/tuplespace.rb:325: [BUG] object allocation
during garbage collection phase
zd10/270/log:TestGemDependencyInstaller#test_install_dependencies_satisfied
= /home/akr/tst1/ruby/lib/rinda/tuplespace.rb:325: [BUG] object
allocation during garbage collection phase
zd10/288/log:TestWeakRef#test_weakref_finalize =
/home/akr/tst1/ruby/lib/rinda/tuplespace.rb:325: [BUG] object allocation
during garbage collection phase
zd10/291/log:TestWeakRef#test_weakref_finalize =
/home/akr/tst1/ruby/lib/webrick/utils.rb:165: [BUG] object allocation
during garbage collection phase

一昨日の夜、r43539 でやったときは出なかったので、
r43539 から r43558 のあいだのどれかだとおもうのですが、
心当たりのある方はいませんか。

% svn log -r43539:43558

r43539 | tarui | 2013-11-05 20:15:21 +0900 (Tue, 05 Nov 2013) | 3 lines

gc.c (is_live_object): A hidden object may be a live object.
[ruby-dev:47788] [Bug #9072]

r43540 | akr | 2013-11-05 21:25:15 +0900 (Tue, 05 Nov 2013) | 4 lines

test/ruby/test_thread.rb (test_thread_join_in_trap):
Run the test in a different process.

r43541 | tenderlove | 2013-11-06 04:15:40 +0900 (Wed, 06 Nov 2013) | 4
lines

ext/psych/lib/psych/visitors/to_ruby.rb: process merge keys before
reviving objects. Fixes GH psych #168
test/psych/test_merge_keys.rb: test for change
https://github.com/tenderlove/psych/issues/168

r43542 | svn | 2013-11-06 04:15:46 +0900 (Wed, 06 Nov 2013) | 1 line

2013-11-06

r43543 | ko1 | 2013-11-06 07:13:08 +0900 (Wed, 06 Nov 2013) | 3 lines

benchmark/gc/gcbench.rb: add some options to make quiet.

r43544 | ko1 | 2013-11-06 07:13:51 +0900 (Wed, 06 Nov 2013) | 3 lines

gc.c (Init_GC): add GC::OPTS to show options.

r43545 | eregon | 2013-11-06 07:27:27 +0900 (Wed, 06 Nov 2013) | 1 line

benchmark/gc/gcbench.rb: fix typo of r43543

r43546 | ko1 | 2013-11-06 09:14:26 +0900 (Wed, 06 Nov 2013) | 3 lines

gc.c: define RGENGC_ESTIMATE_OLDSPACE == 0 if USE_RGENGC is 0.

r43547 | ko1 | 2013-11-06 09:17:14 +0900 (Wed, 06 Nov 2013) | 12 lines

benchmark/bm_vm1_gc_short_lived.rb: added.
These GC benchmarks do not reflect practical applications.
They are only for tuning.
benchmark/bm_vm1_gc_short_with_complex_long.rb: added.
benchmark/bm_vm1_gc_short_with_long.rb: added.
benchmark/bm_vm1_gc_short_with_symbol.rb: added.
benchmark/bm_vm1_gc_wb_ary.rb: added.
benchmark/bm_vm1_gc_wb_obj.rb: added.
benchmark/bm_vm_thread_queue.rb: added.
Thie benchmark is added to know how fast C verion of thread.so.

r43548 | nobu | 2013-11-06 09:21:05 +0900 (Wed, 06 Nov 2013) | 1 line

properties.

r43549 | glass | 2013-11-06 10:39:55 +0900 (Wed, 06 Nov 2013) | 1 line

array.c (rb_ary_and): defer hash creation and some refactoring.

r43550 | glass | 2013-11-06 11:50:28 +0900 (Wed, 06 Nov 2013) | 2 lines

array.c (rb_ary_sample): use RARRAY_AREF() and RARRAY_PTR_USE()
instead of RARRAY_PTR().

r43551 | naruse | 2013-11-06 15:23:27 +0900 (Wed, 06 Nov 2013) | 1 line

Suppress Warnings: instance variable @installed_by_version not
initialized

r43552 | naruse | 2013-11-06 15:23:29 +0900 (Wed, 06 Nov 2013) | 1 line

Suppress warnings: File.exists? is a deprecated name

r43553 | naruse | 2013-11-06 15:25:18 +0900 (Wed, 06 Nov 2013) | 1 line

Suppress warnings: ambiguous first argument; put parentheses or even
spaces

r43554 | duerst | 2013-11-06 16:32:56 +0900 (Wed, 06 Nov 2013) | 1 line

lib/open3.rb: tweaked grammar in comments

r43555 | tarui | 2013-11-06 19:32:40 +0900 (Wed, 06 Nov 2013) | 2 lines

common.mk (help): add texts about gcbench.

r43556 | glass | 2013-11-06 21:09:31 +0900 (Wed, 06 Nov 2013) | 1 line

array.c (rb_ary_reverse): use RARRAY_PTR_USE().

r43557 | glass | 2013-11-06 21:20:39 +0900 (Wed, 06 Nov 2013) | 2 lines

array.c (rb_ary_shift_m): use RARRAY_PTR_USE() without WB because
there are not new relations.

r43558 | tarui | 2013-11-06 21:36:34 +0900 (Wed, 06 Nov 2013) | 12 lines

gc.c (gc_before_sweep): Change algorithm of malloc_limit to
conservative for closing to memory consumption of ruby 2.0.
gc.c (GC_MALLOC_LIMIT, GC_MALLOC_LIMIT_GROWTH_FACTOR):
Adjust parameters for new algorithm.

Example: make gcbench-rdoc on a pc
time maxrss
2.0.0p343 285.27 281853952
trunk before patch 207.19 690405376
trunk after patch 211.59 312500224

akr_SAkira_T.S · November 7, 2013, 2:37am

Issue #9090 has been updated by tarui (Masaya T.).

C-level stack traceにシンボル情報がほとんど載ってないので、objdump -S ruby
の結果も何処かに上げていただけるとありがたいです。

Bug #9090: [BUG] object allocation during garbage collection phase

Author: akr (Akira T.)
Status: Open
Priority: Normal
Assignee:
Category:
Target version:
ruby -v: ruby 2.1.0dev (2013-11-06 trunk 43558) [x86_64-linux]
Backport: 1.9.3: UNKNOWN, 2.0.0: UNKNOWN

昨日の夜、r43558 で make check を 300回動かしてみたところ、
なんかずいぶんと [BUG] が出ました。

% ./ruby -v
ruby 2.1.0dev (2013-11-06 trunk 43558) [x86_64-linux]
% fgrep ‘[BUG]’ zd10/*/log
zd10/1/log:TestGem#test_looks_for_gemdeps_files_automatically_on_start =
/home/akr/tst1/ruby/lib/rinda/tuplespace.rb:325: [BUG] object allocation
during garbage collection phase
zd10/27/log:TestGem#test_gem_path_ordering =
/home/akr/tst1/ruby/lib/rinda/tuplespace.rb:325: [BUG] object allocation
during garbage collection phase
zd10/34/log:TestGemDependencyInstaller#test_install_version =
/home/akr/tst1/ruby/lib/rinda/tuplespace.rb:325: [BUG] object allocation
during garbage collection phase
zd10/45/log:TestGemSourceInstalled#test_spaceship =
/home/akr/tst1/ruby/lib/rubygems/package.rb:419: [BUG] rb_gc_mark():
0x002b969501c870 is T_ZOMBIE
zd10/51/log:TestWeakRef#test_weakref_finalize =
/home/akr/tst1/ruby/lib/rinda/tuplespace.rb:325: [BUG] object allocation
during garbage collection phase
zd10/52/log:TestGem#test_looks_for_gemdeps_files_automatically_on_start
= /home/akr/tst1/ruby/lib/rinda/tuplespace.rb:325: [BUG] object
allocation during garbage collection phase
zd10/56/log:TestGemInstaller#test_generate_bin_symlink_update_older =
/home/akr/tst1/ruby/lib/rinda/tuplespace.rb:325: [BUG] object allocation
during garbage collection phase
zd10/73/log:TestCSV::Features#test_gzip_writer_bug_fix =
/home/akr/tst1/ruby/lib/rinda/tuplespace.rb:325: [BUG] object allocation
during garbage collection phase
zd10/74/log:TestGemDependencyInstaller#test_install_minimal_deps =
/home/akr/tst1/ruby/lib/rinda/tuplespace.rb:325: [BUG] object allocation
during garbage collection phase
zd10/88/log:TestGemDependencyInstaller#test_install_dependency_old =
/home/akr/tst1/ruby/lib/rinda/tuplespace.rb:325: [BUG] object allocation
during garbage collection phase
zd10/99/log:TestGemCommandsInstallCommand#test_execute_prerelease_skipped_when_non_pre_available
= /home/akr/tst1/ruby/lib/rinda/tuplespace.rb:325: [BUG] object
allocation during garbage collection phase
zd10/102/log:TestGemUninstaller#test_uninstall_doesnt_prompt_when_other_gem_satifies_requirement
= /home/akr/tst1/ruby/lib/rinda/tuplespace.rb:325: [BUG] object
allocation during garbage collection phase
zd10/104/log:TestWeakRef#test_weakref_finalize =
/home/akr/tst1/ruby/lib/webrick/utils.rb:165: [BUG] object allocation
during garbage collection phase
zd10/120/log:TestGemSpecFetcher#test_available_specs_prerelease =
/home/akr/tst1/ruby/lib/rinda/tuplespace.rb:325: [BUG] object allocation
during garbage collection phase
zd10/127/log:TestGemDependencyInstaller#test_install_dependency_development_shallow
= /home/akr/tst1/ruby/lib/rinda/tuplespace.rb:325: [BUG] object
allocation during garbage collection phase
zd10/132/log:TestGemSourceSpecificFile#test_spec =
/home/akr/tst1/ruby/lib/rinda/tuplespace.rb:325: [BUG] object allocation
during garbage collection phase
zd10/157/log:TestGemUninstaller#test_remove_executables_user_format =
/home/akr/tst1/ruby/lib/rinda/tuplespace.rb:325: [BUG] object allocation
during garbage collection phase
zd10/172/log:TestGemSourceLocal#test_find_gem_prerelease =
/home/akr/tst1/ruby/lib/webrick/utils.rb:165: [BUG] Segmentation fault
zd10/173/log:TestGem#test_looks_for_gemdeps_files_automatically_on_start
= /home/akr/tst1/ruby/lib/rinda/tuplespace.rb:325: [BUG] object
allocation during garbage collection phase
zd10/193/log:TestGemSourceLocal#test_find_gem_prerelease =
/home/akr/tst1/ruby/lib/rinda/tuplespace.rb:325: [BUG] object allocation
during garbage collection phase
zd10/195/log:TestGem#test_looks_for_gemdeps_files_automatically_on_start
= /home/akr/tst1/ruby/lib/rinda/tuplespace.rb:325: [BUG] object
allocation during garbage collection phase
zd10/196/log:TestGemUninstaller#test_remove_executables_user =
/home/akr/tst1/ruby/lib/rinda/tuplespace.rb:325: [BUG] object allocation
during garbage collection phase
zd10/197/log:TestGemUninstaller#test_uninstall_prompt_includes_dep_type
= /home/akr/tst1/ruby/lib/rinda/tuplespace.rb:325: [BUG] object
allocation during garbage collection phase
zd10/215/log:TestWeakRef#test_weakref_finalize =
/home/akr/tst1/ruby/lib/rinda/tuplespace.rb:325: [BUG] object allocation
during garbage collection phase
zd10/216/log:TestGem#test_looks_for_gemdeps_files_automatically_on_start
= /home/akr/tst1/ruby/lib/rinda/tuplespace.rb:325: [BUG] object
allocation during garbage collection phase
zd10/217/log:TestGemDependencyInstaller#test_install_dependency_development_deep
= /home/akr/tst1/ruby/lib/rinda/tuplespace.rb:325: [BUG] object
allocation during garbage collection phase
zd10/227/log:TestGemCommandsCleanupCommand#test_handle_options_dry_run =
/home/akr/tst1/ruby/lib/rinda/tuplespace.rb:325: [BUG] object allocation
during garbage collection phase
zd10/234/log:TestGemInstaller#test_install_extension_flat =
/home/akr/tst1/ruby/lib/rinda/tuplespace.rb:325: [BUG] object allocation
during garbage collection phase
zd10/239/log:TestGemUninstaller#test_uninstall_only_lists_unsatified_deps
= /home/akr/tst1/ruby/lib/rinda/tuplespace.rb:325: [BUG] object
allocation during garbage collection phase
zd10/246/log:TestGemDependencyInstaller#test_install_install_dir =
/home/akr/tst1/ruby/lib/rinda/tuplespace.rb:325: [BUG] object allocation
during garbage collection phase
zd10/255/log:TestWeakRef#test_weakref_finalize =
/home/akr/tst1/ruby/lib/rinda/tuplespace.rb:325: [BUG] object allocation
during garbage collection phase
zd10/270/log:TestGemDependencyInstaller#test_install_dependencies_satisfied
= /home/akr/tst1/ruby/lib/rinda/tuplespace.rb:325: [BUG] object
allocation during garbage collection phase
zd10/288/log:TestWeakRef#test_weakref_finalize =
/home/akr/tst1/ruby/lib/rinda/tuplespace.rb:325: [BUG] object allocation
during garbage collection phase
zd10/291/log:TestWeakRef#test_weakref_finalize =
/home/akr/tst1/ruby/lib/webrick/utils.rb:165: [BUG] object allocation
during garbage collection phase

一昨日の夜、r43539 でやったときは出なかったので、
r43539 から r43558 のあいだのどれかだとおもうのですが、
心当たりのある方はいませんか。

% svn log -r43539:43558

r43539 | tarui | 2013-11-05 20:15:21 +0900 (Tue, 05 Nov 2013) | 3 lines

gc.c (is_live_object): A hidden object may be a live object.
[ruby-dev:47788] [Bug #9072]

r43540 | akr | 2013-11-05 21:25:15 +0900 (Tue, 05 Nov 2013) | 4 lines

test/ruby/test_thread.rb (test_thread_join_in_trap):
Run the test in a different process.

r43541 | tenderlove | 2013-11-06 04:15:40 +0900 (Wed, 06 Nov 2013) | 4
lines

ext/psych/lib/psych/visitors/to_ruby.rb: process merge keys before
reviving objects. Fixes GH psych #168
test/psych/test_merge_keys.rb: test for change
Unable to load DateTime.new · Issue #168 · ruby/psych · GitHub

r43542 | svn | 2013-11-06 04:15:46 +0900 (Wed, 06 Nov 2013) | 1 line

2013-11-06

r43543 | ko1 | 2013-11-06 07:13:08 +0900 (Wed, 06 Nov 2013) | 3 lines

benchmark/gc/gcbench.rb: add some options to make quiet.

r43544 | ko1 | 2013-11-06 07:13:51 +0900 (Wed, 06 Nov 2013) | 3 lines

gc.c (Init_GC): add GC::OPTS to show options.

r43545 | eregon | 2013-11-06 07:27:27 +0900 (Wed, 06 Nov 2013) | 1 line

benchmark/gc/gcbench.rb: fix typo of r43543

r43546 | ko1 | 2013-11-06 09:14:26 +0900 (Wed, 06 Nov 2013) | 3 lines

gc.c: define RGENGC_ESTIMATE_OLDSPACE == 0 if USE_RGENGC is 0.

r43547 | ko1 | 2013-11-06 09:17:14 +0900 (Wed, 06 Nov 2013) | 12 lines

benchmark/bm_vm1_gc_short_lived.rb: added.
These GC benchmarks do not reflect practical applications.
They are only for tuning.
benchmark/bm_vm1_gc_short_with_complex_long.rb: added.
benchmark/bm_vm1_gc_short_with_long.rb: added.
benchmark/bm_vm1_gc_short_with_symbol.rb: added.
benchmark/bm_vm1_gc_wb_ary.rb: added.
benchmark/bm_vm1_gc_wb_obj.rb: added.
benchmark/bm_vm_thread_queue.rb: added.
Thie benchmark is added to know how fast C verion of thread.so.

r43548 | nobu | 2013-11-06 09:21:05 +0900 (Wed, 06 Nov 2013) | 1 line

properties.

r43549 | glass | 2013-11-06 10:39:55 +0900 (Wed, 06 Nov 2013) | 1 line

array.c (rb_ary_and): defer hash creation and some refactoring.

r43550 | glass | 2013-11-06 11:50:28 +0900 (Wed, 06 Nov 2013) | 2 lines

array.c (rb_ary_sample): use RARRAY_AREF() and RARRAY_PTR_USE()
instead of RARRAY_PTR().

r43551 | naruse | 2013-11-06 15:23:27 +0900 (Wed, 06 Nov 2013) | 1 line

Suppress Warnings: instance variable @installed_by_version not
initialized

r43552 | naruse | 2013-11-06 15:23:29 +0900 (Wed, 06 Nov 2013) | 1 line

Suppress warnings: File.exists? is a deprecated name

r43553 | naruse | 2013-11-06 15:25:18 +0900 (Wed, 06 Nov 2013) | 1 line

Suppress warnings: ambiguous first argument; put parentheses or even
spaces

r43554 | duerst | 2013-11-06 16:32:56 +0900 (Wed, 06 Nov 2013) | 1 line

lib/open3.rb: tweaked grammar in comments

r43555 | tarui | 2013-11-06 19:32:40 +0900 (Wed, 06 Nov 2013) | 2 lines

common.mk (help): add texts about gcbench.

r43556 | glass | 2013-11-06 21:09:31 +0900 (Wed, 06 Nov 2013) | 1 line

array.c (rb_ary_reverse): use RARRAY_PTR_USE().

r43557 | glass | 2013-11-06 21:20:39 +0900 (Wed, 06 Nov 2013) | 2 lines

array.c (rb_ary_shift_m): use RARRAY_PTR_USE() without WB because
there are not new relations.

r43558 | tarui | 2013-11-06 21:36:34 +0900 (Wed, 06 Nov 2013) | 12 lines

gc.c (gc_before_sweep): Change algorithm of malloc_limit to
conservative for closing to memory consumption of ruby 2.0.
gc.c (GC_MALLOC_LIMIT, GC_MALLOC_LIMIT_GROWTH_FACTOR):
Adjust parameters for new algorithm.

Example: make gcbench-rdoc on a pc
time maxrss
2.0.0p343 285.27 281853952
trunk before patch 207.19 690405376
trunk after patch 211.59 312500224

akr_SAkira_T.S · November 7, 2013, 9:34am

Issue #9090 has been updated by tarui (Masaya T.).

r43558もGC起動のスレッシュルドを変えただけなので、
ここで発生となるとこれまで発生確率が低くて眠ってたバグを掘り起こしたって事に。
とりあえず見てみます。

Bug #9090: [BUG] object allocation during garbage collection phase

Author: akr (Akira T.)
Status: Open
Priority: Normal
Assignee:
Category:
Target version:
ruby -v: ruby 2.1.0dev (2013-11-06 trunk 43558) [x86_64-linux]
Backport: 1.9.3: UNKNOWN, 2.0.0: UNKNOWN

昨日の夜、r43558 で make check を 300回動かしてみたところ、
なんかずいぶんと [BUG] が出ました。

% ./ruby -v
ruby 2.1.0dev (2013-11-06 trunk 43558) [x86_64-linux]
% fgrep ‘[BUG]’ zd10/*/log
zd10/1/log:TestGem#test_looks_for_gemdeps_files_automatically_on_start =
/home/akr/tst1/ruby/lib/rinda/tuplespace.rb:325: [BUG] object allocation
during garbage collection phase
zd10/27/log:TestGem#test_gem_path_ordering =
/home/akr/tst1/ruby/lib/rinda/tuplespace.rb:325: [BUG] object allocation
during garbage collection phase
zd10/34/log:TestGemDependencyInstaller#test_install_version =
/home/akr/tst1/ruby/lib/rinda/tuplespace.rb:325: [BUG] object allocation
during garbage collection phase
zd10/45/log:TestGemSourceInstalled#test_spaceship =
/home/akr/tst1/ruby/lib/rubygems/package.rb:419: [BUG] rb_gc_mark():
0x002b969501c870 is T_ZOMBIE
zd10/51/log:TestWeakRef#test_weakref_finalize =
/home/akr/tst1/ruby/lib/rinda/tuplespace.rb:325: [BUG] object allocation
during garbage collection phase
zd10/52/log:TestGem#test_looks_for_gemdeps_files_automatically_on_start
= /home/akr/tst1/ruby/lib/rinda/tuplespace.rb:325: [BUG] object
allocation during garbage collection phase
zd10/56/log:TestGemInstaller#test_generate_bin_symlink_update_older =
/home/akr/tst1/ruby/lib/rinda/tuplespace.rb:325: [BUG] object allocation
during garbage collection phase
zd10/73/log:TestCSV::Features#test_gzip_writer_bug_fix =
/home/akr/tst1/ruby/lib/rinda/tuplespace.rb:325: [BUG] object allocation
during garbage collection phase
zd10/74/log:TestGemDependencyInstaller#test_install_minimal_deps =
/home/akr/tst1/ruby/lib/rinda/tuplespace.rb:325: [BUG] object allocation
during garbage collection phase
zd10/88/log:TestGemDependencyInstaller#test_install_dependency_old =
/home/akr/tst1/ruby/lib/rinda/tuplespace.rb:325: [BUG] object allocation
during garbage collection phase
zd10/99/log:TestGemCommandsInstallCommand#test_execute_prerelease_skipped_when_non_pre_available
= /home/akr/tst1/ruby/lib/rinda/tuplespace.rb:325: [BUG] object
allocation during garbage collection phase
zd10/102/log:TestGemUninstaller#test_uninstall_doesnt_prompt_when_other_gem_satifies_requirement
= /home/akr/tst1/ruby/lib/rinda/tuplespace.rb:325: [BUG] object
allocation during garbage collection phase
zd10/104/log:TestWeakRef#test_weakref_finalize =
/home/akr/tst1/ruby/lib/webrick/utils.rb:165: [BUG] object allocation
during garbage collection phase
zd10/120/log:TestGemSpecFetcher#test_available_specs_prerelease =
/home/akr/tst1/ruby/lib/rinda/tuplespace.rb:325: [BUG] object allocation
during garbage collection phase
zd10/127/log:TestGemDependencyInstaller#test_install_dependency_development_shallow
= /home/akr/tst1/ruby/lib/rinda/tuplespace.rb:325: [BUG] object
allocation during garbage collection phase
zd10/132/log:TestGemSourceSpecificFile#test_spec =
/home/akr/tst1/ruby/lib/rinda/tuplespace.rb:325: [BUG] object allocation
during garbage collection phase
zd10/157/log:TestGemUninstaller#test_remove_executables_user_format =
/home/akr/tst1/ruby/lib/rinda/tuplespace.rb:325: [BUG] object allocation
during garbage collection phase
zd10/172/log:TestGemSourceLocal#test_find_gem_prerelease =
/home/akr/tst1/ruby/lib/webrick/utils.rb:165: [BUG] Segmentation fault
zd10/173/log:TestGem#test_looks_for_gemdeps_files_automatically_on_start
= /home/akr/tst1/ruby/lib/rinda/tuplespace.rb:325: [BUG] object
allocation during garbage collection phase
zd10/193/log:TestGemSourceLocal#test_find_gem_prerelease =
/home/akr/tst1/ruby/lib/rinda/tuplespace.rb:325: [BUG] object allocation
during garbage collection phase
zd10/195/log:TestGem#test_looks_for_gemdeps_files_automatically_on_start
= /home/akr/tst1/ruby/lib/rinda/tuplespace.rb:325: [BUG] object
allocation during garbage collection phase
zd10/196/log:TestGemUninstaller#test_remove_executables_user =
/home/akr/tst1/ruby/lib/rinda/tuplespace.rb:325: [BUG] object allocation
during garbage collection phase
zd10/197/log:TestGemUninstaller#test_uninstall_prompt_includes_dep_type
= /home/akr/tst1/ruby/lib/rinda/tuplespace.rb:325: [BUG] object
allocation during garbage collection phase
zd10/215/log:TestWeakRef#test_weakref_finalize =
/home/akr/tst1/ruby/lib/rinda/tuplespace.rb:325: [BUG] object allocation
during garbage collection phase
zd10/216/log:TestGem#test_looks_for_gemdeps_files_automatically_on_start
= /home/akr/tst1/ruby/lib/rinda/tuplespace.rb:325: [BUG] object
allocation during garbage collection phase
zd10/217/log:TestGemDependencyInstaller#test_install_dependency_development_deep
= /home/akr/tst1/ruby/lib/rinda/tuplespace.rb:325: [BUG] object
allocation during garbage collection phase
zd10/227/log:TestGemCommandsCleanupCommand#test_handle_options_dry_run =
/home/akr/tst1/ruby/lib/rinda/tuplespace.rb:325: [BUG] object allocation
during garbage collection phase
zd10/234/log:TestGemInstaller#test_install_extension_flat =
/home/akr/tst1/ruby/lib/rinda/tuplespace.rb:325: [BUG] object allocation
during garbage collection phase
zd10/239/log:TestGemUninstaller#test_uninstall_only_lists_unsatified_deps
= /home/akr/tst1/ruby/lib/rinda/tuplespace.rb:325: [BUG] object
allocation during garbage collection phase
zd10/246/log:TestGemDependencyInstaller#test_install_install_dir =
/home/akr/tst1/ruby/lib/rinda/tuplespace.rb:325: [BUG] object allocation
during garbage collection phase
zd10/255/log:TestWeakRef#test_weakref_finalize =
/home/akr/tst1/ruby/lib/rinda/tuplespace.rb:325: [BUG] object allocation
during garbage collection phase
zd10/270/log:TestGemDependencyInstaller#test_install_dependencies_satisfied
= /home/akr/tst1/ruby/lib/rinda/tuplespace.rb:325: [BUG] object
allocation during garbage collection phase
zd10/288/log:TestWeakRef#test_weakref_finalize =
/home/akr/tst1/ruby/lib/rinda/tuplespace.rb:325: [BUG] object allocation
during garbage collection phase
zd10/291/log:TestWeakRef#test_weakref_finalize =
/home/akr/tst1/ruby/lib/webrick/utils.rb:165: [BUG] object allocation
during garbage collection phase

一昨日の夜、r43539 でやったときは出なかったので、
r43539 から r43558 のあいだのどれかだとおもうのですが、
心当たりのある方はいませんか。

% svn log -r43539:43558

r43539 | tarui | 2013-11-05 20:15:21 +0900 (Tue, 05 Nov 2013) | 3 lines

gc.c (is_live_object): A hidden object may be a live object.
[ruby-dev:47788] [Bug #9072]

r43540 | akr | 2013-11-05 21:25:15 +0900 (Tue, 05 Nov 2013) | 4 lines

test/ruby/test_thread.rb (test_thread_join_in_trap):
Run the test in a different process.

r43541 | tenderlove | 2013-11-06 04:15:40 +0900 (Wed, 06 Nov 2013) | 4
lines

ext/psych/lib/psych/visitors/to_ruby.rb: process merge keys before
reviving objects. Fixes GH psych #168
test/psych/test_merge_keys.rb: test for change
Unable to load DateTime.new · Issue #168 · ruby/psych · GitHub

r43542 | svn | 2013-11-06 04:15:46 +0900 (Wed, 06 Nov 2013) | 1 line

2013-11-06

r43543 | ko1 | 2013-11-06 07:13:08 +0900 (Wed, 06 Nov 2013) | 3 lines

benchmark/gc/gcbench.rb: add some options to make quiet.

r43544 | ko1 | 2013-11-06 07:13:51 +0900 (Wed, 06 Nov 2013) | 3 lines

gc.c (Init_GC): add GC::OPTS to show options.

r43545 | eregon | 2013-11-06 07:27:27 +0900 (Wed, 06 Nov 2013) | 1 line

benchmark/gc/gcbench.rb: fix typo of r43543

r43546 | ko1 | 2013-11-06 09:14:26 +0900 (Wed, 06 Nov 2013) | 3 lines

gc.c: define RGENGC_ESTIMATE_OLDSPACE == 0 if USE_RGENGC is 0.

r43547 | ko1 | 2013-11-06 09:17:14 +0900 (Wed, 06 Nov 2013) | 12 lines

benchmark/bm_vm1_gc_short_lived.rb: added.
These GC benchmarks do not reflect practical applications.
They are only for tuning.
benchmark/bm_vm1_gc_short_with_complex_long.rb: added.
benchmark/bm_vm1_gc_short_with_long.rb: added.
benchmark/bm_vm1_gc_short_with_symbol.rb: added.
benchmark/bm_vm1_gc_wb_ary.rb: added.
benchmark/bm_vm1_gc_wb_obj.rb: added.
benchmark/bm_vm_thread_queue.rb: added.
Thie benchmark is added to know how fast C verion of thread.so.

r43548 | nobu | 2013-11-06 09:21:05 +0900 (Wed, 06 Nov 2013) | 1 line

properties.

r43549 | glass | 2013-11-06 10:39:55 +0900 (Wed, 06 Nov 2013) | 1 line

array.c (rb_ary_and): defer hash creation and some refactoring.

r43550 | glass | 2013-11-06 11:50:28 +0900 (Wed, 06 Nov 2013) | 2 lines

array.c (rb_ary_sample): use RARRAY_AREF() and RARRAY_PTR_USE()
instead of RARRAY_PTR().

r43551 | naruse | 2013-11-06 15:23:27 +0900 (Wed, 06 Nov 2013) | 1 line

Suppress Warnings: instance variable @installed_by_version not
initialized

r43552 | naruse | 2013-11-06 15:23:29 +0900 (Wed, 06 Nov 2013) | 1 line

Suppress warnings: File.exists? is a deprecated name

r43553 | naruse | 2013-11-06 15:25:18 +0900 (Wed, 06 Nov 2013) | 1 line

Suppress warnings: ambiguous first argument; put parentheses or even
spaces

r43554 | duerst | 2013-11-06 16:32:56 +0900 (Wed, 06 Nov 2013) | 1 line

lib/open3.rb: tweaked grammar in comments

r43555 | tarui | 2013-11-06 19:32:40 +0900 (Wed, 06 Nov 2013) | 2 lines

common.mk (help): add texts about gcbench.

r43556 | glass | 2013-11-06 21:09:31 +0900 (Wed, 06 Nov 2013) | 1 line

array.c (rb_ary_reverse): use RARRAY_PTR_USE().

r43557 | glass | 2013-11-06 21:20:39 +0900 (Wed, 06 Nov 2013) | 2 lines

array.c (rb_ary_shift_m): use RARRAY_PTR_USE() without WB because
there are not new relations.

r43558 | tarui | 2013-11-06 21:36:34 +0900 (Wed, 06 Nov 2013) | 12 lines

gc.c (gc_before_sweep): Change algorithm of malloc_limit to
conservative for closing to memory consumption of ruby 2.0.
gc.c (GC_MALLOC_LIMIT, GC_MALLOC_LIMIT_GROWTH_FACTOR):
Adjust parameters for new algorithm.

Example: make gcbench-rdoc on a pc
time maxrss
2.0.0p343 285.27 281853952
trunk before patch 207.19 690405376
trunk after patch 211.59 312500224

akr_SAkira_T.S · November 7, 2013, 4:08am

Issue #9090 has been updated by akr (Akira T.).

File r43558-asm.txt.gz added

objdump -S ruby の結果をつけます。

あと、rubyci.org の結果をざっとみると、同じような失敗がいくつか見つかります。

r43540
http://fb32.rubyci.org/~chkbuild/ruby-trunk/log/20131105T170302Z.diff.html.gz
r43558
http://c5632.rubyci.org/~chkbuild/ruby-trunk/log/20131106T170301Z.diff.html.gz
r43558
http://rbci.lakewood.privs.net/ruby-trunk/log/20131106T201002Z.diff.html.gz
r43560
http://fb.rubyci.org/~chkbuild/ruby-trunk/log/20131106T220301Z.diff.html.gz
r43560
http://rbci.lakewood.privs.net/ruby-trunk/log/20131106T211002Z.diff.html.gz
r43560
http://ruby-mswin.cloudapp.net/vc10-x64/ruby-trunk/log/20131106T221741Z.log.html.gz

r43540 がいちばん早いようです。

% svn log -r43539:43540

r43539 | tarui | 2013-11-05 20:15:21 +0900 (Tue, 05 Nov 2013) | 3 lines

gc.c (is_live_object): A hidden object may be a live object.
[ruby-dev:47788] [Bug #9072]

r43540 | akr | 2013-11-05 21:25:15 +0900 (Tue, 05 Nov 2013) | 4 lines

test/ruby/test_thread.rb (test_thread_join_in_trap):
Run the test in a different process.

r43539 では起きなかったので残りは r43540 で、えーと、それは私の commit ですが、
これはさすがに違うような気がするので r43540 が fb32 で起こしたのは別件かなぁ。
そうすると r43558 ですかねぇ。

% svn log -r43558

r43558 | tarui | 2013-11-06 21:36:34 +0900 (Wed, 06 Nov 2013) | 12 lines

gc.c (gc_before_sweep): Change algorithm of malloc_limit to
conservative for closing to memory consumption of ruby 2.0.
gc.c (GC_MALLOC_LIMIT, GC_MALLOC_LIMIT_GROWTH_FACTOR):
Adjust parameters for new algorithm.

Example: make gcbench-rdoc on a pc
time maxrss
2.0.0p343 285.27 281853952
trunk before patch 207.19 690405376
trunk after patch 211.59 312500224

Bug #9090: [BUG] object allocation during garbage collection phase

Author: akr (Akira T.)
Status: Open
Priority: Normal
Assignee:
Category:
Target version:
ruby -v: ruby 2.1.0dev (2013-11-06 trunk 43558) [x86_64-linux]
Backport: 1.9.3: UNKNOWN, 2.0.0: UNKNOWN

昨日の夜、r43558 で make check を 300回動かしてみたところ、
なんかずいぶんと [BUG] が出ました。

% ./ruby -v
ruby 2.1.0dev (2013-11-06 trunk 43558) [x86_64-linux]
% fgrep ‘[BUG]’ zd10/*/log
zd10/1/log:TestGem#test_looks_for_gemdeps_files_automatically_on_start =
/home/akr/tst1/ruby/lib/rinda/tuplespace.rb:325: [BUG] object allocation
during garbage collection phase
zd10/27/log:TestGem#test_gem_path_ordering =
/home/akr/tst1/ruby/lib/rinda/tuplespace.rb:325: [BUG] object allocation
during garbage collection phase
zd10/34/log:TestGemDependencyInstaller#test_install_version =
/home/akr/tst1/ruby/lib/rinda/tuplespace.rb:325: [BUG] object allocation
during garbage collection phase
zd10/45/log:TestGemSourceInstalled#test_spaceship =
/home/akr/tst1/ruby/lib/rubygems/package.rb:419: [BUG] rb_gc_mark():
0x002b969501c870 is T_ZOMBIE
zd10/51/log:TestWeakRef#test_weakref_finalize =
/home/akr/tst1/ruby/lib/rinda/tuplespace.rb:325: [BUG] object allocation
during garbage collection phase
zd10/52/log:TestGem#test_looks_for_gemdeps_files_automatically_on_start
= /home/akr/tst1/ruby/lib/rinda/tuplespace.rb:325: [BUG] object
allocation during garbage collection phase
zd10/56/log:TestGemInstaller#test_generate_bin_symlink_update_older =
/home/akr/tst1/ruby/lib/rinda/tuplespace.rb:325: [BUG] object allocation
during garbage collection phase
zd10/73/log:TestCSV::Features#test_gzip_writer_bug_fix =
/home/akr/tst1/ruby/lib/rinda/tuplespace.rb:325: [BUG] object allocation
during garbage collection phase
zd10/74/log:TestGemDependencyInstaller#test_install_minimal_deps =
/home/akr/tst1/ruby/lib/rinda/tuplespace.rb:325: [BUG] object allocation
during garbage collection phase
zd10/88/log:TestGemDependencyInstaller#test_install_dependency_old =
/home/akr/tst1/ruby/lib/rinda/tuplespace.rb:325: [BUG] object allocation
during garbage collection phase
zd10/99/log:TestGemCommandsInstallCommand#test_execute_prerelease_skipped_when_non_pre_available
= /home/akr/tst1/ruby/lib/rinda/tuplespace.rb:325: [BUG] object
allocation during garbage collection phase
zd10/102/log:TestGemUninstaller#test_uninstall_doesnt_prompt_when_other_gem_satifies_requirement
= /home/akr/tst1/ruby/lib/rinda/tuplespace.rb:325: [BUG] object
allocation during garbage collection phase
zd10/104/log:TestWeakRef#test_weakref_finalize =
/home/akr/tst1/ruby/lib/webrick/utils.rb:165: [BUG] object allocation
during garbage collection phase
zd10/120/log:TestGemSpecFetcher#test_available_specs_prerelease =
/home/akr/tst1/ruby/lib/rinda/tuplespace.rb:325: [BUG] object allocation
during garbage collection phase
zd10/127/log:TestGemDependencyInstaller#test_install_dependency_development_shallow
= /home/akr/tst1/ruby/lib/rinda/tuplespace.rb:325: [BUG] object
allocation during garbage collection phase
zd10/132/log:TestGemSourceSpecificFile#test_spec =
/home/akr/tst1/ruby/lib/rinda/tuplespace.rb:325: [BUG] object allocation
during garbage collection phase
zd10/157/log:TestGemUninstaller#test_remove_executables_user_format =
/home/akr/tst1/ruby/lib/rinda/tuplespace.rb:325: [BUG] object allocation
during garbage collection phase
zd10/172/log:TestGemSourceLocal#test_find_gem_prerelease =
/home/akr/tst1/ruby/lib/webrick/utils.rb:165: [BUG] Segmentation fault
zd10/173/log:TestGem#test_looks_for_gemdeps_files_automatically_on_start
= /home/akr/tst1/ruby/lib/rinda/tuplespace.rb:325: [BUG] object
allocation during garbage collection phase
zd10/193/log:TestGemSourceLocal#test_find_gem_prerelease =
/home/akr/tst1/ruby/lib/rinda/tuplespace.rb:325: [BUG] object allocation
during garbage collection phase
zd10/195/log:TestGem#test_looks_for_gemdeps_files_automatically_on_start
= /home/akr/tst1/ruby/lib/rinda/tuplespace.rb:325: [BUG] object
allocation during garbage collection phase
zd10/196/log:TestGemUninstaller#test_remove_executables_user =
/home/akr/tst1/ruby/lib/rinda/tuplespace.rb:325: [BUG] object allocation
during garbage collection phase
zd10/197/log:TestGemUninstaller#test_uninstall_prompt_includes_dep_type
= /home/akr/tst1/ruby/lib/rinda/tuplespace.rb:325: [BUG] object
allocation during garbage collection phase
zd10/215/log:TestWeakRef#test_weakref_finalize =
/home/akr/tst1/ruby/lib/rinda/tuplespace.rb:325: [BUG] object allocation
during garbage collection phase
zd10/216/log:TestGem#test_looks_for_gemdeps_files_automatically_on_start
= /home/akr/tst1/ruby/lib/rinda/tuplespace.rb:325: [BUG] object
allocation during garbage collection phase
zd10/217/log:TestGemDependencyInstaller#test_install_dependency_development_deep
= /home/akr/tst1/ruby/lib/rinda/tuplespace.rb:325: [BUG] object
allocation during garbage collection phase
zd10/227/log:TestGemCommandsCleanupCommand#test_handle_options_dry_run =
/home/akr/tst1/ruby/lib/rinda/tuplespace.rb:325: [BUG] object allocation
during garbage collection phase
zd10/234/log:TestGemInstaller#test_install_extension_flat =
/home/akr/tst1/ruby/lib/rinda/tuplespace.rb:325: [BUG] object allocation
during garbage collection phase
zd10/239/log:TestGemUninstaller#test_uninstall_only_lists_unsatified_deps
= /home/akr/tst1/ruby/lib/rinda/tuplespace.rb:325: [BUG] object
allocation during garbage collection phase
zd10/246/log:TestGemDependencyInstaller#test_install_install_dir =
/home/akr/tst1/ruby/lib/rinda/tuplespace.rb:325: [BUG] object allocation
during garbage collection phase
zd10/255/log:TestWeakRef#test_weakref_finalize =
/home/akr/tst1/ruby/lib/rinda/tuplespace.rb:325: [BUG] object allocation
during garbage collection phase
zd10/270/log:TestGemDependencyInstaller#test_install_dependencies_satisfied
= /home/akr/tst1/ruby/lib/rinda/tuplespace.rb:325: [BUG] object
allocation during garbage collection phase
zd10/288/log:TestWeakRef#test_weakref_finalize =
/home/akr/tst1/ruby/lib/rinda/tuplespace.rb:325: [BUG] object allocation
during garbage collection phase
zd10/291/log:TestWeakRef#test_weakref_finalize =
/home/akr/tst1/ruby/lib/webrick/utils.rb:165: [BUG] object allocation
during garbage collection phase

一昨日の夜、r43539 でやったときは出なかったので、
r43539 から r43558 のあいだのどれかだとおもうのですが、
心当たりのある方はいませんか。

% svn log -r43539:43558

r43539 | tarui | 2013-11-05 20:15:21 +0900 (Tue, 05 Nov 2013) | 3 lines

gc.c (is_live_object): A hidden object may be a live object.
[ruby-dev:47788] [Bug #9072]

r43540 | akr | 2013-11-05 21:25:15 +0900 (Tue, 05 Nov 2013) | 4 lines

test/ruby/test_thread.rb (test_thread_join_in_trap):
Run the test in a different process.

r43541 | tenderlove | 2013-11-06 04:15:40 +0900 (Wed, 06 Nov 2013) | 4
lines

ext/psych/lib/psych/visitors/to_ruby.rb: process merge keys before
reviving objects. Fixes GH psych #168
test/psych/test_merge_keys.rb: test for change
Unable to load DateTime.new · Issue #168 · ruby/psych · GitHub

r43542 | svn | 2013-11-06 04:15:46 +0900 (Wed, 06 Nov 2013) | 1 line

2013-11-06

r43543 | ko1 | 2013-11-06 07:13:08 +0900 (Wed, 06 Nov 2013) | 3 lines

benchmark/gc/gcbench.rb: add some options to make quiet.

r43544 | ko1 | 2013-11-06 07:13:51 +0900 (Wed, 06 Nov 2013) | 3 lines

gc.c (Init_GC): add GC::OPTS to show options.

r43545 | eregon | 2013-11-06 07:27:27 +0900 (Wed, 06 Nov 2013) | 1 line

benchmark/gc/gcbench.rb: fix typo of r43543

r43546 | ko1 | 2013-11-06 09:14:26 +0900 (Wed, 06 Nov 2013) | 3 lines

gc.c: define RGENGC_ESTIMATE_OLDSPACE == 0 if USE_RGENGC is 0.

r43547 | ko1 | 2013-11-06 09:17:14 +0900 (Wed, 06 Nov 2013) | 12 lines

benchmark/bm_vm1_gc_short_lived.rb: added.
These GC benchmarks do not reflect practical applications.
They are only for tuning.
benchmark/bm_vm1_gc_short_with_complex_long.rb: added.
benchmark/bm_vm1_gc_short_with_long.rb: added.
benchmark/bm_vm1_gc_short_with_symbol.rb: added.
benchmark/bm_vm1_gc_wb_ary.rb: added.
benchmark/bm_vm1_gc_wb_obj.rb: added.
benchmark/bm_vm_thread_queue.rb: added.
Thie benchmark is added to know how fast C verion of thread.so.

r43548 | nobu | 2013-11-06 09:21:05 +0900 (Wed, 06 Nov 2013) | 1 line

properties.

r43549 | glass | 2013-11-06 10:39:55 +0900 (Wed, 06 Nov 2013) | 1 line

array.c (rb_ary_and): defer hash creation and some refactoring.

r43550 | glass | 2013-11-06 11:50:28 +0900 (Wed, 06 Nov 2013) | 2 lines

array.c (rb_ary_sample): use RARRAY_AREF() and RARRAY_PTR_USE()
instead of RARRAY_PTR().

r43551 | naruse | 2013-11-06 15:23:27 +0900 (Wed, 06 Nov 2013) | 1 line

Suppress Warnings: instance variable @installed_by_version not
initialized

r43552 | naruse | 2013-11-06 15:23:29 +0900 (Wed, 06 Nov 2013) | 1 line

Suppress warnings: File.exists? is a deprecated name

r43553 | naruse | 2013-11-06 15:25:18 +0900 (Wed, 06 Nov 2013) | 1 line

Suppress warnings: ambiguous first argument; put parentheses or even
spaces

r43554 | duerst | 2013-11-06 16:32:56 +0900 (Wed, 06 Nov 2013) | 1 line

lib/open3.rb: tweaked grammar in comments

r43555 | tarui | 2013-11-06 19:32:40 +0900 (Wed, 06 Nov 2013) | 2 lines

common.mk (help): add texts about gcbench.

r43556 | glass | 2013-11-06 21:09:31 +0900 (Wed, 06 Nov 2013) | 1 line

array.c (rb_ary_reverse): use RARRAY_PTR_USE().

r43557 | glass | 2013-11-06 21:20:39 +0900 (Wed, 06 Nov 2013) | 2 lines

array.c (rb_ary_shift_m): use RARRAY_PTR_USE() without WB because
there are not new relations.

r43558 | tarui | 2013-11-06 21:36:34 +0900 (Wed, 06 Nov 2013) | 12 lines

gc.c (gc_before_sweep): Change algorithm of malloc_limit to
conservative for closing to memory consumption of ruby 2.0.
gc.c (GC_MALLOC_LIMIT, GC_MALLOC_LIMIT_GROWTH_FACTOR):
Adjust parameters for new algorithm.

Example: make gcbench-rdoc on a pc
time maxrss
2.0.0p343 285.27 281853952
trunk before patch 207.19 690405376
trunk after patch 211.59 312500224

akr_SAkira_T.S · November 7, 2013, 3:23pm

Issue #9090 has been updated by akr (Akira T.).

File r43563-backtrace.txt added

mswin の CI だと backtrace がまともに出ていますね。

r43558
http://ruby-mswin.cloudapp.net/vc10-x64/ruby-trunk/log/20131106T191452Z.log.html.gz
r43560
http://ruby-mswin.cloudapp.net/vc10-x64/ruby-trunk/log/20131106T221741Z.log.html.gz
r43564
http://ruby-mswin.cloudapp.net/vc10-x64/ruby-trunk/log/20131107T101335Z.log.html.gz

あと、手元でも gdb の上で以下のように (くりかえしくりかえしくりかえし) 動かして
なんとか失敗させて、backtrace をとってみました。
(gdb) run -Ilib test/runner.rb -v test/rubygems test/rinda test/webrick
test/test_weakref.rb test/csv

r43563-backtrace.txt として添付しておきます。

Bug #9090: [BUG] object allocation during garbage collection phase

Author: akr (Akira T.)
Status: Open
Priority: Normal
Assignee:
Category:
Target version:
ruby -v: ruby 2.1.0dev (2013-11-06 trunk 43558) [x86_64-linux]
Backport: 1.9.3: UNKNOWN, 2.0.0: UNKNOWN

昨日の夜、r43558 で make check を 300回動かしてみたところ、
なんかずいぶんと [BUG] が出ました。

% ./ruby -v
ruby 2.1.0dev (2013-11-06 trunk 43558) [x86_64-linux]
% fgrep ‘[BUG]’ zd10/*/log
zd10/1/log:TestGem#test_looks_for_gemdeps_files_automatically_on_start =
/home/akr/tst1/ruby/lib/rinda/tuplespace.rb:325: [BUG] object allocation
during garbage collection phase
zd10/27/log:TestGem#test_gem_path_ordering =
/home/akr/tst1/ruby/lib/rinda/tuplespace.rb:325: [BUG] object allocation
during garbage collection phase
zd10/34/log:TestGemDependencyInstaller#test_install_version =
/home/akr/tst1/ruby/lib/rinda/tuplespace.rb:325: [BUG] object allocation
during garbage collection phase
zd10/45/log:TestGemSourceInstalled#test_spaceship =
/home/akr/tst1/ruby/lib/rubygems/package.rb:419: [BUG] rb_gc_mark():
0x002b969501c870 is T_ZOMBIE
zd10/51/log:TestWeakRef#test_weakref_finalize =
/home/akr/tst1/ruby/lib/rinda/tuplespace.rb:325: [BUG] object allocation
during garbage collection phase
zd10/52/log:TestGem#test_looks_for_gemdeps_files_automatically_on_start
= /home/akr/tst1/ruby/lib/rinda/tuplespace.rb:325: [BUG] object
allocation during garbage collection phase
zd10/56/log:TestGemInstaller#test_generate_bin_symlink_update_older =
/home/akr/tst1/ruby/lib/rinda/tuplespace.rb:325: [BUG] object allocation
during garbage collection phase
zd10/73/log:TestCSV::Features#test_gzip_writer_bug_fix =
/home/akr/tst1/ruby/lib/rinda/tuplespace.rb:325: [BUG] object allocation
during garbage collection phase
zd10/74/log:TestGemDependencyInstaller#test_install_minimal_deps =
/home/akr/tst1/ruby/lib/rinda/tuplespace.rb:325: [BUG] object allocation
during garbage collection phase
zd10/88/log:TestGemDependencyInstaller#test_install_dependency_old =
/home/akr/tst1/ruby/lib/rinda/tuplespace.rb:325: [BUG] object allocation
during garbage collection phase
zd10/99/log:TestGemCommandsInstallCommand#test_execute_prerelease_skipped_when_non_pre_available
= /home/akr/tst1/ruby/lib/rinda/tuplespace.rb:325: [BUG] object
allocation during garbage collection phase
zd10/102/log:TestGemUninstaller#test_uninstall_doesnt_prompt_when_other_gem_satifies_requirement
= /home/akr/tst1/ruby/lib/rinda/tuplespace.rb:325: [BUG] object
allocation during garbage collection phase
zd10/104/log:TestWeakRef#test_weakref_finalize =
/home/akr/tst1/ruby/lib/webrick/utils.rb:165: [BUG] object allocation
during garbage collection phase
zd10/120/log:TestGemSpecFetcher#test_available_specs_prerelease =
/home/akr/tst1/ruby/lib/rinda/tuplespace.rb:325: [BUG] object allocation
during garbage collection phase
zd10/127/log:TestGemDependencyInstaller#test_install_dependency_development_shallow
= /home/akr/tst1/ruby/lib/rinda/tuplespace.rb:325: [BUG] object
allocation during garbage collection phase
zd10/132/log:TestGemSourceSpecificFile#test_spec =
/home/akr/tst1/ruby/lib/rinda/tuplespace.rb:325: [BUG] object allocation
during garbage collection phase
zd10/157/log:TestGemUninstaller#test_remove_executables_user_format =
/home/akr/tst1/ruby/lib/rinda/tuplespace.rb:325: [BUG] object allocation
during garbage collection phase
zd10/172/log:TestGemSourceLocal#test_find_gem_prerelease =
/home/akr/tst1/ruby/lib/webrick/utils.rb:165: [BUG] Segmentation fault
zd10/173/log:TestGem#test_looks_for_gemdeps_files_automatically_on_start
= /home/akr/tst1/ruby/lib/rinda/tuplespace.rb:325: [BUG] object
allocation during garbage collection phase
zd10/193/log:TestGemSourceLocal#test_find_gem_prerelease =
/home/akr/tst1/ruby/lib/rinda/tuplespace.rb:325: [BUG] object allocation
during garbage collection phase
zd10/195/log:TestGem#test_looks_for_gemdeps_files_automatically_on_start
= /home/akr/tst1/ruby/lib/rinda/tuplespace.rb:325: [BUG] object
allocation during garbage collection phase
zd10/196/log:TestGemUninstaller#test_remove_executables_user =
/home/akr/tst1/ruby/lib/rinda/tuplespace.rb:325: [BUG] object allocation
during garbage collection phase
zd10/197/log:TestGemUninstaller#test_uninstall_prompt_includes_dep_type
= /home/akr/tst1/ruby/lib/rinda/tuplespace.rb:325: [BUG] object
allocation during garbage collection phase
zd10/215/log:TestWeakRef#test_weakref_finalize =
/home/akr/tst1/ruby/lib/rinda/tuplespace.rb:325: [BUG] object allocation
during garbage collection phase
zd10/216/log:TestGem#test_looks_for_gemdeps_files_automatically_on_start
= /home/akr/tst1/ruby/lib/rinda/tuplespace.rb:325: [BUG] object
allocation during garbage collection phase
zd10/217/log:TestGemDependencyInstaller#test_install_dependency_development_deep
= /home/akr/tst1/ruby/lib/rinda/tuplespace.rb:325: [BUG] object
allocation during garbage collection phase
zd10/227/log:TestGemCommandsCleanupCommand#test_handle_options_dry_run =
/home/akr/tst1/ruby/lib/rinda/tuplespace.rb:325: [BUG] object allocation
during garbage collection phase
zd10/234/log:TestGemInstaller#test_install_extension_flat =
/home/akr/tst1/ruby/lib/rinda/tuplespace.rb:325: [BUG] object allocation
during garbage collection phase
zd10/239/log:TestGemUninstaller#test_uninstall_only_lists_unsatified_deps
= /home/akr/tst1/ruby/lib/rinda/tuplespace.rb:325: [BUG] object
allocation during garbage collection phase
zd10/246/log:TestGemDependencyInstaller#test_install_install_dir =
/home/akr/tst1/ruby/lib/rinda/tuplespace.rb:325: [BUG] object allocation
during garbage collection phase
zd10/255/log:TestWeakRef#test_weakref_finalize =
/home/akr/tst1/ruby/lib/rinda/tuplespace.rb:325: [BUG] object allocation
during garbage collection phase
zd10/270/log:TestGemDependencyInstaller#test_install_dependencies_satisfied
= /home/akr/tst1/ruby/lib/rinda/tuplespace.rb:325: [BUG] object
allocation during garbage collection phase
zd10/288/log:TestWeakRef#test_weakref_finalize =
/home/akr/tst1/ruby/lib/rinda/tuplespace.rb:325: [BUG] object allocation
during garbage collection phase
zd10/291/log:TestWeakRef#test_weakref_finalize =
/home/akr/tst1/ruby/lib/webrick/utils.rb:165: [BUG] object allocation
during garbage collection phase

一昨日の夜、r43539 でやったときは出なかったので、
r43539 から r43558 のあいだのどれかだとおもうのですが、
心当たりのある方はいませんか。

% svn log -r43539:43558

r43539 | tarui | 2013-11-05 20:15:21 +0900 (Tue, 05 Nov 2013) | 3 lines

gc.c (is_live_object): A hidden object may be a live object.
[ruby-dev:47788] [Bug #9072]

r43540 | akr | 2013-11-05 21:25:15 +0900 (Tue, 05 Nov 2013) | 4 lines

test/ruby/test_thread.rb (test_thread_join_in_trap):
Run the test in a different process.

r43541 | tenderlove | 2013-11-06 04:15:40 +0900 (Wed, 06 Nov 2013) | 4
lines

ext/psych/lib/psych/visitors/to_ruby.rb: process merge keys before
reviving objects. Fixes GH psych #168
test/psych/test_merge_keys.rb: test for change
Unable to load DateTime.new · Issue #168 · ruby/psych · GitHub

r43542 | svn | 2013-11-06 04:15:46 +0900 (Wed, 06 Nov 2013) | 1 line

2013-11-06

r43543 | ko1 | 2013-11-06 07:13:08 +0900 (Wed, 06 Nov 2013) | 3 lines

benchmark/gc/gcbench.rb: add some options to make quiet.

r43544 | ko1 | 2013-11-06 07:13:51 +0900 (Wed, 06 Nov 2013) | 3 lines

gc.c (Init_GC): add GC::OPTS to show options.

r43545 | eregon | 2013-11-06 07:27:27 +0900 (Wed, 06 Nov 2013) | 1 line

benchmark/gc/gcbench.rb: fix typo of r43543

r43546 | ko1 | 2013-11-06 09:14:26 +0900 (Wed, 06 Nov 2013) | 3 lines

gc.c: define RGENGC_ESTIMATE_OLDSPACE == 0 if USE_RGENGC is 0.

r43547 | ko1 | 2013-11-06 09:17:14 +0900 (Wed, 06 Nov 2013) | 12 lines

benchmark/bm_vm1_gc_short_lived.rb: added.
These GC benchmarks do not reflect practical applications.
They are only for tuning.
benchmark/bm_vm1_gc_short_with_complex_long.rb: added.
benchmark/bm_vm1_gc_short_with_long.rb: added.
benchmark/bm_vm1_gc_short_with_symbol.rb: added.
benchmark/bm_vm1_gc_wb_ary.rb: added.
benchmark/bm_vm1_gc_wb_obj.rb: added.
benchmark/bm_vm_thread_queue.rb: added.
Thie benchmark is added to know how fast C verion of thread.so.

r43548 | nobu | 2013-11-06 09:21:05 +0900 (Wed, 06 Nov 2013) | 1 line

properties.

r43549 | glass | 2013-11-06 10:39:55 +0900 (Wed, 06 Nov 2013) | 1 line

array.c (rb_ary_and): defer hash creation and some refactoring.

r43550 | glass | 2013-11-06 11:50:28 +0900 (Wed, 06 Nov 2013) | 2 lines

array.c (rb_ary_sample): use RARRAY_AREF() and RARRAY_PTR_USE()
instead of RARRAY_PTR().

r43551 | naruse | 2013-11-06 15:23:27 +0900 (Wed, 06 Nov 2013) | 1 line

Suppress Warnings: instance variable @installed_by_version not
initialized

r43552 | naruse | 2013-11-06 15:23:29 +0900 (Wed, 06 Nov 2013) | 1 line

Suppress warnings: File.exists? is a deprecated name

r43553 | naruse | 2013-11-06 15:25:18 +0900 (Wed, 06 Nov 2013) | 1 line

Suppress warnings: ambiguous first argument; put parentheses or even
spaces

r43554 | duerst | 2013-11-06 16:32:56 +0900 (Wed, 06 Nov 2013) | 1 line

lib/open3.rb: tweaked grammar in comments

r43555 | tarui | 2013-11-06 19:32:40 +0900 (Wed, 06 Nov 2013) | 2 lines

common.mk (help): add texts about gcbench.

r43556 | glass | 2013-11-06 21:09:31 +0900 (Wed, 06 Nov 2013) | 1 line

array.c (rb_ary_reverse): use RARRAY_PTR_USE().

r43557 | glass | 2013-11-06 21:20:39 +0900 (Wed, 06 Nov 2013) | 2 lines

array.c (rb_ary_shift_m): use RARRAY_PTR_USE() without WB because
there are not new relations.

r43558 | tarui | 2013-11-06 21:36:34 +0900 (Wed, 06 Nov 2013) | 12 lines

gc.c (gc_before_sweep): Change algorithm of malloc_limit to
conservative for closing to memory consumption of ruby 2.0.
gc.c (GC_MALLOC_LIMIT, GC_MALLOC_LIMIT_GROWTH_FACTOR):
Adjust parameters for new algorithm.

Example: make gcbench-rdoc on a pc
time maxrss
2.0.0p343 285.27 281853952
trunk before patch 207.19 690405376
trunk after patch 211.59 312500224

akr_SAkira_T.S · November 8, 2013, 4:13am

Issue #9090 has been updated by akr (Akira T.).

r43577 で 100回ほど make check してみましたがこの問題は発生しませんでした。
ありがとうございます。

Bug #9090: [BUG] object allocation during garbage collection phase

Author: akr (Akira T.)
Status: Closed
Priority: Normal
Assignee: ko1 (Koichi Sasada)
Category:
Target version:
ruby -v: ruby 2.1.0dev (2013-11-06 trunk 43558) [x86_64-linux]
Backport: 1.9.3: UNKNOWN, 2.0.0: UNKNOWN

昨日の夜、r43558 で make check を 300回動かしてみたところ、
なんかずいぶんと [BUG] が出ました。

% ./ruby -v
ruby 2.1.0dev (2013-11-06 trunk 43558) [x86_64-linux]
% fgrep ‘[BUG]’ zd10/*/log
zd10/1/log:TestGem#test_looks_for_gemdeps_files_automatically_on_start =
/home/akr/tst1/ruby/lib/rinda/tuplespace.rb:325: [BUG] object allocation
during garbage collection phase
zd10/27/log:TestGem#test_gem_path_ordering =
/home/akr/tst1/ruby/lib/rinda/tuplespace.rb:325: [BUG] object allocation
during garbage collection phase
zd10/34/log:TestGemDependencyInstaller#test_install_version =
/home/akr/tst1/ruby/lib/rinda/tuplespace.rb:325: [BUG] object allocation
during garbage collection phase
zd10/45/log:TestGemSourceInstalled#test_spaceship =
/home/akr/tst1/ruby/lib/rubygems/package.rb:419: [BUG] rb_gc_mark():
0x002b969501c870 is T_ZOMBIE
zd10/51/log:TestWeakRef#test_weakref_finalize =
/home/akr/tst1/ruby/lib/rinda/tuplespace.rb:325: [BUG] object allocation
during garbage collection phase
zd10/52/log:TestGem#test_looks_for_gemdeps_files_automatically_on_start
= /home/akr/tst1/ruby/lib/rinda/tuplespace.rb:325: [BUG] object
allocation during garbage collection phase
zd10/56/log:TestGemInstaller#test_generate_bin_symlink_update_older =
/home/akr/tst1/ruby/lib/rinda/tuplespace.rb:325: [BUG] object allocation
during garbage collection phase
zd10/73/log:TestCSV::Features#test_gzip_writer_bug_fix =
/home/akr/tst1/ruby/lib/rinda/tuplespace.rb:325: [BUG] object allocation
during garbage collection phase
zd10/74/log:TestGemDependencyInstaller#test_install_minimal_deps =
/home/akr/tst1/ruby/lib/rinda/tuplespace.rb:325: [BUG] object allocation
during garbage collection phase
zd10/88/log:TestGemDependencyInstaller#test_install_dependency_old =
/home/akr/tst1/ruby/lib/rinda/tuplespace.rb:325: [BUG] object allocation
during garbage collection phase
zd10/99/log:TestGemCommandsInstallCommand#test_execute_prerelease_skipped_when_non_pre_available
= /home/akr/tst1/ruby/lib/rinda/tuplespace.rb:325: [BUG] object
allocation during garbage collection phase
zd10/102/log:TestGemUninstaller#test_uninstall_doesnt_prompt_when_other_gem_satifies_requirement
= /home/akr/tst1/ruby/lib/rinda/tuplespace.rb:325: [BUG] object
allocation during garbage collection phase
zd10/104/log:TestWeakRef#test_weakref_finalize =
/home/akr/tst1/ruby/lib/webrick/utils.rb:165: [BUG] object allocation
during garbage collection phase
zd10/120/log:TestGemSpecFetcher#test_available_specs_prerelease =
/home/akr/tst1/ruby/lib/rinda/tuplespace.rb:325: [BUG] object allocation
during garbage collection phase
zd10/127/log:TestGemDependencyInstaller#test_install_dependency_development_shallow
= /home/akr/tst1/ruby/lib/rinda/tuplespace.rb:325: [BUG] object
allocation during garbage collection phase
zd10/132/log:TestGemSourceSpecificFile#test_spec =
/home/akr/tst1/ruby/lib/rinda/tuplespace.rb:325: [BUG] object allocation
during garbage collection phase
zd10/157/log:TestGemUninstaller#test_remove_executables_user_format =
/home/akr/tst1/ruby/lib/rinda/tuplespace.rb:325: [BUG] object allocation
during garbage collection phase
zd10/172/log:TestGemSourceLocal#test_find_gem_prerelease =
/home/akr/tst1/ruby/lib/webrick/utils.rb:165: [BUG] Segmentation fault
zd10/173/log:TestGem#test_looks_for_gemdeps_files_automatically_on_start
= /home/akr/tst1/ruby/lib/rinda/tuplespace.rb:325: [BUG] object
allocation during garbage collection phase
zd10/193/log:TestGemSourceLocal#test_find_gem_prerelease =
/home/akr/tst1/ruby/lib/rinda/tuplespace.rb:325: [BUG] object allocation
during garbage collection phase
zd10/195/log:TestGem#test_looks_for_gemdeps_files_automatically_on_start
= /home/akr/tst1/ruby/lib/rinda/tuplespace.rb:325: [BUG] object
allocation during garbage collection phase
zd10/196/log:TestGemUninstaller#test_remove_executables_user =
/home/akr/tst1/ruby/lib/rinda/tuplespace.rb:325: [BUG] object allocation
during garbage collection phase
zd10/197/log:TestGemUninstaller#test_uninstall_prompt_includes_dep_type
= /home/akr/tst1/ruby/lib/rinda/tuplespace.rb:325: [BUG] object
allocation during garbage collection phase
zd10/215/log:TestWeakRef#test_weakref_finalize =
/home/akr/tst1/ruby/lib/rinda/tuplespace.rb:325: [BUG] object allocation
during garbage collection phase
zd10/216/log:TestGem#test_looks_for_gemdeps_files_automatically_on_start
= /home/akr/tst1/ruby/lib/rinda/tuplespace.rb:325: [BUG] object
allocation during garbage collection phase
zd10/217/log:TestGemDependencyInstaller#test_install_dependency_development_deep
= /home/akr/tst1/ruby/lib/rinda/tuplespace.rb:325: [BUG] object
allocation during garbage collection phase
zd10/227/log:TestGemCommandsCleanupCommand#test_handle_options_dry_run =
/home/akr/tst1/ruby/lib/rinda/tuplespace.rb:325: [BUG] object allocation
during garbage collection phase
zd10/234/log:TestGemInstaller#test_install_extension_flat =
/home/akr/tst1/ruby/lib/rinda/tuplespace.rb:325: [BUG] object allocation
during garbage collection phase
zd10/239/log:TestGemUninstaller#test_uninstall_only_lists_unsatified_deps
= /home/akr/tst1/ruby/lib/rinda/tuplespace.rb:325: [BUG] object
allocation during garbage collection phase
zd10/246/log:TestGemDependencyInstaller#test_install_install_dir =
/home/akr/tst1/ruby/lib/rinda/tuplespace.rb:325: [BUG] object allocation
during garbage collection phase
zd10/255/log:TestWeakRef#test_weakref_finalize =
/home/akr/tst1/ruby/lib/rinda/tuplespace.rb:325: [BUG] object allocation
during garbage collection phase
zd10/270/log:TestGemDependencyInstaller#test_install_dependencies_satisfied
= /home/akr/tst1/ruby/lib/rinda/tuplespace.rb:325: [BUG] object
allocation during garbage collection phase
zd10/288/log:TestWeakRef#test_weakref_finalize =
/home/akr/tst1/ruby/lib/rinda/tuplespace.rb:325: [BUG] object allocation
during garbage collection phase
zd10/291/log:TestWeakRef#test_weakref_finalize =
/home/akr/tst1/ruby/lib/webrick/utils.rb:165: [BUG] object allocation
during garbage collection phase

一昨日の夜、r43539 でやったときは出なかったので、
r43539 から r43558 のあいだのどれかだとおもうのですが、
心当たりのある方はいませんか。

% svn log -r43539:43558

r43539 | tarui | 2013-11-05 20:15:21 +0900 (Tue, 05 Nov 2013) | 3 lines

gc.c (is_live_object): A hidden object may be a live object.
[ruby-dev:47788] [Bug #9072]

r43540 | akr | 2013-11-05 21:25:15 +0900 (Tue, 05 Nov 2013) | 4 lines

test/ruby/test_thread.rb (test_thread_join_in_trap):
Run the test in a different process.

r43541 | tenderlove | 2013-11-06 04:15:40 +0900 (Wed, 06 Nov 2013) | 4
lines

ext/psych/lib/psych/visitors/to_ruby.rb: process merge keys before
reviving objects. Fixes GH psych #168
test/psych/test_merge_keys.rb: test for change
Unable to load DateTime.new · Issue #168 · ruby/psych · GitHub

r43542 | svn | 2013-11-06 04:15:46 +0900 (Wed, 06 Nov 2013) | 1 line

2013-11-06

r43543 | ko1 | 2013-11-06 07:13:08 +0900 (Wed, 06 Nov 2013) | 3 lines

benchmark/gc/gcbench.rb: add some options to make quiet.

r43544 | ko1 | 2013-11-06 07:13:51 +0900 (Wed, 06 Nov 2013) | 3 lines

gc.c (Init_GC): add GC::OPTS to show options.

r43545 | eregon | 2013-11-06 07:27:27 +0900 (Wed, 06 Nov 2013) | 1 line

benchmark/gc/gcbench.rb: fix typo of r43543

r43546 | ko1 | 2013-11-06 09:14:26 +0900 (Wed, 06 Nov 2013) | 3 lines

gc.c: define RGENGC_ESTIMATE_OLDSPACE == 0 if USE_RGENGC is 0.

r43547 | ko1 | 2013-11-06 09:17:14 +0900 (Wed, 06 Nov 2013) | 12 lines

benchmark/bm_vm1_gc_short_lived.rb: added.
These GC benchmarks do not reflect practical applications.
They are only for tuning.
benchmark/bm_vm1_gc_short_with_complex_long.rb: added.
benchmark/bm_vm1_gc_short_with_long.rb: added.
benchmark/bm_vm1_gc_short_with_symbol.rb: added.
benchmark/bm_vm1_gc_wb_ary.rb: added.
benchmark/bm_vm1_gc_wb_obj.rb: added.
benchmark/bm_vm_thread_queue.rb: added.
Thie benchmark is added to know how fast C verion of thread.so.

r43548 | nobu | 2013-11-06 09:21:05 +0900 (Wed, 06 Nov 2013) | 1 line

properties.

r43549 | glass | 2013-11-06 10:39:55 +0900 (Wed, 06 Nov 2013) | 1 line

array.c (rb_ary_and): defer hash creation and some refactoring.

r43550 | glass | 2013-11-06 11:50:28 +0900 (Wed, 06 Nov 2013) | 2 lines

array.c (rb_ary_sample): use RARRAY_AREF() and RARRAY_PTR_USE()
instead of RARRAY_PTR().

r43551 | naruse | 2013-11-06 15:23:27 +0900 (Wed, 06 Nov 2013) | 1 line

Suppress Warnings: instance variable @installed_by_version not
initialized

r43552 | naruse | 2013-11-06 15:23:29 +0900 (Wed, 06 Nov 2013) | 1 line

Suppress warnings: File.exists? is a deprecated name

r43553 | naruse | 2013-11-06 15:25:18 +0900 (Wed, 06 Nov 2013) | 1 line

Suppress warnings: ambiguous first argument; put parentheses or even
spaces

r43554 | duerst | 2013-11-06 16:32:56 +0900 (Wed, 06 Nov 2013) | 1 line

lib/open3.rb: tweaked grammar in comments

r43555 | tarui | 2013-11-06 19:32:40 +0900 (Wed, 06 Nov 2013) | 2 lines

common.mk (help): add texts about gcbench.

r43556 | glass | 2013-11-06 21:09:31 +0900 (Wed, 06 Nov 2013) | 1 line

array.c (rb_ary_reverse): use RARRAY_PTR_USE().

r43557 | glass | 2013-11-06 21:20:39 +0900 (Wed, 06 Nov 2013) | 2 lines

array.c (rb_ary_shift_m): use RARRAY_PTR_USE() without WB because
there are not new relations.

r43558 | tarui | 2013-11-06 21:36:34 +0900 (Wed, 06 Nov 2013) | 12 lines

gc.c (gc_before_sweep): Change algorithm of malloc_limit to
conservative for closing to memory consumption of ruby 2.0.
gc.c (GC_MALLOC_LIMIT, GC_MALLOC_LIMIT_GROWTH_FACTOR):
Adjust parameters for new algorithm.

Example: make gcbench-rdoc on a pc
time maxrss
2.0.0p343 285.27 281853952
trunk before patch 207.19 690405376
trunk after patch 211.59 312500224

akr_SAkira_T.S · November 7, 2013, 6:25pm

Issue #9090 has been updated by tarui (Masaya T.).

Assignee set to ko1 (Koichi Sasada)

=begin
手元で再現させた結果GVL無しでsweepしてる部分がみつかりました。
ここはささださんの部分らしいので担当を設定しておきます。
#これを修正しても他の部分でエラーならその時にreopenと言う事で。

(gdb) thread 1
[Switching to thread 1 (Thread 0x7ffff7fe3740 (LWP 17027))]
#0 0x0000000000435cfa in gc_page_sweep (sweep_page=0x953440,
heap=0x6b7a00, objspace=) at …/gc.c:2674
2674 if ((bitset & 1) && BUILTIN_TYPE(p) !=
T_ZOMBIE) {
(gdb) bt
#0 0x0000000000435cfa in gc_page_sweep (sweep_page=0x953440,
heap=0x6b7a00, objspace=) at …/gc.c:2674
#1 gc_heap_lazy_sweep (heap=0x6b7a00, objspace=0x6b79e0) at
…/gc.c:2930
#2 gc_heap_rest_sweep (heap=0x6b7a00, objspace=0x6b79e0) at
…/gc.c:2955
#3 gc_rest_sweep (objspace=0x6b79e0) at …/gc.c:2965
#4 vm_malloc_increase (objspace=objspace@entry=0x6b79e0,
do_gc=, old_size=, new_size=) at …/gc.c:5451
#5 0x0000000000437ee2 in vm_malloc_increase (do_gc=,
old_size=, new_size=, objspace=) at …/gc.c:5444
#6 vm_malloc_prepare (size=, objspace=0x6b79e0) at
…/gc.c:5472
#7 vm_xmalloc (objspace=0x6b79e0, size=size@entry=32768) at
…/gc.c:5503
=end

Bug #9090: [BUG] object allocation during garbage collection phase

Author: akr (Akira T.)
Status: Open
Priority: Normal
Assignee: ko1 (Koichi Sasada)
Category:
Target version:
ruby -v: ruby 2.1.0dev (2013-11-06 trunk 43558) [x86_64-linux]
Backport: 1.9.3: UNKNOWN, 2.0.0: UNKNOWN

昨日の夜、r43558 で make check を 300回動かしてみたところ、
なんかずいぶんと [BUG] が出ました。

% ./ruby -v
ruby 2.1.0dev (2013-11-06 trunk 43558) [x86_64-linux]
% fgrep ‘[BUG]’ zd10/*/log
zd10/1/log:TestGem#test_looks_for_gemdeps_files_automatically_on_start =
/home/akr/tst1/ruby/lib/rinda/tuplespace.rb:325: [BUG] object allocation
during garbage collection phase
zd10/27/log:TestGem#test_gem_path_ordering =
/home/akr/tst1/ruby/lib/rinda/tuplespace.rb:325: [BUG] object allocation
during garbage collection phase
zd10/34/log:TestGemDependencyInstaller#test_install_version =
/home/akr/tst1/ruby/lib/rinda/tuplespace.rb:325: [BUG] object allocation
during garbage collection phase
zd10/45/log:TestGemSourceInstalled#test_spaceship =
/home/akr/tst1/ruby/lib/rubygems/package.rb:419: [BUG] rb_gc_mark():
0x002b969501c870 is T_ZOMBIE
zd10/51/log:TestWeakRef#test_weakref_finalize =
/home/akr/tst1/ruby/lib/rinda/tuplespace.rb:325: [BUG] object allocation
during garbage collection phase
zd10/52/log:TestGem#test_looks_for_gemdeps_files_automatically_on_start
= /home/akr/tst1/ruby/lib/rinda/tuplespace.rb:325: [BUG] object
allocation during garbage collection phase
zd10/56/log:TestGemInstaller#test_generate_bin_symlink_update_older =
/home/akr/tst1/ruby/lib/rinda/tuplespace.rb:325: [BUG] object allocation
during garbage collection phase
zd10/73/log:TestCSV::Features#test_gzip_writer_bug_fix =
/home/akr/tst1/ruby/lib/rinda/tuplespace.rb:325: [BUG] object allocation
during garbage collection phase
zd10/74/log:TestGemDependencyInstaller#test_install_minimal_deps =
/home/akr/tst1/ruby/lib/rinda/tuplespace.rb:325: [BUG] object allocation
during garbage collection phase
zd10/88/log:TestGemDependencyInstaller#test_install_dependency_old =
/home/akr/tst1/ruby/lib/rinda/tuplespace.rb:325: [BUG] object allocation
during garbage collection phase
zd10/99/log:TestGemCommandsInstallCommand#test_execute_prerelease_skipped_when_non_pre_available
= /home/akr/tst1/ruby/lib/rinda/tuplespace.rb:325: [BUG] object
allocation during garbage collection phase
zd10/102/log:TestGemUninstaller#test_uninstall_doesnt_prompt_when_other_gem_satifies_requirement
= /home/akr/tst1/ruby/lib/rinda/tuplespace.rb:325: [BUG] object
allocation during garbage collection phase
zd10/104/log:TestWeakRef#test_weakref_finalize =
/home/akr/tst1/ruby/lib/webrick/utils.rb:165: [BUG] object allocation
during garbage collection phase
zd10/120/log:TestGemSpecFetcher#test_available_specs_prerelease =
/home/akr/tst1/ruby/lib/rinda/tuplespace.rb:325: [BUG] object allocation
during garbage collection phase
zd10/127/log:TestGemDependencyInstaller#test_install_dependency_development_shallow
= /home/akr/tst1/ruby/lib/rinda/tuplespace.rb:325: [BUG] object
allocation during garbage collection phase
zd10/132/log:TestGemSourceSpecificFile#test_spec =
/home/akr/tst1/ruby/lib/rinda/tuplespace.rb:325: [BUG] object allocation
during garbage collection phase
zd10/157/log:TestGemUninstaller#test_remove_executables_user_format =
/home/akr/tst1/ruby/lib/rinda/tuplespace.rb:325: [BUG] object allocation
during garbage collection phase
zd10/172/log:TestGemSourceLocal#test_find_gem_prerelease =
/home/akr/tst1/ruby/lib/webrick/utils.rb:165: [BUG] Segmentation fault
zd10/173/log:TestGem#test_looks_for_gemdeps_files_automatically_on_start
= /home/akr/tst1/ruby/lib/rinda/tuplespace.rb:325: [BUG] object
allocation during garbage collection phase
zd10/193/log:TestGemSourceLocal#test_find_gem_prerelease =
/home/akr/tst1/ruby/lib/rinda/tuplespace.rb:325: [BUG] object allocation
during garbage collection phase
zd10/195/log:TestGem#test_looks_for_gemdeps_files_automatically_on_start
= /home/akr/tst1/ruby/lib/rinda/tuplespace.rb:325: [BUG] object
allocation during garbage collection phase
zd10/196/log:TestGemUninstaller#test_remove_executables_user =
/home/akr/tst1/ruby/lib/rinda/tuplespace.rb:325: [BUG] object allocation
during garbage collection phase
zd10/197/log:TestGemUninstaller#test_uninstall_prompt_includes_dep_type
= /home/akr/tst1/ruby/lib/rinda/tuplespace.rb:325: [BUG] object
allocation during garbage collection phase
zd10/215/log:TestWeakRef#test_weakref_finalize =
/home/akr/tst1/ruby/lib/rinda/tuplespace.rb:325: [BUG] object allocation
during garbage collection phase
zd10/216/log:TestGem#test_looks_for_gemdeps_files_automatically_on_start
= /home/akr/tst1/ruby/lib/rinda/tuplespace.rb:325: [BUG] object
allocation during garbage collection phase
zd10/217/log:TestGemDependencyInstaller#test_install_dependency_development_deep
= /home/akr/tst1/ruby/lib/rinda/tuplespace.rb:325: [BUG] object
allocation during garbage collection phase
zd10/227/log:TestGemCommandsCleanupCommand#test_handle_options_dry_run =
/home/akr/tst1/ruby/lib/rinda/tuplespace.rb:325: [BUG] object allocation
during garbage collection phase
zd10/234/log:TestGemInstaller#test_install_extension_flat =
/home/akr/tst1/ruby/lib/rinda/tuplespace.rb:325: [BUG] object allocation
during garbage collection phase
zd10/239/log:TestGemUninstaller#test_uninstall_only_lists_unsatified_deps
= /home/akr/tst1/ruby/lib/rinda/tuplespace.rb:325: [BUG] object
allocation during garbage collection phase
zd10/246/log:TestGemDependencyInstaller#test_install_install_dir =
/home/akr/tst1/ruby/lib/rinda/tuplespace.rb:325: [BUG] object allocation
during garbage collection phase
zd10/255/log:TestWeakRef#test_weakref_finalize =
/home/akr/tst1/ruby/lib/rinda/tuplespace.rb:325: [BUG] object allocation
during garbage collection phase
zd10/270/log:TestGemDependencyInstaller#test_install_dependencies_satisfied
= /home/akr/tst1/ruby/lib/rinda/tuplespace.rb:325: [BUG] object
allocation during garbage collection phase
zd10/288/log:TestWeakRef#test_weakref_finalize =
/home/akr/tst1/ruby/lib/rinda/tuplespace.rb:325: [BUG] object allocation
during garbage collection phase
zd10/291/log:TestWeakRef#test_weakref_finalize =
/home/akr/tst1/ruby/lib/webrick/utils.rb:165: [BUG] object allocation
during garbage collection phase

一昨日の夜、r43539 でやったときは出なかったので、
r43539 から r43558 のあいだのどれかだとおもうのですが、
心当たりのある方はいませんか。

% svn log -r43539:43558

r43539 | tarui | 2013-11-05 20:15:21 +0900 (Tue, 05 Nov 2013) | 3 lines

gc.c (is_live_object): A hidden object may be a live object.
[ruby-dev:47788] [Bug #9072]

r43540 | akr | 2013-11-05 21:25:15 +0900 (Tue, 05 Nov 2013) | 4 lines

test/ruby/test_thread.rb (test_thread_join_in_trap):
Run the test in a different process.

r43541 | tenderlove | 2013-11-06 04:15:40 +0900 (Wed, 06 Nov 2013) | 4
lines

ext/psych/lib/psych/visitors/to_ruby.rb: process merge keys before
reviving objects. Fixes GH psych #168
test/psych/test_merge_keys.rb: test for change
Unable to load DateTime.new · Issue #168 · ruby/psych · GitHub

r43542 | svn | 2013-11-06 04:15:46 +0900 (Wed, 06 Nov 2013) | 1 line

2013-11-06

r43543 | ko1 | 2013-11-06 07:13:08 +0900 (Wed, 06 Nov 2013) | 3 lines

benchmark/gc/gcbench.rb: add some options to make quiet.

r43544 | ko1 | 2013-11-06 07:13:51 +0900 (Wed, 06 Nov 2013) | 3 lines

gc.c (Init_GC): add GC::OPTS to show options.

r43545 | eregon | 2013-11-06 07:27:27 +0900 (Wed, 06 Nov 2013) | 1 line

benchmark/gc/gcbench.rb: fix typo of r43543

r43546 | ko1 | 2013-11-06 09:14:26 +0900 (Wed, 06 Nov 2013) | 3 lines

gc.c: define RGENGC_ESTIMATE_OLDSPACE == 0 if USE_RGENGC is 0.

r43547 | ko1 | 2013-11-06 09:17:14 +0900 (Wed, 06 Nov 2013) | 12 lines

benchmark/bm_vm1_gc_short_lived.rb: added.
These GC benchmarks do not reflect practical applications.
They are only for tuning.
benchmark/bm_vm1_gc_short_with_complex_long.rb: added.
benchmark/bm_vm1_gc_short_with_long.rb: added.
benchmark/bm_vm1_gc_short_with_symbol.rb: added.
benchmark/bm_vm1_gc_wb_ary.rb: added.
benchmark/bm_vm1_gc_wb_obj.rb: added.
benchmark/bm_vm_thread_queue.rb: added.
Thie benchmark is added to know how fast C verion of thread.so.

r43548 | nobu | 2013-11-06 09:21:05 +0900 (Wed, 06 Nov 2013) | 1 line

properties.

r43549 | glass | 2013-11-06 10:39:55 +0900 (Wed, 06 Nov 2013) | 1 line

array.c (rb_ary_and): defer hash creation and some refactoring.

r43550 | glass | 2013-11-06 11:50:28 +0900 (Wed, 06 Nov 2013) | 2 lines

array.c (rb_ary_sample): use RARRAY_AREF() and RARRAY_PTR_USE()
instead of RARRAY_PTR().

r43551 | naruse | 2013-11-06 15:23:27 +0900 (Wed, 06 Nov 2013) | 1 line

Suppress Warnings: instance variable @installed_by_version not
initialized

r43552 | naruse | 2013-11-06 15:23:29 +0900 (Wed, 06 Nov 2013) | 1 line

Suppress warnings: File.exists? is a deprecated name

r43553 | naruse | 2013-11-06 15:25:18 +0900 (Wed, 06 Nov 2013) | 1 line

Suppress warnings: ambiguous first argument; put parentheses or even
spaces

r43554 | duerst | 2013-11-06 16:32:56 +0900 (Wed, 06 Nov 2013) | 1 line

lib/open3.rb: tweaked grammar in comments

r43555 | tarui | 2013-11-06 19:32:40 +0900 (Wed, 06 Nov 2013) | 2 lines

common.mk (help): add texts about gcbench.

r43556 | glass | 2013-11-06 21:09:31 +0900 (Wed, 06 Nov 2013) | 1 line

array.c (rb_ary_reverse): use RARRAY_PTR_USE().

r43557 | glass | 2013-11-06 21:20:39 +0900 (Wed, 06 Nov 2013) | 2 lines

array.c (rb_ary_shift_m): use RARRAY_PTR_USE() without WB because
there are not new relations.

r43558 | tarui | 2013-11-06 21:36:34 +0900 (Wed, 06 Nov 2013) | 12 lines

gc.c (gc_before_sweep): Change algorithm of malloc_limit to
conservative for closing to memory consumption of ruby 2.0.
gc.c (GC_MALLOC_LIMIT, GC_MALLOC_LIMIT_GROWTH_FACTOR):
Adjust parameters for new algorithm.

Example: make gcbench-rdoc on a pc
time maxrss
2.0.0p343 285.27 281853952
trunk before patch 207.19 690405376
trunk after patch 211.59 312500224

% svn log -r43539:43558

Suppress Warnings: instance variable @installed_by_version not initialized

Suppress warnings: File.exists? is a deprecated name

Suppress warnings: ambiguous first argument; put parentheses or even spaces

lib/open3.rb: tweaked grammar in comments

C-level stack traceにシンボル情報がほとんど載ってないので、objdump -S ruby の結果も何処かに上げていただけるとありがたいです。

% svn log -r43539:43558

Suppress Warnings: instance variable @installed_by_version not initialized

Suppress warnings: File.exists? is a deprecated name

Suppress warnings: ambiguous first argument; put parentheses or even spaces

lib/open3.rb: tweaked grammar in comments

r43558もGC起動のスレッシュルドを変えただけなので、 ここで発生となるとこれまで発生確率が低くて眠ってたバグを掘り起こしたって事に。 とりあえず見てみます。

% svn log -r43539:43558

Suppress Warnings: instance variable @installed_by_version not initialized

Suppress warnings: File.exists? is a deprecated name

Suppress warnings: ambiguous first argument; put parentheses or even spaces

lib/open3.rb: tweaked grammar in comments

% svn log -r43539:43540

% svn log -r43558

% svn log -r43539:43558

Suppress Warnings: instance variable @installed_by_version not initialized

Suppress warnings: File.exists? is a deprecated name

Suppress warnings: ambiguous first argument; put parentheses or even spaces

lib/open3.rb: tweaked grammar in comments

% svn log -r43539:43558

Suppress Warnings: instance variable @installed_by_version not initialized

Suppress warnings: File.exists? is a deprecated name

Suppress warnings: ambiguous first argument; put parentheses or even spaces

lib/open3.rb: tweaked grammar in comments

r43577 で 100回ほど make check してみましたがこの問題は発生しませんでした。 ありがとうございます。

% svn log -r43539:43558

Suppress Warnings: instance variable @installed_by_version not initialized

Suppress warnings: File.exists? is a deprecated name

Suppress warnings: ambiguous first argument; put parentheses or even spaces

lib/open3.rb: tweaked grammar in comments

% svn log -r43539:43558

Suppress Warnings: instance variable @installed_by_version not initialized

Suppress warnings: File.exists? is a deprecated name

Suppress warnings: ambiguous first argument; put parentheses or even spaces

lib/open3.rb: tweaked grammar in comments

Suppress Warnings: instance variable @installed_by_version not
initialized

Suppress warnings: ambiguous first argument; put parentheses or even
spaces

C-level stack traceにシンボル情報がほとんど載ってないので、objdump -S ruby
の結果も何処かに上げていただけるとありがたいです。

Suppress Warnings: instance variable @installed_by_version not
initialized

Suppress warnings: ambiguous first argument; put parentheses or even
spaces

r43558もGC起動のスレッシュルドを変えただけなので、
ここで発生となるとこれまで発生確率が低くて眠ってたバグを掘り起こしたって事に。
とりあえず見てみます。

Suppress Warnings: instance variable @installed_by_version not
initialized

Suppress warnings: ambiguous first argument; put parentheses or even
spaces

Suppress Warnings: instance variable @installed_by_version not
initialized

Suppress warnings: ambiguous first argument; put parentheses or even
spaces

Suppress Warnings: instance variable @installed_by_version not
initialized

Suppress warnings: ambiguous first argument; put parentheses or even
spaces

r43577 で 100回ほど make check してみましたがこの問題は発生しませんでした。
ありがとうございます。

Suppress Warnings: instance variable @installed_by_version not
initialized

Suppress warnings: ambiguous first argument; put parentheses or even
spaces

Suppress Warnings: instance variable @installed_by_version not
initialized

Suppress warnings: ambiguous first argument; put parentheses or even
spaces