`moz-phab submit` has become slower, spends a lot of time at the "Creating local diff" step
Categories
(Conduit :: moz-phab, defect)
Tracking
(Not tracked)
People
(Reporter: botond, Unassigned)
Details
Attachments
(6 files)
In recent weeks, moz-phab submit
seems to have become slower for me. It often spends 30-60 seconds per patch at the "Creating local diff" step. This definitely feels like a regression, though it's unclear if it's related to moz-phab itself, or mercurial, or something else.
Suggestions for how to profile / diagnose the issue further are welcome.
Reporter | ||
Updated•4 years ago
|
The current version of moz-phab was released on Jul 27, 2020, so you aren't seeing a result of recent changes to moz-phab itself.
"Creating local diff" is all querying hg to generate a diff, so if just that phase is slow it's likely to be a hg regression/issue.
If you pass --debug
to moz-phab
you'll get a lot of output which will show where the time is spent.
Comment 2•4 years ago
|
||
Here is the log with hg 5.5.2 and MozPahb 0.1.90
I pushed:
https://phabricator.services.mozilla.com/D92459
https://phabricator.services.mozilla.com/D92460
Stack of 2, the first one touched a bunch of files.
Started at 18:38:42
Ended at 18:40:21
So, still slow (I agree that it should be counted in second, not minute) but not a significant regression compared to what I used to have.
Some operations like:
DEBUG 2020-10-05 18:39:58,154 $ hg --config extensions.rebase= --pager never --config rebase.experimental.inmemory=true --config experimental.evolution.createmarkers=true --config extensions.strip= update --quiet 1bf38454797dc344e91852f54a8e1dd33fe9d794
DEBUG 2020-10-05 18:40:04,514 --- arc message
took 6 seconds
In term of hg commands executed:
% grep "hg \-\-config " moz-phab.log|awk '{print $16}'| sort|uniq -c|sort -n -r
62 files
58 cat
29 log
29 diff
6 update
4 bookmark
3 status
3 rebase
3 commit
1 strip
1 qapplied
1 id
the first patch touched 26 files, the second 3 (which matches the number of "hg diff" calls)
Breakdown of Sylvestre's log. This doesn't show any abnormally slow operations.
Reporter | ||
Comment 4•4 years ago
|
||
(In reply to :glob 🎈 from comment #1)
If you pass
--debug
tomoz-phab
you'll get a lot of output which will show where the time is spent.
I can't seem to repro the slowness at the moment. I just submitted a series of 6 patches and it completed in under 2 minutes, which I think is fine.
Maybe it was just a particular patch that was amended many times or touched a lot of files that caused the slowness.
I will keep --debug
in mind and upload a log if I see slowness again.
Thanks, closing bug.
If it happens again moz-phab keeps a debug log in ~/.mozbuild/moz-phab/moz-phab.log
; as it's a log of all requests it's important to edit it prior to submission so it only includes the relevant part (this can be tricky, which is why --debug
is preferred).
Comment 6•4 years ago
|
||
Here is another log. The initial moz-phab submit
for the three patches of bug 1669450. This took 1:10. Subsequent update of the same three patches took only 0:50, but the stddev is high (simply repeating the same command, I've seen 0:58, for example):
moz-phab 24.66user 13.32system 0:50.37 elapsed 75%CPU (0avgtext+0avgdata 410912maxresident),
I made a quick comparison with phabsend
from here, where I resubmitted the same three patches:
phabsend 1.15user 0.26system 0:18.49 elapsed 7%CPU (0avgtext+0avgdata 470480maxresident)
This is on a ridiculously fast machine that builds firefox debug in 8min.
Comment 7•4 years ago
|
||
Reopening in light of comment 6. Relevant info:
- Ubuntu 20.04.1 LTS, up to date
- Mercurial 5.5
moz-phab
up to date
Thanks padenot.
There's a lot of scope for performance improvements in moz-phab; see bug 1649086.
As you can see from the logs moz-phab interacts with your repository a lot, in places this is inefficient (most of the blockers on that bug) and in others there's major architectural work required to avoid (eg. items from https://docs.google.com/document/d/14v33dMrAvs9KlhYVdbN7yYqJpubs8XFpnrDlsZTPBW0/).
For this bug I'm interested in submissions which are taking a abnormally long time to submit; I've heard 3rd hand reports of submissions taking 30 to 40 minutes, something I've been unable to reproduce.
moz-phab's performance is something that we want to fix, but it's already been tracked in other bugs.
Duplicating this bug against the meta I referenced in comment 8 to make that clearer.
Feel free to reopen if you capture a submission taking significantly longer than usual.
Comment 10•4 years ago
|
||
Took 5 minutes to upload https://phabricator.services.mozilla.com/D90795?id=352232
touching 90 files
Logs attached!
Comment 11•4 years ago
|
||
Updating took 7 minutes
Comment 12•4 years ago
|
||
Update in debug mode
Comment 13•4 years ago
|
||
For both of those the step where it uploads to phabricator (search for https://phabricator.services.mozilla.com/api/differential.creatediff) is taking the bulk of the time. Timings are significantly impacted by the number of files touched, and there's known ineffiencies in moz-phab's interaction with hg and git (eg. Bug 1649090, which will be part of the next moz-phab release).
For the 4 logs here's the breakdown (note the 3rd log has 28 submissions in it, I picked the most likely):
00:01:37 hg (202 calls, longest 7.2s)
00:00:08 Phabricator (7 calls, longest 2.1s)
00:01:48 Total (58 files, 1.3m)
00:01:02 hg (79 calls, longest 2.2s)
00:00:04 Phabricator (4 calls, longest 1.5s)
00:01:07 Total (20 files, 91.9k)
00:05:07 hg (886 calls, longest 4.2s)
00:07:03 Phabricator (3 calls, longest 6m59s)
00:14:09 Total (342 files, 13.3m)
00:02:04 hg (465 calls, longest 1.8s)
00:04:44 Phabricator (5 calls, longest 4m38s)
00:07:05 Total (178 files, 8.4m)
How Phabricator works is it expects a unified diff with context set large enough to capture the whole file. If you're touching a lot of files this can quickly add up.
moz-phab detects if an individual file is larger than 4mb and will automatically switch to submitting files with "just" 100 lines of context.
You can manually trigger this with the --less-context
switch to moz-phab submit
.
Sylvestre as an experiment can you pass --less-context
to moz-phab submit
next time you do your clang-format run?
I'm thinking it might be useful to automatically switch to less context if the total size of all files exceeds a threshold.
Comment 14•4 years ago
•
|
||
Here's some moz-phab logs that contain 2 distinct sessions:
- 2020-10-13: submitting an initial queue of 19 commits, that took more than 2 hours to complete
- 2020-10-14: updating the queue (+ adding 2 new commits), that took more than 1 hours to complete
Hope this will help, don't hesitate to ask me any question
Comment 15•4 years ago
|
||
Thanks Nicolas. Those are indeed painful numbers.
02:02:37 hg (3826 calls, longest 2m55s)
00:04:03 Phabricator (58 calls, longest 22s)
02:06:52 Total (1,327 files, 5.8m)
01:03:08 hg (3339 calls, longest 20s)
00:03:19 Phabricator (66 calls, longest 19s)
01:06:31 Total (1,347 files, 4.2m)
Both of these are the result of the large amount of files rather than a recent performance regression.
Many of the bugs hanging off Bug 1649086 should address inefficiencies there.
Comment 16•4 years ago
|
||
Great news, with mozphab 0.1.92 which contains Tarek's perf improvement: https://github.com/mozilla-conduit/review/commit/bc07a811ecbd3b645cbe994db32a4e1f2f6006e6
Pushing https://phabricator.services.mozilla.com/D95456 which contains 686 files using moz-phab took only 16 seconds (from beginning to end)
Wins might not be as big for large stack series but this is still a great improvement.
Description
•