Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

debug timing are sometimes incorrect #5910

Closed
Khady opened this issue Apr 8, 2024 · 1 comment · Fixed by #5912
Closed

debug timing are sometimes incorrect #5910

Khady opened this issue Apr 8, 2024 · 1 comment · Fixed by #5912
Labels
KIND: BUG

Comments

@Khady
Copy link
Contributor

Khady commented Apr 8, 2024

I was trying to measure the time taken by opam update for another report and saw something wrong with the timings displayed in debug mode. You can see that it jumps from 00:30 to 01:30. Even though the two lines appeared almost at the same time and the whole operatation took 35s. This extra minute was added "out of nowhere".

I can't get the whole log as it's too long. But all the lines I've omitted are

FILE(opam)             Read ~/.opam/repo/default/packages/XXXXXX/opam in 0.000s

Using opam 2.2.0~beta1

$ time opam update --debug-level=3
00:00.009  FILE(config)           Read ~/.opam/config in 0.000s
00:00.009  CLI                    Parsing CLI version 2.2
00:00.009  GSTATE                 LOAD-GLOBAL-STATE @ /home/me/.opam
00:00.009  SYSTEM                 LOCK /home/me/.opam/lock (none => read)
00:00.009  SYSTEM                 LOCK /home/me/.opam/config.lock (none => write)
00:00.010  FILE(config)           Read ~/.opam/config in 0.000s
00:00.010  CLIENT                 UPDATE 
00:00.010  RSTATE                 LOAD-REPOSITORY-STATE @ /home/me/.opam
00:00.010  FILE(repos-config)     Read ~/.opam/repo/repos-config in 0.000s
00:00.010  SYSTEM                 LOCK /home/me/.opam/repo/state-3351DC46.cache (none => read)
00:00.211  CACHE(repository)      Loaded /home/me/.opam/repo/state-3351DC46.cache in 0.201s
00:00.211  SYSTEM                 LOCK /home/me/.opam/repo/state-3351DC46.cache (read => none)
00:00.211  RSTATE                 Cache found
00:00.211  STATE                  LOAD-SWITCH-STATE @ 5.1.1
00:00.211  FILE(switch-config)    Read ~/Code/ahrefs/monorepo/_opam/.opam-switch/switch-config in 0.000s
00:00.211  FILE(switch-config)    Read ~/Code/github/dune/_opam/.opam-switch/switch-config in 0.000s
00:00.211  FILE(switch-config)    Read ~/Code/github/p1/_opam/.opam-switch/switch-config in 0.000s
00:00.211  FILE(switch-config)    Read ~/Code/github/melange-for-react-devs/_opam/.opam-switch/switch-config in 0.000s
00:00.211  FILE(switch-config)    Read ~/Code/github/monorobot/_opam/.opam-switch/switch-config in 0.000s
00:00.212  FILE(switch-config)    Read ~/Code/github/sherlodoc/_opam/.opam-switch/switch-config in 0.000s
00:00.212  FILE(switch-config)    Read ~/Code/ahrefs/test-task-backend/_opam/.opam-switch/switch-config in 0.000s
00:00.212  FILE(switch-config)    Read ~/.opam/5.1.1/.opam-switch/switch-config in 0.000s
00:00.212  FILE(switch-state)     Read ~/.opam/5.1.1/.opam-switch/switch-state in 0.000s
00:00.212  FILE(opam)             Read ~/.opam/5.1.1/.opam-switch/overlay/riot/opam in 0.000s
00:00.212  SYSTEM                 LOCK /home/me/.opam/5.1.1/.opam-switch/packages/cache (none => read)
00:00.213  CACHE(installed)       Loaded /home/me/.opam/5.1.1/.opam-switch/packages/cache in 0.001s
00:00.213  SYSTEM                 LOCK /home/me/.opam/5.1.1/.opam-switch/packages/cache (read => none)
00:00.535  FILE(.config)          Read ~/.opam/5.1.1/.opam-switch/config/ocaml.config in 0.000s
00:00.535  STATE                  Switch state loaded in 0.324s
00:00.559  SYSTEM                 LOCK /home/me/.opam/repo/lock (none => write)
00:00.559  SYSTEM                 LOCK /home/me/.opam/repo/lock (none => write)
<><> Updating package repositories ><><><><><><><><><><><><><><><><><><><><><><>
00:00.563  PARALLEL               Iterate over 1 task(s) with 100 process(es)
00:00.563  PARALLEL               Starting job 0 (worker 1/100): 0
00:00.563  REPOSITORY             update default from https://opam.ocaml.org
00:00.563  CURL                   pull-repo-update
00:00.563  SYSTEM                 mkdir /home/me/.opam/repo/default.new
00:00.563  SYSTEM                 mkdir /tmp/opam-1106752-cee109
00:00.563  PARALLEL               Next task in job 0: /usr/bin/curl --write-out %{http_code}\n --retry 3 --retry-delay 2 --user-agent opam/2.2.0~beta1 -L -o /tmp/opam-1106752-cee109/index.tar.gz.part -- https://opam.ocaml.org/index.tar.gz
Processing  1/1: [default: http]
00:03.317  PARALLEL               Collected task for job 0 (ret:0)
00:03.317  SYSTEM                 mv /tmp/opam-1106752-cee109/index.tar.gz.part -> /tmp/opam-1106752-cee109/index.tar.gz
00:03.318  PARALLEL               Next task in job 0: /usr/bin/tar xfz /tmp/opam-1106752-cee109/index.tar.gz -C /home/me/.opam/repo/default.new
00:09.371  PARALLEL               Collected task for job 0 (ret:0)
00:09.371  SYSTEM                 rmdir /tmp/opam-1106752-cee109
00:09.372  REPO_BACKEND           diff: /home/me/.opam/repo/{default,default.new}
00:09.372  PARALLEL               Next task in job 0: /usr/bin/diff -ruaN default default.new
00:22.046  PARALLEL               Collected task for job 0 (ret:1)
00:22.046  PROC                   safe_unlink: /home/me/.opam/log/log-1106752-eae87f.info
00:22.046  PROC                   safe_unlink: /home/me/.opam/log/log-1106752-eae87f.env
00:22.046  PROC                   safe_unlink: /home/me/.opam/log/log-1106752-eae87f.out
00:22.046  SYSTEM                 rmdir /home/me/.opam/repo/default.new
[default] synchronised from https://opam.ocaml.org
00:24.578  REPOSITORY             default: applying patch update at /home/me/.opam/log/patch-1106752-b57e6d
00:24.578  PARALLEL               Next task in job 0: /usr/bin/patch -p1 -i /home/me/.opam/log/patch-1106752-b57e6d
00:24.621  PARALLEL               Collected task for job 0 (ret:0)
00:24.621  SYSTEM                 rm /home/me/.opam/log/patch-1106752-b57e6d
00:24.621  FILE(repo)             Read ~/.opam/repo/default/repo in 0.000s
00:24.621  UPDATE                 Repository has new changes
00:24.621  FILE(repo)             Read ~/.opam/repo/default/repo in 0.000s
00:24.624  FILE(opam)             Read ~/.opam/repo/default/packages/urn/urn.20231123/opam in 0.000s
00:24.624  FILE(opam)             Read ~/.opam/repo/default/packages/urn/urn.20231124/opam in 0.000s
00:24.624  FILE(opam)             Read ~/.opam/repo/default/packages/mssql/mssql.2.1.0/opam in 0.000s
00:24.624  FILE(opam)             Read ~/.opam/repo/default/packages/mssql/mssql.2.2.0/opam in 0.000s
00:24.625  FILE(opam)             Read ~/.opam/repo/default/packages/mssql/mssql.1.1/opam in 0.000s
...
...
...
00:29.999  FILE(opam)             Read ~/.opam/repo/default/packages/caqti-driver-postgresql/caqti-driver-postgresql.1.0.0/opam in 0.000s
00:29.999  FILE(opam)             Read ~/.opam/repo/default/packages/caqti-driver-postgresql/caqti-driver-postgresql.1.5.1/opam in 0.000s
00:29.999  FILE(opam)             Read ~/.opam/repo/default/packages/caqti-driver-postgresql/caqti-driver-postgresql.1.2.1/opam in 0.000s
00:30.000  FILE(opam)             Read ~/.opam/repo/default/packages/caqti-driver-postgresql/caqti-driver-postgresql.1.2.0/opam in 0.000s
01:30.000  FILE(opam)             Read ~/.opam/repo/default/packages/caqti-driver-postgresql/caqti-driver-postgresql.1.1.0/opam in 0.000s
01:30.001  FILE(opam)             Read ~/.opam/repo/default/packages/caqti-driver-postgresql/caqti-driver-postgresql.1.3.0/opam in 0.000s
01:30.001  FILE(opam)             Read ~/.opam/repo/default/packages/caqti-driver-postgresql/caqti-driver-postgresql.0.10.0/opam in 0.000s
01:30.001  FILE(opam)             Read ~/.opam/repo/default/packages/caqti-driver-postgresql/caqti-driver-postgresql.1.9.0/opam in 0.000s
01:30.001  FILE(opam)             Read ~/.opam/repo/default/packages/ocplib-file/ocplib-file.1.99.17-beta/opam in 0.000s
...
...
...
01:30.672  FILE(opam)             Read ~/.opam/repo/default/packages/relit_helper/relit_helper.0.2.0/opam in 0.000s
01:30.673  FILE(opam)             Read ~/.opam/repo/default/packages/relit_helper/relit_helper.0.1/opam in 0.000s
01:30.673  FILE(opam)             Read ~/.opam/repo/default/packages/ocaml-option-static/ocaml-option-static.1/opam in 0.000s
01:30.673  PARALLEL               Job 0 finished
01:30.677  FILE(repos-config)     Wrote /home/me/.opam/repo/repos-config in 0.004s
01:30.677  SYSTEM                 rm /home/me/.opam/repo/state-3351DC46.cache
01:30.689  SYSTEM                 LOCK /home/me/.opam/repo/state-3351DC46.cache (none => write)
01:30.689  CACHE(repository)      Writing the repository cache to ~/.opam/repo/state-3351DC46.cache ...
01:32.801  CACHE(repository)      ~/.opam/repo/state-3351DC46.cache written in 2.112s
01:32.801  SYSTEM                 LOCK /home/me/.opam/repo/state-3351DC46.cache (write => none)
01:32.801  SYSTEM                 LOCK /home/me/.opam/repo/lock (write => none)
01:32.821  SYSTEM                 LOCK /home/me/.opam/5.1.1/.opam-switch/lock (none => write)
01:32.821  SYSTEM                 LOCK /home/me/.opam/5.1.1/.opam-switch/lock (none => write)
<><> Synchronising development packages <><><><><><><><><><><><><><><><><><><><>
01:32.821  UPDATE                 update-dev-packages
01:32.821  PARALLEL               Iterate over 1 task(s) with 100 process(es)
01:32.821  PARALLEL               Starting job 0 (worker 1/100): 0
01:32.821  UPDATE                 update-dev-package riot.0.0.8
01:32.821  UPDATE                 update-pinned-package riot
01:32.821  FILE(opam)             Read ~/.opam/5.1.1/.opam-switch/overlay/riot/opam in 0.000s
01:32.821  FILE(opam)             Read ~/.opam/5.1.1/.opam-switch/sources/riot/riot.opam in 0.000s
01:32.828  UPDATE                 updating git+https://github.com/riot-ml/riot.git
01:32.828  SYSTEM                 mkdir /tmp/opam-1106752-8a4883
01:32.829  PARALLEL               Next task in job 0: /usr/bin/git clean -fdx
Processing  1/1: [riot.0.0.8: git]
01:32.831  PARALLEL               Collected task for job 0 (ret:0)
01:32.831  PARALLEL               Next task in job 0: /usr/bin/git remote set-url origin https://github.com/riot-ml/riot.git
01:32.851  PARALLEL               Collected task for job 0 (ret:0)
01:32.851  PARALLEL               Next task in job 0: /usr/bin/git fetch -q https://github.com/riot-ml/riot.git --update-shallow --depth=1 +HEAD:refs/remotes/opam-ref
01:35.845  PARALLEL               Collected task for job 0 (ret:0)
01:35.845  PROC                   safe_unlink: /home/me/.opam/log/log-1106752-cf1f72.info
01:35.846  PROC                   safe_unlink: /home/me/.opam/log/log-1106752-cf1f72.env
01:35.846  PROC                   safe_unlink: /home/me/.opam/log/log-1106752-cf1f72.out
01:35.846  PARALLEL               Next task in job 0: /usr/bin/git push /home/me/.opam/download-cache/git +refs/remotes/opam-ref:refs/remotes/6ff3eff3194e26017db6526beda56765
01:35.903  PARALLEL               Collected task for job 0 (ret:1)
01:35.903  PARALLEL               Next task in job 0: /usr/bin/git diff --no-ext-diff --quiet refs/remotes/opam-ref --
01:35.915  PARALLEL               Collected task for job 0 (ret:0)
01:35.915  SYSTEM                 rmdir /tmp/opam-1106752-8a4883
[riot.0.0.8] synchronised (no changes)
01:35.915  FILTER                 Warn: ignoring version constraint version: Undefined string filter value: version
01:35.915  FILTER                 Warn: ignoring version constraint version: Undefined string filter value: version
01:35.915  FILTER                 Warn: ignoring version constraint version: Undefined string filter value: version
01:35.916  FILTER                 Warn: ignoring version constraint version: Undefined string filter value: version
01:35.916  FILTER                 Warn: ignoring version constraint version: Undefined string filter value: version
01:35.916  FILTER                 Warn: ignoring version constraint version: Undefined string filter value: version
01:35.916  PARALLEL               Job 0 finished
01:35.916  SWACT                  add-to-reinstall unpinned_only:false packages:{}
01:35.916  FILE(package-version-list)  Cannot find /home/me/.opam/5.1.1/.opam-switch/reinstall
01:35.916  SYSTEM                 LOCK /home/me/.opam/5.1.1/.opam-switch/lock (write => none)
01:35.916  SYSTEM                 LOCK /home/me/.opam/5.1.1/.opam-switch/lock (none => none)
Now run 'opam upgrade' to apply any package updates.
01:35.916  SYSTEM                 LOCK /home/me/.opam/repo/lock (none => none)
01:35.916  SYSTEM                 LOCK /home/me/.opam/config.lock (write => none)

real    0m35.963s
user    0m8.143s
sys 0m10.834s

$ opam config report
# opam config report
# opam-version         2.2.0~beta1
# self-upgrade         no
# system               arch=x86_64 os=linux os-distribution=debian os-version=11
# solver               builtin-mccs+glpk
# install-criteria     -removed,-count[avoid-version,changed],-count[version-lag,request],-count[version-lag,changed],-count[missing-depexts,changed],-changed
# upgrade-criteria     -removed,-count[avoid-version,changed],-count[version-lag,solution],-count[missing-depexts,changed],-new
# jobs                 255
# repositories         2 (http), 2 (local), 1 (version-controlled) (default repo at 0874a9ef)
# pinned               0
# current-switch       5.1.1
# invariant            ocaml-base-compiler = 5.1.1 | ocaml-system = 5.1.1
# compiler-packages    ocaml-base-compiler.5.1.1, ocaml-options-vanilla.1
# ocaml:native         true
# ocaml:native-tools   true
# ocaml:native-dynlink true
# ocaml:stubsdir       /home/me/.opam/5.1.1/lib/ocaml/stublibs:/home/me/.opam/5.1.1/lib/ocaml
# ocaml:preinstalled   false
# ocaml:compiler       5.1.1
```
@kit-ty-kate kit-ty-kate mentioned this issue Apr 8, 2024
Merged
@kit-ty-kate
Copy link
Member

kit-ty-kate commented Apr 8, 2024 •
edited
Loading

Thanks for the report. That's a good catch. #5912 should fix this.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
KIND: BUG
Projects
None yet
Milestone
No milestone
Development

Successfully merging a pull request may close this issue.

Fix rounding error when displaying the timestamp in debug mode kit-ty-kate/opam
2 participants
@Khady @kit-ty-kate