Bug #49264 BACKUP: Huge slowdown while backup triggers
Submitted: 1 Dec 2009 14:28 Modified: 3 Mar 2010 2:09
Reporter: Alexey Stroganov Email Updates:
Status: Closed Impact on me:
None 
Category:MySQL Server: Backup Severity:S2 (Serious)
Version:6.0.14-backup(2894) OS:Any
Assigned to: Thava Alagu
Triage: Triaged: D3 (Medium) / R3 (Medium) / E3 (Medium)

[1 Dec 2009 14:28] Alexey Stroganov
Description:
While tested backup performance of meta-data I've observed huge drop in performance(~80 times) for scenario when database has triggers.

 BACKUP database with 15.000 tables + 15.000 triggers
----------------------------------------------------------
                                           MyISAM| InnoDB|
----------------------------------------------------------
6.0-rev2703                              |   111 |    38 |
----------------------------------------------------------
6.0-rev2894                              |  8611 |  8506 |
----------------------------------------------------------

Further analysis showed that most of the time server spending in 'checking permission stage' while executing following query:

SELECT event_object_table FROM INFORMATION_SCHEMA.TRIGGERS
WHERE trigger_schema = <trigger_schema> AND trigger_name COLLATEutf8_bin = <trigger_name>

Avg exec time of this query ~0.6sec that is very expensive.

I've discussed issue with Sergey Gluhov and he explained that for such query 
we perform following stages:

1. create list of DB 
2. for every db create list of tables 
3. for every table -> open it, check for triggers and if exist put them to tmp table 
4. perform our query with using created tmp table 

And we perform above steps for every trigger.

How to repeat:
- Run backup on database with many triggers
[8 Dec 2009 4:07] Alexey Stroganov
Below are two aspects that I've found and would like to highlight:

1. temporary tables
--------------------

 While I've run the backup test for triggers I've noted that number of created temporary tables(both on disk and in memory) looks significant. Further investigation showed that for every access to I_S.TRIGGERS table that doesn't involve 'pseudo-indexed' fields(EVENT_*) (like query in the issue) server will create 10 tables on disk and 34 in memory. It means that with current approach if one will try to backup 1000 triggers then server will create 10000 on disk and 34000 in memory tables. Although total time spent for creation of these tables is insignificant I think it will be better to avoid it at all as such activity may affect for instance table cache.

We can improve situation by replacing of trigger_schema with event_object_schema as we know for sure database name. Such way we will completely eliminate creation of temporary tables:

SELECT event_object_table FROM INFORMATION_SCHEMA.TRIGGERS
WHERE EVENT_OBJECT_SCHEMA = <trigger_schema> AND trigger_name COLLATEutf8_bin =
<trigger_name>

As backup subsystem now relies on I_S in many cases I've decided to check this aspect for other I_S tables as well by executing of 'select count(*) from INFORMATION_SCHEMA.<table>' and checking values of Created_tmp_disk_tables' and 'Created_tmp_tables'. Below are info for several other I_S tables:
                                        created_tmp_tables
                                         on_disk in_memory
---------------------------------------------------------------
 1                                   EVENTS   1   3
 2                               PARTITIONS  10  34
 3                                 ROUTINES   1   3
 4                                   TABLES   0   3
 5                              TABLESPACES   0   3
 6                                 TRIGGERS  10  34
 7                                    VIEWS  10  34

2. What is slow?
----------------

I've profiled query from issue. We spent most of the time in 'checking permissions' as for every query(trigger) we have to rescan all tables(sql_parse.cc:5124). And in case when we have many tables in backup-ed database it becomes bottleneck. In my case with 15000 of tables execution of query took ~0.6-0.7 sec. 

|       36 |   1 | starting             | 0.000061 |
|       36 |   2 | Opening tables       | 0.000284 |
|       36 |   3 | System lock          | 0.000007 |
|       36 |   4 | init                 | 0.000030 |
|       36 |   5 | optimizing           | 0.000016 |
|       36 |   6 | statistics           | 0.000019 |
|       36 |   7 | preparing            | 0.000015 |
|       36 |   8 | executing            | 0.000052 |
|       36 |   9 | checking permissions | 0.000019 |
|       36 |  10 | Opening tables       | 0.000023 |
|       36 |  11 | removing tmp table   | 0.000012 |

|       36 |  12 | <above Open/remove> >30 times 

|       36 |  72 | checking permissions | 0.638685 |
|       36 |  73 | checking permissions | 0.000326 |
|       36 |  74 | checking permissions | 0.000025 |
|       36 |  75 | Sending data         | 0.009675 |
|       36 |  76 | end                  | 0.000008 |
|       36 |  77 | query end            | 0.000003 |
|       36 |  78 | freeing items        | 0.000059 |
|       36 |  79 | removing tmp table   | 0.001139 |
|       36 |  80 | closing tables       | 0.000003 |
|       36 |  81 | logging slow query   | 0.000002 |
|       36 |  82 | cleaning up          | 0.001112 |
+----------+-----+----------------------+----------+

Due to inefficiency of the current implementation of I_S it looks that approach when objects are handled one by one is not really best one. 

We may consider batch approach when we will get all needed info about triggers with one query like:

CREATE TEMPORARY TABLE trigger_tmp_db0 SELECT trigger_name,event_object_table FROM INFORMATION_SCHEMA.TRIGGERS WHERE event_object_schema = 'db0'

it will take only 1 sec to execute it and then process data from this temporary table.
[9 Dec 2009 12:07] Rafal Somla
REFINED PROBLEM DESCRIPTION
---------------------------
The time consuming query is executed by si_objects function find_table_for_trigger() (si_objects.cc:3179). The function is used in backup code when a trigger object is added to backup catalogue (Image_info::add_db_object() in image_info.cc). In that case trigger's table is determined and its coordinates stored in the catalogue entry for the trigger. This is done by calling find_table_for_trigger() for each trigger added to the catalogue and for each such call the select against I_S is executed.

SUGGESTED SOLUTION
------------------
This solution will remove the offending select against I_S. 

When database triggers are enumerated using obs::Trigger_iterator, read and store trigger's table in each returned obs::TriggerObj instance. Then reimplement find_table_for_trigger() to simply read table name stored in the table instance. This would eliminate the SQL query completely. However, the signature of find_table_for_trigger() would have to change to:

Obj *find_table_for_trigger(const Obj *trigger);

With this change we need access to obs::Obj instance representing the trigger to find the corresponding table. With current Image_info::ad_db_object() we have only trigger name. But the obs::Obj instance is available one level up, in Backup_info::add_db_object(). This suggests that determining trigger's table should be done in Backup_info::add_db_object(), not on the lower level in Image_info::add_db_object(). 

In my recent patch for BUG#43596 I have already meved trigger handling from Image_info::add_db_object() to Backup_info::add_db_object(), so it might be consulted for ideas. Alternatively, if BUG#43596 is accepted and pushed first then this patch will be easier doing modifications in Backup_info::add_db_object().
[16 Dec 2009 4:22] Bugs System
A patch for this bug has been committed. After review, it may
be pushed to the relevant source trees for release in the next
version. You can access the patch from:

  http://lists.mysql.com/commits/94350

2910 Thava Alagu	2009-12-16
      Bug#49264   BACKUP: Huge slowdown while backup triggers
      
      [ Note: This is prototype fix since I have not run all the tests
        on the latest tree. This is for commit records. ]
      
      Significant degrade in performance was observed when lots of
      triggers present.
      
      The main culprit of this slowdown is due to executing si_objects
      select query on information schema to find the associated table
      for the trigger. This query was executed for each trigger. 
      This was fixed to cache the associated table information in the 
      trigger object. The fix is mostly based on the suggested solution 
      approach by Rafal as described in the bug report.
[16 Dec 2009 14:09] Bugs System
A patch for this bug has been committed. After review, it may
be pushed to the relevant source trees for release in the next
version. You can access the patch from:

  http://lists.mysql.com/commits/94503

2916 Thava Alagu	2009-12-16
      Bug#49264   BACKUP: Huge slowdown while backup triggers
      
      Significant degrade in performance was observed when lots of
      triggers present.
      
      The main culprit of this slowdown is due to executing si_objects
      select query on information schema to find the associated table
      for the trigger. This query was executed for each trigger. 
      This was fixed to cache the associated table information in the 
      trigger object. The fix is mostly based on the suggested solution
      approach by Rafal as described in the bug report.
[16 Dec 2009 14:48] Chuck Bell
Approved pending changes
[16 Dec 2009 14:57] Chuck Bell
I might also suggest Ranger try out the solution to see what the improvement. It would be nice to know how much faster the fix is.
[16 Dec 2009 21:20] Alexey Stroganov
I apologize for the mess, previous results of rerun were not for the trigger test. Correct ones:
-----------------------------------------------------------
                                           |MyISAM| InnoDB|
-----------------------------------------------------------
6.0-rev2915+patch                          |   128 |   43 |
-----------------------------------------------------------
[17 Dec 2009 12:27] Rafal Somla
Waiting for Thava to submit an updated patch.
[17 Dec 2009 20:39] Thava Alagu
I think the Ranger's suggestions are good and that we need to keep in mind while using all the queries on information schema and pay attention if information schema queries are used in optimized manner. The current proposed fix fortunately eliminates the following query completely which is executed for each trigger:

  SELECT event_object_table FROM INFORMATION_SCHEMA.TRIGGERS
WHERE trigger_schema = <trigger_schema> AND trigger_name COLLATEutf8_bin =
<trigger_name>

There may be few other queries which may benefit from information schema optimization techniques but they are unlikely to make any significant difference in performance especially if they are executed only once.
[24 Dec 2009 17:23] Bugs System
A patch for this bug has been committed. After review, it may
be pushed to the relevant source trees for release in the next
version. You can access the patch from:

  http://lists.mysql.com/commits/95688

2927 Thava Alagu	2009-12-24
      Bug#49264   BACKUP: Huge slowdown while backup triggers
      
      Significant degrade in performance was observed when lots of
      triggers present.
      
      The main culprit of this slowdown is due to executing si_objects
      select query on information schema to find the associated table
      for the trigger. This query was executed for each trigger. 
      This was fixed to cache the associated table information in the 
      trigger object.
[4 Jan 2010 12:33] Rafal Somla
Good to push.
[5 Jan 2010 6:54] Bugs System
A patch for this bug has been committed. After review, it may
be pushed to the relevant source trees for release in the next
version. You can access the patch from:

  http://lists.mysql.com/commits/95924

2927 Thava Alagu	2010-01-05
      Bug#49264   BACKUP: Huge slowdown while backup triggers
      
      Significant degrade in performance was observed when lots of
      triggers present.
      
      The main culprit of this slowdown is due to executing si_objects
      select query on information schema to find the associated table
      for the trigger. This query was executed for each trigger. 
      This was fixed to cache the associated table information in the 
      trigger object.
[5 Jan 2010 11:03] Thava Alagu
pushed the fix to mysql-6.0-backup tree.
revision_id: thavamuni.alagu@sun.com-20100105065419-uljcif2ttvg47m97
[15 Jan 2010 17:07] Bugs System
A patch for this bug has been committed. After review, it may
be pushed to the relevant source trees for release in the next
version. You can access the patch from:

  http://lists.mysql.com/commits/97131

3068 Chuck Bell	2010-01-15
      Bug#49264   BACKUP: Huge slowdown while backup triggers
      
      Significant degrade in performance was observed when lots of
      triggers present.
      
      The main culprit of this slowdown is due to executing si_objects
      select query on information schema to find the associated table
      for the trigger. This query was executed for each trigger. 
      This was fixed to cache the associated table information in the 
      trigger object.
      
      original changeset: 2955.1.2 (mysql-6.0-backup)
[20 Feb 2010 9:17] Bugs System
Pushed into 6.0.14-alpha (revid:ingo.struewing@sun.com-20100218152520-s4v1ld76bif06eqn) (version source revid:ingo.struewing@sun.com-20100119103538-wtp5alpz4p2jayl5) (merge vers: 6.0.14-alpha) (pib:16)
[3 Mar 2010 2:09] Paul Dubois
Noted in 6.0.14 changelog.

BACKUP DATABASE performance was degraded for backups that included 
many triggers.