Bug #36600 SHOW STATUS takes a lot of CPU in buf_get_latched_pages_number

• Submitted: 8 May 2008 17:20
• Modified: 18 Jun 2010 22:55
• Reporter: Mark Callaghan
• Status: Closed
• Category: MySQL Server: InnoDB storage engine
• Severity: S1 (Critical)
• Version: 5.0, 5.1
• OS: Any
• CPU Architecture: Any
• Tags: innodb, performance, show, STATUS

[8 May 2008 17:20] Mark Callaghan

Description:
Peter Z described the problem almost 1 year ago. The bug is still in the 5.1 InnoDB plugin. I assume the bug is still in latest 5.0, but I am still on 5.0.37.

http://www.mysqlperformanceblog.com/2007/07/27/more-gotchas-with-mysql-50/

This consumes a huge amount of time on servers with large InnoDB buffer caches. From my memory, it was saturating a CPU.

How to repeat:
Run a busy server with a large (8G+) InnoDB buffer cache. 
Call SHOW STATUS a few times.
Watch the CPU load.

Suggested fix:
Don't call SHOW STATUS, or change SHOW STATUS to not call buf_get_latched_pages_number.

[9 May 2008 12:28] Peter Laursen

I would really like to know is only SHOW STATUS is affected!

SHOW VARIABLES?
SHOW TABLE STATUS?
etc ..

????

[12 May 2008 14:49] Heikki Tuuri

Vasil,

please remove the latched pages calculation from 5.0 and 5.1 in SHOW STATUS, unless UNIV_DEBUG is specified.

It probably scans all buffer page control blocks buf_block_t. For a big buffer pool, that may cause millions of memory accesses and waste several seconds of CPU time.

Regards,

Heikki

[16 May 2008 13:16] MySQL Verification Team

Thank you for the bug report.

[17 May 2008 6:50] Vasil Dimov

Peter, yes, only SHOW STATUS is affected and particularly the calculation of the value of the variable Innodb_buffer_pool_pages_latched, shown in SHOW STATUS.

This variable will be removed from SHOW STATUS to fix the problem.

[19 May 2008 15:40] Vasil Dimov

patch for 5.0 that removes the offending variable from SHOW STATUS

Attachment: bug36600-5.0.diff (application/octet-stream, text), 5.01 KiB.

[24 Jun 2008 21:54] Calvin Sun

Merged into 6.0.6-alpha, according to Tim. But the patch has not been pushed into 5.0, 5.1 yet.

[26 Jun 2008 3:40] Timothy Smith

This has been queued into the mysql-5.1-bugteam tree, and will be pushed to main along with the other SR51SP bugs.  Docs: please return to Patch Queued or NDI once documented for 6.0.

[23 Jul 2008 1:36] Paul DuBois

Noted in 6.0.6 changelog.

SHOW STATUS took a lot of CPU time for calculating the value of the
Innodb_buffer_pool_pages_latched status variable. Now this variable
is calculated and included in the output of SHOW STATUS only when the
UNIV_DEBUG symbol is defined at server build time.

Setting report to Patch queued pending push of fix into 5.1.x (and 5.0.x?).

[13 Aug 2008 8:29] Bugs System

Pushed into 6.0.7-alpha  (revid:[e-mail]-20080731214757-65lrunl1vmnnlues) (version source revid:[e-mail]-20080813063149-5o63l7vlvbm6nuhm) (pib:3)

[13 Aug 2008 8:35] Bugs System

Pushed into 5.0.68  (revid:[e-mail]-20080731214757-65lrunl1vmnnlues) (version source revid:[e-mail]-20080813061111-bt9vnarlk41r3yif) (pib:3)

[13 Aug 2008 8:38] Bugs System

Pushed into 5.1.28  (revid:[e-mail]-20080731214757-65lrunl1vmnnlues) (version source revid:[e-mail]-20080813061206-ew8rffhoqwi9wm5p) (pib:3)

[13 Aug 2008 15:49] Paul DuBois

Noted in 5.0.68 changelog.

[13 Aug 2008 15:49] Paul DuBois

Setting report to Patch Queued pending push of fix into 5.1.x.

[20 Aug 2008 0:39] Bugs System

A patch for this bug has been committed. After review, it may
be pushed to the relevant source trees for release in the next
version. You can access the patch from:

  http://lists.mysql.com/commits/52003

2713 Timothy Smith	2008-08-19
      Cherry-pick some changes from innodb-5.1-ss2479 snapshot.  Includes fixes for
      Bug#36600 and Bug#36793:
      
      Bug #36600 SHOW STATUS takes a lot of CPU in buf_get_latched_pages_number
      
      Fix by removing the Innodb_buffer_pool_pages_latched variable from SHOW
      STATUS output in non-UNIV_DEBUG compilation.
      
      Bug #36793 rpl_innodb_bug28430 fails on Solaris
      
      This is a back port from branches/zip. This code has been tested on a
      big-endian machine too.

[21 Aug 2008 18:00] Bugs System

Pushed into 5.1.28  (revid:[e-mail]-20080820003741-xe0zudmryth44k79) (version source revid:[e-mail]-20080821081500-f2d61fh4u61owz3p) (pib:3)

[25 Aug 2008 20:10] Paul DuBois

Noted in 5.1.28 changelog.

[28 Aug 2008 20:16] Bugs System

Pushed into 6.0.7-alpha  (revid:[e-mail]-20080822132131-uveo6wiuecy6m2b8) (version source revid:[e-mail]-20080822132131-uveo6wiuecy6m2b8) (pib:3)

[13 Sep 2008 21:28] Bugs System

Pushed into 6.0.8-alpha  (revid:[e-mail]-20080820003741-xe0zudmryth44k79) (version source revid:[e-mail]-20080908113103-2e4vdpm695vk3ji4) (pib:3)

[15 Sep 2008 21:16] James Day

Mark, are you content with the removal of the variable from the output without any deprecation process for it? Any way that you'd prefer to have it done? Zero value unless compiled with UNIV_DEBUG? Something else?

[16 Sep 2008 15:09] Mark Callaghan

Total or slow removal is fine by me. You can add a my.cnf variable to determine whether it gets updated for someone who doesn't want this bug fix.

[25 Sep 2009 14:48] Anh Nguyen

'show innodb status' output

Attachment: status.out (application/octet-stream, text), 127.85 KiB.

[25 Sep 2009 15:08] Anh Nguyen

my.cnf

Attachment: my.cnf (application/octet-stream, text), 1.59 KiB.

[25 Sep 2009 15:09] Anh Nguyen

Regardless of whether I ran 'show innodb status' or not, ps command never showed multi-thread in my testing environment, where a highload was put on mysql.
I hope someone could help me to confirm and explain my observation.
This seems to suggest another serialization issue on top of what described so far in this bug. The threads_running is almost always 1.
I wonder:
a. If there has been similar observation, and a corresponding bug has been filed?
b. If I need to upgrade to see multi-thread working.
Also the same behavior was observed regardless of whether I ran 'show innodb status'
c. If there is thread pooling in the version I am using - 5.0.84?
and the lack of it while unlikely could explain why I have not been able to see multi-thread from ps as threads come and go.
d. If I have misconfigured mysql in any ways.

I am attaching my.conf, and the output of 'show innodb status'

My environment:
[root@perf14 pt]# uname -a
Linux systemname.com 2.6.18-164.el5 #1 SMP Tue Aug 18 15:51:48 EDT 2009 x86_64 x86_64 x86_64 GNU/Linux

[root@perf14 pt]# rpm -qa | grep mysql
mysql-5.0.84-2.el5s2
mysql-libs-5.0.84-2.el5s2
php-mysql-5.2.9-2.el5s2
mysql-jdbc-5.0.8-1jpp.1.el5s2
mysql-libs-5.0.84-2.el5s2
mysql-connector-odbc-3.51.27r695-1.el5s2
mysqlclient14-4.1.22-1.el5s2
mysql-5.0.84-2.el5s2
mod_auth_mysql-3.0.0-3.2.el5_3
mysql-server-5.0.84-2.el5s2

ps never showed multi-thread:
root     10999     1  0 09:56 pts/1    00:00:00 /bin/sh /usr/bin/mysqld_safe --datadir=/home/mysql/data --socket=/var/lib/mysql/mysql.sock --log-error=/var/log/mysqld.log --pid-file=/var/run/mysqld/mysqld.pid --user=mysql
mysql    11049 10999 32 09:56 pts/1    00:09:38 /usr/libexec/mysqld --basedir=/usr --datadir=/home/mysql/data --user=mysql --pid-file=/var/run/mysqld/mysqld.pid --skip-external-locking --socket=/var/lib/mysql/mysql.sock
root     11401  9681  0 10:26 pts/1    00:00:00 grep mysql

[25 Sep 2009 15:20] Mark Callaghan

@Anh -- I have no idea what you are writing about and why it is relevant to this bug. Post a new bug, make sure that someone else can figure out what problem you are describing, and try running 'ps -L' if you want to to see the threads listed separately in output from ps.

[30 Sep 2009 21:57] James Day

Anh, ps shows multiple threads if you are using linuxthreads as the thread library and one if you are using the newer NPTL as your thread library. NPTL is now more common than linuxthreads. Consult your operating system documentation for more details. Enterprise customers can read more at https://kb.mysql.com/view.php?id=5157 .

[5 May 2010 15:05] Bugs System

Pushed into 5.1.47 (revid:[e-mail]-20100505145753-ivlt4hclbrjy8eye) (version source revid:[e-mail]-20100331130613-8ja7n0vh36a80457) (merge vers: 5.1.46) (pib:16)

[6 May 2010 14:58] Paul DuBois

Push resulted from incorporation of InnoDB tree. No changes pertinent to this bug.
Re-closing.

[28 May 2010 5:55] Bugs System

Pushed into mysql-next-mr (revid:[e-mail]-20100524190136-egaq7e8zgkwb9aqi) (version source revid:[e-mail]-20100331130613-8ja7n0vh36a80457) (pib:16)

[28 May 2010 6:24] Bugs System

Pushed into 6.0.14-alpha (revid:[e-mail]-20100524190941-nuudpx60if25wsvx) (version source revid:[e-mail]-20100331130613-8ja7n0vh36a80457) (merge vers: 5.1.46) (pib:16)

[28 May 2010 6:52] Bugs System

Pushed into 5.5.5-m3 (revid:[e-mail]-20100524185725-c8k5q7v60i5nix3t) (version source revid:[e-mail]-20100331130613-8ja7n0vh36a80457) (merge vers: 5.1.46) (pib:16)

[29 May 2010 15:09] Paul DuBois

Push resulted from incorporation of InnoDB tree. No changes pertinent to this bug.
Re-closing.

[17 Jun 2010 11:56] Bugs System

Pushed into 5.1.47-ndb-7.0.16 (revid:[e-mail]-20100617114014-bva0dy24yyd67697) (version source revid:[e-mail]-20100331130613-8ja7n0vh36a80457) (merge vers: 5.1.46) (pib:16)

[17 Jun 2010 12:35] Bugs System

Pushed into 5.1.47-ndb-6.2.19 (revid:[e-mail]-20100617115448-idrbic6gbki37h1c) (version source revid:[e-mail]-20100331130613-8ja7n0vh36a80457) (merge vers: 5.1.46) (pib:16)

[17 Jun 2010 13:22] Bugs System

Pushed into 5.1.47-ndb-6.3.35 (revid:[e-mail]-20100617114611-61aqbb52j752y116) (version source revid:[e-mail]-20100331130613-8ja7n0vh36a80457) (merge vers: 5.1.46) (pib:16)