Running ble.sh takes too much memory - eval_unsafe_arith

[andychu]

From

• Run ble.sh (2022) #1069

#1069 (comment)

~/.mwg/git/oilshell/oil/_bin/cxx-asan/osh --rcfile oshrc.source

Oh actually don't test with cxx-asan !

Ah, yeah. I actually wasn't sure about how I should generate the non-ASAN binary. That's the reason I also tested the behavior with the tarball of 0.27.0 from the release page. As I've already written in #1069 (comment), the same behavior is observed with the release tarball of 0.27.0. It still uses 1.1 GB memory with shopt -s eval_unsafe_arith.

You should do ninja _bin/cxx-opt/osh, and then run that binary.

Without eval_unsafe_arith

$ ~/.mwg/git/oilshell/oil/_bin/cxx-opt/osh --rcfile oshrc.source
  shopt -s checkwinsize
  ^~~~~
out/ble.osh:2815: 'shopt' got invalid option 'checkwinsize'
osh warning: The 'RETURN' hook isn't implemented
[??? no location ???] warning: Invalid start of UTF-8 sequence
[??? no location ???] warning: Invalid start of UTF-8 sequence
RSS: 38244
[ble: elapsed 930ms, CPU 98.9% (self)usr4ms/sys0+(child)usr530ms/sys388ms]

With eval_unsafe_arith

$ ~/.mwg/git/oilshell/oil/_bin/cxx-opt/osh --rcfile oshrc.source
  shopt -s checkwinsize
  ^~~~~
out/ble.osh:2815: 'shopt' got invalid option 'checkwinsize'
osh warning: The 'RETURN' hook isn't implemented
[??? no location ???] warning: Invalid start of UTF-8 sequence
[??? no location ???] warning: Invalid start of UTF-8 sequence
RSS: 1087120
[ble: elapsed 964ms, CPU 98.9% (self)usr3ms/sys2ms+(child)usr538ms/sys413ms]

So, the updated table would be this:

	Python version	osh (cxx-asan)	osh (cxx-opt)	Bash 5.3-beta (for ref)
Without eval_unsafe_arith	69.23 MB (41.64s)	157.9 MB (6.364s)	38.24 MB (0.930s)	14.77 MB (0.178s)
With eval_unsafe_arith	69.17 MB (41.45s)	1.207 GB (6.421s)	1.087 GB (0.964s)	N/A

OK, the memory footprint without eval_unsafe_arith is smaller than the Python version and only 2x as large as Bash 5.3. Also, the execution time was much improved to be 5x slower compared to Bash. However, with eval_unsafe_arith, it still uses 1.1 GB.

[andychu]

Python repro

$ time ~/git/oils-for-unix/oils/bin/osh --rcfile oshrc.source 
  shopt -s checkwinsize
  ^~~~~
out/ble.osh:2815: 'shopt' got invalid option 'checkwinsize'
osh warning: The 'RETURN' hook isn't implemented
RSS: 68152

real    0m34.067s
user    0m32.029s
sys     0m0.270s

[andychu]

C++ repro

$ time ~/git/oils-for-unix/oils/_bin/cxx-opt/osh --rcfile oshrc.source 
  shopt -s checkwinsize
  ^~~~~
out/ble.osh:2815: 'shopt' got invalid option 'checkwinsize'
osh warning: The 'RETURN' hook isn't implemented
[??? no location ???] warning: Invalid start of UTF-8 sequence
[??? no location ???] warning: Invalid start of UTF-8 sequence
RSS: 1086400

real    0m1.110s
user    0m0.420s
sys     0m0.659s

@akinomyoga OK thanks I am getting similar results as you

I think this is a GC bug

---

How did you know to turn off eval_unsafe_arith ? I would think that breaks the tests?

[andychu]

I guess you are changing oshrc.source to include `shopt -s eval_unsafe_arith ?

I wonder if you can submit the file oshrc.source to the osh branch? So we can be sure we are testing the same thing

I manually created it

[andychu]

OK yeah I commented out the line, and I got less memory usage!

I guess I am surprised that doesn't break anything

$ time OILS_GC_STATS=1 ~/git/oils-for-unix/oils/_bin/cxx-opt/osh --rcfile oshrc.source 
  shopt -s checkwinsize
  ^~~~~
out/ble.osh:2815: 'shopt' got invalid option 'checkwinsize'
osh warning: The 'RETURN' hook isn't implemented
[??? no location ???] warning: Invalid start of UTF-8 sequence
[??? no location ???] warning: Invalid start of UTF-8 sequence
RSS: 38128
  num live         =     682202
  max survived     =     516960

  num allocated    =    2503534
  num in heap      =     126450
  num in pool 1    =    1215704
  num in pool 2    =    1161380
bytes allocated    = 1113977176

  num gc points    =      18897
  num collections  =         25

   gc threshold    =     736504
  num growths      =          6

  max gc millis    =       13.6
total gc millis    =       96.4

roots capacity     =       2048
 objs capacity     =      81920

real    0m0.747s
user    0m0.440s
sys     0m0.300s

[andychu]

And then here is OILS_GC_STATS with the leak ?

$ time OILS_GC_STATS=1 ~/git/oils-for-unix/oils/_bin/cxx-opt/osh --rcfile oshrc.source 
  shopt -s checkwinsize
  ^~~~~
out/ble.osh:2815: 'shopt' got invalid option 'checkwinsize'
osh warning: The 'RETURN' hook isn't implemented
[??? no location ???] warning: Invalid start of UTF-8 sequence
[??? no location ???] warning: Invalid start of UTF-8 sequence
RSS: 1086860
  num live         =     670346
  max survived     =     516859

  num allocated    =    2499492
  num in heap      =     126453
  num in pool 1    =    1213695
  num in pool 2    =    1159344
bytes allocated    = 1114091928

  num gc points    =      18899
  num collections  =         25

   gc threshold    =     739916
  num growths      =          6

  max gc millis    =       13.2
total gc millis    =      106.3

roots capacity     =       2048
 objs capacity     =      81920

real    0m0.786s
user    0m0.430s
sys     0m0.349s

[andychu]

Actually I'm surprised the GC stats aren't much different ???

Hmmm

[andychu]

Turning on _OILS_GC_VERBOSE=1, I don't see much difference either

20. GC with 257 roots (5 global) and 491140 live objects
    274146 live after sweep
    7.0 ms GC

21. GC with 391 roots (5 global) and 486815 live objects
    326607 live after sweep
    9.6 ms GC

22. GC with 240 roots (5 global) and 486843 live objects
    369962 live after sweep
    exceeded 365077 live objects; gc_threshold set to 739924
    10.8 ms GC

23. GC with 330 roots (5 global) and 740107 live objects
    492524 live after sweep
    19.1 ms GC
RSS: 1086888
  num live         =     670350
  max survived     =     516863

  num allocated    =    2499497
  num in heap      =     126453
  num in pool 1    =    1213699
  num in pool 2    =    1159345
bytes allocated    = 1114091956

  num gc points    =      18899
  num collections  =         25

   gc threshold    =     739924
  num growths      =          6

  max gc millis    =       19.1
total gc millis    =      111.8

roots capacity     =       2048
 objs capacity     =      81920

real    0m0.804s
user    0m0.444s
sys     0m0.354s

andy@hoover:~/git/oils-for-unix/ble.sh$ time _OILS_GC_VERBOSE=1 OILS_GC_STATS=1 ~/git/oils-for-unix/oils/_bin/cxx-opt/osh --rcfile oshrc_unsafe.source

[andychu]

Malloc calls are very similar, wtf

This is with ltrace -e malloc

andy@hoover:~/git/oils-for-unix/ble.sh$ cat unsafe.log |./malloc.py | pysum
1118174019

andy@hoover:~/git/oils-for-unix/ble.sh$ cat safe.log |./malloc.py | pysum
1118022055

[andychu]

I want some sort of heap profile

unsafe

VmPeak:  1095280 kB
VmSize:  1095280 kB
VmLck:         0 kB
VmPin:         0 kB
VmHWM:   1087056 kB
VmRSS:   1087056 kB
RssAnon:         1080836 kB
RssFile:            6220 kB
RssShmem:              0 kB
VmData:  1081184 kB
VmStk:       132 kB
VmExe:      1620 kB
VmLib:      3348 kB
VmPTE:      2188 kB
VmSwap:        0 kB

[akinomyoga]

I guess you are changing oshrc.source to include `shopt -s eval_unsafe_arith ?

Ah, yes.

I wonder if you can submit the file oshrc.source to the osh branch? So we can be sure we are testing the same thing

I added oshrc.source and bashrc.source to the osh branch of akinomyoga/ble.sh in the latest pushes.

edit: To run oshrc.source without eval_unsafe_arith, you can specify an environment variable BLE_SAFE_ARITH:

$ BLE_SAVE_ARITH=1 /path/to/osh --rcfile oshrc.source

I manually created it

I pushed those files with the same names, so please rename yours if you are going to pull the latest osh branch.

I guess I am surprised that doesn't break anything

Yeah, but it seems to source ble.sh successfully even without eval_unsafe_arith, but it's just sourcing. It might cause the actual problems in running ble.sh. It might also cause differences in the tests, but I haven't checked.

[akinomyoga]

How about the free'd size?

Another possibility is that there is some 1.1 GB memory area that is always allocated but unused when eval_unsafe_arith is disabled. Then, it is allocated in the virtual memory (VSZ) yet not in the physical memory (RSS).

[andychu]

Actually now I see the safe version also has a high VmPeak

I turned both into a while 1; sleep 1; loop

I am not quite sure what's going on, but there could be a bug in both cases. 1 GB is a lot ...

Actually I want to test the peak for bash now too

VmPeak:  1094896 kB
VmSize:    46316 kB
VmLck:         0 kB
VmPin:         0 kB
VmHWM:   1086492 kB
VmRSS:     38244 kB
RssAnon:           31960 kB
RssFile:            6284 kB
RssShmem:              0 kB
VmData:    32220 kB
VmStk:       132 kB
VmExe:      1620 kB
VmLib:      3348 kB
VmPTE:       128 kB
VmSwap:        0 kB

[andychu]

So basically the size goes down in one case but not the other, but they both have a high peak, which is kinda bad

This is consistent with what the GC logs above say -- they are both allocating approximately the same amount, and the GC is doing approximately the same thing in both cases

[andychu]

bash uses a lot less memory ... I'd be happy if we are using 46 MB

The issue is that we keep many data structures around in memory to give precise errors, and bash doesn't do that

But still there is some other bug here

VmPeak:    11544 kB
VmSize:    10160 kB
VmLck:         0 kB
VmPin:         0 kB
VmHWM:      5268 kB
VmRSS:      3900 kB
RssAnon:             464 kB
RssFile:            3436 kB
RssShmem:              0 kB
VmData:      436 kB
VmStk:       132 kB
VmExe:       772 kB
VmLib:      1588 kB
VmPTE:        60 kB
VmSwap:        0 kB