Skip to content
This repository has been archived by the owner on Aug 29, 2023. It is now read-only.

Dynamic kwargs generation as part of the recipe #7

Merged
merged 7 commits into from
May 17, 2022

Conversation

jbusecke
Copy link
Collaborator

@jbusecke jbusecke commented May 14, 2022

This PR reflects work that @cisaacstern and I did together a few days ago + plus some additional work I finished today.

In general this PR enables us to dynamically generate values for the required input kwargs: target_chunks and subset_inputs, which vary widely across the datasets in the CMIP6 archive. This will hopefully enable us to scale this recipe to a larger number of instance ids, which would otherwise present a tremendous burden in terms of maintenance.

The basic logic starts from a list of 'allowed' chunksizes, to ensure that we do not chunk too 'odd', and if possible maintain full years, or multiples of 5 years etc. Currently this is only added for monthly resolution (but we can add others later easily, which will be required for e.g. the daily data in #5 ).

We then pull information of the ESGF API for any given instance id to determine the number of timesteps (from the daterange given in the filename) and the size for each file. Consequently we try to maximize the chunksize to get as close as possible with the given constraints to a target chunksize of 150MB (but never larger!) and designate the chunksize value as target_chunk kwarg.

We apply a similar logic to determine into how many parts we need to divide the input to have an input size <500MB, and parse that into the subset_inputs kwarg.

@pangeo-forge-bot
Copy link
Collaborator

🎉 New recipe runs created for the following recipes at sha fe1649b977aad79a2c20c6a5968f21a82f170819:

@jbusecke
Copy link
Collaborator Author

Ughh sorry for the formatting changes here @cisaacstern. I guess my black was updated?

@jbusecke
Copy link
Collaborator Author

jbusecke commented May 14, 2022

I think we can absorb #6 into this one here? Or should we move this ahead and then add new iids as part of a new PR? Might be cleaner.

@cisaacstern
Copy link
Member

I think we can absorb #6 into this one here? Or should we move this ahead and then add new iids as part of a new PR? Might be cleaner.

Yes, I just closed #6 so that we can add new iids via a new PR once this is merged. So excited for this. Going to run the tests now.

@cisaacstern
Copy link
Member

/run recipe-test recipe_run_id=166

@cisaacstern
Copy link
Member

/run recipe-test recipe_run_id=167

@pangeo-forge-bot
Copy link
Collaborator

✨ A test of your recipe CMIP6.CMIP.CCCma.CanESM5.historical.r1i1p1f1.Omon.zos.gn.v20190429 is now running on Pangeo Forge Cloud!

I'll notify you with a comment on this thread when this test is complete. (This could be a little while...)

In the meantime, you can follow the logs for this recipe run at https://pangeo-forge.org/dashboard/recipe-run/166

@pangeo-forge-bot
Copy link
Collaborator

✨ A test of your recipe CMIP6.CMIP.CCCma.CanESM5.historical.r1i1p1f1.Omon.so.gn.v20190429 is now running on Pangeo Forge Cloud!

I'll notify you with a comment on this thread when this test is complete. (This could be a little while...)

In the meantime, you can follow the logs for this recipe run at https://pangeo-forge.org/dashboard/recipe-run/167

return output_chunksizes[0]


def dynamic_kwarg_generation(
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Wow @jbusecke heroic work here :)

@pangeo-forge-bot
Copy link
Collaborator

Pangeo Forge Cloud told me that our test of your recipe CMIP6.CMIP.CCCma.CanESM5.historical.r1i1p1f1.Omon.zos.gn.v20190429 failed. But don't worry, I'm sure we can fix this!

To see what error caused the failure, please review the logs at https://pangeo-forge.org/dashboard/recipe-run/166

If you haven't yet tried pruning and running your recipe locally, I suggest trying that now.

Please report back on the results of your local testing in a new comment below, and a Pangeo Forge maintainer will help you with next steps!

@pangeo-forge-bot
Copy link
Collaborator

Pangeo Forge Cloud told me that our test of your recipe CMIP6.CMIP.CCCma.CanESM5.historical.r1i1p1f1.Omon.so.gn.v20190429 failed. But don't worry, I'm sure we can fix this!

To see what error caused the failure, please review the logs at https://pangeo-forge.org/dashboard/recipe-run/167

If you haven't yet tried pruning and running your recipe locally, I suggest trying that now.

Please report back on the results of your local testing in a new comment below, and a Pangeo Forge maintainer will help you with next steps!

@pangeo-forge-bot
Copy link
Collaborator

🎉 New recipe runs created for the following recipes at sha f3cb92fad7fcc030009a80197f2ef0d21b417fd3:

@pangeo-forge-bot
Copy link
Collaborator

🎉 New recipe runs created for the following recipes at sha a3067ead55b5578e193750cdd40efb3681f027bf:

@pangeo-forge-bot
Copy link
Collaborator

🎉 New recipe runs created for the following recipes at sha 597b07405ef8f842ae77ea243c66bfa4e13c25eb:

@pangeo-forge-bot
Copy link
Collaborator

🎉 New recipe runs created for the following recipes at sha a6fdc9cb7ba9e9c8c72064e973d599ade4235bbf:

@cisaacstern
Copy link
Member

Failures like we saw on #7 (comment)

Task 'store_chunk[0]': Exception encountered during task execution!
Traceback (most recent call last):
  File "/srv/conda/envs/notebook/lib/python3.9/site-packages/s3fs/core.py", line 261, in _call_s3
    out = await method(**additional_kwargs)
  File "/srv/conda/envs/notebook/lib/python3.9/site-packages/aiobotocore/client.py", line 180, in _make_api_call
    raise error_class(parsed_response, operation_name)
botocore.exceptions.ClientError: An error occurred (InternalError) when calling the CompleteMultipartUpload operation (reached max retries: 4): This multipart completion is already in progress

The above exception was the direct cause of the following exception:

Traceback (most recent call last):
  File "/srv/conda/envs/notebook/lib/python3.9/site-packages/prefect/engine/task_runner.py", line 861, in get_task_run_state
    value = prefect.utilities.executors.run_task_with_timeout(
  File "/srv/conda/envs/notebook/lib/python3.9/site-packages/prefect/utilities/executors.py", line 323, in run_task_with_timeout
    return task.run(*args, **kwargs)  # type: ignore
  File "/usr/local/lib/python3.9/site-packages/registrar/flow.py", line 113, in wrapper
  File "/srv/conda/envs/notebook/lib/python3.9/site-packages/pangeo_forge_recipes/recipes/xarray_zarr.py", line 573, in store_chunk
    zarr_array[zarr_region] = data
  File "/srv/conda/envs/notebook/lib/python3.9/site-packages/zarr/core.py", line 1224, in __setitem__
    self.set_basic_selection(selection, value, fields=fields)
  File "/srv/conda/envs/notebook/lib/python3.9/site-packages/zarr/core.py", line 1319, in set_basic_selection
    return self._set_basic_selection_nd(selection, value, fields=fields)
  File "/srv/conda/envs/notebook/lib/python3.9/site-packages/zarr/core.py", line 1610, in _set_basic_selection_nd
    self._set_selection(indexer, value, fields=fields)
  File "/srv/conda/envs/notebook/lib/python3.9/site-packages/zarr/core.py", line 1682, in _set_selection
    self._chunk_setitems(lchunk_coords, lchunk_selection, chunk_values,
  File "/srv/conda/envs/notebook/lib/python3.9/site-packages/zarr/core.py", line 1874, in _chunk_setitems
    self.chunk_store.setitems(values)
  File "/srv/conda/envs/notebook/lib/python3.9/site-packages/fsspec/mapping.py", line 113, in setitems
    self.fs.pipe(values)
  File "/srv/conda/envs/notebook/lib/python3.9/site-packages/fsspec/asyn.py", line 91, in wrapper
    return sync(self.loop, func, *args, **kwargs)
  File "/srv/conda/envs/notebook/lib/python3.9/site-packages/fsspec/asyn.py", line 71, in sync
    raise return_result
  File "/srv/conda/envs/notebook/lib/python3.9/site-packages/fsspec/asyn.py", line 25, in _runner
    result[0] = await coro
  File "/srv/conda/envs/notebook/lib/python3.9/site-packages/fsspec/asyn.py", line 355, in _pipe
    return await _run_coros_in_chunks(
  File "/srv/conda/envs/notebook/lib/python3.9/site-packages/fsspec/asyn.py", line 249, in _run_coros_in_chunks
    await asyncio.gather(*chunk, return_exceptions=return_exceptions),
  File "/srv/conda/envs/notebook/lib/python3.9/asyncio/tasks.py", line 442, in wait_for
    return await fut
  File "/srv/conda/envs/notebook/lib/python3.9/site-packages/s3fs/core.py", line 928, in _pipe_file
    await self._call_s3(
  File "/srv/conda/envs/notebook/lib/python3.9/site-packages/s3fs/core.py", line 281, in _call_s3
    raise err
OSError: [Errno 121] This multipart completion is already in progress

look like they could be related to not running the latest versions of fsspec/s3fs on Pangeo Forge Cloud. I've just updated to the latest versions of those packages on the cloud backend. Let's see if the latest recipe runs succeed now.

@cisaacstern
Copy link
Member

/run recipe-test recipe_run_id=174

@cisaacstern
Copy link
Member

/run recipe-test recipe_run_id=175

@pangeo-forge-bot
Copy link
Collaborator

✨ A test of your recipe CMIP6.CMIP.CCCma.CanESM5.historical.r1i1p1f1.Omon.so.gn.v20190429 is now running on Pangeo Forge Cloud!

I'll notify you with a comment on this thread when this test is complete. (This could be a little while...)

In the meantime, you can follow the logs for this recipe run at https://pangeo-forge.org/dashboard/recipe-run/175

@pangeo-forge-bot
Copy link
Collaborator

✨ A test of your recipe CMIP6.CMIP.CCCma.CanESM5.historical.r1i1p1f1.Omon.zos.gn.v20190429 is now running on Pangeo Forge Cloud!

I'll notify you with a comment on this thread when this test is complete. (This could be a little while...)

In the meantime, you can follow the logs for this recipe run at https://pangeo-forge.org/dashboard/recipe-run/174

@jbusecke
Copy link
Collaborator Author

🚨 Caveat: I just noticed that the filesize we extract from the ESGF API does not agree with the size we get for cached files.
As an example for `'CMIP6.CMIP.CCCma.CanESM5.historical.r1i1p1f1.Omon.zos.gn.v20190429' the ESGF API gives:

import requests
url = "https://esgf-data.dkrz.de/esg-search/search"
params = {'type': 'File',
 'format': 'application/solr+json',
 'latest': 'true',
 'limit': 500,
 'mip_era': 'CMIP6',
 'activity_id': 'CMIP',
 'institution_id': 'CCCma',
 'source_id': 'CanESM5',
 'experiment_id': 'historical',
 'variant_label': 'r1i1p1f1',
 'table_id': 'Omon',
 'variable_id': 'zos',
 'grid_label': 'gn'}

resp = requests.get(url=url, params=params)
resp.json()['response']['docs'][0]['size']/1e6

gives ~470MB

But when I cache the actual file with this recipe

from feedstock.recipe import recipes
import pathlib
import xarray as xr

recipe = recipes['CMIP6.CMIP.CCCma.CanESM5.historical.r1i1p1f1.Omon.zos.gn.v20190429']
root = pathlib.Path(recipe.storage_config.cache.root_path)
for f in os.listdir(root):
    print(xr.open_dataset(root.joinpath(f)).nbytes/1e6)

I get a bit over 800MB.

I suspect that the API is giving some sort of compressed filesize? Maybe @agstephens can confirm/deny this as somebody who has more experience with the API?

Basically unless we can get an estimate of the filesize as it appears when opened the inferred chunksizes will not adhere to our parameters!

In the short run, I think it is acceptable here, and we should move on to scale to more datasets. Just wanted to document this here. Ultimately pangeo-forge/pangeo-forge-recipes#355 would solve this issue, since we would not have to rely on the ESGF API at all, and could infer these kwargs from the cached files, which should be more accurate.

@pangeo-forge-bot
Copy link
Collaborator

🥳 Hooray! The test execution of your recipe CMIP6.CMIP.CCCma.CanESM5.historical.r1i1p1f1.Omon.zos.gn.v20190429 succeeded.

Here is a static representation of the dataset built by this recipe:

            <xarray.Dataset>
    Dimensions:             (i: 360, j: 291, time: 1980, bnds: 2, vertices: 4)
    Coordinates:
      * i                   (i) int32 0 1 2 3 4 5 6 ... 353 354 355 356 357 358 359
      * j                   (j) int32 0 1 2 3 4 5 6 ... 284 285 286 287 288 289 290
        latitude            (j, i) float64 dask.array<chunksize=(291, 360), meta=np.ndarray>
        longitude           (j, i) float64 dask.array<chunksize=(291, 360), meta=np.ndarray>
      * time                (time) object 1850-01-16 12:00:00 ... 2014-12-16 12:0...
    Dimensions without coordinates: bnds, vertices
    Data variables:
        time_bnds           (time, bnds) object dask.array<chunksize=(660, 2), meta=np.ndarray>
        vertices_latitude   (j, i, vertices) float64 dask.array<chunksize=(291, 360, 4), meta=np.ndarray>
        vertices_longitude  (j, i, vertices) float64 dask.array<chunksize=(291, 360, 4), meta=np.ndarray>
        zos                 (time, j, i) float32 dask.array<chunksize=(660, 291, 360), meta=np.ndarray>
    Attributes: (12/53)
        CCCma_model_hash:            3dedf95315d603326fde4f5340dc0519d80d10c0
        CCCma_parent_runid:          rc3-pictrl
        CCCma_pycmor_hash:           33c30511acc319a98240633965a04ca99c26427e
        CCCma_runid:                 rc3.1-his01
        Conventions:                 CF-1.7 CMIP-6.2
        YMDH_branch_time_in_child:   1850:01:01:00
        ...                          ...
        table_info:                  Creation Date:(20 February 2019) MD5:374fbe5...
        title:                       CanESM5 output prepared for CMIP6
        tracking_id:                 hdl:21.14100/99be0cf0-54b1-405b-b46c-e69c274...
        variable_id:                 zos
        variant_label:               r1i1p1f1
        version:                     v20190429

You can also open this dataset by running the following Python code

import fsspec
import xarray as xr

dataset_public_url = 'https://ncsa.osn.xsede.org/Pangeo/pangeo-forge-test/prod/recipe-run-174/pangeo-forge/cmip6-feedstock/CMIP6.CMIP.CCCma.CanESM5.historical.r1i1p1f1.Omon.zos.gn.v20190429.zarr'
mapper = fsspec.get_mapper(dataset_public_url)
ds = xr.open_zarr(mapper, consolidated=True)
ds

in this badge (or your Python interpreter of choice).

Checklist

Please copy-and-paste the list below into a new comment on this thread, and check the boxes off as you've reviewed them.

Note: This test execution is limited to two increments in the concatenation dimension, so you should expect the length of that dimension (e.g, "time" or equivalent) to be 2.

- [ ] Are the dimension lengths correct?
- [ ] Are all of the expected variables present?
- [ ] Does plotting the data produce a plot that looks like your dataset?
- [ ] Can you run a simple computation/reduction on the data and produce a plausible result?

@cisaacstern
Copy link
Member

The test of variable so (recipe run 175) appears to be hanging on a locking call:



2022-05-16T17:08:32.045347689Z stderr F distributed.nanny - INFO -         Start Nanny at: 'tcp://10.60.5.4:40869'
--
  |   | 2022-05-16T17:08:35.864705186Z stderr F distributed.worker - INFO -       Start worker at:      tcp://10.60.5.4:44849
  |   | 2022-05-16T17:08:35.865213907Z stderr F distributed.worker - INFO -          Listening to:      tcp://10.60.5.4:44849
  |   | 2022-05-16T17:08:35.865650618Z stderr F distributed.worker - INFO -          dashboard at:            10.60.5.4:43609
  |   | 2022-05-16T17:08:35.865719238Z stderr F distributed.worker - INFO - Waiting to connect to: tcp://dask-jovyan-f6caec0b-5.pangeo-forge-columbia-staging-bakery:8786
  |   | 2022-05-16T17:08:35.865763392Z stderr F distributed.worker - INFO - -------------------------------------------------
  |   | 2022-05-16T17:08:35.865783405Z stderr F distributed.worker - INFO -               Threads:                          1
  |   | 2022-05-16T17:08:35.865815153Z stderr F distributed.worker - INFO -                Memory:                   3.90 GiB
  |   | 2022-05-16T17:08:35.865891345Z stderr F distributed.worker - INFO -       Local Directory: /home/jovyan/dask-worker-space/worker-ivd7tn09
  |   | 2022-05-16T17:08:35.865989555Z stderr F distributed.worker - INFO - -------------------------------------------------
  |   | 2022-05-16T17:08:35.884326204Z stderr F distributed.worker - INFO -         Registered to: tcp://dask-jovyan-f6caec0b-5.pangeo-forge-columbia-staging-bakery:8786
  |   | 2022-05-16T17:08:35.884353691Z stderr F distributed.worker - INFO - -------------------------------------------------
  |   | 2022-05-16T17:08:35.885788134Z stderr F distributed.core - INFO - Starting established connection
  |   | 2022-05-16T17:08:50.097265915Z stderr F distributed.core - INFO - Event loop was unresponsive in Worker for 14.13s.  This is often caused by long-running GIL-holding functions or moving large chunks of data. This can cause timeouts and instability.
  |   | 2022-05-16T17:08:50.378408374Z stdout F [2022-05-16 17:08:50+0000] INFO - prefect.CloudTaskRunner \| Task 'store_chunk[9]': Starting task run...
  |   | 2022-05-16T17:08:50.526713057Z stderr F INFO:pangeo_forge_recipes.recipes.xarray_zarr:Opening inputs for chunk Index({DimIndex(name='time', index=9, sequence_len=11, operation=<CombineOp.SUBSET: 3>), DimIndex(name='time', index=0, sequence_len=2, operation=<CombineOp.CONCAT: 2>)})
  |   | 2022-05-16T17:08:50.526997632Z stderr F INFO:pangeo_forge_recipes.recipes.xarray_zarr:Opening input with Xarray Index({DimIndex(name='time', index=0, sequence_len=2, operation=<CombineOp.CONCAT: 2>)}): 'http://esgf-data1.llnl.gov/thredds/fileServer/css03_data/CMIP6/CMIP/CCCma/CanESM5/historical/r1i1p1f1/Omon/so/gn/v20190429/so_Omon_CanESM5_historical_r1i1p1f1_gn_185001-186012.nc'
  |   | 2022-05-16T17:08:50.527110157Z stderr F INFO:pangeo_forge_recipes.storage:Opening 'http://esgf-data1.llnl.gov/thredds/fileServer/css03_data/CMIP6/CMIP/CCCma/CanESM5/historical/r1i1p1f1/Omon/so/gn/v20190429/so_Omon_CanESM5_historical_r1i1p1f1_gn_185001-186012.nc' from cache
  |   | 2022-05-16T17:08:50.527192205Z stderr F DEBUG:pangeo_forge_recipes.storage:file_opener entering first context for <contextlib._GeneratorContextManager object at 0x7efe003d3340>
  |   | 2022-05-16T17:08:50.527688938Z stderr F DEBUG:pangeo_forge_recipes.storage:entering fs.open context manager for pfcsb-bucket/cache/1da029109a61fdb642f8c8ebe28ca0cb-http_esgf-data1.llnl.gov_thredds_fileserver_css03_data_cmip6_cmip_cccma_canesm5_historical_r1i1p1f1_omon_so_gn_v20190429_so_omon_canesm5_historical_r1i1p1f1_gn_185001-186012.nc
  |   | 2022-05-16T17:08:50.618155489Z stderr F DEBUG:pangeo_forge_recipes.storage:FSSpecTarget.open yielding <File-like object GCSFileSystem, pfcsb-bucket/cache/1da029109a61fdb642f8c8ebe28ca0cb-http_esgf-data1.llnl.gov_thredds_fileserver_css03_data_cmip6_cmip_cccma_canesm5_historical_r1i1p1f1_omon_so_gn_v20190429_so_omon_canesm5_historical_r1i1p1f1_gn_185001-186012.nc>
  |   | 2022-05-16T17:08:50.618492337Z stderr F DEBUG:pangeo_forge_recipes.storage:file_opener entering second context for <File-like object GCSFileSystem, pfcsb-bucket/cache/1da029109a61fdb642f8c8ebe28ca0cb-http_esgf-data1.llnl.gov_thredds_fileserver_css03_data_cmip6_cmip_cccma_canesm5_historical_r1i1p1f1_omon_so_gn_v20190429_so_omon_canesm5_historical_r1i1p1f1_gn_185001-186012.nc>
  |   | 2022-05-16T17:08:50.61881968Z stderr F DEBUG:pangeo_forge_recipes.recipes.xarray_zarr:about to enter xr.open_dataset context on <File-like object GCSFileSystem, pfcsb-bucket/cache/1da029109a61fdb642f8c8ebe28ca0cb-http_esgf-data1.llnl.gov_thredds_fileserver_css03_data_cmip6_cmip_cccma_canesm5_historical_r1i1p1f1_omon_so_gn_v20190429_so_omon_canesm5_historical_r1i1p1f1_gn_185001-186012.nc>
  |   | 2022-05-16T17:08:53.65248022Z stderr F DEBUG:pangeo_forge_recipes.recipes.xarray_zarr:successfully opened dataset
  |   | 2022-05-16T17:08:53.65677328Z stderr F DEBUG:pangeo_forge_recipes.recipes.xarray_zarr:<xarray.Dataset>
  |   | 2022-05-16T17:08:53.656868638Z stderr F Dimensions:             (time: 132, bnds: 2, lev: 45, j: 291, i: 360, vertices: 4)
  |   | 2022-05-16T17:08:53.656883838Z stderr F Coordinates:
  |   | 2022-05-16T17:08:53.656891731Z stderr F   * time                (time) object 1850-01-16 12:00:00 ... 1860-12-16 12:0...
  |   | 2022-05-16T17:08:53.656901631Z stderr F   * lev                 (lev) float64 3.047 9.454 16.36 ... 5.375e+03 5.625e+03
  |   | 2022-05-16T17:08:53.656908525Z stderr F   * j                   (j) int32 0 1 2 3 4 5 6 ... 284 285 286 287 288 289 290
  |   | 2022-05-16T17:08:53.656915432Z stderr F   * i                   (i) int32 0 1 2 3 4 5 6 ... 353 354 355 356 357 358 359
  |   | 2022-05-16T17:08:53.656923305Z stderr F     latitude            (j, i) float64 ...
  |   | 2022-05-16T17:08:53.656929599Z stderr F     longitude           (j, i) float64 ...
  |   | 2022-05-16T17:08:53.656935414Z stderr F Dimensions without coordinates: bnds, vertices
  |   | 2022-05-16T17:08:53.656942011Z stderr F Data variables:
  |   | 2022-05-16T17:08:53.656948294Z stderr F     time_bnds           (time, bnds) object ...
  |   | 2022-05-16T17:08:53.656954186Z stderr F     lev_bnds            (lev, bnds) float64 ...
  |   | 2022-05-16T17:08:53.656960189Z stderr F     vertices_latitude   (j, i, vertices) float64 ...
  |   | 2022-05-16T17:08:53.656966589Z stderr F     vertices_longitude  (j, i, vertices) float64 ...
  |   | 2022-05-16T17:08:53.656972563Z stderr F     so                  (time, lev, j, i) float32 ...
  |   | 2022-05-16T17:08:53.656978582Z stderr F Attributes: (12/53)
  |   | 2022-05-16T17:08:53.656985001Z stderr F     CCCma_model_hash:            3dedf95315d603326fde4f5340dc0519d80d10c0
  |   | 2022-05-16T17:08:53.656991514Z stderr F     CCCma_parent_runid:          rc3-pictrl
  |   | 2022-05-16T17:08:53.65699796Z stderr F     CCCma_pycmor_hash:           33c30511acc319a98240633965a04ca99c26427e
  |   | 2022-05-16T17:08:53.657004571Z stderr F     CCCma_runid:                 rc3.1-his01
  |   | 2022-05-16T17:08:53.657010528Z stderr F     Conventions:                 CF-1.7 CMIP-6.2
  |   | 2022-05-16T17:08:53.657016428Z stderr F     YMDH_branch_time_in_child:   1850:01:01:00
  |   | 2022-05-16T17:08:53.65702242Z stderr F     ...                          ...
  |   | 2022-05-16T17:08:53.657032886Z stderr F     variable_id:                 so
  |   | 2022-05-16T17:08:53.65703902Z stderr F     variant_label:               r1i1p1f1
  |   | 2022-05-16T17:08:53.657044959Z stderr F     version:                     v20190429
  |   | 2022-05-16T17:08:53.657051392Z stderr F     license:                     CMIP6 model data produced by The Government ...
  |   | 2022-05-16T17:08:53.657057468Z stderr F     cmor_version:                3.4.0
  |   | 2022-05-16T17:08:53.657063806Z stderr F     tracking_id:                 hdl:21.14100/afebd704-0f03-4b26-98c5-a62f564...
  |   | 2022-05-16T17:08:53.657105023Z stderr F INFO:pangeo_forge_recipes.recipes.xarray_zarr:Subsetting input according to time-9
  |   | 2022-05-16T17:08:53.657132293Z stderr F DEBUG:pangeo_forge_recipes.recipes.xarray_zarr:Subsetting dataset with indexer {'time': slice(108, 120, None)}
  |   | 2022-05-16T17:08:53.662079904Z stderr F INFO:pangeo_forge_recipes.recipes.xarray_zarr:Combining inputs for chunk 'Index({DimIndex(name='time', index=9, sequence_len=11, operation=<CombineOp.SUBSET: 3>), DimIndex(name='time', index=0, sequence_len=2, operation=<CombineOp.CONCAT: 2>)})'
  |   | 2022-05-16T17:08:53.66587694Z stderr F DEBUG:pangeo_forge_recipes.recipes.xarray_zarr:<xarray.Dataset>
  |   | 2022-05-16T17:08:53.666140816Z stderr F Dimensions:             (time: 12, bnds: 2, lev: 45, j: 291, i: 360, vertices: 4)
  |   | 2022-05-16T17:08:53.666387813Z stderr F Coordinates:
  |   | 2022-05-16T17:08:53.66653475Z stderr F   * time                (time) object 1859-01-16 12:00:00 ... 1859-12-16 12:0...
  |   | 2022-05-16T17:08:53.666629295Z stderr F   * lev                 (lev) float64 3.047 9.454 16.36 ... 5.375e+03 5.625e+03
  |   | 2022-05-16T17:08:53.666709762Z stderr F   * j                   (j) int32 0 1 2 3 4 5 6 ... 284 285 286 287 288 289 290
  |   | 2022-05-16T17:08:53.666863555Z stderr F   * i                   (i) int32 0 1 2 3 4 5 6 ... 353 354 355 356 357 358 359
  |   | 2022-05-16T17:08:53.666897863Z stderr F     latitude            (j, i) float64 dask.array<chunksize=(291, 360), meta=np.ndarray>
  |   | 2022-05-16T17:08:53.666906605Z stderr F     longitude           (j, i) float64 dask.array<chunksize=(291, 360), meta=np.ndarray>
  |   | 2022-05-16T17:08:53.666914413Z stderr F Dimensions without coordinates: bnds, vertices
  |   | 2022-05-16T17:08:53.666921931Z stderr F Data variables:
  |   | 2022-05-16T17:08:53.666932759Z stderr F     time_bnds           (time, bnds) object dask.array<chunksize=(12, 2), meta=np.ndarray>
  |   | 2022-05-16T17:08:53.666940903Z stderr F     lev_bnds            (lev, bnds) float64 dask.array<chunksize=(45, 2), meta=np.ndarray>
  |   | 2022-05-16T17:08:53.666947818Z stderr F     vertices_latitude   (j, i, vertices) float64 dask.array<chunksize=(291, 360, 4), meta=np.ndarray>
  |   | 2022-05-16T17:08:53.66695445Z stderr F     vertices_longitude  (j, i, vertices) float64 dask.array<chunksize=(291, 360, 4), meta=np.ndarray>
  |   | 2022-05-16T17:08:53.666960772Z stderr F     so                  (time, lev, j, i) float32 dask.array<chunksize=(12, 45, 291, 360), meta=np.ndarray>
  |   | 2022-05-16T17:08:53.666967826Z stderr F Attributes: (12/53)
  |   | 2022-05-16T17:08:53.66697454Z stderr F     CCCma_model_hash:            3dedf95315d603326fde4f5340dc0519d80d10c0
  |   | 2022-05-16T17:08:53.666981695Z stderr F     CCCma_parent_runid:          rc3-pictrl
  |   | 2022-05-16T17:08:53.666988545Z stderr F     CCCma_pycmor_hash:           33c30511acc319a98240633965a04ca99c26427e
  |   | 2022-05-16T17:08:53.666995301Z stderr F     CCCma_runid:                 rc3.1-his01
  |   | 2022-05-16T17:08:53.667001363Z stderr F     Conventions:                 CF-1.7 CMIP-6.2
  |   | 2022-05-16T17:08:53.667007342Z stderr F     YMDH_branch_time_in_child:   1850:01:01:00
  |   | 2022-05-16T17:08:53.667013835Z stderr F     ...                          ...
  |   | 2022-05-16T17:08:53.667020076Z stderr F     variable_id:                 so
  |   | 2022-05-16T17:08:53.667026382Z stderr F     variant_label:               r1i1p1f1
  |   | 2022-05-16T17:08:53.667032646Z stderr F     version:                     v20190429
  |   | 2022-05-16T17:08:53.667038793Z stderr F     license:                     CMIP6 model data produced by The Government ...
  |   | 2022-05-16T17:08:53.66704561Z stderr F     cmor_version:                3.4.0
  |   | 2022-05-16T17:08:53.667051879Z stderr F     tracking_id:                 hdl:21.14100/afebd704-0f03-4b26-98c5-a62f564...
  |   | 2022-05-16T17:08:54.087800912Z stderr F DEBUG:pangeo_forge_recipes.recipes.xarray_zarr:Converting variable time of 96 bytes to `numpy.ndarray`
  |   | 2022-05-16T17:08:54.08858715Z stderr F DEBUG:pangeo_forge_recipes.recipes.xarray_zarr:Acquiring locks []
  |   | 2022-05-16T17:08:54.099032249Z stderr F INFO:pangeo_forge_recipes.recipes.xarray_zarr:Storing variable time chunk Index({DimIndex(name='time', index=9, sequence_len=11, operation=<CombineOp.SUBSET: 3>), DimIndex(name='time', index=0, sequence_len=2, operation=<CombineOp.CONCAT: 2>)}) to Zarr region (slice(108, 120, None),)
  |   | 2022-05-16T17:08:54.412029392Z stderr F DEBUG:pangeo_forge_recipes.recipes.xarray_zarr:Converting variable time_bnds of 192 bytes to `numpy.ndarray`
  |   | 2022-05-16T17:08:54.412414761Z stderr F DEBUG:pangeo_forge_recipes.recipes.xarray_zarr:Acquiring locks []
  |   | 2022-05-16T17:08:54.412470503Z stderr F INFO:pangeo_forge_recipes.recipes.xarray_zarr:Storing variable time_bnds chunk Index({DimIndex(name='time', index=9, sequence_len=11, operation=<CombineOp.SUBSET: 3>), DimIndex(name='time', index=0, sequence_len=2, operation=<CombineOp.CONCAT: 2>)}) to Zarr region (slice(108, 120, None), slice(None, None, None))
  |   | 2022-05-16T17:08:54.623798648Z stderr F DEBUG:pangeo_forge_recipes.recipes.xarray_zarr:Converting variable so of 226281600 bytes to `numpy.ndarray`
  |   | 2022-05-16T17:09:04.037535319Z stderr F DEBUG:pangeo_forge_recipes.recipes.xarray_zarr:Acquiring locks []
  |   | 2022-05-16T17:09:04.037855989Z stderr F INFO:pangeo_forge_recipes.recipes.xarray_zarr:Storing variable so chunk Index({DimIndex(name='time', index=9, sequence_len=11, operation=<CombineOp.SUBSET: 3>), DimIndex(name='time', index=0, sequence_len=2, operation=<CombineOp.CONCAT: 2>)}) to Zarr region (slice(108, 120, None), slice(None, None, None), slice(None, None, None), slice(None, None, None))
  |   | 2022-05-16T17:09:06.359438139Z stderr F DEBUG:pangeo_forge_recipes.storage:file_opener yielded
  |   | 2022-05-16T17:09:06.359521176Z stderr F DEBUG:pangeo_forge_recipes.storage:FSSpecTarget.open yielded
  |   | 2022-05-16T17:09:06.359569989Z stderr F DEBUG:pangeo_forge_recipes.storage:opener done
  |   | 2022-05-16T17:09:06.505744539Z stdout F [2022-05-16 17:09:06+0000] INFO - prefect.CloudTaskRunner \| Task 'store_chunk[9]': Finished task run for task with final state: 'Success'
  |   | 2022-05-16T17:09:06.505881804Z stderr F INFO:prefect.CloudTaskRunner:Task 'store_chunk[9]': Finished task run for task with final state: 'Success'
  |   | 2022-05-16T17:09:08.695575368Z stdout F [2022-05-16 17:09:08+0000] INFO - prefect.CloudTaskRunner \| Task 'store_chunk[14]': Starting task run...
  |   | 2022-05-16T17:09:08.696005034Z stderr F INFO:prefect.CloudTaskRunner:Task 'store_chunk[14]': Starting task run...
  |   | 2022-05-16T17:09:08.830067663Z stderr F INFO:pangeo_forge_recipes.recipes.xarray_zarr:Opening inputs for chunk Index({DimIndex(name='time', index=3, sequence_len=11, operation=<CombineOp.SUBSET: 3>), DimIndex(name='time', index=1, sequence_len=2, operation=<CombineOp.CONCAT: 2>)})
  |   | 2022-05-16T17:09:08.830323015Z stderr F INFO:pangeo_forge_recipes.recipes.xarray_zarr:Opening input with Xarray Index({DimIndex(name='time', index=1, sequence_len=2, operation=<CombineOp.CONCAT: 2>)}): 'http://crd-esgf-drc.ec.gc.ca/thredds/fileServer/esgC_dataroot/AR6/CMIP6/CMIP/CCCma/CanESM5/historical/r1i1p1f1/Omon/so/gn/v20190429/so_Omon_CanESM5_historical_r1i1p1f1_gn_186101-187012.nc'
  |   | 2022-05-16T17:09:08.830381485Z stderr F INFO:pangeo_forge_recipes.storage:Opening 'http://crd-esgf-drc.ec.gc.ca/thredds/fileServer/esgC_dataroot/AR6/CMIP6/CMIP/CCCma/CanESM5/historical/r1i1p1f1/Omon/so/gn/v20190429/so_Omon_CanESM5_historical_r1i1p1f1_gn_186101-187012.nc' from cache
  |   | 2022-05-16T17:09:08.830494434Z stderr F DEBUG:pangeo_forge_recipes.storage:file_opener entering first context for <contextlib._GeneratorContextManager object at 0x7efdec804820>
  |   | 2022-05-16T17:09:08.830641087Z stderr F DEBUG:pangeo_forge_recipes.storage:entering fs.open context manager for pfcsb-bucket/cache/c54bd486f988071a0795855ebf8873aa-http_crd-esgf-drc.ec.gc.ca_thredds_fileserver_esgc_dataroot_ar6_cmip6_cmip_cccma_canesm5_historical_r1i1p1f1_omon_so_gn_v20190429_so_omon_canesm5_historical_r1i1p1f1_gn_186101-187012.nc
  |   | 2022-05-16T17:09:08.850532914Z stderr F DEBUG:pangeo_forge_recipes.storage:FSSpecTarget.open yielding <File-like object GCSFileSystem, pfcsb-bucket/cache/c54bd486f988071a0795855ebf8873aa-http_crd-esgf-drc.ec.gc.ca_thredds_fileserver_esgc_dataroot_ar6_cmip6_cmip_cccma_canesm5_historical_r1i1p1f1_omon_so_gn_v20190429_so_omon_canesm5_historical_r1i1p1f1_gn_186101-187012.nc>
  |   | 2022-05-16T17:09:08.850588625Z stderr F DEBUG:pangeo_forge_recipes.storage:file_opener entering second context for <File-like object GCSFileSystem, pfcsb-bucket/cache/c54bd486f988071a0795855ebf8873aa-http_crd-esgf-drc.ec.gc.ca_thredds_fileserver_esgc_dataroot_ar6_cmip6_cmip_cccma_canesm5_historical_r1i1p1f1_omon_so_gn_v20190429_so_omon_canesm5_historical_r1i1p1f1_gn_186101-187012.nc>
  |   | 2022-05-16T17:09:08.850656446Z stderr F DEBUG:pangeo_forge_recipes.recipes.xarray_zarr:about to enter xr.open_dataset context on <File-like object GCSFileSystem, pfcsb-bucket/cache/c54bd486f988071a0795855ebf8873aa-http_crd-esgf-drc.ec.gc.ca_thredds_fileserver_esgc_dataroot_ar6_cmip6_cmip_cccma_canesm5_historical_r1i1p1f1_omon_so_gn_v20190429_so_omon_canesm5_historical_r1i1p1f1_gn_186101-187012.nc>
  |   | 2022-05-16T17:09:09.581815413Z stderr F DEBUG:pangeo_forge_recipes.recipes.xarray_zarr:successfully opened dataset
  |   | 2022-05-16T17:09:09.589451429Z stderr F DEBUG:pangeo_forge_recipes.recipes.xarray_zarr:<xarray.Dataset>
  |   | 2022-05-16T17:09:09.589515861Z stderr F Dimensions:             (time: 120, bnds: 2, lev: 45, j: 291, i: 360, vertices: 4)
  |   | 2022-05-16T17:09:09.589533907Z stderr F Coordinates:
  |   | 2022-05-16T17:09:09.589543194Z stderr F   * time                (time) object 1861-01-16 12:00:00 ... 1870-12-16 12:0...
  |   | 2022-05-16T17:09:09.589550805Z stderr F   * lev                 (lev) float64 3.047 9.454 16.36 ... 5.375e+03 5.625e+03
  |   | 2022-05-16T17:09:09.589558333Z stderr F   * j                   (j) int32 0 1 2 3 4 5 6 ... 284 285 286 287 288 289 290
  |   | 2022-05-16T17:09:09.589564828Z stderr F   * i                   (i) int32 0 1 2 3 4 5 6 ... 353 354 355 356 357 358 359
  |   | 2022-05-16T17:09:09.589572731Z stderr F     latitude            (j, i) float64 ...
  |   | 2022-05-16T17:09:09.589588963Z stderr F     longitude           (j, i) float64 ...
  |   | 2022-05-16T17:09:09.589595151Z stderr F Dimensions without coordinates: bnds, vertices
  |   | 2022-05-16T17:09:09.589601014Z stderr F Data variables:
  |   | 2022-05-16T17:09:09.589607504Z stderr F     time_bnds           (time, bnds) object ...
  |   | 2022-05-16T17:09:09.589613071Z stderr F     lev_bnds            (lev, bnds) float64 ...
  |   | 2022-05-16T17:09:09.589618574Z stderr F     vertices_latitude   (j, i, vertices) float64 ...
  |   | 2022-05-16T17:09:09.589638425Z stderr F     vertices_longitude  (j, i, vertices) float64 ...
  |   | 2022-05-16T17:09:09.589643888Z stderr F     so                  (time, lev, j, i) float32 ...
  |   | 2022-05-16T17:09:09.589649429Z stderr F Attributes: (12/53)
  |   | 2022-05-16T17:09:09.589656168Z stderr F     CCCma_model_hash:            3dedf95315d603326fde4f5340dc0519d80d10c0
  |   | 2022-05-16T17:09:09.589663213Z stderr F     CCCma_parent_runid:          rc3-pictrl
  |   | 2022-05-16T17:09:09.589671223Z stderr F     CCCma_pycmor_hash:           33c30511acc319a98240633965a04ca99c26427e
  |   | 2022-05-16T17:09:09.589678396Z stderr F     CCCma_runid:                 rc3.1-his01
  |   | 2022-05-16T17:09:09.589685208Z stderr F     Conventions:                 CF-1.7 CMIP-6.2
  |   | 2022-05-16T17:09:09.589692287Z stderr F     YMDH_branch_time_in_child:   1850:01:01:00
  |   | 2022-05-16T17:09:09.589733083Z stderr F     ...                          ...
  |   | 2022-05-16T17:09:09.58974378Z stderr F     variable_id:                 so
  |   | 2022-05-16T17:09:09.589751831Z stderr F     variant_label:               r1i1p1f1
  |   | 2022-05-16T17:09:09.589760053Z stderr F     version:                     v20190429
  |   | 2022-05-16T17:09:09.589766757Z stderr F     license:                     CMIP6 model data produced by The Government ...
  |   | 2022-05-16T17:09:09.589773429Z stderr F     cmor_version:                3.4.0
  |   | 2022-05-16T17:09:09.589789133Z stderr F     tracking_id:                 hdl:21.14100/46f06738-42b3-4696-a2bc-cb3878f...
  |   | 2022-05-16T17:09:09.58987526Z stderr F INFO:pangeo_forge_recipes.recipes.xarray_zarr:Subsetting input according to time-3
  |   | 2022-05-16T17:09:09.589894063Z stderr F DEBUG:pangeo_forge_recipes.recipes.xarray_zarr:Subsetting dataset with indexer {'time': slice(30, 40, None)}
  |   | 2022-05-16T17:09:09.593882758Z stderr F INFO:pangeo_forge_recipes.recipes.xarray_zarr:Combining inputs for chunk 'Index({DimIndex(name='time', index=3, sequence_len=11, operation=<CombineOp.SUBSET: 3>), DimIndex(name='time', index=1, sequence_len=2, operation=<CombineOp.CONCAT: 2>)})'
  |   | 2022-05-16T17:09:09.5967524Z stderr F DEBUG:pangeo_forge_recipes.recipes.xarray_zarr:<xarray.Dataset>
  |   | 2022-05-16T17:09:09.596784692Z stderr F Dimensions:             (time: 10, bnds: 2, lev: 45, j: 291, i: 360, vertices: 4)
  |   | 2022-05-16T17:09:09.596794134Z stderr F Coordinates:
  |   | 2022-05-16T17:09:09.596801901Z stderr F   * time                (time) object 1863-07-16 12:00:00 ... 1864-04-16 00:0...
  |   | 2022-05-16T17:09:09.596809115Z stderr F   * lev                 (lev) float64 3.047 9.454 16.36 ... 5.375e+03 5.625e+03
  |   | 2022-05-16T17:09:09.596833078Z stderr F   * j                   (j) int32 0 1 2 3 4 5 6 ... 284 285 286 287 288 289 290
  |   | 2022-05-16T17:09:09.596851703Z stderr F   * i                   (i) int32 0 1 2 3 4 5 6 ... 353 354 355 356 357 358 359
  |   | 2022-05-16T17:09:09.596859925Z stderr F     latitude            (j, i) float64 dask.array<chunksize=(291, 360), meta=np.ndarray>
  |   | 2022-05-16T17:09:09.596866186Z stderr F     longitude           (j, i) float64 dask.array<chunksize=(291, 360), meta=np.ndarray>
  |   | 2022-05-16T17:09:09.596873068Z stderr F Dimensions without coordinates: bnds, vertices
  |   | 2022-05-16T17:09:09.596880696Z stderr F Data variables:
  |   | 2022-05-16T17:09:09.59688746Z stderr F     time_bnds           (time, bnds) object dask.array<chunksize=(10, 2), meta=np.ndarray>
  |   | 2022-05-16T17:09:09.596895417Z stderr F     lev_bnds            (lev, bnds) float64 dask.array<chunksize=(45, 2), meta=np.ndarray>
  |   | 2022-05-16T17:09:09.59690272Z stderr F     vertices_latitude   (j, i, vertices) float64 dask.array<chunksize=(291, 360, 4), meta=np.ndarray>
  |   | 2022-05-16T17:09:09.596909791Z stderr F     vertices_longitude  (j, i, vertices) float64 dask.array<chunksize=(291, 360, 4), meta=np.ndarray>
  |   | 2022-05-16T17:09:09.596916463Z stderr F     so                  (time, lev, j, i) float32 dask.array<chunksize=(10, 45, 291, 360), meta=np.ndarray>
  |   | 2022-05-16T17:09:09.596924343Z stderr F Attributes: (12/53)
  |   | 2022-05-16T17:09:09.596931292Z stderr F     CCCma_model_hash:            3dedf95315d603326fde4f5340dc0519d80d10c0
  |   | 2022-05-16T17:09:09.596937523Z stderr F     CCCma_parent_runid:          rc3-pictrl
  |   | 2022-05-16T17:09:09.59694424Z stderr F     CCCma_pycmor_hash:           33c30511acc319a98240633965a04ca99c26427e
  |   | 2022-05-16T17:09:09.596952226Z stderr F     CCCma_runid:                 rc3.1-his01
  |   | 2022-05-16T17:09:09.596959638Z stderr F     Conventions:                 CF-1.7 CMIP-6.2
  |   | 2022-05-16T17:09:09.596966389Z stderr F     YMDH_branch_time_in_child:   1850:01:01:00
  |   | 2022-05-16T17:09:09.596973284Z stderr F     ...                          ...
  |   | 2022-05-16T17:09:09.596981697Z stderr F     variable_id:                 so
  |   | 2022-05-16T17:09:09.596989521Z stderr F     variant_label:               r1i1p1f1
  |   | 2022-05-16T17:09:09.596997523Z stderr F     version:                     v20190429
  |   | 2022-05-16T17:09:09.597005149Z stderr F     license:                     CMIP6 model data produced by The Government ...
  |   | 2022-05-16T17:09:09.597013722Z stderr F     cmor_version:                3.4.0
  |   | 2022-05-16T17:09:09.597020682Z stderr F     tracking_id:                 hdl:21.14100/46f06738-42b3-4696-a2bc-cb3878f...
  |   | 2022-05-16T17:09:09.826879508Z stderr F DEBUG:pangeo_forge_recipes.recipes.xarray_zarr:Converting variable time of 80 bytes to `numpy.ndarray`
  |   | 2022-05-16T17:09:09.826957556Z stderr F DEBUG:pangeo_forge_recipes.recipes.xarray_zarr:Acquiring locks ['time-time-13', 'time-time-14']
  |   | 2022-05-16T17:09:09.827269868Z stderr F DEBUG:pangeo_forge_recipes.utils:Acquiring lock pangeo-forge-time-time-13...
  |   | 2022-05-16T17:09:09.829364089Z stderr F DEBUG:pangeo_forge_recipes.utils:Acquired lock pangeo-forge-time-time-13
  |   | 2022-05-16T17:09:09.829446607Z stderr F DEBUG:pangeo_forge_recipes.utils:Acquiring lock pangeo-forge-time-time-14...
  |   | 2022-05-16T17:09:09.830957194Z stderr F DEBUG:pangeo_forge_recipes.utils:Acquired lock pangeo-forge-time-time-14
  |   | 2022-05-16T17:09:09.831070158Z stderr F INFO:pangeo_forge_recipes.recipes.xarray_zarr:Storing variable time chunk Index({DimIndex(name='time', index=3, sequence_len=11, operation=<CombineOp.SUBSET: 3>), DimIndex(name='time', index=1, sequence_len=2, operation=<CombineOp.CONCAT: 2>)}) to Zarr region (slice(162, 172, None),)
  |   | 2022-05-16T17:09:10.109853614Z stderr F DEBUG:pangeo_forge_recipes.utils:Released lock pangeo-forge-time-time-13
  |   | 2022-05-16T17:09:10.111016531Z stderr F DEBUG:pangeo_forge_recipes.utils:Released lock pangeo-forge-time-time-14
  |   | 2022-05-16T17:09:10.229145566Z stderr F DEBUG:pangeo_forge_recipes.recipes.xarray_zarr:Converting variable time_bnds of 160 bytes to `numpy.ndarray`
  |   | 2022-05-16T17:09:10.229288348Z stderr F DEBUG:pangeo_forge_recipes.recipes.xarray_zarr:Acquiring locks ['time_bnds-time-13', 'time_bnds-time-14']
  |   | 2022-05-16T17:09:10.229553903Z stderr F DEBUG:pangeo_forge_recipes.utils:Acquiring lock pangeo-forge-time_bnds-time-13...
  |   | 2022-05-16T17:09:10.23121724Z stderr F DEBUG:pangeo_forge_recipes.utils:Acquired lock pangeo-forge-time_bnds-time-13
  |   | 2022-05-16T17:09:10.231296115Z stderr F DEBUG:pangeo_forge_recipes.utils:Acquiring lock pangeo-forge-time_bnds-time-14...
  |   | 2022-05-16T17:09:10.232772982Z stderr F DEBUG:pangeo_forge_recipes.utils:Acquired lock pangeo-forge-time_bnds-time-14
  |   | 2022-05-16T17:09:10.232830064Z stderr F INFO:pangeo_forge_recipes.recipes.xarray_zarr:Storing variable time_bnds chunk Index({DimIndex(name='time', index=3, sequence_len=11, operation=<CombineOp.SUBSET: 3>), DimIndex(name='time', index=1, sequence_len=2, operation=<CombineOp.CONCAT: 2>)}) to Zarr region (slice(162, 172, None), slice(None, None, None))
  |   | 2022-05-16T17:09:10.466183116Z stderr F DEBUG:pangeo_forge_recipes.utils:Released lock pangeo-forge-time_bnds-time-13
  |   | 2022-05-16T17:09:10.468273041Z stderr F DEBUG:pangeo_forge_recipes.utils:Released lock pangeo-forge-time_bnds-time-14
  |   | 2022-05-16T17:09:10.545387646Z stderr F DEBUG:pangeo_forge_recipes.recipes.xarray_zarr:Converting variable so of 188568000 bytes to `numpy.ndarray`
  |   | 2022-05-16T17:09:18.837153009Z stderr F DEBUG:pangeo_forge_recipes.recipes.xarray_zarr:Acquiring locks ['so-time-13', 'so-time-14']
  |   | 2022-05-16T17:09:18.837872847Z stderr F DEBUG:pangeo_forge_recipes.utils:Acquiring lock pangeo-forge-so-time-13...

I will manually cancel this test now, since it's been stuck here for many hours.

This seems to be a different issue than those reported in pangeo-forge/pangeo-forge-recipes#358.

As a short-term workaround, I wonder if there's a way to tune the so kwargs to avoid locking?

@jbusecke
Copy link
Collaborator Author

As a short-term workaround, I wonder if there's a way to tune the so kwargs to avoid locking?

I would think we could, but I need to understand what causes the locking, better.
Is this the case when two file subsets (the result of subset_inputs) overlap in a resulting chunk, or when a resulting chunk is drawing data from two files (this should not happen at all in this case, since the value is 12, and all files are evenly divided by 12).

Once I know what to tune for, I can definitely try to address this.

@jbusecke
Copy link
Collaborator Author

I wonder if there is a way to specifiy the subsets in a more robust way. If I could say e.g. subset_input_chunks=12, and each file would be split into a certain number of 12 element chunks, that would be a lot more transparent IMO.
In this case, I would go for a 'maybe-slow-but-locking-safe' config, where each subset is basically a target chunk. If we can achieve that, I would be surprised if the locking would still be invoked.

@pangeo-forge-bot
Copy link
Collaborator

🎉 New recipe runs created for the following recipes at sha 6f1040996379811c360a7e5be276828e81f859d8:

@jbusecke
Copy link
Collaborator Author

jbusecke commented May 17, 2022

I just pushed a simplified logic for the subsetting. I previously tried to find divisors that would result in subsets that are evenly dividable into the target_chunks, but with the fact that the first file contains 11 years and all others 10 for the ...so... dataset, that is just not possible.
The currentl logic should spit out subset_inputs=2 for this case, and I would like to see if that works. If it doesnt we can consider two options before merging this:

  • Relax the MAX_SUBSET_SIZE=1e9 to 1GB. This would eliminate the need to subset at all here (filesize is ~800-700MB each)
  • Removing the ...so... recipe and carry an issue to document this failure.

@cisaacstern
Copy link
Member

/run recipe-test recipe_run_id=177

@cisaacstern
Copy link
Member

and I will also do 176, just to be sure that still works

@cisaacstern
Copy link
Member

/run recipe-test recipe_run_id=176

@pangeo-forge-bot
Copy link
Collaborator

✨ A test of your recipe CMIP6.CMIP.CCCma.CanESM5.historical.r1i1p1f1.Omon.so.gn.v20190429 is now running on Pangeo Forge Cloud!

I'll notify you with a comment on this thread when this test is complete. (This could be a little while...)

In the meantime, you can follow the logs for this recipe run at https://pangeo-forge.org/dashboard/recipe-run/177

@pangeo-forge-bot
Copy link
Collaborator

✨ A test of your recipe CMIP6.CMIP.CCCma.CanESM5.historical.r1i1p1f1.Omon.zos.gn.v20190429 is now running on Pangeo Forge Cloud!

I'll notify you with a comment on this thread when this test is complete. (This could be a little while...)

In the meantime, you can follow the logs for this recipe run at https://pangeo-forge.org/dashboard/recipe-run/176

@cisaacstern
Copy link
Member

From the Pangeo Forge Cloud backend logs:

Dynamically determined kwargs: ***'target_chunks': ***'time': 12***, 'subset_inputs': ***'time': 2*** for CMIP6.CMIP.CCCma.CanESM5.historical.r1i1p1f1.Omon.so.gn.v20190429

which looks promising!

@pangeo-forge-bot
Copy link
Collaborator

Pangeo Forge Cloud told me that our test of your recipe CMIP6.CMIP.CCCma.CanESM5.historical.r1i1p1f1.Omon.so.gn.v20190429 failed. But don't worry, I'm sure we can fix this!

To see what error caused the failure, please review the logs at https://pangeo-forge.org/dashboard/recipe-run/177

If you haven't yet tried pruning and running your recipe locally, I suggest trying that now.

Please report back on the results of your local testing in a new comment below, and a Pangeo Forge maintainer will help you with next steps!

@pangeo-forge-bot
Copy link
Collaborator

🥳 Hooray! The test execution of your recipe CMIP6.CMIP.CCCma.CanESM5.historical.r1i1p1f1.Omon.zos.gn.v20190429 succeeded.

Here is a static representation of the dataset built by this recipe:

            <xarray.Dataset>
    Dimensions:             (i: 360, j: 291, time: 1980, bnds: 2, vertices: 4)
    Coordinates:
      * i                   (i) int32 0 1 2 3 4 5 6 ... 353 354 355 356 357 358 359
      * j                   (j) int32 0 1 2 3 4 5 6 ... 284 285 286 287 288 289 290
        latitude            (j, i) float64 dask.array<chunksize=(291, 360), meta=np.ndarray>
        longitude           (j, i) float64 dask.array<chunksize=(291, 360), meta=np.ndarray>
      * time                (time) object 1850-01-16 12:00:00 ... 2014-12-16 12:0...
    Dimensions without coordinates: bnds, vertices
    Data variables:
        time_bnds           (time, bnds) object dask.array<chunksize=(660, 2), meta=np.ndarray>
        vertices_latitude   (j, i, vertices) float64 dask.array<chunksize=(291, 360, 4), meta=np.ndarray>
        vertices_longitude  (j, i, vertices) float64 dask.array<chunksize=(291, 360, 4), meta=np.ndarray>
        zos                 (time, j, i) float32 dask.array<chunksize=(660, 291, 360), meta=np.ndarray>
    Attributes: (12/53)
        CCCma_model_hash:            3dedf95315d603326fde4f5340dc0519d80d10c0
        CCCma_parent_runid:          rc3-pictrl
        CCCma_pycmor_hash:           33c30511acc319a98240633965a04ca99c26427e
        CCCma_runid:                 rc3.1-his01
        Conventions:                 CF-1.7 CMIP-6.2
        YMDH_branch_time_in_child:   1850:01:01:00
        ...                          ...
        table_info:                  Creation Date:(20 February 2019) MD5:374fbe5...
        title:                       CanESM5 output prepared for CMIP6
        tracking_id:                 hdl:21.14100/99be0cf0-54b1-405b-b46c-e69c274...
        variable_id:                 zos
        variant_label:               r1i1p1f1
        version:                     v20190429

You can also open this dataset by running the following Python code

import fsspec
import xarray as xr

dataset_public_url = 'https://ncsa.osn.xsede.org/Pangeo/pangeo-forge-test/prod/recipe-run-176/pangeo-forge/cmip6-feedstock/CMIP6.CMIP.CCCma.CanESM5.historical.r1i1p1f1.Omon.zos.gn.v20190429.zarr'
mapper = fsspec.get_mapper(dataset_public_url)
ds = xr.open_zarr(mapper, consolidated=True)
ds

in this badge (or your Python interpreter of choice).

Checklist

Please copy-and-paste the list below into a new comment on this thread, and check the boxes off as you've reviewed them.

Note: This test execution is limited to two increments in the concatenation dimension, so you should expect the length of that dimension (e.g, "time" or equivalent) to be 2.

- [ ] Are the dimension lengths correct?
- [ ] Are all of the expected variables present?
- [ ] Does plotting the data produce a plot that looks like your dataset?
- [ ] Can you run a simple computation/reduction on the data and produce a plausible result?

feedstock/recipe.py Outdated Show resolved Hide resolved
@pangeo-forge-bot
Copy link
Collaborator

🎉 New recipe runs created for the following recipes at sha 0ca9875fa4a2b54c305c47acfab8be264a346659:

@cisaacstern
Copy link
Member

@jbusecke, the so recipe failed with a KilledWorker #7 (comment) which suggests that subset_inputs: 2 was not enough subsetting for this recipe.

To move forward, I've removed so, and will now merge.

@cisaacstern cisaacstern merged commit cae6500 into pangeo-forge:main May 17, 2022
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

3 participants