364237 - With 345 products, query.cgi is currently much slower than 2.22.1+

Status: RESOLVED FIXED

(Bugzilla :: Bugzilla-General, defect)

Description

[Olav Vitters]

In 2.23.3+ query.cgi is much slower when you have a large amount of products (345). The performance difference is very noticeable when comparing to 2.22.2 (with same amount of products and product related information).

Time information from 2.22.2:
2.08user 0.17system 0:07.62elapsed 29%CPU (0avgtext+0avgdata 0maxresident)k
0inputs+0outputs (32major+4339minor)pagefaults 0swaps

after running query.cgi a few times:
1.95user 0.11system 0:02.42elapsed 85%CPU (0avgtext+0avgdata 0maxresident)k
0inputs+0outputs (0major+4369minor)pagefaults 0swaps

Time information from 2.23.3+ (not cached):
7.33user 0.71system 0:19.39elapsed 41%CPU (0avgtext+0avgdata 0maxresident)k
0inputs+0outputs (26major+5428minor)pagefaults 0swaps

after running query.cgi a few times:
6.56user 0.53system 0:12.30elapsed 57%CPU (0avgtext+0avgdata 0maxresident)k
0inputs+0outputs (0major+5425minor)pagefaults 0swaps

Note: I do not consider 2.22.2 to be efficient. Total execution time is 5 times slower under 2.23.3 cached; 2.5 times non-cached.

Output from DBI::ProfileDumper will follow.

Comment 1

[Olav Vitters]

Attachment: dbi.prof non-cached from 2.23.3+

Comment 2

[Olav Vitters]

Attachment: dbiprof --number 999 for 2.23.3+ non-cached

Comment 3

[Olav Vitters]

Attachment: dbi.prof non-cached from 2.22.1+

Comment 4

[Olav Vitters]

Attachment: dbiprof --number 999 for 2.22.1+ non-cached

Comment 5

[Max Kanat-Alexander]

Okay, this is becoming a meta bug to track this issue, and the individual slow queries will be handled in separate bugs (most of which have already been filed).

We need to fix:

$product->components
$product->versions
$product->milestones

Comment 6

[Olav Vitters]

Just FYI: Non-cached means it was the first run after I cleared the kernel file cache (echo 3 > /proc/sys/vm/drop_caches) + restarted MySQL (to clear any query cache). Cached means I ran the query.cgi 4 times (times reflect the 5th run). This will make the kernel cache the template files, database files, etc.

Comment 7

[Frédéric Buclin]

Release notes for 2.23.4 should mention progress we did in the perf area, and that any other bottleneck should be reported.

Comment 8

[Olav Vitters]

Attachment: dbiprof --number 50 for 2.23.3+ non-cached

The dbi.log is 211KB, which is a bit big too attach.

Since starting the performance work, the number of queries dropped from 9561 to 2920. The time spent on queries went from 10.8 to 3.5 seconds. There are still some easy gains left.

Comment 9

[Max Kanat-Alexander]

(In reply to comment #8)
> There are still some easy gains left.

  Actually, the only easy gain left is that we shouldn't be calling ->components twice, which would take off 0.4 seconds. That's not a significant enough improvement to do major re-architecture work, but if it's an easy change it's something we can do.

  Other than that, the only significant gain would be to create all products, components, versions, and milestones in a single SQL statement, which would be architecturally too complex to go into 3.0.

  At this point, what are actual "time" results (like you posted in comment 0)?

Comment 10

[Frédéric Buclin]

I think we can now close this meta bug. With the last checkin we just did, the number of DB calls dropped from 9561 earlier this week to 2214 now! 4 times less queries!! About the time spent to query the DB, we went from 10.8 seconds to 2.0 seconds (bkor: tell me if this last value is wrong ;)). 5 times faster!

Definitely a huge progress.

Comment 11

[Olav Vitters]

Attachment: Add pre_cache function to speed it up even more

Probably considered a big hack :)  Adding for interested people.

With this the non-cached case goes to:

1.83user 0.20system 0:07.84elapsed 25%CPU (0avgtext+0avgdata 0maxresident)k
0inputs+0outputs (33major+5299minor)pagefaults 0swaps

150 queries; Total Runtime : 1.077216 seconds

cached case:

1.69user 0.14system 0:02.06elapsed 89%CPU (0avgtext+0avgdata 0maxresident)k
0inputs+0outputs (0major+5333minor)pagefaults 0swaps

still 150 queries; Total Runtime : 0.445682 seconds

The cached case is consistently faster than 2.22 (2.22: 2.4 seconds; patch does it in 2.0-2.1)!

The Bugzilla/User.pm change is not needed actually.

Comment 12

[Max Kanat-Alexander]

I don't think there's actually anything to relnote about this bug, since it was a perf regression we fixed during the development cycle.

Comment 13

[Max Kanat-Alexander]

Added to the release notes on bug 255155.

Comment 14

[Max Kanat-Alexander]

The correct bug number for those release notes is actually bug 349423.