Bug #30604 different flagging of time_zone_used in normal and ps-protocol
Submitted: 23 Aug 2007 18:02 Modified: 15 Apr 2008 23:09
Reporter: Andrei Elkin Email Updates:
Status: Closed Impact on me:
None 
Category:MySQL Server: General Severity:S3 (Non-critical)
Version:5.0 BK OS:Any
Assigned to: Georgi Kodinov CPU Architecture:Any
Triage: D2 (Serious)

[23 Aug 2007 18:02] Andrei Elkin
Description:
One of the consequences of the established fact is that a query binlogged differently, particularly amount of data written to the binlog is different.

Analysis of executions with and without ps-protocol shows
that thd gains time_zone_used= 1
on bottom of the following stack, which represents the execution in normal protocol,

 thd->time_zone_used= 1;

#0  Field_timestamp::val_int (this=0x8de56f0) at field.cc:4465
#1  0x083dd710 in db_find_routine (thd=0x8da0c80, type=1, name=0xb371cdb0, 
    sphp=0xb371cdd4) at sp.cc:352
#2  0x083ddb08 in sp_cache_routines_and_add_tables_aux (thd=0x8da0c80, 
    lex=0x8da1994, start=0x8df0828, first_no_prelock=false, 
    tabs_changed=0xb371d033) at sp.cc:1613
#3  0x083ddf10 in sp_cache_routines_and_add_tables (thd=0x8da0c80, 
    lex=0x8da1994, first_no_prelock=false, tabs_changed=0xb371d033)
    at sp.cc:1704
#4  0x08279b78 in open_tables (thd=0x8da0c80, start=0xb371d094, 
    counter=0xb371d080, flags=0) at sql_base.cc:2684
#5  0x0827a20d in open_and_lock_tables (thd=0x8da0c80, tables=0x8df05b8)
    at sql_base.cc:3057
#6  0x082b5842 in mysql_insert (thd=0x8da0c80, table_list=0x8df05b8, 
    fields=@0x8da1e7c, values_list=@0x8da1ea0, update_fields=@0x8da1e94, 
    update_values=@0x8da1e88, duplic=DUP_ERROR, ignore=false)
    at sql_insert.cc:622
#7  0x08241a93 in mysql_execute_command (thd=0x8da0c80) at sql_parse.cc:3520
#8  0x08247974 in mysql_parse (thd=0x8da0c80, 
    inBuf=0x8df0520 "insert into t2 values (69+bug23333(),1)", length=39, 

The raised flag generates non-zero thd->time_zone_len which is responsible for
recording time zone info with the query into binlog.

The same assignment happens with ps-protocol but as the function sp_cache_routines_and_add_tables_aux() is invoked only through mysql_stmt_prepare() and the effect of the assignment is cleaned up by mysql_stmt_execute() time, the flag is off by recording the query into binlog.
That's why ps-protocol execution creates less size data - thd->time_zone_used == 0 and hence thd->time_zone_len == 0 in such case.

Note, that there was not reason to raise the flag as the function used in the INSERT query did not deal with time at all. 
I assume the assingment in Field_timestamp::val_int() is not necessary and then it's a bug.

Leaving this report to go although there seems to be a related issues like
Bug #16529 Different time value results within normal and ps-protocol modes

How to repeat:
Create a binlogable query which invokes a stored function.
I use the following test:

-- source include/have_innodb.inc
-- source include/have_log_bin.inc

delimiter |;

CREATE TABLE t1 (a int  NOT NULL auto_increment primary key) ENGINE=MyISAM|
CREATE TABLE t2 (a int  NOT NULL auto_increment, b int, PRIMARY KEY (a)) ENGINE=InnoDB|

# the function does not deal with time objects
create function bug23333() 
RETURNS int(11)
DETERMINISTIC
begin
  insert into t1 values (null);
  select count(*) from t1 into @a;
  return @a;
end|

insert into t2 values (2,2),(10+bug23333(),1)| 
drop table t1, t2|
drop function bug23333|

Suggested fix:
Consider why thd->time_zone_used= 1
through the stack which merely opens needed tables for the query.
[23 Aug 2007 19:06] Andrei Elkin
To prove that there is the difference do the following

1. to insert "show master status" in between
   of two queries:

insert into t2 values (2,2),(10+bug23333(),1)| 
+show master status|
drop table t1, t2|

2. record the result file

3. execute with mysql-test-run.pl --ps-protocol

4. to find the diff like this one:

*** r/a_bug.result      Thu Aug 23 22:01:51 2007
--- r/a_bug.reject      Thu Aug 23 22:01:59 2007
***************
*** 11,16 ****
  insert into t2 values (2,2),(10+bug23333(),1)|
  show master status|
  File  Position        Binlog_Do_DB    Binlog_Ignore_DB
! master-bin.000001     6885
  drop table t1, t2|
  drop function bug23333|
--- 11,16 ----
  insert into t2 values (2,2),(10+bug23333(),1)|
  show master status|
  File  Position        Binlog_Do_DB    Binlog_Ignore_DB
! master-bin.000001     7702
  drop table t1, t2|
  drop function bug23333|
[23 Aug 2007 19:14] Andrei Elkin
The last report files were recorded with "dirty" server.
Please take the modified version of the test

-- source include/have_innodb.inc
-- source include/have_log_bin.inc

delimiter |;

CREATE TABLE t1 (a int  NOT NULL auto_increment primary key) ENGINE=MyISAM|
CREATE TABLE t2 (a int  NOT NULL auto_increment, b int, PRIMARY KEY (a)) ENGINE=InnoDB|

create function bug23333() 
RETURNS int(11)
DETERMINISTIC
begin
  insert into t1 values (null);
  select count(*) from t1 into @a;
  return @a;
end|

reset master|
insert into t2 values (2,2),(10+bug23333(),1)| 
show master status|
drop table t1, t2|
drop function bug23333|

1. to record the results in normal protocol
2. to execute witn --ps-protocol
3. to see the diff:
*** r/a_bug.result      Thu Aug 23 22:08:06 2007
--- r/a_bug.reject      Thu Aug 23 22:08:10 2007
***************
*** 12,17 ****
  insert into t2 values (2,2),(10+bug23333(),1)|
  show master status|
  File  Position        Binlog_Do_DB    Binlog_Ignore_DB
! master-bin.000001     241
  drop table t1, t2|
  drop function bug23333|
--- 12,17 ----
  insert into t2 values (2,2),(10+bug23333(),1)|
  show master status|
  File  Position        Binlog_Do_DB    Binlog_Ignore_DB
! master-bin.000001     233
  drop table t1, t2|
  drop function bug23333|
-------------------------------------------------------

There are 8 bytes extra in the normal protocol version.
[24 Aug 2007 7:51] Sveta Smirnova
Thank you for the report.

Verified as described using version 5.0. With other version bug is not repeatable.
[19 Feb 2008 15:27] 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/42559

ChangeSet@1.2584, 2008-02-19 17:27:18+02:00, gkodinov@magare.gmz +4 -0
  Bug #30604: different flagging of time_zone_used in normal 
    and ps-protocol
  Finding a routine should be a transparent operation as 
  far as the binary log is concerned.
  But it was influencing the binary log because of the TIMESTAMP
  column in the proc table.
  
  Fixed by preserving and restoring the time_zone usage flag when
  searching for a stored routine in the proc table.
[13 Mar 2008 19:27] Bugs System
Pushed into 6.0.5-alpha
[13 Mar 2008 19:35] Bugs System
Pushed into 5.1.24-rc
[13 Mar 2008 19:42] Bugs System
Pushed into 5.0.60
[15 Apr 2008 23:09] Paul Dubois
Noted in 5.0.60, 5.1.24, 6.0.5 changelogs.

Binary logging for a stored procedure differed depending on whether
or not execution occurred in a prepared statement.