Bug #10010: Error in TestEnv#test_memory_leak_* on Solaris

• Status: Closed
• Assignee: nobu (Nobuyoshi Nakada)
• Target version: 2.2.0
• ruby -v: ruby 2.2.0dev (2014-07-04) [sparc64-solaris2.10]
• Backport: 2.0.0: UNKNOWN, 2.1: UNKNOWN

[ngoto (Naohisa Goto)]

r46550 くらい以降、Solaris 10 にて make test-all 中、以下のエラーが発生します。
(r44686 にて確認)

test/envutil.rb の 438行目にて、:size や :rss 用の情報が、OS側の何らかの理由で示されず、その結果ハッシュにも格納されず、 a または b が nil になることがあるのに、それに対応していないのが原因と思います。

なお、Solaris では、/proc/self/status は struct pstatus_t の内容のバイナリを返しますが、それには全く対応していないので、nil になるか、偶然バイナリ値が何かに一致した場合にでたらめな値が返されるかのいずれかになります。

 53) Error:
TestEnv#test_memory_leak_shift:
NoMethodError: undefined method `>' for nil:NilClass
    /XXXXX/test/ruby/envutil.rb:438:in `block in assert_no_memory_leak'
    /XXXXX/test/ruby/envutil.rb:435:in `each'
    /XXXXX/test/ruby/envutil.rb:435:in `assert_no_memory_leak'
    /XXXXX/test/ruby/test_env.rb:543:in `test_memory_leak_shift'

 54) Error:
TestEnv#test_memory_leak_select:
NoMethodError: undefined method `>' for nil:NilClass
    /XXXXX/test/ruby/envutil.rb:438:in `block in assert_no_memory_leak'
    /XXXXX/test/ruby/envutil.rb:435:in `each'
    /XXXXX/test/ruby/envutil.rb:435:in `assert_no_memory_leak'
    /XXXXX/test/ruby/test_env.rb:525:in `test_memory_leak_select'

 55) Error:
TestEnv#test_memory_leak_aset:
NoMethodError: undefined method `>' for nil:NilClass
    /XXXXX/test/ruby/envutil.rb:438:in `block in assert_no_memory_leak'
    /XXXXX/test/ruby/envutil.rb:435:in `each'
    /XXXXX/test/ruby/envutil.rb:435:in `assert_no_memory_leak'
    /XXXXX/test/ruby/test_env.rb:514:in `test_memory_leak_aset'

[ngoto (Naohisa Goto)]

コードをよく読んだら原因の推測が間違っていたので訂正します。

なお、Solaris では、/proc/self/status は struct pstatus_t の内容のバイナリを返しますが、それには全く対応していないので、nil になるか、偶然バイナリ値が何かに一致した場合にでたらめな値が返されるかのいずれかになります。

は明確に間違いで、ps を利用して、それなりの値を返すようにはなっていました。

しかし、test_env.rb 内のテストコードで ENV.clear を呼んでいるため、
環境変数 PATH もクリアされてしまい、
memory_status.rb 内で IO.popen を使って ps を呼ぶ際に、
システム既定またはどこかにハードコードされた謎の PATH が使われ、
その結果、私の環境では /usr/ucb/ps が呼ばれ、
/usr/ucb/ps は POSIX の ps を想定したオプションを受け付けないため、
期待した結果を返さず、:size や :rss が nil になっていました。

memory_status.rb 内の

    PSCMD = ["ps", "-ovsz=","-orss=", "-p"]

の "ps" を絶対パスを使用するように変更すれば解決すると思いますが、マイナー環境対応を壊さないよう実現するコードはすぐには思いつきませんでした。

[nobu (Nobuyoshi Nakada)]

• Status changed from Open to Feedback

これでどうでしょう。
見つからなかったときにどうするか悩ましいですが。

diff --git a/test/ruby/memory_status.rb b/test/ruby/memory_status.rb
index f8e097a..ef973ee 100644
--- a/test/ruby/memory_status.rb
+++ b/test/ruby/memory_status.rb
@@ -82,7 +82,17 @@ module Memory
       end
     end
   else
-    PSCMD = ["ps", "-ovsz=","-orss=", "-p"]
+    ps = ENV["PATH"].split(File::PATH_SEPARATOR).find {|path|
+      next if path.empty?
+      ps = File.join(path, "ps")
+      begin
+        st = File.stat(ps)
+      rescue
+      else
+        break ps if st.file? and st.executable?
+      end
+    }
+    PSCMD = [ps, "-ovsz=","-orss=", "-p"]
     PAT = /^\s*(\d+)\s+(\d+)$/
 
     keys << :size << :rss

[ngoto (Naohisa Goto)]

TestEnv#test_memory_leak_* では、子プロセス内のコードで ENV.clear を呼んでいて、
上記コードもその子プロセス内で呼ばれることになるため、つまり、
上記コードを通る際には ENV[PATH]は nil になった状態です。
このため、ENV["PATH"].split の部分でエラーになると思います。

以下のようにPATHを保存して最後に復旧するようにしたら、Errorは出なくなりました。（Failureにはなりますが、OSのメモリ管理の方針によると思われます。）

Index: test/ruby/test_env.rb
===================================================================
--- test/ruby/test_env.rb	(revision 46727)
+++ test/ruby/test_env.rb	(working copy)
@@ -512,22 +512,26 @@
   def test_memory_leak_aset
     bug9977 = '[ruby-dev:48323] [Bug #9977]'
     assert_no_memory_leak([], <<-'end;', "5_000.times(&doit)", bug9977, limit: 2.0)
+      path = ENV['PATH']
       ENV.clear
       k = 'FOO'
       v = (ENV[k] = 'bar'*5000 rescue 'bar'*1500)
       doit = proc {ENV[k] = v}
       500.times(&doit)
+      ENV['PATH'] = path
     end;
   end
 
   def test_memory_leak_select
     bug9978 = '[ruby-dev:48325] [Bug #9978]'
     assert_no_memory_leak([], <<-'end;', "5_000.times(&doit)", bug9978, limit: 2.0)
+      path = ENV['PATH']
       ENV.clear
       k = 'FOO'
       (ENV[k] = 'bar'*5000 rescue 'bar'*1500)
       doit = proc {ENV.select {break}}
       500.times(&doit)
+      ENV['PATH'] = path
     end;
   end
 
@@ -541,11 +545,13 @@
   def test_memory_leak_shift
     bug9983 = '[ruby-dev:48332] [Bug #9983]'
     assert_no_memory_leak([], <<-'end;', "5_000.times(&doit)", bug9983, limit: 2.0)
+      path = ENV['PATH']
       ENV.clear
       k = 'FOO'
       v = (ENV[k] = 'bar'*5000 rescue 'bar'*1500)
       doit = proc {ENV[k] = v; ENV.shift}
       500.times(&doit)
+      ENV['PATH'] = path
     end;
   end
 end

これでも、Solarisで /usr/ucb を /usr/bin や /bin より先に PATH に入れていた場合は救えません。

[nobu (Nobuyoshi Nakada)]

Naohisa Goto wrote:

TestEnv#test_memory_leak_* では、子プロセス内のコードで ENV.clear を呼んでいて、
上記コードもその子プロセス内で呼ばれることになるため、つまり、
上記コードを通る際には ENV[PATH]は nil になった状態です。
このため、ENV["PATH"].split の部分でエラーになると思います。

定数の初期化はロードされてモジュール定義のときですから、まだテストでPATHが変更される前です。

これでも、Solarisで /usr/ucb を /usr/bin や /bin より先に PATH に入れていた場合は救えません。

使えるpsを探すようにしてみました。

diff --git a/test/ruby/memory_status.rb b/test/ruby/memory_status.rb
index f8e097a..9bdaa73 100644
--- a/test/ruby/memory_status.rb
+++ b/test/ruby/memory_status.rb
@@ -82,8 +82,17 @@ module Memory
       end
     end
   else
-    PSCMD = ["ps", "-ovsz=","-orss=", "-p"]
     PAT = /^\s*(\d+)\s+(\d+)$/
+    PSCMD =  ENV["PATH"].split(File::PATH_SEPARATOR).find {|path|
+      next if path.empty?
+      pscmd = [File.join(path, "ps"), "-ovsz=", "-orss=", "-p"]
+      begin
+        break pscmd if PAT =~ IO.popen(pscmd + [$$.to_s], "r", err: [:child, :out], &:read)
+      rescue
+        next
+      end
+    }
+    raise MiniTest::Skip, "ps command not found" unless PSCMD
 
     keys << :size << :rss
     def self.read_status

[ngoto (Naohisa Goto)]

定数の初期化はロードされてモジュール定義のときですから、まだテストでPATHが変更される前です。

確かにそのとおりでした、すみません。

パッチを当てて、PATH=/usr/ucb:$PATH などとした状態でも Error が出なくなるのは確認しました。

Errorのかわりに、下記の2つのFailureに変わりましたが、本件とは別問題として調べてみます。

  1) Failure:
TestEnv#test_memory_leak_aset [/XXXXX/test/ruby/test_env.rb:514]:
[ruby-dev:48323] [Bug #9977].
size: 21692416 => 97189888..
Expected 4.480362537764351 to be < 2.0.

  2) Failure:
TestEnv#test_memory_leak_shift [/XXXXX/test/ruby/test_env.rb:543]:
[ruby-dev:48332] [Bug #9983].
size: 38469632 => 155910144..
Expected 4.0528109028960815 to be < 2.0.

[nobu (Nobuyoshi Nakada)]

• Status changed from Feedback to Closed
• % Done changed from 0 to 100

Applied in changeset r46755.

---

memory_status.rb: find proper ps

• test/ruby/memory_status.rb (Memory::PSCMD): use ps command which
  outputs expected result. [ruby-dev:48370] [Bug #10010]

[ngoto (Naohisa Goto)]

以下のように test/ruby/test_env.rb を実行すると、なぜか、
uninitialized constant EnvUtil::RbConfig (NameError) になります。
実行に使ったrubyはr46751で、svnレポジトリのローカルコピーr46756 の test/ruby/test_env.rb を相対パス指定にて直接実行した結果のものです。

 $ ruby test/ruby/test_env.rb 
Run options: 

# Running tests:

[22/49] TestEnv#test_memory_leak_aset = 0.15 s           
  1) Failure:
TestEnv#test_memory_leak_aset [test/ruby/test_env.rb:514]:
[ruby-dev:48323] [Bug #9977].
<[true, ""]> expected but was
<[false,
 "/XXXXX/test/ruby/find_executable.rb:3:in `find_executable': uninitialized constant EnvUtil::RbConfig (NameError)\n\tfrom /XXXXX/test/ruby/memory_status.rb:87:in `<module:Memory>'\n\tfrom /XXXXX/test/ruby/memory_status.rb:1:in `<top (required)>'\n\tfrom -:1:in `require'\n"]>.

[23/49] TestEnv#test_memory_leak_select = 0.06 s      
  2) Failure:
TestEnv#test_memory_leak_select [test/ruby/test_env.rb:525]:
[ruby-dev:48325] [Bug #9978].
<[true, ""]> expected but was
<[false,
 "/XXXXX/test/ruby/find_executable.rb:3:in `find_executable': uninitialized constant EnvUtil::RbConfig (NameError)\n\tfrom /XXXXX/test/ruby/memory_status.rb:87:in `<module:Memory>'\n\tfrom /XXXXX/test/ruby/memory_status.rb:1:in `<top (required)>'\n\tfrom -:1:in `require'\n"]>.

[24/49] TestEnv#test_memory_leak_shift = 0.06 s         
  3) Failure:
TestEnv#test_memory_leak_shift [test/ruby/test_env.rb:543]:
[ruby-dev:48332] [Bug #9983].
<[true, ""]> expected but was
<[false,
 "/XXXXX/test/ruby/find_executable.rb:3:in `find_executable': uninitialized constant EnvUtil::RbConfig (NameError)\n\tfrom /XXXXX/test/ruby/memory_status.rb:87:in `<module:Memory>'\n\tfrom /XXXXX/test/ruby/memory_status.rb:1:in `<top (required)>'\n\tfrom -:1:in `require'\n"]>.

Finished tests in 0.608052s, 80.5852 tests/s, 596.9886 assertions/s.
49 tests, 363 assertions, 3 failures, 0 errors, 0 skips

ruby -v: ruby 2.2.0dev (2014-07-07) [sparc64-solaris2.10]

[ngoto (Naohisa Goto)]

• Status changed from Closed to Open

r46756 の make test-all にて、同じ Failure がすべての test/ruby/memory_status.rb 関連の場所で出たので再オープンします。

invoke_ruby によって --diable-gems を付けて呼んだ子プロセスの ruby 内で実行される envutil.rb にて、 require 'rbconfig' より前に find_executable が実行されるため、エラーになっているように見えます。（親プロセスでは通常 rubygems が有効のため、require 'rbconfig' が最初からされた状態なので、顕在化しなかった。）

現在（r26299 以降）、envutil.rb の最後のほうで require 'rbconfig' していますが、これをもっと前に持ってくれば解決しそうな気はします。

[ngoto (Naohisa Goto)]

• Status changed from Open to Closed

r46762 fix this issue

[ngoto (Naohisa Goto)]

• Related to Bug #10020: TestEnv#test_memory_leak_*, Fiddle::TestPointer#test_no_memory_leak, and Test_StringModifyExpand#test_modify_expand_memory_leak on Solaris added