#At file:///ext/mysql/bzr/backup/bug43322/ based on revid:rafal.somla@stripped
2846 Rafal Somla 2009-07-27
Bug #43322 - Finish time of BACKUP operation not stored in backup image
Before this patch, the finish time of BACKUP operation was reported in the
backup logs, but was not stored in the summary section of the backup image.
This was because the time was not yet stored in the Backup_info object at
the time when backup image summary section was written. This patch fixes
this by ensuring that:
1) End time of backup operation is stored in Backup_info *before* backup image
summary is written.
2) The times stored in backup image's summary and logged in backup logs are the
same.
@ mysql-test/suite/backup/t/backup_logs.test
Added new test case for checking that times stored in backup logs and in
backup image's summary section are the same.
@ sql/backup/image_info.h
Add get_end_time() method. Move code common to get_*_time() to new
helper function read_time() - a counterpart of save_time().
@ sql/backup/kernel.cc
- When end of backup/restore operation is reported in Backup_info::close() use
the end time saved in the Backup_info structure. If the end time was not saved
before, save and use the current time.
- Save end time after backup of table data is complete and before the summary
section is written.
modified:
mysql-test/suite/backup/r/backup_logs.result
mysql-test/suite/backup/t/backup_logs.test
sql/backup/image_info.h
sql/backup/kernel.cc
=== modified file 'mysql-test/suite/backup/r/backup_logs.result'
--- a/mysql-test/suite/backup/r/backup_logs.result 2009-05-25 07:11:29 +0000
+++ b/mysql-test/suite/backup/r/backup_logs.result 2009-07-27 11:22:02 +0000
@@ -230,6 +230,13 @@ timediff(stop_time, validity_point_time)
from mysql.backup_history WHERE backup_id=500;
timediff(validity_point_time, start_time) >= 0 timediff(stop_time, validity_point_time) >=0
1 1
+Now verify that times from the log are the same as the ones stored in the image.
+SELECT start_time = @summary_start,
+stop_time = @summary_stop,
+validity_point_time = @summary_vp
+FROM mysql.backup_history WHERE backup_id= 500;
+start_time = @summary_start stop_time = @summary_stop validity_point_time = @summary_vp
+1 1 1
From backup_history log we will notice that "drivers" column will show
Myisam, snapshot, default and no-data drivers
=== modified file 'mysql-test/suite/backup/t/backup_logs.test'
--- a/mysql-test/suite/backup/t/backup_logs.test 2009-05-25 07:11:29 +0000
+++ b/mysql-test/suite/backup/t/backup_logs.test 2009-07-27 11:22:02 +0000
@@ -318,6 +318,43 @@ SELECT timediff(validity_point_time, sta
timediff(stop_time, validity_point_time) >=0
from mysql.backup_history WHERE backup_id=500;
+
+--echo Now verify that times from the log are the same as the ones stored in the image.
+
+# Use mysqlbackup utility to read the summary of the backup image.
+exec $MYSQL_BACKUP --summary $MYSQLD_BACKUPDIR/backup_logs_orig.bak >$MYSQLD_DATADIR/backup_logs_orig.summary;
+
+#
+# No need to include in the result set the following queries whose only purpose
+# is to get the contents of the summary file produced by the above command.\
+#
+--disable_warnings
+--disable_query_log
+
+# Create a table and load output of mysqlbackup into it to access the data.
+CREATE TABLE summary (header text, value datetime);
+eval LOAD DATA INFILE '$MYSQLD_DATADIR/backup_logs_orig.summary'
+ INTO TABLE summary
+ FIELDS TERMINATED BY 'time:';
+--remove_file $MYSQLD_DATADIR/backup_logs_orig.summary
+
+# Read times from the summary table (creation time is reported twice).
+SELECT value FROM summary WHERE header like 'Creation%' LIMIT 1 INTO @summary_start;
+SELECT value FROM summary WHERE header like 'Finish%' INTO @summary_stop;
+SELECT value FROM summary WHERE header like 'Validity%' INTO @summary_vp;
+
+DROP TABLE summary;
+
+--enable_query_log
+--enable_warnings
+
+# Compare times from summary with these in backup_history log.
+SELECT start_time = @summary_start,
+ stop_time = @summary_stop,
+ validity_point_time = @summary_vp
+FROM mysql.backup_history WHERE backup_id= 500;
+
+
--echo
--echo From backup_history log we will notice that "drivers" column will show
--echo Myisam, snapshot, default and no-data drivers
=== modified file 'sql/backup/image_info.h'
--- a/sql/backup/image_info.h 2009-05-21 13:17:37 +0000
+++ b/sql/backup/image_info.h 2009-07-27 11:22:02 +0000
@@ -134,7 +134,8 @@ public: // public interface
void save_master_binlog_info(const ::Master_info&);
/// Return the validity point time.
- time_t get_vp_time() const;
+ time_t get_vp_time() const;
+ time_t get_end_time() const;
protected: // internal interface
@@ -865,19 +866,37 @@ Image_info::Ts* Image_info::get_ts(uint
return m_ts_map[pos];
}
+/**
+ Save time inside a @c bstream_time_t structure (helper function).
+ */
inline
-time_t Image_info::get_vp_time() const
+static
+void save_time(const time_t t, bstream_time_t &buf)
+{
+ struct tm time;
+ gmtime_r(&t, &time);
+ buf.year= time.tm_year;
+ buf.mon= time.tm_mon;
+ buf.mday= time.tm_mday;
+ buf.hour= time.tm_hour;
+ buf.min= time.tm_min;
+ buf.sec= time.tm_sec;
+}
+
+inline
+static
+time_t read_time(const bstream_time_t &buf)
{
struct tm time;
bzero(&time,sizeof(time));
- time.tm_year= vp_time.year;
- time.tm_mon= vp_time.mon;
- time.tm_mday= vp_time.mday;
- time.tm_hour= vp_time.hour;
- time.tm_min= vp_time.min;
- time.tm_sec= vp_time.sec;
+ time.tm_year= buf.year;
+ time.tm_mon= buf.mon;
+ time.tm_mday= buf.mday;
+ time.tm_hour= buf.hour;
+ time.tm_min= buf.min;
+ time.tm_sec= buf.sec;
/*
Note: mktime() assumes that time is expressed as local time and vp_time is
@@ -886,23 +905,20 @@ time_t Image_info::get_vp_time() const
return mktime(&time) - (time_t)timezone;
}
-/**
- Save time inside a @c bstream_time_t structure (helper function).
- */
+
inline
-static
-void save_time(const time_t t, bstream_time_t &buf)
+time_t Image_info::get_vp_time() const
{
- struct tm time;
- gmtime_r(&t, &time);
- buf.year= time.tm_year;
- buf.mon= time.tm_mon;
- buf.mday= time.tm_mday;
- buf.hour= time.tm_hour;
- buf.min= time.tm_min;
- buf.sec= time.tm_sec;
+ return read_time(vp_time);
}
+inline
+time_t Image_info::get_end_time() const
+{
+ return read_time(end_time);
+}
+
+
/**
Store backup/restore start time inside image's header.
*/
=== modified file 'sql/backup/kernel.cc'
--- a/sql/backup/kernel.cc 2009-07-01 20:42:26 +0000
+++ b/sql/backup/kernel.cc 2009-07-27 11:22:02 +0000
@@ -1086,19 +1086,20 @@ int Backup_restore_ctx::close()
if (m_catalog && !m_catalog->is_valid())
fatal_error(m_type == BACKUP ? ER_BACKUP_BACKUP : ER_BACKUP_RESTORE);
+ if (m_catalog && !m_catalog->get_end_time())
+ m_catalog->save_end_time(my_time(0));
+
+ time_t end_time= m_catalog ? m_catalog->get_end_time() : my_time(0);
+
/*
Report end of the operation which has started if it has not been done
before (Logger is in RUNNING state).
*/
if (Logger::m_state == RUNNING)
{
- time_t now= my_time(0);
- if (m_catalog)
- m_catalog->save_end_time(now);
-
// Report either completion or interruption depending on m_completed flag.
if (m_completed)
- report_completed(now);
+ report_completed(end_time);
else
{
/*
@@ -1107,7 +1108,7 @@ int Backup_restore_ctx::close()
*/
const bool data_changed= m_type==RESTORE && m_catalog &&
static_cast<Restore_info*>(m_catalog)->m_data_changed;
- report_aborted(now, data_changed);
+ report_aborted(end_time, data_changed);
}
}
@@ -1239,6 +1240,10 @@ int Backup_restore_ctx::do_backup()
if (ret)
DBUG_RETURN(fatal_error(ret));
+ DEBUG_SYNC(m_thd, "after_backup_data");
+
+ info.save_end_time(my_time(0));
+
DBUG_PRINT("backup",("Writing summary"));
DEBUG_SYNC(m_thd, "before_backup_summary");
Attachment: [text/bzr-bundle] bzr/rafal.somla@sun.com-20090727112202-68oedki36xd3nrv7.bundle
