clock skew in wsl2

[surfacepatterns]

Windows Version

Microsoft Windows [Version 10.0.22631.3737]

WSL Version

2.2.4.0

Are you using WSL 1 or WSL 2?

• WSL 2
• WSL 1

Kernel Version

5.15.153.1-2

Distro Version

CBL-Mariner 2.0.20240628

Other Software

No response

Repro Steps

1. Start the Linux instance.
2. Do various things in the wsl instance.
3. Observe that, occasionally, you get error messages regarding timestamps in the future, and detection of clock skew. Sometimes, depending on the task, clock skew occurs often enough that you can't complete the task (e.g. building RPMs wherein the tests rely on file modification times that end up appearing to be in the future).

Expected Behavior

I expect to observe clock skew quite rarely, and to have it impact my work on a much less frequent basis.

Actual Behavior

Here are a couple examples.

dmesg output

[danderson: /tmp/tmpawdfb76t]
> dmesg | tail -n 40
[404082.973889] systemd-journald[84]: Time jumped backwards, rotating.
[404111.348115] systemd-journald[84]: Time jumped backwards, rotating.
[404139.703269] systemd-journald[84]: Time jumped backwards, rotating.
[404168.096403] systemd-journald[84]: Time jumped backwards, rotating.
[404196.480773] systemd-journald[84]: Time jumped backwards, rotating.
[404224.872429] systemd-journald[84]: Time jumped backwards, rotating.
[404253.223833] systemd-journald[84]: Time jumped backwards, rotating.
[404281.594155] systemd-journald[84]: Time jumped backwards, rotating.
[404309.968480] systemd-journald[84]: Time jumped backwards, rotating.
[404338.363311] systemd-journald[84]: Time jumped backwards, rotating.
[404366.732147] systemd-journald[84]: Time jumped backwards, rotating.
[404395.108002] systemd-journald[84]: Time jumped backwards, rotating.
[404423.480880] systemd-journald[84]: Time jumped backwards, rotating.
[404451.831353] systemd-journald[84]: Time jumped backwards, rotating.
[404480.194392] systemd-journald[84]: Time jumped backwards, rotating.
[404508.549149] systemd-journald[84]: Time jumped backwards, rotating.
[404536.920285] systemd-journald[84]: Time jumped backwards, rotating.
[404565.283479] systemd-journald[84]: Time jumped backwards, rotating.
[404593.654135] systemd-journald[84]: Time jumped backwards, rotating.
[404622.024996] systemd-journald[84]: Time jumped backwards, rotating.
[404650.397592] systemd-journald[84]: Time jumped backwards, rotating.
[404678.775581] systemd-journald[84]: Time jumped backwards, rotating.
[404707.127293] systemd-journald[84]: Time jumped backwards, rotating.
[404735.490979] systemd-journald[84]: Time jumped backwards, rotating.
[404763.840208] systemd-journald[84]: Time jumped backwards, rotating.
[404792.189098] systemd-journald[84]: Time jumped backwards, rotating.
[404820.536595] systemd-journald[84]: Time jumped backwards, rotating.
[404848.904155] systemd-journald[84]: Time jumped backwards, rotating.
[404877.268762] systemd-journald[84]: Time jumped backwards, rotating.
[404905.630039] systemd-journald[84]: Time jumped backwards, rotating.
[404933.999577] systemd-journald[84]: Time jumped backwards, rotating.
[404962.374937] systemd-journald[84]: Time jumped backwards, rotating.
[404990.729142] systemd-journald[84]: Time jumped backwards, rotating.
[405019.091547] systemd-journald[84]: Time jumped backwards, rotating.
[405047.445148] systemd-journald[84]: Time jumped backwards, rotating.
[405075.793623] systemd-journald[84]: Time jumped backwards, rotating.
[405104.138690] systemd-journald[84]: Time jumped backwards, rotating.
[405132.488783] systemd-journald[84]: Time jumped backwards, rotating.
[405160.846706] systemd-journald[84]: Time jumped backwards, rotating.
[405189.185044] systemd-journald[84]: Time jumped backwards, rotating.

Partial (relevant) output when meson tests fail, which are run as part of building binary RPMs:

Traceback (most recent call last):
  File "/builddir/build/BUILD/meson-1.3.1/meson.py", line 40, in <module>
    sys.exit(mesonmain.main())
  File "/builddir/build/BUILD/meson-1.3.1/mesonbuild/mesonmain.py", line 294, in main
    return run(sys.argv[1:], launcher)
  File "/builddir/build/BUILD/meson-1.3.1/mesonbuild/mesonmain.py", line 280, in run
    return errorhandler(e, 'setup')
  File "/builddir/build/BUILD/meson-1.3.1/mesonbuild/mesonmain.py", line 40, in errorhandler
    raise e
  File "/builddir/build/BUILD/meson-1.3.1/mesonbuild/mesonmain.py", line 278, in run
    return msetup.run(['--reconfigure'] + args[2:])
  File "/builddir/build/BUILD/meson-1.3.1/mesonbuild/msetup.py", line 358, in run
    app.generate()
  File "/builddir/build/BUILD/meson-1.3.1/mesonbuild/msetup.py", line 181, in generate
    return self._generate(env, capture, vslite_ctx)
  File "/builddir/build/BUILD/meson-1.3.1/mesonbuild/msetup.py", line 251, in _generate
    captured_compile_args = intr.backend.generate(capture, vslite_ctx)
  File "/builddir/build/BUILD/meson-1.3.1/mesonbuild/backend/ninjabackend.py", line 657, in generate
    self.generate_ending()
  File "/builddir/build/BUILD/meson-1.3.1/mesonbuild/backend/ninjabackend.py", line 3679, in generate_ending
    deps = self.get_regen_filelist()
  File "/builddir/build/BUILD/meson-1.3.1/mesonbuild/backend/backends.py", line 1353, in get_regen_filelist
    self.check_clock_skew(deps)
  File "/builddir/build/BUILD/meson-1.3.1/mesonbuild/backend/backends.py", line 1380, in check_clock_skew
    raise MesonException(f'Clock skew detected. File {absf} has a time stamp {delta:.4f}s in the future.')
mesonbuild.utils.core.MesonException: Clock skew detected. File /builddir/build/BUILD/meson-1.3.1/b 41766a13e6/../test cases/common/22 object extraction/meson.build has a time stamp 0.2633s in the future.
ninja: error: rebuilding 'build.ninja': subcommand failed

(In the build log this excerpt is from, there were 32 such clock skew failures. I've tried building this package five times today, and each instance results in a similar amount of failures.)

Note that I've seen the issues about clock skew after sleeping. A few things make me think this is different:

1. I'm running a version of WSL that should have the fix for that issue.
2. I observe these issues right after restarting my computer, prior to the computer sleeping.
3. Running sudo hwclock -s doesn't seem to change anything.

Diagnostic Logs

No response

[github-actions]

Logs are required for review from WSL team

If this a feature request, please reply with '/feature'. If this is a question, reply with '/question'.
Otherwise please attach logs by following the instructions below, your issue will not be reviewed unless they are added. These logs will help us understand what is going on in your machine.

How to collect WSL logs

Download and execute collect-wsl-logs.ps1 in an administrative powershell prompt:

Invoke-WebRequest -UseBasicParsing "https://raw.githubusercontent.com/microsoft/WSL/master/diagnostics/collect-wsl-logs.ps1" -OutFile collect-wsl-logs.ps1
Set-ExecutionPolicy Bypass -Scope Process -Force
.\collect-wsl-logs.ps1

The scipt will output the path of the log file once done.

Once completed please upload the output files to this Github issue.

Click here for more info on logging
If you choose to email these logs instead of attaching to the bug, please send them to [email protected] with the number of the github issue in the subject, and in the message a link to your comment in the github issue and reply with '/emailed-logs'.

View similar issues

Please view the issues below to see if they solve your problem, and if the issue describes your problem please consider closing this one and thumbs upping the other issue to help us prioritize it!

Closed similar issues:

• WSL Clock still not updating correctly - frequently out of sync (#9183), similarity score: 0.80
• Clock skew detected during build (#8318), similarity score: 0.79
• WSL2 - clock problems during build (#4975), similarity score: 0.79
• system date is not same with windows (WSL 2) (#6974), similarity score: 0.79
• WSL2 clock becomes unsynced on Desktop system (#7255), similarity score: 0.78

Note: You can give me feedback by thumbs upping or thumbs downing this comment.

[surfacepatterns]

WslLogs-2024-07-17_16-35-07.zip

[github-actions]

Diagnostic information

Detected appx version: 2.2.4.0

[surfacepatterns]

So, it seems like wsl, or something wsl is dependent upon, get's in a bad state sometimes. Right now, after waking up from sleep, the issue isn't happening:

[danderson: /tmp/tmpawdfb76t]
> dmesg | tail -n 5
[456589.205091] hv_utils: TimeSync IC version 4.0
[456665.948959] mini_init (176): drop_caches: 1
[459550.465849] mini_init (176): drop_caches: 1
[459640.326553] mini_init (176): drop_caches: 1
[459910.870860] mini_init (176): drop_caches: 1

I'm going to continue monitoring the system, and try to identify what happens around the time that the issue starts.

[barries]

+1: We have this too on current WSL2 and in Docker containers. This is not the hibernate/sleep/wake defect of yore, that seems to have been fixed and I no longer need to use the hwclock -s hack.

On my 20 core machine, running buildroot with 10 jobs in parallel is almost guaranteed to incur a clock skew detected warning (from make) or error from autotools, etc. Running with 5 jobs in parallel almost always works. I'm still playing with different configurations to see if I can flush any discernible clues out of the undergrowth.

Could this have to do with swap thrash causing WSL2 or Hypervisor to miss a beat with its virtualized clock(s)?

WSL version: 2.4.11.0
Kernel version: 5.15.167.4-1
WSLg version: 1.0.65
MSRDC version: 1.2.5716
Direct3D version: 1.611.1-81528511
DXCore version: 10.0.26100.1-240331-1435.ge-release
Windows version: 10.0.22621.3880

Linux wiglaf-12 5.15.167.4-microsoft-standard-WSL2 #1 SMP Tue Nov 5 00:21:55 UTC 2024 x86_64 x86_64 x86_64 GNU/Linux

No LSB modules are available.
Distributor ID: Ubuntu
Description:    Ubuntu 22.04.5 LTS
Release:        22.04
Codename:       jammy

[barries]

@surfacepatterns, does this happen more with higher parallelism for you, too?