Ensure Java garbage collection

[khaeru]

This PR responds to reports from @OFR-IIASA that JDBCBackend was exhausting memory after loading ~5 Scenarios of the MESSAGEix-GLOBIOM global model.

• The symptom was that Python or GAMS would be unable to allocate sufficient memory; this was because Java was using it.

UPD: symptom was Java toGDX was throwing OutOfMemory exception due to the objects from heap could not be garbage collected (having referenced either from java or from python via JPype1).

The changes:

• Add the base.Backend method del_ts, called by TimeSeries.__del__.
  This signals the Backend to perform any clean-up when the TimeSeries (or Scenario) object is cleaned up.
• CachingBackend.del_ts empties the Python cache associated with the TimeSeries object that's being deleted. Add test_cache_del_ts to test this behaviour.
• Modify JDBCBackend.jindex to use a WeakKeyDictionary
  Technical explanation: Formerly this was a dict of (Python TimeSeries/Scenario object → Java TimeSeries/Scenario object, via JPype); but the keys referencing the TimeSeries objects prevented them from being garbage collected. WeakRefDictionary ensures that the dict key is not counted as a reference to the object.
  Add test_del_ts() to test this.
• {TimeSeries,Scenario}.platform are now proxy objects, with the same logic: an existing Scenario that references a Platform does not prevent del platform. Add test_weakref to test this.
• test_jdbc.test_gc and the pytest mark test_gc are added (by @zikolach) to check that Java-side garbage collection under JDBCBackend functions as intended.

May fix #227.

How to review

Confirm that a reasonable number of 'large' Scenarios can be loaded using this code.

PR checklist

• Tests added.
• Documentation added. N/A
• Release notes updated.

[codecov]

Codecov Report

Merging #298 into master will not change coverage.
The diff coverage is n/a.

@@           Coverage Diff           @@
##           master     #298   +/-   ##
=======================================
  Coverage   96.04%   96.04%           
=======================================
  Files          42       42           
  Lines        4677     4677           
=======================================
  Hits         4492     4492           
  Misses        185      185           

---

Continue to review full report at Codecov.

Legend - Click here to learn more
Δ = absolute <relative> (impact), ø = not affected, ? = missing data
Powered by Codecov. Last update 0f29a0f...0f29a0f. Read the comment docs.

[zikolach]

@khaeru I added pytest mark as you suggested to gc test so it can be run separately from all other tests. Also updated build to run it at the end. I didn't include it into ci/run.sh as wasn't sure whether it can break something (e.g. coverage reporting) on other CI servers.

[zikolach]

Following test was executed to test Java export to GDX

public class TestToGDX {
	public static void main(String[] args) throws IxException, InterruptedException {
		Thread.sleep(1000 * 30);
		Platform mp = new Platform("java", "/Users/kushin/iiasa/src/ixmp_source/ixmp_dev.properties");
		mp.setLogLevel("DEBUG");
		final List<Map<String, Object>> scenarios = mp.getScenarioList(true, "SSP2", null);
		for (Map<String, Object> data : scenarios) {
			final String model = (String) data.get("model");
			final String scenario = (String) data.get("scenario");
			System.out.println(model + "  "  + scenario);
			final Scenario scen = mp.getScenario(model, scenario);
			System.out.println(scen.getClass());
			scen.toGDX("output", format("%s-%s.gdx", model, scenario));
		}
	}
}

20 scenarios were exported from DB without any issues (see memory consumption on screenshot).

$ ls -la output/
total 3653072
drwxr-xr-x  24 kushin  staff       768 Apr 10 13:25 .
drwxr-xr-x@ 70 kushin  staff      2240 Apr 10 15:29 ..
-rw-r--r--   1 kushin  staff  79476104 Apr 10 12:00 SSP2-INDC2030i-con-prim-dir-ncr.gdx
-rw-r--r--   1 kushin  staff  79580616 Apr 10 12:04 SSP2-INDC2030i_forever-con-prim-dir-ncr.gdx
-rw-r--r--   1 kushin  staff  79579600 Apr 10 12:08 SSP2-INDCi_1000-con-prim-dir-ncr.gdx
-rw-r--r--   1 kushin  staff  79579600 Apr 10 12:13 SSP2-INDCi_1600-con-prim-dir-ncr.gdx
-rw-r--r--   1 kushin  staff  79353200 Apr 10 12:17 SSP2-NPi2020-con-prim-dir-ncr.gdx
-rw-r--r--   1 kushin  staff  79463856 Apr 10 12:21 SSP2-NPi2020_1000-con-prim-dir-ncr.gdx
-rw-r--r--   1 kushin  staff  79463856 Apr 10 12:24 SSP2-NPi2020_1600-con-prim-dir-ncr.gdx
-rw-r--r--   1 kushin  staff  79463856 Apr 10 12:28 SSP2-NPi2020_400-con-prim-dir-ncr.gdx
-rw-r--r--   1 kushin  staff  79473484 Apr 10 12:33 SSP2-NPi2030-con-prim-dir-ncr.gdx
-rw-r--r--   1 kushin  staff  79576692 Apr 10 12:36 SSP2-NPiREF-con-prim-dir-ncr.gdx
-rw-r--r--   1 kushin  staff  79352242 Apr 10 12:41 SSP2-NPip2020-con-prim-dir-ncr.gdx
-rw-r--r--   1 kushin  staff  79323756 Apr 10 12:45 SSP2-baseline.gdx
-rw-r--r--   1 kushin  staff  79307844 Apr 10 12:48 SSP2-baseline_DEFAULT.gdx
-rw-r--r--   1 kushin  staff  79306508 Apr 10 12:52 SSP2-bl_WEO2018_SOLARNUC.gdx
-rw-r--r--   1 kushin  staff  79329136 Apr 10 12:59 SSP2-bl_WEO2018_SOLARNUC_test.gdx
-rw-r--r--   1 kushin  staff  79306100 Apr 10 13:03 SSP2-bl_coal_comb.gdx
-rw-r--r--   1 kushin  staff  79306628 Apr 10 13:08 SSP2-bl_cpot_cost_incr.gdx
-rw-r--r--   1 kushin  staff  79305980 Apr 10 13:13 SSP2-bl_cpot_red.gdx
-rw-r--r--   1 kushin  staff  79306508 Apr 10 13:17 SSP2-bl_cppl_cost_incr.gdx
-rw-r--r--   1 kushin  staff  79306508 Apr 10 13:21 SSP2-bl_cppl_cost_red.gdx
-rw-r--r--   1 kushin  staff  79323756 Apr 10 13:25 SSP2-bl_ren_red.gdx
-rw-r--r--   1 kushin  staff  79307844 Apr 10 10:53 SSP2_test_nikolay-baseline.gdx

It has to be tested also uploading solutions (or any other methods called upon solve) to ensure they has no leaks.

[khaeru]

@OFR-IIASA reported (via Slack) that the changes here from April 15 ("Allow disabling JDBCBackend caching", currently commit # 77538ee, but will change if the branch is rebased) do not resolve the issue in real-world usage.

The commits today add a new test, test_reload_cycle, plus fixtures, command-line options, and utility code. Please see the docstring of the new test. These allow me to reproduce the memory error on my system quickly (in under a minute):

Experiment 1:

$ pytest -m performance -k reload_cycle --verbose --log-cli-level=DEBUG \
         --resource-limit=DATA:1024 --jvm-mem-limit=256
[...]
___________________________________________________________________________________________ test_reload_cycle[gc1-cache1] ___________________________________________________________________________________________
[...]
_ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _ _
                                                                                                          
self = <ixmp.backend.jdbc.JDBCBackend object at 0x7f635ad529d0>, ts = <ixmp.core.Scenario object at 0x7f633a796a90>, version = 1                                                                                     
                                                                                                                                                                                                                     
    def get(self, ts, version):                                                                                                                                                                                      
        args = [ts.model, ts.scenario]                                                                                                                                                                               
        if version is not None:                                                                                                                                                                                      
            # Load a TimeSeries of specific version                                                                                                                                                                  
            args.append(version)                                                                                                                                                                                     
                                                                                                                                                                                                                     
        # either getTimeSeries or getScenario                                                                                                                                                                        
        method = getattr(self.jobj, 'get' + ts.__class__.__name__)                                                                                                                                                   
        try:                                                                                                                                                                                                         
>           jobj = method(*args)                                                                                                                                                                                     
E           jpype._jclass.java.lang.OutOfMemoryError: java.lang.OutOfMemoryError: Java heap space                                                                                                                    
                                                                                                                                                                                                                     
ixmp/backend/jdbc.py:453: java.lang.OutOfMemoryError
[...]
------------------------------------------------------------------------------------------------- Captured log call -------------------------------------------------------------------------------------------------
INFO     ixmp.backend.jdbc:jdbc.py:216 launching ixmp.Platform connected to jdbc:hsqldb:file:/tmp/pytest-of-khaeru/pytest-128/test_reload_cycle_gc1_cache1_0/testdb
DEBUG    ixmp.model.base:base.py:46 No initialization for None-scheme Scenario
DEBUG    ixmp.testing:testing.py:583  26 pass 7 -- platform instantiated
MemInfo(profiled=' 525.09', max_rss=' 528.49', jvm_total=' 228.00', jvm_free='  51.14', jvm_used=' 176.86', python=' 348.23')
MemInfo(profiled='  -3.34', max_rss='   0.07', jvm_total='   0.00', jvm_free=' -19.31', jvm_used='  19.31', python=' -22.65')
FAILED
[…]
============================================================================================== short test summary info ==============================================================================================
FAILED ixmp/tests/backend/test_jdbc.py::test_reload_cycle[gc1-cache1] - jpype._jclass.java.lang.OutOfMemoryError: java.lang.OutOfMemoryError: Java heap space
FAILED ixmp/tests/backend/test_jdbc.py::test_reload_cycle[gc1-cache0] - jpype._jclass.java.lang.OutOfMemoryError: java.lang.OutOfMemoryError: GC overhead limit exceeded
FAILED ixmp/tests/backend/test_jdbc.py::test_reload_cycle[gc0-cache1] - jpype._jclass.java.lang.OutOfMemoryError: java.lang.OutOfMemoryError: GC overhead limit exceeded
FAILED ixmp/tests/backend/test_jdbc.py::test_reload_cycle[gc0-cache0] - jpype._jclass.java.lang.OutOfMemoryError: java.lang.OutOfMemoryError: GC overhead limit exceeded

pass 7 means that the error occurs on the 7th cycle (of reloading a Platform, loading/cloning a Scenario, and loading data from it into memory; again, please read the docstring/test function linked above).

Other experiments:

1. (as above)
2. If I instead give --jvm-mem-limit=512, the tests fail with MemoryError in Python on the second pass.
3. If I give -k 'reload_cycle and gc1 and cache0' (this selects just the default behaviour when ixmp.Platform(..., cache=False)) and --resource-limit=DATA:2048 --jvm-mem-limit=512, it fails on the 26th pass with java.lang.OutOfMemoryError.
4. If I give -k 'reload_cycle and gc1 and cache0' --resource-limit=DATA:3072 --jvm-mem-limit=1024, it completes 30 passes successfully, ending with:

   DEBUG    ixmp.testing:testing.py:583 122 post
   MemInfo(profiled='1301.23', max_rss='1304.00', jvm_total=' 910.50', jvm_free=' 455.19', jvm_used=' 455.31', python=' 845.92')
   MemInfo(profiled='   0.00', max_rss='   0.00', jvm_total='   0.00', jvm_free=' -43.04', jvm_used='  43.04', python=' -43.04')
   INFO     test_jdbc:test_jdbc.py:399 JVM memory usage gained 13.769 MiB / cycle
   INFO     test_jdbc:test_jdbc.py:401 Total memory usage gained 25.185 MiB / cycle
   

   The full log is attached as pytest-log.txt.

Some thoughts at first glance:

• Python and Java compete for available memory, and the failure mode depends on whether the JVM -Xmx option allows Java (experiment 2) to win or Python (experiments 1 and 3).

• The experiments above occur with rc_data_size set to 5e4, i.e. 50,000 rows in a single parameter. Further experimentation is needed; the reported error would seem to correspond to:

  • rc_data_size = 1e6 or whatever the largest parameter is in the Scenario in use.
  • N_cycles = 20 or whatever the total desired count is.
  • --resource-limit=DATA:16384 or just omit it to use all system memory.
  • --jvm-mem-limit=???—no idea, although it seems like when this is 50% or more of the total memory available to Python, then the error is not the reported one.

  In such a case, the "JVM memory usage gained / cycle" might be higher, exhausting the total available sooner.

• The test could also be modified/extended: e.g. instead of loading data into memory, call the method to write to and/or read from GDX.

Finally, a disclaimer that I have no experience in performance profiling, so I could be misinterpreting these numbers.

[khaeru]

The latest commit "Also write to GDX in test_reload_cycle" does what's on the label, per discussion this morning in Slack.

I also adjusted testing.add_random_model_data() to use a 2-D parameter, e.g. for rc_data_size = 50000, the index set has length 224 such that the parameter has 224² = 50176 ≥ 50000 elements. For large data, e.g. rc_data_size ~= 2e6, this should cut down significantly on the overhead of creating and writing the set.

@zikolach over to you for the advanced profiling.

[khaeru]

@zikolach over to you for the advanced profiling.

Some information was shared in Slack.

As well, @OFR-IIASA reported:

so in term s of memory management..i was able to run 12 scenarios sequentially, reloading the platform between each scenario with 12GB allocated to java
after that i didnt run out of memory...i just didnt run more scenarios

This is encouraging—I guess we can continue to wait and see if the problem recurs or not. If not (after a week so), we can imagine that these changes (or others in the code @OFR-IIASA is running) collectively resolved it.

[khaeru]

@zikolach I'm seeing failures across CI platforms with similar messages like this. This test isn't related to the Python code changed in this PR, so I'm wondering why a Scenario would not be in a checked-in state immediately after it is solved. Might this have anything to do with the changes to ixmp.jar on this branch?

[OFR-IIASA]

Some recent issues I have been having using this branch. I have had this happen with setting a scenario to default, but also in the case below:

INFO:message_ix.macro:MACRO converged after 100.0 of a maximum of 100.0 iterations
Traceback (most recent call last):
  File "C:\Users\fricko\Anaconda3\Scripts\mix-data-script.py", line 11, in <module>
    load_entry_point('message-data', 'console_scripts', 'mix-data')()
  File "C:\Users\fricko\Anaconda3\lib\site-packages\click\core.py", line 764, in __call__
    return self.main(*args, **kwargs)
  File "C:\Users\fricko\Anaconda3\lib\site-packages\click\core.py", line 717, in main
    rv = self.invoke(ctx)
  File "C:\Users\fricko\Anaconda3\lib\site-packages\click\core.py", line 1137, in invoke
    return _process_result(sub_ctx.command.invoke(sub_ctx))
  File "C:\Users\fricko\Anaconda3\lib\site-packages\click\core.py", line 1137, in invoke
    return _process_result(sub_ctx.command.invoke(sub_ctx))
  File "C:\Users\fricko\Anaconda3\lib\site-packages\click\core.py", line 956, in invoke
    return ctx.invoke(self.callback, **ctx.params)
  File "C:\Users\fricko\Anaconda3\lib\site-packages\click\core.py", line 555, in invoke
    return callback(*args, **kwargs)
  File "C:\Users\fricko\Anaconda3\lib\site-packages\click\decorators.py", line 27, in new_func
    return f(get_current_context().obj, *args, **kwargs)
  File "c:\repo\message_data\message_data\model\__init__.py", line 45, in new_baseline
    scenario = create_res(context)
  File "c:\repo\message_data\message_data\model\create.py", line 715, in create_res
    scenario = scenario.add_macro(xls_file)
  File "c:\repo\message_ix\message_ix\core.py", line 457, in add_macro
    calibrate(clone, check_convergence=check_convergence, **kwargs)
  File "c:\repo\message_ix\message_ix\macro.py", line 434, in calibrate
    s.remove_solution()
  File "c:\repo\ixmp\ixmp\core.py", line 1418, in remove_solution
    self._backend('clear_solution', first_model_year)
  File "c:\repo\ixmp\ixmp\core.py", line 439, in _backend
    return self.platform._backend(self, method, *args, **kwargs)
  File "c:\repo\ixmp\ixmp\backend\base.py", line 22, in __call__
    return getattr(self, method)(obj, *args, **kwargs)
  File "c:\repo\ixmp\ixmp\backend\jdbc.py", line 849, in clear_solution
    self.jindex[s].removeSolution()
jpype._jclass.IxException: at.ac.iiasa.ixmp.exceptions.IxException: This Scenario must be checked in before performing this operation!
2020-04-29 13:49:43,119  INFO at.ac.iiasa.ixmp.Platform:157 - closed the connection to database 'jdbc:oracle:thin:@gp3.iiasa.ac.at:1521:GP3'

[OFR-IIASA]

Here another example of a different error but with the same root cause

at.ac.iiasa.ixmp.exceptions.IxException   Traceback (most recent call last)
<ipython-input-20-741f3a588faf> in <module>
      9     scenario.commit('rounded values')
     10     scenario.solve()
---> 11     scenario.set_as_default()
c:\repo\ixmp\ixmp\core.py in set_as_default(self)
    476         """Preload timeseries data to in-memory cache. Useful for bulk updates.
    477         """
--> 478         self._backend('preload')
    479 
    480     def add_timeseries(self, df, meta=False, year_lim=(None, None)):
c:\repo\ixmp\ixmp\core.py in _backend(self, method, *args, **kwargs)
    437         self._backend('check_out', timeseries_only)
    438 
--> 439     def commit(self, comment):
    440         """Commit all changed data to the database.
    441 
c:\repo\ixmp\ixmp\backend\base.py in __call__(self, obj, method, *args, **kwargs)
     20         for the method name, e.g. 'ts_{method}'.
     21         """
---> 22         return getattr(self, method)(obj, *args, **kwargs)
     23 
     24     def close_db(self):
c:\repo\ixmp\ixmp\backend\jdbc.py in set_as_default(self, ts)
    503         y = to_jlist(year)
    504 
--> 505         # Field types
    506         ftype = {
    507             'year': int,
at.ac.iiasa.ixmp.exceptions.IxException: at.ac.iiasa.ixmp.exceptions.IxException: this Scenario must be checked in before setting it as default version!

[khaeru]

failures across CI platforms with similar messages like this. This test isn't related to the Python code changed in this PR, so I'm wondering why a Scenario would not be in a checked-in state immediately after it is solved. Might this have anything to do with the changes to ixmp.jar on this branch?

This turned out to be the case; the error (same as #298 (comment) and #298 (comment)) was resolved by the commit titled "Updated ixmp.jar built from [ixmp_source] b1b60ca…", currently 8aa8deb.

[khaeru]

Also, note that I just ran:

• All 8 parametrizations of test_reload_cycle (caching on/off; aggressive garbage collection on/off; writing to GDX on/off),
• rc_data_size = 2e6, i.e. a parameter with 2 million elements,
• on a system with 16 GiB of RAM and an Intel Core i7-8550U.

These all passed, in about 90 minutes.

[OFR-IIASA]

after pulling this branch and reinstalling ixmp, i restarted the script to receive the following error.

INFO:ixmp.backend.jdbc:launching ixmp.Platform connected to jdbc:oracle:thin:@gp3.iiasa.ac.at:1521:GP3
2020-05-05 08:01:56,982  INFO at.ac.iiasa.ixmp.Platform:140 - Welcome to the IX modeling platform!
2020-05-05 08:01:56,984  INFO at.ac.iiasa.ixmp.Platform:141 -  connected to database 'jdbc:oracle:thin:@gp3.iiasa.ac.at:1521:GP3' (user: ixmp_dev)...
Traceback (most recent call last):
  File "C:\Users\fricko\Anaconda3\Scripts\mix-data-script.py", line 11, in <module>
    load_entry_point('message-data', 'console_scripts', 'mix-data')()
  File "C:\Users\fricko\Anaconda3\lib\site-packages\click\core.py", line 764, in __call__
    return self.main(*args, **kwargs)
  File "C:\Users\fricko\Anaconda3\lib\site-packages\click\core.py", line 717, in main
    rv = self.invoke(ctx)
  File "C:\Users\fricko\Anaconda3\lib\site-packages\click\core.py", line 1137, in invoke
    return _process_result(sub_ctx.command.invoke(sub_ctx))
  File "C:\Users\fricko\Anaconda3\lib\site-packages\click\core.py", line 1137, in invoke
    return _process_result(sub_ctx.command.invoke(sub_ctx))
  File "C:\Users\fricko\Anaconda3\lib\site-packages\click\core.py", line 956, in invoke
    return ctx.invoke(self.callback, **ctx.params)
  File "C:\Users\fricko\Anaconda3\lib\site-packages\click\core.py", line 555, in invoke
    return callback(*args, **kwargs)
  File "C:\Users\fricko\Anaconda3\lib\site-packages\click\decorators.py", line 27, in new_func
    return f(get_current_context().obj, *args, **kwargs)
  File "c:\repo\message_data\message_data\projects\engage\__init__.py", line 73, in run
    main(context)
  File "c:\repo\message_data\message_data\projects\engage\runscript_main.py", line 114, in main
    runscript(subcontext)
  File "c:\repo\message_data\message_data\model\runscript.py", line 306, in main
    sr.run_all()
  File "c:\repo\message_data\message_data\model\scenario_runner.py", line 130, in run_all
    self.scen['base'] = self.context.get_scenario()
  File "c:\repo\message_data\message_data\tools\cli.py", line 91, in get_scenario
    return message_ix.Scenario(mp, **self.scenario_info, cache=True)
  File "c:\repo\message_ix\message_ix\core.py", line 37, in __init__
    cache)
TypeError: __init__() takes from 4 to 7 positional arguments but 8 were given
Exception ignored in: <function TimeSeries.__del__ at 0x000001CEDE69E0D8>
Traceback (most recent call last):
  File "c:\repo\ixmp\ixmp\core.py", line 459, in __del__
    self._backend('del_ts')
  File "c:\repo\ixmp\ixmp\core.py", line 454, in _backend
    return self.platform._backend(self, method, *args, **kwargs)
AttributeError: 'Scenario' object has no attribute 'platform'
2020-05-05 08:01:57,055  INFO at.ac.iiasa.ixmp.Platform:157 - closed the connection to database 'jdbc:oracle:thin:@gp3.iiasa.ac.at:1521:GP3'

[khaeru]

after pulling this branch and reinstalling ixmp, i restarted the script to receive the following error.

This was due to mismatched versions of ixmp and message_ix.