MySQL Bugs: #31222: com_% global status counters behave randomly with mysql_change

Bug #31222	com_% global status counters behave randomly with mysql_change_user
Submitted:	27 Sep 2007 8:26	Modified:	14 Mar 3:11
Reporter:	Shane Bester
Status:	Closed
Category:	Server: General	Severity:	S3 (Non-critical)
Version:	5.0.50, 5.1.23	OS:	Any
Assigned to:	Alexander Nozdrin	Target Version:	5.0+
Tags:	mysql_change_user
Triage:	D2 (Serious)

Description:
I was monitoring status variable to debug a problem, and found this output is wrong:

mysql> show global status like '%stmt%';
+-------------------------+-------+
| Variable_name           | Value |
+-------------------------+-------+
| Com_stmt_close          | 52495 |
| Com_stmt_execute        | 52644 |
| Com_stmt_fetch          | 0     |
| Com_stmt_prepare        | 74145 |
| Com_stmt_reset          | 0     |
| Com_stmt_send_long_data | 0     |
| Prepared_stmt_count     | 12    |
+-------------------------+-------+
7 rows in set (0.00 sec)

mysql> show global status like '%stmt%';
+-------------------------+-------+
| Variable_name           | Value |
+-------------------------+-------+
| Com_stmt_close          | 52493 | <--decreased!
| Com_stmt_execute        | 52642 | <--decreased!
| Com_stmt_fetch          | 0     |
| Com_stmt_prepare        | 74143 | <--decreased!
| Com_stmt_reset          | 0     |
| Com_stmt_send_long_data | 0     |
| Prepared_stmt_count     | 12    |
+-------------------------+-------+
7 rows in set (0.00 sec)

How to repeat:
I think this is possible memory corruption.  I'll make a testcase.
Indeed, mysqld-debug printed some errors to the logs from safemalloc that might be a root
cause of this:

Version: '5.1.23-beta-debug'  socket: '/tmp/mysql.sock'  port: 3306  yes
Error: Memory allocated at sql_string.cc:51 was overrun, discovered at
'sql_select.cc:6493'
Error: Memory allocated at sql_string.cc:51 was overrun, discovered at
'mf_iocache.c:1825'
Error: Memory allocated at sql_string.cc:51 was overrun, discovered at 'lock.cc:389'
Error: Memory allocated at sql_string.cc:51 was overrun, discovered at 'array.c:281'

Suggested fix:
a counter should never go backwards. Looking at the code, I cannot see how this is
possible.  Therefore I suspect memory corruption.

evidence of memory corruption:

mysql> call p1('select now()');
ERROR 1054 (42S22): Unknown column 'R☻.root.☻' in 'field list'
mysql>

using rainbow's queries as a parameter to this proc1 caused the error after a few thousand. need to try repeat it reliably.

Attachment: proc1.sql (application/octet-stream, text), 297 bytes.

I now suspect the cause of the problem is mysql_change_user call. after removing those
from my application, the counters looks correct again.

testcase to show mysql_change_user messes up global variables.

Attachment: bug31222.php (application/octet-stream, text), 1.23 KiB.

ok, I uploaded a php testcase to show how com_select is affected by mysql_change_user.  I
think the memory corruptions can be a different problem afterall.  Sorry for the mess
here.

E:\wrk\bugs\bug31222>php bug31222.php
global status before select:
Array
(
    [0] => Com_select
    [Variable_name] => Com_select
    [1] => 0
    [Value] => 0
)
now running 100 selects
..........................................................................................
..........
global status after select:
Array
(
    [0] => Com_select
    [Variable_name] => Com_select
    [1] => 100
    [Value] => 100
)
about to change user
global status after change user:
Array
(
    [0] => Com_select
    [Variable_name] => Com_select
    [1] => 0
    [Value] => 0 <-----what happened to the hundred selects??
)

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/42123

ChangeSet@1.2546, 2008-02-12 20:59:09+03:00, anozdrin@quad. +3 -0
  Fix for Bug#31222: com_% global status counters
  behave randomly with mysql_change_user.
    
  The problem was that global status variables were not updated
  in THD::check_user(), so thread statistics were lost after
  COM_CHANGE_USER.
    
  The fix is to update global status variables with the thread ones
  before preparing the thread for new user.

Pushed into 5.1-runtime.

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/42131

ChangeSet@1.2547, 2008-02-12 21:42:15+03:00, anozdrin@quad. +1 -0
  Additional fix for Bug#31222.

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/42198

ChangeSet@1.2550, 2008-02-13 13:00:24+03:00, anozdrin@quad. +5 -0
  Additional patch for Bug#31222: com_% global status counters
  behave randomly with mysql_change_user.
  
  The test case had to be moved into not_embedded_server.test file,
  because SHOW GLOBAL STATUS does not work properly in embedded
  server (see bug 34517).

Pushed into 5.1.24-rc

Pushed into 6.0.5-alpha

Noted in 5.1.24, 6.0.5 changelogs.

The mysql_change_user() C API function caused global Com_xxx status
variable values to be incorrect.

Also documented fix for 5.1.23-ndb-6.3.11.