February 2010 - developers - lists.mariadb.org

[Maria-developers] Rev 157: saving uncommitted changes in /etc prior to apt run in file:///etc/
by timour＠askmonty.org 04 Feb '10

04 Feb '10

At file:///etc/ ------------------------------------------------------------ revno: 157 revision-id: timour(a)askmonty.org-20100204112537-3a6fyd3ibqzi73wc parent: root@lamia-20100203064317-whagbeui3pyl1bck committer: timour(a)askmonty.org branch nick: lamia /etc repository timestamp: Thu 2010-02-04 13:25:37 +0200 message: saving uncommitted changes in /etc prior to apt run === modified file 'cups/subscriptions.conf' --- a/cups/subscriptions.conf 2010-02-03 06:43:17 +0000 +++ b/cups/subscriptions.conf 2010-02-04 11:25:37 +0000 @@ -1,11 +1,11 @@ # Subscription configuration file for CUPS v1.4.1 -# Written by cupsd on 2010-02-02 08:18 -NextSubscriptionId 101 -<Subscription 100> +# Written by cupsd on 2010-02-04 13:19 +NextSubscriptionId 102 +<Subscription 101> Events printer-state-changed printer-restarted printer-shutdown printer-stopped printer-added printer-deleted job-state-changed job-created job-completed job-stopped job-progress Owner tsk LeaseDuration 86400 Interval 0 -ExpirationTime 1265177812 -NextEventId 8 +ExpirationTime 1265368739 +NextEventId 1 </Subscription> === modified file 'cups/subscriptions.conf.O' --- a/cups/subscriptions.conf.O 2010-02-03 06:43:17 +0000 +++ b/cups/subscriptions.conf.O 2010-02-04 11:25:37 +0000 @@ -1,11 +1,3 @@ # Subscription configuration file for CUPS v1.4.1 -# Written by cupsd on 2010-02-02 08:17 +# Written by cupsd on 2010-02-03 08:43 NextSubscriptionId 101 -<Subscription 100> -Events printer-state-changed printer-restarted printer-shutdown printer-stopped printer-added printer-deleted job-state-changed job-created job-completed job-stopped job-progress -Owner tsk -LeaseDuration 86400 -Interval 0 -ExpirationTime 1265177812 -NextEventId 7 -</Subscription> === modified file 'resolv.conf' --- a/resolv.conf 2010-02-01 11:56:20 +0000 +++ b/resolv.conf 2010-02-04 11:25:37 +0000 @@ -1,2 +1,3 @@ # Generated by NetworkManager -nameserver 192.168.2.1 +nameserver 212.50.0.10 +nameserver 212.50.10.50

1 0

[Maria-developers] bzr commit into file:///etc/ branch (timour:157)
by timour＠askmonty.org 04 Feb '10

04 Feb '10

#At file:///etc/ based on revid:root@lamia-20100203064317-whagbeui3pyl1bck 157 timour(a)askmonty.org 2010-02-04 saving uncommitted changes in /etc prior to apt run modified: cups/subscriptions.conf cups/subscriptions.conf.O resolv.conf === modified file 'cups/subscriptions.conf' --- a/cups/subscriptions.conf 2010-02-03 06:43:17 +0000 +++ b/cups/subscriptions.conf 2010-02-04 11:25:37 +0000 @@ -1,11 +1,11 @@ # Subscription configuration file for CUPS v1.4.1 -# Written by cupsd on 2010-02-02 08:18 -NextSubscriptionId 101 -<Subscription 100> +# Written by cupsd on 2010-02-04 13:19 +NextSubscriptionId 102 +<Subscription 101> Events printer-state-changed printer-restarted printer-shutdown printer-stopped printer-added printer-deleted job-state-changed job-created job-completed job-stopped job-progress Owner tsk LeaseDuration 86400 Interval 0 -ExpirationTime 1265177812 -NextEventId 8 +ExpirationTime 1265368739 +NextEventId 1 </Subscription> === modified file 'cups/subscriptions.conf.O' --- a/cups/subscriptions.conf.O 2010-02-03 06:43:17 +0000 +++ b/cups/subscriptions.conf.O 2010-02-04 11:25:37 +0000 @@ -1,11 +1,3 @@ # Subscription configuration file for CUPS v1.4.1 -# Written by cupsd on 2010-02-02 08:17 +# Written by cupsd on 2010-02-03 08:43 NextSubscriptionId 101 -<Subscription 100> -Events printer-state-changed printer-restarted printer-shutdown printer-stopped printer-added printer-deleted job-state-changed job-created job-completed job-stopped job-progress -Owner tsk -LeaseDuration 86400 -Interval 0 -ExpirationTime 1265177812 -NextEventId 7 -</Subscription> === modified file 'resolv.conf' --- a/resolv.conf 2010-02-01 11:56:20 +0000 +++ b/resolv.conf 2010-02-04 11:25:37 +0000 @@ -1,2 +1,3 @@ # Generated by NetworkManager -nameserver 192.168.2.1 +nameserver 212.50.0.10 +nameserver 212.50.10.50

1 0

[Maria-developers] Rev 8: Merge. in file:///Users/hakan/work/monty_program/mariadb-tools/
by Hakan Kuecuekyilmaz 04 Feb '10

04 Feb '10

At file:///Users/hakan/work/monty_program/mariadb-tools/ ------------------------------------------------------------ revno: 8 [merge] revision-id: hakan(a)askmonty.org-20100204111840-0d9u3nyio2h8tavi parent: hakan(a)askmonty.org-20100204011956-u74a4es6oogvd50w parent: knielsen@hasky-20100202151012-pjcblb2v3bqsp5eo committer: Hakan Kuecuekyilmaz <hakan(a)askmonty.org> branch nick: mariadb-tools timestamp: Thu 2010-02-04 12:18:40 +0100 message: Merge. modified: buildbot/maria-master.cfg mariamaster.cfg-20091218103450-cvifjz3i70oerkej-1 buildbot/runvm runvm-20091218082659-ept0jpsqa5e8jno6-2 === modified file 'buildbot/maria-master.cfg' --- a/buildbot/maria-master.cfg 2010-01-02 21:17:58 +0000 +++ b/buildbot/maria-master.cfg 2010-02-02 15:10:12 +0000 @@ -59,7 +59,6 @@ ,mkSlave("psergey-pylon-amd64", max_builds=1) ,mkSlave("psergey-foxhole-x86", max_builds=1) ,mkSlave("psergey-pslp2-x86", max_builds=1) - ,mkSlave("hakan-mac-g5", max_builds=1) ,mkSlave("work-opensuse-amd64", max_builds=1) ,mkSlave("psergey-win32box", max_builds=1) ,mkSlave("vm-win-1", max_builds=1) @@ -114,7 +113,7 @@ "lp:~maria-captains/maria/maria-5.2-merge-5.1" : "maria-5.2-merge-5.1", "lp:~maria-captains/maria/5.2-dsmrr" : "5.2-dsmrr", "lp:~maria-captains/maria/5.3" : "5.3", - "lp:~maria-captains/maria/5.3" : "5.3-sj-subqueries" + "lp:~maria-captains/maria/5.3-sj-subqueries" : "5.3-sj-subqueries" } mailSource = mail.BzrLaunchpadEmailMaildirSource("/var/lib/buildbot/Maildir", branchMap=myBranchMap) @@ -163,7 +162,7 @@ # "lenny-amd64-dbg", "adutko-alpha", "debian5-i386-fulltest", "jaunty-x86-valgrind", "jaunty-amd64-rel", - "gentoo-x86-dbg", "ubuntu-x86-dbg", "macosx-g5-dbg", + "gentoo-x86-dbg", "ubuntu-x86-dbg", "macosx-x86-bld", "work-amd64-valgrind", "winxp-x86-nmake", "win32-rel-nmake", "hardy-amd64-fulltest", "gentoo-amd64-sanja", "opensolaris-511-x86", @@ -180,6 +179,7 @@ branches=["mariadb-5.1-knielsen", "5.1-release", "5.1", "5.1.39-oqgraph", "5.1-merge", "mariadb-5.1-monty", + "5.2", "mariadb-5.2-monty", ], treeStableTimer=1, # 1 sec for bzr properties= {"bakebranch": "lp:~maria-captains/ourdelta/ourdelta-montyprogram-fixes"}, @@ -197,7 +197,9 @@ "kvm-deb-jaunty-amd64", "kvm-deb-jaunty-x86", "kvm-deb-karmic-amd64", "kvm-deb-karmic-x86", "kvm-deb-lucid-amd64", "kvm-deb-lucid-x86", - "kvm-bintar-hardy-amd64", "kvm-bintar-hardy-x86",])) + "kvm-bintar-hardy-amd64", "kvm-bintar-hardy-x86", + "opensolaris-511-bintar", + ])) ####### BUILDERS @@ -529,7 +531,7 @@ "slavename": "adutko-centos5-amd64", "builddir": "centos5-amd64-minimal", "factory": f_minimal, - "category": "experimental", + "category": "main", } f_win32_rel_nmake = factory.BuildFactory() @@ -699,7 +701,7 @@ "slavename": "adutko-ultrasparc3", "builddir": "adutko-ultrasparc3", "factory": f_sol_sparc_32, - "category": "new", + "category": "main", } f_dbg_alpha = factory.BuildFactory() @@ -771,23 +773,6 @@ "category": "experimental", } -f_dbg_g5 = factory.BuildFactory() -f_dbg_g5.addStep(bzr_shared_repo) -f_dbg_g5.addStep(bzr_checkout) -f_dbg_g5.addStep(getCompileStep(["BUILD/compile-ppc-max"])) -f_dbg_g5.addStep(getMTR( - test_type="nm", - test_info="Normal run, no --ps-protocol", - command=["sh", "-c", "cd mysql-test && exec perl mysql-test-run.pl --force --retry=3 --skip-ndb --testcase-timeout=45 --suite-timeout=1080 --mysqld=--skip-safemalloc"], - timeout=2700)) - -bld_mac_g5 = {'name': "macosx-g5-dbg", - 'slavename': "hakan-mac-g5", - 'builddir': "hakan-mac-g5", - 'factory': f_dbg_g5, - "category": "experimental", - } - f_mac_x86 = factory.BuildFactory() f_mac_x86.addStep(bzr_shared_repo) f_mac_x86.addStep(bzr_checkout) @@ -878,6 +863,36 @@ "category": "experimental", } +# The trees for which we save binary packages. +savedPackageBranches= ["5.1-release", "5.2-release", "5.3-release"] + +# Get a build step that will archive binary packages (or source tarball). +# Only the newest 3 builds are saved for each (branch, builder) combination. +# The packages are saved under the build number of the tarbake step, so it is +# easy to locate all packages for a given release. +def getPackageArchiveStep(source, tarbuildnum): + cmdText= ("TARBUILDNUM='" + tarbuildnum + "'\n" + + "SRC='" + source + "'\n" + """ +BUILDERNAME='%(buildername)s' +BRANCH='%(branch)s' +BASE="/archive/pack/$BRANCH" +DST="$BASE/build-$TARBUILDNUM/$BUILDERNAME" +set -ex +mkdir -p "$BASE" +rm -Rf "$DST" +(ls -td $BASE/build-*/"$BUILDERNAME" || : ) | (read DUMMY || exit 0; read DUMMY || exit 0; while read VICTIM; do rm -Rf "$VICTIM"; done) +rmdir $BASE/build-* 2>/dev/null || : +mkdir -p "$DST" +cp -r "$SRC" "$DST/" +""") + return ShellCommand( + doStepIf=(lambda(step): step.getProperty("branch") in savedPackageBranches), + description=["archiving"], + descriptionDone=["archive"], + command=["sh", "-c", WithProperties(cmdText)], + ) + + f_kvm_tarbake_jaunty_x86= factory.BuildFactory() f_kvm_tarbake_jaunty_x86.addStep(Compile( description=["making", "dist"], @@ -906,35 +921,38 @@ """ set -ex cd buildbot/build/$(cat buildbot/build/bakery.txt)/ -echo mariadb-*.tar.gz > ../distname.txt -mv $(cat ../distname.txt) ../ +basename mariadb-*.tar.gz .tar.gz > ../distdirname.txt +mv "$(cat ../distdirname.txt).tar.gz" ../ """, - "= scp -P 2223 buildbot@localhost:buildbot/build/distname.txt .", + "= scp -P 2223 buildbot@localhost:buildbot/build/distdirname.txt .", "= scp -P 2223 buildbot@localhost:buildbot/build/bakery.txt .", "= scp -P 2223 'buildbot@localhost:buildbot/build/mariadb-*.tar.gz' .", "= scp -P 2223 'buildbot@localhost:buildbot/build/bakery-*.tar.gz' .", ], )) f_kvm_tarbake_jaunty_x86.addStep(SetProperty( - property="distname", - command=["cat", "distname.txt"], + property="distdirname", + command=["cat", "distdirname.txt"], )) f_kvm_tarbake_jaunty_x86.addStep(SetProperty( property="bakery", command=["cat", "bakery.txt"], )) -f_kvm_tarbake_jaunty_x86.addStep(FileUpload(slavesrc=WithProperties("%(distname)s"), - masterdest=WithProperties("/var/lib/buildbot/OQ-tarballs/%(buildnumber)s:%(distname)s"))) +f_kvm_tarbake_jaunty_x86.addStep(getPackageArchiveStep("%(distdirname)s.tar.gz", "%(buildnumber)s")) +f_kvm_tarbake_jaunty_x86.addStep(FileUpload(slavesrc=WithProperties("%(distdirname)s.tar.gz"), + masterdest=WithProperties("/var/lib/buildbot/OQ-tarballs/%(buildnumber)s:%(distdirname)s.tar.gz"))) f_kvm_tarbake_jaunty_x86.addStep(FileUpload(slavesrc=WithProperties("%(bakery)s.tar.gz"), masterdest=WithProperties("/var/lib/buildbot/OQ-bakeries/%(buildnumber)s:%(bakery)s.tar.gz"))) f_kvm_tarbake_jaunty_x86.addStep(Trigger( schedulerNames=["kvm-ourdelta-sched"], waitForFinish=False, updateSourceStamp=True, - set_properties={ "tarballpath": WithProperties("/var/lib/buildbot/OQ-tarballs/%(buildnumber)s:%(distname)s"), + set_properties={ "tarballpath": WithProperties("/var/lib/buildbot/OQ-tarballs/%(buildnumber)s:%(distdirname)s.tar.gz"), "bakerypath": WithProperties("/var/lib/buildbot/OQ-bakeries/%(buildnumber)s:%(bakery)s.tar.gz"), + "distname": WithProperties("%(distdirname)s.tar.gz"), + "tarbuildnum": WithProperties("%(buildnumber)s"), }, - copy_properties=[ "distname", "bakery" ])) + copy_properties=[ "distdirname", "bakery" ])) bld_kvm_tarbake_jaunty_x86 = {"name": "kvm-tarbake-jaunty-x86", "slavename": "knielsen-kvm-x86", @@ -977,6 +995,7 @@ "= rm -Rf rpms && mkdir rpms", "= scp -P "+port+" 'buildbot@localhost:/usr/src/redhat/RPMS/"+arch+"/*.rpm' rpms/", ])) + rpm_fact.addStep(getPackageArchiveStep("rpms", "%(tarbuildnum)s")) rpm_fact.addStep(Test( description=["testing", "install"], descriptionDone=["test", "install"], @@ -1013,11 +1032,22 @@ deb_fact.addStep(FileDownload( mastersrc=WithProperties("%(bakerypath)s"), slavedest=WithProperties("%(bakery)s.tar.gz"))) + # Extract the compiler warning suppressions file from the source tarball. + deb_fact.addStep(ShellCommand( + description=["getting", ".supp"], + descriptionDone=["get", ".supp"], + command=["sh", "-c", WithProperties(""" +rm -f compiler_warnings.supp +tar zxf "%(distname)s" --strip 2 "$(basename %(distname)s .tar.gz)/support-files/compiler_warnings.supp" +exit 0 # best-effort, not fatal if no suppression file +""")])) deb_fact.addStep(Compile( description=["making", "debs"], descriptionDone=["make", "debs"], logfiles={"kernel": "kernel_"+port+".log"}, warningPattern=gccWarningPattern, + warningExtractor=Compile.warnExtractFromRegexpGroups, + suppressionFile=WithProperties("compiler_warnings.supp"), command=["runvm", "--base-image=/kvm/vms/"+kvm_image+"-build.qcow2"] + args +["--logfile=kernel_"+port+".log", "vm-tmp-"+port+".qcow2", "rm -Rf buildbot && mkdir buildbot", WithProperties("= scp -P "+port+" %(distname)s buildbot@localhost:buildbot/"), @@ -1039,6 +1069,7 @@ "= rm -Rf debs", "= scp -r -P "+port+" buildbot@localhost:buildbot/debs .", ])) + deb_fact.addStep(getPackageArchiveStep("debs", "%(tarbuildnum)s")) deb_fact.addStep(Test( description=["testing", "install"], descriptionDone=["test", "install"], @@ -1144,6 +1175,7 @@ property="bindistname", command=["cat", "bindistname.txt"], )) + bin_fact.addStep(getPackageArchiveStep("%(bindistname)s.tar.gz", "%(tarbuildnum)s")) bin_fact.addStep(Test( description=["testing", "bintar"], descriptionDone=["test", "bintar"], @@ -1178,14 +1210,55 @@ 'slavename': 'opensolaris-x86', 'builddir': 'opensolaris-511-x86', 'factory': f_dbg_sol_64, - "category": "new", + "category": "main", } +f_sol_64_bintar = factory.BuildFactory() +f_sol_64_bintar.addStep(FileDownload(mastersrc=WithProperties("%(tarballpath)s"), + slavedest=WithProperties("%(distname)s"))) +f_sol_64_bintar.addStep(ShellCommand( + description="untarring", descriptionDone="untar", + command=["sh", "-c", WithProperties("rm -Rf %(distdirname)s && tar zxf %(distname)s")])) +f_sol_64_bintar.addStep(getCompileStep(["sh", "-c", WithProperties("cd %(distdirname)s && BUILD/compile-solaris-amd64-debug")], + subdir="%(distdirname)s")) +f_sol_64_bintar.addStep(ShellCommand( + description="packaging", descriptionDone="package", + command=["sh", "-c", WithProperties(""" +set -ex +cd %(distdirname)s +scripts/make_binary_distribution +ORIG_TAR=$(echo mariadb-*.tar.gz) +ORIG_DIR=$(basename ${ORIG_TAR} .tar.gz) +NEW_DIR="$(echo "${ORIG_DIR}" | sed -e 's/-MariaDB//')" +NEW_TAR="${NEW_DIR}.tar.gz" +rm -Rf $ORIG_DIR +tar zxf $ORIG_TAR +mv $ORIG_DIR "${NEW_DIR}" +tar zcf "${NEW_TAR}" "${NEW_DIR}/" +echo "${NEW_TAR}" > ../bindistname.txt +""")])) +f_sol_64_bintar.addStep(SetProperty( + property="bindistname", + command=["cat", "bindistname.txt"], + )) +f_sol_64_bintar.addStep(getPackageArchiveStep("%(distdirname)s/%(bindistname)s", "%(tarbuildnum)s")) +f_sol_64_bintar.addStep(getMTR( + test_type="nm", + test_info="Normal run, no --ps-protocol", + command=["sh", "-c", WithProperties("cd %(distdirname)s/mysql-test && exec perl mysql-test-run.pl --force --retry=3 --skip-ndb --parallel=2")], + mtr_subdir=WithProperties("%(distdirname)s/mysql-test"))) + +bld_opensolaris_511_bintar = {'name': 'opensolaris-511-bintar', + 'slavename': 'opensolaris-x86', + 'builddir': 'opensolaris-511-bintar', + 'factory': f_sol_64_bintar, + "category": "package", + } + c['builders'] = [bld_fulltest, bld_fulltest2, bld_work_valgrind, bld_valgrind_32, bld_rel_amd64, bld_dbg_x86, bld_makedist, bld_archivist_amd64, bld_archivist_cnc, - bld_mac_g5, bld_dbg2_x86, bld_psergey_win32box, bld_win32_tarball, bld_win32_zip, bld_win32_rel_nmake, bld_mac_x86, @@ -1205,6 +1278,7 @@ bld_kvm_deb_karmic_amd64, bld_kvm_deb_karmic_x86, bld_kvm_deb_lucid_amd64, bld_kvm_deb_lucid_x86, bld_kvm_bintar_hardy_amd64, bld_kvm_bintar_hardy_x86, + bld_opensolaris_511_bintar, bld_opensolaris_511_x86, bld_sol_sparc_32, ] === modified file 'buildbot/runvm' --- a/buildbot/runvm 2010-01-14 13:43:51 +0000 +++ b/buildbot/runvm 2010-02-01 12:44:19 +0000 @@ -52,6 +52,19 @@ my $opt_baseimage= undef; my @user_cmd_opt; +# Disable host key checking for ssh. +# This is a bit convoluted due to OpenSSH's slight security-paranoia. +# Without this, we would get a login failure if using another VM image +# (with different host key) on the same port, which is annoying. +# An alternative would be to use CheckHostIP=no and HostKeyAlias=<img.qcow2> +# to get ssh to check a different key for each image. But that would still +# cause an error if re-generating an image (with new ssh host key), and it +# doesn't really give any additional security. +my @ssh_cmd_prefix= ($ssh_exec, + '-o', 'UserKnownHostsFile=/dev/null', + '-o', 'StrictHostKeyChecking=no', + '-o', 'LogLevel=ERROR'); + my $image; my $pidfile; @@ -177,17 +190,6 @@ return $res; } -sub exec_guest_cmd { - my ($cmd_and_args)= @_; - if (scalar(@$cmd_and_args) == 0 || $cmd_and_args->[0] eq '') - { - # Otherwise ssh will do an interactive login, which we do not want. - exit 0; - } - - exec_guest_cmd $ssh_exec, '-p', $opt_port, @user_cmd_opt, 'localhost', @$cmd_and_args; -} - sub is_port_used { socket(SOCK, PF_INET, SOCK_STREAM, getprotobyname('tcp')) or die "socket() failed: $!\n"; @@ -348,7 +350,7 @@ die "Fatal error: Cannot fork(): $!\n"; } elsif (!$pid) { # Child. - exec_with_print($ssh_exec, '-o', 'ConnectTimeout=4', '-p', $opt_port, + exec_with_print(@ssh_cmd_prefix, '-o', 'ConnectTimeout=4', '-p', $opt_port, @user_cmd_opt, 'localhost', 'sudo', '/sbin/shutdown', '-h', 'now'); } else { @@ -410,7 +412,7 @@ die "Fatal error: Cannot fork(): $!\n"; } elsif (!$pid) { # Child. - exec_with_print($ssh_exec, '-o', 'ConnectTimeout=4', '-p', $opt_port, + exec_with_print(@ssh_cmd_prefix, '-o', 'ConnectTimeout=4', '-p', $opt_port, @user_cmd_opt, 'localhost', '/bin/true'); } else { # Parent. @@ -506,7 +508,7 @@ $res= system(substr($arg, 1)); } else { print STDERR "+ $arg\n"; - $res= system($ssh_exec, '-p', $opt_port, @user_cmd_opt, 'localhost', $arg); + $res= system(@ssh_cmd_prefix, '-p', $opt_port, @user_cmd_opt, 'localhost', $arg); } if ($res < 0) { print STDERR "Could not spawn command: $!\n";

1 0

[Maria-developers] Updated (by Alexi): Store in binlog text of statements that caused RBR events (47)
by worklog-noreply＠askmonty.org 04 Feb '10

04 Feb '10

----------------------------------------------------------------------- WORKLOG TASK -=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=- TASK...........: Store in binlog text of statements that caused RBR events CREATION DATE..: Sat, 15 Aug 2009, 23:48 SUPERVISOR.....: Monty IMPLEMENTOR....: COPIES TO......: Knielsen CATEGORY.......: Server-RawIdeaBin TASK ID........: 47 (http://askmonty.org/worklog/?tid=47) VERSION........: Server-9.x STATUS.........: Un-Assigned PRIORITY.......: 60 WORKED HOURS...: 20 ESTIMATE.......: 35 (hours remain) ORIG. ESTIMATE.: 35 PROGRESS NOTES: -=-=(Alexi - Thu, 04 Feb 2010, 09:54)=-=- Low Level Design modified. --- /tmp/wklog.47.old.16174 2010-02-04 09:54:13.000000000 +0200 +++ /tmp/wklog.47.new.16174 2010-02-04 09:54:13.000000000 +0200 @@ -171,35 +171,20 @@ 5. How slave IO thread requests Annotate_rows events ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~ -When requesting an event, the slave should inform the master whether -it should send Annotate_rows events or not. To that end we add a new -BINLOG_SEND_ANNOTATE_ROWS_EVENT flag used when requesting an event: +If the replicate-annotate-rows-events option is not set on a slave, there +is no need for master to send Annotate_rows events to this slave. The slave +(or mysqlbinlog in remote case), before requesting binlog dump via the +COM_BINLOG_DUMP command, informs the master whether it should send these +events by executing the newly added COM_BINLOG_DUMP_OPTIONS_EXT server +command: + + case COM_BINLOG_DUMP_OPTIONS_EXT: + thd->binlog_dump_flags_ext= packet[0]; + my_ok(thd); + break; - #define BINLOG_DUMP_NON_BLOCK 1 - #define BINLOG_SEND_ANNOTATE_ROWS_EVENT 2 - - pthread_handler_t handle_slave_io(void *arg) - { ... - request_dump(mysql, ...); - ... - } - - int request_dump(MYSQL* mysql, ...) - { ... - if (opt_log_slave_updates && - mi->io_thd->variables.binlog_annotate_rows_events) - binlog_flags|= BINLOG_SEND_ANNOTATE_ROWS_EVENT; - ... - int2store(buf + 4, binlog_flags); - ... - simple_command(mysql, COM_BINLOG_DUMP, buf, ...); - ... - } - -NOTE. mysqlbinlog, when remotely requesting BINLOG_DUMP by calling the -simple_command() function, should also use this flag if it wants (in case -of the --print-annotate-rows-events option set) to recieve Annotate_rows -events. +Note. We add this new command and don't use COM_BINLOG_DUMP to avoid possible +conflicts with MySQL/Sun. 6. How master executes the request ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~ @@ -338,10 +323,4 @@ to internals(a)lists.mysql.com about this and suggesting to reserve the event number. -Also we should notice the introduction of the BINLOG_SEND_ANNOTATE_ROWS_EVENT -flag taking into account that MySQL/Sun may also introduce a flag with the -same value to be used in the request_dump-mysql_binlog_send interface. -But this is mainly the question of merging: if a conflict concerning this -flag occur, we may simply change the BINLOG_SEND_ANNOTATE_ROWS_EVENT value -(this does not require additional changes in the code). -=-=(Alexi - Sun, 20 Dec 2009, 16:00)=-=- Low Level Design modified. --- /tmp/wklog.47.old.19667 2009-12-20 14:00:56.000000000 +0000 +++ /tmp/wklog.47.new.19667 2009-12-20 14:00:56.000000000 +0000 @@ -196,6 +196,11 @@ ... } +NOTE. mysqlbinlog, when remotely requesting BINLOG_DUMP by calling the +simple_command() function, should also use this flag if it wants (in case +of the --print-annotate-rows-events option set) to recieve Annotate_rows +events. + 6. How master executes the request ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~ @@ -212,8 +217,7 @@ Log_event::read_log_event(&log, packet, ...); ... if ((*packet)[EVENT_TYPE_OFFSET + 1] != ANNOTATE_ROWS_EVENT || - flags & BINLOG_SEND_ANNOTATE_ROWS_EVENT || - thd->server_id == 0 /* slave == mysqlbinlog */ ) + flags & BINLOG_SEND_ANNOTATE_ROWS_EVENT) { my_net_write(net, packet->ptr(), packet->length()); } -=-=(Alexi - Sun, 20 Dec 2009, 13:14)=-=- Low Level Design modified. --- /tmp/wklog.47.old.11350 2009-12-20 13:14:04.000000000 +0200 +++ /tmp/wklog.47.new.11350 2009-12-20 13:14:04.000000000 +0200 @@ -282,23 +282,18 @@ Annotate_rows_log_event* m_annotate_event; }; -When the saved Annotate_rows object may be deleted? When all corresponding -Rows events will be processed, i.e. before processing the first non-Rows -event (note that Annotate_rows object resides in the binary log *after* -the (possible) 'BEGIN' Query event which accompanies the rows events; note -also that this deletion is adjusted with the case when some or all -corresponding Rows events are filtered out by replicate filter rules): +The saved Annotate_rows object should be deleted when all corresponding +Rows events will be processed: int exec_relay_log_event(THD* thd, Relay_log_info* rli) { ... Log_event *ev= next_event(rli); ... - if (rli->get_annotate_event() && !IS_RBR_EVENT_TYPE(ev->get_type_code())) - rli->free_annotate_event(); - apply_event_and_update_pos(ev, ...); - if (ev->get_type_code() == ANNOTATE_ROWS_EVENT) + if (rli->get_annotate_event() && is_last_rows_event(ev)) + rli->free_annotate_event(); + else if (ev->get_type_code() == ANNOTATE_ROWS_EVENT) rli->set_annotate_event((Annotate_rows_log_event*) ev); else if (ev->get_type_code() != FORMAT_DESCRIPTION_EVENT) delete ev; @@ -307,10 +302,21 @@ where - #define IS_RBR_EVENT_TYPE(type) ( (type) == TABLE_MAP_EVENT || \ - (type) == WRITE_ROWS_EVENT || \ + bool is_last_rows_event(Log_event* ev) + { + Log_event_type type= ev->get_type_code(); + if (IS_ROWS_EVENT_TYPE(type)) + { + Rows_log_event* rows= (Rows_log_event*)ev; + return rows->get_flags(Rows_log_event::STMT_END_F); + } + + return 0; + } + + #define IS_ROWS_EVENT_TYPE(type) ((type) == WRITE_ROWS_EVENT || \ (type) == UPDATE_ROWS_EVENT || \ - (type) == DELETE_ROWS_EVENT ) + (type) == DELETE_ROWS_EVENT) 8. General remarks ~~~~~~~~~~~~~~~~~~ -=-=(Alexi - Sun, 20 Dec 2009, 09:29)=-=- Low Level Design modified. --- /tmp/wklog.47.old.32726 2009-12-20 07:29:56.000000000 +0000 +++ /tmp/wklog.47.new.32726 2009-12-20 07:29:56.000000000 +0000 @@ -56,7 +56,7 @@ 0000006A | 00 | 0 - RESERVED [27] ..... ... 00000081 | 00 | 0 - RESERVED [50] - 00000082 | 00 | 0 - ANNOTATE_RBR_EVENT [51] + 00000082 | 00 | 0 - ANNOTATE_ROWS_EVENT [51] ************************ 2. Outline of Annotate_rows event behavior -=-=(Alexi - Sat, 19 Dec 2009, 16:10)=-=- Low Level Design modified. --- /tmp/wklog.47.old.16051 2009-12-19 16:10:48.000000000 +0200 +++ /tmp/wklog.47.new.16051 2009-12-19 16:10:48.000000000 +0200 @@ -253,7 +253,7 @@ thd query to that of the described by the event, i.e. to the query which caused the subsequent Rows events (see "How Master writes Annotate_rows events to the binary log" to follow what happens further when the subsequent -Rows events is applied): +Rows events are applied): int Annotate_rows_log_event::do_apply_event(...) { -=-=(Alexi - Sat, 19 Dec 2009, 16:02)=-=- High-Level Specification modified. --- /tmp/wklog.47.old.15695 2009-12-19 16:02:33.000000000 +0200 +++ /tmp/wklog.47.new.15695 2009-12-19 16:02:33.000000000 +0200 @@ -12,7 +12,7 @@ post-header and contains the query text in its data part. Example: ************************ - ANNOTATE_RBR_EVENT + ANNOTATE_ROWS_EVENT ************************ 00000220 | B6 A0 2C 4B | time_when = 1261215926 00000224 | 33 | event_type = 51 -=-=(Alexi - Sat, 19 Dec 2009, 15:58)=-=- Low Level Design modified. --- /tmp/wklog.47.old.15437 2009-12-19 13:58:12.000000000 +0000 +++ /tmp/wklog.47.new.15437 2009-12-19 13:58:12.000000000 +0000 @@ -1 +1,337 @@ +Content +~~~~~~~ + 1. Annotate_rows event number + 2. Outline of Annotate_rows event behavior + 3. How Master writes Annotate_rows events to the binary log + 4. How slave treats replicate-annotate-rows-events option + 5. How slave IO thread requests Annotate_rows events + 6. How master executes the request + 7. How slave SQL thread processes Annotate_rows events + 8. General remarks + +1. Annotate_rows event number +~~~~~~~~~~~~~~~~~~~~~~~~~~~~~ +To avoid possible event numbers conflict with MySQL/Sun, we leave a gap +between the last MySQL event number and the Annotate_rows event number: + + enum Log_event_type + { ... + INCIDENT_EVENT= 26, + // New MySQL event numbers are to be added here + MYSQL_EVENTS_END, + + MARIA_EVENTS_BEGIN= 51, + // New Maria event numbers start from here + ANNOTATE_ROWS_EVENT= 51, + + ENUM_END_EVENT + }; + +together with the corresponding extension of 'post_header_len' array in the +Format description event. (This extension does not affect the compatibility +of the binary log). Here is how Format description event looks like with +this extension: + + ************************ + FORMAT_DESCRIPTION_EVENT + ************************ + 00000004 | A1 A0 2C 4B | time_when = 1261215905 + 00000008 | 0F | event_type = 15 + 00000009 | 64 00 00 00 | server_id = 100 + 0000000D | 7F 00 00 00 | event_len = 127 + 00000011 | 83 00 00 00 | log_pos = 00000083 + 00000015 | 01 00 | flags = LOG_EVENT_BINLOG_IN_USE_F + ------------------------ + 00000017 | 04 00 | binlog_ver = 4 + 00000019 | 35 2E 32 2E | server_ver = 5.2.0-MariaDB-alpha-debug-log + ..... ... + 0000004B | A1 A0 2C 4B | time_created = 1261215905 + 0000004F | 13 | common_header_len = 19 + ------------------------ + post_header_len + ------------------------ + 00000050 | 38 | 56 - START_EVENT_V3 [1] + ..... ... + 00000069 | 02 | 2 - INCIDENT_EVENT [26] + 0000006A | 00 | 0 - RESERVED [27] + ..... ... + 00000081 | 00 | 0 - RESERVED [50] + 00000082 | 00 | 0 - ANNOTATE_RBR_EVENT [51] + ************************ + +2. Outline of Annotate_rows event behavior +~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~ +Each Annotate_rows_log_event object has two private members describing the +corresponding query: + + char *m_query_txt; + uint m_query_len; + +When the object is created for writing to a binary log, this query is taken +from 'thd' (for short, below we omit the 'Annotate_rows_log_event::' prefix +as well as other implementation details): + + Annotate_rows_log_event(THD *thd) + { + m_query_txt = thd->query(); + m_query_len = thd->query_length(); + } + +When the object is read from a binary log, the query is taken from the buffer +containing the binary log representation of the event (this buffer is allocated +in Log_event object from which all Log events are derived): + + Annotate_rows_log_event(char *buf, uint event_len, + Format_description_log_event *desc) + { + m_query_len = event_len - desc->common_header_len; + m_query_txt = buf + desc->common_header_len; + } + +The events are written to the binary log by the Log_event::write() member +which calls virtual write_data_header() and write_data_body() members +("data header" and "post header" are synonym in replication terminology). +In our case, data header is empty and data body is just the query: + + bool write_data_body(IO_CACHE *file) + { + return my_b_safe_write(file, (uchar*) m_query_txt, m_query_len); + } + +Printing the event is just printing the query: + + void Annotate_rows_log_event::print(FILE *file, PRINT_EVENT_INFO *pinfo) + { + my_b_printf(&pinfo->head_cache, "\tQuery: `%s`\n", m_query_txt); + } + +3. How Master writes Annotate_rows events to the binary log +~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~ +The event is written to the binary log just before the group of Table_map +events which precede corresponding Rows events (one query may generate +several Table map events in the binary log, but the corresponding +Annotate_rows event must be written only once before the first Table map +event; hence the boolean variable 'with_annotate' below): + + int write_locked_table_maps(THD *thd) + { ... + bool with_annotate= thd->variables.binlog_annotate_rows_events; + ... + for (uint i= 0; i < ... <number of tables> ...; ++i) + { ... + thd->binlog_write_table_map(table, ..., with_annotate); + with_annotate= 0; // write Annotate_event not more than once + ... + } + ... + } + + int THD::binlog_write_table_map(TABLE *table, ..., bool with_annotate) + { ... + Table_map_log_event the_event(...); + ... + if (with_annotate) + { + Annotate_rows_log_event anno(this); + mysql_bin_log.write(&anno); + } + + mysql_bin_log.write(&the_event); + ... + } + +4. How slave treats replicate-annotate-rows-events option +~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~ +The replicate-annotate-rows-events option is treated just as the session +value of the binlog_annotate_rows_events variable for the slave IO and +SQL threads. This setting is done during initialization of these threads: + + pthread_handler_t handle_slave_io(void *arg) + { + THD *thd= new THD; + ... + init_slave_thread(thd, SLAVE_THD_IO); + ... + } + + pthread_handler_t handle_slave_sql(void *arg) + { + THD *thd= new THD; + ... + init_slave_thread(thd, SLAVE_THD_SQL); + ... + } + + int init_slave_thread(THD* thd, SLAVE_THD_TYPE thd_type) + { ... + thd->variables.binlog_annotate_rows_events= + opt_replicate_annotate_rows_events; + ... + } + +5. How slave IO thread requests Annotate_rows events +~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~ +When requesting an event, the slave should inform the master whether +it should send Annotate_rows events or not. To that end we add a new +BINLOG_SEND_ANNOTATE_ROWS_EVENT flag used when requesting an event: + + #define BINLOG_DUMP_NON_BLOCK 1 + #define BINLOG_SEND_ANNOTATE_ROWS_EVENT 2 + + pthread_handler_t handle_slave_io(void *arg) + { ... + request_dump(mysql, ...); + ... + } + + int request_dump(MYSQL* mysql, ...) + { ... + if (opt_log_slave_updates && + mi->io_thd->variables.binlog_annotate_rows_events) + binlog_flags|= BINLOG_SEND_ANNOTATE_ROWS_EVENT; + ... + int2store(buf + 4, binlog_flags); + ... + simple_command(mysql, COM_BINLOG_DUMP, buf, ...); + ... + } + +6. How master executes the request +~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~ + + case COM_BINLOG_DUMP: + { ... + flags= uint2korr(packet + 4); + ... + mysql_binlog_send(thd, ..., flags); + ... + } + + void mysql_binlog_send(THD* thd, ..., ushort flags) + { ... + Log_event::read_log_event(&log, packet, ...); + ... + if ((*packet)[EVENT_TYPE_OFFSET + 1] != ANNOTATE_ROWS_EVENT || + flags & BINLOG_SEND_ANNOTATE_ROWS_EVENT || + thd->server_id == 0 /* slave == mysqlbinlog */ ) + { + my_net_write(net, packet->ptr(), packet->length()); + } + ... + } + +7. How slave SQL thread processes Annotate_rows events +~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~ +The slave processes each recieved event by "applying" it, i.e. by +calling the Log_event::apply_event() function which in turn calls +the virtual do_apply_event() member specific for each type of the +event. + + int exec_relay_log_event(THD* thd, Relay_log_info* rli) + { ... + Log_event *ev = next_event(rli); + ... + apply_event_and_update_pos(ev, ...); + + if (ev->get_type_code() != FORMAT_DESCRIPTION_EVENT) + delete ev; + ... + } + + int apply_event_and_update_pos(Log_event *ev, ...) + { ... + ev->apply_event(...); + ... + } + + int Log_event::apply_event(...) + { + return do_apply_event(...); + } + +What does it mean to "apply" an Annotate_rows event? It means to set current +thd query to that of the described by the event, i.e. to the query which +caused the subsequent Rows events (see "How Master writes Annotate_rows +events to the binary log" to follow what happens further when the subsequent +Rows events is applied): + + int Annotate_rows_log_event::do_apply_event(...) + { + thd->set_query(m_query_txt, m_query_len); + } + +NOTE. I am not sure, but possibly current values of thd->query and +thd->query_length should be saved before calling set_query() and to be +restored on the Annotate_rows_log_event object deletion. +Is it really needed ? + +After calling this do_apply_event() function we may not delete the +Annotate_rows_log_event object immediatedly (see exec_relay_log_event() +above) because thd->query now points to the string inside this object. +We may keep the pointer to this object in the Relay_log_info: + + class Relay_log_info + { + public: + ... + void set_annotate_event(Annotate_rows_log_event*); + Annotate_rows_log_event* get_annotate_event(); + void free_annotate_event(); + ... + private: + Annotate_rows_log_event* m_annotate_event; + }; + +When the saved Annotate_rows object may be deleted? When all corresponding +Rows events will be processed, i.e. before processing the first non-Rows +event (note that Annotate_rows object resides in the binary log *after* +the (possible) 'BEGIN' Query event which accompanies the rows events; note +also that this deletion is adjusted with the case when some or all +corresponding Rows events are filtered out by replicate filter rules): + + int exec_relay_log_event(THD* thd, Relay_log_info* rli) + { ... + Log_event *ev= next_event(rli); + ... + if (rli->get_annotate_event() && !IS_RBR_EVENT_TYPE(ev->get_type_code())) + rli->free_annotate_event(); + + apply_event_and_update_pos(ev, ...); + + if (ev->get_type_code() == ANNOTATE_ROWS_EVENT) + rli->set_annotate_event((Annotate_rows_log_event*) ev); + else if (ev->get_type_code() != FORMAT_DESCRIPTION_EVENT) + delete ev; + ... + } + +where + + #define IS_RBR_EVENT_TYPE(type) ( (type) == TABLE_MAP_EVENT || \ + (type) == WRITE_ROWS_EVENT || \ + (type) == UPDATE_ROWS_EVENT || \ + (type) == DELETE_ROWS_EVENT ) + +8. General remarks +~~~~~~~~~~~~~~~~~~ +Kristian noticed that introducing new log event type should be coordinated +somehow with MySQL/Sun: + + Kristian: The numeric code for this event must be assigned carefully. + It should be coordinated with MySQL/Sun, otherwise we can get into a + situation where MySQL uses the same numeric code for one event that + MariaDB uses for ANNOTATE_ROWS_EVENT, which would make merging the two + impossible. + Alex: I reserved about 20 numbers not to have possible conflicts + with MySQL. + Kristian: Still, I think it would be appropriate to send a polite email + to internals(a)lists.mysql.com about this and suggesting to reserve the + event number. + +Also we should notice the introduction of the BINLOG_SEND_ANNOTATE_ROWS_EVENT +flag taking into account that MySQL/Sun may also introduce a flag with the +same value to be used in the request_dump-mysql_binlog_send interface. +But this is mainly the question of merging: if a conflict concerning this +flag occur, we may simply change the BINLOG_SEND_ANNOTATE_ROWS_EVENT value +(this does not require additional changes in the code). -=-=(Alexi - Sat, 19 Dec 2009, 15:41)=-=- High-Level Specification modified. --- /tmp/wklog.47.old.14545 2009-12-19 15:41:21.000000000 +0200 +++ /tmp/wklog.47.new.14545 2009-12-19 15:41:21.000000000 +0200 @@ -1,122 +1,107 @@ -First suggestion: - -> I think for this we would actually need a new binlog event type -> (Comment_log_event?). Unless we want to log an empty statement Query_log_event -> containing only a comment (a bit of a hack). - -New server option -~~~~~~~~~~~~~~~~~ - --binlog-annotate-rows-events - -Setting this option makes RBR (rows-) events in the binary log to be -preceded by Annotate rows events (see below). The corresponding -'binlog_annotate_rows_events' system variable is dynamic and has both -global and session values. Default global value is OFF. - -Note. Session values are usefull to make it possible to annotate only - some selected statements: +Content +~~~~~~~ + 1. Annotate_rows_log_event + 2. Server option: --binlog-annotate-rows-events + 3. Server option: --replicate-annotate-rows-events + 4. mysqlbinlog option: --print-annotate-rows-events + 5. mysqlbinlog output + +1. Annotate_rows_log_event [ ANNOTATE_ROWS_EVENT ] +~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~ +Describes the query which caused the corresponding rows events. Has empty +post-header and contains the query text in its data part. Example: + + ************************ + ANNOTATE_RBR_EVENT + ************************ + 00000220 | B6 A0 2C 4B | time_when = 1261215926 + 00000224 | 33 | event_type = 51 + 00000225 | 64 00 00 00 | server_id = 100 + 00000229 | 36 00 00 00 | event_len = 54 + 0000022D | 56 02 00 00 | log_pos = 00000256 + 00000231 | 00 00 | flags = <none> + ------------------------ + 00000233 | 49 4E 53 45 | query = "INSERT INTO t1 VALUES (1), (2), (3)" + 00000237 | 52 54 20 49 | + 0000023B | 4E 54 4F 20 | + 0000023F | 74 31 20 56 | + 00000243 | 41 4C 55 45 | + 00000247 | 53 20 28 31 | + 0000024B | 29 2C 20 28 | + 0000024F | 32 29 2C 20 | + 00000253 | 28 33 29 | + ************************ + +In binary log, Annotate_rows event follows the (possible) 'BEGIN' Query event +and precedes the first of Table map events which accompany the corresponding +rows events. (See example in the "mysqlbinlog output" section below.) + +2. Server option: --binlog-annotate-rows-events +~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~ +Tells the master to write Annotate_rows events to the binary log. + + * Variable Name: binlog_annotate_rows_events + * Scope: Global & Session + * Access Type: Dynamic + * Data Type: bool + * Default Value: OFF +NOTE. Session values allows to annotate only some selected statements: ... SET SESSION binlog_annotate_rows_events=ON; ... statements to be annotated ... SET SESSION binlog_annotate_rows_events=OFF; ... statements not to be annotated ... -New binlog event type -~~~~~~~~~~~~~~~~~~~~~ - Annotate_rows_log_event [ ANNOTATE_ROWS_EVENT ] - -Describes the query which caused the corresponding rows event. In binary log, -precedes each Table_map_log_event. Contains empty post-header and the query -text in its data part. - -The numeric code for this event must be assigned carefully. It should be -coordinated with MySQL/Sun, otherwise we can get into a situation where MySQL -uses the same numeric code for one event that MariaDB uses for -ANNOTATE_ROWS_EVENT, which would make merging the two impossible. - -Example: - - ... - ************************ - ANNOTATE_ROWS_EVENT [51] - ************************ - 000000C7 | 54 1B 12 4B | time_when = 1259477844 - 000000CB | 33 | event_type = 51 - 000000CC | 64 00 00 00 | server_id = 100 - 000000D0 | 2C 00 00 00 | event_len = 44 - 000000D4 | F3 00 00 00 | log_pos = 000000F3 - 000000D8 | 00 00 | flags = <none> - ------------------------ - 000000DA | 69 6E 73 65 | query = "insert into t1 values (1)" - 000000DE | 72 74 20 69 | - 000000E2 | 6E 74 6F 20 | - 000000E6 | 74 31 20 76 | - 000000EA | 61 6C 75 65 | - 000000EE | 73 20 28 31 | - 000000F2 | 29 | - ************************ - TABLE_MAP_EVENT [19] - ************************ - 000000F3 | 54 1B 12 4B | time_when = 1259477844 - 000000F7 | 13 | event_type = 19 - 000000F8 | 64 00 00 00 | server_id = 100 - 000000FC | 29 00 00 00 | event_len = 41 - 00000100 | 1C 01 00 00 | log_pos = 0000011C - 00000104 | 00 00 | flags = <none> - ------------------------ - ... - ************************ - WRITE_ROWS_EVENT [23] - ************************ - 0000011C | 54 1B 12 4B | time_when = 1259477844 - 00000120 | 17 | event_type = 23 - 00000121 | 64 00 00 00 | server_id = 100 - 00000125 | 22 00 00 00 | event_len = 34 - 00000129 | 3E 01 00 00 | log_pos = 0000013E - 0000012D | 10 00 | flags = LOG_EVENT_UPDATE_TABLE_MAP_VERSION_F - ------------------------ - 0000012F | 0F 00 00 00 | table_id = 15 - ... - -New mysqlbinlog option -~~~~~~~~~~~~~~~~~~~~~~ - --print-annotate-rows-events - -With this option, mysqlbinlog prints the content of Annotate-rows -events (if the binary log does contain them). Without this option -(i.e. by default), mysqlbinlog skips Annotate rows events. - - -mysqlbinlog output -~~~~~~~~~~~~~~~~~~ -Something like this: +3. Server option: --replicate-annotate-rows-events +~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~ +Tells the slave to reproduce Annotate_rows events recieved from the master +in its own binary log (sensible only in pair with log-slave-updates option). + + * Variable Name: replicate_annotate_rows_events + * Scope: Global + * Access Type: Read only + * Data Type: bool + * Default Value: OFF + +NOTE. Why do we additionally need this 'replicate' option? Why not to make +the slave to reproduce this events when its binlog-annotate-rows-events +global value is ON? Well, because, for example, we may want to configure +the slave which should reproduce Annotate_rows events but has global +binlog-annotate-rows-events = OFF meaning this to be the default value for +the client threads (see also "How slave treats replicate-annotate-rows-events +option" in LLD part). + +4. mysqlbinlog option: --print-annotate-rows-events +~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~ +With this option, mysqlbinlog prints the content of Annotate_rows events (if +the binary log does contain them). Without this option (i.e. by default), +mysqlbinlog skips Annotate_rows events. +5. mysqlbinlog output +~~~~~~~~~~~~~~~~~~~~~ +With --print-annotate-rows-events, mysqlbinlog outputs Annotate_rows events +in a form like this: ... - # at 199 - # at 243 - # at 284 - #091129 9:57:24 server id 100 end_log_pos 243 Query: `insert into t1 values -(1)` - #091129 9:57:24 server id 100 end_log_pos 284 Table_map: `test`.`t1` mapped -to number 15 - #091129 9:57:24 server id 100 end_log_pos 318 Write_rows: table id 15 + # at 1646 + #091219 12:45:26 server id 100 end_log_pos 1714 Query thread_id=1 +exec_time=0 error_code=0 + SET TIMESTAMP=1261215926/*!*/; + BEGIN + /*!*/; + # at 1714 + # at 1812 + # at 1853 + # at 1894 + # at 1938 + #091219 12:45:26 server id 100 end_log_pos 1812 Query: `DELETE t1, t2 FROM +t1 INNER JOIN t2 INNER JOIN t3 WHERE t1.a=t2.a AND t2.a=t3.a` + #091219 12:45:26 server id 100 end_log_pos 1853 Table_map: `test`.`t1` +mapped to number 16 + #091219 12:45:26 server id 100 end_log_pos 1894 Table_map: `test`.`t2` +mapped to number 17 + #091219 12:45:26 server id 100 end_log_pos 1938 Delete_rows: table id 16 + #091219 12:45:26 server id 100 end_log_pos 1982 Delete_rows: table id 17 flags: STMT_END_F - - BINLOG ' - VBsSSzNkAAAALAAAAPMAAAAAAGluc2VydCBpbnRvIHQxIHZhbHVlcyAoMSk= - VBsSSxNkAAAAKQAAABwBAAAAAA8AAAAAAAAABHRlc3QAAnQxAAEDAAE= - VBsSSxdkAAAAIgAAAD4BAAAQAA8AAAAAAAEAAf/+AQAAAA== - '/*!*/; - ### INSERT INTO test.t1 - ### SET - ### @1=1 /* INT meta=0 nullable=1 is_null=0 */ ... -When master sends Annotate rows events -~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~ -1. Master always sends Annotate_rows events to mysqlbinlog (in - remote case). -2. Master sends Annotate_rows events to a slave only if the slave has - both log-slave-updates and binlog-annotate-rows-events options set. - -=-=(Bothorsen - Fri, 18 Dec 2009, 16:22)=-=- Add estimation time. Worked 5 hours and estimate 35 hours remain (original estimate increased by 5 hours). -=-=(Bothorsen - Fri, 18 Dec 2009, 16:16)=-=- This is the work done on this patch so far. Most of it done by Alex. Worked 15 hours and estimate 035 hours remain (original estimate increased by 50 hours). ------------------------------------------------------------ -=-=(View All Progress Notes, 20 total)=-=- http://askmonty.org/worklog/index.pl?tid=47&nolimit=1 DESCRIPTION: Store in binlog (and show in mysqlbinlog output) texts of statements that caused RBR events This is needed for (list from Monty): - Easier to understand why updates happened - Would make it easier to find out where in application things went wrong (as you can search for exact strings) - Allow one to filter things based on comments in the statement. The cost of this can be that the binlog will be approximately 2x in size (especially insert of big blob's would be a bit painful), so this should be an optional feature. HIGH-LEVEL SPECIFICATION: Content ~~~~~~~ 1. Annotate_rows_log_event 2. Server option: --binlog-annotate-rows-events 3. Server option: --replicate-annotate-rows-events 4. mysqlbinlog option: --print-annotate-rows-events 5. mysqlbinlog output 1. Annotate_rows_log_event [ ANNOTATE_ROWS_EVENT ] ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~ Describes the query which caused the corresponding rows events. Has empty post-header and contains the query text in its data part. Example: ************************ ANNOTATE_ROWS_EVENT ************************ 00000220 | B6 A0 2C 4B | time_when = 1261215926 00000224 | 33 | event_type = 51 00000225 | 64 00 00 00 | server_id = 100 00000229 | 36 00 00 00 | event_len = 54 0000022D | 56 02 00 00 | log_pos = 00000256 00000231 | 00 00 | flags = <none> ------------------------ 00000233 | 49 4E 53 45 | query = "INSERT INTO t1 VALUES (1), (2), (3)" 00000237 | 52 54 20 49 | 0000023B | 4E 54 4F 20 | 0000023F | 74 31 20 56 | 00000243 | 41 4C 55 45 | 00000247 | 53 20 28 31 | 0000024B | 29 2C 20 28 | 0000024F | 32 29 2C 20 | 00000253 | 28 33 29 | ************************ In binary log, Annotate_rows event follows the (possible) 'BEGIN' Query event and precedes the first of Table map events which accompany the corresponding rows events. (See example in the "mysqlbinlog output" section below.) 2. Server option: --binlog-annotate-rows-events ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~ Tells the master to write Annotate_rows events to the binary log. * Variable Name: binlog_annotate_rows_events * Scope: Global & Session * Access Type: Dynamic * Data Type: bool * Default Value: OFF NOTE. Session values allows to annotate only some selected statements: ... SET SESSION binlog_annotate_rows_events=ON; ... statements to be annotated ... SET SESSION binlog_annotate_rows_events=OFF; ... statements not to be annotated ... 3. Server option: --replicate-annotate-rows-events ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~ Tells the slave to reproduce Annotate_rows events recieved from the master in its own binary log (sensible only in pair with log-slave-updates option). * Variable Name: replicate_annotate_rows_events * Scope: Global * Access Type: Read only * Data Type: bool * Default Value: OFF NOTE. Why do we additionally need this 'replicate' option? Why not to make the slave to reproduce this events when its binlog-annotate-rows-events global value is ON? Well, because, for example, we may want to configure the slave which should reproduce Annotate_rows events but has global binlog-annotate-rows-events = OFF meaning this to be the default value for the client threads (see also "How slave treats replicate-annotate-rows-events option" in LLD part). 4. mysqlbinlog option: --print-annotate-rows-events ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~ With this option, mysqlbinlog prints the content of Annotate_rows events (if the binary log does contain them). Without this option (i.e. by default), mysqlbinlog skips Annotate_rows events. 5. mysqlbinlog output ~~~~~~~~~~~~~~~~~~~~~ With --print-annotate-rows-events, mysqlbinlog outputs Annotate_rows events in a form like this: ... # at 1646 #091219 12:45:26 server id 100 end_log_pos 1714 Query thread_id=1 exec_time=0 error_code=0 SET TIMESTAMP=1261215926/*!*/; BEGIN /*!*/; # at 1714 # at 1812 # at 1853 # at 1894 # at 1938 #091219 12:45:26 server id 100 end_log_pos 1812 Query: `DELETE t1, t2 FROM t1 INNER JOIN t2 INNER JOIN t3 WHERE t1.a=t2.a AND t2.a=t3.a` #091219 12:45:26 server id 100 end_log_pos 1853 Table_map: `test`.`t1` mapped to number 16 #091219 12:45:26 server id 100 end_log_pos 1894 Table_map: `test`.`t2` mapped to number 17 #091219 12:45:26 server id 100 end_log_pos 1938 Delete_rows: table id 16 #091219 12:45:26 server id 100 end_log_pos 1982 Delete_rows: table id 17 flags: STMT_END_F ... LOW-LEVEL DESIGN: Content ~~~~~~~ 1. Annotate_rows event number 2. Outline of Annotate_rows event behavior 3. How Master writes Annotate_rows events to the binary log 4. How slave treats replicate-annotate-rows-events option 5. How slave IO thread requests Annotate_rows events 6. How master executes the request 7. How slave SQL thread processes Annotate_rows events 8. General remarks 1. Annotate_rows event number ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~ To avoid possible event numbers conflict with MySQL/Sun, we leave a gap between the last MySQL event number and the Annotate_rows event number: enum Log_event_type { ... INCIDENT_EVENT= 26, // New MySQL event numbers are to be added here MYSQL_EVENTS_END, MARIA_EVENTS_BEGIN= 51, // New Maria event numbers start from here ANNOTATE_ROWS_EVENT= 51, ENUM_END_EVENT }; together with the corresponding extension of 'post_header_len' array in the Format description event. (This extension does not affect the compatibility of the binary log). Here is how Format description event looks like with this extension: ************************ FORMAT_DESCRIPTION_EVENT ************************ 00000004 | A1 A0 2C 4B | time_when = 1261215905 00000008 | 0F | event_type = 15 00000009 | 64 00 00 00 | server_id = 100 0000000D | 7F 00 00 00 | event_len = 127 00000011 | 83 00 00 00 | log_pos = 00000083 00000015 | 01 00 | flags = LOG_EVENT_BINLOG_IN_USE_F ------------------------ 00000017 | 04 00 | binlog_ver = 4 00000019 | 35 2E 32 2E | server_ver = 5.2.0-MariaDB-alpha-debug-log ..... ... 0000004B | A1 A0 2C 4B | time_created = 1261215905 0000004F | 13 | common_header_len = 19 ------------------------ post_header_len ------------------------ 00000050 | 38 | 56 - START_EVENT_V3 [1] ..... ... 00000069 | 02 | 2 - INCIDENT_EVENT [26] 0000006A | 00 | 0 - RESERVED [27] ..... ... 00000081 | 00 | 0 - RESERVED [50] 00000082 | 00 | 0 - ANNOTATE_ROWS_EVENT [51] ************************ 2. Outline of Annotate_rows event behavior ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~ Each Annotate_rows_log_event object has two private members describing the corresponding query: char *m_query_txt; uint m_query_len; When the object is created for writing to a binary log, this query is taken from 'thd' (for short, below we omit the 'Annotate_rows_log_event::' prefix as well as other implementation details): Annotate_rows_log_event(THD *thd) { m_query_txt = thd->query(); m_query_len = thd->query_length(); } When the object is read from a binary log, the query is taken from the buffer containing the binary log representation of the event (this buffer is allocated in Log_event object from which all Log events are derived): Annotate_rows_log_event(char *buf, uint event_len, Format_description_log_event *desc) { m_query_len = event_len - desc->common_header_len; m_query_txt = buf + desc->common_header_len; } The events are written to the binary log by the Log_event::write() member which calls virtual write_data_header() and write_data_body() members ("data header" and "post header" are synonym in replication terminology). In our case, data header is empty and data body is just the query: bool write_data_body(IO_CACHE *file) { return my_b_safe_write(file, (uchar*) m_query_txt, m_query_len); } Printing the event is just printing the query: void Annotate_rows_log_event::print(FILE *file, PRINT_EVENT_INFO *pinfo) { my_b_printf(&pinfo->head_cache, "\tQuery: `%s`\n", m_query_txt); } 3. How Master writes Annotate_rows events to the binary log ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~ The event is written to the binary log just before the group of Table_map events which precede corresponding Rows events (one query may generate several Table map events in the binary log, but the corresponding Annotate_rows event must be written only once before the first Table map event; hence the boolean variable 'with_annotate' below): int write_locked_table_maps(THD *thd) { ... bool with_annotate= thd->variables.binlog_annotate_rows_events; ... for (uint i= 0; i < ... <number of tables> ...; ++i) { ... thd->binlog_write_table_map(table, ..., with_annotate); with_annotate= 0; // write Annotate_event not more than once ... } ... } int THD::binlog_write_table_map(TABLE *table, ..., bool with_annotate) { ... Table_map_log_event the_event(...); ... if (with_annotate) { Annotate_rows_log_event anno(this); mysql_bin_log.write(&anno); } mysql_bin_log.write(&the_event); ... } 4. How slave treats replicate-annotate-rows-events option ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~ The replicate-annotate-rows-events option is treated just as the session value of the binlog_annotate_rows_events variable for the slave IO and SQL threads. This setting is done during initialization of these threads: pthread_handler_t handle_slave_io(void *arg) { THD *thd= new THD; ... init_slave_thread(thd, SLAVE_THD_IO); ... } pthread_handler_t handle_slave_sql(void *arg) { THD *thd= new THD; ... init_slave_thread(thd, SLAVE_THD_SQL); ... } int init_slave_thread(THD* thd, SLAVE_THD_TYPE thd_type) { ... thd->variables.binlog_annotate_rows_events= opt_replicate_annotate_rows_events; ... } 5. How slave IO thread requests Annotate_rows events ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~ If the replicate-annotate-rows-events option is not set on a slave, there is no need for master to send Annotate_rows events to this slave. The slave (or mysqlbinlog in remote case), before requesting binlog dump via the COM_BINLOG_DUMP command, informs the master whether it should send these events by executing the newly added COM_BINLOG_DUMP_OPTIONS_EXT server command: case COM_BINLOG_DUMP_OPTIONS_EXT: thd->binlog_dump_flags_ext= packet[0]; my_ok(thd); break; Note. We add this new command and don't use COM_BINLOG_DUMP to avoid possible conflicts with MySQL/Sun. 6. How master executes the request ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~ case COM_BINLOG_DUMP: { ... flags= uint2korr(packet + 4); ... mysql_binlog_send(thd, ..., flags); ... } void mysql_binlog_send(THD* thd, ..., ushort flags) { ... Log_event::read_log_event(&log, packet, ...); ... if ((*packet)[EVENT_TYPE_OFFSET + 1] != ANNOTATE_ROWS_EVENT || flags & BINLOG_SEND_ANNOTATE_ROWS_EVENT) { my_net_write(net, packet->ptr(), packet->length()); } ... } 7. How slave SQL thread processes Annotate_rows events ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~ The slave processes each recieved event by "applying" it, i.e. by calling the Log_event::apply_event() function which in turn calls the virtual do_apply_event() member specific for each type of the event. int exec_relay_log_event(THD* thd, Relay_log_info* rli) { ... Log_event *ev = next_event(rli); ... apply_event_and_update_pos(ev, ...); if (ev->get_type_code() != FORMAT_DESCRIPTION_EVENT) delete ev; ... } int apply_event_and_update_pos(Log_event *ev, ...) { ... ev->apply_event(...); ... } int Log_event::apply_event(...) { return do_apply_event(...); } What does it mean to "apply" an Annotate_rows event? It means to set current thd query to that of the described by the event, i.e. to the query which caused the subsequent Rows events (see "How Master writes Annotate_rows events to the binary log" to follow what happens further when the subsequent Rows events are applied): int Annotate_rows_log_event::do_apply_event(...) { thd->set_query(m_query_txt, m_query_len); } NOTE. I am not sure, but possibly current values of thd->query and thd->query_length should be saved before calling set_query() and to be restored on the Annotate_rows_log_event object deletion. Is it really needed ? After calling this do_apply_event() function we may not delete the Annotate_rows_log_event object immediatedly (see exec_relay_log_event() above) because thd->query now points to the string inside this object. We may keep the pointer to this object in the Relay_log_info: class Relay_log_info { public: ... void set_annotate_event(Annotate_rows_log_event*); Annotate_rows_log_event* get_annotate_event(); void free_annotate_event(); ... private: Annotate_rows_log_event* m_annotate_event; }; The saved Annotate_rows object should be deleted when all corresponding Rows events will be processed: int exec_relay_log_event(THD* thd, Relay_log_info* rli) { ... Log_event *ev= next_event(rli); ... apply_event_and_update_pos(ev, ...); if (rli->get_annotate_event() && is_last_rows_event(ev)) rli->free_annotate_event(); else if (ev->get_type_code() == ANNOTATE_ROWS_EVENT) rli->set_annotate_event((Annotate_rows_log_event*) ev); else if (ev->get_type_code() != FORMAT_DESCRIPTION_EVENT) delete ev; ... } where bool is_last_rows_event(Log_event* ev) { Log_event_type type= ev->get_type_code(); if (IS_ROWS_EVENT_TYPE(type)) { Rows_log_event* rows= (Rows_log_event*)ev; return rows->get_flags(Rows_log_event::STMT_END_F); } return 0; } #define IS_ROWS_EVENT_TYPE(type) ((type) == WRITE_ROWS_EVENT || \ (type) == UPDATE_ROWS_EVENT || \ (type) == DELETE_ROWS_EVENT) 8. General remarks ~~~~~~~~~~~~~~~~~~ Kristian noticed that introducing new log event type should be coordinated somehow with MySQL/Sun: Kristian: The numeric code for this event must be assigned carefully. It should be coordinated with MySQL/Sun, otherwise we can get into a situation where MySQL uses the same numeric code for one event that MariaDB uses for ANNOTATE_ROWS_EVENT, which would make merging the two impossible. Alex: I reserved about 20 numbers not to have possible conflicts with MySQL. Kristian: Still, I think it would be appropriate to send a polite email to internals(a)lists.mysql.com about this and suggesting to reserve the event number. ESTIMATED WORK TIME ESTIMATED COMPLETION DATE ----------------------------------------------------------------------- WorkLog (v3.5.9)

1 0

[Maria-developers] Updated (by Alexi): Store in binlog text of statements that caused RBR events (47)
by worklog-noreply＠askmonty.org 04 Feb '10

04 Feb '10

----------------------------------------------------------------------- WORKLOG TASK -=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=- TASK...........: Store in binlog text of statements that caused RBR events CREATION DATE..: Sat, 15 Aug 2009, 23:48 SUPERVISOR.....: Monty IMPLEMENTOR....: COPIES TO......: Knielsen CATEGORY.......: Server-RawIdeaBin TASK ID........: 47 (http://askmonty.org/worklog/?tid=47) VERSION........: Server-9.x STATUS.........: Un-Assigned PRIORITY.......: 60 WORKED HOURS...: 20 ESTIMATE.......: 35 (hours remain) ORIG. ESTIMATE.: 35 PROGRESS NOTES: -=-=(Alexi - Thu, 04 Feb 2010, 09:54)=-=- Low Level Design modified. --- /tmp/wklog.47.old.16174 2010-02-04 09:54:13.000000000 +0200 +++ /tmp/wklog.47.new.16174 2010-02-04 09:54:13.000000000 +0200 @@ -171,35 +171,20 @@ 5. How slave IO thread requests Annotate_rows events ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~ -When requesting an event, the slave should inform the master whether -it should send Annotate_rows events or not. To that end we add a new -BINLOG_SEND_ANNOTATE_ROWS_EVENT flag used when requesting an event: +If the replicate-annotate-rows-events option is not set on a slave, there +is no need for master to send Annotate_rows events to this slave. The slave +(or mysqlbinlog in remote case), before requesting binlog dump via the +COM_BINLOG_DUMP command, informs the master whether it should send these +events by executing the newly added COM_BINLOG_DUMP_OPTIONS_EXT server +command: + + case COM_BINLOG_DUMP_OPTIONS_EXT: + thd->binlog_dump_flags_ext= packet[0]; + my_ok(thd); + break; - #define BINLOG_DUMP_NON_BLOCK 1 - #define BINLOG_SEND_ANNOTATE_ROWS_EVENT 2 - - pthread_handler_t handle_slave_io(void *arg) - { ... - request_dump(mysql, ...); - ... - } - - int request_dump(MYSQL* mysql, ...) - { ... - if (opt_log_slave_updates && - mi->io_thd->variables.binlog_annotate_rows_events) - binlog_flags|= BINLOG_SEND_ANNOTATE_ROWS_EVENT; - ... - int2store(buf + 4, binlog_flags); - ... - simple_command(mysql, COM_BINLOG_DUMP, buf, ...); - ... - } - -NOTE. mysqlbinlog, when remotely requesting BINLOG_DUMP by calling the -simple_command() function, should also use this flag if it wants (in case -of the --print-annotate-rows-events option set) to recieve Annotate_rows -events. +Note. We add this new command and don't use COM_BINLOG_DUMP to avoid possible +conflicts with MySQL/Sun. 6. How master executes the request ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~ @@ -338,10 +323,4 @@ to internals(a)lists.mysql.com about this and suggesting to reserve the event number. -Also we should notice the introduction of the BINLOG_SEND_ANNOTATE_ROWS_EVENT -flag taking into account that MySQL/Sun may also introduce a flag with the -same value to be used in the request_dump-mysql_binlog_send interface. -But this is mainly the question of merging: if a conflict concerning this -flag occur, we may simply change the BINLOG_SEND_ANNOTATE_ROWS_EVENT value -(this does not require additional changes in the code). -=-=(Alexi - Sun, 20 Dec 2009, 16:00)=-=- Low Level Design modified. --- /tmp/wklog.47.old.19667 2009-12-20 14:00:56.000000000 +0000 +++ /tmp/wklog.47.new.19667 2009-12-20 14:00:56.000000000 +0000 @@ -196,6 +196,11 @@ ... } +NOTE. mysqlbinlog, when remotely requesting BINLOG_DUMP by calling the +simple_command() function, should also use this flag if it wants (in case +of the --print-annotate-rows-events option set) to recieve Annotate_rows +events. + 6. How master executes the request ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~ @@ -212,8 +217,7 @@ Log_event::read_log_event(&log, packet, ...); ... if ((*packet)[EVENT_TYPE_OFFSET + 1] != ANNOTATE_ROWS_EVENT || - flags & BINLOG_SEND_ANNOTATE_ROWS_EVENT || - thd->server_id == 0 /* slave == mysqlbinlog */ ) + flags & BINLOG_SEND_ANNOTATE_ROWS_EVENT) { my_net_write(net, packet->ptr(), packet->length()); } -=-=(Alexi - Sun, 20 Dec 2009, 13:14)=-=- Low Level Design modified. --- /tmp/wklog.47.old.11350 2009-12-20 13:14:04.000000000 +0200 +++ /tmp/wklog.47.new.11350 2009-12-20 13:14:04.000000000 +0200 @@ -282,23 +282,18 @@ Annotate_rows_log_event* m_annotate_event; }; -When the saved Annotate_rows object may be deleted? When all corresponding -Rows events will be processed, i.e. before processing the first non-Rows -event (note that Annotate_rows object resides in the binary log *after* -the (possible) 'BEGIN' Query event which accompanies the rows events; note -also that this deletion is adjusted with the case when some or all -corresponding Rows events are filtered out by replicate filter rules): +The saved Annotate_rows object should be deleted when all corresponding +Rows events will be processed: int exec_relay_log_event(THD* thd, Relay_log_info* rli) { ... Log_event *ev= next_event(rli); ... - if (rli->get_annotate_event() && !IS_RBR_EVENT_TYPE(ev->get_type_code())) - rli->free_annotate_event(); - apply_event_and_update_pos(ev, ...); - if (ev->get_type_code() == ANNOTATE_ROWS_EVENT) + if (rli->get_annotate_event() && is_last_rows_event(ev)) + rli->free_annotate_event(); + else if (ev->get_type_code() == ANNOTATE_ROWS_EVENT) rli->set_annotate_event((Annotate_rows_log_event*) ev); else if (ev->get_type_code() != FORMAT_DESCRIPTION_EVENT) delete ev; @@ -307,10 +302,21 @@ where - #define IS_RBR_EVENT_TYPE(type) ( (type) == TABLE_MAP_EVENT || \ - (type) == WRITE_ROWS_EVENT || \ + bool is_last_rows_event(Log_event* ev) + { + Log_event_type type= ev->get_type_code(); + if (IS_ROWS_EVENT_TYPE(type)) + { + Rows_log_event* rows= (Rows_log_event*)ev; + return rows->get_flags(Rows_log_event::STMT_END_F); + } + + return 0; + } + + #define IS_ROWS_EVENT_TYPE(type) ((type) == WRITE_ROWS_EVENT || \ (type) == UPDATE_ROWS_EVENT || \ - (type) == DELETE_ROWS_EVENT ) + (type) == DELETE_ROWS_EVENT) 8. General remarks ~~~~~~~~~~~~~~~~~~ -=-=(Alexi - Sun, 20 Dec 2009, 09:29)=-=- Low Level Design modified. --- /tmp/wklog.47.old.32726 2009-12-20 07:29:56.000000000 +0000 +++ /tmp/wklog.47.new.32726 2009-12-20 07:29:56.000000000 +0000 @@ -56,7 +56,7 @@ 0000006A | 00 | 0 - RESERVED [27] ..... ... 00000081 | 00 | 0 - RESERVED [50] - 00000082 | 00 | 0 - ANNOTATE_RBR_EVENT [51] + 00000082 | 00 | 0 - ANNOTATE_ROWS_EVENT [51] ************************ 2. Outline of Annotate_rows event behavior -=-=(Alexi - Sat, 19 Dec 2009, 16:10)=-=- Low Level Design modified. --- /tmp/wklog.47.old.16051 2009-12-19 16:10:48.000000000 +0200 +++ /tmp/wklog.47.new.16051 2009-12-19 16:10:48.000000000 +0200 @@ -253,7 +253,7 @@ thd query to that of the described by the event, i.e. to the query which caused the subsequent Rows events (see "How Master writes Annotate_rows events to the binary log" to follow what happens further when the subsequent -Rows events is applied): +Rows events are applied): int Annotate_rows_log_event::do_apply_event(...) { -=-=(Alexi - Sat, 19 Dec 2009, 16:02)=-=- High-Level Specification modified. --- /tmp/wklog.47.old.15695 2009-12-19 16:02:33.000000000 +0200 +++ /tmp/wklog.47.new.15695 2009-12-19 16:02:33.000000000 +0200 @@ -12,7 +12,7 @@ post-header and contains the query text in its data part. Example: ************************ - ANNOTATE_RBR_EVENT + ANNOTATE_ROWS_EVENT ************************ 00000220 | B6 A0 2C 4B | time_when = 1261215926 00000224 | 33 | event_type = 51 -=-=(Alexi - Sat, 19 Dec 2009, 15:58)=-=- Low Level Design modified. --- /tmp/wklog.47.old.15437 2009-12-19 13:58:12.000000000 +0000 +++ /tmp/wklog.47.new.15437 2009-12-19 13:58:12.000000000 +0000 @@ -1 +1,337 @@ +Content +~~~~~~~ + 1. Annotate_rows event number + 2. Outline of Annotate_rows event behavior + 3. How Master writes Annotate_rows events to the binary log + 4. How slave treats replicate-annotate-rows-events option + 5. How slave IO thread requests Annotate_rows events + 6. How master executes the request + 7. How slave SQL thread processes Annotate_rows events + 8. General remarks + +1. Annotate_rows event number +~~~~~~~~~~~~~~~~~~~~~~~~~~~~~ +To avoid possible event numbers conflict with MySQL/Sun, we leave a gap +between the last MySQL event number and the Annotate_rows event number: + + enum Log_event_type + { ... + INCIDENT_EVENT= 26, + // New MySQL event numbers are to be added here + MYSQL_EVENTS_END, + + MARIA_EVENTS_BEGIN= 51, + // New Maria event numbers start from here + ANNOTATE_ROWS_EVENT= 51, + + ENUM_END_EVENT + }; + +together with the corresponding extension of 'post_header_len' array in the +Format description event. (This extension does not affect the compatibility +of the binary log). Here is how Format description event looks like with +this extension: + + ************************ + FORMAT_DESCRIPTION_EVENT + ************************ + 00000004 | A1 A0 2C 4B | time_when = 1261215905 + 00000008 | 0F | event_type = 15 + 00000009 | 64 00 00 00 | server_id = 100 + 0000000D | 7F 00 00 00 | event_len = 127 + 00000011 | 83 00 00 00 | log_pos = 00000083 + 00000015 | 01 00 | flags = LOG_EVENT_BINLOG_IN_USE_F + ------------------------ + 00000017 | 04 00 | binlog_ver = 4 + 00000019 | 35 2E 32 2E | server_ver = 5.2.0-MariaDB-alpha-debug-log + ..... ... + 0000004B | A1 A0 2C 4B | time_created = 1261215905 + 0000004F | 13 | common_header_len = 19 + ------------------------ + post_header_len + ------------------------ + 00000050 | 38 | 56 - START_EVENT_V3 [1] + ..... ... + 00000069 | 02 | 2 - INCIDENT_EVENT [26] + 0000006A | 00 | 0 - RESERVED [27] + ..... ... + 00000081 | 00 | 0 - RESERVED [50] + 00000082 | 00 | 0 - ANNOTATE_RBR_EVENT [51] + ************************ + +2. Outline of Annotate_rows event behavior +~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~ +Each Annotate_rows_log_event object has two private members describing the +corresponding query: + + char *m_query_txt; + uint m_query_len; + +When the object is created for writing to a binary log, this query is taken +from 'thd' (for short, below we omit the 'Annotate_rows_log_event::' prefix +as well as other implementation details): + + Annotate_rows_log_event(THD *thd) + { + m_query_txt = thd->query(); + m_query_len = thd->query_length(); + } + +When the object is read from a binary log, the query is taken from the buffer +containing the binary log representation of the event (this buffer is allocated +in Log_event object from which all Log events are derived): + + Annotate_rows_log_event(char *buf, uint event_len, + Format_description_log_event *desc) + { + m_query_len = event_len - desc->common_header_len; + m_query_txt = buf + desc->common_header_len; + } + +The events are written to the binary log by the Log_event::write() member +which calls virtual write_data_header() and write_data_body() members +("data header" and "post header" are synonym in replication terminology). +In our case, data header is empty and data body is just the query: + + bool write_data_body(IO_CACHE *file) + { + return my_b_safe_write(file, (uchar*) m_query_txt, m_query_len); + } + +Printing the event is just printing the query: + + void Annotate_rows_log_event::print(FILE *file, PRINT_EVENT_INFO *pinfo) + { + my_b_printf(&pinfo->head_cache, "\tQuery: `%s`\n", m_query_txt); + } + +3. How Master writes Annotate_rows events to the binary log +~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~ +The event is written to the binary log just before the group of Table_map +events which precede corresponding Rows events (one query may generate +several Table map events in the binary log, but the corresponding +Annotate_rows event must be written only once before the first Table map +event; hence the boolean variable 'with_annotate' below): + + int write_locked_table_maps(THD *thd) + { ... + bool with_annotate= thd->variables.binlog_annotate_rows_events; + ... + for (uint i= 0; i < ... <number of tables> ...; ++i) + { ... + thd->binlog_write_table_map(table, ..., with_annotate); + with_annotate= 0; // write Annotate_event not more than once + ... + } + ... + } + + int THD::binlog_write_table_map(TABLE *table, ..., bool with_annotate) + { ... + Table_map_log_event the_event(...); + ... + if (with_annotate) + { + Annotate_rows_log_event anno(this); + mysql_bin_log.write(&anno); + } + + mysql_bin_log.write(&the_event); + ... + } + +4. How slave treats replicate-annotate-rows-events option +~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~ +The replicate-annotate-rows-events option is treated just as the session +value of the binlog_annotate_rows_events variable for the slave IO and +SQL threads. This setting is done during initialization of these threads: + + pthread_handler_t handle_slave_io(void *arg) + { + THD *thd= new THD; + ... + init_slave_thread(thd, SLAVE_THD_IO); + ... + } + + pthread_handler_t handle_slave_sql(void *arg) + { + THD *thd= new THD; + ... + init_slave_thread(thd, SLAVE_THD_SQL); + ... + } + + int init_slave_thread(THD* thd, SLAVE_THD_TYPE thd_type) + { ... + thd->variables.binlog_annotate_rows_events= + opt_replicate_annotate_rows_events; + ... + } + +5. How slave IO thread requests Annotate_rows events +~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~ +When requesting an event, the slave should inform the master whether +it should send Annotate_rows events or not. To that end we add a new +BINLOG_SEND_ANNOTATE_ROWS_EVENT flag used when requesting an event: + + #define BINLOG_DUMP_NON_BLOCK 1 + #define BINLOG_SEND_ANNOTATE_ROWS_EVENT 2 + + pthread_handler_t handle_slave_io(void *arg) + { ... + request_dump(mysql, ...); + ... + } + + int request_dump(MYSQL* mysql, ...) + { ... + if (opt_log_slave_updates && + mi->io_thd->variables.binlog_annotate_rows_events) + binlog_flags|= BINLOG_SEND_ANNOTATE_ROWS_EVENT; + ... + int2store(buf + 4, binlog_flags); + ... + simple_command(mysql, COM_BINLOG_DUMP, buf, ...); + ... + } + +6. How master executes the request +~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~ + + case COM_BINLOG_DUMP: + { ... + flags= uint2korr(packet + 4); + ... + mysql_binlog_send(thd, ..., flags); + ... + } + + void mysql_binlog_send(THD* thd, ..., ushort flags) + { ... + Log_event::read_log_event(&log, packet, ...); + ... + if ((*packet)[EVENT_TYPE_OFFSET + 1] != ANNOTATE_ROWS_EVENT || + flags & BINLOG_SEND_ANNOTATE_ROWS_EVENT || + thd->server_id == 0 /* slave == mysqlbinlog */ ) + { + my_net_write(net, packet->ptr(), packet->length()); + } + ... + } + +7. How slave SQL thread processes Annotate_rows events +~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~ +The slave processes each recieved event by "applying" it, i.e. by +calling the Log_event::apply_event() function which in turn calls +the virtual do_apply_event() member specific for each type of the +event. + + int exec_relay_log_event(THD* thd, Relay_log_info* rli) + { ... + Log_event *ev = next_event(rli); + ... + apply_event_and_update_pos(ev, ...); + + if (ev->get_type_code() != FORMAT_DESCRIPTION_EVENT) + delete ev; + ... + } + + int apply_event_and_update_pos(Log_event *ev, ...) + { ... + ev->apply_event(...); + ... + } + + int Log_event::apply_event(...) + { + return do_apply_event(...); + } + +What does it mean to "apply" an Annotate_rows event? It means to set current +thd query to that of the described by the event, i.e. to the query which +caused the subsequent Rows events (see "How Master writes Annotate_rows +events to the binary log" to follow what happens further when the subsequent +Rows events is applied): + + int Annotate_rows_log_event::do_apply_event(...) + { + thd->set_query(m_query_txt, m_query_len); + } + +NOTE. I am not sure, but possibly current values of thd->query and +thd->query_length should be saved before calling set_query() and to be +restored on the Annotate_rows_log_event object deletion. +Is it really needed ? + +After calling this do_apply_event() function we may not delete the +Annotate_rows_log_event object immediatedly (see exec_relay_log_event() +above) because thd->query now points to the string inside this object. +We may keep the pointer to this object in the Relay_log_info: + + class Relay_log_info + { + public: + ... + void set_annotate_event(Annotate_rows_log_event*); + Annotate_rows_log_event* get_annotate_event(); + void free_annotate_event(); + ... + private: + Annotate_rows_log_event* m_annotate_event; + }; + +When the saved Annotate_rows object may be deleted? When all corresponding +Rows events will be processed, i.e. before processing the first non-Rows +event (note that Annotate_rows object resides in the binary log *after* +the (possible) 'BEGIN' Query event which accompanies the rows events; note +also that this deletion is adjusted with the case when some or all +corresponding Rows events are filtered out by replicate filter rules): + + int exec_relay_log_event(THD* thd, Relay_log_info* rli) + { ... + Log_event *ev= next_event(rli); + ... + if (rli->get_annotate_event() && !IS_RBR_EVENT_TYPE(ev->get_type_code())) + rli->free_annotate_event(); + + apply_event_and_update_pos(ev, ...); + + if (ev->get_type_code() == ANNOTATE_ROWS_EVENT) + rli->set_annotate_event((Annotate_rows_log_event*) ev); + else if (ev->get_type_code() != FORMAT_DESCRIPTION_EVENT) + delete ev; + ... + } + +where + + #define IS_RBR_EVENT_TYPE(type) ( (type) == TABLE_MAP_EVENT || \ + (type) == WRITE_ROWS_EVENT || \ + (type) == UPDATE_ROWS_EVENT || \ + (type) == DELETE_ROWS_EVENT ) + +8. General remarks +~~~~~~~~~~~~~~~~~~ +Kristian noticed that introducing new log event type should be coordinated +somehow with MySQL/Sun: + + Kristian: The numeric code for this event must be assigned carefully. + It should be coordinated with MySQL/Sun, otherwise we can get into a + situation where MySQL uses the same numeric code for one event that + MariaDB uses for ANNOTATE_ROWS_EVENT, which would make merging the two + impossible. + Alex: I reserved about 20 numbers not to have possible conflicts + with MySQL. + Kristian: Still, I think it would be appropriate to send a polite email + to internals(a)lists.mysql.com about this and suggesting to reserve the + event number. + +Also we should notice the introduction of the BINLOG_SEND_ANNOTATE_ROWS_EVENT +flag taking into account that MySQL/Sun may also introduce a flag with the +same value to be used in the request_dump-mysql_binlog_send interface. +But this is mainly the question of merging: if a conflict concerning this +flag occur, we may simply change the BINLOG_SEND_ANNOTATE_ROWS_EVENT value +(this does not require additional changes in the code). -=-=(Alexi - Sat, 19 Dec 2009, 15:41)=-=- High-Level Specification modified. --- /tmp/wklog.47.old.14545 2009-12-19 15:41:21.000000000 +0200 +++ /tmp/wklog.47.new.14545 2009-12-19 15:41:21.000000000 +0200 @@ -1,122 +1,107 @@ -First suggestion: - -> I think for this we would actually need a new binlog event type -> (Comment_log_event?). Unless we want to log an empty statement Query_log_event -> containing only a comment (a bit of a hack). - -New server option -~~~~~~~~~~~~~~~~~ - --binlog-annotate-rows-events - -Setting this option makes RBR (rows-) events in the binary log to be -preceded by Annotate rows events (see below). The corresponding -'binlog_annotate_rows_events' system variable is dynamic and has both -global and session values. Default global value is OFF. - -Note. Session values are usefull to make it possible to annotate only - some selected statements: +Content +~~~~~~~ + 1. Annotate_rows_log_event + 2. Server option: --binlog-annotate-rows-events + 3. Server option: --replicate-annotate-rows-events + 4. mysqlbinlog option: --print-annotate-rows-events + 5. mysqlbinlog output + +1. Annotate_rows_log_event [ ANNOTATE_ROWS_EVENT ] +~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~ +Describes the query which caused the corresponding rows events. Has empty +post-header and contains the query text in its data part. Example: + + ************************ + ANNOTATE_RBR_EVENT + ************************ + 00000220 | B6 A0 2C 4B | time_when = 1261215926 + 00000224 | 33 | event_type = 51 + 00000225 | 64 00 00 00 | server_id = 100 + 00000229 | 36 00 00 00 | event_len = 54 + 0000022D | 56 02 00 00 | log_pos = 00000256 + 00000231 | 00 00 | flags = <none> + ------------------------ + 00000233 | 49 4E 53 45 | query = "INSERT INTO t1 VALUES (1), (2), (3)" + 00000237 | 52 54 20 49 | + 0000023B | 4E 54 4F 20 | + 0000023F | 74 31 20 56 | + 00000243 | 41 4C 55 45 | + 00000247 | 53 20 28 31 | + 0000024B | 29 2C 20 28 | + 0000024F | 32 29 2C 20 | + 00000253 | 28 33 29 | + ************************ + +In binary log, Annotate_rows event follows the (possible) 'BEGIN' Query event +and precedes the first of Table map events which accompany the corresponding +rows events. (See example in the "mysqlbinlog output" section below.) + +2. Server option: --binlog-annotate-rows-events +~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~ +Tells the master to write Annotate_rows events to the binary log. + + * Variable Name: binlog_annotate_rows_events + * Scope: Global & Session + * Access Type: Dynamic + * Data Type: bool + * Default Value: OFF +NOTE. Session values allows to annotate only some selected statements: ... SET SESSION binlog_annotate_rows_events=ON; ... statements to be annotated ... SET SESSION binlog_annotate_rows_events=OFF; ... statements not to be annotated ... -New binlog event type -~~~~~~~~~~~~~~~~~~~~~ - Annotate_rows_log_event [ ANNOTATE_ROWS_EVENT ] - -Describes the query which caused the corresponding rows event. In binary log, -precedes each Table_map_log_event. Contains empty post-header and the query -text in its data part. - -The numeric code for this event must be assigned carefully. It should be -coordinated with MySQL/Sun, otherwise we can get into a situation where MySQL -uses the same numeric code for one event that MariaDB uses for -ANNOTATE_ROWS_EVENT, which would make merging the two impossible. - -Example: - - ... - ************************ - ANNOTATE_ROWS_EVENT [51] - ************************ - 000000C7 | 54 1B 12 4B | time_when = 1259477844 - 000000CB | 33 | event_type = 51 - 000000CC | 64 00 00 00 | server_id = 100 - 000000D0 | 2C 00 00 00 | event_len = 44 - 000000D4 | F3 00 00 00 | log_pos = 000000F3 - 000000D8 | 00 00 | flags = <none> - ------------------------ - 000000DA | 69 6E 73 65 | query = "insert into t1 values (1)" - 000000DE | 72 74 20 69 | - 000000E2 | 6E 74 6F 20 | - 000000E6 | 74 31 20 76 | - 000000EA | 61 6C 75 65 | - 000000EE | 73 20 28 31 | - 000000F2 | 29 | - ************************ - TABLE_MAP_EVENT [19] - ************************ - 000000F3 | 54 1B 12 4B | time_when = 1259477844 - 000000F7 | 13 | event_type = 19 - 000000F8 | 64 00 00 00 | server_id = 100 - 000000FC | 29 00 00 00 | event_len = 41 - 00000100 | 1C 01 00 00 | log_pos = 0000011C - 00000104 | 00 00 | flags = <none> - ------------------------ - ... - ************************ - WRITE_ROWS_EVENT [23] - ************************ - 0000011C | 54 1B 12 4B | time_when = 1259477844 - 00000120 | 17 | event_type = 23 - 00000121 | 64 00 00 00 | server_id = 100 - 00000125 | 22 00 00 00 | event_len = 34 - 00000129 | 3E 01 00 00 | log_pos = 0000013E - 0000012D | 10 00 | flags = LOG_EVENT_UPDATE_TABLE_MAP_VERSION_F - ------------------------ - 0000012F | 0F 00 00 00 | table_id = 15 - ... - -New mysqlbinlog option -~~~~~~~~~~~~~~~~~~~~~~ - --print-annotate-rows-events - -With this option, mysqlbinlog prints the content of Annotate-rows -events (if the binary log does contain them). Without this option -(i.e. by default), mysqlbinlog skips Annotate rows events. - - -mysqlbinlog output -~~~~~~~~~~~~~~~~~~ -Something like this: +3. Server option: --replicate-annotate-rows-events +~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~ +Tells the slave to reproduce Annotate_rows events recieved from the master +in its own binary log (sensible only in pair with log-slave-updates option). + + * Variable Name: replicate_annotate_rows_events + * Scope: Global + * Access Type: Read only + * Data Type: bool + * Default Value: OFF + +NOTE. Why do we additionally need this 'replicate' option? Why not to make +the slave to reproduce this events when its binlog-annotate-rows-events +global value is ON? Well, because, for example, we may want to configure +the slave which should reproduce Annotate_rows events but has global +binlog-annotate-rows-events = OFF meaning this to be the default value for +the client threads (see also "How slave treats replicate-annotate-rows-events +option" in LLD part). + +4. mysqlbinlog option: --print-annotate-rows-events +~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~ +With this option, mysqlbinlog prints the content of Annotate_rows events (if +the binary log does contain them). Without this option (i.e. by default), +mysqlbinlog skips Annotate_rows events. +5. mysqlbinlog output +~~~~~~~~~~~~~~~~~~~~~ +With --print-annotate-rows-events, mysqlbinlog outputs Annotate_rows events +in a form like this: ... - # at 199 - # at 243 - # at 284 - #091129 9:57:24 server id 100 end_log_pos 243 Query: `insert into t1 values -(1)` - #091129 9:57:24 server id 100 end_log_pos 284 Table_map: `test`.`t1` mapped -to number 15 - #091129 9:57:24 server id 100 end_log_pos 318 Write_rows: table id 15 + # at 1646 + #091219 12:45:26 server id 100 end_log_pos 1714 Query thread_id=1 +exec_time=0 error_code=0 + SET TIMESTAMP=1261215926/*!*/; + BEGIN + /*!*/; + # at 1714 + # at 1812 + # at 1853 + # at 1894 + # at 1938 + #091219 12:45:26 server id 100 end_log_pos 1812 Query: `DELETE t1, t2 FROM +t1 INNER JOIN t2 INNER JOIN t3 WHERE t1.a=t2.a AND t2.a=t3.a` + #091219 12:45:26 server id 100 end_log_pos 1853 Table_map: `test`.`t1` +mapped to number 16 + #091219 12:45:26 server id 100 end_log_pos 1894 Table_map: `test`.`t2` +mapped to number 17 + #091219 12:45:26 server id 100 end_log_pos 1938 Delete_rows: table id 16 + #091219 12:45:26 server id 100 end_log_pos 1982 Delete_rows: table id 17 flags: STMT_END_F - - BINLOG ' - VBsSSzNkAAAALAAAAPMAAAAAAGluc2VydCBpbnRvIHQxIHZhbHVlcyAoMSk= - VBsSSxNkAAAAKQAAABwBAAAAAA8AAAAAAAAABHRlc3QAAnQxAAEDAAE= - VBsSSxdkAAAAIgAAAD4BAAAQAA8AAAAAAAEAAf/+AQAAAA== - '/*!*/; - ### INSERT INTO test.t1 - ### SET - ### @1=1 /* INT meta=0 nullable=1 is_null=0 */ ... -When master sends Annotate rows events -~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~ -1. Master always sends Annotate_rows events to mysqlbinlog (in - remote case). -2. Master sends Annotate_rows events to a slave only if the slave has - both log-slave-updates and binlog-annotate-rows-events options set. - -=-=(Bothorsen - Fri, 18 Dec 2009, 16:22)=-=- Add estimation time. Worked 5 hours and estimate 35 hours remain (original estimate increased by 5 hours). -=-=(Bothorsen - Fri, 18 Dec 2009, 16:16)=-=- This is the work done on this patch so far. Most of it done by Alex. Worked 15 hours and estimate 035 hours remain (original estimate increased by 50 hours). ------------------------------------------------------------ -=-=(View All Progress Notes, 20 total)=-=- http://askmonty.org/worklog/index.pl?tid=47&nolimit=1 DESCRIPTION: Store in binlog (and show in mysqlbinlog output) texts of statements that caused RBR events This is needed for (list from Monty): - Easier to understand why updates happened - Would make it easier to find out where in application things went wrong (as you can search for exact strings) - Allow one to filter things based on comments in the statement. The cost of this can be that the binlog will be approximately 2x in size (especially insert of big blob's would be a bit painful), so this should be an optional feature. HIGH-LEVEL SPECIFICATION: Content ~~~~~~~ 1. Annotate_rows_log_event 2. Server option: --binlog-annotate-rows-events 3. Server option: --replicate-annotate-rows-events 4. mysqlbinlog option: --print-annotate-rows-events 5. mysqlbinlog output 1. Annotate_rows_log_event [ ANNOTATE_ROWS_EVENT ] ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~ Describes the query which caused the corresponding rows events. Has empty post-header and contains the query text in its data part. Example: ************************ ANNOTATE_ROWS_EVENT ************************ 00000220 | B6 A0 2C 4B | time_when = 1261215926 00000224 | 33 | event_type = 51 00000225 | 64 00 00 00 | server_id = 100 00000229 | 36 00 00 00 | event_len = 54 0000022D | 56 02 00 00 | log_pos = 00000256 00000231 | 00 00 | flags = <none> ------------------------ 00000233 | 49 4E 53 45 | query = "INSERT INTO t1 VALUES (1), (2), (3)" 00000237 | 52 54 20 49 | 0000023B | 4E 54 4F 20 | 0000023F | 74 31 20 56 | 00000243 | 41 4C 55 45 | 00000247 | 53 20 28 31 | 0000024B | 29 2C 20 28 | 0000024F | 32 29 2C 20 | 00000253 | 28 33 29 | ************************ In binary log, Annotate_rows event follows the (possible) 'BEGIN' Query event and precedes the first of Table map events which accompany the corresponding rows events. (See example in the "mysqlbinlog output" section below.) 2. Server option: --binlog-annotate-rows-events ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~ Tells the master to write Annotate_rows events to the binary log. * Variable Name: binlog_annotate_rows_events * Scope: Global & Session * Access Type: Dynamic * Data Type: bool * Default Value: OFF NOTE. Session values allows to annotate only some selected statements: ... SET SESSION binlog_annotate_rows_events=ON; ... statements to be annotated ... SET SESSION binlog_annotate_rows_events=OFF; ... statements not to be annotated ... 3. Server option: --replicate-annotate-rows-events ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~ Tells the slave to reproduce Annotate_rows events recieved from the master in its own binary log (sensible only in pair with log-slave-updates option). * Variable Name: replicate_annotate_rows_events * Scope: Global * Access Type: Read only * Data Type: bool * Default Value: OFF NOTE. Why do we additionally need this 'replicate' option? Why not to make the slave to reproduce this events when its binlog-annotate-rows-events global value is ON? Well, because, for example, we may want to configure the slave which should reproduce Annotate_rows events but has global binlog-annotate-rows-events = OFF meaning this to be the default value for the client threads (see also "How slave treats replicate-annotate-rows-events option" in LLD part). 4. mysqlbinlog option: --print-annotate-rows-events ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~ With this option, mysqlbinlog prints the content of Annotate_rows events (if the binary log does contain them). Without this option (i.e. by default), mysqlbinlog skips Annotate_rows events. 5. mysqlbinlog output ~~~~~~~~~~~~~~~~~~~~~ With --print-annotate-rows-events, mysqlbinlog outputs Annotate_rows events in a form like this: ... # at 1646 #091219 12:45:26 server id 100 end_log_pos 1714 Query thread_id=1 exec_time=0 error_code=0 SET TIMESTAMP=1261215926/*!*/; BEGIN /*!*/; # at 1714 # at 1812 # at 1853 # at 1894 # at 1938 #091219 12:45:26 server id 100 end_log_pos 1812 Query: `DELETE t1, t2 FROM t1 INNER JOIN t2 INNER JOIN t3 WHERE t1.a=t2.a AND t2.a=t3.a` #091219 12:45:26 server id 100 end_log_pos 1853 Table_map: `test`.`t1` mapped to number 16 #091219 12:45:26 server id 100 end_log_pos 1894 Table_map: `test`.`t2` mapped to number 17 #091219 12:45:26 server id 100 end_log_pos 1938 Delete_rows: table id 16 #091219 12:45:26 server id 100 end_log_pos 1982 Delete_rows: table id 17 flags: STMT_END_F ... LOW-LEVEL DESIGN: Content ~~~~~~~ 1. Annotate_rows event number 2. Outline of Annotate_rows event behavior 3. How Master writes Annotate_rows events to the binary log 4. How slave treats replicate-annotate-rows-events option 5. How slave IO thread requests Annotate_rows events 6. How master executes the request 7. How slave SQL thread processes Annotate_rows events 8. General remarks 1. Annotate_rows event number ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~ To avoid possible event numbers conflict with MySQL/Sun, we leave a gap between the last MySQL event number and the Annotate_rows event number: enum Log_event_type { ... INCIDENT_EVENT= 26, // New MySQL event numbers are to be added here MYSQL_EVENTS_END, MARIA_EVENTS_BEGIN= 51, // New Maria event numbers start from here ANNOTATE_ROWS_EVENT= 51, ENUM_END_EVENT }; together with the corresponding extension of 'post_header_len' array in the Format description event. (This extension does not affect the compatibility of the binary log). Here is how Format description event looks like with this extension: ************************ FORMAT_DESCRIPTION_EVENT ************************ 00000004 | A1 A0 2C 4B | time_when = 1261215905 00000008 | 0F | event_type = 15 00000009 | 64 00 00 00 | server_id = 100 0000000D | 7F 00 00 00 | event_len = 127 00000011 | 83 00 00 00 | log_pos = 00000083 00000015 | 01 00 | flags = LOG_EVENT_BINLOG_IN_USE_F ------------------------ 00000017 | 04 00 | binlog_ver = 4 00000019 | 35 2E 32 2E | server_ver = 5.2.0-MariaDB-alpha-debug-log ..... ... 0000004B | A1 A0 2C 4B | time_created = 1261215905 0000004F | 13 | common_header_len = 19 ------------------------ post_header_len ------------------------ 00000050 | 38 | 56 - START_EVENT_V3 [1] ..... ... 00000069 | 02 | 2 - INCIDENT_EVENT [26] 0000006A | 00 | 0 - RESERVED [27] ..... ... 00000081 | 00 | 0 - RESERVED [50] 00000082 | 00 | 0 - ANNOTATE_ROWS_EVENT [51] ************************ 2. Outline of Annotate_rows event behavior ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~ Each Annotate_rows_log_event object has two private members describing the corresponding query: char *m_query_txt; uint m_query_len; When the object is created for writing to a binary log, this query is taken from 'thd' (for short, below we omit the 'Annotate_rows_log_event::' prefix as well as other implementation details): Annotate_rows_log_event(THD *thd) { m_query_txt = thd->query(); m_query_len = thd->query_length(); } When the object is read from a binary log, the query is taken from the buffer containing the binary log representation of the event (this buffer is allocated in Log_event object from which all Log events are derived): Annotate_rows_log_event(char *buf, uint event_len, Format_description_log_event *desc) { m_query_len = event_len - desc->common_header_len; m_query_txt = buf + desc->common_header_len; } The events are written to the binary log by the Log_event::write() member which calls virtual write_data_header() and write_data_body() members ("data header" and "post header" are synonym in replication terminology). In our case, data header is empty and data body is just the query: bool write_data_body(IO_CACHE *file) { return my_b_safe_write(file, (uchar*) m_query_txt, m_query_len); } Printing the event is just printing the query: void Annotate_rows_log_event::print(FILE *file, PRINT_EVENT_INFO *pinfo) { my_b_printf(&pinfo->head_cache, "\tQuery: `%s`\n", m_query_txt); } 3. How Master writes Annotate_rows events to the binary log ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~ The event is written to the binary log just before the group of Table_map events which precede corresponding Rows events (one query may generate several Table map events in the binary log, but the corresponding Annotate_rows event must be written only once before the first Table map event; hence the boolean variable 'with_annotate' below): int write_locked_table_maps(THD *thd) { ... bool with_annotate= thd->variables.binlog_annotate_rows_events; ... for (uint i= 0; i < ... <number of tables> ...; ++i) { ... thd->binlog_write_table_map(table, ..., with_annotate); with_annotate= 0; // write Annotate_event not more than once ... } ... } int THD::binlog_write_table_map(TABLE *table, ..., bool with_annotate) { ... Table_map_log_event the_event(...); ... if (with_annotate) { Annotate_rows_log_event anno(this); mysql_bin_log.write(&anno); } mysql_bin_log.write(&the_event); ... } 4. How slave treats replicate-annotate-rows-events option ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~ The replicate-annotate-rows-events option is treated just as the session value of the binlog_annotate_rows_events variable for the slave IO and SQL threads. This setting is done during initialization of these threads: pthread_handler_t handle_slave_io(void *arg) { THD *thd= new THD; ... init_slave_thread(thd, SLAVE_THD_IO); ... } pthread_handler_t handle_slave_sql(void *arg) { THD *thd= new THD; ... init_slave_thread(thd, SLAVE_THD_SQL); ... } int init_slave_thread(THD* thd, SLAVE_THD_TYPE thd_type) { ... thd->variables.binlog_annotate_rows_events= opt_replicate_annotate_rows_events; ... } 5. How slave IO thread requests Annotate_rows events ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~ If the replicate-annotate-rows-events option is not set on a slave, there is no need for master to send Annotate_rows events to this slave. The slave (or mysqlbinlog in remote case), before requesting binlog dump via the COM_BINLOG_DUMP command, informs the master whether it should send these events by executing the newly added COM_BINLOG_DUMP_OPTIONS_EXT server command: case COM_BINLOG_DUMP_OPTIONS_EXT: thd->binlog_dump_flags_ext= packet[0]; my_ok(thd); break; Note. We add this new command and don't use COM_BINLOG_DUMP to avoid possible conflicts with MySQL/Sun. 6. How master executes the request ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~ case COM_BINLOG_DUMP: { ... flags= uint2korr(packet + 4); ... mysql_binlog_send(thd, ..., flags); ... } void mysql_binlog_send(THD* thd, ..., ushort flags) { ... Log_event::read_log_event(&log, packet, ...); ... if ((*packet)[EVENT_TYPE_OFFSET + 1] != ANNOTATE_ROWS_EVENT || flags & BINLOG_SEND_ANNOTATE_ROWS_EVENT) { my_net_write(net, packet->ptr(), packet->length()); } ... } 7. How slave SQL thread processes Annotate_rows events ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~ The slave processes each recieved event by "applying" it, i.e. by calling the Log_event::apply_event() function which in turn calls the virtual do_apply_event() member specific for each type of the event. int exec_relay_log_event(THD* thd, Relay_log_info* rli) { ... Log_event *ev = next_event(rli); ... apply_event_and_update_pos(ev, ...); if (ev->get_type_code() != FORMAT_DESCRIPTION_EVENT) delete ev; ... } int apply_event_and_update_pos(Log_event *ev, ...) { ... ev->apply_event(...); ... } int Log_event::apply_event(...) { return do_apply_event(...); } What does it mean to "apply" an Annotate_rows event? It means to set current thd query to that of the described by the event, i.e. to the query which caused the subsequent Rows events (see "How Master writes Annotate_rows events to the binary log" to follow what happens further when the subsequent Rows events are applied): int Annotate_rows_log_event::do_apply_event(...) { thd->set_query(m_query_txt, m_query_len); } NOTE. I am not sure, but possibly current values of thd->query and thd->query_length should be saved before calling set_query() and to be restored on the Annotate_rows_log_event object deletion. Is it really needed ? After calling this do_apply_event() function we may not delete the Annotate_rows_log_event object immediatedly (see exec_relay_log_event() above) because thd->query now points to the string inside this object. We may keep the pointer to this object in the Relay_log_info: class Relay_log_info { public: ... void set_annotate_event(Annotate_rows_log_event*); Annotate_rows_log_event* get_annotate_event(); void free_annotate_event(); ... private: Annotate_rows_log_event* m_annotate_event; }; The saved Annotate_rows object should be deleted when all corresponding Rows events will be processed: int exec_relay_log_event(THD* thd, Relay_log_info* rli) { ... Log_event *ev= next_event(rli); ... apply_event_and_update_pos(ev, ...); if (rli->get_annotate_event() && is_last_rows_event(ev)) rli->free_annotate_event(); else if (ev->get_type_code() == ANNOTATE_ROWS_EVENT) rli->set_annotate_event((Annotate_rows_log_event*) ev); else if (ev->get_type_code() != FORMAT_DESCRIPTION_EVENT) delete ev; ... } where bool is_last_rows_event(Log_event* ev) { Log_event_type type= ev->get_type_code(); if (IS_ROWS_EVENT_TYPE(type)) { Rows_log_event* rows= (Rows_log_event*)ev; return rows->get_flags(Rows_log_event::STMT_END_F); } return 0; } #define IS_ROWS_EVENT_TYPE(type) ((type) == WRITE_ROWS_EVENT || \ (type) == UPDATE_ROWS_EVENT || \ (type) == DELETE_ROWS_EVENT) 8. General remarks ~~~~~~~~~~~~~~~~~~ Kristian noticed that introducing new log event type should be coordinated somehow with MySQL/Sun: Kristian: The numeric code for this event must be assigned carefully. It should be coordinated with MySQL/Sun, otherwise we can get into a situation where MySQL uses the same numeric code for one event that MariaDB uses for ANNOTATE_ROWS_EVENT, which would make merging the two impossible. Alex: I reserved about 20 numbers not to have possible conflicts with MySQL. Kristian: Still, I think it would be appropriate to send a polite email to internals(a)lists.mysql.com about this and suggesting to reserve the event number. ESTIMATED WORK TIME ESTIMATED COMPLETION DATE ----------------------------------------------------------------------- WorkLog (v3.5.9)

1 0

[Maria-developers] Updated (by Alexi): Store in binlog text of statements that caused RBR events (47)
by worklog-noreply＠askmonty.org 04 Feb '10

04 Feb '10

----------------------------------------------------------------------- WORKLOG TASK -=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=-=- TASK...........: Store in binlog text of statements that caused RBR events CREATION DATE..: Sat, 15 Aug 2009, 23:48 SUPERVISOR.....: Monty IMPLEMENTOR....: COPIES TO......: Knielsen CATEGORY.......: Server-RawIdeaBin TASK ID........: 47 (http://askmonty.org/worklog/?tid=47) VERSION........: Server-9.x STATUS.........: Un-Assigned PRIORITY.......: 60 WORKED HOURS...: 20 ESTIMATE.......: 35 (hours remain) ORIG. ESTIMATE.: 35 PROGRESS NOTES: -=-=(Alexi - Thu, 04 Feb 2010, 09:54)=-=- Low Level Design modified. --- /tmp/wklog.47.old.16174 2010-02-04 09:54:13.000000000 +0200 +++ /tmp/wklog.47.new.16174 2010-02-04 09:54:13.000000000 +0200 @@ -171,35 +171,20 @@ 5. How slave IO thread requests Annotate_rows events ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~ -When requesting an event, the slave should inform the master whether -it should send Annotate_rows events or not. To that end we add a new -BINLOG_SEND_ANNOTATE_ROWS_EVENT flag used when requesting an event: +If the replicate-annotate-rows-events option is not set on a slave, there +is no need for master to send Annotate_rows events to this slave. The slave +(or mysqlbinlog in remote case), before requesting binlog dump via the +COM_BINLOG_DUMP command, informs the master whether it should send these +events by executing the newly added COM_BINLOG_DUMP_OPTIONS_EXT server +command: + + case COM_BINLOG_DUMP_OPTIONS_EXT: + thd->binlog_dump_flags_ext= packet[0]; + my_ok(thd); + break; - #define BINLOG_DUMP_NON_BLOCK 1 - #define BINLOG_SEND_ANNOTATE_ROWS_EVENT 2 - - pthread_handler_t handle_slave_io(void *arg) - { ... - request_dump(mysql, ...); - ... - } - - int request_dump(MYSQL* mysql, ...) - { ... - if (opt_log_slave_updates && - mi->io_thd->variables.binlog_annotate_rows_events) - binlog_flags|= BINLOG_SEND_ANNOTATE_ROWS_EVENT; - ... - int2store(buf + 4, binlog_flags); - ... - simple_command(mysql, COM_BINLOG_DUMP, buf, ...); - ... - } - -NOTE. mysqlbinlog, when remotely requesting BINLOG_DUMP by calling the -simple_command() function, should also use this flag if it wants (in case -of the --print-annotate-rows-events option set) to recieve Annotate_rows -events. +Note. We add this new command and don't use COM_BINLOG_DUMP to avoid possible +conflicts with MySQL/Sun. 6. How master executes the request ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~ @@ -338,10 +323,4 @@ to internals(a)lists.mysql.com about this and suggesting to reserve the event number. -Also we should notice the introduction of the BINLOG_SEND_ANNOTATE_ROWS_EVENT -flag taking into account that MySQL/Sun may also introduce a flag with the -same value to be used in the request_dump-mysql_binlog_send interface. -But this is mainly the question of merging: if a conflict concerning this -flag occur, we may simply change the BINLOG_SEND_ANNOTATE_ROWS_EVENT value -(this does not require additional changes in the code). -=-=(Alexi - Sun, 20 Dec 2009, 16:00)=-=- Low Level Design modified. --- /tmp/wklog.47.old.19667 2009-12-20 14:00:56.000000000 +0000 +++ /tmp/wklog.47.new.19667 2009-12-20 14:00:56.000000000 +0000 @@ -196,6 +196,11 @@ ... } +NOTE. mysqlbinlog, when remotely requesting BINLOG_DUMP by calling the +simple_command() function, should also use this flag if it wants (in case +of the --print-annotate-rows-events option set) to recieve Annotate_rows +events. + 6. How master executes the request ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~ @@ -212,8 +217,7 @@ Log_event::read_log_event(&log, packet, ...); ... if ((*packet)[EVENT_TYPE_OFFSET + 1] != ANNOTATE_ROWS_EVENT || - flags & BINLOG_SEND_ANNOTATE_ROWS_EVENT || - thd->server_id == 0 /* slave == mysqlbinlog */ ) + flags & BINLOG_SEND_ANNOTATE_ROWS_EVENT) { my_net_write(net, packet->ptr(), packet->length()); } -=-=(Alexi - Sun, 20 Dec 2009, 13:14)=-=- Low Level Design modified. --- /tmp/wklog.47.old.11350 2009-12-20 13:14:04.000000000 +0200 +++ /tmp/wklog.47.new.11350 2009-12-20 13:14:04.000000000 +0200 @@ -282,23 +282,18 @@ Annotate_rows_log_event* m_annotate_event; }; -When the saved Annotate_rows object may be deleted? When all corresponding -Rows events will be processed, i.e. before processing the first non-Rows -event (note that Annotate_rows object resides in the binary log *after* -the (possible) 'BEGIN' Query event which accompanies the rows events; note -also that this deletion is adjusted with the case when some or all -corresponding Rows events are filtered out by replicate filter rules): +The saved Annotate_rows object should be deleted when all corresponding +Rows events will be processed: int exec_relay_log_event(THD* thd, Relay_log_info* rli) { ... Log_event *ev= next_event(rli); ... - if (rli->get_annotate_event() && !IS_RBR_EVENT_TYPE(ev->get_type_code())) - rli->free_annotate_event(); - apply_event_and_update_pos(ev, ...); - if (ev->get_type_code() == ANNOTATE_ROWS_EVENT) + if (rli->get_annotate_event() && is_last_rows_event(ev)) + rli->free_annotate_event(); + else if (ev->get_type_code() == ANNOTATE_ROWS_EVENT) rli->set_annotate_event((Annotate_rows_log_event*) ev); else if (ev->get_type_code() != FORMAT_DESCRIPTION_EVENT) delete ev; @@ -307,10 +302,21 @@ where - #define IS_RBR_EVENT_TYPE(type) ( (type) == TABLE_MAP_EVENT || \ - (type) == WRITE_ROWS_EVENT || \ + bool is_last_rows_event(Log_event* ev) + { + Log_event_type type= ev->get_type_code(); + if (IS_ROWS_EVENT_TYPE(type)) + { + Rows_log_event* rows= (Rows_log_event*)ev; + return rows->get_flags(Rows_log_event::STMT_END_F); + } + + return 0; + } + + #define IS_ROWS_EVENT_TYPE(type) ((type) == WRITE_ROWS_EVENT || \ (type) == UPDATE_ROWS_EVENT || \ - (type) == DELETE_ROWS_EVENT ) + (type) == DELETE_ROWS_EVENT) 8. General remarks ~~~~~~~~~~~~~~~~~~ -=-=(Alexi - Sun, 20 Dec 2009, 09:29)=-=- Low Level Design modified. --- /tmp/wklog.47.old.32726 2009-12-20 07:29:56.000000000 +0000 +++ /tmp/wklog.47.new.32726 2009-12-20 07:29:56.000000000 +0000 @@ -56,7 +56,7 @@ 0000006A | 00 | 0 - RESERVED [27] ..... ... 00000081 | 00 | 0 - RESERVED [50] - 00000082 | 00 | 0 - ANNOTATE_RBR_EVENT [51] + 00000082 | 00 | 0 - ANNOTATE_ROWS_EVENT [51] ************************ 2. Outline of Annotate_rows event behavior -=-=(Alexi - Sat, 19 Dec 2009, 16:10)=-=- Low Level Design modified. --- /tmp/wklog.47.old.16051 2009-12-19 16:10:48.000000000 +0200 +++ /tmp/wklog.47.new.16051 2009-12-19 16:10:48.000000000 +0200 @@ -253,7 +253,7 @@ thd query to that of the described by the event, i.e. to the query which caused the subsequent Rows events (see "How Master writes Annotate_rows events to the binary log" to follow what happens further when the subsequent -Rows events is applied): +Rows events are applied): int Annotate_rows_log_event::do_apply_event(...) { -=-=(Alexi - Sat, 19 Dec 2009, 16:02)=-=- High-Level Specification modified. --- /tmp/wklog.47.old.15695 2009-12-19 16:02:33.000000000 +0200 +++ /tmp/wklog.47.new.15695 2009-12-19 16:02:33.000000000 +0200 @@ -12,7 +12,7 @@ post-header and contains the query text in its data part. Example: ************************ - ANNOTATE_RBR_EVENT + ANNOTATE_ROWS_EVENT ************************ 00000220 | B6 A0 2C 4B | time_when = 1261215926 00000224 | 33 | event_type = 51 -=-=(Alexi - Sat, 19 Dec 2009, 15:58)=-=- Low Level Design modified. --- /tmp/wklog.47.old.15437 2009-12-19 13:58:12.000000000 +0000 +++ /tmp/wklog.47.new.15437 2009-12-19 13:58:12.000000000 +0000 @@ -1 +1,337 @@ +Content +~~~~~~~ + 1. Annotate_rows event number + 2. Outline of Annotate_rows event behavior + 3. How Master writes Annotate_rows events to the binary log + 4. How slave treats replicate-annotate-rows-events option + 5. How slave IO thread requests Annotate_rows events + 6. How master executes the request + 7. How slave SQL thread processes Annotate_rows events + 8. General remarks + +1. Annotate_rows event number +~~~~~~~~~~~~~~~~~~~~~~~~~~~~~ +To avoid possible event numbers conflict with MySQL/Sun, we leave a gap +between the last MySQL event number and the Annotate_rows event number: + + enum Log_event_type + { ... + INCIDENT_EVENT= 26, + // New MySQL event numbers are to be added here + MYSQL_EVENTS_END, + + MARIA_EVENTS_BEGIN= 51, + // New Maria event numbers start from here + ANNOTATE_ROWS_EVENT= 51, + + ENUM_END_EVENT + }; + +together with the corresponding extension of 'post_header_len' array in the +Format description event. (This extension does not affect the compatibility +of the binary log). Here is how Format description event looks like with +this extension: + + ************************ + FORMAT_DESCRIPTION_EVENT + ************************ + 00000004 | A1 A0 2C 4B | time_when = 1261215905 + 00000008 | 0F | event_type = 15 + 00000009 | 64 00 00 00 | server_id = 100 + 0000000D | 7F 00 00 00 | event_len = 127 + 00000011 | 83 00 00 00 | log_pos = 00000083 + 00000015 | 01 00 | flags = LOG_EVENT_BINLOG_IN_USE_F + ------------------------ + 00000017 | 04 00 | binlog_ver = 4 + 00000019 | 35 2E 32 2E | server_ver = 5.2.0-MariaDB-alpha-debug-log + ..... ... + 0000004B | A1 A0 2C 4B | time_created = 1261215905 + 0000004F | 13 | common_header_len = 19 + ------------------------ + post_header_len + ------------------------ + 00000050 | 38 | 56 - START_EVENT_V3 [1] + ..... ... + 00000069 | 02 | 2 - INCIDENT_EVENT [26] + 0000006A | 00 | 0 - RESERVED [27] + ..... ... + 00000081 | 00 | 0 - RESERVED [50] + 00000082 | 00 | 0 - ANNOTATE_RBR_EVENT [51] + ************************ + +2. Outline of Annotate_rows event behavior +~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~ +Each Annotate_rows_log_event object has two private members describing the +corresponding query: + + char *m_query_txt; + uint m_query_len; + +When the object is created for writing to a binary log, this query is taken +from 'thd' (for short, below we omit the 'Annotate_rows_log_event::' prefix +as well as other implementation details): + + Annotate_rows_log_event(THD *thd) + { + m_query_txt = thd->query(); + m_query_len = thd->query_length(); + } + +When the object is read from a binary log, the query is taken from the buffer +containing the binary log representation of the event (this buffer is allocated +in Log_event object from which all Log events are derived): + + Annotate_rows_log_event(char *buf, uint event_len, + Format_description_log_event *desc) + { + m_query_len = event_len - desc->common_header_len; + m_query_txt = buf + desc->common_header_len; + } + +The events are written to the binary log by the Log_event::write() member +which calls virtual write_data_header() and write_data_body() members +("data header" and "post header" are synonym in replication terminology). +In our case, data header is empty and data body is just the query: + + bool write_data_body(IO_CACHE *file) + { + return my_b_safe_write(file, (uchar*) m_query_txt, m_query_len); + } + +Printing the event is just printing the query: + + void Annotate_rows_log_event::print(FILE *file, PRINT_EVENT_INFO *pinfo) + { + my_b_printf(&pinfo->head_cache, "\tQuery: `%s`\n", m_query_txt); + } + +3. How Master writes Annotate_rows events to the binary log +~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~ +The event is written to the binary log just before the group of Table_map +events which precede corresponding Rows events (one query may generate +several Table map events in the binary log, but the corresponding +Annotate_rows event must be written only once before the first Table map +event; hence the boolean variable 'with_annotate' below): + + int write_locked_table_maps(THD *thd) + { ... + bool with_annotate= thd->variables.binlog_annotate_rows_events; + ... + for (uint i= 0; i < ... <number of tables> ...; ++i) + { ... + thd->binlog_write_table_map(table, ..., with_annotate); + with_annotate= 0; // write Annotate_event not more than once + ... + } + ... + } + + int THD::binlog_write_table_map(TABLE *table, ..., bool with_annotate) + { ... + Table_map_log_event the_event(...); + ... + if (with_annotate) + { + Annotate_rows_log_event anno(this); + mysql_bin_log.write(&anno); + } + + mysql_bin_log.write(&the_event); + ... + } + +4. How slave treats replicate-annotate-rows-events option +~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~ +The replicate-annotate-rows-events option is treated just as the session +value of the binlog_annotate_rows_events variable for the slave IO and +SQL threads. This setting is done during initialization of these threads: + + pthread_handler_t handle_slave_io(void *arg) + { + THD *thd= new THD; + ... + init_slave_thread(thd, SLAVE_THD_IO); + ... + } + + pthread_handler_t handle_slave_sql(void *arg) + { + THD *thd= new THD; + ... + init_slave_thread(thd, SLAVE_THD_SQL); + ... + } + + int init_slave_thread(THD* thd, SLAVE_THD_TYPE thd_type) + { ... + thd->variables.binlog_annotate_rows_events= + opt_replicate_annotate_rows_events; + ... + } + +5. How slave IO thread requests Annotate_rows events +~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~ +When requesting an event, the slave should inform the master whether +it should send Annotate_rows events or not. To that end we add a new +BINLOG_SEND_ANNOTATE_ROWS_EVENT flag used when requesting an event: + + #define BINLOG_DUMP_NON_BLOCK 1 + #define BINLOG_SEND_ANNOTATE_ROWS_EVENT 2 + + pthread_handler_t handle_slave_io(void *arg) + { ... + request_dump(mysql, ...); + ... + } + + int request_dump(MYSQL* mysql, ...) + { ... + if (opt_log_slave_updates && + mi->io_thd->variables.binlog_annotate_rows_events) + binlog_flags|= BINLOG_SEND_ANNOTATE_ROWS_EVENT; + ... + int2store(buf + 4, binlog_flags); + ... + simple_command(mysql, COM_BINLOG_DUMP, buf, ...); + ... + } + +6. How master executes the request +~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~ + + case COM_BINLOG_DUMP: + { ... + flags= uint2korr(packet + 4); + ... + mysql_binlog_send(thd, ..., flags); + ... + } + + void mysql_binlog_send(THD* thd, ..., ushort flags) + { ... + Log_event::read_log_event(&log, packet, ...); + ... + if ((*packet)[EVENT_TYPE_OFFSET + 1] != ANNOTATE_ROWS_EVENT || + flags & BINLOG_SEND_ANNOTATE_ROWS_EVENT || + thd->server_id == 0 /* slave == mysqlbinlog */ ) + { + my_net_write(net, packet->ptr(), packet->length()); + } + ... + } + +7. How slave SQL thread processes Annotate_rows events +~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~ +The slave processes each recieved event by "applying" it, i.e. by +calling the Log_event::apply_event() function which in turn calls +the virtual do_apply_event() member specific for each type of the +event. + + int exec_relay_log_event(THD* thd, Relay_log_info* rli) + { ... + Log_event *ev = next_event(rli); + ... + apply_event_and_update_pos(ev, ...); + + if (ev->get_type_code() != FORMAT_DESCRIPTION_EVENT) + delete ev; + ... + } + + int apply_event_and_update_pos(Log_event *ev, ...) + { ... + ev->apply_event(...); + ... + } + + int Log_event::apply_event(...) + { + return do_apply_event(...); + } + +What does it mean to "apply" an Annotate_rows event? It means to set current +thd query to that of the described by the event, i.e. to the query which +caused the subsequent Rows events (see "How Master writes Annotate_rows +events to the binary log" to follow what happens further when the subsequent +Rows events is applied): + + int Annotate_rows_log_event::do_apply_event(...) + { + thd->set_query(m_query_txt, m_query_len); + } + +NOTE. I am not sure, but possibly current values of thd->query and +thd->query_length should be saved before calling set_query() and to be +restored on the Annotate_rows_log_event object deletion. +Is it really needed ? + +After calling this do_apply_event() function we may not delete the +Annotate_rows_log_event object immediatedly (see exec_relay_log_event() +above) because thd->query now points to the string inside this object. +We may keep the pointer to this object in the Relay_log_info: + + class Relay_log_info + { + public: + ... + void set_annotate_event(Annotate_rows_log_event*); + Annotate_rows_log_event* get_annotate_event(); + void free_annotate_event(); + ... + private: + Annotate_rows_log_event* m_annotate_event; + }; + +When the saved Annotate_rows object may be deleted? When all corresponding +Rows events will be processed, i.e. before processing the first non-Rows +event (note that Annotate_rows object resides in the binary log *after* +the (possible) 'BEGIN' Query event which accompanies the rows events; note +also that this deletion is adjusted with the case when some or all +corresponding Rows events are filtered out by replicate filter rules): + + int exec_relay_log_event(THD* thd, Relay_log_info* rli) + { ... + Log_event *ev= next_event(rli); + ... + if (rli->get_annotate_event() && !IS_RBR_EVENT_TYPE(ev->get_type_code())) + rli->free_annotate_event(); + + apply_event_and_update_pos(ev, ...); + + if (ev->get_type_code() == ANNOTATE_ROWS_EVENT) + rli->set_annotate_event((Annotate_rows_log_event*) ev); + else if (ev->get_type_code() != FORMAT_DESCRIPTION_EVENT) + delete ev; + ... + } + +where + + #define IS_RBR_EVENT_TYPE(type) ( (type) == TABLE_MAP_EVENT || \ + (type) == WRITE_ROWS_EVENT || \ + (type) == UPDATE_ROWS_EVENT || \ + (type) == DELETE_ROWS_EVENT ) + +8. General remarks +~~~~~~~~~~~~~~~~~~ +Kristian noticed that introducing new log event type should be coordinated +somehow with MySQL/Sun: + + Kristian: The numeric code for this event must be assigned carefully. + It should be coordinated with MySQL/Sun, otherwise we can get into a + situation where MySQL uses the same numeric code for one event that + MariaDB uses for ANNOTATE_ROWS_EVENT, which would make merging the two + impossible. + Alex: I reserved about 20 numbers not to have possible conflicts + with MySQL. + Kristian: Still, I think it would be appropriate to send a polite email + to internals(a)lists.mysql.com about this and suggesting to reserve the + event number. + +Also we should notice the introduction of the BINLOG_SEND_ANNOTATE_ROWS_EVENT +flag taking into account that MySQL/Sun may also introduce a flag with the +same value to be used in the request_dump-mysql_binlog_send interface. +But this is mainly the question of merging: if a conflict concerning this +flag occur, we may simply change the BINLOG_SEND_ANNOTATE_ROWS_EVENT value +(this does not require additional changes in the code). -=-=(Alexi - Sat, 19 Dec 2009, 15:41)=-=- High-Level Specification modified. --- /tmp/wklog.47.old.14545 2009-12-19 15:41:21.000000000 +0200 +++ /tmp/wklog.47.new.14545 2009-12-19 15:41:21.000000000 +0200 @@ -1,122 +1,107 @@ -First suggestion: - -> I think for this we would actually need a new binlog event type -> (Comment_log_event?). Unless we want to log an empty statement Query_log_event -> containing only a comment (a bit of a hack). - -New server option -~~~~~~~~~~~~~~~~~ - --binlog-annotate-rows-events - -Setting this option makes RBR (rows-) events in the binary log to be -preceded by Annotate rows events (see below). The corresponding -'binlog_annotate_rows_events' system variable is dynamic and has both -global and session values. Default global value is OFF. - -Note. Session values are usefull to make it possible to annotate only - some selected statements: +Content +~~~~~~~ + 1. Annotate_rows_log_event + 2. Server option: --binlog-annotate-rows-events + 3. Server option: --replicate-annotate-rows-events + 4. mysqlbinlog option: --print-annotate-rows-events + 5. mysqlbinlog output + +1. Annotate_rows_log_event [ ANNOTATE_ROWS_EVENT ] +~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~ +Describes the query which caused the corresponding rows events. Has empty +post-header and contains the query text in its data part. Example: + + ************************ + ANNOTATE_RBR_EVENT + ************************ + 00000220 | B6 A0 2C 4B | time_when = 1261215926 + 00000224 | 33 | event_type = 51 + 00000225 | 64 00 00 00 | server_id = 100 + 00000229 | 36 00 00 00 | event_len = 54 + 0000022D | 56 02 00 00 | log_pos = 00000256 + 00000231 | 00 00 | flags = <none> + ------------------------ + 00000233 | 49 4E 53 45 | query = "INSERT INTO t1 VALUES (1), (2), (3)" + 00000237 | 52 54 20 49 | + 0000023B | 4E 54 4F 20 | + 0000023F | 74 31 20 56 | + 00000243 | 41 4C 55 45 | + 00000247 | 53 20 28 31 | + 0000024B | 29 2C 20 28 | + 0000024F | 32 29 2C 20 | + 00000253 | 28 33 29 | + ************************ + +In binary log, Annotate_rows event follows the (possible) 'BEGIN' Query event +and precedes the first of Table map events which accompany the corresponding +rows events. (See example in the "mysqlbinlog output" section below.) + +2. Server option: --binlog-annotate-rows-events +~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~ +Tells the master to write Annotate_rows events to the binary log. + + * Variable Name: binlog_annotate_rows_events + * Scope: Global & Session + * Access Type: Dynamic + * Data Type: bool + * Default Value: OFF +NOTE. Session values allows to annotate only some selected statements: ... SET SESSION binlog_annotate_rows_events=ON; ... statements to be annotated ... SET SESSION binlog_annotate_rows_events=OFF; ... statements not to be annotated ... -New binlog event type -~~~~~~~~~~~~~~~~~~~~~ - Annotate_rows_log_event [ ANNOTATE_ROWS_EVENT ] - -Describes the query which caused the corresponding rows event. In binary log, -precedes each Table_map_log_event. Contains empty post-header and the query -text in its data part. - -The numeric code for this event must be assigned carefully. It should be -coordinated with MySQL/Sun, otherwise we can get into a situation where MySQL -uses the same numeric code for one event that MariaDB uses for -ANNOTATE_ROWS_EVENT, which would make merging the two impossible. - -Example: - - ... - ************************ - ANNOTATE_ROWS_EVENT [51] - ************************ - 000000C7 | 54 1B 12 4B | time_when = 1259477844 - 000000CB | 33 | event_type = 51 - 000000CC | 64 00 00 00 | server_id = 100 - 000000D0 | 2C 00 00 00 | event_len = 44 - 000000D4 | F3 00 00 00 | log_pos = 000000F3 - 000000D8 | 00 00 | flags = <none> - ------------------------ - 000000DA | 69 6E 73 65 | query = "insert into t1 values (1)" - 000000DE | 72 74 20 69 | - 000000E2 | 6E 74 6F 20 | - 000000E6 | 74 31 20 76 | - 000000EA | 61 6C 75 65 | - 000000EE | 73 20 28 31 | - 000000F2 | 29 | - ************************ - TABLE_MAP_EVENT [19] - ************************ - 000000F3 | 54 1B 12 4B | time_when = 1259477844 - 000000F7 | 13 | event_type = 19 - 000000F8 | 64 00 00 00 | server_id = 100 - 000000FC | 29 00 00 00 | event_len = 41 - 00000100 | 1C 01 00 00 | log_pos = 0000011C - 00000104 | 00 00 | flags = <none> - ------------------------ - ... - ************************ - WRITE_ROWS_EVENT [23] - ************************ - 0000011C | 54 1B 12 4B | time_when = 1259477844 - 00000120 | 17 | event_type = 23 - 00000121 | 64 00 00 00 | server_id = 100 - 00000125 | 22 00 00 00 | event_len = 34 - 00000129 | 3E 01 00 00 | log_pos = 0000013E - 0000012D | 10 00 | flags = LOG_EVENT_UPDATE_TABLE_MAP_VERSION_F - ------------------------ - 0000012F | 0F 00 00 00 | table_id = 15 - ... - -New mysqlbinlog option -~~~~~~~~~~~~~~~~~~~~~~ - --print-annotate-rows-events - -With this option, mysqlbinlog prints the content of Annotate-rows -events (if the binary log does contain them). Without this option -(i.e. by default), mysqlbinlog skips Annotate rows events. - - -mysqlbinlog output -~~~~~~~~~~~~~~~~~~ -Something like this: +3. Server option: --replicate-annotate-rows-events +~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~ +Tells the slave to reproduce Annotate_rows events recieved from the master +in its own binary log (sensible only in pair with log-slave-updates option). + + * Variable Name: replicate_annotate_rows_events + * Scope: Global + * Access Type: Read only + * Data Type: bool + * Default Value: OFF + +NOTE. Why do we additionally need this 'replicate' option? Why not to make +the slave to reproduce this events when its binlog-annotate-rows-events +global value is ON? Well, because, for example, we may want to configure +the slave which should reproduce Annotate_rows events but has global +binlog-annotate-rows-events = OFF meaning this to be the default value for +the client threads (see also "How slave treats replicate-annotate-rows-events +option" in LLD part). + +4. mysqlbinlog option: --print-annotate-rows-events +~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~ +With this option, mysqlbinlog prints the content of Annotate_rows events (if +the binary log does contain them). Without this option (i.e. by default), +mysqlbinlog skips Annotate_rows events. +5. mysqlbinlog output +~~~~~~~~~~~~~~~~~~~~~ +With --print-annotate-rows-events, mysqlbinlog outputs Annotate_rows events +in a form like this: ... - # at 199 - # at 243 - # at 284 - #091129 9:57:24 server id 100 end_log_pos 243 Query: `insert into t1 values -(1)` - #091129 9:57:24 server id 100 end_log_pos 284 Table_map: `test`.`t1` mapped -to number 15 - #091129 9:57:24 server id 100 end_log_pos 318 Write_rows: table id 15 + # at 1646 + #091219 12:45:26 server id 100 end_log_pos 1714 Query thread_id=1 +exec_time=0 error_code=0 + SET TIMESTAMP=1261215926/*!*/; + BEGIN + /*!*/; + # at 1714 + # at 1812 + # at 1853 + # at 1894 + # at 1938 + #091219 12:45:26 server id 100 end_log_pos 1812 Query: `DELETE t1, t2 FROM +t1 INNER JOIN t2 INNER JOIN t3 WHERE t1.a=t2.a AND t2.a=t3.a` + #091219 12:45:26 server id 100 end_log_pos 1853 Table_map: `test`.`t1` +mapped to number 16 + #091219 12:45:26 server id 100 end_log_pos 1894 Table_map: `test`.`t2` +mapped to number 17 + #091219 12:45:26 server id 100 end_log_pos 1938 Delete_rows: table id 16 + #091219 12:45:26 server id 100 end_log_pos 1982 Delete_rows: table id 17 flags: STMT_END_F - - BINLOG ' - VBsSSzNkAAAALAAAAPMAAAAAAGluc2VydCBpbnRvIHQxIHZhbHVlcyAoMSk= - VBsSSxNkAAAAKQAAABwBAAAAAA8AAAAAAAAABHRlc3QAAnQxAAEDAAE= - VBsSSxdkAAAAIgAAAD4BAAAQAA8AAAAAAAEAAf/+AQAAAA== - '/*!*/; - ### INSERT INTO test.t1 - ### SET - ### @1=1 /* INT meta=0 nullable=1 is_null=0 */ ... -When master sends Annotate rows events -~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~ -1. Master always sends Annotate_rows events to mysqlbinlog (in - remote case). -2. Master sends Annotate_rows events to a slave only if the slave has - both log-slave-updates and binlog-annotate-rows-events options set. - -=-=(Bothorsen - Fri, 18 Dec 2009, 16:22)=-=- Add estimation time. Worked 5 hours and estimate 35 hours remain (original estimate increased by 5 hours). -=-=(Bothorsen - Fri, 18 Dec 2009, 16:16)=-=- This is the work done on this patch so far. Most of it done by Alex. Worked 15 hours and estimate 035 hours remain (original estimate increased by 50 hours). ------------------------------------------------------------ -=-=(View All Progress Notes, 20 total)=-=- http://askmonty.org/worklog/index.pl?tid=47&nolimit=1 DESCRIPTION: Store in binlog (and show in mysqlbinlog output) texts of statements that caused RBR events This is needed for (list from Monty): - Easier to understand why updates happened - Would make it easier to find out where in application things went wrong (as you can search for exact strings) - Allow one to filter things based on comments in the statement. The cost of this can be that the binlog will be approximately 2x in size (especially insert of big blob's would be a bit painful), so this should be an optional feature. HIGH-LEVEL SPECIFICATION: Content ~~~~~~~ 1. Annotate_rows_log_event 2. Server option: --binlog-annotate-rows-events 3. Server option: --replicate-annotate-rows-events 4. mysqlbinlog option: --print-annotate-rows-events 5. mysqlbinlog output 1. Annotate_rows_log_event [ ANNOTATE_ROWS_EVENT ] ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~ Describes the query which caused the corresponding rows events. Has empty post-header and contains the query text in its data part. Example: ************************ ANNOTATE_ROWS_EVENT ************************ 00000220 | B6 A0 2C 4B | time_when = 1261215926 00000224 | 33 | event_type = 51 00000225 | 64 00 00 00 | server_id = 100 00000229 | 36 00 00 00 | event_len = 54 0000022D | 56 02 00 00 | log_pos = 00000256 00000231 | 00 00 | flags = <none> ------------------------ 00000233 | 49 4E 53 45 | query = "INSERT INTO t1 VALUES (1), (2), (3)" 00000237 | 52 54 20 49 | 0000023B | 4E 54 4F 20 | 0000023F | 74 31 20 56 | 00000243 | 41 4C 55 45 | 00000247 | 53 20 28 31 | 0000024B | 29 2C 20 28 | 0000024F | 32 29 2C 20 | 00000253 | 28 33 29 | ************************ In binary log, Annotate_rows event follows the (possible) 'BEGIN' Query event and precedes the first of Table map events which accompany the corresponding rows events. (See example in the "mysqlbinlog output" section below.) 2. Server option: --binlog-annotate-rows-events ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~ Tells the master to write Annotate_rows events to the binary log. * Variable Name: binlog_annotate_rows_events * Scope: Global & Session * Access Type: Dynamic * Data Type: bool * Default Value: OFF NOTE. Session values allows to annotate only some selected statements: ... SET SESSION binlog_annotate_rows_events=ON; ... statements to be annotated ... SET SESSION binlog_annotate_rows_events=OFF; ... statements not to be annotated ... 3. Server option: --replicate-annotate-rows-events ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~ Tells the slave to reproduce Annotate_rows events recieved from the master in its own binary log (sensible only in pair with log-slave-updates option). * Variable Name: replicate_annotate_rows_events * Scope: Global * Access Type: Read only * Data Type: bool * Default Value: OFF NOTE. Why do we additionally need this 'replicate' option? Why not to make the slave to reproduce this events when its binlog-annotate-rows-events global value is ON? Well, because, for example, we may want to configure the slave which should reproduce Annotate_rows events but has global binlog-annotate-rows-events = OFF meaning this to be the default value for the client threads (see also "How slave treats replicate-annotate-rows-events option" in LLD part). 4. mysqlbinlog option: --print-annotate-rows-events ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~ With this option, mysqlbinlog prints the content of Annotate_rows events (if the binary log does contain them). Without this option (i.e. by default), mysqlbinlog skips Annotate_rows events. 5. mysqlbinlog output ~~~~~~~~~~~~~~~~~~~~~ With --print-annotate-rows-events, mysqlbinlog outputs Annotate_rows events in a form like this: ... # at 1646 #091219 12:45:26 server id 100 end_log_pos 1714 Query thread_id=1 exec_time=0 error_code=0 SET TIMESTAMP=1261215926/*!*/; BEGIN /*!*/; # at 1714 # at 1812 # at 1853 # at 1894 # at 1938 #091219 12:45:26 server id 100 end_log_pos 1812 Query: `DELETE t1, t2 FROM t1 INNER JOIN t2 INNER JOIN t3 WHERE t1.a=t2.a AND t2.a=t3.a` #091219 12:45:26 server id 100 end_log_pos 1853 Table_map: `test`.`t1` mapped to number 16 #091219 12:45:26 server id 100 end_log_pos 1894 Table_map: `test`.`t2` mapped to number 17 #091219 12:45:26 server id 100 end_log_pos 1938 Delete_rows: table id 16 #091219 12:45:26 server id 100 end_log_pos 1982 Delete_rows: table id 17 flags: STMT_END_F ... LOW-LEVEL DESIGN: Content ~~~~~~~ 1. Annotate_rows event number 2. Outline of Annotate_rows event behavior 3. How Master writes Annotate_rows events to the binary log 4. How slave treats replicate-annotate-rows-events option 5. How slave IO thread requests Annotate_rows events 6. How master executes the request 7. How slave SQL thread processes Annotate_rows events 8. General remarks 1. Annotate_rows event number ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~ To avoid possible event numbers conflict with MySQL/Sun, we leave a gap between the last MySQL event number and the Annotate_rows event number: enum Log_event_type { ... INCIDENT_EVENT= 26, // New MySQL event numbers are to be added here MYSQL_EVENTS_END, MARIA_EVENTS_BEGIN= 51, // New Maria event numbers start from here ANNOTATE_ROWS_EVENT= 51, ENUM_END_EVENT }; together with the corresponding extension of 'post_header_len' array in the Format description event. (This extension does not affect the compatibility of the binary log). Here is how Format description event looks like with this extension: ************************ FORMAT_DESCRIPTION_EVENT ************************ 00000004 | A1 A0 2C 4B | time_when = 1261215905 00000008 | 0F | event_type = 15 00000009 | 64 00 00 00 | server_id = 100 0000000D | 7F 00 00 00 | event_len = 127 00000011 | 83 00 00 00 | log_pos = 00000083 00000015 | 01 00 | flags = LOG_EVENT_BINLOG_IN_USE_F ------------------------ 00000017 | 04 00 | binlog_ver = 4 00000019 | 35 2E 32 2E | server_ver = 5.2.0-MariaDB-alpha-debug-log ..... ... 0000004B | A1 A0 2C 4B | time_created = 1261215905 0000004F | 13 | common_header_len = 19 ------------------------ post_header_len ------------------------ 00000050 | 38 | 56 - START_EVENT_V3 [1] ..... ... 00000069 | 02 | 2 - INCIDENT_EVENT [26] 0000006A | 00 | 0 - RESERVED [27] ..... ... 00000081 | 00 | 0 - RESERVED [50] 00000082 | 00 | 0 - ANNOTATE_ROWS_EVENT [51] ************************ 2. Outline of Annotate_rows event behavior ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~ Each Annotate_rows_log_event object has two private members describing the corresponding query: char *m_query_txt; uint m_query_len; When the object is created for writing to a binary log, this query is taken from 'thd' (for short, below we omit the 'Annotate_rows_log_event::' prefix as well as other implementation details): Annotate_rows_log_event(THD *thd) { m_query_txt = thd->query(); m_query_len = thd->query_length(); } When the object is read from a binary log, the query is taken from the buffer containing the binary log representation of the event (this buffer is allocated in Log_event object from which all Log events are derived): Annotate_rows_log_event(char *buf, uint event_len, Format_description_log_event *desc) { m_query_len = event_len - desc->common_header_len; m_query_txt = buf + desc->common_header_len; } The events are written to the binary log by the Log_event::write() member which calls virtual write_data_header() and write_data_body() members ("data header" and "post header" are synonym in replication terminology). In our case, data header is empty and data body is just the query: bool write_data_body(IO_CACHE *file) { return my_b_safe_write(file, (uchar*) m_query_txt, m_query_len); } Printing the event is just printing the query: void Annotate_rows_log_event::print(FILE *file, PRINT_EVENT_INFO *pinfo) { my_b_printf(&pinfo->head_cache, "\tQuery: `%s`\n", m_query_txt); } 3. How Master writes Annotate_rows events to the binary log ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~ The event is written to the binary log just before the group of Table_map events which precede corresponding Rows events (one query may generate several Table map events in the binary log, but the corresponding Annotate_rows event must be written only once before the first Table map event; hence the boolean variable 'with_annotate' below): int write_locked_table_maps(THD *thd) { ... bool with_annotate= thd->variables.binlog_annotate_rows_events; ... for (uint i= 0; i < ... <number of tables> ...; ++i) { ... thd->binlog_write_table_map(table, ..., with_annotate); with_annotate= 0; // write Annotate_event not more than once ... } ... } int THD::binlog_write_table_map(TABLE *table, ..., bool with_annotate) { ... Table_map_log_event the_event(...); ... if (with_annotate) { Annotate_rows_log_event anno(this); mysql_bin_log.write(&anno); } mysql_bin_log.write(&the_event); ... } 4. How slave treats replicate-annotate-rows-events option ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~ The replicate-annotate-rows-events option is treated just as the session value of the binlog_annotate_rows_events variable for the slave IO and SQL threads. This setting is done during initialization of these threads: pthread_handler_t handle_slave_io(void *arg) { THD *thd= new THD; ... init_slave_thread(thd, SLAVE_THD_IO); ... } pthread_handler_t handle_slave_sql(void *arg) { THD *thd= new THD; ... init_slave_thread(thd, SLAVE_THD_SQL); ... } int init_slave_thread(THD* thd, SLAVE_THD_TYPE thd_type) { ... thd->variables.binlog_annotate_rows_events= opt_replicate_annotate_rows_events; ... } 5. How slave IO thread requests Annotate_rows events ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~ If the replicate-annotate-rows-events option is not set on a slave, there is no need for master to send Annotate_rows events to this slave. The slave (or mysqlbinlog in remote case), before requesting binlog dump via the COM_BINLOG_DUMP command, informs the master whether it should send these events by executing the newly added COM_BINLOG_DUMP_OPTIONS_EXT server command: case COM_BINLOG_DUMP_OPTIONS_EXT: thd->binlog_dump_flags_ext= packet[0]; my_ok(thd); break; Note. We add this new command and don't use COM_BINLOG_DUMP to avoid possible conflicts with MySQL/Sun. 6. How master executes the request ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~ case COM_BINLOG_DUMP: { ... flags= uint2korr(packet + 4); ... mysql_binlog_send(thd, ..., flags); ... } void mysql_binlog_send(THD* thd, ..., ushort flags) { ... Log_event::read_log_event(&log, packet, ...); ... if ((*packet)[EVENT_TYPE_OFFSET + 1] != ANNOTATE_ROWS_EVENT || flags & BINLOG_SEND_ANNOTATE_ROWS_EVENT) { my_net_write(net, packet->ptr(), packet->length()); } ... } 7. How slave SQL thread processes Annotate_rows events ~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~ The slave processes each recieved event by "applying" it, i.e. by calling the Log_event::apply_event() function which in turn calls the virtual do_apply_event() member specific for each type of the event. int exec_relay_log_event(THD* thd, Relay_log_info* rli) { ... Log_event *ev = next_event(rli); ... apply_event_and_update_pos(ev, ...); if (ev->get_type_code() != FORMAT_DESCRIPTION_EVENT) delete ev; ... } int apply_event_and_update_pos(Log_event *ev, ...) { ... ev->apply_event(...); ... } int Log_event::apply_event(...) { return do_apply_event(...); } What does it mean to "apply" an Annotate_rows event? It means to set current thd query to that of the described by the event, i.e. to the query which caused the subsequent Rows events (see "How Master writes Annotate_rows events to the binary log" to follow what happens further when the subsequent Rows events are applied): int Annotate_rows_log_event::do_apply_event(...) { thd->set_query(m_query_txt, m_query_len); } NOTE. I am not sure, but possibly current values of thd->query and thd->query_length should be saved before calling set_query() and to be restored on the Annotate_rows_log_event object deletion. Is it really needed ? After calling this do_apply_event() function we may not delete the Annotate_rows_log_event object immediatedly (see exec_relay_log_event() above) because thd->query now points to the string inside this object. We may keep the pointer to this object in the Relay_log_info: class Relay_log_info { public: ... void set_annotate_event(Annotate_rows_log_event*); Annotate_rows_log_event* get_annotate_event(); void free_annotate_event(); ... private: Annotate_rows_log_event* m_annotate_event; }; The saved Annotate_rows object should be deleted when all corresponding Rows events will be processed: int exec_relay_log_event(THD* thd, Relay_log_info* rli) { ... Log_event *ev= next_event(rli); ... apply_event_and_update_pos(ev, ...); if (rli->get_annotate_event() && is_last_rows_event(ev)) rli->free_annotate_event(); else if (ev->get_type_code() == ANNOTATE_ROWS_EVENT) rli->set_annotate_event((Annotate_rows_log_event*) ev); else if (ev->get_type_code() != FORMAT_DESCRIPTION_EVENT) delete ev; ... } where bool is_last_rows_event(Log_event* ev) { Log_event_type type= ev->get_type_code(); if (IS_ROWS_EVENT_TYPE(type)) { Rows_log_event* rows= (Rows_log_event*)ev; return rows->get_flags(Rows_log_event::STMT_END_F); } return 0; } #define IS_ROWS_EVENT_TYPE(type) ((type) == WRITE_ROWS_EVENT || \ (type) == UPDATE_ROWS_EVENT || \ (type) == DELETE_ROWS_EVENT) 8. General remarks ~~~~~~~~~~~~~~~~~~ Kristian noticed that introducing new log event type should be coordinated somehow with MySQL/Sun: Kristian: The numeric code for this event must be assigned carefully. It should be coordinated with MySQL/Sun, otherwise we can get into a situation where MySQL uses the same numeric code for one event that MariaDB uses for ANNOTATE_ROWS_EVENT, which would make merging the two impossible. Alex: I reserved about 20 numbers not to have possible conflicts with MySQL. Kristian: Still, I think it would be appropriate to send a polite email to internals(a)lists.mysql.com about this and suggesting to reserve the event number. ESTIMATED WORK TIME ESTIMATED COMPLETION DATE ----------------------------------------------------------------------- WorkLog (v3.5.9)

1 0

[Maria-developers] SHOW PROFILE enhancements for Windows
by Alex Budovski 04 Feb '10

04 Feb '10

Hi, I've implemented a few things for the Windows port of SHOW PROFILE ( IO read/writes, user/kernel times, page faults) which you may want to consider looking at. There's also a few miscellaneous fixes in there. The commit log has the details. See: https://launchpad.net/~abudovski/maria/robust Thanks.

2 7

[Maria-developers] Rev 7: Added make install and enabled system tables as requested by Monty. in file:///Users/hakan/work/monty_program/mariadb-tools/
by Hakan Kuecuekyilmaz 04 Feb '10

04 Feb '10

At file:///Users/hakan/work/monty_program/mariadb-tools/ ------------------------------------------------------------ revno: 7 revision-id: hakan(a)askmonty.org-20100204011956-u74a4es6oogvd50w parent: hakan(a)askmonty.org-20100115142922-bgc032k180y2i29r committer: Hakan Kuecuekyilmaz <hakan(a)askmonty.org> branch nick: mariadb-tools timestamp: Thu 2010-02-04 02:19:56 +0100 message: Added make install and enabled system tables as requested by Monty. === modified file 'sql-bench/run-sql-bench.sh' --- a/sql-bench/run-sql-bench.sh 2010-01-12 12:42:59 +0000 +++ b/sql-bench/run-sql-bench.sh 2010-02-04 01:19:56 +0000 @@ -51,7 +51,8 @@ # Binaries. # BZR='/usr/local/bin/bzr' -MYSQLADMIN='client/mysqladmin' +#BZR='/usr/bin/bzr' +MYSQLADMIN='bin/mysqladmin' # # Check system. @@ -139,7 +140,9 @@ exit 1 fi - ./configure $MARIADB_CONFIG + # We need --prefix for running make install. Otherwise + # mysql_install_db does not work properly. + ./configure $MARIADB_CONFIG --prefix=${TEMP_DIR}/install if [ $? != 0 ]; then echo "[ERROR]: ./configure $MARIADB_CONFIG failed." echo " Please check your MARIADB_CONFIG in $i." @@ -157,10 +160,24 @@ exit 1 fi + make install + if [ $? != 0 ]; then + echo '[ERROR]: make install.' + echo ' Please check your build logs.' + echo 'Exiting.' + + exit 1 + fi + + cd ${TEMP_DIR}/install + + # Install system tables. + bin/mysql_install_db --no-defaults --basedir=${TEMP_DIR}/install --datadir=${TEMP_DIR}/data + # Start mysqld. MARIADB_SOCKET="${TEMP_DIR}/mysql.sock" MARIADB_OPTIONS="$MARIADB_OPTIONS \ - --datadir=$TEMP_DIR \ + --datadir=${TEMP_DIR}/data \ --tmpdir=$TEMP_DIR \ --socket=$MARIADB_SOCKET" @@ -168,10 +185,10 @@ --socket=$MARIADB_SOCKET" # Determine mysqld version for result file naming. - MARIADB_VERSION=$(sql/mysqld --version | awk '{ print $3 }') + MARIADB_VERSION=$(libexec/mysqld --version | awk '{ print $3 }') SUFFIX="$SUFFIX"-"$MARIADB_VERSION" - sql/mysqld $MARIADB_OPTIONS & + libexec/mysqld $MARIADB_OPTIONS & j=0 STARTED=-1 @@ -196,15 +213,6 @@ exit 1 fi - $MYSQLADMIN $MYSQLADMIN_OPTIONS create test - if [ $? != 0 ]; then - echo '[ERROR]: Create schema test failed.' - echo ' Please check your mysqld error log.' - echo 'Exiting.' - - exit 1 - fi - # Run sql-bench. cd sql-bench COMMENTS="Revision used: $REVISION_ID \ === modified file 'sql-bench/sql-bench-configurations/sql-bench-default-config.inc' --- a/sql-bench/sql-bench-configurations/sql-bench-default-config.inc 2009-12-29 13:42:53 +0000 +++ b/sql-bench/sql-bench-configurations/sql-bench-default-config.inc 2010-02-04 01:19:56 +0000 @@ -16,11 +16,9 @@ # # Options for starting mysqld. # -# Attention: Do not set --datadir, --tmpdir, and --socket. +# Attention: Do not set --datadir, --tmpdir, nor --socket. # -export MARIADB_OPTIONS="--no-defaults \ - --skip-grant-tables \ - --language=./sql/share/english" +export MARIADB_OPTIONS="--no-defaults" # # Options for sql-bench.

1 0

[Maria-developers] Rev 7: Added make install and enabled system tables. in file:///Users/hakan/work/monty_program/mariadb-tools/
by Hakan Kuecuekyilmaz 04 Feb '10

04 Feb '10

At file:///Users/hakan/work/monty_program/mariadb-tools/ ------------------------------------------------------------ revno: 7 revision-id: hakan(a)askmonty.org-20100204011810-rqj1ikb41773p0au parent: hakan(a)askmonty.org-20100115142922-bgc032k180y2i29r committer: Hakan Kuecuekyilmaz <hakan(a)askmonty.org> branch nick: mariadb-tools timestamp: Thu 2010-02-04 02:18:10 +0100 message: Added make install and enabled system tables. === modified file 'sql-bench/run-sql-bench.sh' --- a/sql-bench/run-sql-bench.sh 2010-01-12 12:42:59 +0000 +++ b/sql-bench/run-sql-bench.sh 2010-02-04 01:18:10 +0000 @@ -50,8 +50,9 @@ # # Binaries. # -BZR='/usr/local/bin/bzr' -MYSQLADMIN='client/mysqladmin' +#BZR='/usr/local/bin/bzr' +BZR='/usr/bin/bzr' +MYSQLADMIN='bin/mysqladmin' # # Check system. @@ -139,7 +140,9 @@ exit 1 fi - ./configure $MARIADB_CONFIG + # We need --prefix for running make install. Otherwise + # mysql_install_db does not work properly. + ./configure $MARIADB_CONFIG --prefix=${TEMP_DIR}/install if [ $? != 0 ]; then echo "[ERROR]: ./configure $MARIADB_CONFIG failed." echo " Please check your MARIADB_CONFIG in $i." @@ -157,10 +160,24 @@ exit 1 fi + make install + if [ $? != 0 ]; then + echo '[ERROR]: make install.' + echo ' Please check your build logs.' + echo 'Exiting.' + + exit 1 + fi + + cd ${TEMP_DIR}/install + + # Install system tables. + bin/mysql_install_db --no-defaults --basedir=${TEMP_DIR}/install --datadir=${TEMP_DIR}/data + # Start mysqld. MARIADB_SOCKET="${TEMP_DIR}/mysql.sock" MARIADB_OPTIONS="$MARIADB_OPTIONS \ - --datadir=$TEMP_DIR \ + --datadir=${TEMP_DIR}/data \ --tmpdir=$TEMP_DIR \ --socket=$MARIADB_SOCKET" @@ -168,10 +185,10 @@ --socket=$MARIADB_SOCKET" # Determine mysqld version for result file naming. - MARIADB_VERSION=$(sql/mysqld --version | awk '{ print $3 }') + MARIADB_VERSION=$(libexec/mysqld --version | awk '{ print $3 }') SUFFIX="$SUFFIX"-"$MARIADB_VERSION" - sql/mysqld $MARIADB_OPTIONS & + libexec/mysqld $MARIADB_OPTIONS & j=0 STARTED=-1 @@ -196,15 +213,6 @@ exit 1 fi - $MYSQLADMIN $MYSQLADMIN_OPTIONS create test - if [ $? != 0 ]; then - echo '[ERROR]: Create schema test failed.' - echo ' Please check your mysqld error log.' - echo 'Exiting.' - - exit 1 - fi - # Run sql-bench. cd sql-bench COMMENTS="Revision used: $REVISION_ID \ === modified file 'sql-bench/sql-bench-configurations/sql-bench-default-config.inc' --- a/sql-bench/sql-bench-configurations/sql-bench-default-config.inc 2009-12-29 13:42:53 +0000 +++ b/sql-bench/sql-bench-configurations/sql-bench-default-config.inc 2010-02-04 01:18:10 +0000 @@ -16,11 +16,9 @@ # # Options for starting mysqld. # -# Attention: Do not set --datadir, --tmpdir, and --socket. +# Attention: Do not set --datadir, --tmpdir, nor --socket. # -export MARIADB_OPTIONS="--no-defaults \ - --skip-grant-tables \ - --language=./sql/share/english" +export MARIADB_OPTIONS="--no-defaults" # # Options for sql-bench.

1 0

[Maria-developers] [psergey@askmonty.org: Rev 2750: BUG#31480: Incorrect result for nested subquery when executed via semi join: in file:///home/psergey/dev/maria-5.3-subqueries-r3/]
by Sergey Petrunya 02 Feb '10

02 Feb '10

Hello Igor, I believe that the following patch has the property that item_subselect->update_used_tables() will handle table-bit re-assignments, i.e. it is what we have discussed earlier today. I've also pushed this into 5.3-sj-subqueries tree. ----- Forwarded message from Sergey Petrunya <psergey(a)askmonty.org> ----- From: Sergey Petrunya <psergey(a)askmonty.org> To: maria-developers(a)lists.launchpad.net X-Mailer: mail (GNU Mailutils 1.2) Date: Tue, 2 Feb 2010 23:00:49 +0300 (MSK) Subject: [Maria-developers] Rev 2750: BUG#31480: Incorrect result for nested subquery when executed via semi join: in file:///home/psergey/dev/maria-5.3-subqueries-r3/ At file:///home/psergey/dev/maria-5.3-subqueries-r3/ ------------------------------------------------------------ revno: 2750 revision-id: psergey(a)askmonty.org-20100202200045-13q0nb5dwzm739j6 parent: psergey(a)askmonty.org-20100128134833-9000udjp5wa3tsff committer: Sergey Petrunya <psergey(a)askmonty.org> branch nick: maria-5.3-subqueries-r3 timestamp: Tue 2010-02-02 23:00:45 +0300 message: BUG#31480: Incorrect result for nested subquery when executed via semi join: A mark-2 fix that can survive FROM subquery handling and has some code unification with table elimination: Each subquery predicate now stores a (flat) list of all references from inside to outside the subquery. We actually store (select, referred_item) pairs which allows Item_subselect::fix_after_pullout() to recalculate subquery predicate's attributes after a broad range of FROM- and IN-subselect flattening operations. === modified file 'mysql-test/r/subselect_sj.result' --- a/mysql-test/r/subselect_sj.result 2010-01-17 14:51:10 +0000 +++ b/mysql-test/r/subselect_sj.result 2010-02-02 20:00:45 +0000 @@ -779,3 +779,48 @@ 1 PRIMARY it2 ALL NULL NULL NULL NULL 20 Using where; End temporary DROP TABLE ot1, it1, it2; # End of BUG#38075 +# +# BUG#31480: Incorrect result for nested subquery when executed via semi join +# +create table t1 (a int not null, b int not null); +create table t2 (c int not null, d int not null); +create table t3 (e int not null); +insert into t1 values (1,10); +insert into t1 values (2,10); +insert into t1 values (1,20); +insert into t1 values (2,20); +insert into t1 values (3,20); +insert into t1 values (2,30); +insert into t1 values (4,40); +insert into t2 values (2,10); +insert into t2 values (2,20); +insert into t2 values (4,10); +insert into t2 values (5,10); +insert into t2 values (3,20); +insert into t2 values (2,40); +insert into t3 values (10); +insert into t3 values (30); +insert into t3 values (10); +insert into t3 values (20); +explain extended +select a from t1 +where a in (select c from t2 where d >= some(select e from t3 where b=e)); +id select_type table type possible_keys key key_len ref rows filtered Extra +1 PRIMARY t2 ALL NULL NULL NULL NULL 6 100.00 Start temporary +1 PRIMARY t1 ALL NULL NULL NULL NULL 7 100.00 Using where; End temporary; Using join buffer +3 DEPENDENT SUBQUERY t3 ALL NULL NULL NULL NULL 4 100.00 Using where +Warnings: +Note 1276 Field or reference 'test.t1.b' of SELECT #3 was resolved in SELECT #1 +Note 1003 select `test`.`t1`.`a` AS `a` from `test`.`t1` semi join (`test`.`t2`) where ((`test`.`t1`.`a` = `test`.`t2`.`c`) and <nop>(<in_optimizer>(`test`.`t2`.`d`,<exists>(select 1 AS `Not_used` from `test`.`t3` where ((`test`.`t1`.`b` = `test`.`t3`.`e`) and (<cache>(`test`.`t2`.`d`) >= `test`.`t3`.`e`)))))) +show warnings; +Level Code Message +Note 1276 Field or reference 'test.t1.b' of SELECT #3 was resolved in SELECT #1 +Note 1003 select `test`.`t1`.`a` AS `a` from `test`.`t1` semi join (`test`.`t2`) where ((`test`.`t1`.`a` = `test`.`t2`.`c`) and <nop>(<in_optimizer>(`test`.`t2`.`d`,<exists>(select 1 AS `Not_used` from `test`.`t3` where ((`test`.`t1`.`b` = `test`.`t3`.`e`) and (<cache>(`test`.`t2`.`d`) >= `test`.`t3`.`e`)))))) +select a from t1 +where a in (select c from t2 where d >= some(select e from t3 where b=e)); +a +2 +2 +3 +2 +drop table t1, t2, t3; === modified file 'mysql-test/r/subselect_sj_jcl6.result' --- a/mysql-test/r/subselect_sj_jcl6.result 2010-01-17 14:51:10 +0000 +++ b/mysql-test/r/subselect_sj_jcl6.result 2010-02-02 20:00:45 +0000 @@ -783,6 +783,51 @@ 1 PRIMARY it2 ALL NULL NULL NULL NULL 20 Using where; End temporary; Using join buffer DROP TABLE ot1, it1, it2; # End of BUG#38075 +# +# BUG#31480: Incorrect result for nested subquery when executed via semi join +# +create table t1 (a int not null, b int not null); +create table t2 (c int not null, d int not null); +create table t3 (e int not null); +insert into t1 values (1,10); +insert into t1 values (2,10); +insert into t1 values (1,20); +insert into t1 values (2,20); +insert into t1 values (3,20); +insert into t1 values (2,30); +insert into t1 values (4,40); +insert into t2 values (2,10); +insert into t2 values (2,20); +insert into t2 values (4,10); +insert into t2 values (5,10); +insert into t2 values (3,20); +insert into t2 values (2,40); +insert into t3 values (10); +insert into t3 values (30); +insert into t3 values (10); +insert into t3 values (20); +explain extended +select a from t1 +where a in (select c from t2 where d >= some(select e from t3 where b=e)); +id select_type table type possible_keys key key_len ref rows filtered Extra +1 PRIMARY t2 ALL NULL NULL NULL NULL 6 100.00 Start temporary +1 PRIMARY t1 ALL NULL NULL NULL NULL 7 100.00 Using where; End temporary; Using join buffer +3 DEPENDENT SUBQUERY t3 ALL NULL NULL NULL NULL 4 100.00 Using where +Warnings: +Note 1276 Field or reference 'test.t1.b' of SELECT #3 was resolved in SELECT #1 +Note 1003 select `test`.`t1`.`a` AS `a` from `test`.`t1` semi join (`test`.`t2`) where ((`test`.`t1`.`a` = `test`.`t2`.`c`) and <nop>(<in_optimizer>(`test`.`t2`.`d`,<exists>(select 1 AS `Not_used` from `test`.`t3` where ((`test`.`t1`.`b` = `test`.`t3`.`e`) and (<cache>(`test`.`t2`.`d`) >= `test`.`t3`.`e`)))))) +show warnings; +Level Code Message +Note 1276 Field or reference 'test.t1.b' of SELECT #3 was resolved in SELECT #1 +Note 1003 select `test`.`t1`.`a` AS `a` from `test`.`t1` semi join (`test`.`t2`) where ((`test`.`t1`.`a` = `test`.`t2`.`c`) and <nop>(<in_optimizer>(`test`.`t2`.`d`,<exists>(select 1 AS `Not_used` from `test`.`t3` where ((`test`.`t1`.`b` = `test`.`t3`.`e`) and (<cache>(`test`.`t2`.`d`) >= `test`.`t3`.`e`)))))) +select a from t1 +where a in (select c from t2 where d >= some(select e from t3 where b=e)); +a +2 +2 +3 +2 +drop table t1, t2, t3; set join_cache_level=default; show variables like 'join_cache_level'; Variable_name Value === modified file 'mysql-test/t/subselect_sj.test' --- a/mysql-test/t/subselect_sj.test 2010-01-17 14:51:10 +0000 +++ b/mysql-test/t/subselect_sj.test 2010-02-02 20:00:45 +0000 @@ -681,3 +681,41 @@ DROP TABLE ot1, it1, it2; --echo # End of BUG#38075 + +--echo # +--echo # BUG#31480: Incorrect result for nested subquery when executed via semi join +--echo # +create table t1 (a int not null, b int not null); +create table t2 (c int not null, d int not null); +create table t3 (e int not null); + +insert into t1 values (1,10); +insert into t1 values (2,10); +insert into t1 values (1,20); +insert into t1 values (2,20); +insert into t1 values (3,20); +insert into t1 values (2,30); +insert into t1 values (4,40); + +insert into t2 values (2,10); +insert into t2 values (2,20); +insert into t2 values (4,10); +insert into t2 values (5,10); +insert into t2 values (3,20); +insert into t2 values (2,40); + +insert into t3 values (10); +insert into t3 values (30); +insert into t3 values (10); +insert into t3 values (20); + +explain extended +select a from t1 +where a in (select c from t2 where d >= some(select e from t3 where b=e)); +show warnings; + +select a from t1 +where a in (select c from t2 where d >= some(select e from t3 where b=e)); + +drop table t1, t2, t3; + === modified file 'sql/item.cc' --- a/sql/item.cc 2010-01-17 14:55:08 +0000 +++ b/sql/item.cc 2010-02-02 20:00:45 +0000 @@ -3646,7 +3646,7 @@ substitution) */ -static void mark_as_dependent(THD *thd, SELECT_LEX *last, SELECT_LEX *current, +static bool mark_as_dependent(THD *thd, SELECT_LEX *last, SELECT_LEX *current, Item_ident *resolved_item, Item_ident *mark_item) { @@ -3657,7 +3657,8 @@ /* store pointer on SELECT_LEX from which item is dependent */ if (mark_item) mark_item->depended_from= last; - current->mark_as_dependent(last, resolved_item); + if (current->mark_as_dependent(thd, last, resolved_item)) + return TRUE; if (thd->lex->describe & DESCRIBE_EXTENDED) { push_warning_printf(thd, MYSQL_ERROR::WARN_LEVEL_NOTE, @@ -3667,6 +3668,7 @@ resolved_item->field_name, current->select_number, last->select_number); } + return FALSE; } @@ -4118,6 +4120,7 @@ ((ref_type == REF_ITEM || ref_type == FIELD_ITEM) ? (Item_ident*) (*reference) : 0)); + /* A reference to a view field had been found and we substituted it instead of this Item (find_field_in_tables @@ -6437,7 +6440,7 @@ if (depended_from == new_parent) { *ref= outer_ref; - outer_ref->fix_after_pullout(new_parent, ref); + (*ref)->fix_after_pullout(new_parent, ref); } } === modified file 'sql/item_subselect.cc' --- a/sql/item_subselect.cc 2010-01-28 13:48:33 +0000 +++ b/sql/item_subselect.cc 2010-02-02 20:00:45 +0000 @@ -39,8 +39,8 @@ Item_subselect::Item_subselect(): Item_result_field(), value_assigned(0), thd(0), substitution(0), engine(0), old_engine(0), used_tables_cache(0), have_to_be_excluded(0), - const_item_cache(1), in_fix_fields(0), engine_changed(0), changed(0), - is_correlated(FALSE) + const_item_cache(1), inside_first_fix_fields(0), done_first_fix_fields(FALSE), + engine_changed(0), changed(0), is_correlated(FALSE) { with_subselect= 1; reset(); @@ -167,18 +167,23 @@ DBUG_ASSERT(fixed == 0); engine->set_thd((thd= thd_param)); - if (!in_fix_fields) - refers_to.empty(); + if (!done_first_fix_fields) + { + done_first_fix_fields= TRUE; + inside_first_fix_fields= TRUE; + } + eliminated= FALSE; + parent_select= thd_param->lex->current_select; if (check_stack_overrun(thd, STACK_MIN_SIZE, (uchar*)&res)) return TRUE; - in_fix_fields++; res= engine->prepare(); // all transformation is done (used by prepared statements) changed= 1; + inside_first_fix_fields= FALSE; if (!res) { @@ -210,14 +215,12 @@ if (!(*ref)->fixed) ret= (*ref)->fix_fields(thd, ref); thd->where= save_where; - in_fix_fields--; return ret; } // Is it one field subselect? if (engine->cols() > max_columns) { my_error(ER_OPERAND_COLUMNS, MYF(0), 1); - in_fix_fields--; return TRUE; } fix_length_and_dec(); @@ -234,7 +237,6 @@ fixed= 1; err: - in_fix_fields--; thd->where= save_where; return res; } @@ -242,11 +244,12 @@ bool Item_subselect::enumerate_field_refs_processor(uchar *arg) { - List_iterator<Item> it(refers_to); - Item *item; - while ((item= it++)) + List_iterator<Ref_to_outside> it(upper_refs); + Ref_to_outside *upper; + + while ((upper= it++)) { - if (item->walk(&Item::enumerate_field_refs_processor, FALSE, arg)) + if (upper->item->walk(&Item::enumerate_field_refs_processor, FALSE, arg)) return TRUE; } return FALSE; @@ -258,6 +261,115 @@ return FALSE; } + +bool Item_subselect::mark_as_dependent(THD *thd, st_select_lex *select, + Item *item) +{ + if (inside_first_fix_fields) + { + is_correlated= TRUE; + Ref_to_outside *upper; + if (!(upper= new (thd->stmt_arena->mem_root) Ref_to_outside())) + return TRUE; + upper->select= select; + upper->item= item; + if (upper_refs.push_back(upper, thd->stmt_arena->mem_root)) + return TRUE; + } + return FALSE; +} + +/* + Adjust attributes after our parent select has been merged into grandparent + + DESCRIPTION + Subquery is a composite object which may be correlated, that is, it may + have + 1. references to tables of the parent select (i.e. one that has the clause + with the subquery predicate) + 2. references to tables of the grandparent select + 3. references to tables of further ancestors. + + Before the pullout, this item indicates: + - #1 with table bits in used_tables() + - #2 and #3 with OUTER_REF_TABLE_BIT. + + After parent has been merged with grandparent: + - references to parent and grandparent tables should be indicated with + table bits. + - references to greatgrandparent and further ancestors - with + OUTER_REF_TABLE_BIT. +*/ + +void Item_subselect::fix_after_pullout(st_select_lex *new_parent, Item **ref) +{ + recalc_used_tables(new_parent, TRUE); + parent_select= new_parent; +} + + +/* + Recalculate used_tables_cache +*/ + +void Item_subselect::recalc_used_tables(st_select_lex *new_parent, + bool after_pullout) +{ + List_iterator<Ref_to_outside> it(upper_refs); + Ref_to_outside *upper; + + used_tables_cache= 0; + while ((upper= it++)) + { + bool found= FALSE; + /* + Check if + 1. the upper reference refers to the new immediate parent select, or + 2. one of the further ancestors. + + We rely on the fact that the tree of selects is modified by some kind of + 'flattening', i.e. a process where child selects are merged into their + parents. + The merged selects are removed from the select tree but keep pointers to + their parents. + */ + for (st_select_lex *sel= upper->select; sel; sel= sel->outer_select()) + { + /* + If we've reached the new parent select by walking upwards from + reference's original select, this means that the reference is now + referring to the direct parent: + */ + if (sel == new_parent) + { + found= TRUE; + /* + upper->item may be NULL when we've referred to a grouping function, + in which case we don't care about what it's table_map really is, + because item->with_sum_func==1 will ensure correct placement of the + item. + */ + if (upper->item) + { + if (after_pullout) + upper->item->fix_after_pullout(new_parent, &(upper->item)); + upper->item->update_used_tables(); + used_tables_cache |= upper->item->used_tables(); + } + } + } + if (!found) + used_tables_cache|= OUTER_REF_TABLE_BIT; + } + /* + Don't update const_tables_cache yet as we don't yet know which of the + parent's tables are constant. Parent will call update_used_tables() after + he has done const table detection, and that will be our chance to update + const_tables_cache. + */ +} + + bool Item_subselect::walk(Item_processor processor, bool walk_subquery, uchar *argument) { @@ -397,6 +509,7 @@ void Item_subselect::update_used_tables() { + recalc_used_tables(parent_select, FALSE); if (!engine->uncacheable()) { // did all used tables become static? @@ -1843,6 +1956,18 @@ return result || Item_subselect::fix_fields(thd_arg, ref); } +void Item_in_subselect::fix_after_pullout(st_select_lex *new_parent, Item **ref) +{ + left_expr->fix_after_pullout(new_parent, &left_expr); + Item_subselect::fix_after_pullout(new_parent, ref); +} + +void Item_in_subselect::update_used_tables() +{ + Item_subselect::update_used_tables(); + left_expr->update_used_tables(); + used_tables_cache |= left_expr->used_tables(); +} /** Try to create an engine to compute the subselect via materialization, === modified file 'sql/item_subselect.h' --- a/sql/item_subselect.h 2010-01-28 13:48:33 +0000 +++ b/sql/item_subselect.h 2010-02-02 20:00:45 +0000 @@ -67,14 +67,32 @@ bool have_to_be_excluded; /* cache of constant state */ bool const_item_cache; - + + bool inside_first_fix_fields; + bool done_first_fix_fields; public: - /* - References from inside the subquery to the select that this predicate is - in. References to parent selects not included. + /* A reference from inside subquery predicate to somewhere outside of it */ + class Ref_to_outside : public Sql_alloc + { + public: + st_select_lex *select; /* Select where the reference is pointing to */ + /* + What is being referred. This may be NULL when we're referring to an + aggregate function. + */ + Item *item; + }; + /* + References from within this subquery to somewhere outside of it (i.e. to + parent select, grandparent select, etc) */ - List<Item> refers_to; - int in_fix_fields; + List<Ref_to_outside> upper_refs; + st_select_lex *parent_select; + + /* + TRUE<=>Table Elimination has made it redundant to evaluate this select + (and so it is not part of QEP, etc) + */ bool eliminated; /* changed engine indicator */ @@ -117,6 +135,9 @@ return null_value; } bool fix_fields(THD *thd, Item **ref); + bool mark_as_dependent(THD *thd, st_select_lex *select, Item *item); + void fix_after_pullout(st_select_lex *new_parent, Item **ref); + void recalc_used_tables(st_select_lex *new_parent, bool after_pullout); virtual bool exec(); virtual void fix_length_and_dec(); table_map used_tables() const; @@ -396,6 +417,8 @@ bool test_limit(st_select_lex_unit *unit); virtual void print(String *str, enum_query_type query_type); bool fix_fields(THD *thd, Item **ref); + void fix_after_pullout(st_select_lex *new_parent, Item **ref); + void update_used_tables(); bool setup_engine(); bool init_left_expr_cache(); bool is_expensive_processor(uchar *arg); === modified file 'sql/item_sum.cc' --- a/sql/item_sum.cc 2009-10-15 21:38:29 +0000 +++ b/sql/item_sum.cc 2010-02-02 20:00:45 +0000 @@ -350,7 +350,7 @@ sl= sl->master_unit()->outer_select() ) sl->master_unit()->item->with_sum_func= 1; } - thd->lex->current_select->mark_as_dependent(aggr_sel, NULL); + thd->lex->current_select->mark_as_dependent(thd, aggr_sel, NULL); return FALSE; } === modified file 'sql/sql_lex.cc' --- a/sql/sql_lex.cc 2010-01-28 13:48:33 +0000 +++ b/sql/sql_lex.cc 2010-02-02 20:00:45 +0000 @@ -1841,9 +1841,8 @@ 'last' should be reachable from this st_select_lex_node */ -void st_select_lex::mark_as_dependent(st_select_lex *last, Item *dependency) +bool st_select_lex::mark_as_dependent(THD *thd, st_select_lex *last, Item *dependency) { - SELECT_LEX *next_to_last; /* Mark all selects from resolved to 1 before select where was found table as depended (of select where was found table) @@ -1867,12 +1866,15 @@ sl->uncacheable|= UNCACHEABLE_UNITED; } } - next_to_last= s; + + Item_subselect *subquery_expr= s->master_unit()->item; + if (subquery_expr && subquery_expr->mark_as_dependent(thd, last, + dependency)) + return TRUE; } is_correlated= TRUE; this->master_unit()->item->is_correlated= TRUE; - if (dependency) - next_to_last->master_unit()->item->refers_to.push_back(dependency); + return FALSE; } bool st_select_lex_node::set_braces(bool value) { return 1; } === modified file 'sql/sql_lex.h' --- a/sql/sql_lex.h 2010-01-28 13:48:33 +0000 +++ b/sql/sql_lex.h 2010-02-02 20:00:45 +0000 @@ -747,7 +747,7 @@ return master_unit()->return_after_parsing(); } - void mark_as_dependent(st_select_lex *last, Item *dependency); + bool mark_as_dependent(THD *thd, st_select_lex *last, Item *dependency); bool set_braces(bool value); bool inc_in_sum_expr(); === modified file 'sql/sql_select.h' --- a/sql/sql_select.h 2010-01-28 13:48:33 +0000 +++ b/sql/sql_select.h 2010-02-02 20:00:45 +0000 @@ -282,13 +282,11 @@ } bool check_rowid_field() { -/* !!!NB igor: enable the code in this comment after backporting the SJ code if (keep_current_rowid && !used_rowid_fields) { used_rowid_fields= 1; used_fieldlength+= table->file->ref_length; } -*/ return test(used_rowid_fields); } bool is_inner_table_of_semi_join_with_first_match() _______________________________________________ Mailing list: https://launchpad.net/~maria-developers Post to : maria-developers(a)lists.launchpad.net Unsubscribe : https://launchpad.net/~maria-developers More help : https://help.launchpad.net/ListHelp ----- End forwarded message ----- -- BR Sergey -- Sergey Petrunia, Software Developer Monty Program AB, http://askmonty.org Blog: http://s.petrunia.net/blog

1 0