1140191 - Investigate improving performance of IDL UUID bump hook

Status: RESOLVED FIXED

(Developer Services :: Mercurial: hg.mozilla.org, defect)

Description

[Gregory Szorc [:gps]]

It looks like the new IDL UUID bump hook can take a while to complete:

2015/03/05 15:42:42 [e-mail]> serve --stdio
2015/03/05 15:42:53 [e-mail]> pythonhook-pretxnchangegroup: mozhghooks.treeclosure.hook finished in 0.09 seconds
2015/03/05 15:42:53 [e-mail]> updated base branch cache in 0.0221 seconds
2015/03/05 15:42:53 [e-mail]> wrote base branch cache with 38 labels and 38 nodes
2015/03/05 15:42:53 [e-mail]> pythonhook-pretxnchangegroup: mozhghooks.single_head_per_branch.hook finished in 0.06 seconds
2015/03/05 15:42:53 [e-mail]> pythonhook-pretxnchangegroup: mozhghooks.commit-message.hook finished in 0.03 seconds
2015/03/05 15:42:53 [e-mail]> pythonhook-pretxnchangegroup: mozhghooks.prevent_webidl_changes.hook finished in 0.03 seconds
2015/03/05 15:43:42 [e-mail]> pythonhook-pretxnchangegroup: mozhghooks.prevent_idl_change_without_uuid_bump.hook finished in 48.43 seconds
2015/03/05 15:43:44 [e-mail]> pythonhook-pretxnchangegroup: hgext_pushlog.pretxnchangegrouphook finished in 2.16 seconds
2015/03/05 15:43:44 [e-mail]> exthook-changegroup.recordlogs: /repo/hg/scripts/record-pushes.sh finished in 0.02 seconds
2015/03/05 15:43:52 [e-mail]> exthook-changegroup.mirrorpush: /repo/hg/scripts/push-repo.sh finished in 8.20 seconds
2015/03/05 15:43:52 [e-mail]> pythonhook-changegroup: mozhghooks.push_printurls.hook finished in 0.00 seconds
2015/03/05 15:43:52 [e-mail]> 186 incoming changes - new heads: 0189941a3fd5
2015/03/05 15:43:53 [e-mail]> -R /repo/hg/mozilla/integration/fx-team serve --stdio exited 0 after 71.16 seconds

48s. Yikes. We should profile the hook and see if there are any ways to make it a little faster.

Comment 1

[Biru [:poiru]]

Attachment: Avoid slow `ctx.status(ctx.p1())` call in IDL hook

The WebIDL hook also has to iterate all files, but it ran considerably faster according to comment 0. One difference between the two hooks is that the IDL hook iterates over `ctx.status(ctx.p1()).modified` rather than `ctx.files()`. Iterating `ctx.files()` and manually checking for modified files seems to be faster. Ghetto profiling yielded the following results:

Before this patch (`ctx.status(ctx.p1()).modified`):

  528165 function calls (518154 primitive calls) in 0.411 seconds

     Ordered by: cumulative time
     List reduced from 154 to 25 due to restriction <25>

     ncalls  tottime  percall  cumtime  percall filename:lineno(function)
  14001/10001  0.010    0.000    0.226    0.000 mercurial/util.py:433(__get__)
       2000    0.013    0.000    0.156    0.000 mercurial/context.py:288(status)
       4000    0.005    0.000    0.115    0.000 mercurial/context.py:499(_changeset)
       6002    0.020    0.000    0.104    0.000 mercurial/revlog.py:974(revision)
       4000    0.016    0.000    0.104    0.000 mercurial/changelog.py:277(read)
       6000    0.002    0.000    0.079    0.000 mercurial/context.py:164(manifest)
       4000    0.005    0.000    0.073    0.000 mercurial/context.py:503(_manifest)
       2000    0.001    0.000    0.070    0.000 mercurial/context.py:529(description)
       2000    0.002    0.000    0.068    0.000 mercurial/context.py:102(_prestatus)
       2000    0.002    0.000    0.056    0.000 mercurial/context.py:954(data)
       1000    0.001    0.000    0.054    0.000 mercurial/context.py:702(filerev)
       1000    0.001    0.000    0.052    0.000 mercurial/context.py:664(_filerev)
       2000    0.002    0.000    0.051    0.000 mercurial/filelog.py:39(read)
       1000    0.001    0.000    0.044    0.000 mercurial/context.py:644(_filelog)
       1000    0.001    0.000    0.043    0.000 mercurial/localrepo.py:756(file)
       1000    0.002    0.000    0.042    0.000 mercurial/filelog.py:35(__init__)
       4003    0.012    0.000    0.042    0.000 mercurial/revlog.py:915(_chunks)
       1000    0.010    0.000    0.040    0.000 mercurial/revlog.py:193(__init__)
       2000    0.008    0.000    0.038    0.000 mercurial/context.py:121(_buildstatus)
       4003    0.004    0.000    0.030    0.000 mercurial/revlog.py:1048(_checkhash)
       2000    0.004    0.000    0.029    0.000 mercurial/context.py:93(_matchstatus)
       4000    0.004    0.000    0.026    0.000 mercurial/context.py:72(_manifestmatches)
       6000    0.006    0.000    0.026    0.000 mercurial/encoding.py:83(tolocal)
       2000    0.001    0.000    0.025    0.000 mercurial/context.py:221(parents)
      16000    0.014    0.000    0.023    0.000 mercurial/localrepo.py:28(__get__)

With this patch (`ctx.files()`):

  411092 function calls (407092 primitive calls) in 0.340 seconds

     Ordered by: cumulative time
     List reduced from 122 to 25 due to restriction <25>

     ncalls  tottime  percall  cumtime  percall filename:lineno(function)
  13000/9000   0.009    0.000    0.229    0.000 mercurial/util.py:433(__get__)
       3000    0.001    0.000    0.098    0.000 mercurial/context.py:702(filerev)
       4002    0.018    0.000    0.096    0.000 mercurial/revlog.py:974(revision)
       2000    0.003    0.000    0.095    0.000 mercurial/context.py:664(_filerev)
       2000    0.001    0.000    0.094    0.000 mercurial/context.py:529(description)
       2000    0.003    0.000    0.090    0.000 mercurial/context.py:499(_changeset)
       2000    0.011    0.000    0.084    0.000 mercurial/changelog.py:277(read)
       2000    0.001    0.000    0.080    0.000 mercurial/context.py:644(_filelog)
       2000    0.002    0.000    0.079    0.000 mercurial/localrepo.py:756(file)
       2000    0.003    0.000    0.077    0.000 mercurial/filelog.py:35(__init__)
       2000    0.017    0.000    0.073    0.000 mercurial/revlog.py:193(__init__)
       2000    0.002    0.000    0.053    0.000 mercurial/context.py:954(data)
       2000    0.002    0.000    0.048    0.000 mercurial/filelog.py:39(read)
       4002    0.011    0.000    0.039    0.000 mercurial/revlog.py:915(_chunks)
       2001    0.003    0.000    0.034    0.000 mercurial/store.py:452(__call__)
       2001    0.005    0.000    0.030    0.000 mercurial/scmutil.py:332(__call__)
       4002    0.004    0.000    0.029    0.000 mercurial/revlog.py:1048(_checkhash)
       2000    0.001    0.000    0.025    0.000 mercurial/context.py:221(parents)
       2000    0.005    0.000    0.022    0.000 mercurial/context.py:511(_parents)
       1000    0.002    0.000    0.020    0.000 hghooks/mozhghooks/prevent_idl_change_without_uuid_bump.py:51(check_unbumped_idl_interfaces)
       4000    0.004    0.000    0.018    0.000 mercurial/encoding.py:83(tolocal)
       4000    0.007    0.000    0.018    0.000 mercurial/context.py:373(__init__)
       4003    0.006    0.000    0.018    0.000 mercurial/revlog.py:903(_chunkraw)
       2000    0.005    0.000    0.018    0.000 hghooks/mozhghooks/prevent_idl_change_without_uuid_bump.py:56(parse)
       4002    0.002    0.000    0.018    0.000 mercurial/revlog.py:1053(checkhash)

Comment 2

[Biru [:poiru]]

Attachment: Ignore merge changesets in IDL hook

This makes the IDL hook behave like the WebIDL hook with merges. See also bug 1128518 comment 25 and comment 26.

Comment 3

[Gregory Szorc [:gps]]

Comment on attachment 8574444 [details] [diff] [review]
Avoid slow `ctx.status(ctx.p1())` call in IDL hook

Review of attachment 8574444 [details] [diff] [review]:
-----------------------------------------------------------------

Background.

ctx.status() is slow because it iterates multiple manifests (in our case lists of ~100,000 files) and compares entries. ctx.files() is nearly instantaneous because the commit object contains a cache of the set of files changed by the commit.

Caveat: old and buggy Mercurial clients sometimes don't produce valid .files() sets. But you shouldn't need to worry about this here.

This doesn't get r+ because of copy/move handling. We should add a test there. I /think/ that when you write this test, you'll find the hook is now doing something it isn't (enforcing UUID bumps when files are moved). We /may/ already have an issue with this. Copies and moves are hard. I can be convinced perfect is the enemy of done and it isn't worth the trouble.

::: hghooks/mozhghooks/prevent_idl_change_without_uuid_bump.py
@@ +88,4 @@
>              if not path.endswith('.idl'):
>                  continue
>  
> +            if not path in ctx:  # Deleted file

if path not in ctx:

"not in" is an operator. Whereas what you've written is essentially "not (path in ctx)". By the magic of operator precedence, this does work. But it is considered a not good practice.

@@ +94,3 @@
>              fctx = ctx[path]
> +            if fctx.filerev() == 0:  # New file
> +                continue

I /think/ this change may start inspecting copied files. Please add an explicit test for `hg cp` or `hg mv` behavior.

Comment 4

[Biru [:poiru]]

Attachment: Avoid slow `ctx.status(ctx.p1())` call in IDL hook

Added tests for `hg cp` and `hg mv`. Seems to work fine.

Comment 5

[Biru [:poiru]]

Attachment: Avoid slow `ctx.status(ctx.p1())` call in IDL hook

Gah, wrong patch. (Guess I should stop being lazy and configure bzexport/MozReview for the version-control-tools repo as well.)

Comment 6

[Biru [:poiru]]

Comment on attachment 8574446 [details] [diff] [review]
Ignore merge changesets in IDL hook

http://hg.mozilla.org/hgcustom/version-control-tools/rev/4c687d5732c8

Comment 7

[Biru [:poiru]]

Comment on attachment 8577607 [details] [diff] [review]
Avoid slow `ctx.status(ctx.p1())` call in IDL hook

http://hg.mozilla.org/hgcustom/version-control-tools/rev/885e5e2bb6ae

Comment 8

[Ryan VanderMeulen [:RyanVM]]

Did this ever get deployed?

Comment 9

[Gregory Szorc [:gps]]

It would have got deployed yesterday at the latest.

Comment 10

[Biru [:poiru]]

Marking as fixed. Please reopen if this is still an issue.