1021795 - Loading enter_bug.cgi for the Core product takes 8 seconds due to multiple factors

Status: NEW

(bugzilla.mozilla.org :: Extensions, defect, P2)

Description

[Ed Morley [:emorley]]

Visit https://bugzilla.mozilla.org/enter_bug.cgi?form_name=enter_bug&product=Core with the web console open:

enter_bug.cgi [HTTP/1.1 200 OK 8289ms]
enter_bug.cgi [HTTP/1.1 200 OK 7998ms]
enter_bug.cgi [HTTP/1.1 200 OK 8703ms]
enter_bug.cgi [HTTP/1.1 200 OK 8224ms]
enter_bug.cgi [HTTP/1.1 200 OK 8303ms]

The devtools network panel says ~7550ms waiting for response and ~550ms receiving it.

Compare to:

https://bugzilla.mozilla.org/enter_bug.cgi?form_name=enter_bug&product=Testing
enter_bug.cgi [HTTP/1.1 200 OK 2091ms]
enter_bug.cgi [HTTP/1.1 200 OK 2224ms]
enter_bug.cgi [HTTP/1.1 200 OK 2613ms]

Presuming number of flags/fields/...

Comment 1

[David Lawrence [:dkl]]

Seems the tracking flags extension is taking a lot of that time as I found do some simple debugging. Will need to take a look at further optimization.

dkl

Comment 2

[Ed Morley [:emorley]]

(In reply to David Lawrence [:dkl] from comment #1)
> Seems the tracking flags extension is taking a lot of that time as I found
> do some simple debugging. Will need to take a look at further optimization.

I would hazard a guess that this bug is a major contributor to the "gecko devs think bugzilla is slow" sentiment that is occasionally seen on IRC, given that the vast majority of bugs they file are in the Core component - and also the reason why people end up using bzapi tools to file bugs (eg hg bzexport --new).

I don't suppose you had a chance to profile this? :-)

Comment 3

[Ed Morley [:emorley]]

(In reply to David Lawrence [:dkl] from comment #1)
> Seems the tracking flags extension is taking a lot of that time as I found
> do some simple debugging. Will need to take a look at further optimization.

(In reply to Ed Morley [:edmorley] from comment #2)
> I would hazard a guess that this bug is a major contributor to the "gecko
> devs think bugzilla is slow" sentiment that is occasionally seen on IRC,
> given that the vast majority of bugs they file are in the Core component -
> and also the reason why people end up using bzapi tools to file bugs (eg hg
> bzexport --new).
> 
> I don't suppose you had a chance to profile this? :-)

Comment 4

[Dylan Hardison [:dylan] (he/him)]

Rudimentary profiling strongly suggests this is the culprit:

https://github.com/mozilla/webtools-bmo-bugzilla/blob/master/extensions/TrackingFlags/template/en/default/hook/bug/create/create-form.html.tmpl#L25-L35

Rewriting that logic in perl, and possibly making it achieve more cache hits, can probably speed us up quite a bit.

Comment 5

[Dylan Hardison [:dylan] (he/him)]

I think we can make this faster by serializing to javascript from the perl, rather than in the template, is a good strategy.

Comment 6

[Ed Morley [:emorley]]

I know in the past there was general BMO perf work being performed - is there any ongoing / is there a metabug?

It's just that anecdotally I'm pretty sure this bug ranks high up on the list of perf issues that the bugzilla-heavy Mozilla/Firefox developer hits - so it seems like a good one to throw in the running when it comes to prioritising perf bugs.

Comment 7

[Dylan Hardison [:dylan] (he/him)]

there should be a metabug -- and also this bug may be a lot faster as json serialization was moved out of the template.

Comment 8

[Ed Morley [:emorley]]

It's still the same for me:

22:18:47.214 GET https://bugzilla.mozilla.org/enter_bug.cgi?form_name=enter_bug&product=Core [HTTP/1.1 200 OK 8107ms]

Comment 9

[David Lawrence [:dkl]]

(In reply to Dylan William Hardison [:dylan] from comment #7)
> there should be a metabug -- and also this bug may be a lot faster as json
> serialization was moved out of the template.

If I recall correctly, this has all to do with tracking flags. If you comment out the part that loads the tracking flags for entering a Core bug, it loads rather quickly. We need to take some time to optimize how the tracking flags are loaded as Core has a lot of them and is an extreme case.

dkl

Comment 10

[Mark Côté [:mcote]]

The recent perf work was confined to show_bug, since it gets the most traffic (by far).  Indeed there are improvements we can do elsewhere, and this is one of them. :)  I don't believe there is any meta bug for general perf improvements though (or any specific to pages other than show_bug).

Comment 11

[Wayne Mery (:wsmwk)]

(In reply to Dylan William Hardison [:dylan] from comment #7)
> there should be a metabug -- and also this bug may be a lot faster as json
> serialization was moved out of the template.

(In reply to Mark Côté [:mcote] from comment #10)
> The recent perf work was confined to show_bug, since it gets the most
> traffic (by far).  Indeed there are improvements we can do elsewhere, and
> this is one of them. :)  I don't believe there is any meta bug for general
> perf improvements though (or any specific to pages other than show_bug).

Indeed I've not found an overarching meta bug in http://mzl.la/1HKv3ZP (all meta bugs) nor http://mzl.la/1HKv3ZP (all perf bugs)

Comment 12

[Dylan Hardison [:dylan] (he/him)]

Caching tracking flags would help this, but a big part of the performance is still tied up in generating JSON inside templates.

A good speed improvement could be had if someone rewrote 
https://github.com/mozilla/webtools-bmo-bugzilla/blob/master/extensions/Review/template/en/default/hook/global/header-start.html.tmpl#L42-L91
to be generated by JSON::XS.

It's definitely on my radar -- it might also be something a contributor would want to do.

Comment 13

[Dylan Hardison [:dylan] (he/him)]

Here is the profiling data backing my claim:
http://people.mozilla.org/~dhardison/1021795/

We should also make tracking flags faster, but the JSON fix is even better.

Comment 14

[Dylan Hardison [:dylan] (he/him)]

So the basic plan is to rewrite this:

https://github.com/mozilla-bteam/bmo/blob/master/template/en/default/bug/create/create.html.tmpl#L67-L102

into perl.

probably stuff all the things into %data, then encode_json that to JSON on the perl side, JSON.parse() on the javascript side,
and set all those vars like components = data.components;

Comment 15

[Dylan Hardison [:dylan] (he/him)]

look at enter_bug.cgi, near the end to figure out where to inject variables -- $vars->{data} = \%data
right before $template->process() is called.

Comment 16

[Kalpesh Krishna [:martianwars]]

Attachment: enter_bug fux

Comment 17

[Dylan Hardison [:dylan] (he/him)]

Comment on attachment 8769747 [details] [review]
enter_bug fux

r-, see pull review comments. 

With a small fix I got it working, and I'll run the benchmark against it and upload to my people.mozilla.org for you to look at.

Comment 18

[Kalpesh Krishna [:martianwars]]

12:25 AM <dylan> we make too many DB queries, that's the big problem
12:25 AM <dylan> we have memcache support, but on BMO it's limited until I get Cache::Memcached::Fast installed
12:26 AM <dylan> (plus, caching should be your *last* method of improving speed)
12:26 AM <martianwars> dylan: so the goal is to reduce DB queries right?
12:26 AM <dylan> yep
12:26 AM <martianwars> so lemme try that command now
12:26 AM <martianwars> dbiprof
12:27 AM <dylan> make fewer queries, or spot places where we have no indexes
12:28 AM <dylan> dbiprof --number 5  --sort longest
12:28 AM <dylan> those queries arn't *that* slow
12:28 AM <martianwars> uh why is the gist different from my output? isn't the gist of this file?
12:28 AM <dylan> not sure?
12:29 AM <dylan> did you gunzip it?
12:29 AM <martianwars> well, I see a different execution time
12:29 AM <martianwars> i can see a similar gist, slightly diff values
12:29 AM <dylan> I may have re-run it
12:29 AM <dylan> there is some jitter
12:30 AM <dylan> I'm more concerned with the 2316 requests then the exact timings
12:30 AM <martianwars> okay makes sense, since number of records and total count is same
12:30 AM <martianwars> yeah that is 2316
12:31 AM <dylan> SELECT id,tracking_flag_id,setter_group_id,value,sortkey,is_active,comment FROM tracking_flags_values WHERE  tracking_flag_id IN
12:31 AM <dylan> (?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,
12:31 AM <dylan> ?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?)   ORDER BY sortkey
12:31 AM <dylan> ^ that can not be a healthy query
12:32 AM <dylan> I think that is from Bugzilla::Extension::TrackingFlag::Value->get_all() or similar.
12:32 AM <dylan> (I'm not saying you can fix that particular part, btw)
12:32 AM <martianwars> that query has just run once though
12:33 AM <dylan> but for some reason we call this one
12:33 AM <dylan> SELECT id,name,description,cc_list,target_type,sortkey,is_active,is_requestable,is_requesteeble,is_multiplicable,grant_group_id,request_group_id,default_requestee FROM flagtypes WHERE  id IN
12:33 AM <dylan> (?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,
12:33 AM <dylan> ?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?,?)   ORDER BY sortkey, name
12:33 AM <dylan> a bunch of times
12:34 AM <martianwars> 141 times :O
12:34 AM <dylan> 400ms
12:35 AM <martianwars> yup, 540ms for my file
12:35 AM <martianwars> so where can I start looking for this query/
12:35 AM <dylan> we have our own horrible in-house ORM
12:36 AM <dylan> to find that one though
12:36 AM <dylan> I'm going to look at:
12:36 AM <dylan> http://people.mozilla.org/~dhardison/1021795/martianwars/index-subs-excl.html
12:37 AM <dylan> and see which sub is called about that many times
12:37 AM <dylan> "about"
12:37 AM <dylan> so
12:37 AM <dylan> http://people.mozilla.org/~dhardison/1021795/martianwars/Bugzilla-FlagType-pm-368-line.html#609
12:38 AM <martianwars> FlagType haha :P
12:38 AM <dylan> it has its own match()
12:38 AM <dylan>  return Bugzilla::FlagType->new_from_list($flagtype_ids);
12:39 AM <dylan> alright, eventually we should memcache those
12:39 AM <dylan> but we can get a gain right now by using the request cache
12:40 AM <dylan> which is just a hash in Bugzilla->request_cache
12:41 AM <martianwars> so we store the query results in a cache before we return? 
12:41 AM <martianwars> i didn't get what exactly request_cache is
12:41 AM <dylan> my $rc = Bugzilla->request_cache; # a my var is faster than calling this multiple times
12:43 AM <dylan> my @uncached_flagtype_ids = grep { ! $rc->{flagtype_cache}{$_} } @$flagtype_ids;
12:44 AM <dylan> foreach my $flagtype (@{ Bugzilla::FlagType->new_from_list($flagtype_ids) }) {
12:45 AM <dylan> $rc->{flagtype_cache}{$flagtype->id} = $flagtype;
12:45 AM <dylan> }
12:45 AM <dylan> return [ map { $rc->{flagtype_cache}{$_} } @$flagtype_ids;
12:45 AM <dylan> }
12:45 AM <dylan> something like that
12:45 AM <dylan> maybe
12:46 AM <dylan> er
12:46 AM <dylan> Bugzilla::FlagType->new_from_list(\@uncached_flagtype_ids);
12:49 AM <dylan> I also see another win possible in http://people.mozilla.org/~dhardison/1021795/martianwars/Bugzilla-Component-pm-416-line.html#376
12:49 AM <dylan> but for much smaller values of win

Comment 19

[Kalpesh Krishna [:martianwars]]

I think I will un-assign myself once the first PR is okay. Might get back to this someday later! :)

Comment 20

[Dylan Hardison [:dylan] (he/him)]

Comment on attachment 8769747 [details] [review]
enter_bug fux

Moving review of the patch to Bug 1294478

Comment 21

[Ed Morley [:emorley]]

I believe bug 1294478 should now be in production.

Unfortunately there doesn't seem to be any difference in load time for:
https://bugzilla.mozilla.org/enter_bug.cgi?form_name=enter_bug&product=Core

(If anything it's 0.5-1.0s slower than comment 0, but perhaps more flags have been added since then)

Comment 22

[Dylan Hardison [:dylan] (he/him)]

more flags and also more load on the servers. That's why this bug is still open. 

There are two avenues (both of which are going to be explored):

1) memcache the data that goes into the json structure from bug 1294478
2) decrease the number of sql queries (currently ~2100)

Comment 24

[Dylan Hardison [:dylan] (he/him)]

Comment on attachment 8769747 [details] [review]
enter_bug fux

Step 1 will be fixing up the code that generates the metadata to be in perl-land rather than a template, and step 2 is caching this as configuration data in memcached, keyed by the unique set of groups a user belongs to.

Comment 25

[Jeff Muizelaar [:jrmuizel]]

(In reply to Dylan Hardison [:dylan] from comment #22)
> 
> 1) memcache the data that goes into the json structure from bug 1294478
> 2) decrease the number of sql queries (currently ~2100)

2100 seems like a very high number. Do you have some idea what these are all doing?

Comment 26

[Dylan Hardison [:dylan] (he/him)]

(In reply to Jeff Muizelaar [:jrmuizel] from comment #25)
> (In reply to Dylan Hardison [:dylan] from comment #22)
> > 
> > 1) memcache the data that goes into the json structure from bug 1294478
> > 2) decrease the number of sql queries (currently ~2100)
> 
> 2100 seems like a very high number. Do you have some idea what these are all
> doing?

Yes, it's related to number of tracking flags + other flags + components in the core product.
In addition it builds a giant JSON string using a templating system rather than our (C-based) JSON encoder
(although this way less overheard than all the sql queries). 

Short term (this bug) I'm going to shortcut the SQL queries using our caching system; 
longer term this will be fixed by redoing the enter_bug page to not require as many field values up front.

Comment 27

[Dylan Hardison [:dylan] (he/him)]

Attachment: patch1 v1

micro-patches are a thing, right? 

Rather than do all the changes up front and give dkl a giant patch to review, I can break it up into pieces (and hopefully get other tasks done)

Here is a patch that shaves off 300ms in testing, and probably more like 500ms in production. Because the Review extension blocks reviews, anyone that is a suggested reviewer has to have their "blocking reviews" setting checked. For core this is a lot of people.

We already cache all the user settings, but because of a bug in the previous memcached code we never stored objects. There is no reason to not store objects directly in memcached, so this patch does that.

My benchmarks are here:

Pre-patch: http://people.mozilla.org/~dhardison/1021795/patch1/enter_bug.nytprof/
Post-patch: http://people.mozilla.org/~dhardison/1021795/patch1/enter_bug2.nytprof/

Comment 28

[Dylan Hardison [:dylan] (he/him)]

patch2 will focus on Bugzilla::Product::flag_types

Comment 29

[David Lawrence [:dkl]]

Comment on attachment 8805626 [details] [diff] [review]
patch1 v1

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

r=dkl

::: Bugzilla/User/Setting.pm
@@ +180,5 @@
>  
> +    my $cache_key = "user_settings_all.$user_id";
> +    my $settings = Bugzilla->memcached->get_config({ key => $cache_key });
> +    return $settings if $settings;
> +    

whitespace

Comment 30

[Ed Morley [:emorley]]

I see one of the BMO OKRs [1] is:
"[Improve] worst bug-entry page-load time"

Does that mean ~this bug? :-)

Comment 31

[Ed Morley [:emorley]]

[1] https://wiki.mozilla.org/BMO/Meetings/2017-02-07#OKRs

Comment 32

[Mark Côté [:mcote]]

(In reply to Ed Morley [:emorley] from comment #30)
> I see one of the BMO OKRs [1] is:
> "[Improve] worst bug-entry page-load time"
> 
> Does that mean ~this bug? :-)

Yes. :)

Comment 33

[Jeff Muizelaar [:jrmuizel]]

enter_bug.cgi load times seem to have gotten worse lately. I got load times of 14.44 seconds now.

Comment 34

[Dylan Hardison [:dylan] (he/him)]

Some of this is because we've been under increased load (yesterday, we served more than 5 million requests, mostly because of someone trying to download every bug ever...)

In the short term, I'll see if there's any low-hanging fruit to optimize.
Longer term -- we have a student rewriting the enter bug as part of Google Summer of Code.

The best part is the student's plan is incremental and there should be at least a bare-bones new enter bug page early in the GSoC period (fingers crossed).