Prevent Lock Blocking by Adding Timeout to `JournalStorage` by sawa3030 · Pull Request #5971 · optuna/optuna

sawa3030 · 2025-02-13T01:11:51Z

Motivation

Currently, if a process is terminated without releasing the lock, the next process fails to resume. This change introduces a mechanism to release the existing lock if acquiring it takes too long.
ref: JournalStorage with JournalFileSymlinkLock may fail to resume #5921

Description of the changes

Introduced a grace period for acquiring locks in JournalFileSymlinkLock and JournalFileOpenLock.
If the lock cannot be acquired within the grace period, it is considered stale and released to prevent blocking new processes.

y0z · 2025-02-13T02:23:25Z

@not522 Could you review this PR?

not522

Thank you for your PR! Could you check the following points?

How about using time.monotonic()? This differs from datetime.now() in that it is not affected by system clock updates.
How about checking the last modified time of the lock? As the number of processes increases, it may continue to fail to acquire a lock.

sawa3030 · 2025-02-13T08:08:30Z

@not522 Thank you for your suggestions. There are some changes I made.

I updated the logic to check the last modified time. The previous approach had issues when the grace period was too short, but with your suggested logic, it is now more robust regardless of the grace period length.
I have confirmed that this PR successfully resolves the issue: JournalStorage with JournalFileSymlinkLock may fail to resume #5921. After an unexpected process termination, the optimization process can now successfully resume even if the lock file still exists. It successfully resumes the optimization process whether a new process starts before or after the grace period has elapsed.
I added tests to ensure that a customized grace period functions correctly without issues.

And here are some concerns

As far as I know, time.monotonic() cannot be used for checking the modified time of a file. Do you think it would be better to keep the previous logic, as shown in the code below? Or would that make the implementation unnecessarily complex?

if min(datetime.datetime.now() - mtime, time.monotonic() - start_time) > datetime.timedelta(seconds=self.grace_period):
    self.release()

The documentation for st_mtime states that its resolution depends on the file system, and some file systems have a low resolution (e.g., 2-seconds). If the grace period is set too short, this could lead to unexpected behavior. I’ve added a warning if the grace period is set to less than 3 seconds, but I’m unsure whether this warning is necessary or if it just adds unnecessary complexity.

not522 · 2025-02-13T08:27:03Z

Ah, sorry, my previous comment is misleading. I suggest using both checks, the last modified time of the lock and the waiting time (time.monotonic()).

codecov · 2025-02-13T09:08:14Z

Codecov Report

Attention: Patch coverage is 63.26531% with 18 lines in your changes missing coverage. Please review.

Project coverage is 88.46%. Comparing base (0a649e3) to head (3ba42a7).
Report is 88 commits behind head on master.

Files with missing lines	Patch %	Lines
optuna/storages/journal/_file.py	63.26%	18 Missing ⚠️

Additional details and impacted files

@@           Coverage Diff           @@
##           master    #5971   +/-   ##
=======================================
  Coverage   88.46%   88.46%           
=======================================
  Files         205      206    +1     
  Lines       13768    13857   +89     
=======================================
+ Hits        12180    12259   +79     
- Misses       1588     1598   +10

☔ View full report in Codecov by Sentry.
📢 Have feedback on the report? Share it here.

c-bata · 2025-02-18T08:10:36Z

@y0z Could you review this PR?

not522 · 2025-02-18T10:01:48Z

In my understanding, comparing st_mtime and the local time of the machine is unreliable (for example, NFS records the time of the server, not the machine where the process is running). But, we can trust whether it has been modified or not. So, how about the following logic?

start_time = time.monotonic()
mtime = datetime.datetime.fromtimestamp(os.stat(self._lock_file).st_mtime)
while True:
    ...
    current_mtime = datetime.datetime.fromtimestamp(os.stat(self._lock_file).st_mtime)
    if current_mtime != mtime:
        start_time = time.monotonic()
        mtime = current_mtime
        continue
    if time.monotonic() - start_time > self.grace_period:
        self.release()

sawa3030 · 2025-02-19T02:17:28Z

Thank you for your suggestion! I've updated the logic accordingly.

sawa3030 · 2025-02-19T02:48:48Z

By running the following code, I have confirmed that the logic successfully resolves the issue: JournalStorage with JournalFileSymlinkLock may fail to resume #5921.

import optuna

def objective(trial): 
    x = trial.suggest_uniform('x', -10, 10)
    return (x - 2) ** 2

storage = optuna.storages.JournalStorage(
    optuna.storages.journal.JournalFileBackend("./optuna_journal_storage.log")
)

study = optuna.create_study(study_name = "example",storage=storage, load_if_exists=True)
study.optimize(objective)

Before (master):
If the process is unexpectedly terminated with SIGKILL and the lock file is not removed, it blocks subsequent processes, preventing the optimization from resuming indefinitely.

After (PR):
Even if the lock file remains, the next process will remove it, allowing the optimization to resume after the grace period.

sawa3030 · 2025-02-20T05:07:52Z

@not522 @y0z I’ve made some updates. Could you review the PR when you have time? Thank you!

not522

Thank you for your update! Could you check my suggestions?

optuna/storages/journal/_file.py

tests/storages_tests/journal_tests/test_journal.py

sawa3030 · 2025-02-20T10:24:59Z

@not522 Thank you for your advice! I've made some updates based on your feedback.

y0z · 2025-02-27T07:57:59Z

optuna/storages/journal/_file.py

+                    try:
+                        current_mtime = os.stat(self._lock_file).st_mtime
+                    except OSError:
+                        continue
+                    if current_mtime != mtime:
+                        mtime = current_mtime
+                        last_update_time = time.monotonic()


I am confused about why we need the three variables: last_update_time, mtime, and current_mtime. At first glance, it seems that last_update_time equals to current_mtime since current_mtime != mtime means the lock file has been modified. Could you please provide additional explanation as to the difference between their roles?

last_update_time is based on monotonic clock time, whereas current_mtime and m_time are Epoch timestamps. I chose not to compare mtime directly with grace_period to avoid inconsistencies.

I feel like the name last_update_time is a little confusing, but I couldn't come up with a better variable name.

I change the variable name from last_update_time to last_update_monotonic_time!

y0z · 2025-02-27T08:34:49Z

optuna/storages/journal/_file.py

+                    try:
+                        current_mtime = os.stat(self._lock_file).st_mtime
+                    except OSError:
+                        continue
+                    if current_mtime != mtime:
+                        mtime = current_mtime
+                        last_update_time = time.monotonic()


Ditto: https://github.com/optuna/optuna/pull/5971/files#r1973051800

y0z · 2025-02-27T08:38:22Z

optuna/storages/journal/_file.py

    """

-    def __init__(self, filepath: str) -> None:
+    def __init__(self, filepath: str, grace_period: int = 30) -> None:


What about allowing grace_period = None (i.e., unlimited)? Forcing the release of long-held locks seems to work in many cases, but I'm not sure it's always OK.

Suggested change: grace_period: int | None = 30

y0z · 2025-02-27T08:49:33Z

optuna/storages/journal/_file.py

+                            "for an extended period. Forcibly releasing the lock file."
+                        )
+                        try:
+                            self.release()


Would it be a good idea to reset sleep_secs to 0.001 after calling release()? Another thread may acquire the lock between your release() and os.symlink().

y0z · 2025-02-27T08:51:16Z

optuna/storages/journal/_file.py

    """

-    def __init__(self, filepath: str) -> None:
+    def __init__(self, filepath: str, grace_period: int = 30) -> None:


Ditto: https://github.com/optuna/optuna/pull/5971/files#r1973119843

sawa3030 · 2025-02-28T02:48:41Z

@y0z I made the update. Thank you for your feedback!

sawa3030 · 2025-03-05T03:24:55Z

@y0z @not522 I think all updates have been applied. Thank you for your suggestions! Please let me know if there's anything else that needs to be addressed.

not522

Thank you. It's almost LGTM. Could you checking the following points?

The error type
Adding test for the invalid argument (i.e., zero and negative integer)

I think the warning message can be improved, but I think we can address in a separate PR.

not522 · 2025-03-05T04:40:47Z

optuna/storages/journal/_file.py

+                            try:
+                                self.release()
+                                sleep_secs = 0.001
+                            except OSError:


Maybe it should be RuntimeError.

Suggested change

except OSError:

except RuntimeError:

y0z

LGTM

tests/storages_tests/journal_tests/test_journal.py

Co-authored-by: Naoto Mizuno <naotomizuno@preferred.jp>

sawa3030 · 2025-03-07T02:19:56Z

@not522 Thank you for letting me know that. I updated the code as you suggested.

not522

LGTM!

add grace_period to journal storage

635913a

y0z assigned not522 Feb 13, 2025

not522 reviewed Feb 13, 2025

View reviewed changes

sawa3030 added 3 commits February 13, 2025 15:18

make the grace-period is compared with mtime

6698454

add warning

a5546ea

refactor the code

0cdcd07

y0z added the bug Issue/PR about behavior that is broken. Not for typos/examples/CI/test but for Optuna itself. label Feb 13, 2025

update the logic of grace_period

6b3cae4

c-bata assigned y0z Feb 18, 2025

change the grace period logic

97203eb

sawa3030 force-pushed the fix/add-grace-period branch from d57bd65 to 97203eb Compare February 19, 2025 02:13

not522 reviewed Feb 20, 2025

View reviewed changes

optuna/storages/journal/_file.py Outdated Show resolved Hide resolved

optuna/storages/journal/_file.py Outdated Show resolved Hide resolved

optuna/storages/journal/_file.py Outdated Show resolved Hide resolved

tests/storages_tests/journal_tests/test_journal.py Outdated Show resolved Hide resolved

minor change

ae4fe93

sawa3030 force-pushed the fix/add-grace-period branch from bcfa1c4 to ae4fe93 Compare February 20, 2025 10:24

not522 changed the title ~~Prevent Lock Blocking by Adding Timeout to JournalStorage~~ Prevent Lock Blocking by Adding Timeout to JournalStorage Feb 21, 2025

add error type

54adf52

not522 linked an issue Feb 25, 2025 that may be closed by this pull request

JournalStorage with JournalFileSymlinkLock may fail to resume #5921

Closed

refactor the code

1e5d1dc

y0z reviewed Feb 27, 2025

View reviewed changes

add the type None to the grace period of JournalStorage

3ba42a7

minor change

6c3ed5f

not522 reviewed Mar 5, 2025

View reviewed changes

y0z approved these changes Mar 5, 2025

View reviewed changes

y0z removed their assignment Mar 5, 2025

add test_invalid_grace_period

f74ebed

not522 reviewed Mar 7, 2025

View reviewed changes

tests/storages_tests/journal_tests/test_journal.py Outdated Show resolved Hide resolved

tests/storages_tests/journal_tests/test_journal.py Outdated Show resolved Hide resolved

sawa3030 and others added 2 commits March 7, 2025 10:31

Update tests/storages_tests/journal_tests/test_journal.py

9c8a4cb

Co-authored-by: Naoto Mizuno <naotomizuno@preferred.jp>

Update tests/storages_tests/journal_tests/test_journal.py

9844c26

Co-authored-by: Naoto Mizuno <naotomizuno@preferred.jp>

not522 approved these changes Mar 7, 2025

View reviewed changes

not522 added this to the v4.3.0 milestone Mar 7, 2025

not522 merged commit eb2367b into optuna:master Mar 7, 2025
14 checks passed

sawa3030 deleted the fix/add-grace-period branch November 14, 2025 07:47

sawa3030 mentioned this pull request Nov 28, 2025

Add warnings when JournalStorage lock acquisition is delayed #6361

Merged

Uh oh!

Conversation

sawa3030 commented Feb 13, 2025

Motivation

Description of the changes

Uh oh!

y0z commented Feb 13, 2025

Uh oh!

not522 left a comment

Choose a reason for hiding this comment

Uh oh!

sawa3030 commented Feb 13, 2025

Uh oh!

not522 commented Feb 13, 2025

Uh oh!

codecov bot commented Feb 13, 2025 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Codecov Report

Uh oh!

c-bata commented Feb 18, 2025

Uh oh!

not522 commented Feb 18, 2025

Uh oh!

sawa3030 commented Feb 19, 2025

Uh oh!

sawa3030 commented Feb 19, 2025 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

sawa3030 commented Feb 20, 2025

Uh oh!

not522 left a comment

Choose a reason for hiding this comment

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

sawa3030 commented Feb 20, 2025

Uh oh!

y0z Feb 27, 2025 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Choose a reason for hiding this comment

Uh oh!

sawa3030 Feb 28, 2025

Choose a reason for hiding this comment

Uh oh!

sawa3030 Feb 28, 2025

Choose a reason for hiding this comment

Uh oh!

sawa3030 Feb 28, 2025

Choose a reason for hiding this comment

Uh oh!

y0z Feb 27, 2025

Choose a reason for hiding this comment

Uh oh!

y0z Feb 27, 2025 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Choose a reason for hiding this comment

Uh oh!

y0z Feb 27, 2025

Choose a reason for hiding this comment

Uh oh!

y0z Feb 27, 2025

Choose a reason for hiding this comment

Uh oh!

sawa3030 commented Feb 28, 2025

Uh oh!

sawa3030 commented Mar 5, 2025

Uh oh!

not522 left a comment

Choose a reason for hiding this comment

Uh oh!

not522 Mar 5, 2025

Choose a reason for hiding this comment

Uh oh!

y0z left a comment

Choose a reason for hiding this comment

Uh oh!

Uh oh!

Uh oh!

codecov bot commented Feb 13, 2025 •

edited

Loading

sawa3030 commented Feb 19, 2025 •

edited

Loading

y0z Feb 27, 2025 •

edited

Loading

y0z Feb 27, 2025 •

edited

Loading