New issue
Advanced search Search tips
Note: Color blocks (like or ) mean that a user may not be available. Tooltip shows the reason.

Issue 753394 link

Starred by 5 users

Issue metadata

Status: Fixed
Owner:
Last visit > 30 days ago
Closed: Sep 2017
Cc:
Components:
EstimatedDays: ----
NextAction: ----
OS: ----
Pri: 1
Type: Bug



Sign in to add a comment

AFE Slow queries killed looking for "android\\_wifi\\_tel\\_coex"

Project Member Reported by dgarr...@chromium.org, Aug 8 2017

Issue description

https://groups.google.com/a/google.com/forum/#!topic/chromeos-build-alerts/2hsOHm4n3V0%5B1-25%5D

We are regularly killing slow AFE queries. We should know where they are coming from, and should either not run those queries, or optimize them.
 
Although I tend to often chase slow db queries (so does phobbs@), I'm not the de-facto owner of these things.
Please put on triage queue.

FYI: looking at some the latest queries on that list:

Info: SELECT COUNT(DISTINCT `afe_jobs`.`id`) FROM `afe_jobs` WHERE 
(`afe_jobs`.`owner` = 'chromeos-test'  AND `afe_jobs`.`created_on` > 
'2017-06-01 00:00:00'  AND `afe_jobs`.`name` LIKE 
'%power\\_BatteryCharge%'  AND `afe_jobs`.`created_on` < '2017-08-08 
00:00:00' 


Info: SELECT DISTINCT `afe_jobs`.`id`, `afe_jobs`.`owner`, 
`afe_jobs`.`name`, `afe_jobs`.`priority`, `afe_jobs`.`control_file`, 
`afe_jobs`.`control_type`, `afe_jobs`.`created_on`, 
`afe_jobs`.`synch_count`, `afe_jobs`.`timeout`, 
`afe_jobs`.`run_verify`, `afe_jobs`.`email_list`, 
`afe_jobs`.`reboot_before`, `afe_jobs`.`reboot_after`, 
`afe_jobs`.`parse_failed_repair`, `afe_jobs`.`max_runtime_hrs`, 
`afe_jobs`.`max_runtime_mins`, `afe_jobs`.`drone_set_id`, 
`afe_jobs`.`parameterized_job_id`, `afe_jobs`.`parent_job_id`, 
`afe_jobs`.`test_retry`, `afe_jobs`.`run_reset`, 
`afe_jobs`.`timeout_mins`, `afe_jobs`.`shard_id`, 
`afe_jobs`.`require_ssp` FROM `afe_jobs` WHERE (`afe_jobs`.`owner` = 
'chromeos-test'  AND `afe_jobs`.`created_on` > '2017-06-01 00:00:00' 
AND `afe_jobs`.`name` LIKE '%power\\_BatteryCharge%'  AND 
`afe_jobs`.`created_on` < '2017-08-08 00:00:00' ) ORDER BY 
`afe_jobs`.`created_on` DESC LIMIT 30 


Two points here: https://chromium-review.googlesource.com/c/558669 made the second query start sorting by created_on, which alleviated problems this class of queries was causing.
- Looks like it's still slow
- Looks like the count(*) query run just before the data query still isn't using the correct sorting (and hence the correct index)


(1) adding 'order by created_on' to the first query doesn't change anything (still uses owner_index)

mysql> explain SELECT COUNT(DISTINCT `afe_jobs`.`id`) FROM `afe_jobs` WHERE  (`afe_jobs`.`owner` = 'chromeos-test'  AND `afe_jobs`.`created_on` >  '2017-06-01 00:00:00'  AND `afe_jobs`.`name` LIKE  '%power\\_BatteryCharge%'  AND `afe_jobs`.`created_on` < '2017-08-08 
00:00:00');
+----+-------------+----------+------+------------------------+-------------+---------+-------+----------+-------------+
| id | select_type | table    | type | possible_keys          | key         | key_len | ref   | rows     | Extra       |
+----+-------------+----------+------+------------------------+-------------+---------+-------+----------+-------------+
|  1 | SIMPLE      | afe_jobs | ref  | created_on,owner_index | owner_index | 258     | const | 17004478 | Using where |
+----+-------------+----------+------+------------------------+-------------+---------+-------+----------+-------------+
1 row in set (0.00 sec)

mysql> explain SELECT COUNT(DISTINCT `afe_jobs`.`id`) FROM `afe_jobs` WHERE  (`afe_jobs`.`owner` = 'chromeos-test'  AND `afe_jobs`.`created_on` >  '2017-06-01 00:00:00'  AND `afe_jobs`.`name` LIKE  '%power\\_BatteryCharge%'  AND `afe_jobs`.`created_on` < '2017-08-08 
00:00:00') order by afe_jobs.created_on;
+----+-------------+----------+------+------------------------+-------------+---------+-------+----------+-------------+
| id | select_type | table    | type | possible_keys          | key         | key_len | ref   | rows     | Extra       |
+----+-------------+----------+------+------------------------+-------------+---------+-------+----------+-------------+
|  1 | SIMPLE      | afe_jobs | ref  | created_on,owner_index | owner_index | 258     | const | 17004480 | Using where |
+----+-------------+----------+------+------------------------+-------------+---------+-------+----------+-------------+
1 row in set (0.01 sec)


(2) This query takes forever. This means issue 685424 isn't yet completely solved (we moved from using PRIMARY index to using owner_id index. But owner_id index is useless for most queries -- most of our jobs are run by 'chromeos-test').



(3) I can't even hint to mysql to use the created_on index -- it decides to not use any if I try to force it:
mysql> explain SELECT COUNT(DISTINCT `afe_jobs`.`id`) FROM `afe_jobs` USE INDEX (created_on) WHERE  (`afe_jobs`.`owner` = 'chromeos-test'  AND `afe_jobs`.`created_on` >  '2017-06-01 00:00:00'  AND `afe_jobs`.`name` LIKE  '%power\\_BatteryCharge%'  AND `afe_jobs`.`created_on` < '2017-08-08 
00:00:00') order by afe_jobs.created_on;
+----+-------------+----------+------+---------------+------+---------+------+----------+-------------+
| id | select_type | table    | type | possible_keys | key  | key_len | ref  | rows     | Extra       |
+----+-------------+----------+------+---------------+------+---------+------+----------+-------------+
|  1 | SIMPLE      | afe_jobs | ALL  | created_on    | NULL | NULL    | NULL | 34009495 | Using where |
+----+-------------+----------+------+---------------+------+---------+------+----------+-------------+
1 row in set (0.01 sec)



The problem is that range-scan on the created_on index doesn't like to mix with any other WHERE clauses:

mysql> explain SELECT COUNT(DISTINCT `afe_jobs`.`id`) FROM `afe_jobs` USE INDEX (created_on) WHERE  (`afe_jobs`.`owner` = 'chromeos-test'  AND `afe_jobs`.`created_on` >  '2017-06-01 00:00:00'  AND `afe_jobs`.`name` LIKE  '%power\\_BatteryCharge%'  AND `afe_jobs`.`created_on` < '2017-08-08 
00:00:00') order by afe_jobs.created_on;
+----+-------------+----------+------+---------------+------+---------+------+----------+-------------+
| id | select_type | table    | type | possible_keys | key  | key_len | ref  | rows     | Extra       |
+----+-------------+----------+------+---------------+------+---------+------+----------+-------------+
|  1 | SIMPLE      | afe_jobs | ALL  | created_on    | NULL | NULL    | NULL | 34009495 | Using where |
+----+-------------+----------+------+---------------+------+---------+------+----------+-------------+
1 row in set (0.01 sec)
Last comment was incomplete: The crated_on index is used as expected when used standalone:

mysql> explain SELECT COUNT(DISTINCT `afe_jobs`.`id`) FROM `afe_jobs` WHERE  (`afe_jobs`.`created_on` BETWEEN '2017-06-01 00:00:00' AND '2017-08-08 00:00:00') order by afe_jobs.created_on;+----+-------------+----------+-------+---------------+------------+---------+------+----------+--------------------------+
| id | select_type | table    | type  | possible_keys | key        | key_len | ref  | rows     | Extra                    |
+----+-------------+----------+-------+---------------+------------+---------+------+----------+--------------------------+
|  1 | SIMPLE      | afe_jobs | range | created_on    | created_on | 9       | NULL | 17004980 | Using where; Using index |
+----+-------------+----------+-------+---------------+------------+---------+------+----------+--------------------------+
1 row in set (0.00 sec)

Issue 685424 has been merged into this issue.
Labels: -Pri-3 Pri-1
Owner: pho...@chromium.org
Status: Assigned (was: Untriaged)
Assigned to phobbs@ because this is a continuation of an issue (we thought) he fixed ;)

+ transferring priority from that issue.
There seems to be no way to cajole mysql into using an index for range scan from a different column as long as (`afe_jobs`.`name` LIKE  '%power\\_BatteryCharge%') is in the WHERE clause.

Note that if we were doing prefix matching, name_index would get used instead:
mysql> explain SELECT COUNT(DISTINCT `afe_jobs`.`id`) FROM `afe_jobs` WHERE  (afe_jobs.id < 133584994 AND afe_jobs.id > 120722443 AND `afe_jobs`.`name` LIKE  'power\\_BatteryCharge%');
+----+-------------+----------+-------+--------------------+------------+---------+------+------+--------------------------+
| id | select_type | table    | type  | possible_keys      | key        | key_len | ref  | rows | Extra                    |
+----+-------------+----------+-------+--------------------+------------+---------+------+------+--------------------------+
|  1 | SIMPLE      | afe_jobs | range | PRIMARY,name_index | name_index | 258     | NULL |    1 | Using where; Using index |
+----+-------------+----------+-------+--------------------+------------+---------+------+------+--------------------------+


Dunno if we even want this / it's possible (do we really need infix matching from the job page? or just prefix matching?)
Cc: pprabhu@chromium.org
Cc: dshi@chromium.org jrbarnette@chromium.org
The reason "USE INDEX" is not working is because it is a hint, and MySQL's optimizer is ignoring the hint. If you really want to force the usage of an index, you have to tell it "FORCE INDEX":

mysql> explain SELECT COUNT(DISTINCT `afe_jobs`.`id`) FROM `afe_jobs` USE INDEX (created_on) WHERE  (`afe_jobs`.`owner` = 'chromeos-test'  AND `afe_jobs`.`created_on` >  '2017-06-01 00:00:00'  AND `afe_jobs`.`name` LIKE  '%power\\_BatteryCharge%'  AND `afe_jobs`.`created_on` < '2017-08-08 
    '> 00:00:00') order by afe_jobs.created_on;
+----+-------------+----------+------+---------------+------+---------+------+----------+-------------+
| id | select_type | table    | type | possible_keys | key  | key_len | ref  | rows     | Extra       |
+----+-------------+----------+------+---------------+------+---------+------+----------+-------------+
|  1 | SIMPLE      | afe_jobs | ALL  | created_on    | NULL | NULL    | NULL | 33338960 | Using where |
+----+-------------+----------+------+---------------+------+---------+------+----------+-------------+
1 row in set (0.00 sec)

mysql> explain SELECT COUNT(DISTINCT `afe_jobs`.`id`) FROM `afe_jobs` FORCE INDEX (created_on) WHERE  (`afe_jobs`.`owner` = 'chromeos-test'  AND `afe_jobs`.`created_on` >  '2017-06-01 00:00:00'  AND `afe_jobs`.`name` LIKE  '%power\\_BatteryCharge%'  AND `afe_jobs`.`created_on` < '2017-08-08 
00:00:00') order by afe_jobs.created_on;
+----+-------------+----------+-------+---------------+------------+---------+------+----------+-------------+
| id | select_type | table    | type  | possible_keys | key        | key_len | ref  | rows     | Extra       |
+----+-------------+----------+-------+---------------+------------+---------+------+----------+-------------+
|  1 | SIMPLE      | afe_jobs | range | created_on    | created_on | 9       | NULL | 16669492 | Using where |
+----+-------------+----------+-------+---------------+------------+---------+------+----------+-------------+
1 row in set (0.00 sec)


It actually kinda makes sense to not use an index in this case. The MySQL engine is comparing
 -  using the index: scan 16.7 million index rows and fetching 16.7 million
    main table rows individually, which may not be cache-efficient (for
    all it knows, there is absolutely no correspondence between primary key
    and the created_on column)
 -  linear-scanning 33 million rows in the main table, which is going
    to be cache-efficient and very fast.

The problem here is that 2017-06-01 < created_on < 2017-08-08 is a massive time range and is pretty much useless for narrowing down the search space.

I think #6 is the way to go to optimize the second query. The reason it takes so long (even with an index) is it needs to scan 16.6 million rows to find a name pattern which is extremely rare. The correct solution is to use the name index.

I have no idea whether we actually use the infix matching or whether prefix matching would be good enough - can dshi@ or jrbarnette@ comment?



Labels: Chase-Pending
Also, that issue was Chase. Putting this back on the same queue.
Labels: -Chase-Pending Chase
Restrict created_on ranges to small enough range that these queries are affordable.
Status: Started (was: Assigned)
CL is in code review.
Project Member

Comment 12 by bugdroid1@chromium.org, Aug 22 2017

The following revision refers to this bug:
  https://chromium.googlesource.com/chromiumos/third_party/autotest/+/4442d6fb2c7fa950a49aad4c38402003dc4eb484

commit 4442d6fb2c7fa950a49aad4c38402003dc4eb484
Author: Paul Hobbs <phobbs@google.com>
Date: Tue Aug 22 12:08:48 2017

[autotest] Ui: Add 2 week date restriction.

Add a 2 week date restriction to the datetime-local input box for JobListView and HostDetailView.

WIP; Needs manual testing still.

BUG= chromium:753394 
TEST=None

Change-Id: If4197c795687b0886cf167443c5a4dd35c8a7461
Reviewed-on: https://chromium-review.googlesource.com/617928
Commit-Ready: Paul Hobbs <phobbs@google.com>
Tested-by: Paul Hobbs <phobbs@google.com>
Reviewed-by: Paul Hobbs <phobbs@google.com>

[modify] https://crrev.com/4442d6fb2c7fa950a49aad4c38402003dc4eb484/frontend/client/src/autotest/common/table/DatetimeSegmentFilter.java
[modify] https://crrev.com/4442d6fb2c7fa950a49aad4c38402003dc4eb484/frontend/client/src/autotest/common/ui/DateTimeBox.java

This almost works, but not quite. It adds the 2 week date restriction only after the end time is changed for the first time. You can still make a query with longer than 2 weeks duration by changing the start date without touching the end date.
Adding 2-week date restriction, landing soon.
Project Member

Comment 15 by bugdroid1@chromium.org, Aug 28 2017

The following revision refers to this bug:
  https://chromium.googlesource.com/chromiumos/third_party/autotest/+/a58c18bf8bd47c8ce525d3186d1f2f8bf6d59c89

commit a58c18bf8bd47c8ce525d3186d1f2f8bf6d59c89
Author: Paul Hobbs <phobbs@google.com>
Date: Mon Aug 28 21:25:48 2017

[autotest] ui: Add date constraint on page load

Add a 2-week constraint on the date range as soon
as the page loads, instead of only after the first
change to the endDate.

Factor out the value change handler code which
updates the start date constraint upon changing
the end date.

BUG= chromium:753394 
TEST=tested manually on chromeos-autotest.hot

Change-Id: Id164aa623afa59560114b9a97365d4ff4a83aeb1
Reviewed-on: https://chromium-review.googlesource.com/636515
Reviewed-by: Paul Hobbs <phobbs@google.com>
Commit-Queue: Paul Hobbs <phobbs@google.com>
Tested-by: Paul Hobbs <phobbs@google.com>

[modify] https://crrev.com/a58c18bf8bd47c8ce525d3186d1f2f8bf6d59c89/frontend/client/src/autotest/common/table/DatetimeSegmentFilter.java

Status: Fixed (was: Started)

Sign in to add a comment