[Bug]: e2c command for SImon proess leads to xarray fault.

[TonyB9000]

What happened?

e3sm_to_cmip command leads to a cascade of xarray errors, beginning with "cmor_handlers/mpas_vars/siv.py (ds.compute())" call.

What did you expect to happen? Are there are possible answers you came across?

n/a

Minimal Complete Verifiable Example (MVCE)

CLI command

e3sm_to_cmip -v siv -u /p/user_pub/e3sm/bartoletti1/Operations/5_DatasetGeneration/AltProcess/tmp/v2_1.LR.historical_0251/metadata/historical_r4i1p1f1.json -t /p/user_pub/e3sm/staging/resource/cmor/cmip6-cmor-tables/Tables -o /p/user_pub/e3sm/bartoletti1/Operations/5_DatasetGeneration/AltProcess/tmp/v2_1.LR.historical_0251/product -i /p/user_pub/e3sm/bartoletti1/Operations/5_DatasetGeneration/AltProcess/tmp/v2_1.LR.historical_0251/native_data -s --realm SImon --map /p/user_pub/e3sm/staging/resource/maps/map_EC30to60E2r2_to_cmip6_180x360_aave.20220301.nc >> Local_log 2>&1 &

Python script

from e3sm_to_cmip.__main__ import E3SMtoCMIP

args = [
    "-v",
    "siv",
    "-u",
    "/p/user_pub/e3sm/bartoletti1/Operations/5_DatasetGeneration/AltProcess/tmp/v2_1.LR.historical_0251/metadata/historical_r4i1p1f1.json",
    "-t",
    "/p/user_pub/e3sm/staging/resource/cmor/cmip6-cmor-tables/Tables",
    "-o",
    "../qa/tmp",
    "-i",
    "/p/user_pub/e3sm/bartoletti1/Operations/5_DatasetGeneration/AltProcess/tmp/v2_1.LR.historical_0251/native_data",
    "-s",
    "--realm",
    "SImon",
    "--map",
    "/p/user_pub/e3sm/staging/resource/maps/map_EC30to60E2r2_to_cmip6_180x360_aave.20220301.nc",
    "--serial"
]

run = E3SMtoCMIP(args)
run.run()

Relevant log output

2024-04-08 21:28:24,229 [INFO]: siv.py(handle:48) >> Starting siv
2024-04-08 21:28:24,229_229:INFO:handle:Starting siv
  File "/home/bartoletti1/mambaforge/envs/dsm_prod_inst_e2c_local/lib/python3.12/site-packages/e3sm_to_cmip/__main__.py", line 834, in _run_serial
    name = handler_method(
           ^^^^^^^^^^^^^^^
  File "/home/bartoletti1/mambaforge/envs/dsm_prod_inst_e2c_local/lib/python3.12/site-packages/e3sm_to_cmip/cmor_handlers/mpas_vars/siv.py", line 67, in handle
    ds.compute()
  File "/home/bartoletti1/mambaforge/envs/dsm_prod_inst_e2c_local/lib/python3.12/site-packages/xarray/core/dataset.py", line 1013, in compute
    return new.load(**kwargs)
           ^^^^^^^^^^^^^^^^^^
  File "/home/bartoletti1/mambaforge/envs/dsm_prod_inst_e2c_local/lib/python3.12/site-packages/xarray/core/dataset.py", line 845, in load
    evaluated_data: tuple[np.ndarray[Any, Any], ...] = chunkmanager.compute(
                                                       ^^^^^^^^^^^^^^^^^^^^^
  File "/home/bartoletti1/mambaforge/envs/dsm_prod_inst_e2c_local/lib/python3.12/site-packages/xarray/namedarray/daskmanager.py", line 86, in compute
    return compute(*data, **kwargs)  # type: ignore[no-untyped-call, no-any-return]
           ^^^^^^^^^^^^^^^^^^^^^^^^
  File "/home/bartoletti1/mambaforge/envs/dsm_prod_inst_e2c_local/lib/python3.12/site-packages/dask/base.py", line 661, in compute
    results = schedule(dsk, keys, **kwargs)
              ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/home/bartoletti1/mambaforge/envs/dsm_prod_inst_e2c_local/lib/python3.12/site-packages/xarray/core/indexing.py", line 484, in __array__
    return np.asarray(self.get_duck_array(), dtype=dtype)
                      ^^^^^^^^^^^^^^^^^^^^^
  File "/home/bartoletti1/mambaforge/envs/dsm_prod_inst_e2c_local/lib/python3.12/site-packages/xarray/core/indexing.py", line 487, in get_duck_array
    return self.array.get_duck_array()
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/home/bartoletti1/mambaforge/envs/dsm_prod_inst_e2c_local/lib/python3.12/site-packages/xarray/core/indexing.py", line 664, in get_duck_array
    return self.array.get_duck_array()
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/home/bartoletti1/mambaforge/envs/dsm_prod_inst_e2c_local/lib/python3.12/site-packages/xarray/core/indexing.py", line 551, in get_duck_array
    array = self.array[self.key]
            ~~~~~~~~~~^^^^^^^^^^
  File "/home/bartoletti1/mambaforge/envs/dsm_prod_inst_e2c_local/lib/python3.12/site-packages/xarray/backends/netCDF4_.py", line 101, in __getitem__
    return indexing.explicit_indexing_adapter(
           ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/home/bartoletti1/mambaforge/envs/dsm_prod_inst_e2c_local/lib/python3.12/site-packages/xarray/core/indexing.py", line 858, in explicit_indexing_adapter
    result = raw_indexing_method(raw_key.tuple)
             ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "/home/bartoletti1/mambaforge/envs/dsm_prod_inst_e2c_local/lib/python3.12/site-packages/xarray/backends/netCDF4_.py", line 114, in _getitem
    array = getitem(original_array, key)
            ^^^^^^^^^^^^^^^^^^^^^^^^^^^^
  File "src/netCDF4/_netCDF4.pyx", line 4972, in netCDF4._netCDF4.Variable.__getitem__
  File "src/netCDF4/_netCDF4.pyx", line 5930, in netCDF4._netCDF4.Variable._get
  File "src/netCDF4/_netCDF4.pyx", line 2034, in netCDF4._netCDF4._ensure_nc_success
Resource temporarily unavailable
[-] Error running handlers: siv
Error 11: Resource temporarily unavailable
  0%|          | 0/1 [16:16<?, ?it/s]

Anything else we need to know?

The input directory (/p/user_pub/e3sm/bartoletti1/Operations/5_DatasetGeneration/AltProcess/tmp/v2_1.LR.historical_0251/native_data) contains symlinks to the actual native data, as well as to the region file:

EC30to60E2r2_mocBasinsAndTransects20210623.nc (/p/user_pub/e3sm/staging/resource/maps/EC30to60E2r2_mocBasinsAndTransects20210623.nc)

and to the namefile:

mpassi_in (/p/user_pub/e3sm/warehouse/E3SM/2_1/historical/LR/sea-ice/native/namefile/fixed/ens4/v0/mpassi_in)

as is required for MPAS cmorizing.

Environment

 active environment : dsm_prod_inst_e2c_local
active env location : /home/bartoletti1/mambaforge/envs/dsm_prod_inst_e2c_local
        shell level : 4
   user config file : /home/bartoletti1/.condarc

populated config files : /home/bartoletti1/mambaforge/.condarc
conda version : 24.1.2
conda-build version : not installed
python version : 3.10.6.final.0
solver : libmamba (default)
virtual packages : __archspec=1=broadwell
__conda=24.1.2=0
__glibc=2.17=0
__linux=3.10.0=0
__unix=0=0
base environment : /home/bartoletti1/mambaforge (writable)
conda av data dir : /home/bartoletti1/mambaforge/etc/conda
conda av metadata url : None
channel URLs : https://conda.anaconda.org/conda-forge/linux-64
https://conda.anaconda.org/conda-forge/noarch
package cache : /home/bartoletti1/mambaforge/pkgs
/home/bartoletti1/.conda/pkgs
envs directories : /home/bartoletti1/mambaforge/envs
/home/bartoletti1/.conda/envs
platform : linux-64
user-agent : conda/24.1.2 requests/2.31.0 CPython/3.10.6 Linux/3.10.0-1160.108.1.el7.x86_64 rhel/7.9 glibc/2.17 solver/libmamba conda-libmamba-solver/24.1.0 libmambapy/1.5.7
UID:GID : 61843:4061
netrc file : None
offline mode : False

[TonyB9000]

All MPAS processing is generating these errors (Omon and SImon). A summary:

Compressed stack traces:

	Code Path:  "home/bartoletti1/mambaforge/envs/dsm_prod_inst_e2c_local/lib/python3.12/site-packages/

TEST: CMIP6.CMIP.E3SM-Project.E3SM-2-1.piControl.r1i1p1f1.SImon.siv.gr

    2024-04-16 20:26:22,381_381:INFO:handle:Starting siv
e3sm_to_cmip/__main__.py", line 834, in _run_serial      [ name = handler_method( ]
e3sm_to_cmip/cmor_handlers/mpas_vars/siv.py", line 65, in handle [ ds = mpas.add_time(ds, dsIn) ]
e3sm_to_cmip/mpas.py", line 161, in add_time             [ xtimeEnd = ["".join(x.astype("U")).strip() for x in xtimeEnd.values] ]
xarray/core/dataarray.py", line 770, in values           [ return self.variable.values ]
xarray/core/variable.py", line 508, in values            [ return _as_array_or_item(self._data) ]
xarray/core/variable.py", line 306, in _as_array_or_item [ data = np.asarray(data) ]
dask/array/core.py", line 1700, in __array__             [ x = self.compute() ]
dask/base.py", line 375, in compute                      [ (result,) = compute(self, traverse=False, **kwargs) ]
dask/base.py", line 661, in compute                      [ results = schedule(dsk, keys, **kwargs) ]
xarray/core/indexing.py", line 484, in __array__         [ return np.asarray(self.get_duck_array(), dtype=dtype) ]
xarray/core/indexing.py", line 487, in get_duck_array    [ return self.array.get_duck_array() ]
xarray/core/indexing.py", line 664, in get_duck_array    [ return self.array.get_duck_array() ]
xarray/core/indexing.py", line 551, in get_duck_array    [ array = self.array[self.key] ]
xarray/backends/netCDF4_.py", line 101, in __getitem__   [ return indexing.explicit_indexing_adapter( ]
xarray/core/indexing.py", line 858, in explicit_indexing_adapter [ result = raw_indexing_method(raw_key.tuple) ]
xarray/backends/netCDF4_.py", line 114, in _getitem      [ array = getitem(original_array, key) ]

	(FOLLOWED BY)

  File "src/netCDF4/_netCDF4.pyx", line 4948, in netCDF4._netCDF4.Variable.__getitem__
  File "src/netCDF4/_netCDF4.pyx", line 4551, in netCDF4._netCDF4.Variable.shape.__get__
  File "src/netCDF4/_netCDF4.pyx", line 4499, in netCDF4._netCDF4.Variable._getdims
  File "src/netCDF4/_netCDF4.pyx", line 2034, in netCDF4._netCDF4._ensure_nc_success
NetCDF: Not a valid ID
^[[91m[-] ^[[0m^[[1mError running handlers: siv^[[0m
^M  0%|          | 0/1 [38:48<?, ?it/s]

TEST: CMIP6.CMIP.E3SM-Project.E3SM-2-1.piControl.r1i1p1f1.Omon.thetao.gr.log

	(SAME stack trace as above, then …)
	(FOLLOWED BY)

  File "src/netCDF4/_netCDF4.pyx", line 4972, in netCDF4._netCDF4.Variable.__getitem__
  File "src/netCDF4/_netCDF4.pyx", line 5930, in netCDF4._netCDF4.Variable._get
  File "src/netCDF4/_netCDF4.pyx", line 2034, in netCDF4._netCDF4._ensure_nc_success
Resource temporarily unavailable
[-] Error running handlers: thetao
Error 11: Resource temporarily unavailable
Error 11: Resource temporarily unavailable
Error 11: Resource temporarily unavailable
Error 11: Resource temporarily unavailable
Error 11: Resource temporarily unavailable
  0%|          | 0/1 [00:05<?, ?it/s]

[chengzhuzhang]

@TonyB9000 the Minimal Complete Verifiable Example (MVCE) no longer works: when I check I only find eam data in /p/user_pub/e3sm/bartoletti1/Operations/5_DatasetGeneration/AltProcess/tmp/v2_1.LR.historical_0251/native_data. When create this example, you may want to isolate the test data so others can test. But for this issue, I can test with some v2 data available on acme1.

[chengzhuzhang]

Alright, I can reproduce this with 12 months data with v1.11.2:

 e3sm_to_cmip -s --realm SImon --var-list siv --map /p/user_pub/e3sm/staging/resource/maps/map_EC30to60E2r2_to_cmip6_180x360_aave.20220301.nc --input-path /p/user_pub/e3sm/zhang40/e2c_tony/e2c_test_data/v2.mpassi_input/ --output-path /p/user_pub/e3sm/zhang40/e2c_tony/tests --user-metadata /p/user_pub/e3sm/zhang40/e2c_tony/e2c_test_data/holodeck/input/historical_r1i1p1f1.json --tables-path /p/user_pub/e3sm/staging/resource/cmor/cmip6-cmor-tables/Tables

[chengzhuzhang]

I suspect that the "Resource temporarily unavailable " error is from the use of "lock=False" 0f91fb4. And when testing v1.11.1, things work okay.

With lock=True, large operations hang sometime, with "lock=False" cause "Resource temporarily unavailable " for some variables.

[chengzhuzhang]

@tomvothecoder I don't know if this is specific to acme1's file system, but should we consider revert to use 1.11.1 for upcoming e3sm_unified deployment? I think let's decide after a more thorough investigation.

[tomvothecoder]

I suspect that the "Resource temporarily unavailable " error is from the use of "lock=False" 0f91fb4. And when testing v1.11.1, things work okay.

With lock=True, large operations hang sometime, with "lock=False" cause "Resource temporarily unavailable " for some variables.

I think you might be right about lock=False causing "Resource temporarily unavailable", possibly due to resource contention with multiprocessing.

Related issues

• NETCDF - Resource temporarily unavailable  dask/dask#2657
• netCDF4 Resource unavailable error pydata/xarray#4304
• Threading Lock issue with to_netcdf and Dask arrays pydata/xarray#4406

@tomvothecoder I don't know if this is specific to acme1's file system, but should we consider revert to use 1.11.1 for upcoming e3sm_unified deployment? I think let's decide after a more thorough investigation.

I agree that more investigation is needed before deciding what to do next. v1.11.2 includes another fix for parallel=False to avoid NetCDF: Not a Valid ID with open_mfdataset(), which we need to keep too.

My understanding is that Tony is still using acme1 and datasm with e3sm_to_cmip. Is e3sm_to_cmip used by anybody else in E3SM Unified, besides zppy? If zppy tests pass, then we have the option of keeping v1.11.2 for now with the risk of this bug coming up. It sounds like Xylar pressing to move forward with E3SM Unified v1.10.0, so I don't know how much time we have.

[tomvothecoder]

Minimal Complete Verifiable Example (MVCE)

Command line issued (directly at console):

e3sm_to_cmip -v siv -u /p/user_pub/e3sm/bartoletti1/Operations/5_DatasetGeneration/AltProcess/tmp/v2_1.LR.historical_0251/metadata/historical_r4i1p1f1.json -t /p/user_pub/e3sm/staging/resource/cmor/cmip6-cmor-tables/Tables -o /p/user_pub/e3sm/bartoletti1/Operations/5_DatasetGeneration/AltProcess/tmp/v2_1.LR.historical_0251/product -i /p/user_pub/e3sm/bartoletti1/Operations/5_DatasetGeneration/AltProcess/tmp/v2_1.LR.historical_0251/native_data -s --realm SImon --map /p/user_pub/e3sm/staging/resource/maps/map_EC30to60E2r2_to_cmip6_180x360_aave.20220301.nc >> Local_log 2>&1 &

For future reference, you can use a Python script to invoke e3sm_to_cmip. This makes debugging much easier by enabling the use of the Python debugger. I included examples in the documentation here: https://e3sm-to-cmip.readthedocs.io/en/latest/development-guide.html

I would assume this issue occurs with multiprocessing (serial=False), but I'm not 100% sure. I just noticed the log output says that it is serial.

[chengzhuzhang]

I suspect that the "Resource temporarily unavailable " error is from the use of "lock=False" 0f91fb4. And when testing v1.11.1, things work okay.
With lock=True, large operations hang sometime, with "lock=False" cause "Resource temporarily unavailable " for some variables.

I think you might be right about lock=False causing "Resource temporarily unavailable", possibly due to resource contention with multiprocessing.

Related issues

* [NETCDF - Resource temporarily unavailable  dask/dask#2657](https://github.com/dask/dask/issues/2657)

* [netCDF4 Resource unavailable error pydata/xarray#4304](https://github.com/pydata/xarray/issues/4304)

@tomvothecoder I don't know if this is specific to acme1's file system, but should we consider revert to use 1.11.1 for upcoming e3sm_unified deployment? I think let's decide after a more thorough investigation.

I agree that more investigation is needed before deciding what to do next. v1.11.2 includes another fix for parallel=False to avoid NetCDF: Not a Valid ID with open_mfdataset(), which we need to keep too.

My understanding is that Tony is still using acme1 and datasm with e3sm_to_cmip. Is e3sm_to_cmip used by anybody else in E3SM Unified, besides zppy? If zppy tests pass, then have the option of keeping v1.11.2 for now with the risk of this bug coming up. It sounds like Xylar pressing to move forward with E3SM Unified v1.10.0, so I don't know how much time we have.

Thanks for your insight. Based on Tony's recent operation, I think the zppy application, only including processing atmopshere and land variables are not impacted. So perhaps, we can spend time to resovle this more ocean, sea-ice related error on the side.

[tomvothecoder]

Thanks for your insight. Based on Tony's recent operation, I think the zppy application, only including processing atmopshere and land variables are not impacted. So perhaps, we can spend time to resovle this more ocean, sea-ice related error on the side.

Sounds good. I will convert Tony's command into a Python script and try to do some debugging today.

[TonyB9000]

@tomvothecoder @chengzhuzhang Just a side note - more than half of the v2_1 MPAS jobs (run with datasm back in February) completed successfully. So, I was going to examine the generation dates to see if the first appearance of failures corresponds to any changes I (or others) make have made to e2c.

I am interested in the python-driver you (Tom) mentioned, and will investigate.

[TonyB9000]

@chengzhuzhang Jill wrote "When create this example, you may want to isolate the test data so others can test."

Sorry about that. Yes, I neglected to isolate that data for retesting.

[TonyB9000]

@tomvothecoder @chengzhuzhang Just for the record, we are running into the same errors on Chrysalis - so this is not limited to acme1.

KEY FACT: Circa February 10, both Omon and SImon jobs (v2_1 data) were completing successfully (via datasm postprocess). Soon thereafter, sporadic failures became the norm. I have maintained all of the runlogs for the 296 (v2_1) MPAS jobs, of which 26 are consistently failing. I will seek to characterize the failure dates and types, to see if I can isolate a date upon which to focus.

[chengzhuzhang]

I would suggest to revert the change that sets lock=False. If i understand correctly, this change warrants all mpas variables to fail, no matter on acme1 or Chrysalis.

[TonyB9000]

Turns out, lock=False was set on both acme1 and chrysalis. Setting it to "True" on chrysalis lead to a small change at the end of the stack-trace:

  File "/home/ac.bartoletti1/anaconda3/envs/dsm_prod_e2c_local/lib/python3.12/site-packages/xarray/backends/netCDF4_.py", line 112, in _getitem
    with self.datastore.lock:
^M  0%|          | 0/1 [00:00<?, ?it/s]
'bool' object does not support the context manager protocol