Closed Bug 1668382 Opened 4 years ago Closed 4 years ago

`moz-phab submit` has become slower, spends a lot of time at the "Creating local diff" step

Categories

(Conduit :: moz-phab, defect)

defect

Tracking

(Not tracked)

RESOLVED DUPLICATE of bug 1649086

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.

Summary: moz-phab has become slower, spends a lot of time at the "Creating local diff" step → `moz-phab submit` has become slower, spends a lot of time at the "Creating local diff" step

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.

Flags: needinfo?(botond)
Attached file moz-phab.log

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)

Attachment #9179645 - Attachment mime type: text/x-log → text/plain
Attached file sylvestre log analysis

Breakdown of Sylvestre's log. This doesn't show any abnormally slow operations.

(In reply to :glob 🎈 from comment #1)

If you pass --debug to moz-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.

Flags: needinfo?(botond)

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).

Status: NEW → RESOLVED
Closed: 4 years ago
Resolution: --- → WORKSFORME

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.

Reopening in light of comment 6. Relevant info:

  • Ubuntu 20.04.1 LTS, up to date
  • Mercurial 5.5
  • moz-phab up to date
Status: RESOLVED → REOPENED
Resolution: WORKSFORME → ---
Attachment #9179893 - Attachment mime type: text/x-log → text/plain

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.

Status: REOPENED → RESOLVED
Closed: 4 years ago4 years ago
Resolution: --- → WORKSFORME

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.

Resolution: WORKSFORME → DUPLICATE
Attached file moz-phab.log.tar.gz

Took 5 minutes to upload https://phabricator.services.mozilla.com/D90795?id=352232
touching 90 files
Logs attached!

Updating took 7 minutes

Update in debug mode

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.

Attached file moz-phab-log.tar.gz

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

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.

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.

You need to log in before you can comment on or make changes to this bug.

Attachment

General

Created:
Updated:
Size: