1092273 - gcPreserveCode: not properly cleaning when RootedFunction gets collected

Status: RESOLVED DUPLICATE of bug 1080462

(Core :: JavaScript: GC, defect)

Description

[Yves Gwerder]

Attachment: gcPreserveCode_memory_demo_v1.0.diff

For 0 A.D. (Open source RTS game: play0ad.com) we would like to preserve JIT code when it could still be used because it's a massive performance improvement in our use case (also check bug 1068697). When testing it today, I found some issues with increasing memory usage over time, when gcPreserveCode is enabled.

When you have a JS::RootedFunction on the stack and it goes out of scope, it doesn't seem to properly clean up everything related to that function (JIT code, TI information etc.). My expectation of gcPreserveCode is that it preserves code which is still reachable and could be executed, but still does GC when the associated function gets deleted and can't possibly be called anymore.

I've (mis)used the test-case in bug 1068697 to demonstrate the issue.
Run it with: ./jsapi-tests test_PreserveJitCode

Use an external tool (task manager) to monitor how memory usage keeps increasing. After completing 5, 10, 15 etc. percent, it will ask you if you want to run a shrinking GC. Memory usage will keep increasing until you do that.
Also note the commented part in the attachemed patch:
+    // This keeps printing 1, which is interesting. Because of the braces it should be 0 or 
+    // (if the function doesn't get collected at all) increase by one with each call of foo.
+    //std::cout << "countIonScripts: " << countIonScripts(global) << std::endl;

Comment 1

[Jon Coppeard (:jonco)]

I reproduced this running the modified version of testPreserveJitCode.cpp attached and observed memory usage increasing slowly over time.

Dumping the JS heap showed that there was no buildup of uncollected GC things.

Running under valgrind showed some suspicious output however:

==35814== 16 bytes in 2 blocks are definitely lost in loss record 83 of 679
==35814==    at 0x66CB: malloc (in /usr/local/Cellar/valgrind/3.10.0/lib/valgrind/vgpreload_memcheck-amd64-darwin.so)
==35814==    by 0x1006D1170: js_malloc(unsigned long) (in ./valgrind-build/jsapi-tests)
==35814==    by 0x1006D1AF6: JSScript** js_pod_malloc<JSScript*>(unsigned long) (in ./valgrind-build/jsapi-tests)
==35814==    by 0x1006DB200: JSScript** js::MallocProvider<JSRuntime>::pod_malloc<JSScript*>(unsigned long) (in ./valgrind-build/jsapi-tests)
==35814==    by 0x1006B5B8A: js::jit::CodeGeneratorShared::createNativeToBytecodeScriptList(JSContext*) (in ./valgrind-build/jsapi-tests)
==35814==    by 0x1006B5FDF: js::jit::CodeGeneratorShared::generateCompactNativeToBytecodeMap(JSContext*, js::jit::JitCode*) (in ./valgrind-build/jsapi-tests)
==35814==    by 0x100414133: js::jit::CodeGenerator::link(JSContext*, js::types::CompilerConstraintList*) (in ./valgrind-build/jsapi-tests)
==35814==    by 0x1005383D3: js::jit::IonCompile(JSContext*, JSScript*, js::jit::BaselineFrame*, unsigned char*, bool, js::ExecutionMode, bool, js::jit::OptimizationLevel) (in ./valgrind-build/jsapi-tests)
==35814==    by 0x1004B3833: js::jit::Compile(JSContext*, JS::Handle<JSScript*>, js::jit::BaselineFrame*, unsigned char*, bool, js::ExecutionMode, bool) (in ./valgrind-build/jsapi-tests)
==35814==    by 0x1004B3C06: js::jit::CanEnter(JSContext*, js::RunState&) (in ./valgrind-build/jsapi-tests)
==35814==    by 0x1009AEFBB: js::RunScript(JSContext*, js::RunState&) (in ./valgrind-build/jsapi-tests)
==35814==    by 0x1009A45E0: js::Invoke(JSContext*, JS::CallArgs, js::MaybeConstruct) (in ./valgrind-build/jsapi-tests)

==35814== 72 bytes in 2 blocks are definitely lost in loss record 452 of 679
==35814==    at 0x66CB: malloc (in /usr/local/Cellar/valgrind/3.10.0/lib/valgrind/vgpreload_memcheck-amd64-darwin.so)
==35814==    by 0x100B7A370: js_malloc(unsigned long) (in ./valgrind-build/jsapi-tests)
==35814==    by 0x100B7A310: unsigned char* js_pod_malloc<unsigned char>(unsigned long) (in ./valgrind-build/jsapi-tests)
==35814==    by 0x100BA7D30: unsigned char* js::MallocProvider<JSRuntime>::pod_malloc<unsigned char>(unsigned long) (in ./valgrind-build/jsapi-tests)
==35814==    by 0x1006B62C3: js::jit::CodeGeneratorShared::generateCompactNativeToBytecodeMap(JSContext*, js::jit::JitCode*) (in ./valgrind-build/jsapi-tests)
==35814==    by 0x100414133: js::jit::CodeGenerator::link(JSContext*, js::types::CompilerConstraintList*) (in ./valgrind-build/jsapi-tests)
==35814==    by 0x1005383D3: js::jit::IonCompile(JSContext*, JSScript*, js::jit::BaselineFrame*, unsigned char*, bool, js::ExecutionMode, bool, js::jit::OptimizationLevel) (in ./valgrind-build/jsapi-tests)
==35814==    by 0x1004B3833: js::jit::Compile(JSContext*, JS::Handle<JSScript*>, js::jit::BaselineFrame*, unsigned char*, bool, js::ExecutionMode, bool) (in ./valgrind-build/jsapi-tests)
==35814==    by 0x1004B3C06: js::jit::CanEnter(JSContext*, js::RunState&) (in ./valgrind-build/jsapi-tests)
==35814==    by 0x1009AEFBB: js::RunScript(JSContext*, js::RunState&) (in ./valgrind-build/jsapi-tests)
==35814==    by 0x1009A45E0: js::Invoke(JSContext*, JS::CallArgs, js::MaybeConstruct) (in ./valgrind-build/jsapi-tests)
==35814==    by 0x100988B83: js::Invoke(JSContext*, JS::Value const&, JS::Value const&, unsigned int, JS::Value const*, JS::MutableHandle<JS::Value>) (in ./valgrind-build/jsapi-tests)

It seems like CodeGenerator::nativeToBytecodeScriptList_ is not freed in two situations:

- when the list is of length one it should be freed after the JitcodeGlobalEntry::IonEntry is created
- when the list length is great than one it should be freed when the JitcodeGlobalEntry is removed from the table in JitCode::finalize()

Comment 2

[Jon Coppeard (:jonco)]

Attachment: fix-script-list-leak

Here's a patch.  It also frees them memory under various failure conditions.

Comment 3

[Yves Gwerder]

Attachment: gcPreserveCode_demo_Massif.log

My results from profiling with Massif seem to indicate some other problems.
It looks like most memory is allocated for Baseline inline cache (full log attached).

->91.83% (5,321,728B) 0x512A1A: js::LifoAlloc::getOrCreateChunk(unsigned long) (Utility.h:98)
| ->89.99% (5,215,232B) 0x5FC949: js::jit::ICStubSpace::alloc(unsigned long) (LifoAlloc.h:268)
| | ->89.97% (5,214,208B) 0x5ECC70: js::jit::DoCompareFallback(JSContext*, js::jit::BaselineFrame*, js::jit::ICCompare_Fallback*, JS::Handle<JS::Value>, JS::Handle<JS::Value>, JS::MutableHandle<JS::Value>) (JitCompartment.h:82)
| | | ->89.97% (5,214,208B) 0x402EE20: ???
| | |   ->89.97% (5,214,208B) 0x4026860: ???
| | |     ->89.97% (5,214,208B) 0x58BF8D: EnterBaseline(JSContext*, js::jit::EnterJitData&) (BaselineJIT.cpp:115)
| | |       ->89.97% (5,214,208B) 0x5AC4FF: js::jit::EnterBaselineAtBranch(JSContext*, js::InterpreterFrame*, unsigned char*) (BaselineJIT.cpp:200)
| | |         ->89.97% (5,214,208B) 0x861DB0: Interpret(JSContext*, js::RunState&) (Interpreter.cpp:1694)
| | |           ->89.97% (5,214,208B) 0x8650AF: js::RunScript(JSContext*, js::RunState&) (Interpreter.cpp:432)
| | |             ->89.97% (5,214,208B) 0x865334: js::Invoke(JSContext*, JS::CallArgs, js::MaybeConstruct) (Interpreter.cpp:501)
| | |               ->89.97% (5,214,208B) 0x8671AF: js::Invoke(JSContext*, JS::Value const&, JS::Value const&, unsigned int, JS::Value const*, JS::MutableHandle<JS::Value>) (Interpreter.cpp:538)
| | |                 ->89.97% (5,214,208B) 0x75FA27: JS_CallFunction(JSContext*, JS::Handle<JSObject*>, JS::Handle<JSFunction*>, JS::HandleValueArray const&, JS::MutableHandle<JS::Value>) (jsapi.cpp:4957)
| | |                   ->89.97% (5,214,208B) 0x45C6C4: cls_test_PreserveJitCode::testPreserveJitCode(bool, unsigned int) (testPreserveJitCode.cpp:45)
| | |                     ->89.97% (5,214,208B) 0x45C990: cls_test_PreserveJitCode::run(JS::Handle<JSObject*>) (testPreserveJitCode.cpp:21)
| | |                       ->89.97% (5,214,208B) 0x411F0F: main (tests.cpp:124)

Comment 4

[Kannan Vijayan [:djvj]]

Comment on attachment 8515999 [details] [diff] [review]
fix-script-list-leak

Review of attachment 8515999 [details] [diff] [review]:
-----------------------------------------------------------------

This particular leak is being fixed (under review by h4writer) in bug 1081374.  Same idea as this patch, but it covers a loose end that this one doesn't.  Should I land that seperately or do you want to adopt that patch and land it?

Comment 5

[Kannan Vijayan [:djvj]]

Sorry, wrong bug referenced in comment 4.  It's being fixed in bug 1080462.

Comment 6

[Jon Coppeard (:jonco)]

(In reply to Kannan Vijayan [:djvj] from comment #5)

Please do go ahead and land that.  

We can then check whether that fixes the original issue reported here and and close as duplicate if so.

Comment 7

[Jon Coppeard (:jonco)]

(In reply to Yves Gwerder from comment #3)
I looked at your Massif log and it looks like this is a consequence of disabling the discarding of JIT code.

Some IC stubs are allocated with a LIFO allocator and not tracked individually, but instead are all discarded together when JIT code is discarded (this is the per-zone 'optimized stub space').  In this case this is not happening because we set gcPreserveCode.  So these are building up over time are we're seeing the memory use increase.

Shrinking GC will discard JIT code which brings the memory usage down as observed.

However, this is only happening because new functions are being compiled over and over again in this test program.  In a real application I think there would only be a finite number of these stubs created after which memory use would not increase any further.  Or are you often compiling new code in your application?

Comment 8

[Yves Gwerder]

(In reply to Jon Coppeard (:jonco) from comment #7)
> Or are you often compiling new
> code in your application?
Thanks for checking!
No, as far as I can tell, this shouldn't happen in our case.
The observed memory increase over time in 0 A.D. wasn't the same thing I got in this example program.

In this case it's probably a question of whether using gcPreserveCode is considered a temporary workaround for our use case or if it should be the recommended way when JIT code should be preserved longer than with default settings (for performance reasons).

Comment 9

[Kannan Vijayan [:djvj]]

Comment on attachment 8515999 [details] [diff] [review]
fix-script-list-leak

Review of attachment 8515999 [details] [diff] [review]:
-----------------------------------------------------------------

This leak should be fixed now, as it got resolved by bug 1080462, which landed Nov 12 2014.

Comment 10

[Jon Coppeard (:jonco)]

Resolving this per comment 9.