Failure in loading Deepspeed large model example

[sachanub]

🐛 Describe the bug

I am trying to follow the example to perform inference with the OPT-30B model according to this example: https://github.com/pytorch/serve/tree/master/examples/large_models/deepspeed

However, as specified in the model-config.yaml file, a checkpoints.json file is required. This file gets used here: https://github.com/pytorch/serve/blob/master/ts/handler_utils/distributed/deepspeed.py#L40

As a result, the model fails to load. The error logs are attached below.

Error logs

2023-09-05T23:22:14,652 [INFO ] W-29500-opt_1.0-stdout MODEL_LOG - Failed to load model opt, exception Cannot copy out of meta tensor; no data!
2023-09-05T23:22:14,652 [INFO ] W-29500-opt_1.0-stdout MODEL_LOG - Traceback (most recent call last):
2023-09-05T23:22:14,653 [INFO ] W-29500-opt_1.0-stdout MODEL_LOG -   File "/opt/conda/lib/python3.10/site-packages/ts/model_service_worker.py", line 131, in load_model
2023-09-05T23:22:14,653 [INFO ] W-29500-opt_1.0-stdout MODEL_LOG -     service = model_loader.load(
2023-09-05T23:22:14,653 [INFO ] W-29500-opt_1.0-stdout MODEL_LOG -   File "/opt/conda/lib/python3.10/site-packages/ts/model_loader.py", line 135, in load
2023-09-05T23:22:14,653 [INFO ] W-29500-opt_1.0-stdout MODEL_LOG -     initialize_fn(service.context)
2023-09-05T23:22:14,653 [INFO ] W-29500-opt_1.0-stdout MODEL_LOG -   File "/home/model-server/tmp/models/c1130e4b01c345b9be913ef8414518cb/custom_handler.py", line 55, in initialize
2023-09-05T23:22:14,653 [INFO ] W-29500-opt_1.0-stdout MODEL_LOG -     ds_engine = get_ds_engine(self.model, ctx)
2023-09-05T23:22:14,653 [INFO ] W-29500-opt_1.0-stdout MODEL_LOG -   File "/opt/conda/lib/python3.10/site-packages/ts/handler_utils/distributed/deepspeed.py", line 35, in get_ds_engine
2023-09-05T23:22:14,653 [INFO ] W-29500-opt_1.0-stdout MODEL_LOG -     ds_engine = deepspeed.init_inference(
2023-09-05T23:22:14,653 [INFO ] W-29500-opt_1.0-stdout MODEL_LOG -   File "/opt/conda/lib/python3.10/site-packages/deepspeed/__init__.py", line 342, in init_inference
2023-09-05T23:22:14,653 [INFO ] W-29500-opt_1.0-stdout MODEL_LOG -     engine = InferenceEngine(model, config=ds_inference_config)
2023-09-05T23:22:14,653 [INFO ] W-29500-opt_1.0-stdout MODEL_LOG -   File "/opt/conda/lib/python3.10/site-packages/deepspeed/inference/engine.py", line 154, in __init__
2023-09-05T23:22:14,653 [INFO ] W-29500-opt_1.0-stdout MODEL_LOG -     self.module.to(device)
2023-09-05T23:22:14,653 [INFO ] W-29500-opt_1.0-stdout MODEL_LOG -   File "/opt/conda/lib/python3.10/site-packages/transformers/modeling_utils.py", line 2053, in to
2023-09-05T23:22:14,653 [INFO ] W-29500-opt_1.0-stdout MODEL_LOG -     return super().to(*args, **kwargs)
2023-09-05T23:22:14,653 [INFO ] W-29500-opt_1.0-stdout MODEL_LOG -   File "/opt/conda/lib/python3.10/site-packages/torch/nn/modules/module.py", line 1145, in to
2023-09-05T23:22:14,653 [INFO ] W-29500-opt_1.0-stdout MODEL_LOG -     return self._apply(convert)
2023-09-05T23:22:14,653 [INFO ] W-29500-opt_1.0-stdout MODEL_LOG -   File "/opt/conda/lib/python3.10/site-packages/torch/nn/modules/module.py", line 797, in _apply
2023-09-05T23:22:14,653 [INFO ] W-29500-opt_1.0-stdout MODEL_LOG -     module._apply(fn)
2023-09-05T23:22:14,653 [INFO ] W-29500-opt_1.0-stdout MODEL_LOG -   File "/opt/conda/lib/python3.10/site-packages/torch/nn/modules/module.py", line 797, in _apply
2023-09-05T23:22:14,653 [INFO ] W-29500-opt_1.0-stdout MODEL_LOG -     module._apply(fn)
2023-09-05T23:22:14,653 [INFO ] W-29500-opt_1.0-stdout MODEL_LOG -   File "/opt/conda/lib/python3.10/site-packages/torch/nn/modules/module.py", line 797, in _apply
2023-09-05T23:22:14,653 [INFO ] W-29500-opt_1.0-stdout MODEL_LOG -     module._apply(fn)
2023-09-05T23:22:14,653 [INFO ] W-29500-opt_1.0-stdout MODEL_LOG -   File "/opt/conda/lib/python3.10/site-packages/torch/nn/modules/module.py", line 820, in _apply
2023-09-05T23:22:14,653 [INFO ] W-29500-opt_1.0-stdout MODEL_LOG -     param_applied = fn(param)
2023-09-05T23:22:14,654 [INFO ] W-29500-opt_1.0-stdout MODEL_LOG -   File "/opt/conda/lib/python3.10/site-packages/torch/nn/modules/module.py", line 1143, in convert
2023-09-05T23:22:14,654 [INFO ] W-29500-opt_1.0-stdout MODEL_LOG -     return t.to(device, dtype if t.is_floating_point() or t.is_complex() else None, non_blocking)
2023-09-05T23:22:14,654 [INFO ] W-29500-opt_1.0-stdout MODEL_LOG - NotImplementedError: Cannot copy out of meta tensor; no data!

Installation instructions

Docker image URI: 763104351884.dkr.ecr.us-east-1.amazonaws.com/pytorch-inference:2.0.1-gpu-py310-cu118-ubuntu20.04-ec2
EC2 instance: g5dn.24xlarge

Model Packaing

Created model artifact by following this example:
https://github.com/pytorch/serve/tree/master/examples/large_models/deepspeed

config.properties

No response

Versions

------------------------------------------------------------------------------------------
Environment headers
------------------------------------------------------------------------------------------
Torchserve branch: 

torchserve==0.8.1
torch-model-archiver==0.8.1

Python version: 3.10 (64-bit runtime)
Python executable: /opt/conda/bin/python3

Versions of relevant python libraries:
captum==0.6.0
numpy==1.22.4
nvgpu==0.10.0
psutil==5.9.5
requests==2.31.0
torch==2.0.1+cu118
torch-model-archiver==0.8.1
torchaudio==2.0.2+cu118
torchdata==0.6.1+cu118
torchserve==0.8.1
torchtext==0.15.2+cu118
torchvision==0.15.2+cu118
wheel==0.38.4
torch==2.0.1+cu118
torchtext==0.15.2+cu118
torchvision==0.15.2+cu118
torchaudio==2.0.2+cu118

Java Version:


OS: N/A
GCC version: (Ubuntu 9.4.0-1ubuntu1~20.04.1) 9.4.0
Clang version: N/A
CMake version: version 3.27.2

Is CUDA available: Yes
CUDA runtime version: 11.8.89
GPU models and configuration: 
GPU 0: NVIDIA A10G
GPU 1: NVIDIA A10G
GPU 2: NVIDIA A10G
GPU 3: NVIDIA A10G
Nvidia driver version: 535.54.03
cuDNN version: Probably one of the following:
/usr/lib/x86_64-linux-gnu/libcudnn.so.8.8.0
/usr/lib/x86_64-linux-gnu/libcudnn_adv_infer.so.8.8.0
/usr/lib/x86_64-linux-gnu/libcudnn_adv_train.so.8.8.0
/usr/lib/x86_64-linux-gnu/libcudnn_cnn_infer.so.8.8.0
/usr/lib/x86_64-linux-gnu/libcudnn_cnn_train.so.8.8.0
/usr/lib/x86_64-linux-gnu/libcudnn_ops_infer.so.8.8.0
/usr/lib/x86_64-linux-gnu/libcudnn_ops_train.so.8.8.0

Repro instructions

Please follow the instructions as mentioned here to reproduce this error: https://github.com/pytorch/serve/tree/master/examples/large_models/deepspeed

Possible Solution

No response

[agunapal]

Hi @sachanub This file is being generated at run time here https://github.com/pytorch/serve/blob/master/ts/handler_utils/distributed/deepspeed.py#L11C14-L11C14

[sachanub]

Hi @agunapal
If this file gets generated at run time, then what might be the reason for this error?

Failed to load model opt, exception Cannot copy out of meta tensor; no data!

Is this because of any problematic versions of transformers and deepspeed?

[agunapal]

I have seen this issue before. Let me try tomorrow and get back to you.

[sachanub]

Thank you for the assistance @agunapal !

[agunapal]

Basic question..Have you made sure the snapshot name/folder/path matches the one in model-config.yaml ?

[sachanub]

Yes. I followed these steps:

1. Ran the following to download the model files:

python ../utils/Download_model.py --model_path model --model_name facebook/opt-30b --revision main

2. Started the container with this command inside /serve/examples/large_models/deepspeed:

docker run -it --rm --gpus=all -v$(pwd):/workspace -v$(pwd)/model:/opt/ml/model 763104351884.dkr.ecr.us-east-1.amazonaws.com/pytorch-inference:2.0.1-gpu-py310-cu118-ubuntu20.04-ec2 /bin/bash

3. I set the model path in model-config.yaml to /opt/ml/model/models--facebook--opt-30b/snapshots/ceea0a90ac0f6fae7c2c34bcb40477438c152546 after verifying that this folder exists in the container.
4. Created the opt.tar.gz file by running:

torch-model-archiver --model-name opt --version 1.0 --handler custom_handler.py --extra-files ds-config.json -r requirements.txt --config-file opt/model-config.yaml --archive-format tgz

5. Moved opt.tar.gz to model_store.
6. Started TorchServe with:

torchserve --start --ncs --model-store model_store --models opt.tar.gz

After exactly following these steps, I still get the above mentioned error:

2023-09-06T04:41:57,904 [INFO ] W-29500-opt_1.0-stdout MODEL_LOG - Failed to load model opt, exception Cannot copy out of meta tensor; no data!
2023-09-06T04:41:57,904 [INFO ] W-29500-opt_1.0-stdout MODEL_LOG - Traceback (most recent call last):
2023-09-06T04:41:57,904 [INFO ] W-29500-opt_1.0-stdout MODEL_LOG -   File "/opt/conda/lib/python3.10/site-packages/ts/model_service_worker.py", line 131, in load_model
2023-09-06T04:41:57,904 [INFO ] W-29500-opt_1.0-stdout MODEL_LOG -     service = model_loader.load(
2023-09-06T04:41:57,904 [INFO ] W-29500-opt_1.0-stdout MODEL_LOG -   File "/opt/conda/lib/python3.10/site-packages/ts/model_loader.py", line 135, in load
2023-09-06T04:41:57,904 [INFO ] W-29500-opt_1.0-stdout MODEL_LOG -     initialize_fn(service.context)
2023-09-06T04:41:57,904 [INFO ] W-29500-opt_1.0-stdout MODEL_LOG -   File "/home/model-server/tmp/models/8e87b4f37759452ca1f376b0c1acb10a/custom_handler.py", line 55, in initialize
2023-09-06T04:41:57,904 [INFO ] W-29500-opt_1.0-stdout MODEL_LOG -     ds_engine = get_ds_engine(self.model, ctx)
2023-09-06T04:41:57,904 [INFO ] W-29500-opt_1.0-stdout MODEL_LOG -   File "/opt/conda/lib/python3.10/site-packages/ts/handler_utils/distributed/deepspeed.py", line 35, in get_ds_engine
2023-09-06T04:41:57,904 [INFO ] W-29500-opt_1.0-stdout MODEL_LOG -     ds_engine = deepspeed.init_inference(
2023-09-06T04:41:57,904 [INFO ] W-29500-opt_1.0-stdout MODEL_LOG -   File "/opt/conda/lib/python3.10/site-packages/deepspeed/__init__.py", line 342, in init_inference
2023-09-06T04:41:57,904 [INFO ] W-29500-opt_1.0-stdout MODEL_LOG -     engine = InferenceEngine(model, config=ds_inference_config)
2023-09-06T04:41:57,904 [INFO ] W-29500-opt_1.0-stdout MODEL_LOG -   File "/opt/conda/lib/python3.10/site-packages/deepspeed/inference/engine.py", line 154, in __init__
2023-09-06T04:41:57,904 [INFO ] W-29500-opt_1.0-stdout MODEL_LOG -     self.module.to(device)
2023-09-06T04:41:57,904 [INFO ] W-29500-opt_1.0-stdout MODEL_LOG -   File "/opt/conda/lib/python3.10/site-packages/transformers/modeling_utils.py", line 2053, in to
2023-09-06T04:41:57,904 [INFO ] W-29500-opt_1.0-stdout MODEL_LOG -     return super().to(*args, **kwargs)
2023-09-06T04:41:57,905 [INFO ] W-29500-opt_1.0-stdout MODEL_LOG -   File "/opt/conda/lib/python3.10/site-packages/torch/nn/modules/module.py", line 1145, in to
2023-09-06T04:41:57,905 [INFO ] W-29500-opt_1.0-stdout MODEL_LOG -     return self._apply(convert)
2023-09-06T04:41:57,905 [INFO ] W-29500-opt_1.0-stdout MODEL_LOG -   File "/opt/conda/lib/python3.10/site-packages/torch/nn/modules/module.py", line 797, in _apply
2023-09-06T04:41:57,905 [INFO ] W-29500-opt_1.0-stdout MODEL_LOG -     module._apply(fn)
2023-09-06T04:41:57,905 [INFO ] W-29500-opt_1.0-stdout MODEL_LOG -   File "/opt/conda/lib/python3.10/site-packages/torch/nn/modules/module.py", line 797, in _apply
2023-09-06T04:41:57,905 [INFO ] W-29500-opt_1.0-stdout MODEL_LOG -     module._apply(fn)
2023-09-06T04:41:57,905 [INFO ] W-29500-opt_1.0-stdout MODEL_LOG -   File "/opt/conda/lib/python3.10/site-packages/torch/nn/modules/module.py", line 797, in _apply
2023-09-06T04:41:57,905 [INFO ] W-29500-opt_1.0-stdout MODEL_LOG -     module._apply(fn)
2023-09-06T04:41:57,905 [INFO ] W-29500-opt_1.0-stdout MODEL_LOG -   File "/opt/conda/lib/python3.10/site-packages/torch/nn/modules/module.py", line 820, in _apply
2023-09-06T04:41:57,905 [INFO ] W-29500-opt_1.0-stdout MODEL_LOG -     param_applied = fn(param)
2023-09-06T04:41:57,905 [INFO ] W-29500-opt_1.0-stdout MODEL_LOG -   File "/opt/conda/lib/python3.10/site-packages/torch/nn/modules/module.py", line 1143, in convert
2023-09-06T04:41:57,905 [INFO ] W-29500-opt_1.0-stdout MODEL_LOG -     return t.to(device, dtype if t.is_floating_point() or t.is_complex() else None, non_blocking)
2023-09-06T04:41:57,905 [INFO ] W-29500-opt_1.0-stdout MODEL_LOG - NotImplementedError: Cannot copy out of meta tensor; no data!
2023-09-06T04:41:57,911 [INFO ] W-29500-opt_1.0-stdout MODEL_LOG - Backend worker process died.
2023-09-06T04:41:57,911 [INFO ] W-29500-opt_1.0-stdout MODEL_LOG - Traceback (most recent call last):
2023-09-06T04:41:57,911 [INFO ] W-29500-opt_1.0-stdout MODEL_LOG -   File "/opt/conda/lib/python3.10/site-packages/ts/model_service_worker.py", line 253, in <module>
2023-09-06T04:41:57,911 [INFO ] W-29500-opt_1.0-stdout MODEL_LOG -     worker.run_server()
2023-09-06T04:41:57,911 [INFO ] W-29500-opt_1.0-stdout MODEL_LOG -   File "/opt/conda/lib/python3.10/site-packages/ts/model_service_worker.py", line 221, in run_server
2023-09-06T04:41:57,911 [INFO ] W-29500-opt_1.0-stdout MODEL_LOG -     self.handle_connection(cl_socket)
2023-09-06T04:41:57,911 [INFO ] W-29500-opt_1.0-stdout MODEL_LOG -   File "/opt/conda/lib/python3.10/site-packages/ts/model_service_worker.py", line 189, in handle_connection
2023-09-06T04:41:57,911 [INFO ] W-29500-opt_1.0-stdout MODEL_LOG -     raise RuntimeError("{} - {}".format(code, result))
2023-09-06T04:41:57,911 [INFO ] W-29500-opt_1.0-stdout MODEL_LOG - RuntimeError: 500 - Unknown exception

[sachanub]

Hi @agunapal . I had a chat with @lxning and she mentioned that I should run DS_BUILD_OPS=1 pip3 install deepspeed to install deepspeed. When I tried that in a container of 763104351884.dkr.ecr.us-east-1.amazonaws.com/pytorch-inference:2.0.1-gpu-py310-cu118-ubuntu20.04-ec2, I get the following error:

Collecting deepspeed
  Using cached deepspeed-0.10.2.tar.gz (858 kB)
  Preparing metadata (setup.py) ... error
  error: subprocess-exited-with-error
  
  × python setup.py egg_info did not run successfully.
  │ exit code: 1
  ╰─> [14 lines of output]
      Traceback (most recent call last):
        File "<string>", line 2, in <module>
        File "<pip-setuptools-caller>", line 34, in <module>
        File "/home/model-server/tmp/pip-install-2n_tfsbb/deepspeed_908f51b8c7b5451285bff9683517c68d/setup.py", line 182, in <module>
          abort(f"Unable to pre-compile {op_name}")
        File "/home/model-server/tmp/pip-install-2n_tfsbb/deepspeed_908f51b8c7b5451285bff9683517c68d/setup.py", line 52, in abort
          assert False, msg
      AssertionError: Unable to pre-compile async_io
      DS_BUILD_OPS=1
       [WARNING]  async_io requires the dev libaio .so object and headers but these were not found.
       [WARNING]  async_io: please install the libaio-dev package with apt
       [WARNING]  If libaio is already installed (perhaps from source), try setting the CFLAGS and LDFLAGS environment variables to where it can be found.
       [WARNING]  One can disable async_io with DS_BUILD_AIO=0
       [ERROR]  Unable to pre-compile async_io
      [end of output]
  
  note: This error originates from a subprocess, and is likely not a problem with pip.
error: metadata-generation-failed

× Encountered error while generating package metadata.
╰─> See above for output.

note: This is an issue with the package mentioned above, not pip.
hint: See above for details.

According to the recommendations from the above mentioned warnings and error, I tried installing deepspeed by running DS_BUILD_AIO=0 DS_BUILD_OPS=1 pip3 install deepspeed. That leads to the following error:

Collecting deepspeed
  Using cached deepspeed-0.10.2.tar.gz (858 kB)
  Preparing metadata (setup.py) ... error
  error: subprocess-exited-with-error
  
  × python setup.py egg_info did not run successfully.
  │ exit code: 1
  ╰─> [20 lines of output]
      Traceback (most recent call last):
        File "<string>", line 2, in <module>
        File "<pip-setuptools-caller>", line 34, in <module>
        File "/home/model-server/tmp/pip-install-iwok_6_k/deepspeed_46b40e3ea3254642ba833898b4f23061/setup.py", line 182, in <module>
          abort(f"Unable to pre-compile {op_name}")
        File "/home/model-server/tmp/pip-install-iwok_6_k/deepspeed_46b40e3ea3254642ba833898b4f23061/setup.py", line 52, in abort
          assert False, msg
      AssertionError: Unable to pre-compile sparse_attn
      DS_BUILD_OPS=1
       [WARNING]  async_io requires the dev libaio .so object and headers but these were not found.
       [WARNING]  async_io: please install the libaio-dev package with apt
       [WARNING]  If libaio is already installed (perhaps from source), try setting the CFLAGS and LDFLAGS environment variables to where it can be found.
       [WARNING]  cpu_adam attempted to use `py-cpuinfo` but failed (exception type: <class 'UnboundLocalError'>, local variable 'get_cpu_info' referenced before assignment), falling back to `lscpu` to get this information.
       [WARNING]  cpu_adam attempted to use `py-cpuinfo` but failed (exception type: <class 'UnboundLocalError'>, local variable 'get_cpu_info' referenced before assignment), falling back to `lscpu` to get this information.
       [WARNING]  cpu_adagrad attempted to use `py-cpuinfo` but failed (exception type: <class 'UnboundLocalError'>, local variable 'get_cpu_info' referenced before assignment), falling back to `lscpu` to get this information.
       [WARNING]  cpu_adagrad attempted to use `py-cpuinfo` but failed (exception type: <class 'UnboundLocalError'>, local variable 'get_cpu_info' referenced before assignment), falling back to `lscpu` to get this information.
       [WARNING]  sparse_attn requires a torch version >= 1.5 and < 2.0 but detected 2.0
       [WARNING]  using untested triton version (2.0.0), only 1.0.0 is known to be compatible
       [WARNING]  One can disable sparse_attn with DS_BUILD_SPARSE_ATTN=0
       [ERROR]  Unable to pre-compile sparse_attn
      [end of output]
  
  note: This error originates from a subprocess, and is likely not a problem with pip.
error: metadata-generation-failed

× Encountered error while generating package metadata.
╰─> See above for output.

note: This is an issue with the package mentioned above, not pip.
hint: See above for details.

Finally, I tried installing deepspeed by running DS_BUILD_SPARSE_ATTN=0 DS_BUILD_AIO=0 DS_BUILD_OPS=1 pip3 install deepspeed and it again fails with the error as mentioned in the attached file (message was too long to put in the comment).
error_log.txt

What would be the recommended procedure for installing deepspeed in this case? Should I use older TorchServe and PyTorch versions (<2.0.1) since one of the warning messages is this:

[WARNING]  sparse_attn requires a torch version >= 1.5 and < 2.0 but detected 2.0

[agunapal]

For reference, when I updated the example, this was my config

torch                   2.0.1+cu117
torch-model-archiver    0.8.1b20230622
torch-workflow-archiver 0.2.9b20230622
torchaudio              2.0.2+cu117
torchdata               0.6.1
torchpippy              0.1.1
torchserve              0.8.1b20230622
torchtext               0.15.2+cpu
torchvision             0.15.2+cu117
deepspeed               0.9.4
transformers            4.30.0

[agunapal]

Did a fresh install with these updated versions. Its working for me

torch                   2.0.1+cu117
torch-model-archiver    0.8.2
torch-workflow-archiver 0.2.10
torchaudio              2.0.2+cu117
torchdata               0.6.1
torchserve              0.8.2
torchtext               0.15.2+cpu
torchvision             0.15.2+cu117
transformers            4.33.1
deepspeed               0.10.2

@sachanub The only difference I see is CUDA version. Can you please try with CUDA 11.7

[sachanub]

My container has the following versions:

torch                     2.0.1+cu117
torch-model-archiver      0.8.2
torch-workflow-archiver   0.2.10
torchaudio                2.0.2+cu117
torchdata                 0.6.1
torchserve                0.8.2
torchtext                 0.15.2+cpu
torchvision               0.15.2+cu117
transformers              4.33.1
deepspeed                 0.10.2

With these, the old error went away. However, the worker stops after the checkpoint shards are loaded. Here are the logs:

2023-09-07T07:20:05,064 [WARN ] W-29500-opt_1.0-stderr MODEL_LOG - Loading 7 checkpoint shards:  86%|████████▌ | 6/7 [07:44<01:17, 77.50s/it]
2023-09-07T07:20:05,064 [WARN ] W-29500-opt_1.0-stderr MODEL_LOG - Loading 7 checkpoint shards: 100%|██████████| 7/7 [09:14<00:00, 81.55s/it]
2023-09-07T07:20:05,064 [WARN ] W-29500-opt_1.0-stderr MODEL_LOG - Loading 7 checkpoint shards: 100%|██████████| 7/7 [09:14<00:00, 79.25s/it]
2023-09-07T07:20:05,075 [WARN ] W-29500-opt_1.0-stderr MODEL_LOG - 
2023-09-07T07:20:05,075 [INFO ] W-29500-opt_1.0-stdout MODEL_LOG - checkpoint loading time at rank 3: 554.7325437068939 sec
2023-09-07T07:20:05,075 [WARN ] W-29500-opt_1.0-stderr MODEL_LOG - Loading 7 checkpoint shards: 100%|██████████| 7/7 [09:14<00:00, 81.59s/it]
2023-09-07T07:20:05,075 [WARN ] W-29500-opt_1.0-stderr MODEL_LOG - Loading 7 checkpoint shards: 100%|██████████| 7/7 [09:14<00:00, 79.25s/it]
2023-09-07T07:20:05,499 [INFO ] W-29500-opt_1.0-stdout MODEL_LOG - checkpoint loading time at rank 1: 555.2292792797089 sec
2023-09-07T07:20:05,499 [WARN ] W-29500-opt_1.0-stderr MODEL_LOG - 
2023-09-07T07:20:05,499 [WARN ] W-29500-opt_1.0-stderr MODEL_LOG - Loading 7 checkpoint shards: 100%|██████████| 7/7 [09:15<00:00, 81.69s/it]
2023-09-07T07:20:05,500 [WARN ] W-29500-opt_1.0-stderr MODEL_LOG - Loading 7 checkpoint shards: 100%|██████████| 7/7 [09:15<00:00, 79.32s/it]
2023-09-07T07:20:05,501 [INFO ] W-29500-opt_1.0-stdout MODEL_LOG - checkpoint loading time at rank 0: 555.1914641857147 sec
2023-09-07T07:20:05,501 [WARN ] W-29500-opt_1.0-stderr MODEL_LOG - 
2023-09-07T07:20:05,501 [WARN ] W-29500-opt_1.0-stderr MODEL_LOG - Loading 7 checkpoint shards: 100%|██████████| 7/7 [09:15<00:00, 81.74s/it]
2023-09-07T07:20:05,502 [WARN ] W-29500-opt_1.0-stderr MODEL_LOG - Loading 7 checkpoint shards: 100%|██████████| 7/7 [09:15<00:00, 79.31s/it]
2023-09-07T07:20:06,735 [INFO ] epollEventLoopGroup-5-3 org.pytorch.serve.wlm.WorkerThread - 29500 Worker disconnected. WORKER_STARTED
2023-09-07T07:20:06,735 [DEBUG] W-29500-opt_1.0 org.pytorch.serve.wlm.WorkerThread - System state is : WORKER_STARTED
2023-09-07T07:20:06,735 [DEBUG] W-29500-opt_1.0 org.pytorch.serve.wlm.WorkerThread - Backend worker monitoring thread interrupted or backend worker process died.
java.lang.InterruptedException: null
        at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.reportInterruptAfterWait(AbstractQueuedSynchronizer.java:2056) ~[?:?]
        at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2133) ~[?:?]
        at java.util.concurrent.ArrayBlockingQueue.poll(ArrayBlockingQueue.java:432) ~[?:?]
        at org.pytorch.serve.wlm.WorkerThread.run(WorkerThread.java:213) [model-server.jar:?]
        at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:515) [?:?]
        at java.util.concurrent.FutureTask.run(FutureTask.java:264) [?:?]
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) [?:?]
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) [?:?]
        at java.lang.Thread.run(Thread.java:829) [?:?]
2023-09-07T07:20:06,745 [WARN ] W-29500-opt_1.0 org.pytorch.serve.wlm.BatchAggregator - Load model failed: opt, error: Worker died.
2023-09-07T07:20:06,745 [DEBUG] W-29500-opt_1.0 org.pytorch.serve.wlm.WorkerThread - W-29500-opt_1.0 State change WORKER_STARTED -> WORKER_STOPPED
2023-09-07T07:20:06,746 [INFO ] W-29500-opt_1.0 org.pytorch.serve.wlm.WorkerThread - Auto recovery start timestamp: 1694071206746
2023-09-07T07:20:06,746 [WARN ] W-29500-opt_1.0 org.pytorch.serve.wlm.WorkerLifeCycle - terminateIOStreams() threadName=W-29500-opt_1.0-stderr
2023-09-07T07:20:06,746 [INFO ] epollEventLoopGroup-5-1 org.pytorch.serve.wlm.WorkerThread - 29500 Worker disconnected. WORKER_STARTED
2023-09-07T07:20:06,746 [INFO ] epollEventLoopGroup-5-2 org.pytorch.serve.wlm.WorkerThread - 29500 Worker disconnected. WORKER_STARTED
2023-09-07T07:20:06,746 [INFO ] epollEventLoopGroup-5-4 org.pytorch.serve.wlm.WorkerThread - 29500 Worker disconnected. WORKER_STOPPED
2023-09-07T07:20:06,746 [WARN ] W-29500-opt_1.0 org.pytorch.serve.wlm.WorkerLifeCycle - terminateIOStreams() threadName=W-29500-opt_1.0-stdout
2023-09-07T07:20:06,747 [INFO ] W-29500-opt_1.0 org.pytorch.serve.wlm.WorkerThread - Retry worker: 29500 in 1 seconds.
2023-09-07T07:20:06,760 [INFO ] W-29500-opt_1.0-stderr org.pytorch.serve.wlm.WorkerLifeCycle - Stopped Scanner - W-29500-opt_1.0-stderr
2023-09-07T07:20:06,760 [INFO ] W-29500-opt_1.0-stdout org.pytorch.serve.wlm.WorkerLifeCycle - Stopped Scanner - W-29500-opt_1.0-stdout
2023-09-07T07:20:07,747 [DEBUG] W-29500-opt_1.0 org.pytorch.serve.wlm.WorkerLifeCycle - Worker cmdline: [torchrun, --nnodes, 1, --nproc-per-node, 4, --log-dir, /workspace/logs/torchelastic_ts, --rdzv-backend, c10d, --rdzv-id, opt_29500, --max-restarts, 1, /opt/conda/lib/python3.9/site-packages/ts/model_service_worker.py, --sock-type, unix, --sock-name, /home/model-server/tmp/.ts.sock.29500, --metrics-config, /opt/conda/lib/python3.9/site-packages/ts/configs/metrics.yaml]
2023-09-07T07:20:09,267 [WARN ] W-29500-opt_1.0-stderr MODEL_LOG - master_addr is only used for static rdzv_backend and when rdzv_endpoint is not specified.
2023-09-07T07:20:09,268 [WARN ] W-29500-opt_1.0-stderr MODEL_LOG - INFO:torch.distributed.launcher.api:Starting elastic_operator with launch configs:
2023-09-07T07:20:09,268 [WARN ] W-29500-opt_1.0-stderr MODEL_LOG -   entrypoint       : /opt/conda/lib/python3.9/site-packages/ts/model_service_worker.py
2023-09-07T07:20:09,268 [WARN ] W-29500-opt_1.0-stderr MODEL_LOG -   min_nodes        : 1
2023-09-07T07:20:09,268 [WARN ] W-29500-opt_1.0-stderr MODEL_LOG -   max_nodes        : 1
2023-09-07T07:20:09,268 [WARN ] W-29500-opt_1.0-stderr MODEL_LOG -   nproc_per_node   : 4
2023-09-07T07:20:09,268 [WARN ] W-29500-opt_1.0-stderr MODEL_LOG -   run_id           : opt_29500
2023-09-07T07:20:09,268 [WARN ] W-29500-opt_1.0-stderr MODEL_LOG -   rdzv_backend     : c10d
2023-09-07T07:20:09,268 [WARN ] W-29500-opt_1.0-stderr MODEL_LOG -   rdzv_endpoint    : 
2023-09-07T07:20:09,268 [WARN ] W-29500-opt_1.0-stderr MODEL_LOG -   rdzv_configs     : {'timeout': 900}
2023-09-07T07:20:09,268 [WARN ] W-29500-opt_1.0-stderr MODEL_LOG -   max_restarts     : 1
2023-09-07T07:20:09,268 [WARN ] W-29500-opt_1.0-stderr MODEL_LOG -   monitor_interval : 5
2023-09-07T07:20:09,268 [WARN ] W-29500-opt_1.0-stderr MODEL_LOG -   log_dir          : /workspace/logs/torchelastic_ts
2023-09-07T07:20:09,268 [WARN ] W-29500-opt_1.0-stderr MODEL_LOG -   metrics_cfg      : {}
2023-09-07T07:20:09,270 [WARN ] W-29500-opt_1.0-stderr MODEL_LOG - 
2023-09-07T07:20:09,270 [WARN ] W-29500-opt_1.0-stderr MODEL_LOG - INFO:torch.distributed.elastic.agent.server.local_elastic_agent:log directory set to: /workspace/logs/torchelastic_ts/opt_29500_7ke_yeu7
2023-09-07T07:20:09,270 [WARN ] W-29500-opt_1.0-stderr MODEL_LOG - INFO:torch.distributed.elastic.agent.server.api:[default] starting workers for entrypoint: python3.9
2023-09-07T07:20:09,270 [WARN ] W-29500-opt_1.0-stderr MODEL_LOG - INFO:torch.distributed.elastic.agent.server.api:[default] Rendezvous'ing worker group
2023-09-07T07:20:09,298 [WARN ] W-29500-opt_1.0-stderr MODEL_LOG - INFO:torch.distributed.elastic.agent.server.api:[default] Rendezvous complete for workers. Result:
2023-09-07T07:20:09,298 [WARN ] W-29500-opt_1.0-stderr MODEL_LOG -   restart_count=0
2023-09-07T07:20:09,298 [WARN ] W-29500-opt_1.0-stderr MODEL_LOG -   master_addr=05b5b93d08ea
2023-09-07T07:20:09,298 [WARN ] W-29500-opt_1.0-stderr MODEL_LOG -   master_port=56755
2023-09-07T07:20:09,298 [WARN ] W-29500-opt_1.0-stderr MODEL_LOG -   group_rank=0
2023-09-07T07:20:09,298 [WARN ] W-29500-opt_1.0-stderr MODEL_LOG -   group_world_size=1
2023-09-07T07:20:09,298 [WARN ] W-29500-opt_1.0-stderr MODEL_LOG -   local_ranks=[0, 1, 2, 3]
2023-09-07T07:20:09,298 [WARN ] W-29500-opt_1.0-stderr MODEL_LOG -   role_ranks=[0, 1, 2, 3]
2023-09-07T07:20:09,299 [WARN ] W-29500-opt_1.0-stderr MODEL_LOG -   global_ranks=[0, 1, 2, 3]
2023-09-07T07:20:09,299 [WARN ] W-29500-opt_1.0-stderr MODEL_LOG -   role_world_sizes=[4, 4, 4, 4]
2023-09-07T07:20:09,299 [WARN ] W-29500-opt_1.0-stderr MODEL_LOG -   global_world_sizes=[4, 4, 4, 4]
2023-09-07T07:20:09,299 [WARN ] W-29500-opt_1.0-stderr MODEL_LOG - 
2023-09-07T07:20:09,299 [WARN ] W-29500-opt_1.0-stderr MODEL_LOG - INFO:torch.distributed.elastic.agent.server.api:[default] Starting worker group
2023-09-07T07:20:09,299 [WARN ] W-29500-opt_1.0-stderr MODEL_LOG - INFO:torch.distributed.elastic.agent.server.local_elastic_agent:Environment variable 'TORCHELASTIC_ENABLE_FILE_TIMER' not found. Do not start FileTimerServer.
2023-09-07T07:20:09,299 [WARN ] W-29500-opt_1.0-stderr MODEL_LOG - INFO:torch.distributed.elastic.multiprocessing:Setting worker0 reply file to: /workspace/logs/torchelastic_ts/opt_29500_7ke_yeu7/attempt_0/0/error.json
2023-09-07T07:20:09,299 [WARN ] W-29500-opt_1.0-stderr MODEL_LOG - INFO:torch.distributed.elastic.multiprocessing:Setting worker1 reply file to: /workspace/logs/torchelastic_ts/opt_29500_7ke_yeu7/attempt_0/1/error.json
2023-09-07T07:20:09,299 [WARN ] W-29500-opt_1.0-stderr MODEL_LOG - INFO:torch.distributed.elastic.multiprocessing:Setting worker2 reply file to: /workspace/logs/torchelastic_ts/opt_29500_7ke_yeu7/attempt_0/2/error.json
2023-09-07T07:20:09,299 [WARN ] W-29500-opt_1.0-stderr MODEL_LOG - INFO:torch.distributed.elastic.multiprocessing:Setting worker3 reply file to: /workspace/logs/torchelastic_ts/opt_29500_7ke_yeu7/attempt_0/3/error.json
2023-09-07T07:20:10,532 [INFO ] W-29500-opt_1.0-stdout MODEL_LOG - s_name_part0=/home/model-server/tmp/.ts.sock, s_name_part1=29500, pid=1226
2023-09-07T07:20:10,533 [INFO ] W-29500-opt_1.0-stdout MODEL_LOG - Listening on port: /home/model-server/tmp/.ts.sock.29500
2023-09-07T07:20:10,543 [INFO ] W-29500-opt_1.0-stdout MODEL_LOG - Successfully loaded /opt/conda/lib/python3.9/site-packages/ts/configs/metrics.yaml.
2023-09-07T07:20:10,543 [INFO ] W-29500-opt_1.0-stdout MODEL_LOG - [PID]1226
2023-09-07T07:20:10,543 [INFO ] W-29500-opt_1.0-stdout MODEL_LOG - Torch worker started.
2023-09-07T07:20:10,543 [INFO ] W-29500-opt_1.0-stdout MODEL_LOG - Python runtime: 3.9.13
2023-09-07T07:20:10,543 [INFO ] W-29500-opt_1.0-stdout MODEL_LOG - s_name_part0=/home/model-server/tmp/.ts.sock, s_name_part1=29500, pid=1229
2023-09-07T07:20:10,544 [INFO ] W-29500-opt_1.0-stdout MODEL_LOG - Listening on port: /home/model-server/tmp/.ts.sock.29503
2023-09-07T07:20:10,551 [INFO ] W-29500-opt_1.0-stdout MODEL_LOG - s_name_part0=/home/model-server/tmp/.ts.sock, s_name_part1=29500, pid=1228
2023-09-07T07:20:10,551 [INFO ] W-29500-opt_1.0-stdout MODEL_LOG - Listening on port: /home/model-server/tmp/.ts.sock.29502
2023-09-07T07:20:10,553 [INFO ] W-29500-opt_1.0-stdout MODEL_LOG - s_name_part0=/home/model-server/tmp/.ts.sock, s_name_part1=29500, pid=1227
2023-09-07T07:20:10,553 [INFO ] W-29500-opt_1.0-stdout MODEL_LOG - Listening on port: /home/model-server/tmp/.ts.sock.29501
2023-09-07T07:20:10,554 [INFO ] W-29500-opt_1.0-stdout MODEL_LOG - Successfully loaded /opt/conda/lib/python3.9/site-packages/ts/configs/metrics.yaml.
2023-09-07T07:20:10,554 [INFO ] W-29500-opt_1.0-stdout MODEL_LOG - [PID]1229
2023-09-07T07:20:10,554 [INFO ] W-29500-opt_1.0-stdout MODEL_LOG - Torch worker started.
2023-09-07T07:20:10,554 [INFO ] W-29500-opt_1.0-stdout MODEL_LOG - Python runtime: 3.9.13
2023-09-07T07:20:10,561 [INFO ] W-29500-opt_1.0-stdout MODEL_LOG - Successfully loaded /opt/conda/lib/python3.9/site-packages/ts/configs/metrics.yaml.
2023-09-07T07:20:10,561 [INFO ] W-29500-opt_1.0-stdout MODEL_LOG - [PID]1228
2023-09-07T07:20:10,561 [INFO ] W-29500-opt_1.0-stdout MODEL_LOG - Torch worker started.
2023-09-07T07:20:10,561 [INFO ] W-29500-opt_1.0-stdout MODEL_LOG - Python runtime: 3.9.13
2023-09-07T07:20:10,563 [INFO ] W-29500-opt_1.0-stdout MODEL_LOG - Successfully loaded /opt/conda/lib/python3.9/site-packages/ts/configs/metrics.yaml.
2023-09-07T07:20:10,564 [INFO ] W-29500-opt_1.0-stdout MODEL_LOG - [PID]1227
2023-09-07T07:20:10,564 [INFO ] W-29500-opt_1.0-stdout MODEL_LOG - Torch worker started.
2023-09-07T07:20:10,564 [INFO ] W-29500-opt_1.0-stdout MODEL_LOG - Python runtime: 3.9.13
2023-09-07T07:20:10,564 [DEBUG] W-29500-opt_1.0 org.pytorch.serve.wlm.WorkerThread - W-29500-opt_1.0 State change WORKER_STOPPED -> WORKER_STARTED
2023-09-07T07:20:10,564 [INFO ] W-29500-opt_1.0 org.pytorch.serve.wlm.WorkerThread - Connecting to: /home/model-server/tmp/.ts.sock.29500
2023-09-07T07:20:10,565 [INFO ] W-29500-opt_1.0 org.pytorch.serve.wlm.WorkerThread - Connecting to: /home/model-server/tmp/.ts.sock.29501
2023-09-07T07:20:10,565 [INFO ] epollEventLoopGroup-5-1 org.pytorch.serve.wlm.WorkerThread - 29500 Worker disconnected. WORKER_STARTED
2023-09-07T07:20:10,566 [INFO ] W-29500-opt_1.0-stdout MODEL_LOG - Connection accepted: /home/model-server/tmp/.ts.sock.29500.
2023-09-07T07:20:10,566 [DEBUG] W-29500-opt_1.0 org.pytorch.serve.wlm.WorkerThread - System state is : WORKER_STARTED
2023-09-07T07:20:10,566 [DEBUG] W-29500-opt_1.0 org.pytorch.serve.wlm.WorkerThread - Backend worker monitoring thread interrupted or backend worker process died.
java.lang.InterruptedException: AbstractBootstrap$PendingRegistrationPromise@36fdc4c2(incomplete)
        at io.netty.util.concurrent.DefaultPromise.await(DefaultPromise.java:243) ~[model-server.jar:?]
        at io.netty.channel.DefaultChannelPromise.await(DefaultChannelPromise.java:131) ~[model-server.jar:?]
        at io.netty.channel.DefaultChannelPromise.await(DefaultChannelPromise.java:30) ~[model-server.jar:?]
        at io.netty.util.concurrent.DefaultPromise.sync(DefaultPromise.java:403) ~[model-server.jar:?]
        at io.netty.channel.DefaultChannelPromise.sync(DefaultChannelPromise.java:119) ~[model-server.jar:?]
        at io.netty.channel.DefaultChannelPromise.sync(DefaultChannelPromise.java:30) ~[model-server.jar:?]
        at org.pytorch.serve.wlm.WorkerThread.connect(WorkerThread.java:367) ~[model-server.jar:?]
        at org.pytorch.serve.wlm.WorkerThread.run(WorkerThread.java:183) [model-server.jar:?]
        at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) [?:?]
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) [?:?]
        at java.lang.Thread.run(Thread.java:829) [?:?]