Simplify logging code a bit (to make code smaller and faster)

Moved duplicated code to inline function store_timestamp()
Save thd->time_zone_used when logging to table as CSV internally cases it to be changed
Added MYSQL_LOCK_IGNORE_FLUSH to log tables to avoid deadlock in case of flush tables.
Mark log tables with TIMESTAMP_NO_AUTO_SET to avoid automatic timestamping
Set TABLE->no_replicate on open

client/mysqlbinlog.cc

@@ -1087,6 +1087,7 @@ static int check_master_version(MYSQL *mysql_arg,
     break;
   case '4':
     *description_event= new Format_description_log_event(3);
+    break;
   case '5':
     /*
       The server is soon going to send us its Format_description log
@@ -1310,9 +1311,15 @@ static void check_header(IO_CACHE* file,
   pos= my_b_tell(file);
   my_b_seek(file, (my_off_t)0);
   if (my_b_read(file, header, sizeof(header)))
+  {
+    delete *description_event;
     die("Failed reading header;  Probably an empty file");
+  }
   if (memcmp(header, BINLOG_MAGIC, sizeof(header)))
+  {
+    delete *description_event;
     die("File is not a binary log file");
+  }
 
   /*
     Imagine we are running with --start-position=1000. We still need
@@ -1333,9 +1340,12 @@ static void check_header(IO_CACHE* file,
     if (my_b_read(file, buf, sizeof(buf)))
     {
       if (file->error)
+      {
+        delete *description_event;
         die("\
 Could not read entry at offset %lu : Error in log format or read error",
             tmp_pos); 
+      }
       /*
         Otherwise this is just EOF : this log currently contains 0-2
         events.  Maybe it's going to be filled in the next
@@ -1371,13 +1381,19 @@ Could not read entry at offset %lu : Error in log format or read error",
         break;
       else if (buf[4] == FORMAT_DESCRIPTION_EVENT) /* This is 5.0 */
       {
+        Format_description_log_event *new_description_event;
         my_b_seek(file, tmp_pos); /* seek back to event's start */
-        if (!(*description_event= (Format_description_log_event*) 
+        if (!(new_description_event= (Format_description_log_event*) 
               Log_event::read_log_event(file, *description_event)))
           /* EOF can't be hit here normally, so it's a real error */
+        {
+          delete *description_event;
           die("Could not read a Format_description_log_event event \
 at offset %lu ; this could be a log format error or read error",
               tmp_pos); 
+        }
+        delete *description_event;
+        *description_event= new_description_event;
         DBUG_PRINT("info",("Setting description_event"));
       }
       else if (buf[4] == ROTATE_EVENT)
@@ -1386,8 +1402,11 @@ at offset %lu ; this could be a log format error or read error",
         my_b_seek(file, tmp_pos); /* seek back to event's start */
         if (!(ev= Log_event::read_log_event(file, *description_event)))
           /* EOF can't be hit here normally, so it's a real error */
+        {
+          delete *description_event;
           die("Could not read a Rotate_log_event event at offset %lu ;"
               " this could be a log format error or read error", tmp_pos);
+        }
         delete ev;
       }
       else
@@ -1457,7 +1476,10 @@ static int dump_local_log_entries(PRINT_EVENT_INFO *print_event_info,
   }
 
   if (!glob_description_event || !glob_description_event->is_valid())
+  {
+    delete glob_description_event;
     die("Invalid Format_description log event; could be out of memory");
+  }
 
   if (!start_position && my_b_read(file, tmp_buff, BIN_LOG_HEADER_SIZE))
   {

mysql-test/r/events_logs_tests.result

@@ -41,7 +41,7 @@ SELECT user_host, query_time, db, sql_text FROM mysql.slow_log;
 user_host	query_time	db	sql_text
 "Set new values"
 SET GLOBAL long_query_time=4;
-SET SESSION long_query_time=1;
+SET SESSION long_query_time=0.5;
 "Check that logging is working"
 SELECT SLEEP(2);
 SLEEP(2)

mysql-test/r/variables.result

@@ -523,6 +523,7 @@ set tmp_table_size=100;
 set tx_isolation="READ-COMMITTED";
 set wait_timeout=100;
 set log_warnings=1;
+set global log_warnings=1;
 select @@session.insert_id;
 @@session.insert_id
 1

mysql-test/t/events_logs_tests.test

@@ -58,7 +58,7 @@ TRUNCATE mysql.slow_log;
 SELECT user_host, query_time, db, sql_text FROM mysql.slow_log;
 --echo "Set new values"
 SET GLOBAL long_query_time=4;
-SET SESSION long_query_time=1;
+SET SESSION long_query_time=0.5;
 --echo "Check that logging is working"
 SELECT SLEEP(2);
 --replace_column 1 USER_HOST 2 SLEEPVAL

mysql-test/t/variables.test

@@ -330,6 +330,7 @@ set tmp_table_size=100;
 set tx_isolation="READ-COMMITTED";
 set wait_timeout=100;
 set log_warnings=1;
+set global log_warnings=1;
 
 #
 # Bugs: #20392: INSERT_ID session variable has weird value

sql/field.cc

@@ -4487,15 +4487,7 @@ int Field_timestamp::store(const char *from,uint len,CHARSET_INFO *cs)
       error= 1;
     }
   }
-
-#ifdef WORDS_BIGENDIAN
-  if (table && table->s->db_low_byte_first)
-  {
-    int4store(ptr,tmp);
-  }
-  else
-#endif
-    longstore(ptr,tmp);
+  store_timestamp(tmp);
   return error;
 }
 
@@ -4555,19 +4547,10 @@ int Field_timestamp::store(longlong nr, bool unsigned_val)
                          WARN_DATA_TRUNCATED,
                          nr, MYSQL_TIMESTAMP_DATETIME, 1);
 
-#ifdef WORDS_BIGENDIAN
-  if (table && table->s->db_low_byte_first)
-  {
-    int4store(ptr,timestamp);
-  }
-  else
-#endif
-    longstore(ptr,(uint32) timestamp);
-
+  store_timestamp(timestamp);
   return error;
 }
 
-
 double Field_timestamp::val_real(void)
 {
   ASSERT_COLUMN_MARKED_FOR_READ;
@@ -4762,14 +4745,7 @@ void Field_timestamp::set_time()
   THD *thd= table ? table->in_use : current_thd;
   long tmp= (long) thd->query_start();
   set_notnull();
-#ifdef WORDS_BIGENDIAN
-  if (table && table->s->db_low_byte_first)
-  {
-    int4store(ptr,tmp);
-  }
-  else
-#endif
-    longstore(ptr,tmp);
+  store_timestamp(tmp);
 }
 
 /****************************************************************************
@@ -9571,4 +9547,3 @@ Field::set_datetime_warning(MYSQL_ERROR::enum_warning_level level, uint code,
                                  field_name);
   }
 }
-

sql/field.h

@@ -952,6 +952,17 @@ class Field_timestamp :public Field_str {
     longget(tmp,ptr);
     return tmp;
   }
+  inline void store_timestamp(my_time_t timestamp)
+  {
+#ifdef WORDS_BIGENDIAN
+    if (table && table->s->db_low_byte_first)
+    {
+      int4store(ptr,timestamp);
+    }
+    else
+#endif
+      longstore(ptr,(uint32) timestamp);
+  }
   bool get_date(MYSQL_TIME *ltime,uint fuzzydate);
   bool get_time(MYSQL_TIME *ltime);
   timestamp_auto_set_type get_auto_set_type() const;

sql/handler.cc

@@ -3462,8 +3462,7 @@ namespace {
     if (table->s->cached_row_logging_check == -1)
     {
       int const check(table->s->tmp_table == NO_TMP_TABLE &&
-                      binlog_filter->db_ok(table->s->db.str) &&
-                      !table->no_replicate);
+                      binlog_filter->db_ok(table->s->db.str));
       table->s->cached_row_logging_check= check;
     }
 
@@ -3471,9 +3470,9 @@ namespace {
                 table->s->cached_row_logging_check == 1);
 
     return (thd->current_stmt_binlog_row_based &&
+            table->s->cached_row_logging_check &&
             (thd->options & OPTION_BIN_LOG) &&
-            mysql_bin_log.is_open() &&
-            table->s->cached_row_logging_check);
+            mysql_bin_log.is_open());
   }
 }
 
@@ -3551,7 +3550,7 @@ namespace
                  const uchar *before_record,
                  const uchar *after_record)
   {
-    if (table->file->ha_table_flags() & HA_HAS_OWN_BINLOGGING)
+    if (table->no_replicate)
       return 0;
     bool error= 0;
     THD *const thd= table->in_use;

sql/log.cc

@@ -320,11 +320,15 @@ bool Log_to_csv_event_handler::
   uint field_index;
   Silence_log_table_errors error_handler;
   Open_tables_state open_tables_backup;
-  Field_timestamp *field0;
   ulonglong save_thd_options;
-  bool save_query_start_used;
+  bool save_time_zone_used;
+
+  /*
+    CSV uses TIME_to_timestamp() internally if table needs to be repaired
+    which will set thd->time_zone_used
+  */
+  save_time_zone_used= thd->time_zone_used;
 
-  save_query_start_used= thd->query_start_used; // Because of field->set_time()
   save_thd_options= thd->options;
   thd->options&= ~OPTION_BIN_LOG;
 
@@ -376,8 +380,7 @@ bool Log_to_csv_event_handler::
 
   DBUG_ASSERT(table->field[0]->type() == MYSQL_TYPE_TIMESTAMP);
 
-  field0= (Field_timestamp*) (table->field[0]);
-  field0->set_time();
+  ((Field_timestamp*) table->field[0])->store_timestamp(event_time);
 
   /* do a write */
   if (table->field[1]->store(user_host, user_host_len, client_cs) ||
@@ -387,7 +390,8 @@ bool Log_to_csv_event_handler::
       table->field[5]->store(sql_text, sql_text_len, client_cs))
     goto err;
 
-  /* mark tables as not null */
+
+  /* mark all fields as not null */
   table->field[1]->set_notnull();
   table->field[2]->set_notnull();
   table->field[3]->set_notnull();
@@ -426,7 +430,7 @@ bool Log_to_csv_event_handler::
     close_performance_schema_table(thd, & open_tables_backup);
 
   thd->options= save_thd_options;
-  thd->query_start_used= save_query_start_used;
+  thd->time_zone_used= save_time_zone_used;
   return result;
 }
 
@@ -473,8 +477,15 @@ bool Log_to_csv_event_handler::
   bool need_rnd_end= FALSE;
   Open_tables_state open_tables_backup;
   CHARSET_INFO *client_cs= thd->variables.character_set_client;
+  bool save_time_zone_used;
   DBUG_ENTER("Log_to_csv_event_handler::log_slow");
 
+  /*
+    CSV uses TIME_to_timestamp() internally if table needs to be repaired
+    which will set thd->time_zone_used
+  */
+  save_time_zone_used= thd->time_zone_used;
+
   bzero(& table_list, sizeof(TABLE_LIST));
   table_list.alias= table_list.table_name= SLOW_LOG_NAME.str;
   table_list.table_name_length= SLOW_LOG_NAME.length;
@@ -505,12 +516,9 @@ bool Log_to_csv_event_handler::
   if (table->s->fields < 11)
     goto err;
 
-  /*
-    We do not set a value for table->field[0], as it will use
-    default value.
-  */
-
-  /* store the value */
+  /* store the time and user values */
+  DBUG_ASSERT(table->field[0]->type() == MYSQL_TYPE_TIMESTAMP);
+  ((Field_timestamp*) table->field[0])->store_timestamp(current_time);
   if (table->field[1]->store(user_host, user_host_len, client_cs))
     goto err;
 
@@ -611,7 +619,7 @@ bool Log_to_csv_event_handler::
   }
   if (need_close)
     close_performance_schema_table(thd, & open_tables_backup);
-
+  thd->time_zone_used= save_time_zone_used;
   DBUG_RETURN(result);
 }
 

sql/sql_base.cc

@@ -1314,24 +1314,20 @@ void close_temporary_tables(THD *thd)
 {
   TABLE *table;
   TABLE *next;
- /*
-   TODO: 5.1 maintains prev link in temporary_tables
-   double-linked list so we could fix it. But it is not necessary
-   at this time when the list is being destroyed
- */
   TABLE *prev_table;
   /* Assume thd->options has OPTION_QUOTE_SHOW_CREATE */
   bool was_quote_show= TRUE;
+  LINT_INIT(next);
 
   if (!thd->temporary_tables)
     return;
 
   if (!mysql_bin_log.is_open() || thd->current_stmt_binlog_row_based)
   {
-    TABLE *next;
-    for (table= thd->temporary_tables; table; table= next)
+    TABLE *tmp_next;
+    for (table= thd->temporary_tables; table; table= tmp_next)
     {
-      next=table->next;
+      tmp_next= table->next;
       close_temporary(table, 1, 1);
     }
     thd->temporary_tables= 0;
@@ -1344,13 +1340,12 @@ void close_temporary_tables(THD *thd)
   char buf[256];
   String s_query= String(buf, sizeof(buf), system_charset_info);
   bool found_user_tables= FALSE;
-  LINT_INIT(next);
 
   memcpy(buf, stub, stub_len);
 
   /*
-     insertion sort of temp tables by pseudo_thread_id to build ordered list
-     of sublists of equal pseudo_thread_id
+    Insertion sort of temp tables by pseudo_thread_id to build ordered list
+    of sublists of equal pseudo_thread_id
   */
 
   for (prev_table= thd->temporary_tables, table= prev_table->next;
@@ -7731,23 +7726,30 @@ TABLE *
 open_performance_schema_table(THD *thd, TABLE_LIST *one_table,
                               Open_tables_state *backup)
 {
-  uint flags= ( MYSQL_LOCK_IGNORE_GLOBAL_READ_LOCK
-              | MYSQL_LOCK_IGNORE_GLOBAL_READ_ONLY
-              | MYSQL_LOCK_PERF_SCHEMA );
-
+  uint flags= ( MYSQL_LOCK_IGNORE_GLOBAL_READ_LOCK |
+                MYSQL_LOCK_IGNORE_GLOBAL_READ_ONLY |
+                MYSQL_LOCK_IGNORE_FLUSH |
+                MYSQL_LOCK_PERF_SCHEMA);
+  TABLE *table;
+  /* Save value that is changed in mysql_lock_tables() */
+  ulonglong save_utime_after_lock= thd->utime_after_lock;
   DBUG_ENTER("open_performance_schema_table");
 
   thd->reset_n_backup_open_tables_state(backup);
 
-  TABLE *table= open_ltable(thd, one_table, one_table->lock_type, flags);
-  if (table)
+  if ((table= open_ltable(thd, one_table, one_table->lock_type, flags)))
   {
     DBUG_ASSERT(table->s->table_category == TABLE_CATEGORY_PERFORMANCE);
     /* Make sure all columns get assigned to a default value */
     table->use_all_columns();
     table->no_replicate= 1;
+    /*
+      Don't set automatic timestamps as we may want to use time of logging,
+      not from query start
+    */
+    table->timestamp_field_type= TIMESTAMP_NO_AUTO_SET;
   }
-
+  thd->utime_after_lock= save_utime_after_lock;
   DBUG_RETURN(table);
 }
 

sql/table.cc

@@ -1863,6 +1863,8 @@ int open_table_from_share(THD *thd, TABLE_SHARE *share, const char *alias,
   bzero((char*) bitmaps, bitmap_size*3);
 #endif
 
+  outparam->no_replicate= test(outparam->file->ha_table_flags() &
+                               HA_HAS_OWN_BINLOGGING);
   thd->status_var.opened_tables++;
 
   DBUG_RETURN (0);