List:Commits« Previous MessageNext Message »
From:alfranio correia Date:November 29 2008 6:15pm
Subject:Re: bzr commit into mysql-5.1 branch (luis.soares:2690) Bug#38826
Bug#39325
View as plain text  
alfranio correia wrote:
> Andrei Elkin wrote:
>   
>> Luis, Alfranio, hello!
>>
>> I have a few comments on this work.
>> The patch is basically okay with me.
>>
>>
>>   
>>     
>>> #At file:///stuff/workspace/mysql-server/bugfix/5.1-rpl-38826-39325/
>>>
>>>  2690 Luis Soares	2008-11-04
>>>       This is a combined patch for: BUG#38826 and BUG#39325.
>>>       It merges the previous two proposed patches into a single one.
>>>             
>>>     
>>>       
>> Please add the problem description and the solution sections
>> into the top level change set comments. This is a requirement for all
>> patches.
>> Considering other requirements, such as the coding style there are few 
>> assignments "x = " (which I personally prefer) instead of the required
>> "x= ", could you please fix that?
>>   
>>     
> Sorry for that.
>
>   
>> There is no specific test although lines like
>>   
>>     
>>> +  DBUG_EXECUTE_IF("crash_before_flush_relay_log_info", abort(););
>>>     
>>>       
>> makes me think we can have some.
>>   
>>     
> We have something, we will publish today or in the worst case tomorrow.
>   
>>   
>>     
>>>       
>>>       The difference from previous patch is that it calls 
>>>       "ha_binlog_index_purge_file" before purging the relay log
>>>       file.
>>>     
>>>       
>> As I asked on #rep on Fri about if rpl_ndb had passed, could you
>> please confirm they have done or if there are some issues still (then
>> what kind of?).
>>   
>>     
>
> I haven't had the rpl_ndb enabled but I can re-run the tests.
> I've asked the ndb team to take a look at the patch because their engine
> receives
> a notification when a log file is deleted but there is no description on
> the expected semantics, etc, etc.
> So I was wondering if the patch does not break anything.
> Even if I re-run the tests with ndb enabled, I think they should take a
> look at the patch.
> Luis, do you want me to re-run the tests?
>   

I've re-executed the tests with ndb enabled. Everything seems fine.

That's it.

Cheers.
>>   
>>     
>>> modified:
>>>   mysql-test/suite/binlog/r/binlog_index.result
>>>   sql/log.cc
>>>   sql/log.h
>>>
>>> === modified file 'mysql-test/suite/binlog/r/binlog_index.result'
>>> --- a/mysql-test/suite/binlog/r/binlog_index.result	2008-04-05 11:09:53
> +0000
>>> +++ b/mysql-test/suite/binlog/r/binlog_index.result	2008-11-04 12:20:59
> +0000
>>> @@ -21,6 +21,7 @@ flush logs;
>>>  *** must be a warning master-bin.000001 was not found ***
>>>  Warnings:
>>>  Warning	1612	Being purged log master-bin.000001 was not found
>>> +Warning	1612	Being purged log master-bin.000001 was not found
>>>  *** must show one record, of the active binlog, left in the index file after
> PURGE ***
>>>  show binary logs;
>>>  Log_name	File_size
>>>
>>> === modified file 'sql/log.cc'
>>> --- a/sql/log.cc	2008-10-23 19:27:09 +0000
>>> +++ b/sql/log.cc	2008-11-04 12:20:59 +0000
>>> @@ -2358,6 +2358,7 @@ MYSQL_BIN_LOG::MYSQL_BIN_LOG()
>>>    */
>>>    index_file_name[0] = 0;
>>>    bzero((char*) &index_file, sizeof(index_file));
>>> +  bzero((char*) &purge_temp, sizeof(purge_temp));
>>>  }
>>>  
>>>  /* this is called only once */
>>> @@ -2918,10 +2919,11 @@ err:
>>>  
>>>    IMPLEMENTATION
>>>    - Protects index file with LOCK_index
>>> +  - Read the next file name from the index file and store in rli->linfo
>>>    - Delete relevant relay log files
>>>    - Copy all file names after these ones to the front of the index file
>>>    - If the OS has truncate, truncate the file, else fill it with \n'
>>> -  - Read the next file name from the index file and store in rli->linfo
>>> +
>>>  
>>>    @param rli	       Relay log information
>>>    @param included     If false, all relay logs that are strictly before
>>> @@ -2952,6 +2954,7 @@ err:
>>>  int MYSQL_BIN_LOG::purge_first_log(Relay_log_info* rli, bool included)
>>>  {
>>>    int error;
>>> +  char *to_purge_if_included = NULL;
>>>    DBUG_ENTER("purge_first_log");
>>>  
>>>    DBUG_ASSERT(is_open());
>>> @@ -2959,36 +2962,20 @@ int MYSQL_BIN_LOG::purge_first_log(Relay
>>>   
> DBUG_ASSERT(!strcmp(rli->linfo.log_file_name,rli->event_relay_log_name));
>>>  
>>>    pthread_mutex_lock(&LOCK_index);
>>> -  pthread_mutex_lock(&rli->log_space_lock);
>>> -  rli->relay_log.purge_logs(rli->group_relay_log_name, included,
>>> -                            0, 0, &rli->log_space_total);
>>> -  // Tell the I/O thread to take the relay_log_space_limit into account
>>> -  rli->ignore_log_space_limit= 0;
>>> -  pthread_mutex_unlock(&rli->log_space_lock);
>>> +  to_purge_if_included = my_strdup(rli->group_relay_log_name, MYF(0));
>>>  
>>>    /*
>>> -    Ok to broadcast after the critical region as there is no risk of
>>> -    the mutex being destroyed by this thread later - this helps save
>>> -    context switches
>>> -  */
>>> -  pthread_cond_broadcast(&rli->log_space_cond);
>>> -  
>>> -  /*
>>>      Read the next log file name from the index file and pass it back to
>>> -    the caller
>>> -    If included is true, we want the first relay log;
>>> -    otherwise we want the one after event_relay_log_name.
>>> -  */
>>> -  if ((included && (error=find_log_pos(&rli->linfo, NullS,
> 0))) ||
>>> -      (!included &&
>>> -       ((error=find_log_pos(&rli->linfo,
> rli->event_relay_log_name, 0)) ||
>>> -        (error=find_next_log(&rli->linfo, 0)))))
>>> +    the caller.
>>> +  */
>>> +  if((error=find_log_pos(&rli->linfo, rli->event_relay_log_name,
> 0)) || 
>>> +     (error=find_next_log(&rli->linfo, 0)))
>>>    {
>>>      char buff[22];
>>>      sql_print_error("next log error: %d  offset: %s  log: %s included: %d",
>>>                      error,
>>>                      llstr(rli->linfo.index_file_offset,buff),
>>> -                    rli->group_relay_log_name,
>>> +                    rli->event_relay_log_name,
>>>                      included);
>>>      goto err;
>>>    }
>>> @@ -3013,10 +3000,48 @@ int MYSQL_BIN_LOG::purge_first_log(Relay
>>>      rli->notify_group_relay_log_name_update();
>>>    }
>>>  
>>> +  DBUG_EXECUTE_IF("crash_before_flush_relay_log_info", abort(););
>>> +
>>>    /* Store where we are in the new file for the execution thread */
>>>    flush_relay_log_info(rli);
>>>  
>>> +  DBUG_EXECUTE_IF("crash_before_purge_logs", abort(););
>>>     
>>>       
>> Could you please make a test that confirms the correct execution
>> happens despite of the simulated failures?
>>   
>>     
>
> Of course. Answer above ;) ^^
>   
>>   
>>     
>>> +
>>> +  pthread_mutex_lock(&rli->log_space_lock);
>>> +  rli->relay_log.purge_logs(to_purge_if_included, included,
>>> +                            0, 0, &rli->log_space_total);
>>> +  // Tell the I/O thread to take the relay_log_space_limit into account
>>> +  rli->ignore_log_space_limit= 0;
>>> +  pthread_mutex_unlock(&rli->log_space_lock);
>>> +
>>> +  /*
>>> +    Ok to broadcast after the critical region as there is no risk of
>>> +    the mutex being destroyed by this thread later - this helps save
>>> +    context switches
>>> +  */
>>> +  pthread_cond_broadcast(&rli->log_space_cond);
>>> +
>>>     
>>>       
>>   
>>     
>>> +  /*
>>> +   * Need to update the log pos because purge logs has been called 
>>> +   * after fetching initially the log pos at the begining of the method.
>>> +   */
>>> +  if(error=find_log_pos(&rli->linfo, rli->event_relay_log_name,
> 0))
>>> +  {
>>> +    char buff[22];
>>> +    sql_print_error("next log error: %d  offset: %s  log: %s included: %d",
>>> +                    error,
>>> +                    llstr(rli->linfo.index_file_offset,buff),
>>> +                    rli->group_relay_log_name,
>>> +                    included);
>>> +    goto err;
>>> +  }
>>>     
>>>       
>> I wonder if we really need to call `find_next_log()' at this point.
>> How about to force `MYSQL_BIN_LOG::purge_logs()' to validate
>> correctness of playing around with the logs and the index 
>> with `find_log_pos()' at the end of the method?
>> I.e  if `include' is false then `purge_logs(to_purge_if_included,
>> included...)' must find `to_purge_if_included', otherwise 
>> `find_log_pos(&rli->linfo, 0, 0)' should not return an error.
>>
>>
>>
>>   
>>     
> Not following you here... I will take a look at the code
> and drop a few comments later on.
>   
>>   
>>     
>>> +
>>> +  /* If included was passed, rli->linfo should be the first entry. */
>>> +  DBUG_ASSERT(!included || rli->linfo.index_file_start_offset == 0);
>>> +
>>> +
>>>  err:
>>> +  my_free(to_purge_if_included, MYF(0));
>>>    pthread_mutex_unlock(&LOCK_index);
>>>    DBUG_RETURN(error);
>>>  }
>>> @@ -3076,8 +3101,37 @@ int MYSQL_BIN_LOG::purge_logs(const char
>>>  
>>>    if (need_mutex)
>>>      pthread_mutex_lock(&LOCK_index);
>>> -  if ((error=find_log_pos(&log_info, to_log, 0 /*no mutex*/)))
>>> +
>>> +  if ((error=find_log_pos(&log_info, to_log, 0 /*no mutex*/))) 
>>> +  {
>>> +    sql_print_error("MYSQL_LOG::purge_logs was called with file %s not "
>>> +                    "listed in the index.", to_log);
>>>      goto err;
>>> +  }
>>> +
>>> +  /*
>>> +    For crash recovery reasons the index needs to be updated before
>>> +    any files are deleted. Move files to be deleted into a temp file
>>> +    to be processed after the index is updated.
>>> +  */
>>> +  if (!my_b_inited(&purge_temp))
>>> +  {
>>> +    if (error=open_cached_file(&purge_temp, mysql_tmpdir, TEMP_PREFIX,
>>> +                               DISK_BUFFER_SIZE, MYF(MY_WME)))
>>> +    {
>>> +      sql_print_error("MYSQL_LOG::purge_logs failed to open purge_temp");
>>> +      goto err;
>>> +    }
>>> +  }
>>> +  else
>>> +  {
>>> +    if (error=reinit_io_cache(&purge_temp, WRITE_CACHE, 0, 0, 1))
>>> +    {
>>> +      sql_print_error("MYSQL_LOG::purge_logs failed to reinit purge_temp "
>>> +                      "for write");
>>> +      goto err;
>>> +    }
>>> +  }
>>>  
>>>    /*
>>>      File name exists in index file; delete until we find this file
>>> @@ -3088,6 +3142,61 @@ int MYSQL_BIN_LOG::purge_logs(const char
>>>    while ((strcmp(to_log,log_info.log_file_name) || (exit_loop=included))
> &&
>>>           !log_in_use(log_info.log_file_name))
>>>    {
>>> +    if ((error=my_b_write(&purge_temp, (const
> uchar*)log_info.log_file_name,
>>> +                          strlen(log_info.log_file_name))) ||
>>> +        (error=my_b_write(&purge_temp, (const uchar*)"\n", 1)))
>>> +    {
>>> +      sql_print_error("MYSQL_LOG::purge_logs failed to copy %s to
> purge_temp",
>>> +                      log_info.log_file_name);
>>> +      goto err;
>>> +    }
>>> +
>>> +    if (find_next_log(&log_info, 0) || exit_loop)
>>> +      break;
>>> + }
>>> +
>>> +  /* We know how many files to delete. Update index file. */
>>> +  if (error=update_log_index(&log_info, need_update_threads))
>>> +  {
>>> +    sql_print_error("MSYQL_LOG::purge_logs failed to update the index
> file");
>>> +    goto err;
>>> +  }
>>> +
>>> +  DBUG_EXECUTE_IF("crash_after_update_index", abort(););
>>> +
>>> +  /* Switch purge_temp for read. */
>>> +  if (error=reinit_io_cache(&purge_temp, READ_CACHE, 0, 0, 0))
>>> +  {
>>> +    sql_print_error("MSYQL_LOG::purge_logs failed to reinit purge_temp "
>>> +                    "for read");
>>> +    goto err;
>>> +  }
>>> +
>>> +  /* Read each entry from purge_temp and delete the file. */
>>> +  for (;;)
>>> +  {
>>> +    uint length;
>>> +
>>> +    if ((length=my_b_gets(&purge_temp, log_info.log_file_name,
>>> +                          FN_REFLEN)) <= 1)
>>> +    {
>>> +      if (purge_temp.error)
>>> +      {
>>> +        error= purge_temp.error;
>>> +        sql_print_error("MSYQL_LOG::purge_logs error %d reading from "
>>> +                        "purge_temp", error);
>>> +        goto err;
>>> +      }
>>> +
>>> +      /* Reached EOF */
>>> +      break;
>>> +    }
>>> +
>>> +    /* Get rid of the trailing '\n' */
>>> +    log_info.log_file_name[length-1]= 0;
>>> +
>>> +    ha_binlog_index_purge_file(current_thd, log_info.log_file_name);
>>> +
>>>      MY_STAT s;
>>>      if (!my_stat(log_info.log_file_name, &s, MYF(0)))
>>>      {
>>> @@ -3188,22 +3297,8 @@ int MYSQL_BIN_LOG::purge_logs(const char
>>>          }
>>>        }
>>>      }
>>> -
>>> -    ha_binlog_index_purge_file(current_thd, log_info.log_file_name);
>>> -
>>> -    if (find_next_log(&log_info, 0) || exit_loop)
>>> -      break;
>>>    }
>>>    
>>> -  /*
>>> -    If we get killed -9 here, the sysadmin would have to edit
>>> -    the log index file after restart - otherwise, this should be safe
>>> -  */
>>> -  error= update_log_index(&log_info, need_update_threads);
>>> -  if (error == 0) {
>>> -    error = ret;
>>> -  }
>>> -
>>>  err:
>>>    if (need_mutex)
>>>      pthread_mutex_unlock(&LOCK_index);
>>> @@ -3214,8 +3309,7 @@ err:
>>>    Remove all logs before the given file date from disk and from the
>>>    index file.
>>>  
>>> -  @param thd		Thread pointer
>>> -  @param before_date	Delete all log files before given date.
>>> +  @param purge_time	Delete all log files before given date.
>>>  
>>>    @note
>>>      If any of the logs before the deleted one is in use,
>>> @@ -3232,6 +3326,7 @@ err:
>>>  int MYSQL_BIN_LOG::purge_logs_before_date(time_t purge_time)
>>>  {
>>>    int error;
>>> +  char to_log[FN_REFLEN];
>>>    LOG_INFO log_info;
>>>    MY_STAT stat_area;
>>>    THD *thd= current_thd;
>>> @@ -3240,11 +3335,8 @@ int MYSQL_BIN_LOG::purge_logs_before_dat
>>>  
>>>    pthread_mutex_lock(&LOCK_index);
>>>  
>>> -  /*
>>> -    Delete until we find curren file
>>> -    or a file that is used or a file
>>> -    that is older than purge_time.
>>> -  */
>>> +  to_log[0] = 0;
>>> +
>>>    if ((error=find_log_pos(&log_info, NullS, 0 /*no mutex*/)))
>>>      goto err;
>>>  
>>> @@ -3294,55 +3386,19 @@ int MYSQL_BIN_LOG::purge_logs_before_dat
>>>      }
>>>      else
>>>      {
>>> -      if (stat_area.st_mtime >= purge_time)
>>> -        break;
>>> -      if (my_delete(log_info.log_file_name, MYF(0)))
>>> -      {
>>> -        if (my_errno == ENOENT) 
>>> -        {
>>> -          /* It's not fatal even if we can't delete a log file */
>>> -          if (thd)
>>> -          {
>>> -            push_warning_printf(thd, MYSQL_ERROR::WARN_LEVEL_WARN,
>>> -                                ER_LOG_PURGE_NO_FILE,
> ER(ER_LOG_PURGE_NO_FILE),
>>> -                                log_info.log_file_name);
>>> -          }
>>> -          sql_print_information("Failed to delete file '%s'",
>>> -                                log_info.log_file_name);
>>> -          my_errno= 0;
>>> -        }
>>> -        else
>>> -        {
>>> -          if (thd)
>>> -          {
>>> -            push_warning_printf(thd, MYSQL_ERROR::WARN_LEVEL_ERROR,
>>> -                                ER_BINLOG_PURGE_FATAL_ERR,
>>> -                                "a problem with deleting %s; "
>>> -                                "consider examining correspondence "
>>> -                                "of your binlog index file "
>>> -                                "to the actual binlog files",
>>> -                                log_info.log_file_name);
>>> -          }
>>> -          else
>>> -          {
>>> -            sql_print_information("Failed to delete log file '%s'",
>>> -                                  log_info.log_file_name); 
>>> -          }
>>> -          error= LOG_INFO_FATAL;
>>> -          goto err;
>>> -        }
>>> +      if(stat_area.st_mtime < purge_time)  {
>>> +         strmake(to_log, 
>>> +                 log_info.log_file_name, 
>>> +                 sizeof(log_info.log_file_name));
>>>        }
>>> -      ha_binlog_index_purge_file(current_thd, log_info.log_file_name);
>>> +      else
>>> +        break;
>>>      }
>>>      if (find_next_log(&log_info, 0))
>>>        break;
>>>    }
>>>  
>>> -  /*
>>> -    If we get killed -9 here, the sysadmin would have to edit
>>> -    the log index file after restart - otherwise, this should be safe
>>> -  */
>>> -  error= update_log_index(&log_info, 1);
>>> +  error = (to_log[0] ? purge_logs(to_log, 1, 0, 1, (ulonglong *) 0) : 0);
>>>     
>>>       
>> This looks to me as a very ellegant approach to redefine
>> the before through the most generic method. Thanks for making it!
>>   
>>     
> Just doing the job ;).
>   
>>   
>>     
>>>  
>>>  err:
>>>    pthread_mutex_unlock(&LOCK_index);
>>>
>>> === modified file 'sql/log.h'
>>> --- a/sql/log.h	2008-10-06 08:27:36 +0000
>>> +++ b/sql/log.h	2008-11-04 12:20:59 +0000
>>> @@ -233,6 +233,15 @@ class MYSQL_BIN_LOG: public TC_LOG, priv
>>>    pthread_cond_t update_cond;
>>>    ulonglong bytes_written;
>>>    IO_CACHE index_file;
>>> +
>>> +  /*
>>> +    purge_temp is a temp file used in purge_logs so that the index file
>>> +    can be updated before deleting files from disk, yielding better crash
>>> +    recovery. It is created on demand the first time purge_logs is called
>>> +    and then reused for subsequent calls. It is cleaned up in cleanup().
>>> +  */
>>> +  IO_CACHE purge_temp;
>>> +
>>>    char index_file_name[FN_REFLEN];
>>>    /*
>>>       The max size before rotation (usable only if log_type == LOG_BIN:
> binary
>>>
>>>
>>> -- 
>>> MySQL Code Commits Mailing List
>>> For list archives: http://lists.mysql.com/commits
>>> To unsubscribe:    http://lists.mysql.com/commits?unsub=1
>>>
>>>     
>>>       
>> cheers,
>>
>>   
>>     
>
>
>   

Thread
bzr commit into mysql-5.1 branch (luis.soares:2690) Bug#38826 Bug#39325Luis Soares4 Nov
  • Re: bzr commit into mysql-5.1 branch (luis.soares:2690) Bug#38826Bug#39325alfranio correia4 Nov
  • Re: bzr commit into mysql-5.1 branch (luis.soares:2690) Bug#38826 Bug#39325Andrei Elkin17 Nov
    • Re: bzr commit into mysql-5.1 branch (luis.soares:2690) Bug#38826Bug#39325Luís Soares4 Dec
Re: bzr commit into mysql-5.1 branch (luis.soares:2690) Bug#38826Bug#39325alfranio correia17 Nov
  • Re: bzr commit into mysql-5.1 branch (luis.soares:2690) Bug#38826Bug#39325alfranio correia29 Nov