The stored procedure has been running for 20 minutes now, deleting 5k records at a time older than 2017-07-28.

mysql> select count(*) from tko_jobs where started_time<"2017-07-28";
+----------+
| count(*) |
+----------+
| 45398078 |


Deleting these 5k at a time is going to take a long long time.

mysql> show create procedure remove_old_tests_sp;
+---------------------+------------------------+------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+----------------------+----------------------+--------------------+
| Procedure           | sql_mode               | Create Procedure                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                 | character_set_client | collation_connection | Database Collation |
+---------------------+------------------------+------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+----------------------+----------------------+--------------------+
| remove_old_tests_sp | NO_ENGINE_SUBSTITUTION | CREATE DEFINER=`cros-infra-admin`@`%` PROCEDURE `remove_old_tests_sp`()
BEGIN
  
  
  SET @cutoff_date = DATE_SUB(CURDATE(),INTERVAL 180 day);

  WHILE EXISTS (select * from tko_tests where started_time<@cutoff_date limit 1) DO
    BEGIN
      SELECT concat("Deleting 5k records in tko_tests older than ", @cutoff_date);
      DELETE FROM tko_tests where started_time<@cutoff_date limit 5000;
      SELECT SLEEP(5);
    END;
  END WHILE;

  
  
  
  WHILE EXISTS (select * from tko_tests where started_time is NULL and finished_time<@cutoff_date limit 1) DO
    BEGIN
      SELECT concat("Deleting 5k records in tko_tests with finished time older than ", @cutoff_date);
      DELETE FROM tko_tests where started_time is NULL and finished_time<@cutoff_date limit 5000;
      SELECT SLEEP(5);
    END;
  END WHILE;

  
  
  
  
  SET @cutoff_date = DATE_SUB(@cutoff_date,INTERVAL 5 day);
  WHILE EXISTS (select * from tko_jobs where started_time<@cutoff_date limit 1) DO
    BEGIN
      SELECT concat("Deleting 5k records in tko_jobs older than ", @cutoff_date);
      DELETE FROM tko_jobs where started_time<@cutoff_date limit 5000;
      SELECT SLEEP(5);
    END;
  END WHILE;
END | utf8                 | utf8_general_ci      | utf8_general_ci    |
+---------------------+------------------------+------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+----------------------+----------------------+--------------------+
1 row in set (0.13 sec)

The stored procedure deletes 5k records at a time, each round taking roughly 30s. At that rate, it will take about 75 hours to catch up to the backlog of 45398078 stale results.

75 hours is not too bad. The 5 seconds pause is added for reducing impact on production. Deleting records in tko is a slow process.

I'm going to leave that stored procedure open and running for a few days, while pursuing other investigations.

Does these deletion actually free up space in the db though, or do we need to do a slow table optimize / reclaim step afterward?

It depends on the table layout. At one point, mysql might decide to shrink the table file to release space. anyhow, new records will be written to the space released by the deleted records. so we shouldn't see additional usage of the space for the new record. tko_test_attributes will still keep increasing, as it's a new table.

Note that 45398078 is only for that first query set.

There are also lots of stale tko_jobs:

mysql> select count(*) from tko_jobs where started_time<"2017-07-23";
+----------+
| count(*) |
+----------+
| 44298633 |
+----------+

(the third loop of the stored proc is supposed to clean these)

And still trying to calculate the number of null-start stale tko_tests; The select count is very slow to return;

Actions:
1) Wait for the manual invocation of the record cleanup to finish (estimated at least 90 hours from now; possible more).
2) Evaluate whether these cleanups actually result in freed space on tko.
3) Investigate why the procedure wasn't actually being properly invoked by cleanup_tko_db and fix.

For that 2nd loop, finally determined the number of entries.

select count(*) from tko_tests where started_time is NULL and finished_time<"2017-07-28";
+----------+
| count(*) |
+----------+
|   823434 |
+----------+
1 row in set (56 min 58.36 sec)

It took an hour just to calculate this. The query to delete 5k records is running quite slowly as well.

Do we have the requisite indicies to make this query perform?

mysql> show indexes from tko_tests;
+-----------+------------+----------------------+--------------+----------------------+-----------+-------------+----------+--------+------+------------+---------+---------------+
| Table     | Non_unique | Key_name             | Seq_in_index | Column_name          | Collation | Cardinality | Sub_part | Packed | Null | Index_type | Comment | Index_comment |
+-----------+------------+----------------------+--------------+----------------------+-----------+-------------+----------+--------+------+------------+---------+---------------+
| tko_tests |          0 | PRIMARY              |            1 | test_idx             | A         |    98256478 |     NULL | NULL   |      | BTREE      |         |               |
| tko_tests |          1 | kernel_idx           |            1 | kernel_idx           | A         |       47535 |     NULL | NULL   |      | BTREE      |         |               |
| tko_tests |          1 | status               |            1 | status               | A         |        1734 |     NULL | NULL   |      | BTREE      |         |               |
| tko_tests |          1 | machine_idx          |            1 | machine_idx          | A         |       78794 |     NULL | NULL   |      | BTREE      |         |               |
| tko_tests |          1 | job_idx              |            1 | job_idx              | A         |    98256478 |     NULL | NULL   |      | BTREE      |         |               |
| tko_tests |          1 | reason               |            1 | reason               | A         |     2585696 |      767 | NULL   | YES  | BTREE      |         |               |
| tko_tests |          1 | test                 |            1 | test                 | A         |     1155958 |     NULL | NULL   | YES  | BTREE      |         |               |
| tko_tests |          1 | subdir               |            1 | subdir               | A         |    98256478 |     NULL | NULL   | YES  | BTREE      |         |               |
| tko_tests |          1 | started_time         |            1 | started_time         | A         |    32752159 |     NULL | NULL   | YES  | BTREE      |         |               |
| tko_tests |          1 | invalidates_test_idx |            1 | invalidates_test_idx | A         |     2456411 |     NULL | NULL   | YES  | BTREE      |         |               |
| tko_tests |          1 | finished_time_idx    |            1 | finished_time        | A         |    98256478 |     NULL | NULL   | YES  | BTREE      |         |               |
+-----------+------------+----------------------+--------------+----------------------+-----------+-------------+----------+--------+------+------------+---------+---------------+
11 rows in set (0.12 sec)

mysql> DELETE FROM tko_tests where started_time is NULL and finished_time<2017-07-28 limit 5000;                                                                                                                  

Query OK, 0 rows affected, 2 warnings (49 min 57.71 sec)

It took 50 minutes for one cycle of the query that would be in that second loop. That's no good.

Fishing around in /var/log/cleanup_tko.log is looks to me like the last time the script ran correctly was in April 2017.

04/10 06:53:59.204 INFO |    cleanup_tko_db:0063| Start cleaning up old records in TKO database chromeos_autotest_db on server 173.194.109.7.
04/10 07:49:08.206 INFO |    cleanup_tko_db:0074| Cleanup finished in 3308.99874997 seconds.
04/11 06:50:18.668 INFO |    cleanup_tko_db:0063| Start cleaning up old records in TKO database chromeos_autotest_db on server 173.194.109.7.
04/11 06:50:18.669 INFO |    cleanup_tko_db:0074| Cleanup finished in 9.05990600586e-06 seconds.

On April 10 2017 we had a prod push autotest range 75ed007b..ec125511b

That push included this CL which touched run_sql_cmd, a method used by the cleanup script.

commit 2c32d6b593c4987a525ef162d6704fa6d6d7c0b0
Author: Allen Li <ayatane@chromium.org>
Date:   Fri Feb 3 15:28:10 2017 -0800

    [autotest] Merge client/bin/site_utils
    
    BUG= chromium:672727 
    TEST=None
    
    Change-Id: I03a05a3ae3163437109010106ad988ff101a3998
    Reviewed-on: https://chromium-review.googlesource.com/437589
    Commit-Ready: Allen Li <ayatane@chromium.org>
    Tested-by: Allen Li <ayatane@chromium.org>
    Reviewed-by: Allen Li <ayatane@chromium.org>

Indeed, ^ broke the cleanup script. Fix at https://chromium-review.googlesource.com/c/chromiumos/third_party/autotest/+/884903

RE #13

That query is going to be way too slow. However, a simpler query:

mysql> select count(*) from tko_tests where started_time is NULL;

+----------+
| count(*) |
+----------+
|   837620 |
+----------+
1 row in set (31.04 sec)


returns in a reasonable time (compared to #11) and only shows a few more entries compared to the result from #11 (823434).

I propose we just delete all entries with started_time of Null, at least to get the cleanup script back to reasonable performance. We'll lose only a small number of newer entries, and started_time Null entries are probably not that important anyway (what are these? aborted jobs?).

mysql> delete from tko_tests WHERE started_time is NULL LIMIT 5000;
Query OK, 5000 rows affected (42.29 sec)

This is fast enough.

dshi@ with your blessing I will run the query from #19 in a loop (separately from the cleanup script) so that by the time the real cleanup script catches up to that second loop it actually has a chance of completing in reasonable time.

I can't recall the details about tko tests with starttime being null. Aborted test is certainly one condition.

Delete these records first should be fine. So the later query will be more efficient. We can split out the null check and older time check into two queries.

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

commit f57a0b2592e54ddea6b231e0130030dc7575e585
Author: Aviv Keshet <akeshet@chromium.org>
Date: Thu Jan 25 06:33:14 2018

autotest: cleanup_tko_db: fix metrics so they actually get emitted

BUG= chromium:805580 
TEST=None

Change-Id: Ia4c232fea69444019a2920b2d5603c861ad2db3b
Reviewed-on: https://chromium-review.googlesource.com/884108
Commit-Ready: Aviv Keshet <akeshet@chromium.org>
Tested-by: Aviv Keshet <akeshet@chromium.org>
Reviewed-by: Dan Shi <dshi@google.com>

[modify] https://crrev.com/f57a0b2592e54ddea6b231e0130030dc7575e585/site_utils/cleanup_tko_db.py

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

commit b39504422f5ad03eaaa978b7e2f41f31556a5ea6
Author: Aviv Keshet <akeshet@chromium.org>
Date: Thu Jan 25 08:15:43 2018

autotest: utils: make run_sql_cmd actually run sql commands

BUG= chromium:805580 
TEST=None

Change-Id: I473a6332c91583103ce56ee6b88fb03b5abd3130
Reviewed-on: https://chromium-review.googlesource.com/884903
Commit-Ready: Aviv Keshet <akeshet@chromium.org>
Tested-by: Aviv Keshet <akeshet@chromium.org>
Reviewed-by: Allen Li <ayatane@chromium.org>

[modify] https://crrev.com/b39504422f5ad03eaaa978b7e2f41f31556a5ea6/client/bin/utils.py

After about 10 hours of running, the stored procudure crashed (due to disconnection from mysql instance I think). I've started it back up again.

Seems like it might take some occasional babysitting to make sure it is able to run for the requisite 90ish hours.

I got overzealous with "DELETE FROM tko_tests where started_time is NULL" and caused Issue 806019 tko query pileup. Ooops. Will be more careful.

The script is fixed, but the fix is not yet pushed. I'm babysitting the backlog cleanup. Holding open as P1 for now.

Last cleanup loop failed after 19 hours. Restarting it now. There's probably still many hours of cleanup script remaining.

It's tricky to estimate progress on this, but assuming that select * ... limit is preferentually picking things up at the beginning of the table, then:

mysql> select started_time from tko_tests limit 20;
+---------------------+
| started_time        |
+---------------------+
| NULL                |
| NULL                |
| NULL                |
| NULL                |
| NULL                |
| NULL                |
| NULL                |
| 2017-03-21 23:19:41 |
| 2017-03-21 23:19:41 |
| 2017-03-21 23:19:41 |
| 2017-03-21 23:19:41 |
| 2017-03-21 23:19:41 |
| 2017-03-21 23:19:41 |
| 2017-03-21 23:19:41 |
| 2017-03-21 23:19:41 |
| 2017-03-21 23:19:41 |
| 2017-03-21 23:19:41 |
| 2017-03-21 23:19:41 |
| 2017-03-21 23:19:42 |
| 2017-03-21 23:19:42 |
+---------------------+
20 rows in set (0.48 sec)


We are still cleaning up tko_tests from 2017-02-21. Based on trying this query a few times, every minute of real cleaning time seems to clean up about an hour worth of data.

So, we probably have about 50 hours of cleanup to go just for this table.

The cleanup script is now running properly after push to prod, so I no longer intend to closely babysit it. It is still far behind, however, I expect it needs a few more days to catch up.

Cleanup is finally passed the first two loops (tko_tests) and is now on to the final 3rd loop for cleaning up tko_jobs. I estimate 20 hours of cleanup remain.

We are caught up on backlog, finally. The automated cleanup job dropped the following logs:

02/04 06:52:45.690 INFO |    cleanup_tko_db:0066| Starting cleaning up old records in TKO database chromeos_autotest_db on server 173.194.109.7.
02/04 06:52:45.762 NOTIC|      cros_logging:0038| ts_mon was set up.
02/04 11:13:17.372 INFO |    cleanup_tko_db:0079| Cleanup attempt finished in 15631.6800089 seconds.
02/04 11:13:17.373 INFO |     ts_mon_config:0207| Waiting for ts_mon flushing process to finish...
02/04 11:13:17.381 INFO |            client:0570| Attempting refresh to obtain initial access_token
02/04 11:13:17.479 INFO |            client:0872| Refreshing access_token
02/04 11:13:17.889 INFO |     ts_mon_config:0213| Finished waiting for ts_mon process.

Still pending: 
 - add proper monitoring / alerting so such an outage doesn't go undetected again
 - actually reclaim the disk space from deleted rows

Relevant metric being emitted by the script. https://pcon.corp.google.com/p#chrome-infra/queryplayground?yAxisMin=0&yAxisMin2=0&oldHeatmap=false&query=CAEY9wOKAW4KWwgPelcKVTJTChltb25hcmNoLmFjcXVpc2l0aW9ucy5UYXNrEjYKNC9jaHJvbWUvaW5mcmEvY2hyb21lb3MvYXV0b3Rlc3QvdGtvL2NsZWFudXBfZHVyYXRpb24ggJiavAQqAiABMIDAjofNEZIBDAoGCAEYoI0GEgBgAA&names=Query%201&unitconversion=hours&duration=1w

We should ensure that:
 - we get time intervals in a sensible range (neither too low nor too high)
 - we get a high enough success rate (e.g. a few per week)

Both should be determinable from this metric.

A new alert pending in https://critique.corp.google.com/#review/184543641 

Still need to add one for time interval as well.

https://pantheon.corp.google.com/sql/instances/tko/overview?project=google.com:chromeos-lab&duration=P7D suggests that the cleanup is actually now working at preventing further unbounded growth in disk usage (usage has not climbed appreciably in the last ~day.