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

InnoDB sometimes prints incorrect buffer pool size in the "Over xx percent of the buffer pool is occupied" message

Details

    Description

      10.3 b6f203984bc519a31ac695cbcb6de7f1f638d321

      ...
      2018-12-05 11:39:00 0 [Note] InnoDB: Initializing buffer pool, total size = 128M, instances = 1, chunk size = 128M
      ...
      2018-12-05 11:39:31 17 [Warning] InnoDB: Over 67 percent of the buffer pool is occupied by lock heaps or the adaptive hash index! Check that your transactions do not set too many row locks. innodb_buffer_pool_size=127M. Starting the InnoDB Monitor to print diagnostics.
      ...
      2018-12-05 11:44:12 18 [ERROR] [FATAL] InnoDB: Over 95 percent of the buffer pool is occupied by lock heaps or the adaptive hash index! Check that your transactions do not set too many row locks, or review if innodb_buf
      fer_pool_size=127M could be bigger.
      ...
      

      Note 127M in the error messages vs. 128M upon initialization (default value).
      It doesn't always happen, in most cases it prints 128M as expected.

      I have no information whether it happens with other server versions or other buffer pool sizes.

      Attachments

        Issue Links

          Activity

            alice Alice Sherepa added a comment -

            On 10.5 run for me it was 123M printed instead of 128, and then signal 6:

            bb-10.5-mdev_742 181cd53cf7f6e595c0

            2020-02-12 20:59:35 14 [ERROR] [FATAL] InnoDB: Over 95 percent of the buffer pool is occupied by lock heaps or the adaptive hash index! Check that your transactions do not set too many row locks, or review if innodb_buffer_pool_size=123M could be bigger.
             
            #3  <signal handler called>
            #4  0x00007f8cff5d1428 in __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:54
            #5  0x00007f8cff5d302a in __GI_abort () at abort.c:89
            #6  0x000055fa90097139 in ib::fatal::~fatal (this=0x7f8cf4162d30, __in_chrg=<optimized out>) at /10.5/storage/innobase/ut/ut0ut.cc:597
            #7  0x000055fa90149654 in buf_LRU_check_size_of_non_data_objects (buf_pool=0x55fa92d842d0) at /10.5/storage/innobase/buf/buf0lru.cc:1008
            #8  0x000055fa901499c0 in buf_LRU_get_free_block (buf_pool=0x55fa92d842d0) at /10.5/storage/innobase/buf/buf0lru.cc:1091
            #9  0x000055fa9010e510 in buf_block_alloc (buf_pool=0x55fa92d842d0) at /10.5/storage/innobase/buf/buf0buf.cc:703
            #10 0x000055fa8feeef71 in mem_heap_create_block_func (heap=0x55fa92c61400, n=16184, file_name=0x55fa92c61408 "0trx.cc", line=199, type=1) at /10.5/storage/innobase/mem/mem0mem.cc:297
            #11 0x000055fa8feef32c in mem_heap_add_block (heap=0x55fa92c61400, n=118) at /10.5/storage/innobase/mem/mem0mem.cc:386
            #12 0x000055fa8fea2fcb in mem_heap_alloc (heap=0x55fa92c61400, n=118) at /10.5/storage/innobase/include/mem0mem.ic:203
            #13 0x000055fa8feab932 in lock_rec_create_low (c_lock=0x0, thr=0x0, type_mode=34, space=28, page_no=781, page=0x7f8ce3928000 "", heap_no=1, index=0x7f8c78171ad8, trx=0x7f8cf536c390, holds_trx_mutex=false) at /10.5/storage/innobase/lock/lock0lock.cc:1391
            #14 0x000055fa8fea5bac in lock_rec_create (c_lock=0x0, thr=0x0, type_mode=34, block=0x7f8cdc461768, heap_no=1, index=0x7f8c78171ad8, trx=0x7f8cf536c390, caller_owns_trx_mutex=false) at /10.5/storage/innobase/include/lock0lock.ic:133
            #15 0x000055fa8feadd6f in lock_rec_add_to_queue (type_mode=34, block=0x7f8cdc461768, heap_no=1, index=0x7f8c78171ad8, trx=0x7f8cf536c390, caller_owns_trx_mutex=false) at /10.5/storage/innobase/lock/lock0lock.cc:1899
            #16 0x000055fa8feb039a in lock_rec_move_low (lock_hash=0x55fa93653030, receiver=0x7f8cdc461768, donator=0x7f8cdc26ec48, receiver_heap_no=1, donator_heap_no=1) at /10.5/storage/innobase/lock/lock0lock.cc:2537
            #17 0x000055fa8feb05b5 in lock_rec_move (receiver=0x7f8cdc461768, donator=0x7f8cdc26ec48, receiver_heap_no=1, donator_heap_no=1) at /10.5/storage/innobase/lock/lock0lock.cc:2596
            #18 0x000055fa8feb2592 in lock_update_merge_left (left_block=0x7f8cdc461768, orig_pred=0x7f8ce392ba5e "", right_block=0x7f8cdc26ec48) at /10.5/storage/innobase/lock/lock0lock.cc:3213
            #19 0x000055fa900ac528 in btr_compress (cursor=0x7f8c7c0ac7d8, adjust=0, mtr=0x7f8cf41642b0) at /10.5/storage/innobase/btr/btr0btr.cc:3707
            #20 0x000055fa900df1b6 in btr_cur_compress_if_useful (cursor=0x7f8c7c0ac7d8, adjust=0, mtr=0x7f8cf41642b0) at /10.5/storage/innobase/btr/btr0cur.cc:5642
            #21 0x000055fa900e1019 in btr_cur_pessimistic_delete (err=0x7f8cf4164250, has_reserved_extents=0, cursor=0x7f8c7c0ac7d8, flags=0, rollback=true, mtr=0x7f8cf41642b0) at /10.5/storage/innobase/btr/btr0cur.cc:6079
            #22 0x000055fa90248d9e in row_undo_ins_remove_clust_rec (node=0x7f8c7c0ac768) at /10.5/storage/innobase/row/row0uins.cc:187
            #23 0x000055fa9024a320 in row_undo_ins (node=0x7f8c7c0ac768, thr=0x7f8c7c026cc8) at /10.5/storage/innobase/row/row0uins.cc:590
            #24 0x000055fa9000149b in row_undo (node=0x7f8c7c0ac768, thr=0x7f8c7c026cc8) at /10.5/storage/innobase/row/row0undo.cc:431
            #25 0x000055fa90001774 in row_undo_step (thr=0x7f8c7c026cc8) at /10.5/storage/innobase/row/row0undo.cc:492
            #26 0x000055fa8ff435d4 in que_thr_step (thr=0x7f8c7c026cc8) at /10.5/storage/innobase/que/que0que.cc:1036
            #27 0x000055fa8ff43884 in que_run_threads_low (thr=0x7f8c7c026cc8) at /10.5/storage/innobase/que/que0que.cc:1100
            #28 0x000055fa8ff43ad1 in que_run_threads (thr=0x7f8c7c026cc8) at /10.5/storage/innobase/que/que0que.cc:1140
            #29 0x000055fa900700d0 in trx_rollback_to_savepoint_low (trx=0x7f8cf536c390, savept=0x7f8cf536d3a0) at /10.5/storage/innobase/trx/trx0roll.cc:140
            #30 0x000055fa900705ad in trx_rollback_to_savepoint (trx=0x7f8cf536c390, savept=0x7f8cf536d3a0) at /10.5/storage/innobase/trx/trx0roll.cc:193
            #31 0x000055fa900713f4 in trx_rollback_last_sql_stat_for_mysql (trx=0x7f8cf536c390) at /10.5/storage/innobase/trx/trx0roll.cc:328
            #32 0x000055fa8fdf65cc in innobase_rollback (hton=0x55fa92c3b630, thd=0x7f8c7c000b00, rollback_trx=false) at /10.5/storage/innobase/handler/ha_innodb.cc:4491
            #33 0x000055fa8f8d8bfb in ha_rollback_trans (thd=0x7f8c7c000b00, all=false) at /10.5/sql/handler.cc:1911
            #34 0x000055fa8f73deb8 in trans_rollback_stmt (thd=0x7f8c7c000b00) at /10.5/sql/transaction.cc:495
            #35 0x000055fa8f592d97 in mysql_execute_command (thd=0x7f8c7c000b00) at /10.5/sql/sql_parse.cc:6014
            #36 0x000055fa8f5989e0 in mysql_parse (thd=0x7f8c7c000b00, rawbuf=0x7f8c7c012188 "INSERT INTO `t1` SELECT * FROM `t1` ", length=140, parser_state=0x7f8cf4165440, is_com_multi=false, is_next_command=false) at /10.5/sql/sql_parse.cc:7991
            #37 0x000055fa8f583a6a in dispatch_command (command=COM_QUERY, thd=0x7f8c7c000b00, packet=0x7f8c7c0086c1 "INSERT INTO `t1` SELECT * FROM `t1` ", packet_length=140, is_com_multi=false, is_next_command=false) at /10.5/sql/sql_parse.cc:1846
            #38 0x000055fa8f582198 in do_command (thd=0x7f8c7c000b00) at /10.5/sql/sql_parse.cc:1364
            #39 0x000055fa8f723bd6 in do_handle_one_connection (connect=0x55fa939c4cf0, put_in_cache=true) at /10.5/sql/sql_connect.cc:1422
            #40 0x000055fa8f7238da in handle_one_connection (arg=0x55fa939c4cf0) at /10.5/sql/sql_connect.cc:1319
            #41 0x00007f8d004126ba in start_thread (arg=0x7f8cf4166700) at pthread_create.c:333
            #42 0x00007f8cff6a341d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:109
            

            alice Alice Sherepa added a comment - On 10.5 run for me it was 123M printed instead of 128, and then signal 6: bb-10.5-mdev_742 181cd53cf7f6e595c0 2020-02-12 20:59:35 14 [ERROR] [FATAL] InnoDB: Over 95 percent of the buffer pool is occupied by lock heaps or the adaptive hash index! Check that your transactions do not set too many row locks, or review if innodb_buffer_pool_size=123M could be bigger.   #3 <signal handler called> #4 0x00007f8cff5d1428 in __GI_raise (sig=sig@entry=6) at ../sysdeps/unix/sysv/linux/raise.c:54 #5 0x00007f8cff5d302a in __GI_abort () at abort.c:89 #6 0x000055fa90097139 in ib::fatal::~fatal (this=0x7f8cf4162d30, __in_chrg=<optimized out>) at /10.5/storage/innobase/ut/ut0ut.cc:597 #7 0x000055fa90149654 in buf_LRU_check_size_of_non_data_objects (buf_pool=0x55fa92d842d0) at /10.5/storage/innobase/buf/buf0lru.cc:1008 #8 0x000055fa901499c0 in buf_LRU_get_free_block (buf_pool=0x55fa92d842d0) at /10.5/storage/innobase/buf/buf0lru.cc:1091 #9 0x000055fa9010e510 in buf_block_alloc (buf_pool=0x55fa92d842d0) at /10.5/storage/innobase/buf/buf0buf.cc:703 #10 0x000055fa8feeef71 in mem_heap_create_block_func (heap=0x55fa92c61400, n=16184, file_name=0x55fa92c61408 "0trx.cc", line=199, type=1) at /10.5/storage/innobase/mem/mem0mem.cc:297 #11 0x000055fa8feef32c in mem_heap_add_block (heap=0x55fa92c61400, n=118) at /10.5/storage/innobase/mem/mem0mem.cc:386 #12 0x000055fa8fea2fcb in mem_heap_alloc (heap=0x55fa92c61400, n=118) at /10.5/storage/innobase/include/mem0mem.ic:203 #13 0x000055fa8feab932 in lock_rec_create_low (c_lock=0x0, thr=0x0, type_mode=34, space=28, page_no=781, page=0x7f8ce3928000 "", heap_no=1, index=0x7f8c78171ad8, trx=0x7f8cf536c390, holds_trx_mutex=false) at /10.5/storage/innobase/lock/lock0lock.cc:1391 #14 0x000055fa8fea5bac in lock_rec_create (c_lock=0x0, thr=0x0, type_mode=34, block=0x7f8cdc461768, heap_no=1, index=0x7f8c78171ad8, trx=0x7f8cf536c390, caller_owns_trx_mutex=false) at /10.5/storage/innobase/include/lock0lock.ic:133 #15 0x000055fa8feadd6f in lock_rec_add_to_queue (type_mode=34, block=0x7f8cdc461768, heap_no=1, index=0x7f8c78171ad8, trx=0x7f8cf536c390, caller_owns_trx_mutex=false) at /10.5/storage/innobase/lock/lock0lock.cc:1899 #16 0x000055fa8feb039a in lock_rec_move_low (lock_hash=0x55fa93653030, receiver=0x7f8cdc461768, donator=0x7f8cdc26ec48, receiver_heap_no=1, donator_heap_no=1) at /10.5/storage/innobase/lock/lock0lock.cc:2537 #17 0x000055fa8feb05b5 in lock_rec_move (receiver=0x7f8cdc461768, donator=0x7f8cdc26ec48, receiver_heap_no=1, donator_heap_no=1) at /10.5/storage/innobase/lock/lock0lock.cc:2596 #18 0x000055fa8feb2592 in lock_update_merge_left (left_block=0x7f8cdc461768, orig_pred=0x7f8ce392ba5e "", right_block=0x7f8cdc26ec48) at /10.5/storage/innobase/lock/lock0lock.cc:3213 #19 0x000055fa900ac528 in btr_compress (cursor=0x7f8c7c0ac7d8, adjust=0, mtr=0x7f8cf41642b0) at /10.5/storage/innobase/btr/btr0btr.cc:3707 #20 0x000055fa900df1b6 in btr_cur_compress_if_useful (cursor=0x7f8c7c0ac7d8, adjust=0, mtr=0x7f8cf41642b0) at /10.5/storage/innobase/btr/btr0cur.cc:5642 #21 0x000055fa900e1019 in btr_cur_pessimistic_delete (err=0x7f8cf4164250, has_reserved_extents=0, cursor=0x7f8c7c0ac7d8, flags=0, rollback=true, mtr=0x7f8cf41642b0) at /10.5/storage/innobase/btr/btr0cur.cc:6079 #22 0x000055fa90248d9e in row_undo_ins_remove_clust_rec (node=0x7f8c7c0ac768) at /10.5/storage/innobase/row/row0uins.cc:187 #23 0x000055fa9024a320 in row_undo_ins (node=0x7f8c7c0ac768, thr=0x7f8c7c026cc8) at /10.5/storage/innobase/row/row0uins.cc:590 #24 0x000055fa9000149b in row_undo (node=0x7f8c7c0ac768, thr=0x7f8c7c026cc8) at /10.5/storage/innobase/row/row0undo.cc:431 #25 0x000055fa90001774 in row_undo_step (thr=0x7f8c7c026cc8) at /10.5/storage/innobase/row/row0undo.cc:492 #26 0x000055fa8ff435d4 in que_thr_step (thr=0x7f8c7c026cc8) at /10.5/storage/innobase/que/que0que.cc:1036 #27 0x000055fa8ff43884 in que_run_threads_low (thr=0x7f8c7c026cc8) at /10.5/storage/innobase/que/que0que.cc:1100 #28 0x000055fa8ff43ad1 in que_run_threads (thr=0x7f8c7c026cc8) at /10.5/storage/innobase/que/que0que.cc:1140 #29 0x000055fa900700d0 in trx_rollback_to_savepoint_low (trx=0x7f8cf536c390, savept=0x7f8cf536d3a0) at /10.5/storage/innobase/trx/trx0roll.cc:140 #30 0x000055fa900705ad in trx_rollback_to_savepoint (trx=0x7f8cf536c390, savept=0x7f8cf536d3a0) at /10.5/storage/innobase/trx/trx0roll.cc:193 #31 0x000055fa900713f4 in trx_rollback_last_sql_stat_for_mysql (trx=0x7f8cf536c390) at /10.5/storage/innobase/trx/trx0roll.cc:328 #32 0x000055fa8fdf65cc in innobase_rollback (hton=0x55fa92c3b630, thd=0x7f8c7c000b00, rollback_trx=false) at /10.5/storage/innobase/handler/ha_innodb.cc:4491 #33 0x000055fa8f8d8bfb in ha_rollback_trans (thd=0x7f8c7c000b00, all=false) at /10.5/sql/handler.cc:1911 #34 0x000055fa8f73deb8 in trans_rollback_stmt (thd=0x7f8c7c000b00) at /10.5/sql/transaction.cc:495 #35 0x000055fa8f592d97 in mysql_execute_command (thd=0x7f8c7c000b00) at /10.5/sql/sql_parse.cc:6014 #36 0x000055fa8f5989e0 in mysql_parse (thd=0x7f8c7c000b00, rawbuf=0x7f8c7c012188 "INSERT INTO `t1` SELECT * FROM `t1` ", length=140, parser_state=0x7f8cf4165440, is_com_multi=false, is_next_command=false) at /10.5/sql/sql_parse.cc:7991 #37 0x000055fa8f583a6a in dispatch_command (command=COM_QUERY, thd=0x7f8c7c000b00, packet=0x7f8c7c0086c1 "INSERT INTO `t1` SELECT * FROM `t1` ", packet_length=140, is_com_multi=false, is_next_command=false) at /10.5/sql/sql_parse.cc:1846 #38 0x000055fa8f582198 in do_command (thd=0x7f8c7c000b00) at /10.5/sql/sql_parse.cc:1364 #39 0x000055fa8f723bd6 in do_handle_one_connection (connect=0x55fa939c4cf0, put_in_cache=true) at /10.5/sql/sql_connect.cc:1422 #40 0x000055fa8f7238da in handle_one_connection (arg=0x55fa939c4cf0) at /10.5/sql/sql_connect.cc:1319 #41 0x00007f8d004126ba in start_thread (arg=0x7f8cf4166700) at pthread_create.c:333 #42 0x00007f8cff6a341d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:109

            It aborts because it reaches "Over 95 percent of the buffer pool", not because it prints a wrong number in the log. It can be either legitimate (the buffer pool is indeed too small for your use case), or phony. If it's not legitimate – that is, if it uses more buffer pool than it should – then it needs to be filed separately with something reproducible. This JIRA is about printing a value in a log, I don't think it's a major problem.

            elenst Elena Stepanova added a comment - It aborts because it reaches "Over 95 percent of the buffer pool", not because it prints a wrong number in the log. It can be either legitimate (the buffer pool is indeed too small for your use case), or phony. If it's not legitimate – that is, if it uses more buffer pool than it should – then it needs to be filed separately with something reproducible. This JIRA is about printing a value in a log, I don't think it's a major problem.

            This would be alleviated by MDEV-24813.

            marko Marko Mäkelä added a comment - This would be alleviated by MDEV-24813 .

            I think that danblack has worked on the large memory allocator interface and would be the perfect assignee for this. I am not sure if this is fixable at all, or just a consequence of the design.

            marko Marko Mäkelä added a comment - I think that danblack has worked on the large memory allocator interface and would be the perfect assignee for this. I am not sure if this is fixable at all, or just a consequence of the design.

            People

              Unassigned Unassigned
              elenst Elena Stepanova
              Votes:
              0 Vote for this issue
              Watchers:
              3 Start watching this issue

              Dates

                Created:
                Updated:

                Git Integration

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