# Read Tune console output from Simple Q

**URL:** <https://discuss.ray.io/t/read-tune-console-output-from-simple-q/3845>\
**Category:** RLlib\
**Created:** [October 18, 2021, 4:17pm UTC](https://discuss.ray.io/t/read-tune-console-output-from-simple-q/3845 "2021-10-18T16:17:37Z")\
**Posts on this page:** 9\
**Page:** 1

<div class="post-metadata">

**Author:** ![Lars\_Simon\_Zehnder](https://sea2.discourse-cdn.com/flex020/user_avatar/discuss.ray.io/lars_simon_zehnder/32/1185_2.png) [@Lars\_Simon\_Zehnder](https://discuss.ray.io/u/Lars_Simon_Zehnder)\
**Post date:** [October 18, 2021, 4:17pm UTC](https://discuss.ray.io/t/read-tune-console-output-from-simple-q/3845/1 "2021-10-18T16:17:38Z")

</div>

Hi everyone,

I run `SimpleQTrainer` with `Tune` using the following script:

```auto
import ray
from ray import tune
import ray.rllib.agents.dqn as dqn

ray.init()
config = dqn.SIMPLE_Q_DEFAULT_CONFIG.copy()
config["num_gpus"] = 0
config["num_workers"] = 0

tune_config = {
    "env": "Breakout-v0",
    "model": config
}

tune.run(dqn.SimpleQTrainer, config=tune_config)

```

Everything seems to run nice, but I try to understand the console output from `Tune` and `RLlib`.

**1. First of all:** I get a couple of times the exactly same output in a row from `Tune`:

 ![Bildschirmfoto vom 2021-10-18 17-34-23](https://us1.discourse-cdn.com/flex020/uploads/ray/original/2X/0/06431c88880c4035d8d9dda8d69ded89060e2615.png)  
I can’t understand where this is coming from? From different environments of the `VectorEnv`? The number of such identical outputs variates around 5. **What is the explanation for this behavior?**

**2.** The output of the metrics shows me the following:

![Bildschirmfoto vom 2021-10-18 17-38-32](https://us1.discourse-cdn.com/flex020/uploads/ray/original/2X/2/2ce51ceeabc323e9ee744bf1983cf3375df65dbc.png)

`num_steps_sampled` is clear: I am at iteration `439` and in each iteration `timesteps_per_iteration=1000` steps get sampled. However, the `num_steps_trained` is unclear to me.  
As far as I understood from the [source code](https://github.com/ray-project/ray/blob/1047914ee0ec27d0e7b8fc3599f8a0a573ba2dd7/rllib/agents/dqn/simple_q.py#L174), the sampling and training operations are alternated (`"round_robin"` mode) and a call to `learn_on_batch()` only happens after `1000` steps got sampled? **Why is `num_steps_trained` then so high?** Especially where the `train_batch_size=32 * replay_sequence_length=1` is significantly smaller than `timesteps_per_iteration=1000`?

**3.**  **How can I interpret in the last image, `num_target_updates`?** From the [`DEFAULT_CONFIG`](https://github.com/ray-project/ray/blob/9dba5e0eadd3a065023d6cc7cafff631355c980a/rllib/agents/dqn/simple_q.py#L59) I read that each `500`th iteration the target network is also updated. This fits almost the output:

```auto
(num_steps_sampled - learning_starts - target_update_freq) 
      / target_update_freq = 875

```

so almost `num_target_updates=870`. **Where comes the difference from?**

Thanks for taking time

---

<div class="post-metadata">

**Author:** ![mannyv](https://sea2.discourse-cdn.com/flex020/user_avatar/discuss.ray.io/mannyv/32/606_2.png) [@mannyv](https://discuss.ray.io/u/mannyv)\
**Post date:** [October 18, 2021, 8:42pm UTC](https://discuss.ray.io/t/read-tune-console-output-from-simple-q/3845/2 "2021-10-18T20:42:55Z")

</div>

Hi @Lars_Simon_Zehnder,

Regarding 2. and 3. I have an experiment for you. Change the `rollout_fragment_length` to be equal to the `train_batch_size` and see what happens.

---

<div class="post-metadata">

**Author:** ![Lars\_Simon\_Zehnder](https://sea2.discourse-cdn.com/flex020/user_avatar/discuss.ray.io/lars_simon_zehnder/32/1185_2.png) [@Lars\_Simon\_Zehnder](https://discuss.ray.io/u/Lars_Simon_Zehnder)\
**Post date:** [October 19, 2021, 12:03pm UTC](https://discuss.ray.io/t/read-tune-console-output-from-simple-q/3845/3 "2021-10-19T12:03:29Z")

</div>

Hi @mannyv ,

thanks for the reply. I tried that out and it helped a lot to understand. Thanks!! I saw at first that the worker collects `1024=32*32` steps. Makes sense to me: The `rollout_fragment_length` must be `train_batch_size` times collected.

**Regarding 2.:** The `Trainer` then starts training after `training_starts=1000` steps sampled, which has been done in the first iteration. It trains a `train_batch_size` with `replay_sequence_length=1` (I guess this parameter simply defines how many contiguous steps should be resampled - in this case all samples can be non-contiguous).

Now, `timesteps_per_iteration=1000` and so in each iteration at least 1000 steps should be trained with a `train_batch_size=32`. The smallest multiple of `train_batch_size` greater than `timesteps_per_iteration` equals `-(-(1000)//32)*32=1024`, so each training iteration trains on `1024` steps (`32` batches). As training is allowed only after `learning_starts` steps the `Trainer` is in the first period only allowed to train on a single batch, as this is the smallest mutliple of `32` in `1024-1000=24`. **Where do I find this in the source code?**

**Regarding 3.:** `target_network_update_freq=500` which means everytime `num_train_steps % 500 == 0` holds, the target network also gets updated. This is in the first iteration once and thereafter two times per train iteration the case. **Here, I also would like to take a look at the source code …**

I am still thinking about the multiple identical console outputs from `Tune` under **1.**.

Thanks for your time, @mannyv !

---

<div class="post-metadata">

**Author:** ![kai](https://sea2.discourse-cdn.com/flex020/user_avatar/discuss.ray.io/kai/32/3380_2.png) [@kai](https://discuss.ray.io/u/kai)\
**Post date:** [October 20, 2021, 8:16am UTC](https://discuss.ray.io/t/read-tune-console-output-from-simple-q/3845/4 "2021-10-20T08:16:10Z")

</div>

Hi Lars,

regarding 1), Tune outputs a status table every 5 seconds. If no result is received, the table will remain the same.

In the latest master, we introduced a timer, with this you would see that time progresses:

```auto
== Status ==
Current time: 2021-10-20 09:14:28 (running for 00:00:52.47)
Memory usage on this node: 11.2/16.0 GiB
...

```

---

<div class="post-metadata">

**Author:** ![mannyv](https://sea2.discourse-cdn.com/flex020/user_avatar/discuss.ray.io/mannyv/32/606_2.png) [@mannyv](https://discuss.ray.io/u/mannyv)\
**Post date:** [October 20, 2021, 1:46pm UTC](https://discuss.ray.io/t/read-tune-console-output-from-simple-q/3845/5 "2021-10-20T13:46:03Z")

</div>

Hi @Lars_Simon_Zehnder,

You were right when you were initially trying to relate number of episode steps used during the rollout and training phases. You correctly realized that they alternate back and forth between each phase but I think where you may have had a misunderstanding is on how often those steps occur. At least when I was initially looking at it my first assumption was that it would sample “timesteps\_per\_iteration” steps during rollout and then do one update but that is not how it works.

Assuming we are using batch\_mode=“truncate\_episodes”,  
During the rollout phase it will collect `max(num_workers,1) * rollout_fragment_length` new samples. That is checked here:

> <https://github.com/ray-project/ray/blob/9dba5e0eadd3a065023d6cc7cafff631355c980a/rllib/evaluation/rollout_worker.py#L765-L774>

Then it will do the training step. It will also collect 1000 steps before training at all.

So you have the following:  
In the first iteration you collect 4 samples 250 times and train 1 time with 32 steps.  
On each iteration after that you will collect 1000 new samples in the rollout phase in chunks of 4 250 times and you will train 32 steps 250 times.

steps\_sampled = 439 \* 1000 = 439\_000  
steps\_trained = 32 + 438 \* 32\*250 = 3\_504\_032

OK so target\_updates which should happen every 500 ts is a little tricky. You would expect the following:  
target\_updates = 1 + 438 \* 2 = 877 but we only get 870. Why.

Well you look at the code:

> <https://github.com/ray-project/ray/blob/9dba5e0eadd3a065023d6cc7cafff631355c980a/rllib/execution/train_ops.py#L388-L397>

Line 392 uses \> not \>= so you are shifting the target by `max(num_workers,1) *rollout_fragment_length` every time.

So the update time ends up being:

target\_updates = 1 + 438 \* 2 - (438 \* 2 \* (1 \* 4) / 500) = 870

Here is the code that skips training for learning\_starts steps:

> <https://github.com/ray-project/ray/blob/9dba5e0eadd3a065023d6cc7cafff631355c980a/rllib/execution/replay_buffer.py#L521-L522>

One last thing about replay\_sequence\_length since you mentioned it a couple times.

The replay buffer stores `buffer_size` samples. The question is samples of what size? Well it stores `buffer_size` samples of length `replay_sequence_length`.

This happens here:

> <https://github.com/ray-project/ray/blob/9dba5e0eadd3a065023d6cc7cafff631355c980a/rllib/execution/replay_buffer.py#L483-L512>

If you sample from the buffer then you will get `train_batch_size` samples. These can and usually will be non-contiguous in time but each of these samples will be `replay_sequence_length` long and that sub sequence will be temporally contiguous. Usually, but not strictly required, this is used for memory or attention and the `replay_sequence_length` will be the same as `max_sequence_length`.

Hope this helps everything make sense.

* * *

> **[Manny is helping people do cool things with RL](https://www.buymeacoffee.com/mannyv)**
>
> Hey, so glad we got to connect. If you found my suggestions useful feel free to buy me a coffee!

---

<div class="post-metadata">

**Author:** ![Lars\_Simon\_Zehnder](https://sea2.discourse-cdn.com/flex020/user_avatar/discuss.ray.io/lars_simon_zehnder/32/1185_2.png) [@Lars\_Simon\_Zehnder](https://discuss.ray.io/u/Lars_Simon_Zehnder)\
**Post date:** [October 20, 2021, 3:20pm UTC](https://discuss.ray.io/t/read-tune-console-output-from-simple-q/3845/6 "2021-10-20T15:20:41Z")

</div>

@kai thanks a lot for clarifying this! I like the new approach for the upcoming release. It drove me a little insecure, if this is the right behavior or if I had to make some modifications to the code …

---

<div class="post-metadata">

**Author:** ![Lars\_Simon\_Zehnder](https://sea2.discourse-cdn.com/flex020/user_avatar/discuss.ray.io/lars_simon_zehnder/32/1185_2.png) [@Lars\_Simon\_Zehnder](https://discuss.ray.io/u/Lars_Simon_Zehnder)\
**Post date:** [October 20, 2021, 3:45pm UTC](https://discuss.ray.io/t/read-tune-console-output-from-simple-q/3845/7 "2021-10-20T15:45:31Z")

</div>

Hi @mannyv ,

that is an amazingly detailed answer! Thanks for the clarification. I did indeed misunderstand how samples are collected in rollouts. So, as far as I understand it, the `timesteps_per_iteration` gives a lower bound for the steps to be sampled and if this latter number cannot be divided evenly by `max(num_workers, 1) * rollout_fragment_length)` it could also overshoot this number.

What I do not yet fully understand (only intuitively - but I read deeper into the code) is where the `Trainer` gets the **250 train steps** from. Somehow this might be calculated via the `timesteps_per_iteration` and the `num_workers`?

Regarding the `num_update_target` count - this is tricky indeed! I don’t know, if I would have come up with this explanation without getting this hint.

In regard to the `replay_sequence_length` I assume that a sequence of length 1 is actually one step in the environment with `(s_t, a_t, r_{t+1}, s_{t+1})` like in the original paper by Minh et al. (2013). Correct me, if I am wrong.

Great links to the source code. This helps me a lot! Thanks for your time!

---

<div class="post-metadata">

**Author:** ![mannyv](https://sea2.discourse-cdn.com/flex020/user_avatar/discuss.ray.io/mannyv/32/606_2.png) [@mannyv](https://discuss.ray.io/u/mannyv)\
**Post date:** [October 20, 2021, 11:28pm UTC](https://discuss.ray.io/t/read-tune-console-output-from-simple-q/3845/8 "2021-10-20T23:28:54Z")

</div>

Hi @Lars_Simon_Zehnder,

Yes the timesteps\_per\_iteration expresses a lower bound on the number of new steps sampled. You can collect more timesteps of they do not divide evenly. Keep in mind though that the frequency of an iteration is really more of a decision of how often you want new metrics reported and checkpointing. There are usually sampling and traing cycles within one iteration.

The 250 is not computed explicitly. Tune will call the trainers train function repeatedly until the iteration criteria (timesteps\_per\_iteration and min\_iteration\_ms) are satisfied. It just so happens that when pulling 4 samples at a time it takes 250 calls. If the rollout glfragment length was 6 then I would expect to see 167 cycles per iteration.

Yes you are correct the replay buffer will hold all the values collected for each environment transition. The ones you listed plus a few more I think. It will depend on what ViewRequirements are set.

One last thing to note. The description in the previous post is about the off policy algorithms that use a replay buffer. The on policy ones like PPO and A2C are largely the same but have some slight differences. The main one is that samples are collected in num\_workers \*rollout\_fragment\_length chunks until the training\_batch\_size is reached then the training op is run.

---

<div class="post-metadata">

**Author:** ![Lars\_Simon\_Zehnder](https://sea2.discourse-cdn.com/flex020/user_avatar/discuss.ray.io/lars_simon_zehnder/32/1185_2.png) [@Lars\_Simon\_Zehnder](https://discuss.ray.io/u/Lars_Simon_Zehnder)\
**Post date:** [October 26, 2021, 10:02am UTC](https://discuss.ray.io/t/read-tune-console-output-from-simple-q/3845/9 "2021-10-26T10:02:09Z")

</div>

This is a perfect clarification! Thank you @mannyv ! And respect for reading so much through the source code 💯