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

Complex query in Store procedure corrupts results

Details

    Description

      When running the complex query repeatedly in the stored procedure random garbage or empty results are returned on occasion.

      Data dump with SP and test are contained in attachment. With the SP rewritten to store the output in a table the results that are correct and incorrect are as follows:

      +-------------------+--------------+-----------------+------------+----------------------+-------------------------+-----------------------+--------------+-----------------+--------+----------+----------------+---------------------+
      | customerReference | policyNumber | schemeReference | schemeName | applicationReference | modifiedCreatedDateTime | demandCreatedDateTime | countDemands | genericDemandId | status | isUrgent | reactivateDate | isBusinessException |
      +-------------------+--------------+-----------------+------------+----------------------+-------------------------+-----------------------+--------------+-----------------+--------+----------+----------------+---------------------+
      | reference1        |            1 | NULL            | NULL       | NULL                 | 2020-01-01 10:10:10     | 2020-01-01 10:10:10   |            1 |               1 |      1 |        0 | NULL           |                   0 |
      +-------------------+--------------+-----------------+------------+----------------------+-------------------------+-----------------------+--------------+-----------------+--------+----------+----------------+---------------------+
      

      Under high concurrency (should be a static result) from 10000 iterations the following rows were inserted:

      mysql ds2 -e "select * from results where customerReference<>'reference1'" 
      +--------------------------------+--------------+-----------------+------------+----------------------------------------------------+-------------------------+-----------------------+--------------+-----------------+--------+----------+---------------------+---------------------+
      | customerReference              | policyNumber | schemeReference | schemeName | applicationReference                               | modifiedCreatedDateTime | demandCreatedDateTime | countDemands | genericDemandId | status | isUrgent | reactivateDate      | isBusinessException |
      +--------------------------------+--------------+-----------------+------------+----------------------------------------------------+-------------------------+-----------------------+--------------+-----------------+--------+----------+---------------------+---------------------+
      | w  (       ??      0??K    |            0 | NULL            | NULL       | NULL                                               | 2020-01-01 10:10:10     | NULL                  |   2147483647 |            NULL |   NULL |        0 | NULL                |                NULL |
      |                                |            0 |                 |            |                                                    | 2020-01-01 10:10:10     | 2020-01-01 10:10:10   |            1 |               1 |      1 |        0 | 0000-00-00 00:00:00 |                   0 |
      | w  rence1                     |            1 |                 |            |                                                    | 2020-01-01 10:10:10     | 2020-01-01 10:10:10   |            1 |               1 |      1 |        0 | NULL                |                NULL |
      | w  rence1                     |            1 |                 |            |                                                    | 2020-01-01 10:10:10     | 2020-01-01 10:10:10   |            1 |            NULL |   NULL |        0 | 0000-00-00 00:00:00 |                NULL |
      |                                |            1 |                 |            |                                                    | 2020-01-01 10:10:10     | 2020-01-01 10:10:10   |            1 |               1 |      1 |        0 | 0000-00-00 00:00:00 |                   0 |
      | w  rence1                     |            1 |                 | NULL       | NULL                                               | 2020-01-01 10:10:10     | 2020-01-01 10:10:10   |            1 |            NULL |      1 |     NULL | NULL                |                NULL |
      |                                |            1 |                 |            |                                                    | 2020-01-01 10:10:10     | 2020-01-01 10:10:10   |            1 |               1 |      1 |        0 | 0000-00-00 00:00:00 |                   0 |
      | w  rence1                     |            1 |                 |            | NULL                                               | NULL                    | 2020-01-01 10:10:10   |            1 |            NULL |   NULL |     NULL | 0000-00-00 00:00:00 |                   0 |
      |                                |            1 |                 |            |                                                    | 2020-01-01 10:10:10     | 2020-01-01 10:10:10   |            1 |               1 |      1 |        0 | 0000-00-00 00:00:00 |                   0 |
      | w  rence1                     |            1 |                 | NULL       |                                                    | 2020-01-01 10:10:10     | 2020-01-01 10:10:10   |            1 |               1 |      1 |        0 | NULL                |                NULL |
      |                                |            0 |                 |            |                                                    | 2020-01-01 10:10:10     | 2020-01-01 10:10:10   |            1 |               1 |      1 |        0 | 0000-00-00 00:00:00 |                   0 |
      | w  rence1                     |            1 |                 | NULL       |                                                    | NULL                    | NULL                  |            1 |               1 |      1 |        0 | NULL                |                NULL |
      |                                |            1 |                 |            |                                                    | 2020-01-01 10:10:10     | 2020-01-01 10:10:10   |            1 |               1 |      1 |        0 | 0000-00-00 00:00:00 |                   0 |
      | w  (       ??      0??K    |            0 | NULL            | NULL       |                                                    | 2020-01-01 10:10:10     | NULL                  |   2147483647 |               0 |      1 |        0 | 7036-87-44 17:76:64 |                NULL |
      | w  rence1                     |            1 |                 |            | NULL                                               | 2020-01-01 10:10:10     | 2020-01-01 10:10:10   |            1 |               1 |   NULL |     NULL | 0000-00-00 00:00:00 |                   0 |
      |                                |            1 |                 |            |                                                    | 2020-01-01 10:10:10     | 2020-01-01 10:10:10   |            1 |               1 |      1 |        0 | 0000-00-00 00:00:00 |                   0 |
      |                                |            1 |                 |            |                                                    | 2020-01-01 10:10:10     | 2020-01-01 10:10:10   |            1 |               1 |      1 |        0 | 0000-00-00 00:00:00 |                   0 |
      |                                |            0 |                 |            |                                                    | 2020-01-01 10:10:10     | 2020-01-01 10:10:10   |            1 |               1 |      1 |        0 | 0000-00-00 00:00:00 |                   0 |
      |                                |            0 |                 |            |                                                    | 2020-01-01 10:10:10     | 2020-01-01 10:10:10   |            1 |               1 |      1 |        0 | 0000-00-00 00:00:00 |                   0 |
      |                                |            0 |                 |            |                                                    | 2020-01-01 10:10:10     | 2020-01-01 10:10:10   |   2147483647 |               0 |      1 |        0 | 0000-00-00 00:00:00 |                   0 |
      |                                |            0 |                 |            | ?K                                               | 2020-01-01 10:10:10     | 2020-01-01 10:10:10   |            1 |               1 |      1 |        0 | 0000-00-00 00:00:00 |                   0 |
      |                                |            1 |                 |            |                                                    | 2020-01-01 10:10:10     | 2020-01-01 10:10:10   |            1 |               1 |      1 |        0 | 0000-00-00 00:00:00 |                   0 |
      |                                |            1 |                 |            |                                                    | 2020-01-01 10:10:10     | 2020-01-01 10:10:10   |            1 |               1 |      1 |        0 | 0000-00-00 00:00:00 |                   0 |
      |                                |            1 |                 |            |                                                    | 2020-01-01 10:10:10     | 2020-01-01 10:10:10   |            1 |               1 |      1 |        0 | 0000-00-00 00:00:00 |                   0 |
      |                                |            1 |                 |            |                                                    | 2020-01-01 10:10:10     | 2020-01-01 10:10:10   |            1 |               1 |      1 |        0 | 0000-00-00 00:00:00 |                   0 |
      |                                |            1 |                 |            |                                                    | 2020-01-01 10:10:10     | 2020-01-01 10:10:10   |            1 |               1 |      1 |        0 | 0000-00-00 00:00:00 |                   0 |
      |                                |            1 |                 |            |                                                    | 2020-01-01 10:10:10     | 2020-01-01 10:10:10   |            1 |               1 |      1 |        0 | 0000-00-00 00:00:00 |                   0 |
      +--------------------------------+--------------+-----------------+------------+----------------------------------------------------+-------------------------+-----------------------+--------------+-----------------+--------+----------+---------------------+---------------------+
      

      Attachments

        Issue Links

          Activity

            commit c4ae6b240abff7f3df2c76c8a3ffccc0775470c1 (HEAD -> bb-10.3-MDEV-25182, origin/bb-10.3-MDEV-25182)
            Author: Oleksandr Byelkin <sanja@mariadb.com>
            Date:   Wed Apr 7 12:59:43 2021 +0200
             
                MDEV-25182 Complex query in Store procedure corrupts results
                
                Problem was that on second execution marked more selects as needed:
                  merged derived removed from SELECT tree and limit (last) in
                  st_select_lex::mark_as_dependent is skipped.
                
                To avoid the problem we use name resolution context to go by it "up".
                
                NOTE: problem also exists in 10.2 but has no vosoble effect on execution.
                
                The patch also add debug logging of important procedures and
                 bettr specify parametrs types of st_select_lex::mark_as_dependent.
            

            sanja Oleksandr Byelkin added a comment - commit c4ae6b240abff7f3df2c76c8a3ffccc0775470c1 (HEAD -> bb-10.3-MDEV-25182, origin/bb-10.3-MDEV-25182) Author: Oleksandr Byelkin <sanja@mariadb.com> Date: Wed Apr 7 12:59:43 2021 +0200   MDEV-25182 Complex query in Store procedure corrupts results Problem was that on second execution marked more selects as needed: merged derived removed from SELECT tree and limit (last) in st_select_lex::mark_as_dependent is skipped. To avoid the problem we use name resolution context to go by it "up". NOTE: problem also exists in 10.2 but has no vosoble effect on execution. The patch also add debug logging of important procedures and bettr specify parametrs types of st_select_lex::mark_as_dependent.

            the actual crash in

                #0 in heap_rrnd /10.3/storage/heap/hp_rrnd.c:40
                #1 in ha_heap::rnd_pos(unsigned char*, unsigned char*) /10.3/storage/heap/ha_heap.cc:353
                #2 in handler::ha_rnd_pos(unsigned char*, unsigned char*) /10.3/sql/handler.cc:2881
                #3 in rr_from_pointers(READ_RECORD*) /10.3/sql/records.cc:551
                #4 in READ_RECORD::read_record() /10.3/sql/records.h:70
                #5 in join_init_read_record(st_join_table*) /10.3/sql/sql_select.cc:20739
            

            happens because first rows are written into a temporary HEAP table, then filesort (?) saves row positions (just pointers in memory) and sorts them. Then the table is emptied (with ha_heap::delete_all_rows) — which frees all memory and makes pointers to rows invalid, and then the executor uses rr_from_pointers (see above) that reads these now obsolete positions, and with ha_heap::rnd_pos tries to read the row, which is no longer there.

            serg Sergei Golubchik added a comment - the actual crash in #0 in heap_rrnd /10.3/storage/heap/hp_rrnd.c:40 #1 in ha_heap::rnd_pos(unsigned char*, unsigned char*) /10.3/storage/heap/ha_heap.cc:353 #2 in handler::ha_rnd_pos(unsigned char*, unsigned char*) /10.3/sql/handler.cc:2881 #3 in rr_from_pointers(READ_RECORD*) /10.3/sql/records.cc:551 #4 in READ_RECORD::read_record() /10.3/sql/records.h:70 #5 in join_init_read_record(st_join_table*) /10.3/sql/sql_select.cc:20739 happens because first rows are written into a temporary HEAP table, then filesort (?) saves row positions (just pointers in memory) and sorts them. Then the table is emptied (with ha_heap::delete_all_rows ) — which frees all memory and makes pointers to rows invalid, and then the executor uses rr_from_pointers (see above) that reads these now obsolete positions, and with ha_heap::rnd_pos tries to read the row, which is no longer there.

            More details how we come to the above crash/memory problems.
            After the first execution of the prepared statement (PS) all mergeable derived are already merged and the query of the following form is processed at the second execution of PS:

            select ca.d2 AS d2,ca.d1 AS d1 
              from (select min(t1.d2) AS d2,min((subquery#4)) AS d1 from test.t1) ca
             order by ca.d2
            

            Here's how the query is executed:
            1. The query is is a join containing only one table 'ca' whose result set requires sorting. So single-table join with join_tab 'ca' with join_tab->filesort defined is executed.
            2. As join_tab->join_tab->preread_init_done is false for 'ca' join_tab->preread_init() is called that checks that 'ca' is materialized derived and requires filling.
            3. mysql_derived_fill is called for 'ca' where mysql_select() is called for the select

            select min(t1.d2) AS d2,min((subquery#4)) AS d1 from test.t1
            

            4. Execution of the above query fills the temp table for 'ca'.
            5. As the unit for 'ca' is marked as uncacheable preread_init() does not set join_tab->preread_init_done to TRUE.
            6. join_init_read_record() is called for JOIN_TAB 'ca'. It sees that tab->filesort != NULL and calls sort_table() for 'ca'.
            7. sort_table() calls create_sort_index().
            8. As preread_init_done is still false for 'ca' preread_init() is called for 'ca'.
            9. As ca is marked as uncacheable mysql_derived_fill() is called for'ca'. This is not good by itself as the temp_table has been already filled with all needed rows.
            (TODO. This code should be revised. It does not cause any problems now because the uncacheable derived table that we have now are produced by split optimization and there we have no order by associated with them.)
            10. In mysql_derived_fill() as the unit for 'ca' has been already executed and it is marked as uncacheable
            table->file->ha_delete_all_rows() is called for 'ca' and the mysql_select is called to fill the temp table with the rows for 'ca'. No problems are observed so far except that the temp table for 'ca' is filled twice, but this is just a performance issue.
            11. in preread_init() called for 'ca' the flag preread_init_done remains false.
            12. in create_sort_index() filesort() is called that sets array of pointers to positions of records in the temp table for 'ca'.
            13. in join_init_read_record() for 'ca' preread_init() is called again and it fills the temp table for 'ca' again. At the same time it makes the pointers set by filesort obsolete as mysql_derived_fill first deletes all records from the temp table just by freeing the piece of memory with them.
            (TODO. Here we have another potential problem for future uncacheable derived tables that should be resolved.)
            14. rr_from_pointers() ties to read the first record for the sorted result set. it use the array of pointers to the temp table, but they not actual anymore.

            igor Igor Babaev (Inactive) added a comment - More details how we come to the above crash/memory problems. After the first execution of the prepared statement (PS) all mergeable derived are already merged and the query of the following form is processed at the second execution of PS: select ca.d2 AS d2,ca.d1 AS d1 from ( select min (t1.d2) AS d2, min ((subquery#4)) AS d1 from test.t1) ca order by ca.d2 Here's how the query is executed: 1. The query is is a join containing only one table 'ca' whose result set requires sorting. So single-table join with join_tab 'ca' with join_tab->filesort defined is executed. 2. As join_tab->join_tab->preread_init_done is false for 'ca' join_tab->preread_init() is called that checks that 'ca' is materialized derived and requires filling. 3. mysql_derived_fill is called for 'ca' where mysql_select() is called for the select select min (t1.d2) AS d2, min ((subquery#4)) AS d1 from test.t1 4. Execution of the above query fills the temp table for 'ca'. 5. As the unit for 'ca' is marked as uncacheable preread_init() does not set join_tab->preread_init_done to TRUE. 6. join_init_read_record() is called for JOIN_TAB 'ca'. It sees that tab->filesort != NULL and calls sort_table() for 'ca'. 7. sort_table() calls create_sort_index(). 8. As preread_init_done is still false for 'ca' preread_init() is called for 'ca'. 9. As ca is marked as uncacheable mysql_derived_fill() is called for'ca'. This is not good by itself as the temp_table has been already filled with all needed rows. (TODO. This code should be revised. It does not cause any problems now because the uncacheable derived table that we have now are produced by split optimization and there we have no order by associated with them.) 10. In mysql_derived_fill() as the unit for 'ca' has been already executed and it is marked as uncacheable table->file->ha_delete_all_rows() is called for 'ca' and the mysql_select is called to fill the temp table with the rows for 'ca'. No problems are observed so far except that the temp table for 'ca' is filled twice, but this is just a performance issue. 11. in preread_init() called for 'ca' the flag preread_init_done remains false. 12. in create_sort_index() filesort() is called that sets array of pointers to positions of records in the temp table for 'ca'. 13. in join_init_read_record() for 'ca' preread_init() is called again and it fills the temp table for 'ca' again. At the same time it makes the pointers set by filesort obsolete as mysql_derived_fill first deletes all records from the temp table just by freeing the piece of memory with them. (TODO. Here we have another potential problem for future uncacheable derived tables that should be resolved.) 14. rr_from_pointers() ties to read the first record for the sorted result set. it use the array of pointers to the temp table, but they not actual anymore.

            Here's a detailed explanation how the select that specifies the derived table 'ca' becomes marked as unchacheable.
            At the first execution of the PS
            1. When the column outer reference t1.id1 that used in the subquery

            SELECT t2.d1  FROM t2 WHERE t1.id1 = t2.id1 ORDER BY t2.id DESC LIMIT 1 // subquery#4
            

            is resolved in Item_field::fix_outer_field() the table reference against which it is resolved is the same as it was when PS was processed. This table reference was saved in Item_field::cached_table. This table reference belongs to the from list of this select.

            select t1.d2 AS d2,(subquery#4) AS d1 from test.t1   // outer_select
            

            2. mark_as_dependent() is called to which outer_select is passed as the second parameter and subquery#4 is passed as the third parameter.
            3. the function mark_as_dependent() marks all selects starting from subquery#4 up to outer_select
            as uncacheable. it uses the functionouter_select() to move towards outer_select.
            At the second execution of the PS
            1. mark_as_dependent() is called with the same parameters as at the first execution.
            2. as outer_select has been already merged at the first execution of PS it cannot be reached using the outer_select() function anymore.
            3. as a result all selects towards the top level select including the select for 'ca' are marked as uncacheable.

            igor Igor Babaev (Inactive) added a comment - Here's a detailed explanation how the select that specifies the derived table 'ca' becomes marked as unchacheable. At the first execution of the PS 1. When the column outer reference t1.id1 that used in the subquery SELECT t2.d1 FROM t2 WHERE t1.id1 = t2.id1 ORDER BY t2.id DESC LIMIT 1 // subquery#4 is resolved in Item_field::fix_outer_field() the table reference against which it is resolved is the same as it was when PS was processed. This table reference was saved in Item_field::cached_table. This table reference belongs to the from list of this select. select t1.d2 AS d2,(subquery#4) AS d1 from test.t1 // outer_select 2. mark_as_dependent() is called to which outer_select is passed as the second parameter and subquery#4 is passed as the third parameter. 3. the function mark_as_dependent() marks all selects starting from subquery#4 up to outer_select as uncacheable. it uses the functionouter_select() to move towards outer_select. At the second execution of the PS 1. mark_as_dependent() is called with the same parameters as at the first execution. 2. as outer_select has been already merged at the first execution of PS it cannot be reached using the outer_select() function anymore. 3. as a result all selects towards the top level select including the select for 'ca' are marked as uncacheable.

            Ok to push the fix into 10.2 after providing a proper comment for the patch.

            igor Igor Babaev (Inactive) added a comment - Ok to push the fix into 10.2 after providing a proper comment for the patch.

            People

              sanja Oleksandr Byelkin
              kjoiner Kyle Joiner (Inactive)
              Votes:
              1 Vote for this issue
              Watchers:
              11 Start watching this issue

              Dates

                Created:
                Updated:
                Resolved:

                Git Integration

                  Error rendering 'com.xiplink.jira.git.jira_git_plugin:git-issue-webpanel'. Please contact your Jira administrators.