Uploaded image for project: 'MariaDB Server'
  1. MariaDB Server
  2. MDEV-8254

Performance problems with a simple loop

    Details

    • Type: Bug
    • Status: Confirmed
    • Priority: Major
    • Resolution: Unresolved
    • Affects Version/s: 10.1, 10.0, 5.5
    • Fix Version/s: None
    • Component/s: None

      Description

      First, try benchmarking an increment + assignment:

      SET @x := 0;
      DO BENCHMARK(1000000, @x := @x + 1);
      

      On my local system, this takes ~ .11 seconds.

      But try to do the same in a stored procedure:

      DELIMITER ||
      DROP PROCEDURE IF EXISTS test ||
      CREATE PROCEDURE test()
      BEGIN
      	SET @x := 0;        
      	WHILE @x < 1000000 DO	
                      SET @x := @x + 1;
              END WHILE;
      END ||
      DELIMITER ;
      CALL test();
      

      More than 13.6 seconds on my system!

      For some reason, the problem is notably less critical (but still annoying) if you use a local variable instead of a session variable:

      DELIMITER ||
      DROP PROCEDURE IF EXISTS test ||
      CREATE PROCEDURE test()
      BEGIN
      	DECLARE x INT UNSIGNED DEFAULT 0;        
      	WHILE x < 1000000 DO	
                      SET x := x + 1;
              END WHILE;
      END ||
      DELIMITER ;
      CALL test();
      

      Takes about 5.75.

        Gliffy Diagrams

          Attachments

            Activity

            Hide
            elenst Elena Stepanova added a comment -

            Same with MySQL 5.5, 5.7.

            Also, same is true for MariaDB 10.1 compound statements, so it's not related to the SP call as such.

            Here is some noticeable difference from P_S (although maybe it's not the difference that causes the performance problem, but it might be):

            select event_name, count_star, sum_timer_wait from
            performance_schema.events_waits_summary_global_by_event_name order by
            sum_timer_wait desc limit 5;
            
            BENCHMARK
            +--------------------------------------------------------+------------+------------------+
            | event_name                                             | count_star | sum_timer_wait   |
            +--------------------------------------------------------+------------+------------------+
            | idle                                                   |        155 | 1978525729000000 |
            | wait/synch/mutex/sql/THD::LOCK_thd_data                |    2000119 |    3819579725654 |
            | wait/synch/mutex/sql/TABLE_SHARE::tdc.LOCK_table_share |        169 |        449129871 |
            | wait/synch/rwlock/sql/MDL_lock::rwlock                 |         55 |        207316591 |
            | wait/io/socket/sql/client_connection                   |          4 |        154879998 |
            +--------------------------------------------------------+------------+------------------+
            

            (these values appear in the table right after TRUNCATE, they are barely modified by the BENCHMARK)

            Compound statement
            +--------------------------------------------------------+------------+------------------+
            | event_name                                             | count_star | sum_timer_wait   |
            +--------------------------------------------------------+------------+------------------+
            | idle                                                   |        174 | 2082422485000000 |
            | wait/synch/mutex/sql/THD::LOCK_thd_data                |    4000119 |    7561752296880 |
            | wait/synch/mutex/sql/TABLE_SHARE::tdc.LOCK_table_share |         66 |        124610181 |
            | wait/io/file/sql/FRM                                   |         12 |        113567436 |
            | wait/synch/rwlock/sql/MDL_lock::rwlock                 |         55 |        106337591 |
            +--------------------------------------------------------+------------+------------------+
            
            Stored procedure
            +--------------------------------------------------------+------------+------------------+
            | event_name                                             | count_star | sum_timer_wait   |
            +--------------------------------------------------------+------------+------------------+
            | idle                                                   |        194 | 2441441158000000 |
            | wait/synch/mutex/sql/THD::LOCK_thd_data                |    4000121 |    7569150979606 |
            | wait/synch/mutex/sql/TABLE_SHARE::tdc.LOCK_table_share |         93 |        186116029 |
            | wait/io/file/sql/FRM                                   |         16 |        134974565 |
            | wait/synch/rwlock/sql/MDL_lock::rwlock                 |         57 |        117695843 |
            +--------------------------------------------------------+------------+------------------+
            
            select event_name, count_star, sum_timer_wait from
            performance_schema.events_stages_summary_global_by_event_name order by
            sum_timer_wait desc limit 5;
            
            BENCHMARK
            +--------------------------------+------------+----------------+
            | event_name                     | count_star | sum_timer_wait |
            +--------------------------------+------------+----------------+
            | stage/sql/Opening tables       |         16 |     2494021000 |
            | stage/sql/init                 |         19 |     1333234000 |
            | stage/sql/Sorting result       |          1 |     1263361000 |
            | stage/sql/checking permissions |         14 |     1005380000 |
            | stage/sql/Unlocking tables     |         14 |      312488000 |
            +--------------------------------+------------+----------------+
            
            Compound statement
            +--------------------------------+------------+----------------+
            | event_name                     | count_star | sum_timer_wait |
            +--------------------------------+------------+----------------+
            | stage/sql/closing tables       |    2000018 | 13645989740000 |
            | stage/sql/Opening tables       |    2000016 |  4573616825000 |
            | stage/sql/After opening tables |    2000016 |  4293346982000 |
            | stage/sql/query end            |    1000017 |  2311569542000 |
            | stage/sql/Sorting result       |          1 |     1145411000 |
            +--------------------------------+------------+----------------+
            
            Stored procedure
            +--------------------------------+------------+----------------+
            | event_name                     | count_star | sum_timer_wait |
            +--------------------------------+------------+----------------+
            | stage/sql/closing tables       |    2000019 | 13698547142000 |
            | stage/sql/Opening tables       |    2000018 |  4561133838000 |
            | stage/sql/After opening tables |    2000018 |  4291648574000 |
            | stage/sql/query end            |    1000017 |  2313252823000 |
            | stage/sql/Sorting result       |          1 |     1117100000 |
            +--------------------------------+------------+----------------+
            

            I'll leave it to Sergei Golubchik to decide whether there is a bug in here.

            Show
            elenst Elena Stepanova added a comment - Same with MySQL 5.5, 5.7. Also, same is true for MariaDB 10.1 compound statements, so it's not related to the SP call as such. Here is some noticeable difference from P_S (although maybe it's not the difference that causes the performance problem, but it might be): select event_name, count_star, sum_timer_wait from performance_schema.events_waits_summary_global_by_event_name order by sum_timer_wait desc limit 5; BENCHMARK +--------------------------------------------------------+------------+------------------+ | event_name | count_star | sum_timer_wait | +--------------------------------------------------------+------------+------------------+ | idle | 155 | 1978525729000000 | | wait/synch/mutex/sql/THD::LOCK_thd_data | 2000119 | 3819579725654 | | wait/synch/mutex/sql/TABLE_SHARE::tdc.LOCK_table_share | 169 | 449129871 | | wait/synch/rwlock/sql/MDL_lock::rwlock | 55 | 207316591 | | wait/io/socket/sql/client_connection | 4 | 154879998 | +--------------------------------------------------------+------------+------------------+ (these values appear in the table right after TRUNCATE, they are barely modified by the BENCHMARK) Compound statement +--------------------------------------------------------+------------+------------------+ | event_name | count_star | sum_timer_wait | +--------------------------------------------------------+------------+------------------+ | idle | 174 | 2082422485000000 | | wait/synch/mutex/sql/THD::LOCK_thd_data | 4000119 | 7561752296880 | | wait/synch/mutex/sql/TABLE_SHARE::tdc.LOCK_table_share | 66 | 124610181 | | wait/io/file/sql/FRM | 12 | 113567436 | | wait/synch/rwlock/sql/MDL_lock::rwlock | 55 | 106337591 | +--------------------------------------------------------+------------+------------------+ Stored procedure +--------------------------------------------------------+------------+------------------+ | event_name | count_star | sum_timer_wait | +--------------------------------------------------------+------------+------------------+ | idle | 194 | 2441441158000000 | | wait/synch/mutex/sql/THD::LOCK_thd_data | 4000121 | 7569150979606 | | wait/synch/mutex/sql/TABLE_SHARE::tdc.LOCK_table_share | 93 | 186116029 | | wait/io/file/sql/FRM | 16 | 134974565 | | wait/synch/rwlock/sql/MDL_lock::rwlock | 57 | 117695843 | +--------------------------------------------------------+------------+------------------+ select event_name, count_star, sum_timer_wait from performance_schema.events_stages_summary_global_by_event_name order by sum_timer_wait desc limit 5; BENCHMARK +--------------------------------+------------+----------------+ | event_name | count_star | sum_timer_wait | +--------------------------------+------------+----------------+ | stage/sql/Opening tables | 16 | 2494021000 | | stage/sql/init | 19 | 1333234000 | | stage/sql/Sorting result | 1 | 1263361000 | | stage/sql/checking permissions | 14 | 1005380000 | | stage/sql/Unlocking tables | 14 | 312488000 | +--------------------------------+------------+----------------+ Compound statement +--------------------------------+------------+----------------+ | event_name | count_star | sum_timer_wait | +--------------------------------+------------+----------------+ | stage/sql/closing tables | 2000018 | 13645989740000 | | stage/sql/Opening tables | 2000016 | 4573616825000 | | stage/sql/After opening tables | 2000016 | 4293346982000 | | stage/sql/query end | 1000017 | 2311569542000 | | stage/sql/Sorting result | 1 | 1145411000 | +--------------------------------+------------+----------------+ Stored procedure +--------------------------------+------------+----------------+ | event_name | count_star | sum_timer_wait | +--------------------------------+------------+----------------+ | stage/sql/closing tables | 2000019 | 13698547142000 | | stage/sql/Opening tables | 2000018 | 4561133838000 | | stage/sql/After opening tables | 2000018 | 4291648574000 | | stage/sql/query end | 1000017 | 2313252823000 | | stage/sql/Sorting result | 1 | 1117100000 | +--------------------------------+------------+----------------+ I'll leave it to Sergei Golubchik to decide whether there is a bug in here.

              People

              • Assignee:
                serg Sergei Golubchik
                Reporter:
                f_razzoli Federico Razzoli
              • Votes:
                0 Vote for this issue
                Watchers:
                3 Start watching this issue

                Dates

                • Created:
                  Updated: