[MDEV-6319] MariaDB 10.x gets killed by CentOS oom-killer with my.cnf that worked well for years Created: 2014-06-08  Updated: 2021-01-15  Resolved: 2021-01-15

Status: Closed
Project: MariaDB Server
Component/s: OTHER
Affects Version/s: 10.0.10, 10.0.11
Fix Version/s: N/A

Type: Bug Priority: Major
Reporter: Koen Crijns Assignee: Sergey Vojtovich
Resolution: Incomplete Votes: 7
Labels: need_feedback
Environment:

System | Dell Inc.; PowerEdge R810; vNot Specified (Rack Mount Chassis)
Platform | Linux
Release | CentOS release 6.5 (Final)
Kernel | 2.6.32-431.17.1.el6.x86_64
Architecture | CPU = 64-bit, OS = 64-bit
Threading | NPTL 2.12
Compiler | GNU CC version 4.4.7 20120313 (Red Hat 4.4.7-4).
SELinux | Disabled
Virtualized | No virtualization detected
Processors | physical = 2, cores = 16, virtual = 32, hyperthreading = yes
Speeds | 32x2260.906
Models | 32xIntel(R) Xeon(R) CPU X7560 @ 2.27GHz
Caches | 32x24576 KB
Total | 126.0G
Free | 55.5G
Used | physical = 70.5G, swap allocated = 2.0G, swap used = 701.4M, virtual = 71.2G

Attachments: Text File extendstatus1.txt     Text File extendstatus2.txt     PNG File graph_crash at 16h51.png     PNG File memory-day (2).png     PNG File memory-day.png     PNG File munin-production.png     JPEG File munin.jpg     Text File mycnf.txt     PNG File myisam.png     PNG File myisam_week.png    
Issue Links:
Relates
relates to MDEV-18866 Chewing Through Swap Open
relates to MDEV-9533 Query with an aggregate values in ORD... Open
Sprint: 5.5.48-0

 Description   

MariaDB 10.0.11 (and I believe also 10.0.10 before that) gets killed by CentOS' out-of-memory killer with a configuration that worked well for years in several other MySQL versions like MySQL 5.5 and MariaDB 5.3, before we upgraded to MariaDB 10.x.

The server we use has 128GB of ram and MariaDB as the only real workload. Here's the original my.cnf that we've been using a very long time:

port                                = 3306
 
datadir                             = /var/lib/mysql
 
socket                              = /var/lib/mysql/mysql.sock
 
user                                = mysql
 
key_buffer                          = 1536M
 
max_allowed_packet                  = 64M
 
table_open_cache                    = 10000
 
table_definition_cache              = 10000
 
sort_buffer_size                    = 8M
 
read_buffer_size                    = 4M
 
read_rnd_buffer_size                = 8M
 
thread_cache_size                   = 64
 
query_cache_limit                   = 2M
 
query_cache_size                    = 384M
 
query_cache_type                    = 1
 
join_buffer_size                    = 4M
 
thread_concurrency                  = 64
 
tmp_table_size                      = 128M
 
max_heap_table_size                 = 128M
 
max_user_connections                = 350
 
max_connections                     = 450
 
long_query_time                     = 2
 
wait_timeout                        = 7200
 
interactive_timeout                 = 7200
 
log-error                           = /var/log/mysql/error
 
slow_query_log                      = 0
 
slow_query_log_file                 = /var/log/mysql/slow-queries
 
low_priority_updates                = 1
 
concurrent_insert                   = 2
 
myisam-recover
 
myisam_repair_threads               = 1
 
group_concat_max_len                = 1M
 
max_connect_errors                  = 999999999
 
collation_server                    = utf8_unicode_ci
 
character_set_server                = utf8
 
feedback                            = on
 
tmpdir                              = /tmp
 
innodb_data_home_dir                = /var/lib/mysql/
 
innodb_data_file_path               = ibdata1:20M:autoextend
 
innodb_buffer_pool_size             = 80G
 
innodb_buffer_pool_instances        = 16
 
innodb_log_group_home_dir           = /var/lib/mysql/
 
innodb_log_files_in_group           = 2
 
innodb_log_file_size                = 1G
 
innodb_log_buffer_size              = 8M
 
innodb_flush_log_at_trx_commit      = 0
 
innodb_flush_method                 = O_DIRECT
 
innodb_file_per_table               = 1
 
innodb_open_files                   = 10000
 
innodb_lock_wait_timeout            = 7200
 
ft_min_word_len                     = 2
 
ft_stopword_file                    =

We've already reduced the innodb_buffer_pool_size to 50GB in multiple steps. With the 50GB configuration the mysqltuner.pl scripts reports that the maximum amount of memory that MySQL will use is 63GB, which shouldn't be any problem at all on a 128GB server.

Still MySQL gets killed by the OOM-killer at least once a day. This is the part of the /var/log/messages kernel-log for the latest crash. At the last lines you see that mysqld used 123GB of memory at the moment of crash.

Jun  8 17:07:03 hydra kernel: mysqld invoked oom-killer: gfp_mask=0x280da, order=0, oom_adj=0, oom_score_adj=0
 
Jun  8 17:07:03 hydra kernel: mysqld cpuset=/ mems_allowed=0-1
 
Jun  8 17:07:03 hydra kernel: Pid: 81246, comm: mysqld Not tainted 2.6.32-431.17.1.el6.x86_64 #1
 
Jun  8 17:07:03 hydra kernel: Call Trace:
 
Jun  8 17:07:03 hydra kernel: [<ffffffff810d0211>] ? cpuset_print_task_mems_allowed+0x91/0xb0
 
Jun  8 17:07:03 hydra kernel: [<ffffffff811225c0>] ? dump_header+0x90/0x1b0
 
Jun  8 17:07:03 hydra kernel: [<ffffffff8129011d>] ? __bitmap_intersects+0x1d/0xa0
 
Jun  8 17:07:03 hydra kernel: [<ffffffff8122761c>] ? security_real_capable_noaudit+0x3c/0x70
 
Jun  8 17:07:03 hydra kernel: [<ffffffff81122a42>] ? oom_kill_process+0x82/0x2a0
 
Jun  8 17:07:03 hydra kernel: [<ffffffff81122981>] ? select_bad_process+0xe1/0x120
 
Jun  8 17:07:03 hydra kernel: [<ffffffff81122e80>] ? out_of_memory+0x220/0x3c0
 
Jun  8 17:07:03 hydra kernel: [<ffffffff8112f79f>] ? __alloc_pages_nodemask+0x89f/0x8d0
 
Jun  8 17:07:03 hydra kernel: [<ffffffff8116779a>] ? alloc_pages_vma+0x9a/0x150
 
Jun  8 17:07:03 hydra kernel: [<ffffffff8114a89d>] ? handle_pte_fault+0x73d/0xb00
 
Jun  8 17:07:03 hydra kernel: [<ffffffff8100bc8e>] ? invalidate_interrupt4+0xe/0x20
 
Jun  8 17:07:03 hydra kernel: [<ffffffff8114ae8a>] ? handle_mm_fault+0x22a/0x300
 
Jun  8 17:07:03 hydra kernel: [<ffffffff8104a8d8>] ? __do_page_fault+0x138/0x480
 
Jun  8 17:07:03 hydra kernel: [<ffffffff810097cc>] ? __switch_to+0x1ac/0x320
 
Jun  8 17:07:03 hydra kernel: [<ffffffff8100bc2e>] ? invalidate_interrupt1+0xe/0x20
 
Jun  8 17:07:03 hydra kernel: [<ffffffff8100bc6e>] ? invalidate_interrupt3+0xe/0x20
 
Jun  8 17:07:03 hydra kernel: [<ffffffff8152d73e>] ? do_page_fault+0x3e/0xa0
 
Jun  8 17:07:03 hydra kernel: [<ffffffff8152aaf5>] ? page_fault+0x25/0x30
 
Jun  8 17:07:03 hydra kernel: Mem-Info:
 
Jun  8 17:07:03 hydra kernel: Node 0 DMA per-cpu:
 
Jun  8 17:07:03 hydra kernel: CPU    0: hi:    0, btch:   1 usd:   0
 
Jun  8 17:07:03 hydra kernel: CPU    1: hi:    0, btch:   1 usd:   0
 
Jun  8 17:07:03 hydra kernel: CPU    2: hi:    0, btch:   1 usd:   0
 
Jun  8 17:07:03 hydra kernel: CPU    3: hi:    0, btch:   1 usd:   0
 
Jun  8 17:07:03 hydra kernel: CPU    4: hi:    0, btch:   1 usd:   0
 
Jun  8 17:07:03 hydra kernel: CPU    5: hi:    0, btch:   1 usd:   0
 
Jun  8 17:07:03 hydra kernel: CPU    6: hi:    0, btch:   1 usd:   0
 
Jun  8 17:07:03 hydra kernel: CPU    7: hi:    0, btch:   1 usd:   0
 
Jun  8 17:07:03 hydra kernel: CPU    8: hi:    0, btch:   1 usd:   0
 
Jun  8 17:07:03 hydra kernel: CPU    9: hi:    0, btch:   1 usd:   0
 
Jun  8 17:07:03 hydra kernel: CPU   10: hi:    0, btch:   1 usd:   0
 
Jun  8 17:07:03 hydra kernel: CPU   11: hi:    0, btch:   1 usd:   0
 
Jun  8 17:07:03 hydra kernel: CPU   12: hi:    0, btch:   1 usd:   0
 
Jun  8 17:07:03 hydra kernel: CPU   13: hi:    0, btch:   1 usd:   0
 
Jun  8 17:07:03 hydra kernel: CPU   14: hi:    0, btch:   1 usd:   0
 
Jun  8 17:07:03 hydra kernel: CPU   15: hi:    0, btch:   1 usd:   0
 
Jun  8 17:07:03 hydra kernel: CPU   16: hi:    0, btch:   1 usd:   0
 
Jun  8 17:07:03 hydra kernel: CPU   17: hi:    0, btch:   1 usd:   0
 
Jun  8 17:07:03 hydra kernel: CPU   18: hi:    0, btch:   1 usd:   0
 
Jun  8 17:07:03 hydra kernel: CPU   19: hi:    0, btch:   1 usd:   0
 
Jun  8 17:07:03 hydra kernel: CPU   20: hi:    0, btch:   1 usd:   0
 
Jun  8 17:07:03 hydra kernel: CPU   21: hi:    0, btch:   1 usd:   0
 
Jun  8 17:07:03 hydra kernel: CPU   22: hi:    0, btch:   1 usd:   0
 
Jun  8 17:07:03 hydra kernel: CPU   23: hi:    0, btch:   1 usd:   0
 
Jun  8 17:07:03 hydra kernel: CPU   24: hi:    0, btch:   1 usd:   0
 
Jun  8 17:07:03 hydra kernel: CPU   25: hi:    0, btch:   1 usd:   0
 
Jun  8 17:07:03 hydra kernel: CPU   26: hi:    0, btch:   1 usd:   0
 
Jun  8 17:07:03 hydra kernel: CPU   27: hi:    0, btch:   1 usd:   0
 
Jun  8 17:07:03 hydra kernel: CPU   28: hi:    0, btch:   1 usd:   0
 
Jun  8 17:07:03 hydra kernel: CPU   29: hi:    0, btch:   1 usd:   0
 
Jun  8 17:07:03 hydra kernel: CPU   30: hi:    0, btch:   1 usd:   0
 
Jun  8 17:07:03 hydra kernel: CPU   31: hi:    0, btch:   1 usd:   0
 
Jun  8 17:07:03 hydra kernel: Node 0 DMA32 per-cpu:
 
Jun  8 17:07:03 hydra kernel: CPU    0: hi:  186, btch:  31 usd:   0
 
Jun  8 17:07:03 hydra kernel: CPU    1: hi:  186, btch:  31 usd:  22
 
Jun  8 17:07:03 hydra kernel: CPU    2: hi:  186, btch:  31 usd:  30
 
Jun  8 17:07:03 hydra kernel: CPU    3: hi:  186, btch:  31 usd:   3
 
Jun  8 17:07:03 hydra kernel: CPU    4: hi:  186, btch:  31 usd:   0
 
Jun  8 17:07:03 hydra kernel: CPU    5: hi:  186, btch:  31 usd:   8
 
Jun  8 17:07:03 hydra kernel: CPU    6: hi:  186, btch:  31 usd:   0
 
Jun  8 17:07:03 hydra kernel: CPU    7: hi:  186, btch:  31 usd:   0
 
Jun  8 17:07:03 hydra kernel: CPU    8: hi:  186, btch:  31 usd:   0
 
Jun  8 17:07:03 hydra kernel: CPU    9: hi:  186, btch:  31 usd:   0
 
Jun  8 17:07:03 hydra kernel: CPU   10: hi:  186, btch:  31 usd:   3
 
Jun  8 17:07:03 hydra kernel: CPU   11: hi:  186, btch:  31 usd:   0
 
Jun  8 17:07:03 hydra kernel: CPU   12: hi:  186, btch:  31 usd:   7
 
Jun  8 17:07:03 hydra kernel: CPU   13: hi:  186, btch:  31 usd:   0
 
Jun  8 17:07:03 hydra kernel: CPU   14: hi:  186, btch:  31 usd:   0
 
Jun  8 17:07:03 hydra kernel: CPU   15: hi:  186, btch:  31 usd:   0
 
Jun  8 17:07:03 hydra kernel: CPU   16: hi:  186, btch:  31 usd:   0
 
Jun  8 17:07:03 hydra kernel: CPU   17: hi:  186, btch:  31 usd:   0
 
Jun  8 17:07:03 hydra kernel: CPU   18: hi:  186, btch:  31 usd:   0
 
Jun  8 17:07:03 hydra kernel: CPU   19: hi:  186, btch:  31 usd:   0
 
Jun  8 17:07:03 hydra kernel: CPU   20: hi:  186, btch:  31 usd:   0
 
Jun  8 17:07:03 hydra kernel: CPU   21: hi:  186, btch:  31 usd:   0
 
Jun  8 17:07:03 hydra kernel: CPU   22: hi:  186, btch:  31 usd:   0
 
Jun  8 17:07:03 hydra kernel: CPU   23: hi:  186, btch:  31 usd:   0
 
Jun  8 17:07:03 hydra kernel: CPU   24: hi:  186, btch:  31 usd:  22
 
Jun  8 17:07:03 hydra kernel: CPU   25: hi:  186, btch:  31 usd:   0
 
Jun  8 17:07:03 hydra kernel: CPU   26: hi:  186, btch:  31 usd:   0
 
Jun  8 17:07:03 hydra kernel: CPU   27: hi:  186, btch:  31 usd:   0
 
Jun  8 17:07:03 hydra kernel: CPU   28: hi:  186, btch:  31 usd:   0
 
Jun  8 17:07:03 hydra kernel: CPU   29: hi:  186, btch:  31 usd:   0
 
Jun  8 17:07:03 hydra kernel: CPU   30: hi:  186, btch:  31 usd:   0
 
Jun  8 17:07:03 hydra kernel: CPU   31: hi:  186, btch:  31 usd:   0
 
Jun  8 17:07:03 hydra kernel: Node 0 Normal per-cpu:
 
Jun  8 17:07:03 hydra kernel: CPU    0: hi:  186, btch:  31 usd:   7
 
Jun  8 17:07:03 hydra kernel: CPU    1: hi:  186, btch:  31 usd:   0
 
Jun  8 17:07:03 hydra kernel: CPU    2: hi:  186, btch:  31 usd:   8
 
Jun  8 17:07:03 hydra kernel: CPU    3: hi:  186, btch:  31 usd:   5
 
Jun  8 17:07:03 hydra kernel: CPU    4: hi:  186, btch:  31 usd:   0
 
Jun  8 17:07:03 hydra kernel: CPU    5: hi:  186, btch:  31 usd:   0
 
Jun  8 17:07:03 hydra kernel: CPU    6: hi:  186, btch:  31 usd:   0
 
Jun  8 17:07:03 hydra kernel: CPU    7: hi:  186, btch:  31 usd:   4
 
Jun  8 17:07:03 hydra kernel: CPU    8: hi:  186, btch:  31 usd:   0
 
Jun  8 17:07:03 hydra kernel: CPU    9: hi:  186, btch:  31 usd:   0
 
Jun  8 17:07:03 hydra kernel: CPU   10: hi:  186, btch:  31 usd:   3
 
Jun  8 17:07:03 hydra kernel: CPU   11: hi:  186, btch:  31 usd:   0
 
Jun  8 17:07:03 hydra kernel: CPU   12: hi:  186, btch:  31 usd:   0
 
Jun  8 17:07:03 hydra kernel: CPU   13: hi:  186, btch:  31 usd:   0
 
Jun  8 17:07:03 hydra kernel: CPU   14: hi:  186, btch:  31 usd:   0
 
Jun  8 17:07:03 hydra kernel: CPU   15: hi:  186, btch:  31 usd:   0
 
Jun  8 17:07:03 hydra kernel: CPU   16: hi:  186, btch:  31 usd:   1
 
Jun  8 17:07:03 hydra kernel: CPU   17: hi:  186, btch:  31 usd:   0
 
Jun  8 17:07:03 hydra kernel: CPU   18: hi:  186, btch:  31 usd:   0
 
Jun  8 17:07:03 hydra kernel: CPU   19: hi:  186, btch:  31 usd:   0
 
Jun  8 17:07:03 hydra kernel: CPU   20: hi:  186, btch:  31 usd:   0
 
Jun  8 17:07:03 hydra kernel: CPU   21: hi:  186, btch:  31 usd:   0
 
Jun  8 17:07:03 hydra kernel: CPU   22: hi:  186, btch:  31 usd:   0
 
Jun  8 17:07:03 hydra kernel: CPU   23: hi:  186, btch:  31 usd:   0
 
Jun  8 17:07:03 hydra kernel: CPU   24: hi:  186, btch:  31 usd:  30
 
Jun  8 17:07:03 hydra kernel: CPU   25: hi:  186, btch:  31 usd:   0
 
Jun  8 17:07:03 hydra kernel: CPU   26: hi:  186, btch:  31 usd:   0
 
Jun  8 17:07:03 hydra kernel: CPU   27: hi:  186, btch:  31 usd:   0
 
Jun  8 17:07:03 hydra kernel: CPU   28: hi:  186, btch:  31 usd:   0
 
Jun  8 17:07:03 hydra kernel: CPU   29: hi:  186, btch:  31 usd:   0
 
Jun  8 17:07:03 hydra kernel: CPU   30: hi:  186, btch:  31 usd:   0
 
Jun  8 17:07:03 hydra kernel: CPU   31: hi:  186, btch:  31 usd:   0
 
Jun  8 17:07:03 hydra kernel: Node 1 Normal per-cpu:
 
Jun  8 17:07:03 hydra kernel: CPU    0: hi:  186, btch:  31 usd:  26
 
Jun  8 17:07:03 hydra kernel: CPU    1: hi:  186, btch:  31 usd:   0
 
Jun  8 17:07:03 hydra kernel: CPU    2: hi:  186, btch:  31 usd:   0
 
Jun  8 17:07:03 hydra kernel: CPU    3: hi:  186, btch:  31 usd:  30
 
Jun  8 17:07:03 hydra kernel: CPU    4: hi:  186, btch:  31 usd:   0
 
Jun  8 17:07:03 hydra kernel: CPU    5: hi:  186, btch:  31 usd:  17
 
Jun  8 17:07:03 hydra kernel: CPU    6: hi:  186, btch:  31 usd:   0
 
Jun  8 17:07:03 hydra kernel: CPU    7: hi:  186, btch:  31 usd:   0
 
Jun  8 17:07:03 hydra kernel: CPU    8: hi:  186, btch:  31 usd:   0
 
Jun  8 17:07:03 hydra kernel: CPU    9: hi:  186, btch:  31 usd:   0
 
Jun  8 17:07:03 hydra kernel: CPU   10: hi:  186, btch:  31 usd:  24
 
Jun  8 17:07:03 hydra kernel: CPU   11: hi:  186, btch:  31 usd:   0
 
Jun  8 17:07:03 hydra kernel: CPU   12: hi:  186, btch:  31 usd:   0
 
Jun  8 17:07:03 hydra kernel: CPU   13: hi:  186, btch:  31 usd:   0
 
Jun  8 17:07:03 hydra kernel: CPU   14: hi:  186, btch:  31 usd:   0
 
Jun  8 17:07:03 hydra kernel: CPU   15: hi:  186, btch:  31 usd:   0
 
Jun  8 17:07:03 hydra kernel: CPU   16: hi:  186, btch:  31 usd:   0
 
Jun  8 17:07:03 hydra kernel: CPU   17: hi:  186, btch:  31 usd:   0
 
Jun  8 17:07:03 hydra kernel: CPU   18: hi:  186, btch:  31 usd:   0
 
Jun  8 17:07:03 hydra kernel: CPU   19: hi:  186, btch:  31 usd:   0
 
Jun  8 17:07:03 hydra kernel: CPU   20: hi:  186, btch:  31 usd:   0
 
Jun  8 17:07:03 hydra kernel: CPU   21: hi:  186, btch:  31 usd:   0
 
Jun  8 17:07:03 hydra kernel: CPU   22: hi:  186, btch:  31 usd:   0
 
Jun  8 17:07:03 hydra kernel: CPU   23: hi:  186, btch:  31 usd:   0
 
Jun  8 17:07:03 hydra kernel: CPU   24: hi:  186, btch:  31 usd:  30
 
Jun  8 17:07:03 hydra kernel: CPU   25: hi:  186, btch:  31 usd:  28
 
Jun  8 17:07:03 hydra kernel: CPU   26: hi:  186, btch:  31 usd:   0
 
Jun  8 17:07:03 hydra kernel: CPU   27: hi:  186, btch:  31 usd:   0
 
Jun  8 17:07:03 hydra kernel: CPU   28: hi:  186, btch:  31 usd:   0
 
Jun  8 17:07:03 hydra kernel: CPU   29: hi:  186, btch:  31 usd:   0
 
Jun  8 17:07:03 hydra kernel: CPU   30: hi:  186, btch:  31 usd:   0
 
Jun  8 17:07:03 hydra kernel: CPU   31: hi:  186, btch:  31 usd:   0
 
Jun  8 17:07:03 hydra kernel: active_anon:31249425 inactive_anon:1380038 isolated_anon:1344
 
Jun  8 17:07:03 hydra kernel: active_file:3585 inactive_file:2447 isolated_file:0
 
Jun  8 17:07:03 hydra kernel: unevictable:0 dirty:1453 writeback:1295 unstable:0
 
Jun  8 17:07:03 hydra kernel: free:88927 slab_reclaimable:19247 slab_unreclaimable:20626
 
Jun  8 17:07:03 hydra kernel: mapped:3032 shmem:1 pagetables:77575 bounce:0
 
Jun  8 17:07:03 hydra kernel: Node 0 DMA free:15240kB min:8kB low:8kB high:12kB active_anon:0kB inactive_anon:0kB active_file:0kB inactive_file:0kB unevictable:0kB isolated(anon):0kB isolated(file):0kB present:14860kB mlocked:0kB dirty:0kB writeback:0kB mapped:0kB shmem:0kB slab_reclaimable:0kB slab_unreclaimable:0kB kernel_stack:0kB pagetables:0kB unstable:0kB bounce:0kB writeback_tmp:0kB pages_scanned:0 all_unreclaimable? yes
 
Jun  8 17:07:03 hydra kernel: lowmem_reserve[]: 0 1963 64583 64583
 
Jun  8 17:07:03 hydra kernel: Node 0 DMA32 free:251840kB min:1368kB low:1708kB high:2052kB active_anon:334952kB inactive_anon:331512kB active_file:76kB inactive_file:128kB unevictable:0kB isolated(anon):512kB isolated(file):0kB present:2010560kB mlocked:0kB dirty:76kB writeback:32kB mapped:88kB shmem:0kB slab_reclaimable:184kB slab_unreclaimable:1076kB kernel_stack:48kB pagetables:2928kB unstable:0kB bounce:0kB writeback_tmp:0kB pages_scanned:448 all_unreclaimable? no
 
Jun  8 17:07:03 hydra kernel: lowmem_reserve[]: 0 0 62620 62620
 
Jun  8 17:07:03 hydra kernel: Node 0 Normal free:43648kB min:43660kB low:54572kB high:65488kB active_anon:61743464kB inactive_anon:2569912kB active_file:6736kB inactive_file:4912kB unevictable:0kB isolated(anon):3200kB isolated(file):0kB present:64122880kB mlocked:0kB dirty:3488kB writeback:0kB mapped:5320kB shmem:0kB slab_reclaimable:39256kB slab_unreclaimable:49908kB kernel_stack:9056kB pagetables:168272kB unstable:0kB bounce:0kB writeback_tmp:0kB pages_scanned:7648 all_unreclaimable? no
 
Jun  8 17:07:03 hydra kernel: lowmem_reserve[]: 0 0 0 0
 
Jun  8 17:07:03 hydra kernel: Node 1 Normal free:44980kB min:45068kB low:56332kB high:67600kB active_anon:62919284kB inactive_anon:2618728kB active_file:7528kB inactive_file:4748kB unevictable:0kB isolated(anon):1664kB isolated(file):0kB present:66191360kB mlocked:0kB dirty:2248kB writeback:5568kB mapped:6720kB shmem:4kB slab_reclaimable:37548kB slab_unreclaimable:31520kB kernel_stack:3688kB pagetables:139100kB unstable:0kB bounce:0kB writeback_tmp:0kB pages_scanned:8215 all_unreclaimable? no
 
Jun  8 17:07:03 hydra kernel: lowmem_reserve[]: 0 0 0 0
 
Jun  8 17:07:03 hydra kernel: Node 0 DMA: 2*4kB 2*8kB 3*16kB 2*32kB 0*64kB 0*128kB 1*256kB 1*512kB 0*1024kB 1*2048kB 3*4096kB = 15240kB
 
Jun  8 17:07:03 hydra kernel: Node 0 DMA32: 66*4kB 69*8kB 75*16kB 45*32kB 57*64kB 34*128kB 17*256kB 13*512kB 6*1024kB 3*2048kB 53*4096kB = 251840kB
 
Jun  8 17:07:03 hydra kernel: Node 0 Normal: 9712*4kB 347*8kB 30*16kB 1*32kB 0*64kB 1*128kB 0*256kB 1*512kB 1*1024kB 1*2048kB 0*4096kB = 45848kB
 
Jun  8 17:07:03 hydra kernel: Node 1 Normal: 10142*4kB 382*8kB 6*16kB 1*32kB 0*64kB 2*128kB 0*256kB 1*512kB 1*1024kB 1*2048kB 0*4096kB = 47592kB
 
Jun  8 17:07:03 hydra kernel: 95591 total pagecache pages
 
Jun  8 17:07:03 hydra kernel: 90149 pages in swap cache
 
Jun  8 17:07:03 hydra kernel: Swap cache stats: add 13260661, delete 13170512, find 14306957/14869509
 
Jun  8 17:07:03 hydra kernel: Free swap  = 0kB
 
Jun  8 17:07:03 hydra kernel: Total swap = 2097144kB
 
Jun  8 17:07:03 hydra kernel: 33554431 pages RAM
 
Jun  8 17:07:03 hydra kernel: 519760 pages reserved
 
Jun  8 17:07:03 hydra kernel: 10698 pages shared
 
Jun  8 17:07:03 hydra kernel: 32928576 pages non-shared
 
Jun  8 17:07:03 hydra kernel: [ pid ]   uid  tgid total_vm      rss cpu oom_adj oom_score_adj name
 
Jun  8 17:07:03 hydra kernel: [  853]     0   853     2780        1   1     -17         -1000 udevd
 
Jun  8 17:07:03 hydra kernel: [ 1610]     0  1610    23300       88  17     -17         -1000 auditd
 
Jun  8 17:07:03 hydra kernel: [ 1626]     0  1626    62367      904   1       0             0 rsyslogd
 
Jun  8 17:07:03 hydra kernel: [ 1655]    81  1655     5351        2   0       0             0 dbus-daemon
 
Jun  8 17:07:03 hydra kernel: [ 1692]     0  1692    49448      251  22       0             0 snmpd
 
Jun  8 17:07:03 hydra kernel: [ 1698]     0  1698    63771      211  13       0             0 lsi_mrdsnmpagen
 
Jun  8 17:07:03 hydra kernel: [ 1711]     0  1711    16652       52  18     -17         -1000 sshd
 
Jun  8 17:07:03 hydra kernel: [ 1745]     0  1745     5223       24   0       0             0 lsi_mrdsnmpagen
 
Jun  8 17:07:03 hydra kernel: [ 2113]    93  2113    23413       28  17       0             0 exim
 
Jun  8 17:07:03 hydra kernel: [ 2174]   496  2174     2707       35  29       0             0 epmd
 
Jun  8 17:07:03 hydra kernel: [ 2226]     0  2226    27109        1   0       0             0 S80rabbitmq-ser
 
Jun  8 17:07:03 hydra kernel: [ 2239]     0  2239    27041        2  18       0             0 bash
 
Jun  8 17:07:03 hydra kernel: [ 2240]     0  2240    27041        2   4       0             0 rabbitmq-server
 
Jun  8 17:07:03 hydra kernel: [ 2253]     0  2253    36359        2  20       0             0 su
 
Jun  8 17:07:03 hydra kernel: [ 2260]   496  2260   650702     6906  18       0             0 beam.smp
 
Jun  8 17:07:03 hydra kernel: [ 2430]   496  2430     2698        2   0       0             0 inet_gethost
 
Jun  8 17:07:03 hydra kernel: [ 2431]   496  2431     4280        2   0       0             0 inet_gethost
 
Jun  8 17:07:03 hydra kernel: [ 2439]     0  2439    29325       76  12       0             0 crond
 
Jun  8 17:07:03 hydra kernel: [ 2450]     0  2450     5385        9  19       0             0 atd
 
Jun  8 17:07:03 hydra kernel: [ 2466]     0  2466    27041        2   3       0             0 sh
 
Jun  8 17:07:03 hydra kernel: [ 2471]     0  2471  8801199    17711   0       0             0 java
 
Jun  8 17:07:03 hydra kernel: [ 2508]     0  2508    23103      349  19       0             0 miniserv.pl
 
Jun  8 17:07:03 hydra kernel: [ 2517]     0  2517     1016        2   2       0             0 mingetty
 
Jun  8 17:07:03 hydra kernel: [ 2519]     0  2519     1016        2   2       0             0 mingetty
 
Jun  8 17:07:03 hydra kernel: [ 2521]     0  2521     1016        2  25       0             0 mingetty
 
Jun  8 17:07:03 hydra kernel: [ 2523]     0  2523     1016        2   2       0             0 mingetty
 
Jun  8 17:07:03 hydra kernel: [ 2527]     0  2527     1016        2   0       0             0 mingetty
 
Jun  8 17:07:03 hydra kernel: [ 2529]     0  2529     1016        2  19       0             0 mingetty
 
Jun  8 17:07:03 hydra kernel: [ 2703]     0  2703  8779693       71   0       0             0 java
 
Jun  8 17:07:03 hydra kernel: [ 3414]     0  3414     2779        1   1     -17         -1000 udevd
 
Jun  8 17:07:03 hydra kernel: [ 3415]     0  3415     2779        1  17     -17         -1000 udevd
 
Jun  8 17:07:03 hydra kernel: [81327]   495 81327  7355427  1578291  19       0             0 java
 
Jun  8 17:07:03 hydra kernel: [30759]     0 30759    26549       83  17       0             0 mysqld_safe
 
Jun  8 17:07:03 hydra kernel: [30993]   498 30993 37697878 30935404   0       0             0 mysqld
 
Jun  8 17:07:03 hydra kernel: [31129]     0 31129    35792      475   8       0             0 munin-node
 
Jun  8 17:07:03 hydra kernel: [32419]     0 32419    29810      290  19       0             0 screen
 
Jun  8 17:07:03 hydra kernel: [32420]     0 32420    27109      216   2       0             0 bash
 
Jun  8 17:07:03 hydra kernel: [74824]     0 74824     5545      144   1       0             0 xinetd
 
Jun  8 17:07:03 hydra kernel: [77251]     0 77251    26515      130   2       0             0 memorylog
 
Jun  8 17:07:03 hydra kernel: [77410]     0 77410     1532       92   1       0             0 vmstat
 
Jun  8 17:07:03 hydra kernel: [14379]     0 14379    25227       77  16       0             0 sleep
 
Jun  8 17:07:03 hydra kernel: [14671]     0 14671    35046      193   1       0             0 crond
 
Jun  8 17:07:03 hydra kernel: [14672]     0 14672    35046      193  17       0             0 crond
 
Jun  8 17:07:03 hydra kernel: [14690]     0 14690    26515      135   2       0             0 backup-blieb
 
Jun  8 17:07:03 hydra kernel: [14691]     0 14691    26515      134  19       0             0 bash
 
Jun  8 17:07:03 hydra kernel: [14693]     0 14693    26515      135  18       0             0 updatehits
 
Jun  8 17:07:03 hydra kernel: [14733]     0 14733    56394      379   0       0             0 mysql
 
Jun  8 17:07:03 hydra kernel: [14734]     0 14734    31785      372  21       0             0 mysqldump
 
Jun  8 17:07:03 hydra kernel: [14735]     0 14735     1074       85   1       0             0 gzip
 
Jun  8 17:07:03 hydra kernel: [14788]     0 14788    25356     4879  18       0             0 miniserv.pl
 
Jun  8 17:07:03 hydra kernel: Out of memory: Kill process 30993 (mysqld) score 934 or sacrifice child
 
Jun  8 17:07:03 hydra kernel: Killed process 30993, UID 498, (mysqld) total-vm:150791512kB, anon-rss:123736464kB, file-rss:5148kB

The mysql error log doesn't show anything at the moment the process gets killed.

I've attached an image of the munin memory usage graph of the server, where you clearly see the MariaDB reset at 17:07. If I understand correctly, it looks like MariaDB is allocation a lot of memory, while not really using it.

Could this be a bug in MariaDB 10.x? What can I provide to help you find it?

 Comments   
Comment by Elena Stepanova [ 2014-06-10 ]

Hi,

First, unless you use performance schema, please try to disable it by setting performance_schema=0 in the cnf file.
If you don't know whether you need the performance schema, most likely you don't.
If you ever need it, you can enable it back (changing the value requires the server restart though).

Performance schema is not supposed to allocate any additional memory after it was initialized on startup, but things happen, and it would be helpful to rule out at least one possible point of failure.

Then, could you please let us know which experiments you are able to perform in your environment – e.g. run debug builds, run server with valgrind, etc.
If it's an active production server, you probably can't do much, if it's staging or a slow/unimportant production, maybe you can. When we know that, we might be able to come up with some ideas.

Thanks.

Comment by Koen Crijns [ 2014-06-10 ]

Hi Elena,

Thanks for the suggestion. I've added performance_schema = 0 to our my.cnf. If the servers kills and restarts mysqld it should run without performance schema next time.

As a quick update: I've reverted to MariaDB 10.0.10 yesterday evening (23 hours ago). So far mysqld hasn't been killed by the OOM-killer yet. Still mysqld allocates much more memory than it actually uses.

ps aux shows this for mysqld:
mysql 3581 557 39.8 147816480 52637352 pts/2 Sl Jun09 7702:44 /usr/sbin/mysqld --basedir=/usr --datadir=/var/lib/mysql --plugin-dir=/usr/lib64/mysql/plugin --user=mysql --log-error=/var/log/mysql/error.err --pid-file=/var/lib/mysql/hydra.hwigroup.com.pid --socket=/var/lib/mysql/mysql.sock --port=3306

I.e.: 140,9 GB (147816480 kB) requested (committed), 50,2 GB (52637352 kB) actually used.

You can also see it "live" on the graph here (third graph):
http://nl.hardware.info/extra/serverinfo#tab:hydra

The green part is the actually used memory. The green line (which goes well above the available memory) is the committed memory.

It is a highly used production server. So our possibilities for debugging are quite minimal I'm afraid (although we definitely like to help to find a solution).

Comment by Koen Crijns [ 2014-06-11 ]

And it crashed again, so we've proved the problem also exists with 10.0.10. Here's the log from /var/log/messages:

Jun 11 07:17:06 hydra kernel: mysqld invoked oom-killer: gfp_mask=0x280da, order=0, oom_adj=0, oom_score_adj=0
 
Jun 11 07:17:06 hydra kernel: mysqld cpuset=/ mems_allowed=0-1
 
Jun 11 07:17:06 hydra kernel: Pid: 41839, comm: mysqld Not tainted 2.6.32-431.17.1.el6.x86_64 #1
 
Jun 11 07:17:06 hydra kernel: Call Trace:
 
Jun 11 07:17:06 hydra kernel: [<ffffffff810d0211>] ? cpuset_print_task_mems_allowed+0x91/0xb0
 
Jun 11 07:17:06 hydra kernel: [<ffffffff811225c0>] ? dump_header+0x90/0x1b0
 
Jun 11 07:17:06 hydra kernel: [<ffffffff8122761c>] ? security_real_capable_noaudit+0x3c/0x70
 
Jun 11 07:17:06 hydra kernel: [<ffffffff81122a42>] ? oom_kill_process+0x82/0x2a0
 
Jun 11 07:17:06 hydra kernel: [<ffffffff81122981>] ? select_bad_process+0xe1/0x120
 
Jun 11 07:17:06 hydra kernel: [<ffffffff81122e80>] ? out_of_memory+0x220/0x3c0
 
Jun 11 07:17:06 hydra kernel: [<ffffffff81140cd1>] ? next_zones_zonelist+0x1/0x60
 
Jun 11 07:17:06 hydra kernel: [<ffffffff8112f79f>] ? __alloc_pages_nodemask+0x89f/0x8d0
 
Jun 11 07:17:06 hydra kernel: [<ffffffff8116779a>] ? alloc_pages_vma+0x9a/0x150
 
Jun 11 07:17:06 hydra kernel: [<ffffffff8114a89d>] ? handle_pte_fault+0x73d/0xb00
 
Jun 11 07:17:06 hydra kernel: [<ffffffff8105559d>] ? check_preempt_curr+0x6d/0x90
 
Jun 11 07:17:06 hydra kernel: [<ffffffff8100bcae>] ? invalidate_interrupt5+0xe/0x20
 
Jun 11 07:17:06 hydra kernel: [<ffffffff8114ae8a>] ? handle_mm_fault+0x22a/0x300
 
Jun 11 07:17:06 hydra kernel: [<ffffffff8104a8d8>] ? __do_page_fault+0x138/0x480
 
Jun 11 07:17:06 hydra kernel: [<ffffffff8105dabf>] ? finish_task_switch+0x4f/0xf0
 
Jun 11 07:17:06 hydra kernel: [<ffffffff81527bfe>] ? thread_return+0x4e/0x760
 
Jun 11 07:17:06 hydra kernel: [<ffffffff8152d73e>] ? do_page_fault+0x3e/0xa0
 
Jun 11 07:17:06 hydra kernel: [<ffffffff8152aaf5>] ? page_fault+0x25/0x30
 
Jun 11 07:17:06 hydra kernel: Mem-Info:
 
Jun 11 07:17:06 hydra kernel: Node 0 DMA per-cpu:
 
Jun 11 07:17:06 hydra kernel: CPU    0: hi:    0, btch:   1 usd:   0
 
Jun 11 07:17:06 hydra kernel: CPU    1: hi:    0, btch:   1 usd:   0
 
Jun 11 07:17:06 hydra kernel: CPU    2: hi:    0, btch:   1 usd:   0
 
Jun 11 07:17:06 hydra kernel: CPU    3: hi:    0, btch:   1 usd:   0
 
Jun 11 07:17:06 hydra kernel: CPU    4: hi:    0, btch:   1 usd:   0
 
Jun 11 07:17:06 hydra kernel: CPU    5: hi:    0, btch:   1 usd:   0
 
Jun 11 07:17:06 hydra kernel: CPU    6: hi:    0, btch:   1 usd:   0
 
Jun 11 07:17:06 hydra kernel: CPU    7: hi:    0, btch:   1 usd:   0
 
Jun 11 07:17:06 hydra kernel: CPU    8: hi:    0, btch:   1 usd:   0
 
Jun 11 07:17:06 hydra kernel: CPU    9: hi:    0, btch:   1 usd:   0
 
Jun 11 07:17:06 hydra kernel: CPU   10: hi:    0, btch:   1 usd:   0
 
Jun 11 07:17:06 hydra kernel: CPU   11: hi:    0, btch:   1 usd:   0
 
Jun 11 07:17:06 hydra kernel: CPU   12: hi:    0, btch:   1 usd:   0
 
Jun 11 07:17:06 hydra kernel: CPU   13: hi:    0, btch:   1 usd:   0
 
Jun 11 07:17:06 hydra kernel: CPU   14: hi:    0, btch:   1 usd:   0
 
Jun 11 07:17:06 hydra kernel: CPU   15: hi:    0, btch:   1 usd:   0
 
Jun 11 07:17:06 hydra kernel: CPU   16: hi:    0, btch:   1 usd:   0
 
Jun 11 07:17:06 hydra kernel: CPU   17: hi:    0, btch:   1 usd:   0
 
Jun 11 07:17:06 hydra kernel: CPU   18: hi:    0, btch:   1 usd:   0
 
Jun 11 07:17:06 hydra kernel: CPU   19: hi:    0, btch:   1 usd:   0
 
Jun 11 07:17:06 hydra kernel: CPU   20: hi:    0, btch:   1 usd:   0
 
Jun 11 07:17:06 hydra kernel: CPU   21: hi:    0, btch:   1 usd:   0
 
Jun 11 07:17:06 hydra kernel: CPU   22: hi:    0, btch:   1 usd:   0
 
Jun 11 07:17:06 hydra kernel: CPU   23: hi:    0, btch:   1 usd:   0
 
Jun 11 07:17:06 hydra kernel: CPU   24: hi:    0, btch:   1 usd:   0
 
Jun 11 07:17:06 hydra kernel: CPU   25: hi:    0, btch:   1 usd:   0
 
Jun 11 07:17:06 hydra kernel: CPU   26: hi:    0, btch:   1 usd:   0
 
Jun 11 07:17:06 hydra kernel: CPU   27: hi:    0, btch:   1 usd:   0
 
Jun 11 07:17:06 hydra kernel: CPU   28: hi:    0, btch:   1 usd:   0
 
Jun 11 07:17:06 hydra kernel: CPU   29: hi:    0, btch:   1 usd:   0
 
Jun 11 07:17:06 hydra kernel: CPU   30: hi:    0, btch:   1 usd:   0
 
Jun 11 07:17:06 hydra kernel: CPU   31: hi:    0, btch:   1 usd:   0
 
Jun 11 07:17:06 hydra kernel: Node 0 DMA32 per-cpu:
 
Jun 11 07:17:06 hydra kernel: CPU    0: hi:  186, btch:  31 usd:   0
 
Jun 11 07:17:06 hydra kernel: CPU    1: hi:  186, btch:  31 usd:   0
 
Jun 11 07:17:06 hydra kernel: CPU    2: hi:  186, btch:  31 usd:   0
 
Jun 11 07:17:06 hydra kernel: CPU    3: hi:  186, btch:  31 usd:   0
 
Jun 11 07:17:06 hydra kernel: CPU    4: hi:  186, btch:  31 usd:   0
 
Jun 11 07:17:06 hydra kernel: CPU    5: hi:  186, btch:  31 usd:   0
 
Jun 11 07:17:06 hydra kernel: CPU    6: hi:  186, btch:  31 usd:   0
 
Jun 11 07:17:06 hydra kernel: CPU    7: hi:  186, btch:  31 usd:   0
 
Jun 11 07:17:06 hydra kernel: CPU    8: hi:  186, btch:  31 usd:  30
 
Jun 11 07:17:06 hydra kernel: CPU    9: hi:  186, btch:  31 usd:   0
 
Jun 11 07:17:06 hydra kernel: CPU   10: hi:  186, btch:  31 usd:   0
 
Jun 11 07:17:06 hydra kernel: CPU   11: hi:  186, btch:  31 usd:   0
 
Jun 11 07:17:06 hydra kernel: CPU   12: hi:  186, btch:  31 usd:   0
 
Jun 11 07:17:06 hydra kernel: CPU   13: hi:  186, btch:  31 usd:   0
 
Jun 11 07:17:06 hydra kernel: CPU   14: hi:  186, btch:  31 usd:   0
 
Jun 11 07:17:06 hydra kernel: CPU   15: hi:  186, btch:  31 usd:   0
 
Jun 11 07:17:06 hydra kernel: CPU   16: hi:  186, btch:  31 usd:   0
 
Jun 11 07:17:06 hydra kernel: CPU   17: hi:  186, btch:  31 usd:   0
 
Jun 11 07:17:06 hydra kernel: CPU   18: hi:  186, btch:  31 usd:   0
 
Jun 11 07:17:06 hydra kernel: CPU   19: hi:  186, btch:  31 usd:   0
 
Jun 11 07:17:06 hydra kernel: CPU   20: hi:  186, btch:  31 usd:  30
 
Jun 11 07:17:06 hydra kernel: CPU   21: hi:  186, btch:  31 usd:   0
 
Jun 11 07:17:06 hydra kernel: CPU   22: hi:  186, btch:  31 usd:   0
 
Jun 11 07:17:06 hydra kernel: CPU   23: hi:  186, btch:  31 usd:   0
 
Jun 11 07:17:06 hydra kernel: CPU   24: hi:  186, btch:  31 usd:   0
 
Jun 11 07:17:06 hydra kernel: CPU   25: hi:  186, btch:  31 usd:   0
 
Jun 11 07:17:06 hydra kernel: CPU   26: hi:  186, btch:  31 usd:   0
 
Jun 11 07:17:06 hydra kernel: CPU   27: hi:  186, btch:  31 usd:   0
 
Jun 11 07:17:06 hydra kernel: CPU   28: hi:  186, btch:  31 usd:   0
 
Jun 11 07:17:06 hydra kernel: CPU   29: hi:  186, btch:  31 usd:   0
 
Jun 11 07:17:06 hydra kernel: CPU   30: hi:  186, btch:  31 usd:   0
 
Jun 11 07:17:06 hydra kernel: CPU   31: hi:  186, btch:  31 usd:   0
 
Jun 11 07:17:06 hydra kernel: Node 0 Normal per-cpu:
 
Jun 11 07:17:06 hydra kernel: CPU    0: hi:  186, btch:  31 usd:   0
 
Jun 11 07:17:06 hydra kernel: CPU    1: hi:  186, btch:  31 usd:   0
 
Jun 11 07:17:06 hydra kernel: CPU    2: hi:  186, btch:  31 usd:   0
 
Jun 11 07:17:06 hydra kernel: CPU    3: hi:  186, btch:  31 usd:   0
 
Jun 11 07:17:06 hydra kernel: CPU    4: hi:  186, btch:  31 usd:   0
 
Jun 11 07:17:06 hydra kernel: CPU    5: hi:  186, btch:  31 usd:   0
 
Jun 11 07:17:06 hydra kernel: CPU    6: hi:  186, btch:  31 usd:   0
 
Jun 11 07:17:06 hydra kernel: CPU    7: hi:  186, btch:  31 usd:   0
 
Jun 11 07:17:06 hydra kernel: CPU    8: hi:  186, btch:  31 usd:   0
 
Jun 11 07:17:06 hydra kernel: CPU    9: hi:  186, btch:  31 usd:   0
 
Jun 11 07:17:06 hydra kernel: CPU   10: hi:  186, btch:  31 usd:   0
 
Jun 11 07:17:06 hydra kernel: CPU   11: hi:  186, btch:  31 usd:   0
 
Jun 11 07:17:06 hydra kernel: CPU   12: hi:  186, btch:  31 usd:   0
 
Jun 11 07:17:06 hydra kernel: CPU   13: hi:  186, btch:  31 usd:   0
 
Jun 11 07:17:06 hydra kernel: CPU   14: hi:  186, btch:  31 usd:   0
 
Jun 11 07:17:06 hydra kernel: CPU   15: hi:  186, btch:  31 usd:   0
 
Jun 11 07:17:06 hydra kernel: CPU   16: hi:  186, btch:  31 usd:   0
 
Jun 11 07:17:06 hydra kernel: CPU   17: hi:  186, btch:  31 usd:   0
 
Jun 11 07:17:06 hydra kernel: CPU   18: hi:  186, btch:  31 usd:   0
 
Jun 11 07:17:06 hydra kernel: CPU   19: hi:  186, btch:  31 usd:   0
 
Jun 11 07:17:06 hydra kernel: CPU   20: hi:  186, btch:  31 usd:   0
 
Jun 11 07:17:06 hydra kernel: CPU   21: hi:  186, btch:  31 usd:   0
 
Jun 11 07:17:06 hydra kernel: CPU   22: hi:  186, btch:  31 usd:   0
 
Jun 11 07:17:06 hydra kernel: CPU   23: hi:  186, btch:  31 usd:   0
 
Jun 11 07:17:06 hydra kernel: CPU   24: hi:  186, btch:  31 usd:   0
 
Jun 11 07:17:06 hydra kernel: CPU   25: hi:  186, btch:  31 usd:   0
 
Jun 11 07:17:06 hydra kernel: CPU   26: hi:  186, btch:  31 usd:   0
 
Jun 11 07:17:06 hydra kernel: CPU   27: hi:  186, btch:  31 usd:   0
 
Jun 11 07:17:06 hydra kernel: CPU   28: hi:  186, btch:  31 usd:   0
 
Jun 11 07:17:06 hydra kernel: CPU   29: hi:  186, btch:  31 usd:   0
 
Jun 11 07:17:06 hydra kernel: CPU   30: hi:  186, btch:  31 usd:   0
 
Jun 11 07:17:06 hydra kernel: CPU   31: hi:  186, btch:  31 usd:   0
 
Jun 11 07:17:06 hydra kernel: Node 1 Normal per-cpu:
 
Jun 11 07:17:06 hydra kernel: CPU    0: hi:  186, btch:  31 usd:   0
 
Jun 11 07:17:06 hydra kernel: CPU    1: hi:  186, btch:  31 usd:   0
 
Jun 11 07:17:06 hydra kernel: CPU    2: hi:  186, btch:  31 usd:   0
 
Jun 11 07:17:06 hydra kernel: CPU    3: hi:  186, btch:  31 usd:   0
 
Jun 11 07:17:06 hydra kernel: CPU    4: hi:  186, btch:  31 usd:   0
 
Jun 11 07:17:06 hydra kernel: CPU    5: hi:  186, btch:  31 usd:   0
 
Jun 11 07:17:06 hydra kernel: CPU    6: hi:  186, btch:  31 usd:   0
 
Jun 11 07:17:06 hydra kernel: CPU    7: hi:  186, btch:  31 usd:   0
 
Jun 11 07:17:06 hydra kernel: CPU    8: hi:  186, btch:  31 usd:   0
 
Jun 11 07:17:06 hydra kernel: CPU    9: hi:  186, btch:  31 usd:   0
 
Jun 11 07:17:06 hydra kernel: CPU   10: hi:  186, btch:  31 usd:   0
 
Jun 11 07:17:06 hydra kernel: CPU   11: hi:  186, btch:  31 usd:   0
 
Jun 11 07:17:06 hydra kernel: CPU   12: hi:  186, btch:  31 usd:   0
 
Jun 11 07:17:06 hydra kernel: CPU   13: hi:  186, btch:  31 usd:   0
 
Jun 11 07:17:06 hydra kernel: CPU   14: hi:  186, btch:  31 usd:   0
 
Jun 11 07:17:06 hydra kernel: CPU   15: hi:  186, btch:  31 usd:   0
 
Jun 11 07:17:06 hydra kernel: CPU   16: hi:  186, btch:  31 usd:   0
 
Jun 11 07:17:06 hydra kernel: CPU   17: hi:  186, btch:  31 usd:   0
 
Jun 11 07:17:06 hydra kernel: CPU   18: hi:  186, btch:  31 usd:   0
 
Jun 11 07:17:06 hydra kernel: CPU   19: hi:  186, btch:  31 usd:   0
 
Jun 11 07:17:06 hydra kernel: CPU   20: hi:  186, btch:  31 usd:   0
 
Jun 11 07:17:06 hydra kernel: CPU   21: hi:  186, btch:  31 usd:   0
 
Jun 11 07:17:06 hydra kernel: CPU   22: hi:  186, btch:  31 usd:   0
 
Jun 11 07:17:06 hydra kernel: CPU   23: hi:  186, btch:  31 usd:   0
 
Jun 11 07:17:06 hydra kernel: CPU   24: hi:  186, btch:  31 usd:   0
 
Jun 11 07:17:06 hydra kernel: CPU   25: hi:  186, btch:  31 usd:   0
 
Jun 11 07:17:06 hydra kernel: CPU   26: hi:  186, btch:  31 usd:   0
 
Jun 11 07:17:06 hydra kernel: CPU   27: hi:  186, btch:  31 usd:   0
 
Jun 11 07:17:06 hydra kernel: CPU   28: hi:  186, btch:  31 usd:   0
 
Jun 11 07:17:06 hydra kernel: CPU   29: hi:  186, btch:  31 usd:   0
 
Jun 11 07:17:06 hydra kernel: CPU   30: hi:  186, btch:  31 usd:   0
 
Jun 11 07:17:06 hydra kernel: CPU   31: hi:  186, btch:  31 usd:   0
 
Jun 11 07:17:06 hydra kernel: active_anon:31263628 inactive_anon:1381323 isolated_anon:1984
 
Jun 11 07:17:06 hydra kernel: active_file:134 inactive_file:320 isolated_file:0
 
Jun 11 07:17:06 hydra kernel: unevictable:0 dirty:0 writeback:0 unstable:0
 
Jun 11 07:17:06 hydra kernel: free:88797 slab_reclaimable:10059 slab_unreclaimable:16630
 
Jun 11 07:17:06 hydra kernel: mapped:0 shmem:1 pagetables:79016 bounce:0
 
Jun 11 07:17:06 hydra kernel: Node 0 DMA free:15240kB min:8kB low:8kB high:12kB active_anon:0kB inactive_anon:0kB active_file:0kB inactive_file:0kB unevictable:0kB isolated(anon):0kB isolated(file):0kB present:14860kB mlocked:0kB dirty:0kB writeback:0kB mapped:0kB shmem:0kB slab_reclaimable:0kB slab_unreclaimable:0kB kernel_stack:0kB pagetables:0kB unstable:0kB bounce:0kB writeback_tmp:0kB pages_scanned:0 all_unreclaimable? yes
 
Jun 11 07:17:06 hydra kernel: lowmem_reserve[]: 0 1963 64583 64583
 
Jun 11 07:17:06 hydra kernel: Node 0 DMA32 free:251668kB min:1368kB low:1708kB high:2052kB active_anon:335780kB inactive_anon:333620kB active_file:0kB inactive_file:0kB unevictable:0kB isolated(anon):0kB isolated(file):0kB present:2010560kB mlocked:0kB dirty:0kB writeback:0kB mapped:0kB shmem:0kB slab_reclaimable:80kB slab_unreclaimable:1032kB kernel_stack:56kB pagetables:1420kB unstable:0kB bounce:0kB writeback_tmp:0kB pages_scanned:6 all_unreclaimable? no
 
Jun 11 07:17:06 hydra kernel: lowmem_reserve[]: 0 0 62620 62620
 
Jun 11 07:17:06 hydra kernel: Node 0 Normal free:43372kB min:43660kB low:54572kB high:65488kB active_anon:61783268kB inactive_anon:2571780kB active_file:348kB inactive_file:1448kB unevictable:0kB isolated(anon):3328kB isolated(file):0kB present:64122880kB mlocked:0kB dirty:0kB writeback:0kB mapped:0kB shmem:0kB slab_reclaimable:18356kB slab_unreclaimable:40288kB kernel_stack:7096kB pagetables:163420kB unstable:0kB bounce:0kB writeback_tmp:0kB pages_scanned:308 all_unreclaimable? no
 
Jun 11 07:17:06 hydra kernel: lowmem_reserve[]: 0 0 0 0
 
Jun 11 07:17:06 hydra kernel: Node 1 Normal free:44908kB min:45068kB low:56332kB high:67600kB active_anon:62935464kB inactive_anon:2619892kB active_file:188kB inactive_file:0kB unevictable:0kB isolated(anon):4608kB isolated(file):0kB present:66191360kB mlocked:0kB dirty:20kB writeback:0kB mapped:0kB shmem:4kB slab_reclaimable:21800kB slab_unreclaimable:25200kB kernel_stack:4744kB pagetables:151224kB unstable:0kB bounce:0kB writeback_tmp:0kB pages_scanned:432 all_unreclaimable? no
 
Jun 11 07:17:06 hydra kernel: lowmem_reserve[]: 0 0 0 0
 
Jun 11 07:17:06 hydra kernel: Node 0 DMA: 2*4kB 2*8kB 3*16kB 2*32kB 0*64kB 0*128kB 1*256kB 1*512kB 0*1024kB 1*2048kB 3*4096kB = 15240kB
 
Jun 11 07:17:06 hydra kernel: Node 0 DMA32: 82*4kB 54*8kB 38*16kB 38*32kB 18*64kB 25*128kB 8*256kB 10*512kB 4*1024kB 6*2048kB 54*4096kB = 251672kB
 
Jun 11 07:17:06 hydra kernel: Node 0 Normal: 2497*4kB 939*8kB 526*16kB 237*32kB 90*64kB 16*128kB 0*256kB 0*512kB 0*1024kB 0*2048kB 1*4096kB = 45404kB
 
Jun 11 07:17:06 hydra kernel: Node 1 Normal: 10253*4kB 149*8kB 3*16kB 1*32kB 1*64kB 2*128kB 0*256kB 1*512kB 1*1024kB 1*2048kB 0*4096kB = 46188kB
 
Jun 11 07:17:06 hydra kernel: 255870 total pagecache pages
 
Jun 11 07:17:06 hydra kernel: 255569 pages in swap cache
 
Jun 11 07:17:06 hydra kernel: Swap cache stats: add 15912076, delete 15656507, find 17744431/18456257
 
Jun 11 07:17:06 hydra kernel: Free swap  = 0kB
 
Jun 11 07:17:06 hydra kernel: Total swap = 2097144kB
 
Jun 11 07:17:06 hydra kernel: 33554431 pages RAM
 
Jun 11 07:17:06 hydra kernel: 519760 pages reserved
 
Jun 11 07:17:06 hydra kernel: 3656 pages shared
 
Jun 11 07:17:06 hydra kernel: 32934618 pages non-shared
 
Jun 11 07:17:06 hydra kernel: [ pid ]   uid  tgid total_vm      rss cpu oom_adj oom_score_adj name
 
Jun 11 07:17:06 hydra kernel: [  853]     0   853     2780       28   7     -17         -1000 udevd
 
Jun 11 07:17:06 hydra kernel: [ 1626]     0  1626    62367      843   1       0             0 rsyslogd
 
Jun 11 07:17:06 hydra kernel: [ 1655]    81  1655     5351       21   2       0             0 dbus-daemon
 
Jun 11 07:17:06 hydra kernel: [ 1692]     0  1692    49448      162  17       0             0 snmpd
 
Jun 11 07:17:06 hydra kernel: [ 1698]     0  1698    63771        8  19       0             0 lsi_mrdsnmpagen
 
Jun 11 07:17:06 hydra kernel: [ 1711]     0  1711    16652       33   0     -17         -1000 sshd
 
Jun 11 07:17:06 hydra kernel: [ 1745]     0  1745     5223        1   0       0             0 lsi_mrdsnmpagen
 
Jun 11 07:17:06 hydra kernel: [ 2113]    93  2113    23413       47  17       0             0 exim
 
Jun 11 07:17:06 hydra kernel: [ 2174]   496  2174     2707       19   1       0             0 epmd
 
Jun 11 07:17:06 hydra kernel: [ 2226]     0  2226    27109        1   0       0             0 S80rabbitmq-ser
 
Jun 11 07:17:06 hydra kernel: [ 2239]     0  2239    27041        2  18       0             0 bash
 
Jun 11 07:17:06 hydra kernel: [ 2240]     0  2240    27041        2   4       0             0 rabbitmq-server
 
Jun 11 07:17:06 hydra kernel: [ 2253]     0  2253    36359        2  20       0             0 su
 
Jun 11 07:17:06 hydra kernel: [ 2260]   496  2260   667440     9908  18       0             0 beam.smp
 
Jun 11 07:17:06 hydra kernel: [ 2430]   496  2430     2698        2   0       0             0 inet_gethost
 
Jun 11 07:17:06 hydra kernel: [ 2431]   496  2431     4280        2   0       0             0 inet_gethost
 
Jun 11 07:17:06 hydra kernel: [ 2439]     0  2439    29325       31   1       0             0 crond
 
Jun 11 07:17:06 hydra kernel: [ 2450]     0  2450     5385        0   1       0             0 atd
 
Jun 11 07:17:06 hydra kernel: [ 2466]     0  2466    27041        2   3       0             0 sh
 
Jun 11 07:17:06 hydra kernel: [ 2471]     0  2471  8801199     9053   0       0             0 java
 
Jun 11 07:17:06 hydra kernel: [ 2517]     0  2517    16879        2   0       0             0 login
 
Jun 11 07:17:06 hydra kernel: [ 2519]     0  2519     1016        2   2       0             0 mingetty
 
Jun 11 07:17:06 hydra kernel: [ 2521]     0  2521     1016        1  25       0             0 mingetty
 
Jun 11 07:17:06 hydra kernel: [ 2523]     0  2523     1016        2   2       0             0 mingetty
 
Jun 11 07:17:06 hydra kernel: [ 2527]     0  2527     1016        2   0       0             0 mingetty
 
Jun 11 07:17:06 hydra kernel: [ 2529]     0  2529     1016        1  19       0             0 mingetty
 
Jun 11 07:17:06 hydra kernel: [ 2703]     0  2703  8779693       49   0       0             0 java
 
Jun 11 07:17:06 hydra kernel: [ 3414]     0  3414     2779       37   5     -17         -1000 udevd
 
Jun 11 07:17:06 hydra kernel: [ 3415]     0  3415     2779       38   3     -17         -1000 udevd
 
Jun 11 07:17:06 hydra kernel: [31129]     0 31129    35792      485   1       0             0 munin-node
 
Jun 11 07:17:06 hydra kernel: [32419]     0 32419    30082      154  19       0             0 screen
 
Jun 11 07:17:06 hydra kernel: [32420]     0 32420    27109       47  16       0             0 bash
 
Jun 11 07:17:06 hydra kernel: [77410]     0 77410     1532       17  17       0             0 vmstat
 
Jun 11 07:17:06 hydra kernel: [  677]     0   677  1029123        2   0       0             0 console-kit-dae
 
Jun 11 07:17:06 hydra kernel: [  752]     0   752    27108        3   3       0             0 bash
 
Jun 11 07:17:06 hydra kernel: [ 1950]     0  1950    23294       36  17     -17         -1000 auditd
 
Jun 11 07:17:06 hydra kernel: [ 1979]     0  1979    26515       44   6       0             0 memorylog
 
Jun 11 07:17:06 hydra kernel: [ 1986]     0  1986    27109       29   3       0             0 bash
 
Jun 11 07:17:06 hydra kernel: [ 2004]     0  2004    27109        2  19       0             0 bash
 
Jun 11 07:17:06 hydra kernel: [ 2019]     0  2019    27109        2   1       0             0 bash
 
Jun 11 07:17:06 hydra kernel: [ 2854]     0  2854    26549        3  16       0             0 mysqld_safe
 
Jun 11 07:17:06 hydra kernel: [ 3581]   498  3581 37165125 30084920  16       0             0 mysqld
 
Jun 11 07:17:06 hydra kernel: [21495]     0 21495     5545       62  16       0             0 xinetd
 
Jun 11 07:17:06 hydra kernel: [22141]   495 22141  8430501  2286458   1       0             0 java
 
Jun 11 07:17:06 hydra kernel: [52454]     0 52454    25227       23  20       0             0 sleep
 
Jun 11 07:17:06 hydra kernel: Out of memory: Kill process 3581 (mysqld) score 910 or sacrifice child
 
Jun 11 07:17:06 hydra kernel: Killed process 3581, UID 498, (mysqld) total-vm:148660500kB, anon-rss:120339652kB, file-rss:28kB

Eventually mysqld had committed +/- 150 GB memory.

After the automatic restart, we're now running without performance_schema. But I already see that the committed memory is again a lot higher than the actually used memory: now, after 20 minutes, mysqld has committed +/- 90 GB, while actually using +/- 14 GB. Here's what ps aux show at this moment:

mysql    53287  450 10.3 90802276 13711112 pts/2 Sl 07:34  33:40 /usr/sbin/mysqld --basedir=/usr --datadir=/var/lib/mysql --plugin-dir=/usr/lib64/mysql/plugin --user=mysql --log-error=/var/log/mysql/error.err --pid-file=/var/lib/mysql/hydra.hwigroup.com.pid --socket=/var/lib/mysql/mysql.sock --port=3306

Any other suggestions?

Comment by Koen Crijns [ 2014-06-13 ]

We just had another kill after around one and a half day. At the end MySQL comitted 150+ GB of memory, while actually using about a third of it (like described above).

I'm thinking: didn't you change from malloc to jemalloc for MariaDB 10? Might that be related?

Comment by Koen Crijns [ 2014-06-15 ]

Update: because of the frequent and long downtimes we've decided to downgrade to MariaDB 5.5.

If I can help finding a solution to the problem, please let me know.

Comment by Elena Stepanova [ 2014-06-15 ]

We will see what we can do, it's rather difficult to investigate OOM without debugging tools, using which as we already found out is not possible in this case.

Do you happen to monitor status variables (SHOW [GLOBAL] STATUS), engine (SHOW ENGINE INNODB STATUS), and processlist (SHOW [FULL] PROCESSLIST)? All above could, with some luck, help to understand the dynamics of what's going on the server.

Comment by Koen Crijns [ 2014-06-15 ]

I've saved one SHOW ENGINE INNODB STATUS from a few days ago.

At the time I ran the SHOW ENGINE statement, this was the output of "ps aux|grep mysql": 

mysql     3581  455 39.4 147806844 52133124 pts/2 Sl Jun09 3491:51 /usr/sbin/mysqld --basedir=/usr --datadir=/var/lib/mysql --plugin-dir=/usr/lib64/mysql/plugin --user=mysql --log-error=/var/log/mysql/error.err --pid-file=/var/lib/mysql/hydra.hwigroup.com.pid --socket=/var/lib/mysql/mysql.sock --port=3306

As you can see: around 148 GB committed, around 52 GB actually in use.

This was the InnoDB status output:

=====================================
 
2014-06-10 09:16:13 7f925d3ff700 INNODB MONITOR OUTPUT
 
=====================================
 
Per second averages calculated from the last 5 seconds
 
-----------------
 
BACKGROUND THREAD
 
-----------------
 
srv_master_thread loops: 45729 srv_active, 0 srv_shutdown, 0 srv_idle
 
srv_master_thread log flush and writes: 45729
 
----------
 
SEMAPHORES
 
----------
 
OS WAIT ARRAY INFO: reservation count 17138188
 
OS WAIT ARRAY INFO: signal count 200525295
 
Mutex spin waits 708305394, rounds 734998996, OS waits 372106
 
RW-shared spins 53138563, rounds 518827125, OS waits 11832909
 
RW-excl spins 15817758, rounds 536496429, OS waits 4512962
 
Spin rounds per wait: 1.04 mutex, 9.76 RW-shared, 33.92 RW-excl
 
------------------------
 
LATEST FOREIGN KEY ERROR
 
------------------------
 
2014-06-10 02:05:09 7f89f31b9700 Transaction:
 
TRANSACTION 36540775721, ACTIVE 0 sec inserting
 
mysql tables in use 1, locked 1
 
3 lock struct(s), heap size 1248, 1 row lock(s), undo log entries 1
 
MySQL thread id 1329420, OS thread handle 0x7f89f31b9700, query id 20103763 scorpius.hwigroup.com 217.115.193.91 hwidbuser update
 
 
 
/// DELETED FOR COMPETITIVE REASONS ///
 
------------------------
 
LATEST DETECTED DEADLOCK
 
------------------------
 
2014-06-10 08:27:28 7f89f2a4f700
 
*** (1) TRANSACTION:
 
TRANSACTION 36553593750, ACTIVE 1 sec fetching rows
 
mysql tables in use 4, locked 4
 
LOCK WAIT 662 lock struct(s), heap size 96696, 135118 row lock(s)
 
MySQL thread id 2508952, OS thread handle 0x7f9f2cd0d700, query id 37886385 scorpius.hwigroup.com 217.115.193.91 root Sending data
 
 
 
/// DELETED FOR COMPETITIVE REASONS ///
 
 
 
------------
 
TRANSACTIONS
 
------------
 
Trx id counter 36556436629
 
Purge done for trx's n:o < 36556420466 undo n:o < 0 state: running but idle
 
History list length 428
 
LIST OF TRANSACTIONS FOR EACH SESSION:
 
---TRANSACTION 0, not started
 
MySQL thread id 2761292, OS thread handle 0x7f925d3ff700, query id 41637469 scorpius.hwigroup.com 217.115.193.91 root init
 
show engine innodb status
 
---TRANSACTION 36556436602, not started
 
MySQL thread id 2761288, OS thread handle 0x7f9268aff700, query id 41637457 scorpius.hwigroup.com 217.115.193.91 hwidbuser cleaning up
 
---TRANSACTION 36556436628, not started
 
MySQL thread id 2761283, OS thread handle 0x7f92573b6700, query id 41637467 scorpius.hwigroup.com 217.115.193.91 hwidbuser cleaning up
 
---TRANSACTION 36556433057, not started
 
MySQL thread id 2760897, OS thread handle 0x7f981447f700, query id 41631560 scorpius.hwigroup.com 217.115.193.91 root cleaning up
 
---TRANSACTION 36556435723, not started
 
MySQL thread id 2756151, OS thread handle 0x7f89f2c05700, query id 41636089 scorpius.hwigroup.com 217.115.193.91 root cleaning up
 
---TRANSACTION 36556395320, not started
 
MySQL thread id 2756155, OS thread handle 0x7f89f36db700, query id 41566710 scorpius.hwigroup.com 217.115.193.91 hwidbuser cleaning up
 
---TRANSACTION 36553995365, not started
 
MySQL thread id 2595610, OS thread handle 0x7f925ebff700, query id 38483867 scorpius.hwigroup.com 217.115.193.91 hwidbuser cleaning up
 
---TRANSACTION 36556436626, not started
 
MySQL thread id 2489494, OS thread handle 0x7f92657ff700, query id 41637465 scorpius.hwigroup.com 217.115.193.91 hwidbuser cleaning up
 
---TRANSACTION 36556433220, not started
 
MySQL thread id 1997029, OS thread handle 0x7f89f2c97700, query id 41631846 s51444b38.adsl.online.nl 81.68.75.56 alexander cleaning up
 
---TRANSACTION 36556436627, ACTIVE 0 sec
 
mysql tables in use 2, locked 2
 
14 lock struct(s), heap size 3112, 16 row lock(s), undo log entries 4
 
MySQL thread id 2595604, OS thread handle 0x7f89f33b8700, query id 41637454 scorpius.hwigroup.com 217.115.193.91 root Sending data
 
 
 
/// DELETED FOR COMPETITIVE REASONS ///
 
 
 
--------
 
FILE I/O
 
--------
 
I/O thread 0 state: waiting for completed aio requests (insert buffer thread)
 
I/O thread 1 state: waiting for completed aio requests (log thread)
 
I/O thread 2 state: waiting for completed aio requests (read thread)
 
I/O thread 3 state: waiting for completed aio requests (read thread)
 
I/O thread 4 state: waiting for completed aio requests (read thread)
 
I/O thread 5 state: waiting for completed aio requests (read thread)
 
I/O thread 6 state: waiting for completed aio requests (write thread)
 
I/O thread 7 state: waiting for completed aio requests (write thread)
 
I/O thread 8 state: waiting for completed aio requests (write thread)
 
I/O thread 9 state: waiting for completed aio requests (write thread)
 
Pending normal aio reads: 0 [0, 0, 0, 0] , aio writes: 0 [0, 0, 0, 0] ,
 
ibuf aio reads: 0, log i/o's: 0, sync i/o's: 0
 
Pending flushes (fsync) log: 0; buffer pool: 0
 
5823326 OS file reads, 8160599 OS file writes, 328920 OS fsyncs
 
22.80 reads/s, 16384 avg bytes/read, 23.60 writes/s, 4.00 fsyncs/s
 
-------------------------------------
 
INSERT BUFFER AND ADAPTIVE HASH INDEX
 
-------------------------------------
 
Ibuf: size 1, free list len 129788, seg size 129790, 334817 merges
 
merged operations:
 
insert 1377658, delete mark 19137211, delete 1361386
 
discarded operations:
 
insert 0, delete mark 0, delete 0
 
344149.77 hash searches/s, 68731.65 non-hash searches/s
 
---
 
LOG
 
---
 
Log sequence number 53160485508447
 
Log flushed up to   53160485476582
 
Pages flushed up to 53159847218223
 
Last checkpoint at  53159839763492
 
Max checkpoint age    1738750649
 
Checkpoint age target 1684414692
 
Modified age          638290224
 
Checkpoint age        645744955
 
0 pending log writes, 0 pending chkp writes
 
57137 log i/o's done, 1.20 log i/o's/second
 
----------------------
 
BUFFER POOL AND MEMORY
 
----------------------
 
Total memory allocated 49450844160; in additional pool allocated 0
 
Total memory allocated by read views 2760
 
Internal hash tables (constant factor + variable factor)
 
   Adaptive hash index 6946364368    (764988248 + 6181376120)
 
   Page hash           2989048 (buffer pool 0 only)
 
   Dictionary cache    199399283    (191248688 + 8150595)
 
   File system         1357432    (812272 + 545160)
 
   Lock system         119538528    (119530904 + 7624)
 
   Recovery system     0    (0 + 0)
 
Dictionary memory allocated 8150595
 
Buffer pool size        2949104
 
Buffer pool size, bytes 48318119936
 
Free buffers            16401
 
Database pages          2555422
 
Old database pages      942982
 
Modified db pages       556223
 
Pending reads 0
 
Pending writes: LRU 0, flush list 0, single page 0
 
Pages made young 17806046, not young 519267112
 
1463.31 youngs/s, 3413.52 non-youngs/s
 
Pages read 5822278, created 356306, written 7938171
 
22.80 reads/s, 26.99 creates/s, 21.40 writes/s
 
Buffer pool hit rate 1000 / 1000, young-making rate 1 / 1000 not 2 / 1000
 
Pages read ahead 0.00/s, evicted without access 0.00/s, Random read ahead 0.00/s
 
LRU len: 2555422, unzip_LRU len: 0
 
I/O sum[63520]:cur[384], unzip sum[0]:cur[0]
 
----------------------
 
INDIVIDUAL BUFFER POOL INFO
 
----------------------
 
---BUFFER POOL 0
 
Buffer pool size        184319
 
Buffer pool size, bytes 3019882496
 
Free buffers            1024
 
Database pages          159560
 
Old database pages      58880
 
Modified db pages       37065
 
Pending reads 0
 
Pending writes: LRU 0, flush list 0, single page 0
 
Pages made young 1386976, not young 40952909
 
77.38 youngs/s, 94.38 non-youngs/s
 
Pages read 425247, created 75467, written 593886
 
5.60 reads/s, 2.20 creates/s, 0.00 writes/s
 
Buffer pool hit rate 1000 / 1000, young-making rate 1 / 1000 not 1 / 1000
 
Pages read ahead 0.00/s, evicted without access 0.00/s, Random read ahead 0.00/s
 
LRU len: 159560, unzip_LRU len: 0
 
I/O sum[3970]:cur[24], unzip sum[0]:cur[0]
 
---BUFFER POOL 1
 
Buffer pool size        184319
 
Buffer pool size, bytes 3019882496
 
Free buffers            1024
 
Database pages          159708
 
Old database pages      58934
 
Modified db pages       34789
 
Pending reads 0
 
Pending writes: LRU 0, flush list 0, single page 0
 
Pages made young 1270261, not young 34163094
 
104.18 youngs/s, 1.80 non-youngs/s
 
Pages read 335399, created 18456, written 496726
 
1.00 reads/s, 1.20 creates/s, 0.40 writes/s
 
Buffer pool hit rate 1000 / 1000, young-making rate 1 / 1000 not 0 / 1000
 
Pages read ahead 0.00/s, evicted without access 0.00/s, Random read ahead 0.00/s
 
LRU len: 159708, unzip_LRU len: 0
 
I/O sum[3970]:cur[24], unzip sum[0]:cur[0]
 
---BUFFER POOL 2
 
Buffer pool size        184319
 
Buffer pool size, bytes 3019882496
 
Free buffers            1025
 
Database pages          159749
 
Old database pages      58949
 
Modified db pages       34913
 
Pending reads 0
 
Pending writes: LRU 0, flush list 0, single page 0
 
Pages made young 1285151, not young 31702088
 
79.78 youngs/s, 456.11 non-youngs/s
 
Pages read 359951, created 18394, written 501515
 
3.00 reads/s, 0.60 creates/s, 0.20 writes/s
 
Buffer pool hit rate 1000 / 1000, young-making rate 1 / 1000 not 8 / 1000
 
Pages read ahead 0.00/s, evicted without access 0.00/s, Random read ahead 0.00/s
 
LRU len: 159749, unzip_LRU len: 0
 
I/O sum[3970]:cur[24], unzip sum[0]:cur[0]
 
---BUFFER POOL 3
 
Buffer pool size        184319
 
Buffer pool size, bytes 3019882496
 
Free buffers            1024
 
Database pages          159594
 
Old database pages      58892
 
Modified db pages       34468
 
Pending reads 0
 
Pending writes: LRU 0, flush list 0, single page 0
 
Pages made young 1175503, not young 34163176
 
64.99 youngs/s, 457.31 non-youngs/s
 
Pages read 375776, created 18726, written 494249
 
2.20 reads/s, 3.60 creates/s, 0.00 writes/s
 
Buffer pool hit rate 1000 / 1000, young-making rate 1 / 1000 not 7 / 1000
 
Pages read ahead 0.00/s, evicted without access 0.00/s, Random read ahead 0.00/s
 
LRU len: 159594, unzip_LRU len: 0
 
I/O sum[3970]:cur[24], unzip sum[0]:cur[0]
 
---BUFFER POOL 4
 
Buffer pool size        184319
 
Buffer pool size, bytes 3019882496
 
Free buffers            1024
 
Database pages          159732
 
Old database pages      58943
 
Modified db pages       34690
 
Pending reads 0
 
Pending writes: LRU 0, flush list 0, single page 0
 
Pages made young 1077279, not young 30140528
 
63.79 youngs/s, 1.20 non-youngs/s
 
Pages read 346602, created 18509, written 494197
 
0.80 reads/s, 0.40 creates/s, 3.00 writes/s
 
Buffer pool hit rate 1000 / 1000, young-making rate 1 / 1000 not 0 / 1000
 
Pages read ahead 0.00/s, evicted without access 0.00/s, Random read ahead 0.00/s
 
LRU len: 159732, unzip_LRU len: 0
 
I/O sum[3970]:cur[24], unzip sum[0]:cur[0]
 
---BUFFER POOL 5
 
Buffer pool size        184319
 
Buffer pool size, bytes 3019882496
 
Free buffers            1026
 
Database pages          159766
 
Old database pages      58956
 
Modified db pages       35933
 
Pending reads 0
 
Pending writes: LRU 0, flush list 0, single page 0
 
Pages made young 1055441, not young 31379596
 
82.18 youngs/s, 1.80 non-youngs/s
 
Pages read 358110, created 19112, written 493238
 
0.20 reads/s, 0.60 creates/s, 2.80 writes/s
 
Buffer pool hit rate 1000 / 1000, young-making rate 1 / 1000 not 0 / 1000
 
Pages read ahead 0.00/s, evicted without access 0.00/s, Random read ahead 0.00/s
 
LRU len: 159766, unzip_LRU len: 0
 
I/O sum[3970]:cur[24], unzip sum[0]:cur[0]
 
---BUFFER POOL 6
 
Buffer pool size        184319
 
Buffer pool size, bytes 3019882496
 
Free buffers            1024
 
Database pages          159643
 
Old database pages      58910
 
Modified db pages       35143
 
Pending reads 0
 
Pending writes: LRU 0, flush list 0, single page 0
 
Pages made young 1059711, not young 31130307
 
111.98 youngs/s, 1.00 non-youngs/s
 
Pages read 359961, created 19481, written 490029
 
0.60 reads/s, 12.20 creates/s, 1.60 writes/s
 
Buffer pool hit rate 1000 / 1000, young-making rate 1 / 1000 not 0 / 1000
 
Pages read ahead 0.00/s, evicted without access 0.00/s, Random read ahead 0.00/s
 
LRU len: 159643, unzip_LRU len: 0
 
I/O sum[3970]:cur[24], unzip sum[0]:cur[0]
 
---BUFFER POOL 7
 
Buffer pool size        184319
 
Buffer pool size, bytes 3019882496
 
Free buffers            1024
 
Database pages          159745
 
Old database pages      58948
 
Modified db pages       34702
 
Pending reads 0
 
Pending writes: LRU 0, flush list 0, single page 0
 
Pages made young 1063816, not young 32220098
 
102.18 youngs/s, 445.31 non-youngs/s
 
Pages read 356206, created 18537, written 482670
 
1.60 reads/s, 0.20 creates/s, 2.80 writes/s
 
Buffer pool hit rate 1000 / 1000, young-making rate 1 / 1000 not 7 / 1000
 
Pages read ahead 0.00/s, evicted without access 0.00/s, Random read ahead 0.00/s
 
LRU len: 159745, unzip_LRU len: 0
 
I/O sum[3970]:cur[24], unzip sum[0]:cur[0]
 
---BUFFER POOL 8
 
Buffer pool size        184319
 
Buffer pool size, bytes 3019882496
 
Free buffers            1027
 
Database pages          159739
 
Old database pages      58946
 
Modified db pages       34251
 
Pending reads 0
 
Pending writes: LRU 0, flush list 0, single page 0
 
Pages made young 977504, not young 31879517
 
99.98 youngs/s, 0.40 non-youngs/s
 
Pages read 359799, created 18748, written 486616
 
0.40 reads/s, 0.80 creates/s, 0.00 writes/s
 
Buffer pool hit rate 1000 / 1000, young-making rate 2 / 1000 not 0 / 1000
 
Pages read ahead 0.00/s, evicted without access 0.00/s, Random read ahead 0.00/s
 
LRU len: 159739, unzip_LRU len: 0
 
I/O sum[3970]:cur[24], unzip sum[0]:cur[0]
 
---BUFFER POOL 9
 
Buffer pool size        184319
 
Buffer pool size, bytes 3019882496
 
Free buffers            1024
 
Database pages          159788
 
Old database pages      58964
 
Modified db pages       33418
 
Pending reads 0
 
Pending writes: LRU 0, flush list 0, single page 0
 
Pages made young 1081440, not young 33008447
 
80.98 youngs/s, 440.91 non-youngs/s
 
Pages read 367007, created 19002, written 471065
 
2.00 reads/s, 0.40 creates/s, 7.00 writes/s
 
Buffer pool hit rate 1000 / 1000, young-making rate 0 / 1000 not 3 / 1000
 
Pages read ahead 0.00/s, evicted without access 0.00/s, Random read ahead 0.00/s
 
LRU len: 159788, unzip_LRU len: 0
 
I/O sum[3970]:cur[24], unzip sum[0]:cur[0]
 
---BUFFER POOL 10
 
Buffer pool size        184319
 
Buffer pool size, bytes 3019882496
 
Free buffers            1029
 
Database pages          159805
 
Old database pages      58970
 
Modified db pages       34991
 
Pending reads 0
 
Pending writes: LRU 0, flush list 0, single page 0
 
Pages made young 969318, not young 33258371
 
142.37 youngs/s, 0.20 non-youngs/s
 
Pages read 359892, created 18803, written 489085
 
0.20 reads/s, 0.00 creates/s, 0.00 writes/s
 
Buffer pool hit rate 1000 / 1000, young-making rate 1 / 1000 not 0 / 1000
 
Pages read ahead 0.00/s, evicted without access 0.00/s, Random read ahead 0.00/s
 
LRU len: 159805, unzip_LRU len: 0
 
I/O sum[3970]:cur[24], unzip sum[0]:cur[0]
 
---BUFFER POOL 11
 
Buffer pool size        184319
 
Buffer pool size, bytes 3019882496
 
Free buffers            1024
 
Database pages          159538
 
Old database pages      58871
 
Modified db pages       34346
 
Pending reads 0
 
Pending writes: LRU 0, flush list 0, single page 0
 
Pages made young 1130923, not young 32422825
 
114.38 youngs/s, 839.23 non-youngs/s
 
Pages read 378880, created 17958, written 495163
 
2.60 reads/s, 0.00 creates/s, 0.00 writes/s
 
Buffer pool hit rate 1000 / 1000, young-making rate 0 / 1000 not 4 / 1000
 
Pages read ahead 0.00/s, evicted without access 0.00/s, Random read ahead 0.00/s
 
LRU len: 159538, unzip_LRU len: 0
 
I/O sum[3970]:cur[24], unzip sum[0]:cur[0]
 
---BUFFER POOL 12
 
Buffer pool size        184319
 
Buffer pool size, bytes 3019882496
 
Free buffers            1027
 
Database pages          159844
 
Old database pages      58984
 
Modified db pages       33571
 
Pending reads 0
 
Pending writes: LRU 0, flush list 0, single page 0
 
Pages made young 981932, not young 29575567
 
120.38 youngs/s, 0.60 non-youngs/s
 
Pages read 358005, created 17934, written 470594
 
0.40 reads/s, 0.40 creates/s, 3.60 writes/s
 
Buffer pool hit rate 1000 / 1000, young-making rate 1 / 1000 not 0 / 1000
 
Pages read ahead 0.00/s, evicted without access 0.00/s, Random read ahead 0.00/s
 
LRU len: 159844, unzip_LRU len: 0
 
I/O sum[3970]:cur[24], unzip sum[0]:cur[0]
 
---BUFFER POOL 13
 
Buffer pool size        184319
 
Buffer pool size, bytes 3019882496
 
Free buffers            1027
 
Database pages          159697
 
Old database pages      58930
 
Modified db pages       33626
 
Pending reads 0
 
Pending writes: LRU 0, flush list 0, single page 0
 
Pages made young 1019174, not young 30035393
 
88.98 youngs/s, 0.20 non-youngs/s
 
Pages read 345481, created 19499, written 482580
 
0.20 reads/s, 0.20 creates/s, 0.00 writes/s
 
Buffer pool hit rate 1000 / 1000, young-making rate 1 / 1000 not 0 / 1000
 
Pages read ahead 0.00/s, evicted without access 0.00/s, Random read ahead 0.00/s
 
LRU len: 159697, unzip_LRU len: 0
 
I/O sum[3970]:cur[24], unzip sum[0]:cur[0]
 
---BUFFER POOL 14
 
Buffer pool size        184319
 
Buffer pool size, bytes 3019882496
 
Free buffers            1024
 
Database pages          159734
 
Old database pages      58944
 
Modified db pages       35995
 
Pending reads 0
 
Pending writes: LRU 0, flush list 0, single page 0
 
Pages made young 1112806, not young 33547318
 
61.99 youngs/s, 101.58 non-youngs/s
 
Pages read 386228, created 19054, written 507585
 
1.00 reads/s, 3.80 creates/s, 0.00 writes/s
 
Buffer pool hit rate 1000 / 1000, young-making rate 0 / 1000 not 1 / 1000
 
Pages read ahead 0.00/s, evicted without access 0.00/s, Random read ahead 0.00/s
 
LRU len: 159734, unzip_LRU len: 0
 
I/O sum[3970]:cur[24], unzip sum[0]:cur[0]
 
---BUFFER POOL 15
 
Buffer pool size        184319
 
Buffer pool size, bytes 3019882496
 
Free buffers            1024
 
Database pages          159780
 
Old database pages      58961
 
Modified db pages       34322
 
Pending reads 0
 
Pending writes: LRU 0, flush list 0, single page 0
 
Pages made young 1158811, not young 29687878
 
67.79 youngs/s, 571.49 non-youngs/s
 
Pages read 349734, created 18626, written 488973
 
1.00 reads/s, 0.40 creates/s, 0.00 writes/s
 
Buffer pool hit rate 1000 / 1000, young-making rate 1 / 1000 not 10 / 1000
 
Pages read ahead 0.00/s, evicted without access 0.00/s, Random read ahead 0.00/s
 
LRU len: 159780, unzip_LRU len: 0
 
I/O sum[3970]:cur[24], unzip sum[0]:cur[0]
 
--------------
 
ROW OPERATIONS
 
--------------
 
0 queries inside InnoDB, 0 queries in queue
 
3 read views open inside InnoDB
 
1 RW transactions active inside InnoDB
 
0 RO transactions active inside InnoDB
 
1 out of 1000 descriptors used
 
---OLDEST VIEW---
 
Normal read view
 
Read view low limit trx n:o 36556420300
 
Read view up limit trx id 36556420217
 
Read view low limit trx id 36556420300
 
Read view individually stored trx ids:
 
Read view trx id 36556420217
 
-----------------
 
Main thread process no. 3581, id 140266885334784, state: sleeping
 
Number of rows inserted 19547619, updated 24891587, deleted 17505189, read 32353767345
 
4437.51 inserts/s, 1.40 updates/s, 792.04 deletes/s, 479928.41 reads/s
 
------------------------
 
LATEST DETECTED DEADLOCK
 
------------------------
 
2014-06-10 08:27:28 7f89f2a4f700
 
*** (1) TRANSACTION:
 
TRANSACTION 36553593750, ACTIVE 1 sec fetching rows
 
mysql tables in use 4, locked 4
 
LOCK WAIT 662 lock struct(s), heap size 96696, 135118 row lock(s)
 
MySQL thread id 2508952, OS thread handle 0x7f9f2cd0d700, query id 37886385 scorpius.hwigroup.com 217.115.193.91 root Sending data
 
 
 
/// DELETED FOR COMPETITIVE REASONS ///
 
 
 
------------
 
TRANSACTIONS
 
------------
 
Trx id counter 36556436629
 
Purge done for trx's n:o < 36556420466 undo n:o < 0 state: running but idle
 
History list length 428
 
LIST OF TRANSACTIONS FOR EACH SESSION:
 
---TRANSACTION 0, not started
 
MySQL thread id 2761292, OS thread handle 0x7f925d3ff700, query id 41637469 scorpius.hwigroup.com 217.115.193.91 root init
 
show engine innodb status
 
---TRANSACTION 36556436602, not started
 
MySQL thread id 2761288, OS thread handle 0x7f9268aff700, query id 41637457 scorpius.hwigroup.com 217.115.193.91 hwidbuser cleaning up
 
---TRANSACTION 36556436628, not started
 
MySQL thread id 2761283, OS thread handle 0x7f92573b6700, query id 41637467 scorpius.hwigroup.com 217.115.193.91 hwidbuser cleaning up
 
---TRANSACTION 36556433057, not started
 
MySQL thread id 2760897, OS thread handle 0x7f981447f700, query id 41631560 scorpius.hwigroup.com 217.115.193.91 root cleaning up
 
---TRANSACTION 36556435723, not started
 
MySQL thread id 2756151, OS thread handle 0x7f89f2c05700, query id 41636089 scorpius.hwigroup.com 217.115.193.91 root cleaning up
 
---TRANSACTION 36556395320, not started
 
MySQL thread id 2756155, OS thread handle 0x7f89f36db700, query id 41566710 scorpius.hwigroup.com 217.115.193.91 hwidbuser cleaning up
 
---TRANSACTION 36553995365, not started
 
MySQL thread id 2595610, OS thread handle 0x7f925ebff700, query id 38483867 scorpius.hwigroup.com 217.115.193.91 hwidbuser cleaning up
 
---TRANSACTION 36556436626, not started
 
MySQL thread id 2489494, OS thread handle 0x7f92657ff700, query id 41637465 scorpius.hwigroup.com 217.115.193.91 hwidbuser cleaning up
 
---TRANSACTION 36556433220, not started
 
MySQL thread id 1997029, OS thread handle 0x7f89f2c97700, query id 41631846 s51444b38.adsl.online.nl 81.68.75.56 alexander cleaning up
 
---TRANSACTION 36556436627, ACTIVE 0 sec inserting
 
mysql tables in use 2, locked 2
 
35 lock struct(s), heap size 6960, 57 row lock(s), undo log entries 15
 
MySQL thread id 2595604, OS thread handle 0x7f89f33b8700, query id 41637454 scorpius.hwigroup.com 217.115.193.91 root Sending data
 
 
 
/// DELETED FOR COMPETITIVE REASONS ///
 
 
 
----------------------------
 
END OF INNODB MONITOR OUTPUT
 
============================

As you can see from "Total memory allocated 49450844160; in additional pool allocated 0", InnoDB was using the amount of memory that I configured (50 GB), nothing more.

The processlist didn't show any unusual behaviour.

Unfortunately I didn't save the output of SHOW GLOBAL STATUS.

Comment by Koen Crijns [ 2014-06-16 ]

Because of the frequent and long downtime due to the OOM-crashes, we had to decide to downgrade to MariaDB 5.5 yesterday.

The server is now running on MariaDB 5.5.38 for 20.5 hours with no problem whatsoever. We're using the same my.cnf configuration as quoted above, with one exception: I've set the InnoDB buffer pool back to it's original settings of 80 GB. With MariaDB 10 that would result in an OOM-problem within a couple of hours. With MariaDB 5.5 it's not a problem at all, just like in the past.

Here's the current ps aux output:

mysql    53300  295 69.5 106308000 91867704 ?  Sl   Jun15 3646:12 /usr/sbin/mysqld --basedir=/usr --datadir=/var/lib/mysql --plugin-dir=/usr/lib64/mysql/plugin --user=mysql --log-error=/var/log/mysql/error.err --pid-file=/var/lib/mysql/hydra.hwigroup.com.pid --socket=/var/lib/mysql/mysql.sock --port=3306

As you can see: the comitted memory (around 106 GB) is now almost identical to the actually used memory (92 GB). As stated above, with MariaDB 10 we've see over a 3x difference, resulting in the OOM issues.

Our memory usage graph also looks healthy again since yesterday 12:00 (see attachment).

This seems to prove that there's a bug / abnormality with MariaDB 10?

Comment by Koen Crijns [ 2014-06-16 ]

Second attachment:
Memory usage after downgrade to MariaDB 5.5 and setting InnoDB buffer pool back to 80GB (at 12:00). The big difference between comitted and used memory is gone.

Comment by Elena Stepanova [ 2014-06-16 ]

Hi,

Thanks for the provided info. We are currently discussing with our developers how we can handle the investigation, it's a tough situation since OOM usually requires usage of debugging tools which apparently not applicable here.
We will get back to you when we think of something.

Comment by Carlos Pirez [ 2014-06-23 ]

I have the same problem with Centos 6.5, 64bit and MariaDB 10.0.12 (also I was the same with version 10.0.11).
I copy this message with two 'extended-status' obtained a few seconds before the operating system to restart mysqld process. Also will send my my.cnf file
Sorry for my poor English.

Comment by Koen Crijns [ 2014-06-23 ]

Quick update from our side: MariaDB 5.5.38 is running 100% rock solid for 8 days now on the same server. I think this really proves that the problem sits somewhere in MariaDB 10.0, not with the server configuration.

Comment by Viktor Zeman [ 2015-06-04 ]

We are using latest stable MariaDB 10.0.19 (running on Centos 6.5) and we can see the same problem as reported in this bug.

Before we have set swappiness to 0, the memory of mysqld was growing in the swap. After we have disabled swapping, the memory is slowly growing in the RAM.
The only solution right now is to restart the server each few days, what is very painful operation under high load.

Are there any suggestions how to track down the root of the problem and help to resolve this bug?

Comment by Ruben de Graaf [ 2015-10-07 ]

Hello

I have the exact same issue with MariaDB 10.0.21 on a redhat 6.6 server with 16 GB RAM and its really annoying ! We just migrated from mysql 5.1 to 5.5 and then to MariaDB 10 and I really don't want to give credit to Oracle lovers who say that open source products are junk...

Here is proof of oom doing its job :

  1. egrep -i "oom|kill|mysql" /var/log/messages
    Oct 6 21:42:12 server kernel: mysqld invoked oom-killer: gfp_mask=0x280da, order=0, oom_adj=0, oom_score_adj=0
    Oct 6 21:42:12server kernel: mysqld cpuset=/ mems_allowed=0
    Oct 6 21:42:12server kernel: Pid: 8909, comm: mysqld Not tainted 2.6.32-504.12.2.el6.x86_64 #1
    Oct 6 21:42:12 server kernel: [<ffffffff81127782>] ? oom_kill_process+0x82/0x2a0
    Oct 6 21:42:12 server kernel: [ pid ] uid tgid total_vm rss cpu oom_adj oom_score_adj name
    Oct 6 21:42:12 server kernel: [18055] 0 18055 2869 28 1 0 0 mysqld_safe
    Oct 6 21:42:12 server kernel: [22250] 27 22250 4393227 3991112 0 0 0 mysqld
    Oct 6 21:42:12 server kernel: Out of memory: Kill process 22250 (mysqld) score 973 or sacrifice child
    Oct 6 21:42:12 server kernel: Killed process 22250, UID 27, (mysqld) total-vm:17572908kB, anon-rss:15963612kB, file-rss:836kB

Here is the munin graph where you see that MariaDB starts to swap, while vm_swappiness is set to 0 on this server

The only idea I have so far is to improve the amount of RAM once again (to 24 GB or something), but this server was running fine with 4 GB under mysql 5.1...

Comment by Koen Crijns [ 2015-10-07 ]

As a quick update: we're running CentOS 7 for 200+ days now with MariaDB 10.0 branch (10.0.17 at the moment) on the exact same server and I've never encoutered the problem again.

So it seems something specific in CentOS 6 that was fixed in 7.

Comment by Ruben de Graaf [ 2015-10-08 ]

I have the same issue with an other server (and a completely different configuration), the load is much lower on that server using redhat 6.6, mariadb 10.0.17 and there is no activity during the night. Still it crashed already 3 times in a row at 3 am in 3 weeks.

The only thing i've found in the crontab around 3 am is an updatesys script that checks licences for redhat, gpg keys and does a yum update --security. Finally that script updates the AIDE database.

If you have any other question, don't hesitate to ask.

Here is the complete log that can be found in /var/log/messages :

Oct  8 03:00:47 s-mysql-int kernel: yum invoked oom-killer: gfp_mask=0x280da, order=0, oom_adj=0, oom_score_adj=0
 
Oct  8 03:00:47 s-mysql-int kernel: yum cpuset=/ mems_allowed=0
 
Oct  8 03:00:47 s-mysql-int kernel: Pid: 27465, comm: yum Not tainted 2.6.32-573.3.1.el6.x86_64 #1
 
Oct  8 03:00:47 s-mysql-int kernel: Call Trace:
 
Oct  8 03:00:47 s-mysql-int kernel: [<ffffffff810d6dd1>] ? cpuset_print_task_mems_allowed+0x91/0xb0
 
Oct  8 03:00:47 s-mysql-int kernel: [<ffffffff8112a5d0>] ? dump_header+0x90/0x1b0
 
Oct  8 03:00:47 s-mysql-int kernel: [<ffffffff81232cbc>] ? security_real_capable_noaudit+0x3c/0x70
 
Oct  8 03:00:47 s-mysql-int kernel: [<ffffffff8112aa52>] ? oom_kill_process+0x82/0x2a0
 
Oct  8 03:00:47 s-mysql-int kernel: [<ffffffff8112a94e>] ? select_bad_process+0x9e/0x120
 
Oct  8 03:00:47 s-mysql-int kernel: [<ffffffff8112ae90>] ? out_of_memory+0x220/0x3c0
 
Oct  8 03:00:47 s-mysql-int kernel: [<ffffffff8113786c>] ? __alloc_pages_nodemask+0x93c/0x950
 
Oct  8 03:00:47 s-mysql-int kernel: [<ffffffff8117035a>] ? alloc_pages_vma+0x9a/0x150
 
Oct  8 03:00:47 s-mysql-int kernel: [<ffffffff81152b1d>] ? handle_pte_fault+0x73d/0xb20
 
Oct  8 03:00:47 s-mysql-int kernel: [<ffffffff810537b7>] ? pte_alloc_one+0x37/0x50
 
Oct  8 03:00:47 s-mysql-int kernel: [<ffffffff8118be29>] ? do_huge_pmd_anonymous_page+0xb9/0x3b0
 
Oct  8 03:00:47 s-mysql-int kernel: [<ffffffff81153199>] ? handle_mm_fault+0x299/0x3d0
 
Oct  8 03:00:47 s-mysql-int kernel: [<ffffffff811572a6>] ? vma_adjust+0x556/0x5e0
 
Oct  8 03:00:47 s-mysql-int kernel: [<ffffffff8104f156>] ? __do_page_fault+0x146/0x500
 
Oct  8 03:00:47 s-mysql-int kernel: [<ffffffff8115787a>] ? vma_merge+0x29a/0x3e0
 
Oct  8 03:00:47 s-mysql-int kernel: [<ffffffff81157c84>] ? __vm_enough_memory+0x34/0x140
 
Oct  8 03:00:47 s-mysql-int kernel: [<ffffffff81158c7c>] ? do_brk+0x26c/0x350
 
Oct  8 03:00:47 s-mysql-int kernel: [<ffffffff8153e95e>] ? do_page_fault+0x3e/0xa0
 
Oct  8 03:00:47 s-mysql-int kernel: [<ffffffff8153bd05>] ? page_fault+0x25/0x30
 
Oct  8 03:00:47 s-mysql-int kernel: Mem-Info:
 
Oct  8 03:00:47 s-mysql-int kernel: Node 0 DMA per-cpu:
 
Oct  8 03:00:47 s-mysql-int kernel: CPU    0: hi:    0, btch:   1 usd:   0
 
Oct  8 03:00:47 s-mysql-int kernel: CPU    1: hi:    0, btch:   1 usd:   0
 
Oct  8 03:00:47 s-mysql-int kernel: Node 0 DMA32 per-cpu:
 
Oct  8 03:00:47 s-mysql-int kernel: CPU    0: hi:  186, btch:  31 usd:   0
 
Oct  8 03:00:47 s-mysql-int kernel: CPU    1: hi:  186, btch:  31 usd:  30
 
Oct  8 03:00:47 s-mysql-int kernel: active_anon:332024 inactive_anon:115525 isolated_anon:0
 
Oct  8 03:00:47 s-mysql-int kernel: active_file:5 inactive_file:2 isolated_file:0
 
Oct  8 03:00:47 s-mysql-int kernel: unevictable:0 dirty:20 writeback:0 unstable:0
 
Oct  8 03:00:47 s-mysql-int kernel: free:13242 slab_reclaimable:2345 slab_unreclaimable:6531
 
Oct  8 03:00:47 s-mysql-int kernel: mapped:0 shmem:1 pagetables:2747 bounce:0
 
Oct  8 03:00:47 s-mysql-int kernel: Node 0 DMA free:8344kB min:332kB low:412kB high:496kB active_anon:2660kB inactive_anon:4588kB active_file:36kB inactive_file:0kB unevictable:0kB isolated(anon):0kB isolated(file):0kB present:15304kB mlocked:0kB dirty:20kB writeback:0kB mapped:0kB shmem:0kB slab_reclaimable:12kB slab_unreclaimable:4kB kernel_stack:16kB pagetables:44kB unstable:0kB bounce:0kB writeback_tmp:0kB pages_scanned:0 all_unreclaimable? no
 
Oct  8 03:00:47 s-mysql-int kernel: lowmem_reserve[]: 0 2004 2004 2004
 
Oct  8 03:00:47 s-mysql-int kernel: Node 0 DMA32 free:44624kB min:44720kB low:55900kB high:67080kB active_anon:1325436kB inactive_anon:457512kB active_file:0kB inactive_file:48kB unevictable:0kB isolated(anon):0kB isolated(file):0kB present:2052192kB mlocked:0kB dirty:60kB writeback:0kB mapped:4kB shmem:4kB slab_reclaimable:9368kB slab_unreclaimable:26120kB kernel_stack:2752kB pagetables:10944kB unstable:0kB bounce:0kB writeback_tmp:0kB pages_scanned:31 all_unreclaimable? no
 
Oct  8 03:00:47 s-mysql-int kernel: lowmem_reserve[]: 0 0 0 0
 
Oct  8 03:00:47 s-mysql-int kernel: Node 0 DMA: 2*4kB 5*8kB 0*16kB 4*32kB 3*64kB 4*128kB 3*256kB 1*512kB 2*1024kB 2*2048kB 0*4096kB = 8304kB
 
Oct  8 03:00:47 s-mysql-int kernel: Node 0 DMA32: 803*4kB 473*8kB 340*16kB 210*32kB 136*64kB 65*128kB 21*256kB 4*512kB 1*1024kB 0*2048kB 0*4096kB = 44628kB
 
Oct  8 03:00:47 s-mysql-int kernel: 4467 total pagecache pages
 
Oct  8 03:00:47 s-mysql-int kernel: 4412 pages in swap cache
 
Oct  8 03:00:47 s-mysql-int kernel: Swap cache stats: add 689802, delete 685390, find 307320/319473
 
Oct  8 03:00:47 s-mysql-int kernel: Free swap  = 0kB
 
Oct  8 03:00:47 s-mysql-int kernel: Total swap = 1048572kB
 
Oct  8 03:00:47 s-mysql-int kernel: 524272 pages RAM
 
Oct  8 03:00:47 s-mysql-int kernel: 44727 pages reserved
 
Oct  8 03:00:47 s-mysql-int kernel: 226 pages shared
 
Oct  8 03:00:47 s-mysql-int kernel: 462572 pages non-shared
 
Oct  8 03:00:47 s-mysql-int kernel: [ pid ]   uid  tgid total_vm      rss cpu oom_adj oom_score_adj name
 
Oct  8 03:00:47 s-mysql-int kernel: [  416]     0   416     2702        1   0     -17         -1000 udevd
 
Oct  8 03:00:47 s-mysql-int kernel: [  724]     0   724     2701        1   0     -17         -1000 udevd
 
Oct  8 03:00:47 s-mysql-int kernel: [  728]     0   728     2701        1   0     -17         -1000 udevd
 
Oct  8 03:00:47 s-mysql-int kernel: [ 1182]     0  1182    44789       92   1       0             0 vmtoolsd
 
Oct  8 03:00:47 s-mysql-int kernel: [ 1259]     0  1259    23283       32   1     -17         -1000 auditd
 
Oct  8 03:00:47 s-mysql-int kernel: [ 1279]     0  1279    67718       73   1       0             0 rsyslogd
 
Oct  8 03:00:47 s-mysql-int kernel: [ 1309]     0  1309     2707       32   0       0             0 irqbalance
 
Oct  8 03:00:47 s-mysql-int kernel: [ 1325]    32  1325     4744       13   1       0             0 rpcbind
 
Oct  8 03:00:47 s-mysql-int kernel: [ 1347]    29  1347     5837        2   1       0             0 rpc.statd
 
Oct  8 03:00:47 s-mysql-int kernel: [ 1465]    81  1465     5912       47   1       0             0 dbus-daemon
 
Oct  8 03:00:47 s-mysql-int kernel: [ 1475]     0  1475    47629       46   0       0             0 winbindd
 
Oct  8 03:00:47 s-mysql-int kernel: [ 1506]     0  1506     1020        1   0       0             0 acpid
 
Oct  8 03:00:47 s-mysql-int kernel: [ 1516]     0  1516    49296      165   0       0             0 winbindd
 
Oct  8 03:00:47 s-mysql-int kernel: [ 1517]    68  1517    10008      132   1       0             0 hald
 
Oct  8 03:00:47 s-mysql-int kernel: [ 1518]     0  1518     5100        2   0       0             0 hald-runner
 
Oct  8 03:00:47 s-mysql-int kernel: [ 1520]     0  1520    47457       50   1       0             0 winbindd
 
Oct  8 03:00:47 s-mysql-int kernel: [ 1521]     0  1521    47457       51   0       0             0 winbindd
 
Oct  8 03:00:47 s-mysql-int kernel: [ 1552]     0  1552     5630        2   1       0             0 hald-addon-inpu
 
Oct  8 03:00:47 s-mysql-int kernel: [ 1565]    68  1565     4502        2   0       0             0 hald-addon-acpi
 
Oct  8 03:00:47 s-mysql-int kernel: [ 1582]     0  1582   113176       40   1       0             0 automount
 
Oct  8 03:00:47 s-mysql-int kernel: [ 1603]    99  1603     3222       17   1       0             0 dnsmasq
 
Oct  8 03:00:47 s-mysql-int kernel: [ 1613]     0  1613    50625      181   0       0             0 snmpd
 
Oct  8 03:00:47 s-mysql-int kernel: [ 1630]     0  1630    16554       27   1     -17         -1000 sshd
 
Oct  8 03:00:47 s-mysql-int kernel: [ 1641]     0  1641     5429        2   0       0             0 xinetd
 
Oct  8 03:00:47 s-mysql-int kernel: [ 1651]    38  1651     8208       34   1       0             0 ntpd
 
Oct  8 03:00:47 s-mysql-int kernel: [ 1920]   498  1920    10365       12   0       0             0 nrpe
 
Oct  8 03:00:47 s-mysql-int kernel: [ 2007]     0  2007    20321       26   0       0             0 master
 
Oct  8 03:00:47 s-mysql-int kernel: [ 2033]    89  2033    20908       32   1       0             0 qmgr
 
Oct  8 03:00:47 s-mysql-int kernel: [ 2036]     0  2036    28663        2   1       0             0 abrtd
 
Oct  8 03:00:47 s-mysql-int kernel: [ 2048]     0  2048    28135       17   0       0             0 abrt-dump-oops
 
Oct  8 03:00:47 s-mysql-int kernel: [ 2058]     0  2058    29215       22   1       0             0 crond
 
Oct  8 03:00:47 s-mysql-int kernel: [ 2085]     0  2085    27085       24   0       0             0 rhsmcertd
 
Oct  8 03:00:47 s-mysql-int kernel: [ 2095]     0  2095     5759        1   0       0             0 oddjobd
 
Oct  8 03:00:47 s-mysql-int kernel: [ 2113]     0  2113     1016        2   1       0             0 mingetty
 
Oct  8 03:00:47 s-mysql-int kernel: [ 2115]     0  2115     1016        2   0       0             0 mingetty
 
Oct  8 03:00:47 s-mysql-int kernel: [ 2117]     0  2117     1016        2   0       0             0 mingetty
 
Oct  8 03:00:47 s-mysql-int kernel: [ 2119]     0  2119     1016        2   0       0             0 mingetty
 
Oct  8 03:00:47 s-mysql-int kernel: [ 2121]     0  2121     1016        2   0       0             0 mingetty
 
Oct  8 03:00:47 s-mysql-int kernel: [ 2123]     0  2123     1016        2   0       0             0 mingetty
 
Oct  8 03:00:47 s-mysql-int kernel: [28993]     0 28993    48242       23   1       0             0 winbindd
 
Oct  8 03:00:47 s-mysql-int kernel: [19284]     0 19284     2868        2   1       0             0 mysqld_safe
 
Oct  8 03:00:47 s-mysql-int kernel: [19518]    27 19518   767059   360652   1       0             0 mysqld
 
Oct  8 03:00:47 s-mysql-int kernel: [27325]    89 27325    20865      218   1       0             0 pickup
 
Oct  8 03:00:47 s-mysql-int kernel: [27455]     0 27455    43648      133   0       0             0 crond
 
Oct  8 03:00:47 s-mysql-int kernel: [27458]     0 27458    26524       37   0       0             0 bash
 
Oct  8 03:00:47 s-mysql-int kernel: [27460]     0 27460    30508      102   1       0             0 updateSys
 
Oct  8 03:00:47 s-mysql-int kernel: [27465]     0 27465   169284    80888   1       0             0 yum
 
Oct  8 03:00:47 s-mysql-int kernel: Out of memory: Kill process 19518 (mysqld) score 835 or sacrifice child
 
Oct  8 03:00:47 s-mysql-int kernel: Killed process 19518, UID 27, (mysqld) total-vm:3068236kB, anon-rss:1442604kB, file-rss:4kB

Comment by Elena Stepanova [ 2015-10-23 ]

rdegraaf, unitminer, does either of you have a non-production instance where this problem is reproducible, and where you could experiment (with additional logging, debug binaries, and such)?
I've been trying to reproduce the problem, but without any luck so far.

Comment by Viktor Zeman [ 2015-10-23 ]

We have just production servers with this problem.
On test servers we don't have such high load and the problem is not there.

Now we have upgraded one server to 10.1.8 and we will monitor it if there will not be the same problem.
So far it looks good, but maybe because we have just writes to this server and no selects (we use it just as backup/slave)

Comment by Elena Stepanova [ 2015-10-23 ]

unitminer, can you describe the load on your production servers where you have the problem (kind of queries, size of queries, size of database, engines in use, approximate throughput, number of parallel connections), and what differs on test servers where you don't observe the problem? If possible, please also attach your cnf file(s) from a server where you have the problem, and again, if it's anyhow different on test servers, indicate that.
I've been working with the data provided by koenc, but no result so far, maybe noticing differences and similarities will help me adjust my test load.

Comment by Ruben de Graaf [ 2015-10-23 ]

The second server where I have this issue is a non production environment (actually since I increased the RAM hugely, I don't have the issue anymore), but if you want me to try things feel free to ask, I'll lower the amount of RAM on the virtual server to be in the bug conditions again.

Comment by Elena Stepanova [ 2015-10-23 ]

rdegraaf,

First thing – if you have any kind of monitoring on the machine, do you still observe weird memory dynamics for mysqld (even though it does not go "out of" memory because there is enough of it)?
And yes, if you can work with our developers in order to investigate this problem, it will be great – if it's still reproducible on 10.0.21, I don't have much hope that it has been fixed in 10.1, most likely it is still there somewhere.

Comment by Ruben de Graaf [ 2015-10-23 ]

So far we had no monitoring on our test machine that had the bug, I just activated it, so in a day or two we will have some nice munin graphs available.

Here you have a graph on the production environment that didn't have the bug since I upgraded its RAM to 20G (it was working with 8Go without any problem under mysql 5.1.73).

Sadly I will be on holidays for the 4 weeks so I won't be able to help you much in the meantime, but I'll ask one of my Colleges to help on his free time.

Comment by Elena Stepanova [ 2015-10-29 ]

I can think of two general directions where the investigation might go – please choose whatever is more appropriate for you, in any case there is no guarantee that one would work better than another.

1). Trying to create a scenario that reproduces the problem.

To do that,

  • lower the amount of RAM back to the value where you used to hit the OOM;
  • shut down MariaDB server and make a full physical backup of your datadir, including ibdata* and ib_log* files (alternatively, you can create a full database dump from the running server, but make sure there is no activity on the server at all after you started the dump, and until you shut down the server);
  • set general_log=1 in the server config, make sure you know where it will write the log (set general_log_file explicitly, if necessary);
  • start the server;
  • leave it running until you hit OOM;
  • archive the datadir backup or data dump that you created before, the general log that was created, and your cnf files, and upload them to our ftp.askmonty.org/private and let us know you have done it;
  • unset general_log, fix the RAM, start server, work as usual.

The point is that with the database backup as an entry point, and the general log as the record of the whole work flow, there is a good chance we will be able to reproduce the problem locally, in which case we can proceed investigating it on our side and stop bothering you.
The disadvantage is that you will have to share your datadir with MariaDB developers – if there is any highly confidential information on that test server, it might be impossible. Also it can be difficult if the database is very big.

2) Trying to use debugging tools to find out where the memory leaks

  • set up the memory monitor as Ruben mentioned above;
  • install valgrind if you don't have it on the machine yet;
  • build a debug version of the server, or let us know and we'll build it for you;
  • make sure you know where the server writes its log_error, set it explicitly if necessary, preferably unset writing to syslog for a while;
  • stop MariaDB server;
  • do not decrease the amount of memory;
  • switch the binaries to the debug build;
  • start the MariaDB server under valgrind (if it comes to that, we will give you the valgrind options);
  • let it run and watch the memory;
  • after the amount of used memory exceeded the value which would cause OOM if you had the old smaller RAM, shut down the server gracefully;
  • take the error log from server start and till the very end, and send it to us;
  • switch binaries back, reset syslog if needed, start without valgrind, proceed as usual, but don't remove debug binaries and don't uninstall valgrind, because most likely there will be more iterations needed.

The benefit of this approach is that we will know for sure that the flow is run on the exact same machine, data and flow where the problem usually occurs, so the chance that it will be reproduced is higher than with the first one.
Disadvantages are more severe. First, running under valgrind is extremely slow, impossibly slow for all practical purposes, you can only do it if it's a truly test server which can be rendered useless for a while. Second, it requires the debug server. Third, valgrind is not flawless and it's possible that it won't show anything even if the memory consumption is visible. Forth, the results, if there are any, will only give us some first clues, and we will have to ask you to run more experiments.

If you are still willing to proceed, please let us know which way you prefer.

Comment by Ruben de Graaf [ 2015-11-25 ]

Hello, sorry my college didn't have the time to work on this. But I'm back so it's time to sort this problem out.

First, I've made a clone from our developer database that has the problem when it has a "lowish" amount of RAM, sadly I tried to make it crash on my own and that doesn't happen. So what I've done is talking to the devs and I've lowered the memory of their server after enabling the general logs (and making a full backup of the database before enabling the general logs). So now all I have to do is wait for it to happen.

So basically I choose the solution 1 you offered me, because our developers have to work on it normally and slowing it down even more isn't exactly acceptable for them. A crash of the database isn't a major problem though, because the service restarts within 10 seconds.

If everything goes according to plan the database should crash in the next day or so and I will provide you everything I have then.

Comment by Ruben de Graaf [ 2015-11-30 ]

Ok the developer database server crashed this night at 3:00:30 am (nobody is working on the database at that time).

I have a 800 MB file of general logs to provide you (only 90 MB once ziped) and even a complete backup of the database + some other log files. Where can I upload this for you ?

Comment by Elena Stepanova [ 2015-11-30 ]

rdegraaf,
you can upload everything to ftp.askmonty.org/private.
Thanks!

Comment by Ruben de Graaf [ 2015-11-30 ]

Done !

Do you want the full database backup too (and maybe the my.cnf and my.cnf.d/ files) ? It takes close to 3.1 GB.

Comment by Elena Stepanova [ 2015-11-30 ] 

Do you want the full database backup too (and maybe the my.cnf and my.cnf.d/ files) ? It takes close to 3.1 GB.

Yes, please.

Comment by Ruben de Graaf [ 2015-11-30 ]

Done too.

Comment by Ruben de Graaf [ 2015-12-09 ]

Hello, any news regarding this issue ? Are the provided logs and data enough to find out what's going wrong ?

Comment by Elena Stepanova [ 2015-12-15 ]

Sorry for the delay.
It's good logs and good data; but I tried a few times to replay the log on the provided data, on MariaDB 10.0.11, and did not get anything close to OOM so far.
The further plan is to try it on CentOS 6.5, maybe there is something specific in there. I will also try to refine my replaying, to make sure it works closer to the original flow.

Comment by Ruben de Graaf [ 2015-12-15 ]

If it can help, I can export our whole server.

It's a virtual machine, so if you have a vmware workstation or an ESXI server somewhere you can have it up and running easily.

By the way we do have other servers (rhel 6.6 or 6.7 also) with mariadb 10 where we don't have the problem, so there is probably a relation between the database structure (this one runs a cms called typo3) and the crash. Since the crash can occur at night on the development server when there is no activity at all, it's probably not linked to a particular query.

Comment by Elena Stepanova [ 2015-12-16 ]

rdegraaf, sorry, just to make sure: are you saying that the server keeps growing in memory and eventually gets killed by OOM killer even although there is no activity on the server whatsoever? No backup, no analytics, no nothing?

Comment by Ruben de Graaf [ 2015-12-16 ]

Exactly, but the weird thing is (as the munin graph shows) is that the memory management is correct for many days (with cache making and cache cleaning) and then suddenly it goes wrong at some point and all the memory and swap is consumed which leads to the oom killer ending the process.

On our development server it indeed happens when there is no activity at all, on our production server there is always activity and it may happen at any time after the memory start to be a little filled up.

Comment by Elena Stepanova [ 2015-12-16 ]

jplindst, svoj, wlad, could you please take a look at the above bug report and maybe come up with some theories what can possibly cause this?
The only thing I can seriously think of that might possibly do essential work at idle times is InnoDB, but even then, I don't know what exactly it could be doing so hard to hit OOM.
Even more far-fetched suspicion is Aria checkpoints. Apart from these, I don't have any ideas at all. Any thoughts would be much appreciated.

Comment by Sergey Vojtovich [ 2015-12-16 ]

elenst, did you managed to reproduce this? If no activity is needed, I'd try running server under valgrind and issue normal shutdown before it gets killed by OOM killer.

Comment by Elena Stepanova [ 2015-12-16 ]

svoj, no. If I were able to reproduce this, I wouldn't need to cast a wide net for theories, the bug would have been assigned to somebody.

Comment by Ruben de Graaf [ 2015-12-16 ]

Just to clarify :

There is some activity needed to start the process, it's only once the server has filled most of its memory with cache that the server is able to crash (even with no activity like I said), if there is plenty of free ram left nothing will happen.

Comment by Jan Lindström (Inactive) [ 2015-12-16 ]

Very hard to say anything sure. InnoDB does things when server is idle, e.g. purge thread will purge delete marked rows. But as shown, at least issue is not related to fact that buffer pool would be bigger than expected. Do we have any e.g. PS table that would show memory usage per object/storage engine or something ?

Comment by Ruben de Graaf [ 2015-12-17 ]

I just activated the performance schema to see if I could find something, but if you could tell me where to look for the interesting information (if there is any) it would save me a lot of time, because i'm not familiar with it.

If you have anything else to suggest to find more information, feel free to tell me.

Comment by Ruben de Graaf [ 2016-01-08 ]

I might have found something regarding this OOM issue and it could be kernel related.

Look at this page : https://www.percona.com/blog/2014/04/28/oom-relation-vm-swappiness0-new-kernel/

I have indead vm.swappiness set to 0 on the production server. On the other side, the development server that crashes has a standard swapiness of 60... So no real lead here, but I still changed swapiness to 1 on the production server to see how it goes (we had 3 crashes on the same day 3 days ago, let's hope it will stay quiet now...).

Edit : On second thought, the development server did not crash since it had much more RAM at its disposal (with swappiness at 60), so this might actually be the solution.

I'll keep you in touch if this solves our problem.

Comment by Ruben de Graaf [ 2016-01-14 ]

Some news, we tried with vm.swapinness at 1=> the database processus gets killed, then with vm.swapinness at 60 (which is the normal Redhat value) => the database processus gets killed.

Afterwards I added a script that prevented oom to kill mysql => The whole server crashed this morning due to out of memory.

So oom kills the database and that's a good thing because otherwise the whole server crashes which is much worse.

Comment by Ruben de Graaf [ 2016-02-02 ]

I tried swapoff also on the production server => The database still crashes.

We now have about 2 or 3 crashes a day, we have decided to downgrade to mysql 5.1.73, we have no solution, mariaDB is way too unstable.

Comment by Elena Stepanova [ 2016-02-02 ]

rdegraaf, with which version of MariaDB did you observe the problem? I mean, the latest version you tried.

Comment by Ruben de Graaf [ 2016-02-02 ]

10.0.21 is the last version we used.

Comment by Michael Widenius [ 2016-02-02 ]

First some comments on the configuration file:

key_buffer = 1536M

If you are not using myisam tables, you should set the above to 1M and
instead set aria_pagecache_buffer_size to 1535M, if you are using a
lot of temporary tables that overflows to disk. This is because MariaDB uses Aria instead of MyISAM for internal diskbased temporary tables.

table_open_cache = 10000
table_definition_cache = 10000

Do you really have 10000 different tables or 10000 different tables in
active use ?

If you can execute:
show status like "Open_table%";
on your production server after it has been up 12h, this will give you
some idea of what values are sensible above.

sort_buffer_size = 8M
read_buffer_size = 4M
read_rnd_buffer_size = 8M

Note that with 350 active users, the above can use up to 9G
At least read_buffer_size could be put done to 1M.

max_heap_table_size = 128M

I would push the above done a bit to 64M

max_user_connections = 350
max_connections = 450

One reason for the problem you are having is that you get into some
lock and then you get a lot of new connections that exceutes slow
queries that takes a lot of resources.
Setting down max_connections is a way to ensure that this isn't that
likely to happen.

Another way is to use the thread pool, which will ensure that you
don't get too many concurrent queries running:

https://mariadb.com/kb/en/mariadb/thread-pool-in-mariadb/hread

To find the real problem:

You can monitor with MariaDB 10.0 the dynamic memory usage per process
and the total memory used allocated by the server and the MyISAM,
MEMORY and Aria storage engines.

SELECT memory_used,INFO_BINARY from information_schema.processlist;
SELECT sum(memory_used) from information_schema.processlist;
SHOW global status like "memory_used";

If the problem is that some or a lot of processes starts taking up a
lot of memory as part of executing the queryes, it will show up in the
first SELECT above.

If there is some external cache that grows, then it should show up the
the SHOW global status (with the exception of internal memory
allocated by InnoDB and some other storage engines).

To find out what's going on you could do one of two things:

  • If Linux provide some way for the OOM killer to execute a script
    before it starts killing processes, you could have it start a
    small script that would execute and log the above queries.
  • Write a small script that calls the above commands every minute and logs
    them. If the server dies again killed by the OOM, the last logged entries
    should give us a better picture of where the memory allocation happens.
    (Globally or by a set of queries).
Comment by Ruben de Graaf [ 2016-02-02 ]

Well, I'm not the person who has the server which such high values, that's a guy who migrated to redhat 7 and doesn't have the problem anymore. I had the same problem as he did, so I took this bug thread a little over.

I don't have such high values on my server, but the monitoring of the queries until the crash is interesting so i scripted something that dumps the current query and memory values every second (not sure I can script something triggered by oom).

I'll keep you in touch if I find something.

Comment by Ruben de Graaf [ 2016-02-03 ]

Our server crashed 2 times past night, here are the last queries and memory usage on the database before it went down (my script was running every second and as you can see on the first capture, I already have 5 seconds between the 2 captures which means the database was heavily loaded).

======================================================================================================
 
======================================================================================================
 
2016-02-02 23:03:49
 
------------------------------------------------------------------------------------------------------
 
memory_used     INFO
 
39408   NULL
 
75272   SELECT memory_used,INFO from information_schema.processlist
 
58864   SELECT content FROM cf_extbase_object WHERE identifier = '7b6eafa37459ae90810443b105992a61' AND cf_extbase_object.expires >= 1454450629 LIMIT 1
 
50704   SELECT content FROM cf_extbase_object WHERE identifier = 'ed7ad108d92f851eb75bb78abc9e2218' AND cf_extbase_object.expires >= 1454450629 LIMIT 1
 
64688   SELECT content FROM cf_extbase_reflection WHERE identifier = 'ReflectionData_DeTracking' AND cf_extbase_reflection.expires >= 1454450629 LIMIT 1
 
58864   UPDATE fe_session_data\n\t\t\t\t\tSET\n\t\t\t\t\t\tcontent='a:37:{s:21:\\"souscription_logement\\";s:3:\\"APP\\";s:22:\\"souscription_residence\\";s:1:\\"1\\";s:23:\\"souscription_occupation\\";s:8:\\"TOUJOURS\\";s:24:\\"souscription_nb_habitant\\";s:1:\\"3\\";s:23:\\"souscription_superficie\\";d:60;s:21:\\"souscription_nb_etage\\";s:0:\\"\\";s:32:\\"souscription_implantation_maison\\";s:0:\\"\\";s:37:\\"souscription_implantation_appartement\\";s:13:\\"REZDECHAUSSEE\\";s:30:\\"souscription_date_construction\\";s:4:\\"AV81\\";s:31:\\"souscription_habitude_chauffage\\";s:6:\\"NORMAL\\";s:28:\\"souscription_utilisation_eau\\";s:6:\\"DOUCHE\\";s:26:\\"souscription_chauffage_eau\\";s:9:\\"CHAUDGAZ2\\";s:22:\\"souscription_chauffage\\";s:3:\\"GAZ\\";s:20:\\"souscription_cuisson\\";s:6:\\"GAZBOU\\";s:23:\\"souscription_equipement\\";a:2:{i:0;s:9:\\"EQ_CONGEL\\";i:1;s:17:\\"EQ_LAVE_VAISSELLE\\";}s:24:\\"souscription_climatiseur\\";s:0:\\"\\";s:27:\\"souscription_type_eclairage\\";s:3:\\"ECO\\";s:30:\\"souscription_information_tarif\\";s:0:\\"\\";s:23:\\"souscription_list_offre\\";s:0:\\"\\";s:27:\\"souscription_zone_tarif_gaz\\";s:1:\\"2\\";s:23:\\"souscription_type_devis\\";s:1:\\"2\\";s:20:\\"souscription_energie\\";s:3:\\"gaz\\";s:15:\\"souscription_cp\\";s:5:\\"25000\\";s:18:\\"souscription_ville\\";s:5:\\"25056\\";s:21:\\"souscription_civilite\\";s:4:\\"Mlle\\";s:17:\\"souscription_nom1\\";s:5:\\"Leroi\\";s:20:\\"souscription_prenom1\\";s:6:\\"Alyssa\\";s:19:\\"souscription_email1\\";s:23:\\"censored@hotmail.fr\\";s:17:\\"souscription_tel1\\";s:10:\\"0641122867\\";s:29:\\"souscription_option_tarifaire\\";s:0:\\"\\";s:32:\\"souscription_puissance_souscrite\\";s:0:\\"\\";s:29:\\"souscription_car_elec_base_hp\\";s:0:\\"\\";s:24:\\"souscription_car_elec_hc\\";s:0:\\"\\";s:28:\\"souscription_statut_qas_mail\\";s:7:\\"UNKNOWN\\";s:29:\\"souscription_last_mail_valide\\";s:23:\\"censored@hotmail.fr\\";s:26:\\"souscription_validite_mail\\";s:2:\\"OK\\";s:28:\\"souscription_qc_consommation\\";O:23:\\"getConsommationResponse\\":1:{s:6:\\"return\\";O:10:\\"infosConso\\":2:{s:14:\\"infosConsoElec\\";O:14:\\"infosConsoElec\\":14:{s:37:\\"consommationAnnuelleReferenceDEBaseHP\\";i:1911;s:33:\\"consommationAnnuelleReferenceDEHC\\";i:1501;s:16:\\"formuleTarifaire\\";s:5:\\"MU-DT\\";s:10:\\"mensualite\\";i:50;s:23:\\"mensualiteSaisonnalisee\\";i:46;s:20:\\"mensualiteAnnualisee\\";i:53;s:13:\\"mensualiteTrv\\";i:0;s:6:\\"nbMois\\";i:6;s:11:\\"profilConso\\";s:3:\\"P03\\";s:11:\\"qualiteCade\\";s:3:\\"Q25\\";s:8:\\"typeCade\\";s:2:\\"11\\";s:15:\\"optionTarifaire\\";s:4:\\"HPHC\\";s:18:\\"puissanceSouscrite\\";s:2:\\"06\\";s:27:\\"dateFinPlanPaiementCalculee\\";s:10:\\"2016-08-13\\";}s:13:\\"infosConsoGaz\\";O:13:\\"infosConsoGaz\\":12:{s:31:\\"consommationAnnuelleReferenceDE\\";i:11295;s:16:\\"formuleTarifaire\\";s:2:\\"T2\\";s:10:\\"mensualite\\";i:73;s:23:\\"mensualiteSaisonnalisee\\";i:59;s:20:\\"mensualiteAnnualisee\\";i:87;s:13:\\"mensualiteTrv\\";i:0;s:6:\\"nbMois\\";i:6;s:11:\\"profilConso\\";s:2:\\"02\\";s:11:\\"qualiteCade\\";s:3:\\"Q25\\";s:8:\\"typeCade\\";s:2:\\"11\\";s:27:\\"dateFinPlanPaiementCalculee\\";s:10:\\"2016-08-23\\";s:18:\\"classeConsommation\\";s:2:\\"B1\\";}}}}',\n\t\t\t\t\t\ttstamp='1454450603'\n\t\t\t\t\tWHERE\n\t\t\t\t\t\thash='b223e95274f819eed2ce63a83f4432e2'
 
50704   NULL
 
50704   NULL
 
248056  SELECT index_fulltext.*, ISEC.*, IP.*,MATCH (index_fulltext.fulltextdata) AGAINST ('le déploiement du compteur linky c\\'est quand' WITH QUERY EXPANSION) as score FROM index_fulltext, index_section ISEC, index_phash IP WHERE MATCH (index_fulltext.fulltextdata) AGAINST ('le déploiement du compteur linky c\\'est quand' WITH QUERY EXPANSION)  AND IP.sys_language_uid=0\n\t\t\t\t\tAND index_fulltext.phash = IP.phash\n\t\t\t\t\tAND ISEC.phash = IP.phash\n\t\t\t\t\tAND  ISEC.page_id IN (1078,1079,1080,1081,825,826,827,828,1170,863,838,839,840,841,832,833,835,834,836,567,566,565,830,564,734,735,736,737,738,571,573,574,733,568,563,562,561,569,1077,522,509,536,537,1112,1113,1318,3149,2541,2607,2608,2609,3116,3536,3366,1407,3365,2589,2571,512,511,501,857,858,812,2988,528,529,544,530,3500,3499,3497,3496,3495,3324,3323,3322,3321,3320,3319,3318,3317,3316,3304,490,487,488,489,478,479,480,481,245,246,247,358,249,25,173,26,99,1319,174,3229,3228,3227,3226,3225,1105,15,16,1123,20,3311,3167,1314,3542,1204,1211,1206,363,362,360,361,364,1195,117,119,118,3314,1192,14,13,111,115,116,1315,3543,3511,3078,3237,218,217,3341,3348,159,177,161,2619,156,157,495,11,93,97,504,346,10,12,17,3212,21,103,91,113,3384,3385,3358,3234,3182,3136,3119,3130,2572,3548,527,28,513,154,30,1059,1320,2570,1181,3351,3352,3381,545,500,1154,2588,1403,549,550,560,35531,1087,1092,1097,1101,904,903,902,901,900,899,879,878,877,876,885,884,883,882,881,891,890,889,888,887,897,896,895,894,893,910,909,908,906,892,886,880,875,898,1082,1158,520,853,854,855,856,1073,1074,1072,2989,326,37,38,39,518,519,517,3534,3533,3532,3531,3535,3530,3527,3526,3525,3524,3523,3528,3522,3333,3332,3331,3330,3329,3328,3327,3326,3325,477,491,492,493,336,337,338,339,308,309,314,494,3224,3223,3222,3221,3220,3376,3375,291,3374,294,295,1208,1205,1210,321,324,322,1194,347,284,1156,3570,3493,1193,278,279,280,277,281,290,1316,3512,3240,506,507,731,287,288,289,353,286,496,272,273,505,2584,332,271,276,292,3213,307,342,325,341,3521,3529,2585,864,514,820,1071,1060,1061,546,551,552,874,270,350732,1088,1093,1098,1102,941,940,939,938,937,936,916,915,914,913,922,921,920,919,918,928,927,926,925,924,934,933,932,931,930,947,946,945,943,929,923,917,912,935,1083,1187,2580,859,414,1147,409,410,404,405,399,400,401,397,403,407,412,396,393,394,395,390,391,392,384,385,387,388,383,389,2582,378,379,3155,380,382,373,374,375,376,377,792,43,806,793,386,1065,1068,821,553,554,91133,1089,1094,1099,1103,978,977,976,975,974,973,953,952,951,950,959,958,957,956,955,965,964,963,962,961,971,970,969,968,967,984,983,982,980,966,960,954,949,972,1084,2581,860,784,1142,781,782,873,872,775,799,777,778,752,753,754,755,756,757,749,772,773,774,767,768,770,771,747,751,2583,766,765,763,762,764,1185,758,761,744,745,746,801,802,742,743,789,790,803,788,769,1066,1069,822,555,556,94834,1090,1095,1100,1104,1015,1014,1013,1012,1011,1010,990,989,988,987,996,995,994,993,992,1002,1001,1000,999,998,1008,1007,1006,1005,1004,1021,1020,1019,1017,1003,997,991,986,1009,1085,2624,132,1160,2402,2597,1109,485,483,482,431,2959,428,444,442,441,440,3152,447,446,451,450,448,445,439,3118,3120,455,454,2535,460,818,819,3539,458,457,456,453,464,463,809,810,3183,811,3514,469,468,807,467,475,474,2556,472,471,466,465,462,461,452,438,423,1186,422,824,131,1067,1070,843,823,3193,2404,557,558,98535) AND ISEC.rl0 IN (1,32,33,34,35) GROUP BY IP.phash,ISEC.phash,ISEC.phash_t3,ISEC.rl0,ISEC.rl1,ISEC.rl2,ISEC.page_id,ISEC.uniqid,IP.phash_grouping,IP.data_filename ,IP.data_page_id ,IP.data_page_reg1,IP.data_page_type,IP.data_page_mp,IP.gr_list,IP.item_type,IP.item_title,IP.item_description,IP.item_mtime,IP.tstamp,IP.item_size,IP.contentHash,IP.crdate,IP.parsetime,IP.sys_language_uid,IP.item_crdate,IP.cHashParams,IP.externalUrl,IP.recordUid,IP.freeIndexUid,IP.freeIndexSetId ORDER BY  FIELD(ISEC.rl0, 1,32,33,34,35), score DESC
 
------------------------------------------------------------------------------------------------------
 
sum(memory_used)
 
1011536
 
------------------------------------------------------------------------------------------------------
 
Variable_name   Value
 
Memory_used     551900880
 
======================================================================================================
 
2016-02-02 23:03:54
 
------------------------------------------------------------------------------------------------------
 
memory_used     INFO
 
51760   NULL
 
75272   SELECT memory_used,INFO from information_schema.processlist
 
75184   SELECT uid FROM pages WHERE uid IN (3171) AND pages.deleted=0 AND pages.t3ver_state<=0 AND pages.pid<>-1 AND pages.hidden=0 AND pages.starttime<=1454450640 AND (pages.endtime=0 OR pages.endtime>1454450640) AND (pages.fe_group='' OR pages.fe_group IS NULL OR pages.fe_group='0' OR FIND_IN_SET('0',pages.fe_group) OR FIND_IN_SET('-2',pages.fe_group) OR FIND_IN_SET('1',pages.fe_group) OR FIND_IN_SET('5',pages.fe_group) OR FIND_IN_SET('6',pages.fe_group) OR FIND_IN_SET('11',pages.fe_group) OR FIND_IN_SET('16',pages.fe_group) OR FIND_IN_SET('54',pages.fe_group) OR FIND_IN_SET('57',pages.fe_group) OR FIND_IN_SET('59',pages.fe_group) OR FIND_IN_SET('62',pages.fe_group) OR FIND_IN_SET('65',pages.fe_group) OR FIND_IN_SET('66',pages.fe_group)) AND doktype NOT IN (255)
 
58864   UPDATE fe_session_data\n\t\t\t\t\tSET\n\t\t\t\t\t\tcontent='a:17:{s:37:\\"espace_client_source_authentification\\";s:12:\\"particuliers\\";s:22:\\"authentification_admin\\";s:0:\\"\\";s:22:\\"authentification_login\\";s:0:\\"\\";s:25:\\"authentification_password\\";s:0:\\"\\";s:23:\\"authentification_par_id\\";s:0:\\"\\";s:26:\\"authentification_gc_groupe\\";s:0:\\"\\";s:26:\\"authentification_gc_profil\\";s:0:\\"\\";s:25:\\"authentification_multi_bp\\";s:0:\\"\\";s:28:\\"authentification_admin_infos\\";s:0:\\"\\";s:13:\\"dateEntretien\\";s:19:\\"date non disponible\\";s:29:\\"authentification_erreur_count\\";s:0:\\"\\";s:22:\\"facturation_mensu_goto\\";s:5:\\"step3\\";s:22:\\"facturation_mensu_elec\\";s:3:\\"112\\";s:21:\\"facturation_mensu_gaz\\";s:2:\\"64\\";s:17:\\"facturation_choix\\";s:3:\\"rib\\";s:15:\\"facturation_nom\\";s:18:\\"MR OU MME POSTILLE\\";s:16:\\"facturation_iban\\";s:33:\\"FR76 1670 6050 7916 4032 5570 369\\";}',\n\t\t\t\t\t\ttstamp='1454450638'\n\t\t\t\t\tWHERE\n\t\t\t\t\t\thash='316d75df48d69b1d9bcf6cf1370ccef8'
 
50704   NULL
 
50704   NULL
 
72696   SELECT MIN(starttime) AS starttime FROM tt_content WHERE pid = 3130 AND starttime > 1454450580 AND tt_content.deleted=0 AND tt_content.t3ver_state<=0 AND tt_content.pid<>-1 AND tt_content.hidden=0 AND (tt_content.fe_group='' OR tt_content.fe_group IS NULL OR tt_content.fe_group='0' OR FIND_IN_SET('0',tt_content.fe_group) OR FIND_IN_SET('-1',tt_content.fe_group)) LIMIT 1
 
58864   SELECT content FROM cf_extbase_reflection WHERE identifier = 'ReflectionData_DeTracking' AND cf_extbase_reflection.expires >= 1454450636 LIMIT 1
 
50440   NULL
 
132280  SELECT * FROM pages WHERE uid=1793 AND pages.deleted=0 AND pages.hidden=0 AND pages.starttime<=1454450580 AND (pages.endtime=0 OR pages.endtime>1454450580)  AND NOT pages.t3ver_state>0 AND pages.doktype<200 AND (pages.fe_group='' OR pages.fe_group IS NULL OR pages.fe_group='0' OR FIND_IN_SET('0',pages.fe_group) OR FIND_IN_SET('-2',pages.fe_group) OR FIND_IN_SET('1',pages.fe_group) OR FIND_IN_SET('6',pages.fe_group) OR FIND_IN_SET('12',pages.fe_group) OR FIND_IN_SET('16',pages.fe_group) OR FIND_IN_SET('21',pages.fe_group) OR FIND_IN_SET('37',pages.fe_group) OR FIND_IN_SET('54',pages.fe_group) OR FIND_IN_SET('57',pages.fe_group) OR FIND_IN_SET('59',pages.fe_group) OR FIND_IN_SET('62',pages.fe_group) OR FIND_IN_SET('65',pages.fe_group) OR FIND_IN_SET('66',pages.fe_group))
 
67088   NULL
 
50704   NULL
 
50704   NULL
 
75184   INSERT INTO tx_delib_webservice\n\t\t\t(\n\t\t\t\twebservice_date,\n\t\t\t\twebservice_code,\n\t\t\t\twebservice_message,\n\t\t\t\twebservice_file,\n\t\t\t\twebservice_trace,\n\t\t\t\twebservice_request,\n\t\t\t\twebservice_response,\n\t\t\t\twebservice_user_login\n\t\t\t) VALUES (\n\t\t\t\t'2016-02-02 23:04:06',\n\t\t\t\t'OK',\n\t\t\t\t'',\n\t\t\t\t'/usr/local/apps/sunprd/prd.sunrise/typo3conf/ext/de_lib/Classes/class.deWsGestionProspectPhoenix.php',\n\t\t\t\t'',\n\t\t\t\t'<?xml version=\\"1.0\\" encoding=\\"UTF-8\\"?>\\n<SOAP-ENV:Envelope xmlns:SOAP-ENV=\\"http://schemas.xmlsoap.org/soap/envelope/\\" xmlns:ns1=\\"http://www.direct-energie.com/prospect/gestion/schemas\\"><SOAP-ENV:Body><ns1:GetInformationsDossierRequest><ns1:numeroBS>D0E0205160418</ns1:numeroBS><ns1:controlParameter>a00f903cf570749be757aa339ed9a64d54400e4b588c73e762f3d5748d0ce34f</ns1:controlParameter></ns1:GetInformationsDossierRequest></SOAP-ENV:Body></SOAP-ENV:Envelope>\\n',\n\t\t\t\t'<soap:Envelope xmlns:soap=\\"http://schemas.xmlsoap.org/soap/envelope/\\"><soap:Body><GetInformationsDossierResponse xmlns=\\"http://www.direct-energie.com/prospect/gestion/schemas\\"><avancementElec xmlns:xsi=\\"http://www.w3.org/2001/XMLSchema-instance\\" xsi:nil=\\"true\\"/><avancementGaz><etat>SOUSCRIPTION</etat><statut>F00005</statut></avancementGaz><avancementGlobal><etat>SOUSCRIPTION</etat><statut>FC0070</statut></avancementGlobal><joindre><email>alexisdran@yahoo.fr</email><enseigne xmlns:xsi=\\"http://www.w3.org/2001/XMLSchema-instance\\" xsi:nil=\\"true\\"/><fax xmlns:xsi=\\"http://www.w3.org/2001/XMLSchema-instance\\" xsi:nil=\\"true\\"/><proCodeApe xmlns:xsi=\\"http://www.w3.org/2001/XMLSchema-instance\\" xsi:nil=\\"true\\"/><proCodeSiret xmlns:xsi=\\"http://www.w3.org/2001/XMLSchema-instance\\" xsi:nil=\\"true\\"/><raisonSociale xmlns:xsi=\\"http://www.w3.org/2001/XMLSchema-instance\\" xsi:nil=\\"true\\"/><telephone1>0783117844</telephone1><telephone2 xmlns:xsi=\\"http://www.w3.org/2001/XMLSchema-instance\\" xsi:nil=\\"true\\"/><telephoneTravail xmlns:xsi=\\"http://www.w3.org/2001/XMLSchema-instance\\" xsi:nil=\\"true\\"/><donneesCommerciales xmlns:xsi=\\"http://www.w3.org/2001/XMLSchema-instance\\" xsi:nil=\\"true\\"/></joindre><lieuConsommation><civilite>M</civilite><nom>DRAN</nom><nom2>DRAN</nom2><prenom>censored</prenom><prenom2>censored</prenom2><adresseCompleteFournie xmlns:xsi=\\"http://www.w3.org/2001/XMLSchema-instance\\" xsi:nil=\\"true\\"/><batiment xmlns:xsi=\\"http://www.w3.org/2001/XMLSchema-instance\\" xsi:nil=\\"true\\"/><escalier xmlns:xsi=\\"http://www.w3.org/2001/XMLSchema-instance\\" xsi:nil=\\"true\\"/><etage xmlns:xsi=\\"http://www.w3.org/2001/XMLSchema-instance\\" xsi:nil=\\"true\\"/><numeroAppartement xmlns:xsi=\\"http://www.w3.org/2001/XMLSchema-instance\\" xsi:nil=\\"true\\"/><complementAdresse>2EME ET//</complementAdresse><codeImmeuble xmlns:xsi=\\"http://www.w3.org/2001/XMLSchema-instance\\" xsi:nil=\\"true\\"/><numeroVoie>censored</numeroVoie><voie>censored</voie><codePostal>69240</codePostal><codeInsee>69248</codeInsee><ville>THIZY</ville><nomPredecesseur xmlns:xsi=\\"http://www.w3.org/2001/XMLSchema-instance\\" xsi:nil=\\"true\\"/></lieuConsommation><lieuFacturation><civilite>M</civilite><nom>DRAN</nom><nom2>DRAN</nom2><prenom>censored</prenom><prenom2>censored</prenom2><adresseCompleteFournie xmlns:xsi=\\"http://www.w3.org/2001/XMLSchema-instance\\" xsi:nil=\\"true\\"/><batiment xmlns:xsi=\\"http://www.w3.org/2001/XMLSchema-instance\\" xsi:nil=\\"true\\"/><escalier xmlns:xsi=\\"http://www.w3.org/2001/XMLSchema-instance\\" xsi:nil=\\"true\\"/><etage xmlns:xsi=\\"http://www.w3.org/2001/XMLSchema-instance\\" xsi:nil=\\"true\\"/><numeroAppartement xmlns:xsi=\\"http://www.w3.org/2001/XMLSchema-instance\\" xsi:nil=\\"true\\"/><complementAdresse>2EME ET//</complementAdresse><codeImmeuble xmlns:xsi=\\"http://www.w3.org/2001/XMLSchema-instance\\" xsi:nil=\\"true\\"/><numeroVoie>censored</numeroVoie><voie>censored</voie><codePostal>69240</codePostal><codeInsee>69248</codeInsee><ville>censored</ville><nomPredecesseur xmlns:xsi=\\"http://www.w3.org/2001/XMLSchema-instance\\" xsi:nil=\\"true\\"/></lieuFacturation><mensualisation><mensualiteAncFournisseurElec xmlns:xsi=\\"http://www.w3.org/2001/XMLSchema-instance\\" xsi:nil=\\"true\\"/><mensualiteAncFournisseurGaz xmlns:xsi=\\"http://www.w3.org/2001/XMLSchema-instance\\" xsi:nil=\\"true\\"/><mensualiteDEElec xmlns:xsi=\\"http://www.w3.org/2001/XMLSchema-instance\\" xsi:nil=\\"true\\"/><mensualiteDEGaz>67</mensualiteDEGaz></mensualisation><modePaiement><choixPaiement>SEPA</choixPaiement><prelevementCleRib>96</prelevementCleRib><prelevementCodeBanque>censored</prelevementCodeBanque><prelevementCodeGuichet>censored</prelevementCodeGuichet><prelevementDomiciliation>LBP CENTRE DE LYON</prelevementDomiciliation><prelevementNomBanque>LBP</prelevementNomBanque><prelevementNumeroCompte>censored</prelevementNumeroCompte><prelevementTitulaire>DRAME REBECCA ALEXIS</prelevementTitulaire><mandatInitie>true</mandatInitie></modePaiement><offre><dateSignature>2016-01-27+01:00</dateSignature><modeEnvoiContrat>email</modeEnvoiContrat><modeEnvoiFacture>email</modeEnvoiFacture><modeFacturation>A00</modeFacturation><codeOffre>070</codeOffre><listeOptions><option><packOptionCode>BASE</packOptionCode><packOptionLibelle>Base</packOptionLibelle></option></listeOptions><upsell>false</upsell></offre><reference><codeCanal>PRAV</codeCanal><codePromotion xmlns:xsi=\\"http://www.w3.org/2001/XMLSchema-instance\\" xsi:nil=\\"true\\"/><numeroBP>0103045055</numeroBP><numeroBPDemenagement xmlns:xsi=\\"http://www.w3.org/2001/XMLSchema-instance\\" xsi:nil=\\"true\\"/><numeroBPParrain xmlns:xsi=\\"http://www.w3.org/2001/XMLSchema-instance\\" xsi:nil=\\"true\\"/><numeroBS>D0E0205160418</numeroBS><origine>017</origine><typeClient>D</typeClient><typeSouscription>CDF</typeSouscription></reference><techniqueElec xmlns:xsi=\\"http://www.w3.org/2001/XMLSchema-instance\\" xsi:nil=\\"true\\"/><techniqueGaz><adresseGRDFNumero>censored</adresseGRDFNumero><adresseGRDFVoie>censored</adresseGRDFVoie><adresseGRDFComplement>2EME ET//;</adresseGRDFComplement><adresseGRDFCodePostal>69240</adresseGRDFCodePostal><adresseGRDFCodeINSEE>69248</adresseGRDFCodeINSEE><adresseGRDFVille>THIZY LES BOURGS</adresseGRDFVille><adresseGRDFValidee>true</adresseGRDFValidee><car>20508</car><classeConsommation>B1</classeConsommation><pce>censored</pce><zoneTarifaire>3</zoneTarifaire><numCompteur>932</numCompteur><datePrevisionnelleActivation xmlns:xsi=\\"http://www.w3.org/2001/XMLSchema-instance\\" xsi:nil=\\"true\\"/></techniqueGaz></GetInformationsDossierResponse></soap:Body></soap:Envelope>',\n\t\t\t\tNULL\n\t\t\t)
 
67088   NULL
 
50704   NULL
 
50440   NULL
 
67088   SELECT * FROM fe_session_data WHERE  hash = 'bc34b63d2148ca48fb733ea7d7047e5a'
 
58864   SELECT MIN(starttime) AS starttime FROM tt_content WHERE pid = 1105 AND starttime > 1454450580 AND tt_content.deleted=0 AND tt_content.t3ver_state<=0 AND tt_content.pid<>-1 AND tt_content.hidden=0 AND (tt_content.fe_group='' OR tt_content.fe_group IS NULL OR tt_content.fe_group='0' OR FIND_IN_SET('0',tt_content.fe_group) OR FIND_IN_SET('-1',tt_content.fe_group)) LIMIT 1
 
248056  SELECT index_fulltext.*, ISEC.*, IP.*,MATCH (index_fulltext.fulltextdata) AGAINST ('le déploiement du compteur linky c\\'est quand' WITH QUERY EXPANSION) as score FROM index_fulltext, index_section ISEC, index_phash IP WHERE MATCH (index_fulltext.fulltextdata) AGAINST ('le déploiement du compteur linky c\\'est quand' WITH QUERY EXPANSION)  AND IP.sys_language_uid=0\n\t\t\t\t\tAND index_fulltext.phash = IP.phash\n\t\t\t\t\tAND ISEC.phash = IP.phash\n\t\t\t\t\tAND  ISEC.page_id IN (1078,1079,1080,1081,825,826,827,828,1170,863,838,839,840,841,832,833,835,834,836,567,566,565,830,564,734,735,736,737,738,571,573,574,733,568,563,562,561,569,1077,522,509,536,537,1112,1113,1318,3149,2541,2607,2608,2609,3116,3536,3366,1407,3365,2589,2571,512,511,501,857,858,812,2988,528,529,544,530,3500,3499,3497,3496,3495,3324,3323,3322,3321,3320,3319,3318,3317,3316,3304,490,487,488,489,478,479,480,481,245,246,247,358,249,25,173,26,99,1319,174,3229,3228,3227,3226,3225,1105,15,16,1123,20,3311,3167,1314,3542,1204,1211,1206,363,362,360,361,364,1195,117,119,118,3314,1192,14,13,111,115,116,1315,3543,3511,3078,3237,218,217,3341,3348,159,177,161,2619,156,157,495,11,93,97,504,346,10,12,17,3212,21,103,91,113,3384,3385,3358,3234,3182,3136,3119,3130,2572,3548,527,28,513,154,30,1059,1320,2570,1181,3351,3352,3381,545,500,1154,2588,1403,549,550,560,35531,1087,1092,1097,1101,904,903,902,901,900,899,879,878,877,876,885,884,883,882,881,891,890,889,888,887,897,896,895,894,893,910,909,908,906,892,886,880,875,898,1082,1158,520,853,854,855,856,1073,1074,1072,2989,326,37,38,39,518,519,517,3534,3533,3532,3531,3535,3530,3527,3526,3525,3524,3523,3528,3522,3333,3332,3331,3330,3329,3328,3327,3326,3325,477,491,492,493,336,337,338,339,308,309,314,494,3224,3223,3222,3221,3220,3376,3375,291,3374,294,295,1208,1205,1210,321,324,322,1194,347,284,1156,3570,3493,1193,278,279,280,277,281,290,1316,3512,3240,506,507,731,287,288,289,353,286,496,272,273,505,2584,332,271,276,292,3213,307,342,325,341,3521,3529,2585,864,514,820,1071,1060,1061,546,551,552,874,270,350732,1088,1093,1098,1102,941,940,939,938,937,936,916,915,914,913,922,921,920,919,918,928,927,926,925,924,934,933,932,931,930,947,946,945,943,929,923,917,912,935,1083,1187,2580,859,414,1147,409,410,404,405,399,400,401,397,403,407,412,396,393,394,395,390,391,392,384,385,387,388,383,389,2582,378,379,3155,380,382,373,374,375,376,377,792,43,806,793,386,1065,1068,821,553,554,91133,1089,1094,1099,1103,978,977,976,975,974,973,953,952,951,950,959,958,957,956,955,965,964,963,962,961,971,970,969,968,967,984,983,982,980,966,960,954,949,972,1084,2581,860,784,1142,781,782,873,872,775,799,777,778,752,753,754,755,756,757,749,772,773,774,767,768,770,771,747,751,2583,766,765,763,762,764,1185,758,761,744,745,746,801,802,742,743,789,790,803,788,769,1066,1069,822,555,556,94834,1090,1095,1100,1104,1015,1014,1013,1012,1011,1010,990,989,988,987,996,995,994,993,992,1002,1001,1000,999,998,1008,1007,1006,1005,1004,1021,1020,1019,1017,1003,997,991,986,1009,1085,2624,132,1160,2402,2597,1109,485,483,482,431,2959,428,444,442,441,440,3152,447,446,451,450,448,445,439,3118,3120,455,454,2535,460,818,819,3539,458,457,456,453,464,463,809,810,3183,811,3514,469,468,807,467,475,474,2556,472,471,466,465,462,461,452,438,423,1186,422,824,131,1067,1070,843,823,3193,2404,557,558,98535) AND ISEC.rl0 IN (1,32,33,34,35) GROUP BY IP.phash,ISEC.phash,ISEC.phash_t3,ISEC.rl0,ISEC.rl1,ISEC.rl2,ISEC.page_id,ISEC.uniqid,IP.phash_grouping,IP.data_filename ,IP.data_page_id ,IP.data_page_reg1,IP.data_page_type,IP.data_page_mp,IP.gr_list,IP.item_type,IP.item_title,IP.item_description,IP.item_mtime,IP.tstamp,IP.item_size,IP.contentHash,IP.crdate,IP.parsetime,IP.sys_language_uid,IP.item_crdate,IP.cHashParams,IP.externalUrl,IP.recordUid,IP.freeIndexUid,IP.freeIndexSetId ORDER BY  FIELD(ISEC.rl0, 1,32,33,34,35), score DESC
 
248056  SELECT index_fulltext.*, ISEC.*, IP.*,MATCH (index_fulltext.fulltextdata) AGAINST ('le déploiement du compteur linky c\\'est quand' WITH QUERY EXPANSION) as score FROM index_fulltext, index_section ISEC, index_phash IP WHERE MATCH (index_fulltext.fulltextdata) AGAINST ('le déploiement du compteur linky c\\'est quand' WITH QUERY EXPANSION)  AND IP.sys_language_uid=0\n\t\t\t\t\tAND index_fulltext.phash = IP.phash\n\t\t\t\t\tAND ISEC.phash = IP.phash\n\t\t\t\t\tAND  ISEC.page_id IN (1078,1079,1080,1081,825,826,827,828,1170,863,838,839,840,841,832,833,835,834,836,567,566,565,830,564,734,735,736,737,738,571,573,574,733,568,563,562,561,569,1077,522,509,536,537,1112,1113,1318,3149,2541,2607,2608,2609,3116,3536,3366,1407,3365,2589,2571,512,511,501,857,858,812,2988,528,529,544,530,3500,3499,3497,3496,3495,3324,3323,3322,3321,3320,3319,3318,3317,3316,3304,490,487,488,489,478,479,480,481,245,246,247,358,249,25,173,26,99,1319,174,3229,3228,3227,3226,3225,1105,15,16,1123,20,3311,3167,1314,3542,1204,1211,1206,363,362,360,361,364,1195,117,119,118,3314,1192,14,13,111,115,116,1315,3543,3511,3078,3237,218,217,3341,3348,159,177,161,2619,156,157,495,11,93,97,504,346,10,12,17,3212,21,103,91,113,3384,3385,3358,3234,3182,3136,3119,3130,2572,3548,527,28,513,154,30,1059,1320,2570,1181,3351,3352,3381,545,500,1154,2588,1403,549,550,560,35531,1087,1092,1097,1101,904,903,902,901,900,899,879,878,877,876,885,884,883,882,881,891,890,889,888,887,897,896,895,894,893,910,909,908,906,892,886,880,875,898,1082,1158,520,853,854,855,856,1073,1074,1072,2989,326,37,38,39,518,519,517,3534,3533,3532,3531,3535,3530,3527,3526,3525,3524,3523,3528,3522,3333,3332,3331,3330,3329,3328,3327,3326,3325,477,491,492,493,336,337,338,339,308,309,314,494,3224,3223,3222,3221,3220,3376,3375,291,3374,294,295,1208,1205,1210,321,324,322,1194,347,284,1156,3570,3493,1193,278,279,280,277,281,290,1316,3512,3240,506,507,731,287,288,289,353,286,496,272,273,505,2584,332,271,276,292,3213,307,342,325,341,3521,3529,2585,864,514,820,1071,1060,1061,546,551,552,874,270,350732,1088,1093,1098,1102,941,940,939,938,937,936,916,915,914,913,922,921,920,919,918,928,927,926,925,924,934,933,932,931,930,947,946,945,943,929,923,917,912,935,1083,1187,2580,859,414,1147,409,410,404,405,399,400,401,397,403,407,412,396,393,394,395,390,391,392,384,385,387,388,383,389,2582,378,379,3155,380,382,373,374,375,376,377,792,43,806,793,386,1065,1068,821,553,554,91133,1089,1094,1099,1103,978,977,976,975,974,973,953,952,951,950,959,958,957,956,955,965,964,963,962,961,971,970,969,968,967,984,983,982,980,966,960,954,949,972,1084,2581,860,784,1142,781,782,873,872,775,799,777,778,752,753,754,755,756,757,749,772,773,774,767,768,770,771,747,751,2583,766,765,763,762,764,1185,758,761,744,745,746,801,802,742,743,789,790,803,788,769,1066,1069,822,555,556,94834,1090,1095,1100,1104,1015,1014,1013,1012,1011,1010,990,989,988,987,996,995,994,993,992,1002,1001,1000,999,998,1008,1007,1006,1005,1004,1021,1020,1019,1017,1003,997,991,986,1009,1085,2624,132,1160,2402,2597,1109,485,483,482,431,2959,428,444,442,441,440,3152,447,446,451,450,448,445,439,3118,3120,455,454,2535,460,818,819,3539,458,457,456,453,464,463,809,810,3183,811,3514,469,468,807,467,475,474,2556,472,471,466,465,462,461,452,438,423,1186,422,824,131,1067,1070,843,823,3193,2404,557,558,98535) AND ISEC.rl0 IN (1,32,33,34,35) GROUP BY IP.phash,ISEC.phash,ISEC.phash_t3,ISEC.rl0,ISEC.rl1,ISEC.rl2,ISEC.page_id,ISEC.uniqid,IP.phash_grouping,IP.data_filename ,IP.data_page_id ,IP.data_page_reg1,IP.data_page_type,IP.data_page_mp,IP.gr_list,IP.item_type,IP.item_title,IP.item_description,IP.item_mtime,IP.tstamp,IP.item_size,IP.contentHash,IP.crdate,IP.parsetime,IP.sys_language_uid,IP.item_crdate,IP.cHashParams,IP.externalUrl,IP.recordUid,IP.freeIndexUid,IP.freeIndexSetId ORDER BY  FIELD(ISEC.rl0, 1,32,33,34,35), score DESC
 
------------------------------------------------------------------------------------------------------
 
------------------------------------------------------------------------------------------------------
 

======================================================================================================
 
2016-02-03 04:33:48
 
------------------------------------------------------------------------------------------------------
 
memory_used     INFO
 
39408   NULL
 
75272   SELECT memory_used,INFO from information_schema.processlist
 
150200  SELECT index_fulltext.*, ISEC.*, IP.*,MATCH (index_fulltext.fulltextdata) AGAINST ('e-mail' WITH QUERY EXPANSION) as score FROM index_fulltext, index_section ISEC, index_phash IP WHERE MATCH (index_fulltext.fulltextdata) AGAINST ('e-mail' WITH QUERY EXPANSION)  AND IP.sys_language_uid=2\n\t\t\t\t\tAND index_fulltext.phash = IP.phash\n\t\t\t\t\tAND ISEC.phash = IP.phash\n\t\t\t\t\tAND  ISEC.page_id IN (3482,3336,3242,3135,3172,3371,3488,2710,2716,2715,2714,2713,2724,2723,2722,2721,2719,2730,2729,2728,2727,2726,2725,2718,2717,2712,2735,2734,2733,3387,3386,3280,3279,3278,3277,2750,2749,2754,2755,2753,2752,2748,3271,2739,2740,2732,2731,2711,2709,2708,2965,3134,3568,3485,34872705,2853,2852,2851,2850,2860,2859,2858,2857,2856,2866,2865,2864,2863,2862,2861,2855,3356,2849,2780,2785,2784,2783,3390,3389,3276,3275,3274,3273,2800,2799,2868,2805,2867,2802,2798,3272,2789,2790,2782,2781,2888,2779,2848,2759,27582756,3350,2874,2873,2872,2871,2881,2880,2879,2878,2877,2887,2886,2885,2884,2883,2882,2876,2875,2870,2993,2992,2991,3164,3179,3307,3162,2704,2836,3163,3174,3310,3309,3340,3305,3339,3181,2990,2995,2996,2994,2869,33492693) AND ISEC.rl0 IN (2705,2756,2693) GROUP BY IP.phash,ISEC.phash,ISEC.phash_t3,ISEC.rl0,ISEC.rl1,ISEC.rl2,ISEC.page_id,ISEC.uniqid,IP.phash_grouping,IP.data_filename ,IP.data_page_id ,IP.data_page_reg1,IP.data_page_type,IP.data_page_mp,IP.gr_list,IP.item_type,IP.item_title,IP.item_description,IP.item_mtime,IP.tstamp,IP.item_size,IP.contentHash,IP.crdate,IP.parsetime,IP.sys_language_uid,IP.item_crdate,IP.cHashParams,IP.externalUrl,IP.recordUid,IP.freeIndexUid,IP.freeIndexSetId ORDER BY  FIELD(ISEC.rl0, 2705,2756,2693), score DESC
 
150200  SELECT index_fulltext.*, ISEC.*, IP.*,MATCH (index_fulltext.fulltextdata) AGAINST ('e-mail' WITH QUERY EXPANSION) as score FROM index_fulltext, index_section ISEC, index_phash IP WHERE MATCH (index_fulltext.fulltextdata) AGAINST ('e-mail' WITH QUERY EXPANSION)  AND IP.sys_language_uid=2\n\t\t\t\t\tAND index_fulltext.phash = IP.phash\n\t\t\t\t\tAND ISEC.phash = IP.phash\n\t\t\t\t\tAND  ISEC.page_id IN (3482,3336,3242,3135,3172,3371,3488,2710,2716,2715,2714,2713,2724,2723,2722,2721,2719,2730,2729,2728,2727,2726,2725,2718,2717,2712,2735,2734,2733,3387,3386,3280,3279,3278,3277,2750,2749,2754,2755,2753,2752,2748,3271,2739,2740,2732,2731,2711,2709,2708,2965,3134,3568,3485,34872705,2853,2852,2851,2850,2860,2859,2858,2857,2856,2866,2865,2864,2863,2862,2861,2855,3356,2849,2780,2785,2784,2783,3390,3389,3276,3275,3274,3273,2800,2799,2868,2805,2867,2802,2798,3272,2789,2790,2782,2781,2888,2779,2848,2759,27582756,3350,2874,2873,2872,2871,2881,2880,2879,2878,2877,2887,2886,2885,2884,2883,2882,2876,2875,2870,2993,2992,2991,3164,3179,3307,3162,2704,2836,3163,3174,3310,3309,3340,3305,3339,3181,2990,2995,2996,2994,2869,33492693) AND ISEC.rl0 IN (2705,2756,2693) GROUP BY IP.phash,ISEC.phash,ISEC.phash_t3,ISEC.rl0,ISEC.rl1,ISEC.rl2,ISEC.page_id,ISEC.uniqid,IP.phash_grouping,IP.data_filename ,IP.data_page_id ,IP.data_page_reg1,IP.data_page_type,IP.data_page_mp,IP.gr_list,IP.item_type,IP.item_title,IP.item_description,IP.item_mtime,IP.tstamp,IP.item_size,IP.contentHash,IP.crdate,IP.parsetime,IP.sys_language_uid,IP.item_crdate,IP.cHashParams,IP.externalUrl,IP.recordUid,IP.freeIndexUid,IP.freeIndexSetId ORDER BY  FIELD(ISEC.rl0, 2705,2756,2693), score DESC
 
150200  SELECT index_fulltext.*, ISEC.*, IP.*,MATCH (index_fulltext.fulltextdata) AGAINST ('e-mail' WITH QUERY EXPANSION) as score FROM index_fulltext, index_section ISEC, index_phash IP WHERE MATCH (index_fulltext.fulltextdata) AGAINST ('e-mail' WITH QUERY EXPANSION)  AND IP.sys_language_uid=2\n\t\t\t\t\tAND index_fulltext.phash = IP.phash\n\t\t\t\t\tAND ISEC.phash = IP.phash\n\t\t\t\t\tAND  ISEC.page_id IN (3482,3336,3242,3135,3172,3371,3488,2710,2716,2715,2714,2713,2724,2723,2722,2721,2719,2730,2729,2728,2727,2726,2725,2718,2717,2712,2735,2734,2733,3387,3386,3280,3279,3278,3277,2750,2749,2754,2755,2753,2752,2748,3271,2739,2740,2732,2731,2711,2709,2708,2965,3134,3568,3485,34872705,2853,2852,2851,2850,2860,2859,2858,2857,2856,2866,2865,2864,2863,2862,2861,2855,3356,2849,2780,2785,2784,2783,3390,3389,3276,3275,3274,3273,2800,2799,2868,2805,2867,2802,2798,3272,2789,2790,2782,2781,2888,2779,2848,2759,27582756,3350,2874,2873,2872,2871,2881,2880,2879,2878,2877,2887,2886,2885,2884,2883,2882,2876,2875,2870,2993,2992,2991,3164,3179,3307,3162,2704,2836,3163,3174,3310,3309,3340,3305,3339,3181,2990,2995,2996,2994,2869,33492693) AND ISEC.rl0 IN (2705,2756,2693) GROUP BY IP.phash,ISEC.phash,ISEC.phash_t3,ISEC.rl0,ISEC.rl1,ISEC.rl2,ISEC.page_id,ISEC.uniqid,IP.phash_grouping,IP.data_filename ,IP.data_page_id ,IP.data_page_reg1,IP.data_page_type,IP.data_page_mp,IP.gr_list,IP.item_type,IP.item_title,IP.item_description,IP.item_mtime,IP.tstamp,IP.item_size,IP.contentHash,IP.crdate,IP.parsetime,IP.sys_language_uid,IP.item_crdate,IP.cHashParams,IP.externalUrl,IP.recordUid,IP.freeIndexUid,IP.freeIndexSetId ORDER BY  FIELD(ISEC.rl0, 2705,2756,2693), score DESC
 
50704   NULL
 
50704   NULL
 
------------------------------------------------------------------------------------------------------
 
sum(memory_used)
 
758480
 
------------------------------------------------------------------------------------------------------
 
Variable_name   Value
 
Memory_used     551418752
 
======================================================================================================

Comment by Ruben de Graaf [ 2016-02-04 ]

For information we upgraded from mariadb 10.0.21 to 10.1.11 and we have the same issue...

We upgraded with a complete mysqldump and an import on a new server to prevent any weird forgotten binary issue.

We already crashed two times after 14 hours, time to go back to old mysql...

Comment by Elena Stepanova [ 2016-02-04 ]

rdegraaf, thanks for the info, I'm sure monty will look at it asap.
In the meantime, while working on another issue, I've also hit a memory problem (memory leak or overuse, but the result is the same, the server eventually gets killed due to OOM); I expect to have a test case soon, when I do, I will compare it to your data to see if there are similarities.

Comment by Ruben de Graaf [ 2016-02-04 ]

Glad to hear I'm not the only one with the issue

We had an other crash this afternoon, here is the /var/log/messages log in case Michael sees anything that might help him :

Feb  4 16:51:33 s-mytypo-01 kernel: snmpd invoked oom-killer: gfp_mask=0x201da, order=0, oom_adj=0, oom_score_adj=0
 
Feb  4 16:51:33 s-mytypo-01 kernel: snmpd cpuset=/ mems_allowed=0
 
Feb  4 16:51:33 s-mytypo-01 kernel: Pid: 1807, comm: snmpd Not tainted 2.6.32-573.3.1.el6.x86_64 #1
 
Feb  4 16:51:33 s-mytypo-01 kernel: Call Trace:
 
Feb  4 16:51:33 s-mytypo-01 kernel: [<ffffffff810d6dd1>] ? cpuset_print_task_mems_allowed+0x91/0xb0
 
Feb  4 16:51:33 s-mytypo-01 kernel: [<ffffffff8112a5d0>] ? dump_header+0x90/0x1b0
 
Feb  4 16:51:33 s-mytypo-01 kernel: [<ffffffff81232cbc>] ? security_real_capable_noaudit+0x3c/0x70
 
Feb  4 16:51:33 s-mytypo-01 kernel: [<ffffffff8112aa52>] ? oom_kill_process+0x82/0x2a0
 
Feb  4 16:51:33 s-mytypo-01 kernel: [<ffffffff8112a94e>] ? select_bad_process+0x9e/0x120
 
Feb  4 16:51:33 s-mytypo-01 kernel: [<ffffffff8112ae90>] ? out_of_memory+0x220/0x3c0
 
Feb  4 16:51:33 s-mytypo-01 kernel: [<ffffffff8113786c>] ? __alloc_pages_nodemask+0x93c/0x950
 
Feb  4 16:51:33 s-mytypo-01 kernel: [<ffffffff8117025a>] ? alloc_pages_current+0xaa/0x110
 
Feb  4 16:51:33 s-mytypo-01 kernel: [<ffffffff811279c7>] ? __page_cache_alloc+0x87/0x90
 
Feb  4 16:51:33 s-mytypo-01 kernel: [<ffffffff811273ae>] ? find_get_page+0x1e/0xa0
 
Feb  4 16:51:33 s-mytypo-01 kernel: [<ffffffff81128967>] ? filemap_fault+0x1a7/0x500
 
Feb  4 16:51:33 s-mytypo-01 kernel: [<ffffffff81151f04>] ? __do_fault+0x54/0x530
 
Feb  4 16:51:33 s-mytypo-01 kernel: [<ffffffff811524d7>] ? handle_pte_fault+0xf7/0xb20
 
Feb  4 16:51:33 s-mytypo-01 kernel: [<ffffffff8129b056>] ? vsnprintf+0x336/0x5e0
 
Feb  4 16:51:33 s-mytypo-01 kernel: [<ffffffff81012bbe>] ? copy_user_generic+0xe/0x20
 
Feb  4 16:51:33 s-mytypo-01 kernel: [<ffffffff81153199>] ? handle_mm_fault+0x299/0x3d0
 
Feb  4 16:51:33 s-mytypo-01 kernel: [<ffffffff8104f156>] ? __do_page_fault+0x146/0x500
 
Feb  4 16:51:33 s-mytypo-01 kernel: [<ffffffff81014a19>] ? read_tsc+0x9/0x10
 
Feb  4 16:51:33 s-mytypo-01 kernel: [<ffffffff810ad45f>] ? ktime_get_ts+0xbf/0x100
 
Feb  4 16:51:33 s-mytypo-01 kernel: [<ffffffff811a9348>] ? poll_select_copy_remaining+0xf8/0x150
 
Feb  4 16:51:33 s-mytypo-01 kernel: [<ffffffff8153e95e>] ? do_page_fault+0x3e/0xa0
 
Feb  4 16:51:33 s-mytypo-01 kernel: [<ffffffff8153bd05>] ? page_fault+0x25/0x30
 
Feb  4 16:51:33 s-mytypo-01 kernel: Mem-Info:
 
Feb  4 16:51:33 s-mytypo-01 kernel: Node 0 DMA per-cpu:
 
Feb  4 16:51:33 s-mytypo-01 kernel: CPU    0: hi:    0, btch:   1 usd:   0
 
Feb  4 16:51:33 s-mytypo-01 kernel: CPU    1: hi:    0, btch:   1 usd:   0
 
Feb  4 16:51:33 s-mytypo-01 kernel: CPU    2: hi:    0, btch:   1 usd:   0
 
Feb  4 16:51:33 s-mytypo-01 kernel: CPU    3: hi:    0, btch:   1 usd:   0
 
Feb  4 16:51:33 s-mytypo-01 kernel: CPU    4: hi:    0, btch:   1 usd:   0
 
Feb  4 16:51:33 s-mytypo-01 kernel: CPU    5: hi:    0, btch:   1 usd:   0
 
Feb  4 16:51:33 s-mytypo-01 kernel: CPU    6: hi:    0, btch:   1 usd:   0
 
Feb  4 16:51:33 s-mytypo-01 kernel: CPU    7: hi:    0, btch:   1 usd:   0
 
Feb  4 16:51:33 s-mytypo-01 kernel: Node 0 DMA32 per-cpu:
 
Feb  4 16:51:33 s-mytypo-01 kernel: CPU    0: hi:  186, btch:  31 usd:   0
 
Feb  4 16:51:33 s-mytypo-01 kernel: CPU    1: hi:  186, btch:  31 usd:   0
 
Feb  4 16:51:33 s-mytypo-01 kernel: CPU    2: hi:  186, btch:  31 usd:   0
 
Feb  4 16:51:33 s-mytypo-01 kernel: CPU    3: hi:  186, btch:  31 usd:   0
 
Feb  4 16:51:33 s-mytypo-01 kernel: CPU    4: hi:  186, btch:  31 usd:   0
 
Feb  4 16:51:33 s-mytypo-01 kernel: CPU    5: hi:  186, btch:  31 usd:   0
 
Feb  4 16:51:33 s-mytypo-01 kernel: CPU    6: hi:  186, btch:  31 usd:   0
 
Feb  4 16:51:33 s-mytypo-01 kernel: CPU    7: hi:  186, btch:  31 usd:   0
 
Feb  4 16:51:33 s-mytypo-01 kernel: Node 0 Normal per-cpu:
 
Feb  4 16:51:33 s-mytypo-01 kernel: CPU    0: hi:  186, btch:  31 usd:   0
 
Feb  4 16:51:33 s-mytypo-01 kernel: CPU    1: hi:  186, btch:  31 usd:  30
 
Feb  4 16:51:33 s-mytypo-01 kernel: CPU    2: hi:  186, btch:  31 usd:  45
 
Feb  4 16:51:33 s-mytypo-01 kernel: CPU    3: hi:  186, btch:  31 usd:  50
 
Feb  4 16:51:33 s-mytypo-01 kernel: CPU    4: hi:  186, btch:  31 usd:  52
 
Feb  4 16:51:33 s-mytypo-01 kernel: CPU    5: hi:  186, btch:  31 usd:   0
 
Feb  4 16:51:33 s-mytypo-01 kernel: CPU    6: hi:  186, btch:  31 usd:   0
 
Feb  4 16:51:33 s-mytypo-01 kernel: CPU    7: hi:  186, btch:  31 usd:  76
 
Feb  4 16:51:33 s-mytypo-01 kernel: active_anon:5933881 inactive_anon:104937 isolated_anon:64
 
Feb  4 16:51:33 s-mytypo-01 kernel: active_file:686 inactive_file:861 isolated_file:0
 
Feb  4 16:51:33 s-mytypo-01 kernel: unevictable:0 dirty:0 writeback:0 unstable:0
 
Feb  4 16:51:33 s-mytypo-01 kernel: free:41868 slab_reclaimable:2153 slab_unreclaimable:8476
 
Feb  4 16:51:33 s-mytypo-01 kernel: mapped:1034 shmem:36 pagetables:13523 bounce:0
 
Feb  4 16:51:33 s-mytypo-01 kernel: Node 0 DMA free:15564kB min:40kB low:48kB high:60kB active_anon:0kB inactive_anon:0kB active_file:0kB inactive_file:0kB unevictable:0kB isolated(anon):0kB isolated(file):0kB present:15172kB mlocked:0kB dirty:0kB writeback:0kB mapped:0kB shmem:0kB slab_reclaimable:0kB slab_unreclaimable:0kB kernel_stack:0kB pagetables:0kB unstable:0kB bounce:0kB writeback_tmp:0kB pages_scanned:0 all_unreclaimable? yes
 
Feb  4 16:51:33 s-mytypo-01 kernel: lowmem_reserve[]: 0 3000 24210 24210
 
Feb  4 16:51:33 s-mytypo-01 kernel: Node 0 DMA32 free:93052kB min:8368kB low:10460kB high:12552kB active_anon:2105868kB inactive_anon:368616kB active_file:4kB inactive_file:4kB unevictable:0kB isolated(anon):0kB isolated(file):0kB present:3072160kB mlocked:0kB dirty:0kB writeback:0kB mapped:8kB shmem:0kB slab_reclaimable:0kB slab_unreclaimable:12kB kernel_stack:0kB pagetables:4072kB unstable:0kB bounce:0kB writeback_tmp:0kB pages_scanned:5015597 all_unreclaimable? yes
 
Feb  4 16:51:33 s-mytypo-01 kernel: lowmem_reserve[]: 0 0 21210 21210
 
Feb  4 16:51:33 s-mytypo-01 kernel: Node 0 Normal free:58856kB min:59172kB low:73964kB high:88756kB active_anon:21629656kB inactive_anon:51132kB active_file:2740kB inactive_file:3440kB unevictable:0kB isolated(anon):256kB isolated(file):0kB present:21719040kB mlocked:0kB dirty:0kB writeback:0kB mapped:4128kB shmem:144kB slab_reclaimable:8612kB slab_unreclaimable:33892kB kernel_stack:4352kB pagetables:50020kB unstable:0kB bounce:0kB writeback_tmp:0kB pages_scanned:204576 all_unreclaimable? yes
 
Feb  4 16:51:33 s-mytypo-01 kernel: lowmem_reserve[]: 0 0 0 0
 
Feb  4 16:51:33 s-mytypo-01 kernel: Node 0 DMA: 1*4kB 1*8kB 2*16kB 1*32kB 2*64kB 0*128kB 0*256kB 0*512kB 1*1024kB 1*2048kB 3*4096kB = 15564kB
 
Feb  4 16:51:33 s-mytypo-01 kernel: Node 0 DMA32: 123*4kB 90*8kB 68*16kB 24*32kB 12*64kB 15*128kB 11*256kB 3*512kB 3*1024kB 1*2048kB 19*4096kB = 93052kB
 
Feb  4 16:51:33 s-mytypo-01 kernel: Node 0 Normal: 734*4kB 379*8kB 268*16kB 203*32kB 139*64kB 100*128kB 45*256kB 12*512kB 3*1024kB 0*2048kB 0*4096kB = 59184kB
 
Feb  4 16:51:33 s-mytypo-01 kernel: 1745 total pagecache pages
 
Feb  4 16:51:33 s-mytypo-01 kernel: 38 pages in swap cache
 
Feb  4 16:51:33 s-mytypo-01 kernel: Swap cache stats: add 263631, delete 263593, find 382/528
 
Feb  4 16:51:33 s-mytypo-01 kernel: Free swap  = 8kB
 
Feb  4 16:51:33 s-mytypo-01 kernel: Total swap = 1048572kB
 
Feb  4 16:51:33 s-mytypo-01 kernel: 6291440 pages RAM
 
Feb  4 16:51:33 s-mytypo-01 kernel: 139643 pages reserved
 
Feb  4 16:51:33 s-mytypo-01 kernel: 1311 pages shared
 
Feb  4 16:51:33 s-mytypo-01 kernel: 6104261 pages non-shared
 
Feb  4 16:51:33 s-mytypo-01 kernel: [ pid ]   uid  tgid total_vm      rss cpu oom_adj oom_score_adj name
 
Feb  4 16:51:33 s-mytypo-01 kernel: [  644]     0   644     2760        0   5     -17         -1000 udevd
 
Feb  4 16:51:33 s-mytypo-01 kernel: [ 1082]     0  1082     2759        0   5     -17         -1000 udevd
 
Feb  4 16:51:33 s-mytypo-01 kernel: [ 1085]     0  1085     2759        0   1     -17         -1000 udevd
 
Feb  4 16:51:33 s-mytypo-01 kernel: [ 1541]     0  1541    44789      175   4       0             0 vmtoolsd
 
Feb  4 16:51:33 s-mytypo-01 kernel: [ 1614]     0  1614     6899        3   6     -17         -1000 auditd
 
Feb  4 16:51:33 s-mytypo-01 kernel: [ 1666]     0  1666     4598       97   4       0             0 irqbalance
 
Feb  4 16:51:33 s-mytypo-01 kernel: [ 1684]    32  1684     4744       16   6       0             0 rpcbind
 
Feb  4 16:51:33 s-mytypo-01 kernel: [ 1708]    29  1708     5837        1   0       0             0 rpc.statd
 
Feb  4 16:51:33 s-mytypo-01 kernel: [ 1735]    81  1735     5882        1   1       0             0 dbus-daemon
 
Feb  4 16:51:33 s-mytypo-01 kernel: [ 1795]    99  1795     3222        0   6       0             0 dnsmasq
 
Feb  4 16:51:33 s-mytypo-01 kernel: [ 1807]     0  1807    50638      140   1       0             0 snmpd
 
Feb  4 16:51:33 s-mytypo-01 kernel: [ 1826]     0  1826    16556       13   7     -17         -1000 sshd
 
Feb  4 16:51:33 s-mytypo-01 kernel: [ 1839]    38  1839     8208       17   1       0             0 ntpd
 
Feb  4 16:51:33 s-mytypo-01 kernel: [ 2085]    93  2085    24360       10   4       0             0 exim
 
Feb  4 16:51:33 s-mytypo-01 kernel: [ 2109]   498  2109    10893        8   6       0             0 nrpe
 
Feb  4 16:51:33 s-mytypo-01 kernel: [ 2141]     0  2141    30280       10   7       0             0 crond
 
Feb  4 16:51:33 s-mytypo-01 kernel: [ 2154]     0  2154    35336      226   5       0             0 munin-node
 
Feb  4 16:51:33 s-mytypo-01 kernel: [ 2313]     0  2313    27085        7   7       0             0 rhsmcertd
 
Feb  4 16:51:33 s-mytypo-01 kernel: [ 2377]     0  2377     1016        1   5       0             0 mingetty
 
Feb  4 16:51:33 s-mytypo-01 kernel: [ 2379]     0  2379     1016        1   7       0             0 mingetty
 
Feb  4 16:51:33 s-mytypo-01 kernel: [ 2381]     0  2381     1016        1   5       0             0 mingetty
 
Feb  4 16:51:33 s-mytypo-01 kernel: [ 2383]     0  2383     1016        1   0       0             0 mingetty
 
Feb  4 16:51:33 s-mytypo-01 kernel: [ 2385]     0  2385     1016        1   5       0             0 mingetty
 
Feb  4 16:51:33 s-mytypo-01 kernel: [ 2387]     0  2387     1016        1   5       0             0 mingetty
 
Feb  4 16:51:33 s-mytypo-01 kernel: [25899]     0 25899    27084        8   5       0             0 mysqld_safe
 
Feb  4 16:51:33 s-mytypo-01 kernel: [26082]    27 26082  8107554  6038838   3       0             0 mysqld
 
Feb  4 16:51:33 s-mytypo-01 kernel: [17137]     0 17137    67715      210   7       0             0 rsyslogd
 
Feb  4 16:51:33 s-mytypo-01 kernel: Out of memory: Kill process 26082 (mysqld) score 983 or sacrifice child
 
Feb  4 16:51:33 s-mytypo-01 kernel: Killed process 26082, UID 27, (mysqld) total-vm:32430216kB, anon-rss:24151940kB, file-rss:3412kB
 
Feb  4 16:51:33 s-mytypo-01 kernel: mysqld invoked oom-killer: gfp_mask=0x200da, order=0, oom_adj=0, oom_score_adj=0
 
Feb  4 16:51:33 s-mytypo-01 kernel: mysqld cpuset=/ mems_allowed=0
 
Feb  4 16:51:33 s-mytypo-01 kernel: Pid: 26083, comm: mysqld Not tainted 2.6.32-573.3.1.el6.x86_64 #1
 
Feb  4 16:51:33 s-mytypo-01 kernel: Call Trace:
 
Feb  4 16:51:33 s-mytypo-01 kernel: [<ffffffff810d6dd1>] ? cpuset_print_task_mems_allowed+0x91/0xb0
 
Feb  4 16:51:33 s-mytypo-01 kernel: [<ffffffff8112a5d0>] ? dump_header+0x90/0x1b0
 
Feb  4 16:51:33 s-mytypo-01 kernel: [<ffffffff81232cbc>] ? security_real_capable_noaudit+0x3c/0x70
 
Feb  4 16:51:33 s-mytypo-01 kernel: [<ffffffff8112aa52>] ? oom_kill_process+0x82/0x2a0
 
Feb  4 16:51:33 s-mytypo-01 kernel: [<ffffffff8112a94e>] ? select_bad_process+0x9e/0x120
 
Feb  4 16:51:33 s-mytypo-01 kernel: [<ffffffff8112ae90>] ? out_of_memory+0x220/0x3c0
 
Feb  4 16:51:33 s-mytypo-01 kernel: [<ffffffff8114a0a9>] ? zone_statistics+0x99/0xc0
 
Feb  4 16:51:33 s-mytypo-01 kernel: [<ffffffff8113786c>] ? __alloc_pages_nodemask+0x93c/0x950
 
Feb  4 16:51:33 s-mytypo-01 kernel: [<ffffffff8106f193>] ? dequeue_entity+0x113/0x2e0
 
Feb  4 16:51:33 s-mytypo-01 kernel: [<ffffffff8117035a>] ? alloc_pages_vma+0x9a/0x150
 
Feb  4 16:51:33 s-mytypo-01 kernel: [<ffffffff81163882>] ? read_swap_cache_async+0xf2/0x160
 
Feb  4 16:51:33 s-mytypo-01 kernel: [<ffffffff811643d9>] ? valid_swaphandles+0x69/0x160
 
Feb  4 16:51:33 s-mytypo-01 kernel: [<ffffffff81163977>] ? swapin_readahead+0x87/0xc0
 
Feb  4 16:51:33 s-mytypo-01 kernel: [<ffffffff81152abd>] ? handle_pte_fault+0x6dd/0xb20
 
Feb  4 16:51:33 s-mytypo-01 kernel: [<ffffffff8153b606>] ? rwsem_down_read_failed+0x26/0x30
 
Feb  4 16:51:33 s-mytypo-01 kernel: [<ffffffff81153199>] ? handle_mm_fault+0x299/0x3d0
 
Feb  4 16:51:33 s-mytypo-01 kernel: [<ffffffff8129d4b4>] ? call_rwsem_down_read_failed+0x14/0x30
 
Feb  4 16:51:33 s-mytypo-01 kernel: [<ffffffff8104f156>] ? __do_page_fault+0x146/0x500
 
Feb  4 16:51:33 s-mytypo-01 kernel: [<ffffffff81066053>] ? perf_event_task_sched_out+0x33/0x70
 
Feb  4 16:51:33 s-mytypo-01 kernel: [<ffffffff810097cc>] ? __switch_to+0x1ac/0x340
 
Feb  4 16:51:33 s-mytypo-01 kernel: [<ffffffff8153e95e>] ? do_page_fault+0x3e/0xa0
 
Feb  4 16:51:33 s-mytypo-01 kernel: [<ffffffff8153bd05>] ? page_fault+0x25/0x30
 
Feb  4 16:51:33 s-mytypo-01 kernel: [<ffffffff8129c5cc>] ? __get_user_8+0x1c/0x23
 
Feb  4 16:51:33 s-mytypo-01 kernel: [<ffffffff810b590d>] ? exit_robust_list+0x5d/0x160
 
Feb  4 16:51:33 s-mytypo-01 kernel: [<ffffffff810f59b6>] ? __delayacct_add_tsk+0x196/0x1b0
 
Feb  4 16:51:33 s-mytypo-01 kernel: [<ffffffff81074666>] ? mm_release+0x136/0x150
 
Feb  4 16:51:33 s-mytypo-01 kernel: [<ffffffff8107c156>] ? exit_mm+0x26/0x180
 
Feb  4 16:51:33 s-mytypo-01 kernel: [<ffffffff8107c60f>] ? do_exit+0x15f/0x870
 
Feb  4 16:51:33 s-mytypo-01 kernel: [<ffffffff8107cd78>] ? do_group_exit+0x58/0xd0
 
Feb  4 16:51:33 s-mytypo-01 kernel: [<ffffffff81092a26>] ? get_signal_to_deliver+0x1f6/0x460
 
Feb  4 16:51:33 s-mytypo-01 kernel: [<ffffffff8100a285>] ? do_signal+0x75/0x870
 
Feb  4 16:51:33 s-mytypo-01 kernel: [<ffffffff81297755>] ? rwsem_wake+0x75/0x170
 
Feb  4 16:51:33 s-mytypo-01 kernel: [<ffffffff810b828b>] ? sys_futex+0x7b/0x170
 
Feb  4 16:51:33 s-mytypo-01 kernel: [<ffffffff8100ab10>] ? do_notify_resume+0x90/0xc0
 
Feb  4 16:51:33 s-mytypo-01 kernel: [<ffffffff8100b3a1>] ? int_signal+0x12/0x17
 
Feb  4 16:51:33 s-mytypo-01 kernel: Mem-Info:
 
Feb  4 16:51:33 s-mytypo-01 kernel: Node 0 DMA per-cpu:
 
Feb  4 16:51:33 s-mytypo-01 kernel: CPU    0: hi:    0, btch:   1 usd:   0
 
Feb  4 16:51:33 s-mytypo-01 kernel: CPU    1: hi:    0, btch:   1 usd:   0
 
Feb  4 16:51:33 s-mytypo-01 kernel: CPU    2: hi:    0, btch:   1 usd:   0
 
Feb  4 16:51:33 s-mytypo-01 kernel: CPU    3: hi:    0, btch:   1 usd:   0
 
Feb  4 16:51:33 s-mytypo-01 kernel: CPU    4: hi:    0, btch:   1 usd:   0
 
Feb  4 16:51:33 s-mytypo-01 kernel: CPU    5: hi:    0, btch:   1 usd:   0
 
Feb  4 16:51:33 s-mytypo-01 kernel: CPU    6: hi:    0, btch:   1 usd:   0
 
Feb  4 16:51:33 s-mytypo-01 kernel: CPU    7: hi:    0, btch:   1 usd:   0
 
Feb  4 16:51:33 s-mytypo-01 kernel: Node 0 DMA32 per-cpu:
 
Feb  4 16:51:33 s-mytypo-01 kernel: CPU    0: hi:  186, btch:  31 usd:   0
 
Feb  4 16:51:33 s-mytypo-01 kernel: CPU    1: hi:  186, btch:  31 usd:   0
 
Feb  4 16:51:33 s-mytypo-01 kernel: CPU    2: hi:  186, btch:  31 usd:   0
 
Feb  4 16:51:33 s-mytypo-01 kernel: CPU    3: hi:  186, btch:  31 usd:   0
 
Feb  4 16:51:33 s-mytypo-01 kernel: CPU    4: hi:  186, btch:  31 usd:   0
 
Feb  4 16:51:33 s-mytypo-01 kernel: CPU    5: hi:  186, btch:  31 usd:   0
 
Feb  4 16:51:33 s-mytypo-01 kernel: CPU    6: hi:  186, btch:  31 usd:   0
 
Feb  4 16:51:33 s-mytypo-01 kernel: CPU    7: hi:  186, btch:  31 usd:   0
 
Feb  4 16:51:33 s-mytypo-01 kernel: Node 0 Normal per-cpu:
 
Feb  4 16:51:33 s-mytypo-01 kernel: CPU    0: hi:  186, btch:  31 usd:  30
 
Feb  4 16:51:33 s-mytypo-01 kernel: CPU    1: hi:  186, btch:  31 usd:  29
 
Feb  4 16:51:33 s-mytypo-01 kernel: CPU    2: hi:  186, btch:  31 usd:  44
 
Feb  4 16:51:33 s-mytypo-01 kernel: CPU    3: hi:  186, btch:  31 usd:  49
 
Feb  4 16:51:33 s-mytypo-01 kernel: CPU    4: hi:  186, btch:  31 usd:  52
 
Feb  4 16:51:33 s-mytypo-01 kernel: CPU    5: hi:  186, btch:  31 usd:  29
 
Feb  4 16:51:33 s-mytypo-01 kernel: CPU    6: hi:  186, btch:  31 usd:   0
 
Feb  4 16:51:33 s-mytypo-01 kernel: CPU    7: hi:  186, btch:  31 usd:  74
 
Feb  4 16:51:33 s-mytypo-01 kernel: active_anon:5916331 inactive_anon:122489 isolated_anon:64
 
Feb  4 16:51:33 s-mytypo-01 kernel: active_file:686 inactive_file:861 isolated_file:0
 
Feb  4 16:51:33 s-mytypo-01 kernel: unevictable:0 dirty:0 writeback:0 unstable:0
 
Feb  4 16:51:33 s-mytypo-01 kernel: free:41868 slab_reclaimable:2153 slab_unreclaimable:8476
 
Feb  4 16:51:33 s-mytypo-01 kernel: mapped:1034 shmem:36 pagetables:13523 bounce:0
 
Feb  4 16:51:33 s-mytypo-01 kernel: Node 0 DMA free:15564kB min:40kB low:48kB high:60kB active_anon:0kB inactive_anon:0kB active_file:0kB inactive_file:0kB unevictable:0kB isolated(anon):0kB isolated(file):0kB present:15172kB mlocked:0kB dirty:0kB writeback:0kB mapped:0kB shmem:0kB slab_reclaimable:0kB slab_unreclaimable:0kB kernel_stack:0kB pagetables:0kB unstable:0kB bounce:0kB writeback_tmp:0kB pages_scanned:0 all_unreclaimable? yes
 
Feb  4 16:51:33 s-mytypo-01 kernel: lowmem_reserve[]: 0 3000 24210 24210
 
Feb  4 16:51:33 s-mytypo-01 kernel: Node 0 DMA32 free:93052kB min:8368kB low:10460kB high:12552kB active_anon:2071668kB inactive_anon:402816kB active_file:4kB inactive_file:4kB unevictable:0kB isolated(anon):0kB isolated(file):0kB present:3072160kB mlocked:0kB dirty:0kB writeback:0kB mapped:8kB shmem:0kB slab_reclaimable:0kB slab_unreclaimable:12kB kernel_stack:0kB pagetables:4072kB unstable:0kB bounce:0kB writeback_tmp:0kB pages_scanned:5028336 all_unreclaimable? yes
 
Feb  4 16:51:33 s-mytypo-01 kernel: lowmem_reserve[]: 0 0 21210 21210
 
Feb  4 16:51:33 s-mytypo-01 kernel: Node 0 Normal free:58856kB min:59172kB low:73964kB high:88756kB active_anon:21593656kB inactive_anon:87140kB active_file:2740kB inactive_file:3440kB unevictable:0kB isolated(anon):256kB isolated(file):0kB present:21719040kB mlocked:0kB dirty:0kB writeback:0kB mapped:4128kB shmem:144kB slab_reclaimable:8612kB slab_unreclaimable:33892kB kernel_stack:4352kB pagetables:50020kB unstable:0kB bounce:0kB writeback_tmp:0kB pages_scanned:315456 all_unreclaimable? yes
 
Feb  4 16:51:33 s-mytypo-01 kernel: lowmem_reserve[]: 0 0 0 0
 
Feb  4 16:51:33 s-mytypo-01 kernel: Node 0 DMA: 1*4kB 1*8kB 2*16kB 1*32kB 2*64kB 0*128kB 0*256kB 0*512kB 1*1024kB 1*2048kB 3*4096kB = 15564kB
 
Feb  4 16:51:33 s-mytypo-01 kernel: Node 0 DMA32: 123*4kB 90*8kB 68*16kB 24*32kB 12*64kB 15*128kB 11*256kB 3*512kB 3*1024kB 1*2048kB 19*4096kB = 93052kB
 
Feb  4 16:51:33 s-mytypo-01 kernel: Node 0 Normal: 734*4kB 380*8kB 268*16kB 195*32kB 139*64kB 100*128kB 45*256kB 12*512kB 3*1024kB 0*2048kB 0*4096kB = 58936kB
 
Feb  4 16:51:33 s-mytypo-01 kernel: 1745 total pagecache pages
 
Feb  4 16:51:33 s-mytypo-01 kernel: 38 pages in swap cache
 
Feb  4 16:51:33 s-mytypo-01 kernel: Swap cache stats: add 263631, delete 263593, find 382/529
 
Feb  4 16:51:33 s-mytypo-01 kernel: Free swap  = 4kB
 
Feb  4 16:51:33 s-mytypo-01 kernel: Total swap = 1048572kB
 
Feb  4 16:51:33 s-mytypo-01 kernel: 6291440 pages RAM
 
Feb  4 16:51:33 s-mytypo-01 kernel: 139643 pages reserved
 
Feb  4 16:51:33 s-mytypo-01 kernel: 1366 pages shared
 
Feb  4 16:51:33 s-mytypo-01 kernel: 6104215 pages non-shared
 
Feb  4 16:51:33 s-mytypo-01 kernel: [ pid ]   uid  tgid total_vm      rss cpu oom_adj oom_score_adj name
 
Feb  4 16:51:33 s-mytypo-01 kernel: [  644]     0   644     2760        0   5     -17         -1000 udevd
 
Feb  4 16:51:33 s-mytypo-01 kernel: [ 1082]     0  1082     2759        0   5     -17         -1000 udevd
 
Feb  4 16:51:33 s-mytypo-01 kernel: [ 1085]     0  1085     2759        0   1     -17         -1000 udevd
 
Feb  4 16:51:33 s-mytypo-01 kernel: [ 1541]     0  1541    44789      175   3       0             0 vmtoolsd
 
Feb  4 16:51:33 s-mytypo-01 kernel: [ 1614]     0  1614     6899        3   6     -17         -1000 auditd
 
Feb  4 16:51:33 s-mytypo-01 kernel: [ 1666]     0  1666     4598       97   4       0             0 irqbalance
 
Feb  4 16:51:33 s-mytypo-01 kernel: [ 1684]    32  1684     4744       16   6       0             0 rpcbind
 
Feb  4 16:51:33 s-mytypo-01 kernel: [ 1708]    29  1708     5837        1   0       0             0 rpc.statd
 
Feb  4 16:51:33 s-mytypo-01 kernel: [ 1735]    81  1735     5882        1   1       0             0 dbus-daemon
 
Feb  4 16:51:33 s-mytypo-01 kernel: [ 1795]    99  1795     3222        0   6       0             0 dnsmasq
 
Feb  4 16:51:33 s-mytypo-01 kernel: [ 1807]     0  1807    50638      140   1       0             0 snmpd
 
Feb  4 16:51:33 s-mytypo-01 kernel: [ 1826]     0  1826    16556       13   7     -17         -1000 sshd
 
Feb  4 16:51:33 s-mytypo-01 kernel: [ 1839]    38  1839     8208       17   1       0             0 ntpd
 
Feb  4 16:51:33 s-mytypo-01 kernel: [ 2085]    93  2085    24360       10   4       0             0 exim
 
Feb  4 16:51:33 s-mytypo-01 kernel: [ 2109]   498  2109    10893        8   6       0             0 nrpe
 
Feb  4 16:51:33 s-mytypo-01 kernel: [ 2141]     0  2141    30280       10   7       0             0 crond
 
Feb  4 16:51:33 s-mytypo-01 kernel: [ 2154]     0  2154    35336      226   5       0             0 munin-node
 
Feb  4 16:51:33 s-mytypo-01 kernel: [ 2313]     0  2313    27085        7   7       0             0 rhsmcertd
 
Feb  4 16:51:33 s-mytypo-01 kernel: [ 2377]     0  2377     1016        1   5       0             0 mingetty
 
Feb  4 16:51:33 s-mytypo-01 kernel: [ 2379]     0  2379     1016        1   7       0             0 mingetty
 
Feb  4 16:51:33 s-mytypo-01 kernel: [ 2381]     0  2381     1016        1   5       0             0 mingetty
 
Feb  4 16:51:33 s-mytypo-01 kernel: [ 2383]     0  2383     1016        1   0       0             0 mingetty
 
Feb  4 16:51:33 s-mytypo-01 kernel: [ 2385]     0  2385     1016        1   5       0             0 mingetty
 
Feb  4 16:51:33 s-mytypo-01 kernel: [ 2387]     0  2387     1016        1   5       0             0 mingetty
 
Feb  4 16:51:33 s-mytypo-01 kernel: [25899]     0 25899    27084        8   5       0             0 mysqld_safe
 
Feb  4 16:51:33 s-mytypo-01 kernel: [26083]    27 26082  8108578  6038847   1       0             0 mysqld
 
Feb  4 16:51:33 s-mytypo-01 kernel: [17137]     0 17137    67715      211   7       0             0 rsyslogd

the /var/log/mysql/error.log log at the same time :

2016-02-04 16:51:34 140637078378528 [Note] /usr/sbin/mysqld (mysqld 10.1.11-MariaDB-log) starting as process 7656 ...
 
2016-02-04 16:51:34 140637078378528 [Note] InnoDB: Using mutexes to ref count buffer pool pages
 
2016-02-04 16:51:34 140637078378528 [Note] InnoDB: The InnoDB memory heap is disabled
 
2016-02-04 16:51:34 140637078378528 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
 
2016-02-04 16:51:34 140637078378528 [Note] InnoDB: Memory barrier is not used
 
2016-02-04 16:51:34 140637078378528 [Note] InnoDB: Compressed tables use zlib 1.2.3
 
2016-02-04 16:51:34 140637078378528 [Note] InnoDB: Using Linux native AIO
 
2016-02-04 16:51:34 140637078378528 [Note] InnoDB: Using SSE crc32 instructions
 
2016-02-04 16:51:34 140637078378528 [Note] InnoDB: Initializing buffer pool, size = 12.0G
 
2016-02-04 16:51:35 140637078378528 [Note] InnoDB: Completed initialization of buffer pool
 
2016-02-04 16:51:35 140637078378528 [Note] InnoDB: Highest supported file format is Barracuda.
 
2016-02-04 16:51:35 140637078378528 [Note] InnoDB: Log scan progressed past the checkpoint lsn 23156778703
 
2016-02-04 16:51:35 140637078378528 [Note] InnoDB: Database was not shutdown normally!
 
2016-02-04 16:51:35 140637078378528 [Note] InnoDB: Starting crash recovery.
 
2016-02-04 16:51:35 140637078378528 [Note] InnoDB: Reading tablespace information from the .ibd files...
 
2016-02-04 16:51:35 140637078378528 [Note] InnoDB: Restoring possible half-written data pages
 
2016-02-04 16:51:35 140637078378528 [Note] InnoDB: from the doublewrite buffer...
 
2016-02-04 16:51:46 140637078378528 [Note] InnoDB: Starting an apply batch of log records to the database...
 
2016-02-04 16:51:50 140637078378528 [Note] InnoDB: 128 rollback segment(s) are active.
 
2016-02-04 16:51:50 140637078378528 [Note] InnoDB: Waiting for purge to start
 
2016-02-04 16:51:50 140637078378528 [Note] InnoDB:  Percona XtraDB (http://www.percona.com) 5.6.26-76.0 started; log sequence number 23917321525
 
2016-02-04 16:51:52 140621335467776 [Note] InnoDB: Dumping buffer pool(s) not yet started
 
2016-02-04 16:51:52 140637078378528 [Note] Plugin 'FEEDBACK' is disabled.
 
2016-02-04 16:51:52 140637078378528 [Note] Recovering after a crash using tc.log
 
2016-02-04 16:51:52 140637078378528 [Note] Starting crash recovery...
 
2016-02-04 16:51:52 140637078378528 [Note] Crash recovery finished.
 
2016-02-04 16:51:52 140637078378528 [Warning] Failed to create a socket for IPv6 '::': errno: 97.
 
2016-02-04 16:51:52 140637078378528 [Note] Server socket created on IP: '0.0.0.0'.
 
2016-02-04 16:51:52 140637078378528 [Note] /usr/sbin/mysqld: ready for connections.

our server.cnf file :

[mysqld]
 
slow_query_log=1
 
slow_query_log_file=/var/log/mysql-slowquery.log
 
performance_schema=on
 
datadir=/var/lib/mysql
 
socket=/var/lib/mysql/mysql.sock
 
user=mysql
 
default-storage-engine=innodb
 
# Disabling symbolic-links is recommended to prevent assorted security risks
 
symbolic-links=0
 
ft_min_word_len=3
 
#
 
log-error=/var/log/mysql/error.log
 
#log-output=/var/log/mysql/mysql.log
 
general_log_file=/var/log/mysql/mysql.log
 
max_connections=1000
 
max_allowed_packet=16M
 
query_cache_type=1
 
query_cache_limit=1M
 
query_cache_size=256M
 
innodb_buffer_pool_size=12G
 
innodb_log_file_size=4G
 
innodb_data_home_dir=/var/lib/mysql
 
innodb_data_file_path=ibdata1:128M:autoextend
 
innodb_log_buffer_size=16M
 
innodb_flush_log_at_trx_commit=2
 
innodb_file_per_table
 
innodb_flush_method=O_DIRECT
 
innodb_thread_concurrency=0
 
innodb_read_io_threads=8
 
innodb_write_io_threads=8
 
low_priority_updates=1
 
concurrent_insert=2
 
table_open_cache=1000
 
open_files_limit=2000
 
long_query_time=5
 
tmpdir=/var/lib/mysql/tmp
 
#innodb_force_recovery=1
 
 
 
[mysqld_safe]
 
log-error=/var/log/mysql/error.log
 
#log-output=/var/log/mysql/mysql.log
 
pid-file=/var/run/mysqld/mysqld.pid

and the munin graph of the memory (which is composed of values taken each 5 minutes) :

Comment by Viktor Zeman [ 2016-02-04 ]

we have very similar graphs in our grafana monitoring.
we have 32GB/64GB machines and each time mysql process use more than 27GB/58GB we restart it to make sure it will not crash in next few minutes.

We try to keep our DB up to date (right now on 10.0.x) ... the problem persist long time in all 10.0.x and 10.1.x versions (tested)

Comment by Michael Widenius [ 2016-02-07 ]

Waiting for a test case from Elina.

I am starting to wonder, like Koen, if this could have anything to do with us now using jemalloc.

Is anyone there having this problem willing to try to do a compilation of mariadb without jemalloc and see if the problem disappears?
We could at the same time compile the binary with -g, so that if we could get a core we could find out what has allocated the memory.

Adding this to a production system is not that hard:

  • Recompile same version of mariadb
  • Swap the new compiled 'mysqld' binary with the standard one.
  • Do a restart (or wait for OOM killer)
  • After restart, the new mysqld is used.

In other words, no reason to install any other packages. Backing out is just a matter to restore the original mysqld binary.

Comment by Elena Stepanova [ 2016-02-07 ]

Waiting for a test case from Elina.

I'm working on that, but please, if you can look into it, please don't wait on me. While there is a chance that I'm having the same problem as this bug report describes, this chance at the moment looks rather slim – it seems that what I'm getting is not a real leak, but just a huge memory use on a particular query with joins (it joins 4 relatively small tables, 20, 20, 100 and 1000 rows, and at the top point it wants about 16G memory – so I'd say it's too much). It could have accounted for OOM that Ruben de Graaf is getting, but the initial reporter had a lot of memory on the machine and still had the issue, so I doubt it could be just one query. I will create the test case anyway, so somebody could check if this use of memory is justified.

Comment by Elena Stepanova [ 2016-02-09 ]

I came up with two different test cases, MDEV-9531 and MDEV-9533. The first one is exotic, and it's very unlikely that it's related to this issue. The second one can well be related – even though I don't see queries of the same exact pattern in the processlist above, I also don't see there anything that takes any significant amount of memory; so it's possible that the guilty query somehow escaped the list.

However, we must not forget the statement which is buried somewhere in this bug report – the memory problems were happening even if there was no activity on the server whatsoever. So, it can still be a totally different issue, not even related to query execution at all – e.g. something about background threads, or whatever.

Comment by Ruben de Graaf [ 2016-02-09 ]

Hello,

We might have found something interesting.
We were planning to rollback to mysql 5.1.73 tonight and so we had to adjust some data to be able to rollback in ideal conditions. One of the main things we had to do is change 2 innodb fulltext indexes back to MyISAM since this kind of index is only supported since MySQL 5.6 (those indexes have a weight of 700 MB on our database).

Weirdly enough, we did that change yesterday at 5pm and since then, we have no crash anymore... So either it's due to the ALTER that reconstructed the index and we bought us some time before the database is gonna crash again (I say this because once we upgraded from mariadb 10 to mariadb 10.1 the database didn't crash for about 12 hours), or the whole problem is innodb related when using fulltext indexes.

If this is true, it is valuable information to be able to find out what's going wrong. I'll keep you in touch if the database remains stable.

Comment by Viktor Zeman [ 2016-02-09 ]

I can confirm, that we use fulltext indexes as well on innodb tables.
Before we have used MyISAM tables with fulltext indexes and we had no memory problems as well in the past.
I'm not able to confirm, if our memory problems started exactly from migration to innodb fulltext indexes, but It looks like Ruben could be right.

Comment by Ruben de Graaf [ 2016-02-09 ]

Here is a munin memory graph from our server since the change, the difference is pretty clear :

Comment by Ruben de Graaf [ 2016-02-10 ]

Still no crash this far, the memory graph keeps looking good, the committed memory doesn't exceed the total amount of memory available, I really think the fulltext innodb index was messing the server up.

Comment by Ruben de Graaf [ 2016-02-15 ]

Everything is still going well after more than 5 days, here is a our munin weekly graph.

Comment by Elena Stepanova [ 2016-02-15 ]

rdegraaf,
Strangely though, there is no fulltext search in the general log that you uploaded for us back in November. So, it's either a different problem, or maybe it was a wrong log. What do you think?

I ran some tests involving InnoDB fulltext search, results are inconclusive so far.
It seems the important question might be, how much results these fulltext searches are expected to find.
rdegraaf, do you know this about your database?
InnoDB has a per-thread/query cache of the size innodb_ft_result_cache_limit which is nearly 2G by default. So, I suppose when the results are really big for several queries simultaneously, the memory consumption can quite easily get high, at least as high as we can see on your diagrams. It might be not a good explanation for the initial report though, values there are much higher, but we'll need to look at that data again.

Comment by Koen Crijns [ 2016-02-15 ]

Just want to confirm that when we had the original problem, we also were using full text indexes on InnoDB tables.

As I've stated earlier; after an unpgrade to CentOS 7 (from CentOS 6) the problem disappeared. Both MariaDB 10.0.x and now MariaDB 10.1.x run rock solid on our database server with CentOS 7.

Comment by Elena Stepanova [ 2016-02-15 ]

koenc, can you say how many threads, roughly, could be running full text searches simultaneously, and whether these searches were supposed to fetch bug result sets?

Comment by Ruben de Graaf [ 2016-02-15 ]

Mmh, that database I gave you back in November was the development server (which was crashing if the memory was lowered on the server), normally it should look like the production server, but I don't know exactly what the developers are doing on it though (I'm working in a department that handles the hardware mostly)...

Concerning that innodb cache variable here is what the production server currently has :

MariaDB [(none)]> show variables like "innodb_ft%"
-> ;
-------------------------------------------+

Variable_name Value

-------------------------------------------+

innodb_ft_aux_table  
innodb_ft_cache_size 8000000
innodb_ft_enable_diag_print OFF
innodb_ft_enable_stopword ON
innodb_ft_max_token_size 84
innodb_ft_min_token_size 3
innodb_ft_num_word_optimize 2000
innodb_ft_result_cache_limit 2000000000
innodb_ft_server_stopword_table  
innodb_ft_sort_pll_degree 2
innodb_ft_total_cache_size 640000000
innodb_ft_user_stopword_table  

-------------------------------------------+

Since we are hosting a website that has about 15000 visits per hour, each time a customer tries so search something with the search engine he is using those fulltext indexes and probably the memory isn't correctly used somehow.

Like I said on the production server the index weight is about 700 MB. And the results can be pretty big, If a customer is funny enough to search for a word like "the" the whole website might come back, and that are thousands of pages...

Comment by Michael Caplan [ 2019-03-09 ]

Koen Crijns, running into a similar issue with 10.2.14 (MDEV-18866) How did you resolve this issue 2 years ago, or did you?

Comment by Elena Stepanova [ 2019-03-09 ]

We had never been able to reproduce it, so no.
I'll assign both to svoj, maybe he'll be able to analyze it now using the new information.

Generated at Thu Feb 08 07:10:59 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.