maria-developers team mailing list archive

[Kristian Nielsen <knielsen@xxxxxxxxxxxxxxx>]

Alexi1952 <Alexi1952@xxxxxxxxx> writes:

> Hi Sergey,
>
> Send you for review:
>
> 1. WL#47 branch published on:
>    https://code.launchpad.net/~alexi1952/maria/maria-5.2-wl47
>
> 2. Diff file attached.
>
> 3. Commit message attached.

Hi Alexi,

Thanks for sending the patch. I did the code review as Sergey is really busy
with preparations for the User's conference.

General comments, most of them with details inline in the patch below:

I started by reading the text in MWL#47. It was _very_ nice to have detailed
description of the approach here, thanks!

The patch also looks very well worked-through.

We should run this through our Buildbot in a MWL#47 feature branch before
pushing to main, as there may be more result file updates needed in special
parts of the test suite (eg --big). I'll help you set it up when you're ready.

It seems your Windows editor (?) has added Windows line ending (CTRL-M)
characters to some of the lines in the patch. You need to fix this and remove
those extra characters.

The new COM_BINLOG_DUMP_OPTIONS_EXT will cause problems the next time MySQL
adds a new command (which will have same numeric value but different
semantics). This needs to be coordinated, which I think means we might as well
use (and coordinate) a new flag for the normal COM_BINLOG_DUMP command.

If the server does not support COM_BINLOG_DUMP_OPTIONS_EXT, this should not be
a fatal error (as it will prevent working against older MariaDB, or
MySQL). This is for both mysqlbinlog and slave thread.

I think a newline in a query will cause mysqlbinlog to output a file that
cannot be correctly read by the mysql command-line client.

I suggest adding a couple more test cases, with multi-session INSERT DELAYED,
different character sets in query, and newline in query (see detailed comments
below).

I am wondering about the --print-annotate-rows-events option for
mysqlbinlog. Maybe we should have it on by default? My reasoning is that there
is little concern about backwards compatibility, as output will only change if
the corresponding option is enabled explicitly in the server (and the extra
output is just a comment anyway). And the user may want to see the annotations
by default. What do you think?

I found it a bit unnatural to have the annotate event be logged inside the
binlog_write_table_map() method, using the extra with_annotate
parameter. Check the suggestions for how to do this differently (below), and
see if it makes sense.

Things that need fixing:

 - Windows line ending issue.
 - The COM_BINLOG_DUMP_OPTIONS_EXT potential conflict issue
 - Extra test cases
 - Newline-in-query problem
 - Not fail if server does not support annotate events.
 - Minor coding style, comment spelling, etc. issues.
 - Full Buildbot run before pushing (I'll set it up later).

Also try to see if the other suggestions can be implemented, or if not lets
discuss.


Detailed comments inline with the patch below.

 - Kristian.


> === modified file 'client/mysqlbinlog.cc'
> --- client/mysqlbinlog.cc	2010-03-15 11:51:23 +0000
> +++ client/mysqlbinlog.cc	2010-03-24 06:25:13 +0000

> @@ -128,6 +129,69 @@
>    OK_STOP
>  };
>  
> +/**
> +  Pointer to the last read Annotate_rows_log_event. Having read an
> +  Annotate_rows event, we should not print it immediatedly because all
> +  subsequent rbr events can be filtered away, and have to keep it for a while.
> +  Also because of that when reading a remote Annotate event we have to keep
> +  its binary log representation in a separately allocated buffer.
> +*/
> +static Annotate_rows_log_event *annotate_event= NULL;
> +
> +inline void free_annotate_event()

Do not make this 'inline'.

> +inline void print_annotate_event(PRINT_EVENT_INFO *print_event_info)
> +{
> +  if (annotate_event)
> +  {
> +    annotate_event->print(result_file, print_event_info);
> +    delete annotate_event;  // the event should be printed not more than once

s/should be printed not more than once/should not be printed more than once/

> @@ -1673,6 +1769,16 @@
>    if ((retval= check_master_version()) != OK_CONTINUE)
>      DBUG_RETURN(retval);
>  
> +  buf[0]= 0;
> +  if (opt_print_annotate_rows_events)
> +    buf[0]|= BINLOG_SEND_ANNOTATE_ROWS_EVENT;
> +
> +  if (simple_command(mysql, COM_BINLOG_DUMP_OPTIONS_EXT, buf, 1, 0))
> +  {
> +    error("Got fatal error sending the log dump options command.");
> +    DBUG_RETURN(ERROR_STOP);
> +  }

What if the server we are trying to dump from does not support the
COM_BINLOG_DUMP_OPTIONS_EXT command? This should not be a fatal error.

At most, it should be an error only if the user actually requested printing of
annotate_rows_events. But I think it should not be an error at all - it seems
more useful to have an option that just prints any annotate events that are
available. Maybe print a warning if the user explicitly requests this option,
no more than that I think.

And I am wondering if the opt_print_annotate_rows_events should not be on by
default in mysqlbinlog. After all, the events will only be there if they were
explicitly enabled in the database, so most likely they will be wanted, or if
not most likely they will not do much harm as they are comments only.

> === modified file 'include/mysql_com.h'
> --- include/mysql_com.h	2010-03-15 11:51:23 +0000
> +++ include/mysql_com.h	2010-03-24 06:25:13 +0000
> @@ -62,6 +62,7 @@
>    COM_TABLE_DUMP, COM_CONNECT_OUT, COM_REGISTER_SLAVE,
>    COM_STMT_PREPARE, COM_STMT_EXECUTE, COM_STMT_SEND_LONG_DATA, COM_STMT_CLOSE,
>    COM_STMT_RESET, COM_SET_OPTION, COM_STMT_FETCH, COM_DAEMON,
> +  COM_BINLOG_DUMP_OPTIONS_EXT,

In the MWL#47 text, you explain that 

    "Note. We add this new command and don't use COM_BINLOG_DUMP to avoid
    possible conflicts with MySQL/Sun."

But this does not avoid such conflicts, on the contrary, we will for sure get
serious problems with this the next time upstream MySQL adds _any_ command
here.

One way or the other, when extending the communication between servers and
clients, we need to coordinate with MySQL/Sun/Oracle. And given this, it is
probably better to just use COM_BINLOG_DUMP, do you agree?

(Lars Thalman actually asked if we would be willing to contribute this work
upstream, which suggests that there should be no problem getting such
coordination working).

> === modified file 'mysql-test/extra/rpl_tests/rpl_deadlock.test'
> --- mysql-test/extra/rpl_tests/rpl_deadlock.test	2009-04-03 21:33:13 +0000
> +++ mysql-test/extra/rpl_tests/rpl_deadlock.test	2010-03-24 06:25:13 +0000
> @@ -72,7 +72,7 @@
>  --source include/stop_slave.inc
>  DELETE FROM t2;
>  # Set slave position to the BEGIN log event
> ---replace_result $master_pos_begin MASTER_POS_BEGIN
> +--replace_result $master_pos_begin <master_pos_begin>

Why this change?

> === added file 'mysql-test/extra/rpl_tests/rpl_row_annotate.test'
> --- mysql-test/extra/rpl_tests/rpl_row_annotate.test	1970-01-01 00:00:00 +0000
> +++ mysql-test/extra/rpl_tests/rpl_row_annotate.test	2010-03-24 06:25:13 +0000

> +INSERT DELAYED INTO t2 VALUES (1,1), (2,2), (3,3);

Add to this test to do INSERT DELAYED from two extra connections, one of which
has binlog_annotate_rows_events set and one which does not.

> +INSERT INTO t3 VALUES (1,1), (2,2), (3,3);
> +DELETE t1, t2 FROM t1 INNER JOIN t2 INNER JOIN t3 WHERE t1.a=t2.a AND t2.a=t3.a;
> +
> +INSERT INTO xt1 VALUES (1,1), (2,2), (3,3);
> +INSERT INTO t2 VALUES (1,1), (2,2), (3,3);
> +DELETE xt1, t2 FROM xt1 INNER JOIN t2 INNER JOIN t3 WHERE xt1.a=t2.a AND t2.a=t3.a;
> +
> +INSERT INTO xt1 VALUES (1,1), (2,2), (3,3);
> +INSERT INTO xt2 VALUES (1,1), (2,2), (3,3);
> +DELETE xt1, xt2 FROM xt1 INNER JOIN xt2 INNER JOIN t3 WHERE xt1.a=xt2.a AND xt2.a=t3.a;

Also add tests with a query containing linefeed and other special characters
(eg. insert of blob value and varchar with special character set), to test the
annotation of such queries.

> === added file 'mysql-test/include/binlog_start_pos.inc'
> --- mysql-test/include/binlog_start_pos.inc	1970-01-01 00:00:00 +0000
> +++ mysql-test/include/binlog_start_pos.inc	2010-03-24 06:25:13 +0000
> @@ -0,0 +1,5 @@
> +let $binlog_start_pos=240;
> +--disable_query_log
> +SET @binlog_start_pos=240;
> +--enable_query_log
> +

It would be nice with a short comment explaining what this include file does
and the magic value 240.

(I think what you've tried to do is to clean up this stuff a bit so that the
next change of format_description_event will be easier to integrate in the
test suite, which is good! So just requesting a short explanation here).

> === added file 'mysql-test/suite/binlog/r/binlog_row_annotate.result'
> --- mysql-test/suite/binlog/r/binlog_row_annotate.result	1970-01-01 00:00:00 +0000
> +++ mysql-test/suite/binlog/r/binlog_row_annotate.result	2010-03-24 06:25:13 +0000

> +/*!*/;
> +# at #
> +#010909  4:46:40 server id #  end_log_pos # 	Query	thread_id=#	exec_time=#	error_code=0
> +SET TIMESTAMP=1000000000/*!*/;
> +BEGIN
> +/*!*/;
> +# at #
> +# at #
> +# at #
> +# at #
> +# at #
> +#010909  4:46:40 server id #  end_log_pos # 	Query: `DELETE test1.t1, test2.t2
> +FROM test1.t1 INNER JOIN test2.t2 INNER JOIN test3.t3
> +WHERE test1.t1.a=test2.t2.a AND test2.t2.a=test3.t3.a`

Right, here we see the problem ... this will cause an error if one tries to
apply this mysqlbinlog output to a server.

> === added file 'mysql-test/suite/binlog/t/binlog_row_annotate.test'
> --- mysql-test/suite/binlog/t/binlog_row_annotate.test	1970-01-01 00:00:00 +0000
> +++ mysql-test/suite/binlog/t/binlog_row_annotate.test	2010-03-24 06:25:14 +0000

> +--echo #
> +--echo #####################################################################################
> +--echo # mysqlbinlog --read-from-remote-server --print-annotate-rows-events
> +--echo # Only two Annotates should appear below:
> +--echo # The following Annotates should appear in this output:

These two lines of comment seem to contradict each other? Please fix/clarify.

> === modified file 'sql/handler.cc'
> --- sql/handler.cc	2010-03-15 11:51:23 +0000
> +++ sql/handler.cc	2010-03-24 06:25:16 +0000
> @@ -4594,7 +4594,8 @@
>  
>  /** @brief
>     Write table maps for all (manually or automatically) locked tables
> -   to the binary log.
> +   to the binary log. Also, if binlog_annotate_rows_events is ON,

You have ^M (chr 13) Windows line endings in this line, and in others. Please
check the patch and remove all Windows line endings introduced.

> @@ -4648,7 +4652,8 @@
>              check_table_binlog_row_based(thd, table))
>          {
>            int const has_trans= table->file->has_transactions();
> -          int const error= thd->binlog_write_table_map(table, has_trans);
> +          int const error= thd->binlog_write_table_map(table, has_trans,
> +                                                       &with_annotate);

I think we can avoid the extra complexity with passing the with_annotate
parameter.

Couldn't we write the annotate_rows_event _after_ the table maps? Then there
could just be a call to mysql_bin_log.write(Annotate_rows_log_event(thd))
after the loop that writes the table maps. (In fact if we moved the
"if (thd->get_binlog_table_maps() == 0)" from write_locked_table_maps() into
the caller binlog_log_row(), the writing of Annotate_rows_log_event could also
be moved there, which seems to me to be the natural place to put it).

Or is there some reason that the annotate event must come before the table
maps? If so, we can still avoid the with_annotate flag, but we need this
before the loop writing the table maps:

  if (is_trans)
    binlog_start_trans_and_stmt();
  mysql_bin_log.write(Annotate_rows_log_event(thd))

> === modified file 'sql/log_event.cc'
> --- sql/log_event.cc	2010-03-15 11:51:23 +0000
> +++ sql/log_event.cc	2010-03-24 06:25:16 +0000

> +Annotate_rows_log_event::Annotate_rows_log_event(const char *buf,
> +                                                 uint event_len,
> +                                      const Format_description_log_event *desc)
> +  : Log_event(buf, desc),
> +    m_save_thd_query_txt(0),
> +    m_save_thd_query_len(0)
> +{
> +  m_query_len= event_len - desc->common_header_len;
> +  m_query_txt= (char*) buf + desc->common_header_len;

Instead of this cast, couldn't we make the m_query_txt member a const char * ?
(from a quick check of the patch, it seems we can).

> +}
> +
> +Annotate_rows_log_event::~Annotate_rows_log_event()
> +{
> +#ifndef MYSQL_CLIENT
> +  if (m_save_thd_query_txt)
> +    thd->set_query(m_save_thd_query_txt, m_save_thd_query_len);
> +#endif
> +}

I don't like this, it's much too magic that thd->query can change in the
destructor of a completely unrelated object.

I would suggest instead putting in explicit code to restore thd->query in the
places where it needs to be done (you can have a
Annotate_rows_log_event::restore_thd_query() method for that). This makes it
explicit in the code where the restoration happens.

But actually, I am wondering if it would be better not to change thd->query at
all? And instead just pick the query from a saved annotate_rows_log_event when
needed? But I haven't checked the code sufficient to see if this can be done
in a clean way, so think about it, and see if it makes sense.

> +#ifdef MYSQL_CLIENT
> +void Annotate_rows_log_event::print(FILE *file, PRINT_EVENT_INFO *pinfo)
> +{
> +  if (!pinfo->short_form)
> +  {
> +    print_header(&pinfo->head_cache, pinfo, TRUE);
> +    my_b_printf(&pinfo->head_cache, "\tQuery: `%s`\n", m_query_txt);
> +  }
> +}
> +#endif

I think this will cause problems if the query contains linefeed characters,
right? The mysqlbinlog output will span multiple lines which will not be
marked as comment lines, so trying to apply the output (by piping through
`mysql`) will fail with a syntax error (or worse).

It seems to me we need some kind of quoting here.

Also, I see that mysqlbinlog is careful to make the query string zero
terminated (as required by my_b_printf("%s"), but that's a bit subtle. So
maybe that could also be avoided if some kind of quoting is enabled, or
alternatively add a comment about this zero-termination requirement for
Annotate_rows_log_event::print().

> === modified file 'sql/mysql_priv.h'
> --- sql/mysql_priv.h	2010-03-15 11:51:23 +0000
> +++ sql/mysql_priv.h	2010-03-24 06:25:17 +0000
> @@ -624,7 +624,12 @@
>  /* BINLOG_DUMP options */
>  
>  #define BINLOG_DUMP_NON_BLOCK   1
> -
> +#endif //MYSQL_CLIENT

Make this #endif /* !MYSQL_CLIENT */
(as it is a negative test that this #endif ends)

> +
> +/* Extended BINLOG_DUMP options (passed to COM_BINLOG_DUMP_OPTIONS_EXT) */
> +#define BINLOG_SEND_ANNOTATE_ROWS_EVENT   1
> +
> +#ifndef MYSQL_CLIENT
>  /* sql_show.cc:show_log_files() */
>  #define SHOW_LOG_STATUS_FREE "FREE"
>  #define SHOW_LOG_STATUS_INUSE "IN USE"

> === modified file 'sql/slave.cc'
> --- sql/slave.cc	2010-03-04 08:03:07 +0000
> +++ sql/slave.cc	2010-03-24 06:25:18 +0000
> @@ -1829,6 +1829,36 @@
>  }
>  
>  
> +static int set_master_binlog_dump_options_ext(MYSQL *mysql,
> +                                              bool *suppress_warnings)
> +{
> +  uchar buf[1];
> +  uchar flags= 0;
> +  DBUG_ENTER("set_master_binlog_dump_options_ext");
> +  
> +  *suppress_warnings= FALSE;
> +
> +  if (opt_log_slave_updates && opt_replicate_annotate_rows_events)
> +    flags|= BINLOG_SEND_ANNOTATE_ROWS_EVENT;
> +
> +  buf[0]= flags;
> +
> +  if (simple_command(mysql, COM_BINLOG_DUMP_OPTIONS_EXT, buf, 1, 0))
> +  {
> +    if (mysql_errno(mysql) == ER_NET_READ_INTERRUPTED)
> +      *suppress_warnings= TRUE;
> +    else
> +      sql_print_error("Error on COM_BINLOG_DUMP_OPTIONS_EXT: %d  %s,"
> +                      " will retry in %d secs",
> +                      mysql_errno(mysql), mysql_error(mysql),
> +                      master_connect_retry);
> +    DBUG_RETURN(1);
> +  }

This will break replication from a master that does not know the
COM_BINLOG_DUMP_OPTIONS_EXT command. We could maybe log a warning in this
case (saying that query annotation is not available from master), but we
should not fail I think.

> +
> +  DBUG_RETURN(0);
> +}

> @@ -2234,16 +2264,33 @@
>      }
>      exec_res= apply_event_and_update_pos(ev, thd, rli);
>  
> -    /*
> -      Format_description_log_event should not be deleted because it will be
> -      used to read info about the relay log's format; it will be deleted when
> -      the SQL thread does not need it, i.e. when this thread terminates.
> -    */
> -    if (ev->get_type_code() != FORMAT_DESCRIPTION_EVENT)
> -    {
> -      DBUG_PRINT("info", ("Deleting the event after it has been executed"));
> -      delete ev;
> -    }
> +    switch (ev->get_type_code()) {
> +      case FORMAT_DESCRIPTION_EVENT:
> +        // Format_description_log_event should not be deleted because it
> +        // will be used to read info about the relay log's format;
> +        // it will be deleted when the SQL thread does not need it,
> +        // i.e. when this thread terminates.
> +        break;

According to coding style, multi-line comments should use C-style /* ... */,
not C++-style //

    http://forge.mysql.com/wiki/MySQL_Internals_Coding_Guidelines#Commenting_Code

(Should be changed here and in several other places where it occurs).

> +      case ANNOTATE_ROWS_EVENT:
> +        // Annotate_rows event should not be deleted because after it has
> +        // been applied, thd->query points to the string inside this event.
> +        // The thd->query will be used to generate new Annotate_rows event
> +        // during applying the subsequent Rows events.
> +        rli->set_annotate_event((Annotate_rows_log_event*) ev);
> +        break;
> +      case DELETE_ROWS_EVENT:
> +      case UPDATE_ROWS_EVENT:
> +      case WRITE_ROWS_EVENT:
> +        // After the last Rows event has been applied, the saved Annotate_rows
> +        // event (if any) is not needed anymore and can be deleted.
> +        if (((Rows_log_event*)ev)->get_flags(Rows_log_event::STMT_END_F))
> +          rli->free_annotate_event();

This seems a natural place to explicitly restore thd->query rather than inside
the annotate event destructor (if such restoration is really needed).

> +        /* fall through */
> +      default:
> +        DBUG_PRINT("info", ("Deleting the event after it has been executed"));
> +        delete ev;
> +        break;
> +    }