1339836 - seta-analyze-failures uses >1GB RAM causing the worker dyno to be terminated

Status: RESOLVED FIXED

(Tree Management Graveyard :: Treeherder: SETA, defect, P1)

Description

[Ed Morley [:emorley]]

emorley: Re the background seta-analyse-failures task, I still couldn't see it on New Relic after retriggering
emorley: However checking the dyno shows it's being killed due to using twice the RAM available: https://dashboard.heroku.com/apps/treeherder-prod/metrics/worker_default
emorley: The dyno normally uses 200-250MB RAM (out of 512MB total), but jumps to 1100MB+ when the seta-analyse failures task is being run before being killed
emorley: reading the code it seems to me the task is doing something pretty crazy like "fetch all jobs in the last 4 months that have a comment"
emorley: that seems unlikely to succeed
emorley: ie: 4 months is too long, plus more aggregation should be done at the DB level, plus the queryset should be iterated rather than loaded at once

From papertrail:

Feb 15 15:16:55 treeherder-prod heroku/worker_default.1: Error R14 (Memory quota exceeded) 
Feb 15 15:17:17 treeherder-prod heroku/worker_default.1: source=worker_default.1 dyno=heroku.47819539.f1a59b6d-a67b-40aa-ac3d-d49cba1fce8c sample#load_avg_1m=0.54 sample#load_avg_5m=0.31 sample#load_avg_15m=0.23 
Feb 15 15:17:17 treeherder-prod heroku/worker_default.1: source=worker_default.1 dyno=heroku.47819539.f1a59b6d-a67b-40aa-ac3d-d49cba1fce8c sample#memory_total=980.45MB sample#memory_rss=463.89MB sample#memory_cache=0.00MB sample#memory_swap=516.56MB sample#memory_pgpgin=7400536pages sample#memory_pgpgout=7281781pages sample#memory_quota=512.00MB 
Feb 15 15:17:17 treeherder-prod heroku/worker_default.1: Process running mem=980M(191.5%) 
Feb 15 15:17:17 treeherder-prod heroku/worker_default.1: Error R14 (Memory quota exceeded) 
Feb 15 15:17:39 treeherder-prod heroku/worker_default.1: source=worker_default.1 dyno=heroku.47819539.f1a59b6d-a67b-40aa-ac3d-d49cba1fce8c sample#load_avg_1m=0.68 sample#load_avg_5m=0.35 sample#load_avg_15m=0.25 
Feb 15 15:17:39 treeherder-prod heroku/worker_default.1: source=worker_default.1 dyno=heroku.47819539.f1a59b6d-a67b-40aa-ac3d-d49cba1fce8c sample#memory_total=1109.92MB sample#memory_rss=420.41MB sample#memory_cache=0.00MB sample#memory_swap=689.51MB sample#memory_pgpgin=7710451pages sample#memory_pgpgout=7602825pages sample#memory_quota=512.00MB 
Feb 15 15:17:39 treeherder-prod heroku/worker_default.1: Process running mem=1109M(216.8%) 
Feb 15 15:17:39 treeherder-prod heroku/worker_default.1: Error R15 (Memory quota vastly exceeded) 
Feb 15 15:17:39 treeherder-prod heroku/worker_default.1: Stopping process with SIGKILL 
Feb 15 15:17:39 treeherder-prod heroku/worker_default.1: State changed from up to crashed 
(https://papertrailapp.com/systems/treeherder-prod/events?centered_on_id=768541769469165574&q=program%3Aheroku%2Fworker_default.1)

Comment 1

[Robert Wood [:rwood]]

:jmaher, realistically how far back do we need to go when getting the list of 'fixed by commit' jobs, in order for the SETA algorithm to be effective? Right now we get all of them and there are almost 80,000 entries in JobNote with that classification.

Comment 2

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

minimum 90 days, I think there are 120 days in the database.

Comment 3

[Ed Morley [:emorley]]

Is the 90 days based on statistical analysis, linked to the release cycle in some way, or just an arbitrary figure?

I would have thought on release branches too long of a window might actually be a bad thing, given uplifts every 6 weeks which presumably change the balance somewhat.

Comment 4

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

90 days was arbitrary- we used to do 180 days and found that was too long.  I am open to exploring a shorter time window, but we should analyze that.  The more data the better to be honest.  The data we use should be only for trunk branches and 90 days would span 2 cycles which seems reasonable.  Possibly we are getting fixed_by_commit data on ALL branches?

Comment 5

[Robert Wood [:rwood]]

Ok thanks, there is no filtering on the JobNote query at the moment except for failure_classification, so definitely some optimization to be done here, I'll see what I can come up with.

Comment 6

[GitHub Autolander Bot]

Attachment: [treeherder] rwood-moz:bug1339836 > mozilla:master

Comment 7

[Robert Wood [:rwood]]

Comment on attachment 8840097 [details] [review]
[treeherder] rwood-moz:bug1339836 > mozilla:master

This is by no means ready of course, but can I get your feedback so far guys on the DB query optimization? Thanks!

Comment 8

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

Comment on attachment 8840097 [details] [review]
[treeherder] rwood-moz:bug1339836 > mozilla:master

this looks like a great approach, one comment

Comment 9

[Ed Morley [:emorley]]

Comment on attachment 8840097 [details] [review]
[treeherder] rwood-moz:bug1339836 > mozilla:master

Looks good, left a comment (though can be done as a follow-up rather than now).
Could you also check the SQL generated is what we expect (eg hit /seta/failures-fixed-by-commit/ locally with the debug toolbar enabled)?

Comment 10

[Robert Wood [:rwood]]

> Could you also check the SQL generated is what we expect (eg hit
> /seta/failures-fixed-by-commit/ locally with the debug toolbar enabled)?

Oh that's pretty cool thanks, yes the SQL looks good!

Comment 11

[Robert Wood [:rwood]]

Good thing for the unit tests, there was an error in my resulting SQL... both of the items in the exclude were combined as an AND, so therefore none of the jobs were being excluded based on no note text or invalid platform.

Separated the items into two chained .exclude blocks and now the resulting SQL is better:
...
AND NOT (`reference_data_signatures`.`build_platform` IN ('android-4-2-armv7-api15', 'windows7-64', 'linux64-stylo', 'Win 6.3.9600 x86_64', 'windows8-32', 'windowsxp', 'android-5-0-armv8-api15', 'android-4-4-armv7-api15', 'taskcluster-images', 'other', 'android-5-1-armv7-api15', 'osx-10-9', 'osx-10-7', 'android-6-0-armv8-api15', 'osx-10-11')) AND NOT (`job_note`.`text` = ''))

Comment 12

[Robert Wood [:rwood]]

Comment on attachment 8840097 [details] [review]
[treeherder] rwood-moz:bug1339836 > mozilla:master

Alright hopefully this will reduce the memory overhead substantially.

:emorley, also a question, you'll see my update to test_analyze_failures. Instead of doing:

SETA_FIXED_BY_COMMIT_REPOS.append(test_repository.name)

I tried to do:

@patch('treeherder.seta.settings.SETA_FIXED_BY_COMMIT_REPOS', [test_repository.name])

And variations of that, and tried using monkeypatch too, but I couldn't get it to work... do you know offhand how to do that via patch? Or is the append acceptable? Thanks.

Comment 13

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

Comment on attachment 8840097 [details] [review]
[treeherder] rwood-moz:bug1339836 > mozilla:master

two specific issues, but this is shaping up to be nice!

Comment 14

[Robert Wood [:rwood]]

test_analyze_failures is currently disabled because of another issue (bug 1342451), the required updates to that test will be included in the patch for that bug

Comment 15

[Robert Wood [:rwood]]

Comment on attachment 8840097 [details] [review]
[treeherder] rwood-moz:bug1339836 > mozilla:master

ping :emorley, if you have a chance for the review of the DB query also please that'd be great thanks

Comment 16

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

Comment on attachment 8840097 [details] [review]
[treeherder] rwood-moz:bug1339836 > mozilla:master

thanks rwood.

Comment 17

[Ed Morley [:emorley]]

Comment on attachment 8840097 [details] [review]
[treeherder] rwood-moz:bug1339836 > mozilla:master

Looks good :-)

Could you file a bug for discussing moving the list of repos to properties on the Repository table/fixture instead? (Per https://github.com/mozilla/treeherder/pull/2193#discussion_r102592296)

(In reply to Robert Wood [:rwood] from comment #12)
> :emorley, also a question, you'll see my update to test_analyze_failures.
> Instead of doing:
> 
> SETA_FIXED_BY_COMMIT_REPOS.append(test_repository.name)
> 
> I tried to do:
> 
> @patch('treeherder.seta.settings.SETA_FIXED_BY_COMMIT_REPOS',
> [test_repository.name])
> 
> And variations of that, and tried using monkeypatch too, but I couldn't get
> it to work... do you know offhand how to do that via patch? Or is the append
> acceptable? Thanks.

It will need patching at the place it's imported at due to:
https://docs.python.org/3/library/unittest.mock.html#where-to-patch

Also I think patch.object might be what you need? 

eg:
`@patch.object('treeherder.seta.analyze_failures', 'SETA_FIXED_BY_COMMIT_REPOS')`

(Though I always have to experiment to get this kind of thing to work too, so that still might not be correct!)

Comment 18

[Robert Wood [:rwood]]

Thanks! I filed bug 1342932

Comment 19

[Treeherder GitHub Bugbot]

Commit pushed to master at https://github.com/mozilla/treeherder

https://github.com/mozilla/treeherder/commit/9c4a9c76384f68e1f2611eb13c9d0a50b582e393
Bug 1339836 - SETA: Optimize analyze_failures (#2193)

Comment 20

[Robert Wood [:rwood]]

So in Heroku metrics for treehrder-prod I still see the memory exceeded warning. Just want to make sure I am reading the papertrail logs correctly while analzye_failures was run with this patch.

A memory quota exceeded error is here:

https://papertrailapp.com/systems/treeherder-prod/events?focus=775560399918637080&selected=775560399918637080

However after that I do see the SETA analyze_failures output:

https://papertrailapp.com/systems/treeherder-prod/events?focus=775561532271652896&q=worker_default&selected=775561532271652896

:emorley, am I right to assume that some other process on the default worker is causing a memory exception but analyze_failures is now running fine?

Comment 21

[Ed Morley [:emorley]]

Filtering by `program:worker_default.1` for a clearer view, I believe it's cycle_data that was causing the R14:
https://papertrailapp.com/systems/treeherder-prod/events?q=program%3Aworker_default.1&focus=775560453404393499

Note also that R14 is basically "swapping, since using >100% of the dyno RAM quota", whereas R15 is "has been killed for using >200% of the dyno RAM quota". So in this case nothing was killed (though the R14s are still a red flag).

Comment 22

[Robert Wood [:rwood]]

(In reply to Ed Morley [:emorley] from comment #21)

Ok cool, and good point, thanks!