[tune] EXAMPLE DOESN'T RUN only show failing information from two examples: mnist_pytorch.py and tune_mnist_keras.py

[cgraywang]

System information

• OS Platform and Distribution (e.g., Linux Ubuntu 16.04):

NAME="Ubuntu"
VERSION="16.04.5 LTS (Xenial Xerus)"
ID=ubuntu
ID_LIKE=debian
PRETTY_NAME="Ubuntu 16.04.5 LTS"
VERSION_ID="16.04"
HOME_URL="http://www.ubuntu.com/"
SUPPORT_URL="http://help.ubuntu.com/"
BUG_REPORT_URL="http://bugs.launchpad.net/ubuntu/"
VERSION_CODENAME=xenial
UBUNTU_CODENAME=xenial

• Ray installed from (source or binary): source
• Ray version: 0.6.5
• Python version: Python 3.6.5
• Exact command to reproduce:

cd ray/python/ray/tune/examples
python mnist_pytorch.py

pytorch version:

1.0.0

or

cd ray/python/ray/tune/examples
python tune_mnist_keras.py

TF version:

1.12.0

keras version:

2.2.4

Describe the problem

Without any modfifications, build Ray from source, try to directly use tune provided examples, but seems most of the examples failed due to the

Destroying actor for trial xxxx. If your trainable is slow to initialize, consider setting reuse_actors=True to reduce actor creation overheads.

Btw, the machine has GPU and the version:

Cuda compilation tools, release 9.0, V9.0.176

However, after trying add reuse_actors=True , the same error msg appear.

Since the trials are suddenly stopped without any error or exception, could you please help to take a look? @richardliaw @robertnishihara Thanks!

Source code / logs

python mnist_pytorch.py

2019-03-23 23:54:34,913 WARNING worker.py:1406 -- WARNING: Not updating worker name since setproctitle is not installed. Install this with pip install setproctitle (or ray[debug]) to enable monitoring of worker processes.
2019-03-23 23:54:34,914 INFO node.py:423 -- Process STDOUT and STDERR is being redirected to /tmp/ray/session_2019-03-23_23-54-34_52746/logs.
2019-03-23 23:54:35,021 INFO services.py:363 -- Waiting for redis server at 127.0.0.1:24948 to respond...
2019-03-23 23:54:35,130 INFO services.py:363 -- Waiting for redis server at 127.0.0.1:39939 to respond...
2019-03-23 23:54:35,132 INFO services.py:760 -- Starting Redis shard with 10.0 GB max memory.
2019-03-23 23:54:35,147 WARNING services.py:1236 -- Warning: Capping object memory store to 20.0GB. To increase this further, specify object_store_memory when calling ray.init() or ray start.
2019-03-23 23:54:35,148 INFO services.py:1384 -- Starting the Plasma object store with 20.0 GB memory using /dev/shm.
2019-03-23 23:54:35,793 INFO tune.py:60 -- Tip: to resume incomplete experiments, pass resume='prompt' or resume=True to run()
2019-03-23 23:54:35,796 INFO tune.py:211 -- Starting a new experiment.
2019-03-23 23:54:37,283 WARNING util.py:62 -- The start_trial operation took 1.3957560062408447 seconds to complete, which may be a performance bottleneck.
2019-03-23 23:54:58,442 INFO ray_trial_executor.py:178 -- Destroying actor for trial TRAIN_FN_0_lr=0.081371,momentum=0.40185. If your trainable is slow to initialize, consider setting reuse_actors=True to reduce actor creation overheads.
2019-03-23 23:54:58,754 INFO ray_trial_executor.py:178 -- Destroying actor for trial TRAIN_FN_3_lr=0.010086,momentum=0.41713. If your trainable is slow to initialize, consider setting reuse_actors=True to reduce actor creation overheads.
2019-03-23 23:54:59,133 INFO ray_trial_executor.py:178 -- Destroying actor for trial TRAIN_FN_1_lr=0.028139,momentum=0.40255. If your trainable is slow to initialize, consider setting reuse_actors=True to reduce actor creation overheads.
2019-03-23 23:54:59,160 INFO ray_trial_executor.py:178 -- Destroying actor for trial TRAIN_FN_7_lr=0.030289,momentum=0.55615. If your trainable is slow to initialize, consider setting reuse_actors=True to reduce actor creation overheads.
2019-03-23 23:54:59,299 INFO ray_trial_executor.py:178 -- Destroying actor for trial TRAIN_FN_5_lr=0.08914,momentum=0.18464. If your trainable is slow to initialize, consider setting reuse_actors=True to reduce actor creation overheads.
2019-03-23 23:54:59,449 INFO ray_trial_executor.py:178 -- Destroying actor for trial TRAIN_FN_6_lr=0.066883,momentum=0.68077. If your trainable is slow to initialize, consider setting reuse_actors=True to reduce actor creation overheads.
2019-03-23 23:55:00,221 INFO ray_trial_executor.py:178 -- Destroying actor for trial TRAIN_FN_4_lr=0.059111,momentum=0.82238. If your trainable is slow to initialize, consider setting reuse_actors=True to reduce actor creation overheads.
2019-03-23 23:55:00,525 INFO ray_trial_executor.py:178 -- Destroying actor for trial TRAIN_FN_2_lr=0.063279,momentum=0.43368. If your trainable is slow to initialize, consider setting reuse_actors=True to reduce actor creation overheads.
2019-03-23 23:55:21,020 INFO ray_trial_executor.py:178 -- Destroying actor for trial TRAIN_FN_9_lr=0.084676,momentum=0.45356. If your trainable is slow to initialize, consider setting reuse_actors=True to reduce actor creation overheads.
2019-03-23 23:55:21,150 INFO ray_trial_executor.py:178 -- Destroying actor for trial TRAIN_FN_8_lr=0.051943,momentum=0.6297. If your trainable is slow to initialize, consider setting reuse_actors=True to reduce actor creation overheads.

python tune_mnist_keras.py

(pid=57890) 60000 train samples
(pid=57890) 10000 test samples
(pid=57881) x_train shape: (60000, 28, 28, 1)
(pid=57881) 60000 train samples
(pid=57881) 10000 test samples
(pid=57899) x_train shape: (60000, 28, 28, 1)
(pid=57899) 60000 train samples
(pid=57899) 10000 test samples
(pid=57916) x_train shape: (60000, 28, 28, 1)
(pid=57916) 60000 train samples
(pid=57916) 10000 test samples
(pid=57913) x_train shape: (60000, 28, 28, 1)
(pid=57913) 60000 train samples
(pid=57913) 10000 test samples
(pid=57910) x_train shape: (60000, 28, 28, 1)
(pid=57910) 60000 train samples
(pid=57910) 10000 test samples
2019-03-24 00:09:22,154 INFO ray_trial_executor.py:178 -- Destroying actor for trial TRAIN_FN_3_dropout1=0.41208,hidden=53,lr=0.0045996,momentum=0.29457. If your trainable is slow to initialize, consider setting reuse_actors=True to reduce actor creation overheads.
2019-03-24 00:09:23,633 INFO ray_trial_executor.py:178 -- Destroying actor for trial TRAIN_FN_9_dropout1=0.78277,hidden=424,lr=0.085855,momentum=0.11821. If your trainable is slow to initialize, consider setting reuse_actors=True to reduce actor creation overheads.
2019-03-24 00:09:28,650 WARNING util.py:62 -- The experiment_checkpoint operation took 0.14834022521972656 seconds to complete, which may be a performance bottleneck.
2019-03-24 00:09:36,315 INFO ray_trial_executor.py:178 -- Destroying actor for trial TRAIN_FN_1_dropout1=0.77148,hidden=307,lr=0.084435,momentum=0.87804. If your trainable is slow to initialize, consider setting reuse_actors=True to reduce actor creation overheads.
2019-03-24 00:09:37,978 INFO ray_trial_executor.py:178 -- Destroying actor for trial TRAIN_FN_4_dropout1=0.71993,hidden=442,lr=0.014533,momentum=0.65771. If your trainable is slow to initialize, consider setting reuse_actors=True to reduce actor creation overheads.
2019-03-24 00:10:18,199 INFO ray_trial_executor.py:178 -- Destroying actor for trial TRAIN_FN_6_dropout1=0.72255,hidden=446,lr=0.086364,momentum=0.86826. If your trainable is slow to initialize, consider setting reuse_actors=True to reduce actor creation overheads.
2019-03-24 00:10:44,899 INFO ray_trial_executor.py:178 -- Destroying actor for trial TRAIN_FN_2_dropout1=0.73158,hidden=107,lr=0.087594,momentum=0.5979. If your trainable is slow to initialize, consider setting reuse_actors=True to reduce actor creation overheads.
2019-03-24 00:10:48,515 INFO ray_trial_executor.py:178 -- Destroying actor for trial TRAIN_FN_0_dropout1=0.2571,hidden=236,lr=0.0083709,momentum=0.47214. If your trainable is slow to initialize, consider setting reuse_actors=True to reduce actor creation overheads.
2019-03-24 00:10:51,434 INFO ray_trial_executor.py:178 -- Destroying actor for trial TRAIN_FN_7_dropout1=0.47593,hidden=218,lr=0.067242,momentum=0.85505. If your trainable is slow to initialize, consider setting reuse_actors=True to reduce actor creation overheads.
2019-03-24 00:10:54,745 INFO ray_trial_executor.py:178 -- Destroying actor for trial TRAIN_FN_8_dropout1=0.47459,hidden=383,lr=0.094025,momentum=0.39063. If your trainable is slow to initialize, consider setting reuse_actors=True to reduce actor creation overheads.
2019-03-24 00:10:56,552 INFO ray_trial_executor.py:178 -- Destroying actor for trial TRAIN_FN_5_dropout1=0.5431,hidden=429,lr=0.031262,momentum=0.61523. If your trainable is slow to initialize, consider setting reuse_actors=True to reduce actor creation overheads.

[richardliaw]

I do believe the examples are running but the verbosity is too low. You can see the output by setting verbose=1. I've opened a PR to fix this.

[cgraywang]

Thanks @richardliaw . After setting verbose=1, I got the following by running mnist_pytorch.py. Is that the correct logging info to expect?

== Status ==
Using AsyncHyperBand: num_stopped=0
Bracket: Iter 180.000: None | Iter 60.000: None | Iter 20.000: None
Bracket: Iter 180.000: None | Iter 60.000: None
Bracket: Iter 180.000: None
Resources requested: 0/64 CPUs, 0/8 GPUs
Memory usage on this node: 4.2/515.7 GB

== Status ==
Using AsyncHyperBand: num_stopped=0
Bracket: Iter 180.000: None | Iter 60.000: None | Iter 20.000: None
Bracket: Iter 180.000: None | Iter 60.000: None
Bracket: Iter 180.000: None
Resources requested: 3/64 CPUs, 1/8 GPUs
Memory usage on this node: 4.5/515.7 GB
Result logdir: /home/ubuntu/ray_results/exp
Number of trials: 10 ({'RUNNING': 1, 'PENDING': 9})
PENDING trials:

• TRAIN_FN_1_lr=0.069327,momentum=0.20424: PENDING
• TRAIN_FN_2_lr=0.030203,momentum=0.73374: PENDING
• TRAIN_FN_3_lr=0.047463,momentum=0.86393: PENDING
• TRAIN_FN_4_lr=0.056732,momentum=0.87934: PENDING
• TRAIN_FN_5_lr=0.085988,momentum=0.12916: PENDING
• TRAIN_FN_6_lr=0.086469,momentum=0.75252: PENDING
• TRAIN_FN_7_lr=0.031447,momentum=0.19395: PENDING
• TRAIN_FN_8_lr=0.0037316,momentum=0.20305: PENDING
• TRAIN_FN_9_lr=0.0021654,momentum=0.45954: PENDING
  RUNNING trials:
• TRAIN_FN_0_lr=0.026386,momentum=0.89449: RUNNING

== Status ==
Using AsyncHyperBand: num_stopped=0
Bracket: Iter 180.000: None | Iter 60.000: None | Iter 20.000: None
Bracket: Iter 180.000: None | Iter 60.000: None
Bracket: Iter 180.000: None
Resources requested: 24/64 CPUs, 8/8 GPUs
Memory usage on this node: 28.4/515.7 GB
Result logdir: /home/ubuntu/ray_results/exp
Number of trials: 10 ({'RUNNING': 8, 'PENDING': 2})
PENDING trials:

• TRAIN_FN_8_lr=0.0037316,momentum=0.20305: PENDING
• TRAIN_FN_9_lr=0.0021654,momentum=0.45954: PENDING
  RUNNING trials:
• TRAIN_FN_0_lr=0.026386,momentum=0.89449: RUNNING
• TRAIN_FN_1_lr=0.069327,momentum=0.20424: RUNNING
• TRAIN_FN_2_lr=0.030203,momentum=0.73374: RUNNING
• TRAIN_FN_3_lr=0.047463,momentum=0.86393: RUNNING, [3 CPUs, 1 GPUs], [pid=40211], 21 s, 1 iter, 0.136 loss, 0.96 acc
• TRAIN_FN_4_lr=0.056732,momentum=0.87934: RUNNING
• TRAIN_FN_5_lr=0.085988,momentum=0.12916: RUNNING
• TRAIN_FN_6_lr=0.086469,momentum=0.75252: RUNNING
• TRAIN_FN_7_lr=0.031447,momentum=0.19395: RUNNING

== Status ==
Using AsyncHyperBand: num_stopped=0
Bracket: Iter 180.000: None | Iter 60.000: None | Iter 20.000: None
Bracket: Iter 180.000: None | Iter 60.000: None
Bracket: Iter 180.000: None
Resources requested: 6/64 CPUs, 2/8 GPUs
Memory usage on this node: 11.6/515.7 GB
Result logdir: /home/ubuntu/ray_results/exp
Number of trials: 10 ({'TERMINATED': 8, 'RUNNING': 2})
RUNNING trials:

• TRAIN_FN_8_lr=0.0037316,momentum=0.20305: RUNNING, [3 CPUs, 1 GPUs], [pid=44714], 20 s, 1 iter, 0.615 loss, 0.844 acc
• TRAIN_FN_9_lr=0.0021654,momentum=0.45954: RUNNING
  TERMINATED trials:
• TRAIN_FN_0_lr=0.026386,momentum=0.89449: TERMINATED, [3 CPUs, 1 GPUs], [pid=40216], 22 s, 1 iter, 0.101 loss, 0.972 acc
• TRAIN_FN_1_lr=0.069327,momentum=0.20424: TERMINATED, [3 CPUs, 1 GPUs], [pid=40220], 23 s, 1 iter, 0.1 loss, 0.968 acc
• TRAIN_FN_2_lr=0.030203,momentum=0.73374: TERMINATED, [3 CPUs, 1 GPUs], [pid=40201], 22 s, 1 iter, 0.0935 loss, 0.971 acc
• TRAIN_FN_3_lr=0.047463,momentum=0.86393: TERMINATED, [3 CPUs, 1 GPUs], [pid=40211], 21 s, 1 iter, 0.136 loss, 0.96 acc
• TRAIN_FN_4_lr=0.056732,momentum=0.87934: TERMINATED, [3 CPUs, 1 GPUs], [pid=40210], 21 s, 1 iter, 0.178 loss, 0.95 acc
• TRAIN_FN_5_lr=0.085988,momentum=0.12916: TERMINATED, [3 CPUs, 1 GPUs], [pid=40187], 23 s, 1 iter, 0.108 loss, 0.967 acc
• TRAIN_FN_6_lr=0.086469,momentum=0.75252: TERMINATED, [3 CPUs, 1 GPUs], [pid=40221], 22 s, 1 iter, 0.137 loss, 0.961 acc
• TRAIN_FN_7_lr=0.031447,momentum=0.19395: TERMINATED, [3 CPUs, 1 GPUs], [pid=40183], 21 s, 1 iter, 0.144 loss, 0.957 acc

== Status ==
Using AsyncHyperBand: num_stopped=0
Bracket: Iter 180.000: None | Iter 60.000: None | Iter 20.000: None
Bracket: Iter 180.000: None | Iter 60.000: None
Bracket: Iter 180.000: None
Resources requested: 0/64 CPUs, 0/8 GPUs
Memory usage on this node: 8.9/515.7 GB
Result logdir: /home/ubuntu/ray_results/exp
Number of trials: 10 ({'TERMINATED': 10})
TERMINATED trials:

• TRAIN_FN_0_lr=0.026386,momentum=0.89449: TERMINATED, [3 CPUs, 1 GPUs], [pid=40216], 22 s, 1 iter, 0.101 loss, 0.972 acc
• TRAIN_FN_1_lr=0.069327,momentum=0.20424: TERMINATED, [3 CPUs, 1 GPUs], [pid=40220], 23 s, 1 iter, 0.1 loss, 0.968 acc
• TRAIN_FN_2_lr=0.030203,momentum=0.73374: TERMINATED, [3 CPUs, 1 GPUs], [pid=40201], 22 s, 1 iter, 0.0935 loss, 0.971 acc
• TRAIN_FN_3_lr=0.047463,momentum=0.86393: TERMINATED, [3 CPUs, 1 GPUs], [pid=40211], 21 s, 1 iter, 0.136 loss, 0.96 acc
• TRAIN_FN_4_lr=0.056732,momentum=0.87934: TERMINATED, [3 CPUs, 1 GPUs], [pid=40210], 21 s, 1 iter, 0.178 loss, 0.95 acc
• TRAIN_FN_5_lr=0.085988,momentum=0.12916: TERMINATED, [3 CPUs, 1 GPUs], [pid=40187], 23 s, 1 iter, 0.108 loss, 0.967 acc
• TRAIN_FN_6_lr=0.086469,momentum=0.75252: TERMINATED, [3 CPUs, 1 GPUs], [pid=40221], 22 s, 1 iter, 0.137 loss, 0.961 acc
• TRAIN_FN_7_lr=0.031447,momentum=0.19395: TERMINATED, [3 CPUs, 1 GPUs], [pid=40183], 21 s, 1 iter, 0.144 loss, 0.957 acc
• TRAIN_FN_8_lr=0.0037316,momentum=0.20305: TERMINATED, [3 CPUs, 1 GPUs], [pid=44714], 20 s, 1 iter, 0.615 loss, 0.844 acc
• TRAIN_FN_9_lr=0.0021654,momentum=0.45954: TERMINATED, [3 CPUs, 1 GPUs], [pid=44504], 21 s, 1 iter, 0.785 loss, 0.819 acc

[cgraywang]

@richardliaw I now encounter this error when running on my own dataset, could you help to take a look?

== Status ==
Using AsyncHyperBand: num_stopped=0
Bracket: Iter 180.000: None | Iter 60.000: None | Iter 20.000: -0.807997695746876
Bracket: Iter 180.000: None | Iter 60.000: None
Bracket: Iter 180.000: None
Resources requested: 0/64 CPUs, 0/8 GPUs
Memory usage on this node: 10.3/515.7 GB
Number of trials: 1 ({'TERMINATED': 1})
TERMINATED trials:

• TRAIN_FN_0_lr=0.0011869,momentum=0.85123: TERMINATED, [8 CPUs, 1 GPUs], [pid=62765], 407 s, 20 iter, 0.808 loss, 0.722 acc

Exception ignored in: <object repr() failed>
Traceback (most recent call last):
File "/home/ubuntu/ray/python/ray/actor.py", line 538, in del
AttributeError: 'NoneType' object has no attribute 'get_global_worker'

[cgraywang]

One more question, some trials completed successfully, while some of them completed with errors, do you have any clue on that? @richardliaw The error msg is as below:

Traceback (most recent call last):
File "xxxx.py", line 194, in
lambda spec: np.random.uniform(0.85, 0.95)),
File "/home/ubuntu/ray/python/ray/tune/tune.py", line 253, in run
raise TuneError("Trials did not complete", errored_trials)

The error log looks like:

Traceback (most recent call last):
File "/home/ubuntu/ray/python/ray/tune/trial_runner.py", line 409, in _process_trial
result = self.trial_executor.fetch_result(trial)
File "/home/ubuntu/ray/python/ray/tune/ray_trial_executor.py", line 314, in fetch_result
result = ray.get(trial_future[0])
File "/home/ubuntu/ray/python/ray/worker.py", line 2316, in get
raise value
ray.exceptions.RayTaskError: ESC[36mray_workerESC[39m (pid=110493, host=ip-172-31-16-161)
File "/home/ubuntu/ray/python/ray/tune/trainable.py", line 151, in train
result = self._train()
File "/home/ubuntu/ray/python/ray/tune/function_runner.py", line 203, in _train
("Wrapped function ran until completion without reporting "
ray.tune.error.TuneError: Wrapped function ran until completion without reporting results or raising an exception.

[richardliaw]

Sorry for the late response:

1. Your first output looks right.
2. That doesn't look like an error; it just seems like you completed the run
3. This error is raised if you don't call reporter anywhere in your training run; for the most part it looks harmless.

[cgraywang]

Thanks. Just want to confirm with you that for the third error as the below, you suggest me to add reporter in the train() right? However, in the example mnist_pytorch.py, def train(epoch) also doesn't have the reporter, but def test() you have the reporter, which is the same in my case.

Traceback (most recent call last):
File "/home/ubuntu/ray/python/ray/tune/trial_runner.py", line 409, in _process_trial
result = self.trial_executor.fetch_result(trial)
File "/home/ubuntu/ray/python/ray/tune/ray_trial_executor.py", line 314, in fetch_result
result = ray.get(trial_future[0])
File "/home/ubuntu/ray/python/ray/worker.py", line 2316, in get
raise value
ray.exceptions.RayTaskError: ESC[36mray_workerESC[39m (pid=110493, host=ip-172-31-16-161)
File "/home/ubuntu/ray/python/ray/tune/trainable.py", line 151, in train
result = self._train()
File "/home/ubuntu/ray/python/ray/tune/function_runner.py", line 203, in _train
("Wrapped function ran until completion without reporting "
ray.tune.error.TuneError: Wrapped function ran until completion without reporting results or raising an exception.

[timonbimon]

@cgraywang what did you end up doing about the "AttributeError: 'NoneType' object has no attribute 'get_global_worker'" message?