[MDEV-12992] MariaDB 10.2.6 leaks memory while executing a trigger Created: 2017-06-05  Updated: 2018-01-18  Resolved: 2017-06-11

Status: Closed
Project: MariaDB Server
Component/s: Data Manipulation - Subquery, Server, Triggers
Affects Version/s: 10.2.6
Fix Version/s: 10.2.7

Type: Bug Priority: Critical
Reporter: Ivan Korenkov Assignee: Igor Babaev
Resolution: Fixed Votes: 1
Labels: regression
Environment:

Linux Ubuntu Server 16.04, 14.04


Attachments: Microsoft Word 1_1.csv     Microsoft Word 1_2.csv     Microsoft Word 1_3.csv     PNG File img-2017-06-05-14-16-04.png     PNG File img-2017-06-05-14-29-25.png     PNG File img-2017-06-05-14-30-23.png     PNG File img-2017-06-07-01-28-11.png     HTML File maps     File my.cnf     File my32.cnf    
Issue Links:
Duplicate
is duplicated by MDEV-14987 Memory leak when max or min column fu... Closed
Relates
relates to MDEV-13177 MariaDB 10.2.6 eats virtual memory Closed

 Description   

После обновления с MariaDB 10.1.24 (все работало идеально) на MariaDB 10.2.6 происходит следующее: Постоянно растет потребление памяти до критического и система вырубает процесс mysql
Jun 5 09:09:38 gps-gateway kernel: [140387.414300] Killed process 3411 (mysqld) total-vm:184620312kB, anon-rss:2800140kB, file-rss:24328kB
На этом компе всего 4 гб оперативки. Разрешаю 1ГБ (На MariaDB 10.1.24 разрешал 2Гб)
InnoDB: Initializing buffer pool, total size = 1G, instances = 4, chunk size = 128M
Вот что через парчу часов после запуска
KiB Mem: 3789864 total, 3671884 used, 117980 free, 17148 buffers
KiB Swap: 1832956 total, 1101084 used, 731872 free. 89528 cached Mem
PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
11809 mysql 20 0 0.115t 2.878g 24332 S 11.3 79.6 53:40.37 mysqld
Виртуалки уже на 115ГБ занято.
На другом компе 32гб оперативки
InnoDB: Initializing buffer pool, total size = 16G, instances = 16, chunk size = 128M
через час вот что
top - 14:00:21 up 1 day, 17:36, 1 user, load average: 2.67, 2.23, 1.83
Tasks: 217 total, 2 running, 215 sleeping, 0 stopped, 0 zombie
%Cpu(s): 3.4 us, 1.2 sy, 0.0 ni, 87.1 id, 8.3 wa, 0.0 hi, 0.0 si, 0.0 st
KiB Mem : 32685944 total, 317156 free, 31256184 used, 1112604 buff/cache
KiB Swap: 7996348 total, 7398392 free, 597956 used. 872992 avail Mem
PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
9605 mysql 20 0 0.392t 0.028t 18804 S 25.2 92.0 160:37.32 mysqld
Виртуалки уже на 392ГБ занято. Доходит до 2 ТБ
На 10.1.24 и предыдущии все работало идеально по несколько месяцев без перезапуска.
А сейчас чтоб не покрашить базы приходиться перезапускать каждые 3-4 часа.

И что-то ужасное количество процессов запускается.



 Comments   
Comment by Ivan Korenkov [ 2017-06-05 ]

Как видно на скрине за 15 минут + 50гб виртуалки

Comment by Elena Stepanova [ 2017-06-06 ]

Hi Ivan,

Thanks for the report.

Can you say anything about your workflow? Is it DML-only, or is there DDL, and what kind, or are there lots of admin statements? How many connections run at a time? How often do they reconnect? Could you please paste or attach some typical SELECT * FROM INFORMATION_SCHEMA.PROCESSLIST \G outputs?

Further, please store the output of SHOW GLOBAL STATUS after you started the server (before the memory started growing), and again when it's already grown close to the edge, before you have to restart the server.

Before you restart the server, please send SIGHUP (kill -s SIGHUP <pid>). It should make the server write something to the error log. Please attach the whole error log since server startup and till the end of the session, when you restart it.

Comment by Ivan Korenkov [ 2017-06-06 ]

1_1.csv SELECT * FROM INFORMATION_SCHEMA.PROCESSLIST
1_2.csv SHOW GLOBAL STATUS before restart server
1_3.csv SHOW GLOBAL STATUS after restart server

Comment by Ivan Korenkov [ 2017-06-06 ]

Я на самом основном уже делаю откат на 10.1.24
На втором сервере могу пока все что необходимо скинуть.
Второй с 4Гб ОЗУ. 1_2.csv VIRT = 40Gb
Прирост памяти увеличивается от количества записываемых данных (INSERT). Количество соединений всегда примерно одинаковое.
То что скинул это постоянный набор - это программы. Еще может быть максимум 20 соединений от Apache2 - которые только читают.
Остановка apache ничего не меняет - прирост постояно продолжается
Елена - объясните что такое Is it DML-only, or is there DDL
У меня обычные компы - не виртуалка. С Ubuntu Server, LAMP

Comment by Ivan Korenkov [ 2017-06-06 ]

Прирост где-то около 1 000 000 - 3 000 000 записей в сутки, которые раскладываются по 3 таблицам

Comment by Elena Stepanova [ 2017-06-06 ]

DML – data modification language – это INSERT/REPLACE, UPDATE, DELETE, SELECT, LOAD DATA, работа с HANDLER, вызов процедур.
DDL – data definition language – это всевозможные CREATE, ALTER, DROP, а также TRUNCATE.
Admin statements – это работа с таблицами, типа ANALYZE, OPTIMIZE, CHECK etc, с аккаунтами, с переменными (SET), плагинами (INSTALL/UNINSTALL), логами (FLUSH) и т.п.

В зависимости от того, что происходит на сервере, мы будем пытаться понять, где происходит утечка памяти.

Судя по статусу, в основном выполняется DML, много используются InnoDB, триггеры и транзакции; очень много присваиваний переменных (SET), создаются какие-то UDF, но непонятно используются ли; одновременных соединений не очень много, но реконнекты происходят часто.

Всё это (хотя и не только это) – потенциальные подозреваемые в утечке.

Пожалуйста, сохраните и пришлите error log – желательно с результатом SIGHUP, но если не получится, то хотя бы просто полную сессию сервера от старта и до рестарта.

Comment by Ivan Korenkov [ 2017-06-06 ]

Да у меня DML
Идет постоянное заполнение таблиц.
И тригер который перекладывает данные из одной таблицы в другую, с небольшой конвертацией.
На основном сервере тригер тоже есть, но он просто проверяет определенные поля на наличие определенных данных и при наличии пишет данные в другую таблицу.

Comment by Ivan Korenkov [ 2017-06-06 ]

Сейчас на сервер практически нет прихода данных, но началось кеширование, которое строит отчеты по всем пришедшим за предыдущие сутки данным. Роста нет.

Comment by Elena Stepanova [ 2017-06-08 ]

Simplified test case:

--let $n= 1000000
 
CREATE TABLE t1 (a INT);
INSERT INTO t1 VALUES (1);
CREATE TABLE t2 (b INT);
CREATE TRIGGER tr AFTER UPDATE ON t1 FOR EACH ROW SELECT (SELECT b FROM t2) INTO @x;
 
--disable_query_log
--echo # Running $n queries
while ($n)
{
    UPDATE t1 SET a = 2;
    --dec $n
}
--enable_query_log
 
DROP TABLE t1,t2;

release

  PID USER      PR  NI    VIRT    RES    SHR S  %CPU %MEM     TIME+ COMMAND                                 
25926 elenst    20   0  1.175t 1.045g  14516 S  99.5  6.7   5:46.77 mysqld                                  

debug

  PID USER      PR  NI    VIRT    RES    SHR S  %CPU %MEM     TIME+ COMMAND                                 
27115 elenst    20   0 16.412g 0.015t   2716 S  49.4 95.2   0:11.61 mysqld                                  

Trigger and subquery from a table appear to be important here. Without the trigger the same query executed the same number of times doesn't cause any memory consumption growth; without the subquery the same trigger also works fine.

Not reproducible on 10.1.

Comment by Sergei Golubchik [ 2017-06-09 ]

igor, this is caused by your commit 82cb35be11:

commit 82cb35be11c
Author: Igor Babaev <igor@askmonty.org>
Date:   Wed Mar 23 16:09:58 2016 -0700
 
    Changed the base class for Item_window_func from Item_result_field to
    Item_func_or_sum.
    Implemented method update_used_tables for class Item_findow_func.
    Added the flag Item::with_window_func.
    Made sure that window functions could be used only in SELECT list
    and ORDER BY clause.
    Added test cases that checked different illegal placements of
    window functions.

In particular, by this change:

sql/sql_select.cc

804
 
805
   thd->lex->current_select->parsing_place= SELECT_LIST;
806
  if (setup_fields(thd, ref_ptrs, fields_list, MARK_COLUMNS_READ,
807
                   &all_fields, 1))
808
    DBUG_RETURN(-1);
809
  thd->lex->current_select->parsing_place= save_place;
810

In this bug, trigger invokes Item_singlerow_subselect::fix_length_and_dec() which invokes subselect_single_select_engine::fix_length_and_dec(), then subselect_engine::set_row() and Item_cache::get_cache(). The latter creates a new Item. And the Item constructor counts all items in the SELECT and HAVING clauses:

sql/item.cc

495
    enum_parsing_place place= 
496
      thd->lex->current_select->parsing_place;
497
    if (place == SELECT_LIST || place == IN_HAVING)
498
      thd->lex->current_select->select_n_having_items++;

With your change thd->lex->current_select->select_n_having_items is increased for every trigger invocation, and st_select_lex::setup_ref_array() will allocate larger and larger arrays every time.

Comment by Igor Babaev [ 2017-06-11 ]

The fix for this bug was pushed into the 10.2 tree.

Comment by Elena Stepanova [ 2017-06-20 ]

For future reference, stored procedures were also affected (it was also fixed):

CREATE TABLE t2 (b INT);
 
--delimiter $
CREATE PROCEDURE pr() 
BEGIN
  DECLARE n INT DEFAULT 0;
  WHILE n < 100000
  DO
    SELECT (SELECT b FROM t2) INTO @x;
    SET n = n+1;
  END WHILE;
END $
--delimiter ;
    
CALL pr();
 
DROP PROCEDURE pr;
DROP TABLE t2;

Also, there could be a scenario without an obvious subquery in the SELECT list:

CREATE TABLE t2 (b INT);
CREATE VIEW v2 AS SELECT * FROM t2;
 
--delimiter $
CREATE PROCEDURE pr() 
BEGIN
  DECLARE n INT DEFAULT 0;
  WHILE n < 100000
  DO
    SELECT b FROM v2 INTO @x;
    SET n = n+1;
  END WHILE;
END $
--delimiter ;
    
CALL pr();
 
DROP PROCEDURE pr;
DROP VIEW v2;
DROP TABLE t2;

Prepared statements which are re-executed multiple times also triggered the same problem:

CREATE TABLE t2 (b INT);
CREATE VIEW v2 AS SELECT * FROM t2;
 
PREPARE stmt FROM "SELECT b FROM v2";
 
--let $n= 100000
while ($n)
{
    EXECUTE stmt;
    --dec $n
}
 
DROP VIEW v2;
DROP TABLE t2;

Generated at Thu Feb 08 08:02:04 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.