1303904 - Decision task failing trying to fetch json-automationrelevance on merge to mozilla-aurora

Status: RESOLVED FIXED

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

Description

[Phil Ringnalda (:philor)]

<philor>: tools.taskcluster.net/task-inspector/#ayJi2q5jSK2RAb7bhOga6Q/0 is the decision task failing on the merge to aurora, timing out fetching automationrelevance from hg.m.o
<gps>: philor, dustin: that /may/ be a regression from the recent refactor. previous merge days went fine.
<gps>: a 5s timeout is really short
<gps>: the API is likely CPU bound on the server
<gps>: you can test that by running `time curl mozilla-aurora/json-automationrele…df759f09b1411f33fa0920835b919fc81` a few dozen times. i bet the variance in execution time is really low
<gps>: looks like it is timing out after 60s on the server :/

Bottom line: if we do this regularly on merges, then we'll need to keep the tree closed after the merge (I can't believe we don't just do that as a matter of policy) and then have something innocuous around to push to the closed tree in order to get our first set of Taskcluster jobs on the merge to see how busted they are.

Comment 1

[Gregory Szorc [:gps]]

I don't think this is a regression: the server-side process is taking 60+s to generate output. Bottleneck is reading the pushlog.

There's no easy workaround. We'll have to wait for the next push.

Comment 3

[Carsten Book [:Tomcat]]

(In reply to Gregory Szorc [:gps] from comment #1)
> I don't think this is a regression: the server-side process is taking 60+s
> to generate output. Bottleneck is reading the pushlog.
> 
> There's no easy workaround. We'll have to wait for the next push.

yeah this seems to work here

Comment 4

[Carsten Book [:Tomcat]]

seems this hit us again on the beta to release merge day

Comment 5

[Gregory Szorc [:gps]]

Ugh. I feel bad about having a bug impacting merge day activities. So I decided to spend a few minutes to dig deeper.

The automationrelevant() revset is not a problem: I can execute it on the command line and it completes very quickly. The bottleneck is calling webuitl.changelistentry() thousands of times. Specifically, the pushlog extension's code that runs during changelistentry() opens a new connection to the SQLite database then runs 2 SQL queries.

I suspect reusing the DB connection will make the perf issue go away. But that change isn't exactly trivial :/

Comment 6

[Dustin J. Mitchell [:dustin] (he/him)]

Given that the endpoint is specific to automation, it would not be unreasonable to return some "lots of things changed!" response when the revset exceeds a certain size, with corresponding handling of that response in-tree.

Comment 8

[Joel Maher ( :jmaher ) (UTC -8)]

if we can just ignore the automationrelevant() and let decision task finish, that would be good

Comment 9

[Aki Sasaki (not active)]

We hit this again today (merge day).
+1, if the number of commits hits a certain size, we should return true.

I'm hesitant to equate timeouts as relevant, since that means we might run all automation whenever hg.m.o gets really slammed, which would exacerbate things.  I'm equally hesitant to equate timeouts as non-relevance, since this logic breaks on merge day.  Setting a threshold for the number of commits on the server side makes the most sense to me.

Comment 10

[Wes Kocher (:KWierso) (Not reading bugmail; email directly if needed)]

Attachment: hgmo: Cap at 500 revisions in automationrelevancewebcommand (bug 1303904)

Review commit: https://reviewboard.mozilla.org/r/117800/diff/#index_header
See other reviews: https://reviewboard.mozilla.org/r/117800/

Comment 11

[Wes Kocher (:KWierso) (Not reading bugmail; email directly if needed)]

Comment on attachment 8844279 [details]
hgmo: Cap at 500 revisions in automationrelevancewebcommand (bug 1303904)

I'm unsure if this will work like I think it will work (I can't get my test environment working for some reason), but thought it'd be worth a shot. 

If this works like I think it will work, I think it will just stop looking at csets after we reach 500 csets, and then carry on with the rest of the function with that trimmed list.

Unless I read gps's comment wrong and I need to move this into the automationrelevant() revset itself?

Comment 12

[Aki Sasaki (not active)]

Comment on attachment 8844279 [details]
hgmo: Cap at 500 revisions in automationrelevancewebcommand (bug 1303904)

I'm not sure what the "yes, this is relevant; ignore the details" response should be.  It looks like we populate a json blob normally.  I'm also not sure if 500 is the right threshold, but it's definitely better than an unbounded maximum.  This patch probably requires more knowledgeable eyes than mine.

Comment 13

[Wes Kocher (:KWierso) (Not reading bugmail; email directly if needed)]

Happy to wait for gps to return, we'll still have a month after that before the next thousand+ cset merge day.

Comment 14

[Gregory Szorc [:gps]]

Comment on attachment 8844279 [details]
hgmo: Cap at 500 revisions in automationrelevancewebcommand (bug 1303904)

I'll come up with a hack to fix the perf issues.

The reason I was reluctant to do this before is I preferred to work in an upstream API so we wouldn't need a hack. But on further reflection, that is a lot of work. So the hacky route we will go.

Comment 15

[Gregory Szorc [:gps]]

Attachment: hgmo: stream JSON responses (bug 1303904);

Previously, we called json.dumps() for some web commands. This buffers
the JSON response in memory then sends it. That buffering can take a
long time if the returned document is large.

Because of differences in how the JSON encoder is implemented, this
improves throughput of sending JSON from ~315KB/s to >7MB/s on my
i7-6700K.

Test output for the mozbuildinfo command has changed because we no
longer send trailing whitespace (which is what the default JSONEncoder
does in Python 2.7).

Because of clownshoes that will be fixed in a subsequent commit, this
drops the time to first byte on
json-automationrelevance/5dddbefdf759f09b1411f33fa0920835b919fc81
against the mozilla-aurora repo from ~119s to ~80s.

Review commit: https://reviewboard.mozilla.org/r/147270/diff/#index_header
See other reviews: https://reviewboard.mozilla.org/r/147270/

Comment 16

[Gregory Szorc [:gps]]

Attachment: pushlog: make repo.pushlog a cached property (bug 1303904);

Currently, repo.pushlog creates a new pushlog instance on every
access. This creates overhead and prevents some forms of caching.

The "propertyfilecache" decorator cached the property value, but only
if the underlying files haven't changed. This allows the same pushlog
instance to be returned as long as no updates have occurred.

This is the easiest way to implement a cache of the pushlog instance
without having to consider implications of reusing mutated instances.
This change does introduce a stat() for every property lookup.
Considering we're currently opening a SQLite database for every
iteration of some loops, this overhead, while unfortunate, should
be marginal.

Review commit: https://reviewboard.mozilla.org/r/147272/diff/#index_header
See other reviews: https://reviewboard.mozilla.org/r/147272/

Comment 17

[Gregory Szorc [:gps]]

Attachment: pushlog: factor out code to obtain a push from a node (bug 1303904);

A subsequent commit will introduce a consumer that wants to obtain
push records for multiple nodes. To facilitate doing this with a
single database handle, refactor the code into a function that takes
a database connection as an argument.

Review commit: https://reviewboard.mozilla.org/r/147274/diff/#index_header
See other reviews: https://reviewboard.mozilla.org/r/147274/

Comment 18

[Gregory Szorc [:gps]]

Attachment: hgmo: refactor loop iterating over revs (bug 1303904);

We'll soon introduce a second consumer of this result. So we save the
revset result to a variable to avoid redundant execution. We also buffer
the result in a list because we know we'll be iterating twice and this
will be more efficient than iterating a revset result type.

Review commit: https://reviewboard.mozilla.org/r/147276/diff/#index_header
See other reviews: https://reviewboard.mozilla.org/r/147276/

Comment 19

[Gregory Szorc [:gps]]

Attachment: pushlog: API to cache pushlog lookups (bug 1303904);

The pushlog API is not conducive to performance because various
methods result in a SQLite database handle being opened for every
lookup. When doing things like looking up pushlog entries for
every node in a list, the overhead can really add up.

This commit introduces a context manager for populating a cache
to facilitate rapid node -> push lookups.

This commit is somewhat hacky. There are a number of alternatives
I'd prefer, such as a bulk lookup API or automatic caching. A bulk
lookup API isn't usable in the case of the automationrelevance web
command because the function that calls the pushlog API is per
changeset, not per collection. And I'm not yet willing to implement
automatic caching because caching is hard and I don't want to
invite bugs.

A context manager, however, allows us to create caches with scoped
lifetimes thus limiting the caching (and bugs related to it) to
consumers who opt into the cache. Yes, it's hacky. But it gets the
job done.

To prove the cache works, the automationrelevance web command has
been updated to use it.

This drops time to first byte on
json-automationrelevance/5dddbefdf759f09b1411f33fa0920835b919fc81 HTTP
requests against the mozilla-aurora repo from ~80s to ~1.5s. However,
there is still a major source of clownshoes for that request...

Review commit: https://reviewboard.mozilla.org/r/147278/diff/#index_header
See other reviews: https://reviewboard.mozilla.org/r/147278/

Comment 20

[Gregory Szorc [:gps]]

Attachment: hgmo: don't send list of push nodes with automationrelevant response (bug 1303904);

This data is redundant with other data in the JSON. Furthermore, for
large pushes (such as uplifts, which contains thousands of changesets),
the redundancy is massive.

I'm pretty sure nobody looks at this data. The only consumer of this
API I'm aware of (TaskCluster decision task) only cares about the
"node," "desc," and "files" elements.

For json-automationrelevance/5dddbefdf759f09b1411f33fa0920835b919fc81
against the mozilla-aurora repo, this change reduces the raw HTTP
response size from 2348 MB to 10.8 MB and the server-side CPU required
from ~311s to ~6s (as measured on my i7-6700K). Yes, you read that
correctly.

Review commit: https://reviewboard.mozilla.org/r/147280/diff/#index_header
See other reviews: https://reviewboard.mozilla.org/r/147280/

Comment 21

[Gregory Szorc [:gps]]

The abridged version of the commit messages is this series drops time to first byte for an example uplift push from ~120s to ~1.5s and total size of the JSON response from 2348 MB to 10.8 MB. I listened to Entry of the Gladiators as I was writing the commit messages.

Comment 22

[:glob ✱]

Comment on attachment 8875868 [details]
hgmo: stream JSON responses (bug 1303904);

https://reviewboard.mozilla.org/r/147270/#review152956

::: hgext/hgmo/__init__.py:319
(Diff revision 1)
>      # Round trip to ensure we have valid JSON.
>      try:
>          d = json.loads(stdout)
> -        return json.dumps(d, indent=2, sort_keys=True)
> +        return stream_json(d)
>      except Exception:
>          return json.dumps({'error': 'invalid JSON returned; report this error'},
>                            indent=2)

could we assume it's stable and stream its output directly to the requester without a json decode/encode round trip?

as per our chat feel free to drop this issue and leave as-is; this isn't in the critical path for this performance issue.

Comment 23

[:glob ✱]

Comment on attachment 8875869 [details]
pushlog: make repo.pushlog a cached property (bug 1303904);

https://reviewboard.mozilla.org/r/147272/#review154254

::: commit-message-0f52a:6
(Diff revision 1)
> +pushlog: make repo.pushlog a cached property (bug 1303904); r?glob
> +
> +Currently, repo.pushlog creates a new pushlog instance on every
> +access. This creates overhead and prevents some forms of caching.
> +
> +The "propertyfilecache" decorator cached the property value, but only

i think you mean "repofilecache" here, as propertyfilecache creates a new object on every call.

Comment 24

[:glob ✱]

Comment on attachment 8875870 [details]
pushlog: factor out code to obtain a push from a node (bug 1303904);

https://reviewboard.mozilla.org/r/147274/#review154258

Comment 25

[:glob ✱]

Comment on attachment 8875871 [details]
hgmo: refactor loop iterating over revs (bug 1303904);

https://reviewboard.mozilla.org/r/147276/#review154260

Comment 26

[:glob ✱]

Comment on attachment 8875872 [details]
pushlog: API to cache pushlog lookups (bug 1303904);

https://reviewboard.mozilla.org/r/147278/#review154262

yeah, this is somewhat hacky, but it looks sane given the approach.

Comment 27

[:glob ✱]

Comment on attachment 8875873 [details]
hgmo: don't send list of push nodes with automationrelevant response (bug 1303904);

https://reviewboard.mozilla.org/r/147280/#review154264

Comment 28

[Gregory Szorc [:gps]]

Comment on attachment 8875868 [details]
hgmo: stream JSON responses (bug 1303904);

https://reviewboard.mozilla.org/r/147270/#review152956

> could we assume it's stable and stream its output directly to the requester without a json decode/encode round trip?
> 
> as per our chat feel free to drop this issue and leave as-is; this isn't in the critical path for this performance issue.

Yeah, we can improve this code. But not in this bug.

Comment 29

[Gregory Szorc [:gps]]

Comment on attachment 8875868 [details]
hgmo: stream JSON responses (bug 1303904);

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/147270/diff/1-2/

Comment 30

[Gregory Szorc [:gps]]

Comment on attachment 8875869 [details]
pushlog: make repo.pushlog a cached property (bug 1303904);

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/147272/diff/1-2/

Comment 31

[Gregory Szorc [:gps]]

Comment on attachment 8875870 [details]
pushlog: factor out code to obtain a push from a node (bug 1303904);

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/147274/diff/1-2/

Comment 32

[Gregory Szorc [:gps]]

Comment on attachment 8875871 [details]
hgmo: refactor loop iterating over revs (bug 1303904);

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/147276/diff/1-2/

Comment 33

[Gregory Szorc [:gps]]

Comment on attachment 8875872 [details]
pushlog: API to cache pushlog lookups (bug 1303904);

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/147278/diff/1-2/

Comment 34

[Gregory Szorc [:gps]]

Comment on attachment 8875873 [details]
hgmo: don't send list of push nodes with automationrelevant response (bug 1303904);

Review request updated; see interdiff: https://reviewboard.mozilla.org/r/147280/diff/1-2/

Comment 35

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/hgcustom/version-control-tools/rev/2ba557b29106
hgmo: stream JSON responses ; r=glob
https://hg.mozilla.org/hgcustom/version-control-tools/rev/fa9313510326
pushlog: make repo.pushlog a cached property ; r=glob
https://hg.mozilla.org/hgcustom/version-control-tools/rev/01497dd90af6
pushlog: factor out code to obtain a push from a node ; r=glob
https://hg.mozilla.org/hgcustom/version-control-tools/rev/cbe2a5a5ae20
hgmo: refactor loop iterating over revs ; r=glob
https://hg.mozilla.org/hgcustom/version-control-tools/rev/af4420a6680e
pushlog: API to cache pushlog lookups ; r=glob
https://hg.mozilla.org/hgcustom/version-control-tools/rev/c23d48384dba
hgmo: don't send list of push nodes with automationrelevant response ; r=glob

Comment 36

[Gregory Szorc [:gps]]

This has been deployed. HTTP requests like https://hg.mozilla.org/releases/mozilla-aurora/json-automationrelevance/5dddbefdf759f09b1411f33fa0920835b919fc81 that previously timed out now complete in ~6s. This should no longer impact uplift day activities.