Repository: optuna/optuna
Pull request: Fix the wrong way to set `datetime_start` (clean)
> A clean version of [this PR](https://github.com/optuna/optuna/pull/2196) to change the way to set `datetime_start`, as that one is polluted and closed due to my mistaken push with `--force` option. Sorry for the repeated PR.

Fixes #2036.

## Motivation
<!-- Describe your motivation why you will submit this PR. This is useful for reviewers to understand the context of PR. -->

The current mechanism to set the `datetime_start` of a given trial is to add a time value when creating that trial. However, this could be wrong if the created trial is not the one to be executed right after its creation. The `datetime_start` of these waiting trials won't be updated before and after their delayed execution. For specific example, see [#2306](https://github.com/optuna/optuna/issues/2036).

## Description of the changes
<!-- Describe the changes in this PR. -->

The mechanism to initialize `datetime_start` is changed. Now we set the time of trial start when its state changes to `RUNNING`. This ensures the `datetime_start ` to be the moment right before execution. This is implemented in `set_trial_state`.


<img width="747" alt="Xnip2021-01-13_00-34-10" src="https://user-images.githubusercontent.com/11160442/104410931-5b677080-5537-11eb-84e7-5d4a0782a52b.png">
Trial 11-20 were appended to the study through `enqueue_trial ` after trial 10 but were executed several minutes later. After change the `datetime_start ` becomes the 2s duration set by the objective function:

```python
def objective(trial):
    x = trial.suggest_uniform("x", 0, 10)
    time.sleep(2)
    return x**2
```



Problem statement:
Start time is wrong when calculating trials added by `enqueue_trial`.
I have a study with 30 trials. I read this study with all trials and use `enqueue_trial` to create a new study and add the best 10 trials. Then I start optuna to calculate the results on all 10 trials of the new study.

I observe that the logged "datetime_start" of all 10 trials is the same (which is wrong since the runs need a significant amount of time). After the 10 enqued runs the time is logged correctly for trial 11 and so on.

I am using optuna 2.3.0 from pip.

Hints from issue discussion:
Could you share a minimal example to reproduce your bug?
I saw that the start time is set when the trial is enqued. IMO it should be set when the state changes from WAITING to RUNNING.
> Could you share your minimal example to reproduce your bug?

Just take an optuna study with trials and enque them to an other study. You will see that starting time is set.
Starting time should be set when the state changes to running. Not when enqued (WAITING).
Like this?

```python
import time
import optuna


def objective(trial):
    x = trial.suggest_uniform("x", 0, 10)
    time.sleep(0.5)
    return x ** 2


study = optuna.create_study()
study.optimize(objective, n_trials=10)

new_study = optuna.create_study()


for frozen_trial in study.trials:
    new_study.enqueue_trial(frozen_trial.params)

new_study.optimize(objective, n_trials=20)
```

Yes. But one change is that I use a local SQLite DB and quit the python runtime after first optimization, and after enque.
Thanks, so like this

```python
import optuna
import time


def objective(trial):
    x = trial.suggest_uniform("x", 0, 10)
    time.sleep(1)
    return x ** 2

study = optuna.create_study(study_name='example-study', storage='sqlite:///example.db')
study.optimize(objective, n_trials=10)


new_study = optuna.create_study(study_name='example-study', storage='sqlite:///example.db', load_if_exists=True)
for frozen_trial in study.trials:
    new_study.enqueue_trial(frozen_trial.params)

new_study.optimize(objective, n_trials=10)


print("show all `datetime_start`")
for i in range(len(new_study.trials)):
    print(new_study.trials[i].datetime_start)
```

Output:
```
show all `datetime_start`
2020-11-18 17:57:42.280086
2020-11-18 17:57:43.315864
2020-11-18 17:57:44.345529
2020-11-18 17:57:45.374185
2020-11-18 17:57:46.403691
2020-11-18 17:57:47.433724
2020-11-18 17:57:48.461977
2020-11-18 17:57:49.489054
2020-11-18 17:57:50.517336
2020-11-18 17:57:51.547932
2020-11-18 17:57:52.595424
2020-11-18 17:57:52.605769
2020-11-18 17:57:52.612032
2020-11-18 17:57:52.617892
2020-11-18 17:57:52.624796
2020-11-18 17:57:52.630669
2020-11-18 17:57:52.636577
2020-11-18 17:57:52.642492
2020-11-18 17:57:52.647706
2020-11-18 17:57:52.653105
```

Note that the optuna's version is [latest](https://github.com/optuna/optuna/tree/af7f15764bfce658c8caabdeff5067b9b0bc40bc).
More like this:

```python
import optuna
import time

def objective(trial):
    x = trial.suggest_uniform("x", 0, 10)
    time.sleep(5)
    return x ** 2

study = optuna.create_study(study_name='example-study', storage='sqlite:///example.db')
study.optimize(objective, n_trials=10)

# quit and restart python

old_study = optuna.create_study(study_name='example-study', storage='sqlite:///example.db', load_if_exists=True)

trials = [t for t in old_study .get_trials() if t.value is not None]
trials = sorted(trials, key=lambda trial: trial.value, reverse=True)
trials = trials[:10]

del old_study 

new_study = optuna.create_study(study_name='example-study', storage='sqlite:///example.db', load_if_exists=True)
for frozen_trial in trials:
    new_study.enqueue_trial(frozen_trial.params)

# quit and restart python

new_study = optuna.create_study(study_name='example-study', storage='sqlite:///example.db', load_if_exists=True)
new_study.optimize(objective, n_trials=10)


print("show all `datetime_start`")
for i in range(len(new_study.trials)):
    print(new_study.trials[i].datetime_start)
```
@nzw0301 have you been able to reproduce this?
I misunderstood your comments. Please ignore the original comment below.

---

> I observe that the logged "datetime_start" of all 10 trials is the same 

~You mean `datetime_start` of all enqueued 10 trials are exact same value among them, don't you? If so, I cannot reproduce that.~
Thank you @PhilipMay and @nzw0301 for your discussions.

As @PhilipMay observed, `datetime_start` is set the time when trials are enqueued, not the time when the state changed to `RUNNING`.

> I saw that the start time is set when the trial is enqued. IMO it should be set when the state changes from WAITING to RUNNING.

Thank you for your suggestion. I think it is worth considering to change the behavior though I have some concerns:

* It is a breaking change so we need to fix it carefully.
* How we keep the time when the trial is enqueued?
* It is required to change the [RDB schema](https://github.com/optuna/optuna/blob/2c23679b19695baf1256b76e0e59d426dd644144/optuna/storages/_rdb/models.py#L168).
* It is required to fix the calculation logic of `StudySummary.datetime_start`.

Commit message: add tests for StudySummary with enqueued trials

Patch to review:
diff --git a/optuna/storages/_cached_storage.py b/optuna/storages/_cached_storage.py
index b2daf53a77e..ed40f5b53e1 100644
--- a/optuna/storages/_cached_storage.py
+++ b/optuna/storages/_cached_storage.py
@@ -29,6 +29,7 @@ def __init__(self) -> None:
         self.params: Dict[str, Any] = {}
         self.distributions: Dict[str, distributions.BaseDistribution] = {}
         self.datetime_complete: Optional[datetime.datetime] = None
+        self.datetime_start: Optional[datetime.datetime] = None
 
 
 class _StudyInfo:
@@ -199,6 +200,11 @@ def set_trial_state(self, trial_id: int, state: TrialState) -> bool:
                 updates = self._get_updates(trial_id)
                 cached_trial.state = state
                 updates.state = state
+
+                if state == TrialState.RUNNING:
+                    updates.datetime_start = datetime.datetime.now()
+                    cached_trial.datetime_start = datetime.datetime.now()
+
                 if cached_trial.state.is_finished():
                     updates.datetime_complete = datetime.datetime.now()
                     cached_trial.datetime_complete = datetime.datetime.now()
@@ -424,6 +430,7 @@ def _flush_trial(self, trial_id: int) -> bool:
             distributions_=updates.distributions,
             user_attrs=updates.user_attrs,
             system_attrs=updates.system_attrs,
+            datetime_start=updates.datetime_start,
             datetime_complete=updates.datetime_complete,
         )
 
diff --git a/optuna/storages/_in_memory.py b/optuna/storages/_in_memory.py
index 17cb19a27ef..11893e25b72 100644
--- a/optuna/storages/_in_memory.py
+++ b/optuna/storages/_in_memory.py
@@ -171,7 +171,9 @@ def _build_study_summary(self, study_id: int) -> StudySummary:
                 [
                     cast(datetime, trial.datetime_start)
                     for trial in self.get_all_trials(study_id, deepcopy=False)
-                ]
+                    if trial.datetime_start is not None
+                ],
+                default=None,
             )
             if study.trials
             else None,
@@ -227,6 +229,10 @@ def set_trial_state(self, trial_id: int, state: TrialState) -> bool:
                 return False
 
             trial.state = state
+
+            if state == TrialState.RUNNING:
+                trial.datetime_start = datetime.now()
+
             if state.is_finished():
                 trial.datetime_complete = datetime.now()
                 self._set_trial(trial_id, trial)
diff --git a/optuna/storages/_rdb/models.py b/optuna/storages/_rdb/models.py
index bd5d1e20fc1..9be6f9cf627 100644
--- a/optuna/storages/_rdb/models.py
+++ b/optuna/storages/_rdb/models.py
@@ -1,4 +1,3 @@
-from datetime import datetime
 from typing import Any
 from typing import List
 from typing import Optional
@@ -182,7 +181,7 @@ class TrialModel(BaseModel):
     number = Column(Integer)
     study_id = Column(Integer, ForeignKey("studies.study_id"))
     state = Column(Enum(TrialState), nullable=False)
-    datetime_start = Column(DateTime, default=datetime.now)
+    datetime_start = Column(DateTime)
     datetime_complete = Column(DateTime)
 
     study = orm.relationship(
diff --git a/optuna/storages/_rdb/storage.py b/optuna/storages/_rdb/storage.py
index b82b921adee..76c0c118698 100644
--- a/optuna/storages/_rdb/storage.py
+++ b/optuna/storages/_rdb/storage.py
@@ -540,7 +540,12 @@ def _get_prepared_new_trial(
         self, study_id: int, template_trial: Optional[FrozenTrial], session: orm.Session
     ) -> models.TrialModel:
         if template_trial is None:
-            trial = models.TrialModel(study_id=study_id, number=None, state=TrialState.RUNNING)
+            trial = models.TrialModel(
+                study_id=study_id,
+                number=None,
+                state=TrialState.RUNNING,
+                datetime_start=datetime.now(),
+            )
         else:
             # Because only `RUNNING` trials can be updated,
             # we temporarily set the state of the new trial to `RUNNING`.
@@ -609,6 +614,7 @@ def _update_trial(
         distributions_: Optional[Dict[str, distributions.BaseDistribution]] = None,
         user_attrs: Optional[Dict[str, Any]] = None,
         system_attrs: Optional[Dict[str, Any]] = None,
+        datetime_start: Optional[datetime] = None,
         datetime_complete: Optional[datetime] = None,
     ) -> bool:
         """Sync latest trial updates to a database.
@@ -630,6 +636,9 @@ def _update_trial(
                 New user_attr. None when there are no updates.
             system_attrs:
                 New system_attr. None when there are no updates.
+            datetime_start:
+                Start time of the trial. Set when this method change the state
+                of trial into running state.
             datetime_complete:
                 Completion time of the trial. Set if and only if this method
                 change the state of trial into one of the finished states.
@@ -654,6 +663,9 @@ def _update_trial(
             if state:
                 trial_model.state = state
 
+            if datetime_start:
+                trial_model.datetime_start = datetime_start
+
             if datetime_complete:
                 trial_model.datetime_complete = datetime_complete
 
@@ -751,6 +763,10 @@ def set_trial_state(self, trial_id: int, state: TrialState) -> bool:
                     return False
 
                 trial.state = state
+
+                if state == TrialState.RUNNING:
+                    trial.datetime_start = datetime.now()
+
                 if state.is_finished():
                     trial.datetime_complete = datetime.now()
         except IntegrityError:
diff --git a/optuna/storages/_redis.py b/optuna/storages/_redis.py
index 3e1d242d4fe..5f488af857b 100644
--- a/optuna/storages/_redis.py
+++ b/optuna/storages/_redis.py
@@ -314,7 +314,12 @@ def create_new_trial(self, study_id: int, template_trial: Optional[FrozenTrial]
             study_summary = self._get_study_summary(study_id)
             study_summary.n_trials = len(self._get_study_trials(study_id))
             min_datetime_start = min(
-                [cast(datetime, t.datetime_start) for t in self.get_all_trials(study_id)]
+                [
+                    cast(datetime, t.datetime_start)
+                    for t in self.get_all_trials(study_id)
+                    if t.datetime_start is not None
+                ],
+                default=None,
             )
             study_summary.datetime_start = min_datetime_start
             pipe.set(self._key_study_summary(study_id), pickle.dumps(study_summary))
@@ -352,6 +357,10 @@ def set_trial_state(self, trial_id: int, state: TrialState) -> bool:
             return False
 
         trial.state = state
+
+        if state == TrialState.RUNNING:
+            trial.datetime_start = datetime.now()
+
         if state.is_finished():
             trial.datetime_complete = datetime.now()
             self._redis.set(self._key_trial(trial_id), pickle.dumps(trial))
diff --git a/optuna/study.py b/optuna/study.py
index 3759a6b694c..5dbcfb2a673 100644
--- a/optuna/study.py
+++ b/optuna/study.py
@@ -457,6 +457,8 @@ def ask(
         trial_id = self._pop_waiting_trial_id()
         if trial_id is None:
             trial_id = self._storage.create_new_trial(self._study_id)
+        else:
+            self._storage.set_trial_state(trial_id, TrialState.RUNNING)
         trial = trial_module.Trial(self, trial_id)
 
         for name, param in fixed_distributions.items():
diff --git a/optuna/trial/_frozen.py b/optuna/trial/_frozen.py
index 7f149fc3bf4..29799eedaf0 100644
--- a/optuna/trial/_frozen.py
+++ b/optuna/trial/_frozen.py
@@ -317,8 +317,11 @@ def set_system_attr(self, key: str, value: Any) -> None:
 
     def _validate(self) -> None:
 
-        if self.datetime_start is None:
-            raise ValueError("`datetime_start` is supposed to be set.")
+        if self.state != TrialState.WAITING:
+            if self.datetime_start is None:
+                raise ValueError(
+                    "`datetime_start` is supposed to be set when the trial state is not waiting."
+                )
 
         if self.state.is_finished():
             if self.datetime_complete is None:
@@ -589,7 +592,11 @@ def create_trial(
     intermediate_values = intermediate_values or {}
     state = state or TrialState.COMPLETE
 
-    datetime_start = datetime.datetime.now()
+    if state == TrialState.WAITING:
+        datetime_start = None
+    else:
+        datetime_start = datetime.datetime.now()
+
     if state.is_finished():
         datetime_complete: Optional[datetime.datetime] = datetime_start
     else:
diff --git a/tests/storages_tests/rdb_tests/test_models.py b/tests/storages_tests/rdb_tests/test_models.py
index 4be83f37d10..6b2f2e6a63d 100644
--- a/tests/storages_tests/rdb_tests/test_models.py
+++ b/tests/storages_tests/rdb_tests/test_models.py
@@ -141,16 +141,13 @@ def test_cascade_delete_on_study(session: Session) -> None:
 class TestTrialModel(object):
     @staticmethod
     def test_default_datetime(session: Session) -> None:
-
-        datetime_1 = datetime.now()
-
-        session.add(TrialModel(state=TrialState.RUNNING))
+        # Regardless of the initial state the trial created here should have null datetime_start
+        session.add(TrialModel(state=TrialState.WAITING))
         session.commit()
 
-        datetime_2 = datetime.now()
-
         trial_model = session.query(TrialModel).first()
-        assert datetime_1 < trial_model.datetime_start < datetime_2
+
+        assert trial_model.datetime_start is None
         assert trial_model.datetime_complete is None
 
     @staticmethod
diff --git a/tests/study_tests/test_study.py b/tests/study_tests/test_study.py
index ae022e6efe5..c911c9555d6 100644
--- a/tests/study_tests/test_study.py
+++ b/tests/study_tests/test_study.py
@@ -1010,3 +1010,71 @@ def test_tell_pruned_values() -> None:
 
     study.tell(trial, state=TrialState.PRUNED)
     assert study.trials[-1].value is None
+
+
+@pytest.mark.parametrize("storage_mode", STORAGE_MODES)
+def test_trial_duration_calculation(storage_mode: str) -> None:
+
+    with StorageSupplier(storage_mode) as storage:
+        study = create_study(storage=storage)
+
+        def objective(trial: Trial) -> float:
+            time.sleep(1)
+            x = trial.suggest_int("x", -10, 10)
+            return x
+
+        study.enqueue_trial(params={"x": 1})
+        # Make sure an enqueued trial is created with null datetime_start
+        t_tmp = study.trials[0]
+        assert t_tmp.datetime_start is None
+
+        # Delayed evaluation for enqueued trial
+        time.sleep(2)
+
+        study.optimize(objective, n_trials=2)
+
+        trial = study.ask()
+        values = objective(trial)
+        study.tell(trial, values=values)
+
+        t0 = study.trials[0]
+        assert t0.datetime_start is not None
+        assert t0.datetime_complete is not None
+        duration_error0 = abs((t0.datetime_complete - t0.datetime_start).total_seconds() - 1)
+        assert duration_error0 < 0.1
+
+        t1 = study.trials[1]
+        assert t1.datetime_start is not None
+        assert t1.datetime_complete is not None
+        duration_error1 = abs((t1.datetime_complete - t1.datetime_start).total_seconds() - 1)
+        assert duration_error1 < 0.1
+
+        t2 = study.trials[2]
+        assert t2.datetime_start is not None
+        assert t2.datetime_complete is not None
+        duration_error2 = abs((t2.datetime_complete - t2.datetime_start).total_seconds() - 1)
+        assert duration_error2 < 0.1
+
+
+@pytest.mark.parametrize("storage_mode", STORAGE_MODES)
+def test_studysummary_datetime_start_calculation(storage_mode: str) -> None:
+
+    with StorageSupplier(storage_mode) as storage:
+
+        def objective(trial: Trial) -> float:
+            x = trial.suggest_int("x", -10, 10)
+            return x
+
+        # StudySummary datetime_start tests
+        study = create_study(storage=storage)
+        study.enqueue_trial(params={"x": 1})
+
+        # Study summary with only enqueued trials should have null datetime_start
+        summaries = study._storage.get_all_study_summaries()
+        assert summaries[0].datetime_start is None
+
+        # Study summary with completed trials should have nonnull datetime_start
+        study.optimize(objective, n_trials=1)
+        study.enqueue_trial(params={"x": 1})
+        summaries = study._storage.get_all_study_summaries()
+        assert summaries[0].datetime_start is not None
diff --git a/tests/trial_tests/test_frozen.py b/tests/trial_tests/test_frozen.py
index c53d91d037a..f113c6ff5f3 100644
--- a/tests/trial_tests/test_frozen.py
+++ b/tests/trial_tests/test_frozen.py
@@ -368,11 +368,18 @@ def test_validate() -> None:
     valid_trial = _create_frozen_trial()
     valid_trial._validate()
 
-    # Invalid: `datetime_start` is not set.
-    invalid_trial = copy.copy(valid_trial)
-    invalid_trial.datetime_start = None
-    with pytest.raises(ValueError):
-        invalid_trial._validate()
+    # Invalid: `datetime_start` is not set when the trial is not in the waiting state.
+    for state in [
+        TrialState.RUNNING,
+        TrialState.COMPLETE,
+        TrialState.PRUNED,
+        TrialState.FAIL,
+    ]:
+        invalid_trial = copy.copy(valid_trial)
+        invalid_trial.state = state
+        invalid_trial.datetime_start = None
+        with pytest.raises(ValueError):
+            invalid_trial._validate()
 
     # Invalid: `state` is `RUNNING` and `datetime_complete` is set.
     invalid_trial = copy.copy(valid_trial)


Code review comments:
diff_hunk: @@ -199,6 +200,11 @@ def set_trial_state(self, trial_id: int, state: TrialState) -> bool:
                 updates = self._get_updates(trial_id)
                 cached_trial.state = state
                 updates.state = state
+
+                if state == TrialState.RUNNING:
+                    updates.datetime_start = datetime.datetime.now()
+                    cached_trial.datetime_start = datetime.datetime.now()
path: optuna/storages/_cached_storage.py
text: @user1:
If we set a running trial to running once again, it seems like `datetime_start` will be updated. I think it's inconsistent with the other storages. How about only updating the timestamp here if the state actually changes? I'm sorry for the lack of missing tests here.

@author:
Agreed. Will add that in next commit.

diff_hunk: @@ -1010,3 +1010,71 @@ def test_tell_pruned_values() -> None:
 
     study.tell(trial, state=TrialState.PRUNED)
     assert study.trials[-1].value is None
+
+
+@pytest.mark.parametrize("storage_mode", STORAGE_MODES)
+def test_trial_duration_calculation(storage_mode: str) -> None:
+
+    with StorageSupplier(storage_mode) as storage:
+        study = create_study(storage=storage)
+
+        def objective(trial: Trial) -> float:
+            time.sleep(1)
+            x = trial.suggest_int("x", -10, 10)
+            return x
+
+        study.enqueue_trial(params={"x": 1})
+        # Make sure an enqueued trial is created with null datetime_start
+        t_tmp = study.trials[0]
+        assert t_tmp.datetime_start is None
+
+        # Delayed evaluation for enqueued trial
+        time.sleep(2)
+
+        study.optimize(objective, n_trials=2)
+
+        trial = study.ask()
+        values = objective(trial)
+        study.tell(trial, values=values)
+
+        t0 = study.trials[0]
+        assert t0.datetime_start is not None
+        assert t0.datetime_complete is not None
+        duration_error0 = abs((t0.datetime_complete - t0.datetime_start).total_seconds() - 1)
+        assert duration_error0 < 0.1
+
+        t1 = study.trials[1]
+        assert t1.datetime_start is not None
+        assert t1.datetime_complete is not None
+        duration_error1 = abs((t1.datetime_complete - t1.datetime_start).total_seconds() - 1)
+        assert duration_error1 < 0.1
+
+        t2 = study.trials[2]
+        assert t2.datetime_start is not None
+        assert t2.datetime_complete is not None
+        duration_error2 = abs((t2.datetime_complete - t2.datetime_start).total_seconds() - 1)
+        assert duration_error2 < 0.1
+
+
+@pytest.mark.parametrize("storage_mode", STORAGE_MODES)
+def test_studysummary_datetime_start_calculation(storage_mode: str) -> None:
path: tests/study_tests/test_study.py
text: @user1:
A nit.
```suggestion
def test_study_summary_datetime_start_calculation(storage_mode: str) -> None:
```

diff_hunk: @@ -457,6 +457,8 @@ def ask(
         trial_id = self._pop_waiting_trial_id()
         if trial_id is None:
             trial_id = self._storage.create_new_trial(self._study_id)
+        else:
+            self._storage.set_trial_state(trial_id, TrialState.RUNNING)
path: optuna/study.py
text: @user1:
I think this state update is already performed in `_pop_waiting_trial_id` and isn't needed therefore.

@author:
You're right. Sorry forgot that