Page MenuHomePhabricator

Quibble should emit a report of each time it took to run the steps/stages
Closed, ResolvedPublic

Description

Quibble wraps commands with a chronometer which outputs the time it took for the command upon completion:

INFO:quibble.commands:>>> Start: npm install in /workspace/src
<<< Finish: npm install in /workspace/src, in 20.659 s

Those sections are parsed by the Jenkins collapsible section to show a sidebar:

quibble-jenkins-sections.png (189×281 px, 17 KB)

It would be nice to have all those durations collected and reported at the end of the execution.

I have built a proof of concept emitting:

                       [ REPORT FOR COMMAND DURATIONS ]

╒══════════╤═════════════════════════════════════════════════════════════════╕
│   0.000s │ Save success cache                                              │
│   0.573s │ Versions                                                        │
│   0.001s │ Run phpbench                                                    │
│  32.388s │ Zuul clone {"branch": "master", "cache_dir": "/srv/git",        │
│          │ "projects": ["mediawiki/core", "mediawiki/skins/Vector",        │
│          │ "mediawiki/vendor"], "workers": 4, "workspace":                 │
│          │ "/workspace/src", "zuul_branch": "master", "zuul_project":      │
│          │ "mediawiki/core", "zuul_ref":                                   │
│          │ "refs/zuul/master/Z9ddd61a6894b451ea4e6058c9fdda679",           │
│          │ "zuul_url": "git://contint1002.wikimedia.org"}                  │
│   0.086s │ Check success cache                                             │
│  10.412s │ Install composer dev-requires for vendor.git                    │
│   2.166s │ Start backends: <MySQL (no socket)>                             │
│  16.243s │ Run Post-dependency install, pre-database dependent steps in    │
│          │ parallel (concurrency=2): * Install MediaWiki, db=<MySQL        │
│          │ /workspace/db/quibble-mysql-ifwx2ix0/socket> * npm install in   │
│          │ /workspace/src                                                  │
│  15.171s │ PHPUnit unit tests                                              │
│  68.271s │ PHPUnit default suite (without database or standalone)          │
│  98.161s │ Run 'composer test' and 'npm test' in parallel (concurrency=2): │
│          │ * composer test for mediawiki/core * npm test in /workspace/src │
│   0.010s │ Start backends: <ExternalWebserver http://127.0.0.1:9413        │
│          │ /workspace/src> <Xvfb :94> <ChromeWebDriver :94>                │
│  14.920s │ Run QUnit tests                                                 │
│ 157.602s │ Browser tests: mediawiki/core, mediawiki/skins/Vector,          │
│          │ mediawiki/vendor                                                │
│  29.741s │ Run API-Testing                                                 │
│ 408.583s │ PHPUnit default suite (with database)                           │
╘══════════╧═════════════════════════════════════════════════════════════════╛

Thoughts?

Event Timeline

Change #1235315 had a related patch set uploaded (by Hashar; author: Hashar):

[integration/quibble@master] Keep track of Chronometer measurements

https://gerrit.wikimedia.org/r/1235315

Change #1235326 had a related patch set uploaded (by Hashar; author: Hashar):

[integration/quibble@master] Report Chronometer durations at end of plan

https://gerrit.wikimedia.org/r/1235326

This looks very neat, and not too hard to parse, but for the data-junkies among us it would be really exciting to have this in a relatively stable format for machine-processing. Can there be a start and end marker? And would it be okay to build tools / reports on the basis of processing this output?

👋 I hadn't thought about making it easy to parse!

And would it be okay to build tools / reports on the basis of processing this output?

Definitely, though we already have the tooling/report for that! We could push those data to Prometheus and then get them in Grafana to build dashboard.

There is also an Open Telemetry system which is used to collect traces, though that is for internal uses ( https://wikitech.wikimedia.org/wiki/Distributed_tracing ). I mention it cause it has a trace view that is quite fancy:

jaeger-trace-view.png (636×1 px, 38 KB)


The timings and command descriptions are accumulated in a global quibble.DURATIONS as tuples of (duration, name) https://gerrit.wikimedia.org/r/c/integration/quibble/+/1235315/4/quibble/__init__.py .

There is then a context manager which iterates it, craft a table and print it https://gerrit.wikimedia.org/r/c/integration/quibble/+/1235326/10/quibble/commands.py . I imagine that class can be taught to write down a json file under the log directory which will end up attached to the build in Jenkins? I guess it is all about something such as:

json.dump(quibble.durations, open('log/quibble-durations.json', 'w))

Which would result in:

log/quibble-durations.json
[
 [
  3.4332275390625e-05,
  "Report durations"
 ],
 [
  0.617889404296875,
  "Versions"
 ],
 [
  6.318092346191406e-05,
  "Ensure dir: '/home/hashar/projects/integration/quibble/log'"
 ],
 [
  2.002716064453125e-05,
  "Run Post-dependency install, pre-database dependent steps in parallel (concurrency=1):"
 ],
 [
  0.1059110164642334,
  "Start backends: <PhpWebserver http://127.0.0.1:9412 /home/hashar/projects/integration/quibble/src> <ChromeWebDriver :0>"
 ],
 [
  0.003979206085205078,
  "User commands: true"
 ]
]

Writing the data to a json file in the artefacts would be perfect, at least for the purposes I'm thinking of. I don't know about the tooling/report - are there already dashboards showing data about the breakdown of CI job runtimes?

Change #1243189 had a related patch set uploaded (by Hashar; author: Hashar):

[integration/quibble@master] Write durations report to the log_dir as json

https://gerrit.wikimedia.org/r/1243189

Aside: @ArthurTaylor unsure what you're aiming to do, but in case it's useful, I gather some of this data today (in a very reduced-cardinality format): https://releng-data.wmcloud.org/-/dashboards/jenkins/slow-quibble-steps?date_start=2026-02-17

@thcipriani neat! I had no idea we had such a dashboard. Or a jobs.db. Thanks for the tip!

Change #1248096 had a related patch set uploaded (by Hashar; author: Hashar):

[integration/quibble@master] Propagate SuccessCache.Hit() to the caller

https://gerrit.wikimedia.org/r/1248096

Change #1235315 merged by jenkins-bot:

[integration/quibble@master] Keep track of Chronometer measurements

https://gerrit.wikimedia.org/r/1235315

Change #1235326 merged by jenkins-bot:

[integration/quibble@master] Report Chronometer durations at end of plan

https://gerrit.wikimedia.org/r/1235326

Change #1248096 merged by jenkins-bot:

[integration/quibble@master] Propagate SuccessCache.Hit() to the caller

https://gerrit.wikimedia.org/r/1248096

Change #1243189 merged by jenkins-bot:

[integration/quibble@master] Write durations report to the log_dir as json

https://gerrit.wikimedia.org/r/1243189

The series of patches has been merged. That is now pending a new release of Quibble and a rebuild of the CI images.

Change #1248856 had a related patch set uploaded (by Hashar; author: Hashar):

[integration/quibble@master] release: Quibble 1.16.0

https://gerrit.wikimedia.org/r/1248856

Change #1248856 merged by jenkins-bot:

[integration/quibble@master] release: Quibble 1.16.0

https://gerrit.wikimedia.org/r/1248856

Change #1248880 had a related patch set uploaded (by Hashar; author: Hashar):

[integration/config@master] jjb: update jobs to Quibble 1.16.0

https://gerrit.wikimedia.org/r/1248880

Released with Quibble 1.16.0. I have updated the CI jobs, they now output the ASCII table and have quibble-durations.json attached to the Jenkins build report.

I think we will want to send those metrics to Prometheus so we can get them available in Grafana. That is similar to the task we have to send webdriver.io tests metrics to Prometheus: T392894. That is probably worth a new task, I guess we will file it when we come to it.

Change #1248880 merged by jenkins-bot:

[integration/config@master] jjb: update jobs to Quibble 1.16.0

https://gerrit.wikimedia.org/r/1248880