WL#3071 Maria checkpoint, WL#3072 Maria recovery

instead of fprintf(stderr) when a task (with no user connected) gets
an error, use my_printf_error(). Flags ME_JUST_WARNING and ME_JUST_INFO
added to my_error()/my_printf_error(), which pass it to
my_message_sql() which is modified to call the appropriate
sql_print_*(). This way recovery can signal its start and end with
[Note] and not [ERROR] (but failure with [ERROR]).
Recovery's detailed progress (percents etc) still uses stderr as they
have to stay on one single line.
sql_print_error() changed to use my_progname_short (nicer display).
mysql-test-run.pl --gdb/--ddd does not run mysqld, because
a breakpoint in mysql_parse is too late to debug startup problems;
instead, dev should set the breakpoints it wants and then "run" ("r").


include/my_sys.h:
  new flags to tell error_handler_hook that this is not an error
  but an information or warning
mysql-test/mysql-test-run.pl:
  when running with --gdb/--ddd to debug mysqld, breaking at mysql_parse
  is too late to debug startup problems; now, it does not run mysqld,
  does not set breakpoints, developer can set as early breakpoints
  as it wants and is responsible for typing "run" (or "r")
mysys/my_init.c:
  set my_progname_short
mysys/my_static.c:
  my_progname_short added
sql/mysqld.cc:
  * my_message_sql() can now receive info or warning, not only error;
  this allows mysys to tell the user (or the error log if no user)
  about an info or warning. Used from Maria.
  * plugins (or engines like Maria) may want to call my_error(), so
  set up the error handler hook (my_message_sql) before initializing
  plugins; otherwise they get my_message_no_curses which is less
  integrated into mysqld (is just fputs())
  * using my_progname_short instead of my_progname, in my_message_sql()
  (less space on screen)
storage/maria/ma_checkpoint.c:
  fprintf(stderr) -> ma_message_no_user()
storage/maria/ma_checkpoint.h:
  function for any Maria task, not connected to a user (example:
  checkpoint, recovery; soon could be deleted records purger)
  to report a message (calls my_printf_error() which, when inside ha_maria,
  leads to sql_print_*(), and when outside, leads to
  my_message_no_curses i.e. stderr).
storage/maria/ma_recovery.c:
  To tell that recovery starts and ends we use ma_message_no_user()
  (sql_print_*() in practice). Detailed progress info still uses
  stderr as sql_print() cannot put several messages on one line.
  071116 18:42:16 [Note] mysqld: Maria engine: starting recovery
  recovered pages: 0% 67% 100% (0.0 seconds); transactions to roll back: 1 0 (0.0
  seconds); tables to flush: 1 0 (0.0 seconds);
  071116 18:42:16 [Note] mysqld: Maria engine: recovery done
storage/maria/maria_chk.c:
  my_progname_short moved to mysys
storage/maria/maria_read_log.c:
  my_progname_short moved to mysys
storage/myisam/myisamchk.c:
  my_progname_short moved to mysys

include/my_sys.h

@@ -90,6 +90,8 @@ extern int NEAR my_errno;		/* Last error in mysys */
 #define ME_COLOUR1	((1 << ME_HIGHBYTE))	/* Possibly error-colours */
 #define ME_COLOUR2	((2 << ME_HIGHBYTE))
 #define ME_COLOUR3	((3 << ME_HIGHBYTE))
+#define ME_JUST_INFO    1024    /**< not error but just info */
+#define ME_JUST_WARNING 2048    /**< not error but just warning */
 
 	/* Bits in last argument to fn_format */
 #define MY_REPLACE_DIR		1	/* replace dir in name with 'dir' */
@@ -208,6 +210,7 @@ extern int errno;			/* declare errno */
 extern char NEAR errbuff[NRERRBUFFS][ERRMSGSIZE];
 extern char *home_dir;			/* Home directory for user */
 extern const char *my_progname;		/* program-name (printed in errors) */
+extern const char *my_progname_short;	/* like above but without directory */
 extern char NEAR curr_dir[];		/* Current directory for user */
 extern int (*error_handler_hook)(uint my_err, const char *str,myf MyFlags);
 extern int (*fatal_error_handler_hook)(uint my_err, const char *str,

mysql-test/mysql-test-run.pl

@@ -4885,12 +4885,7 @@ sub gdb_arguments {
   {
     # write init file for mysqld
     mtr_tofile($gdb_init_file,
-	       "set args $str\n" .
-	       "break mysql_parse\n" .
-	       "commands 1\n" .
-	       "disable 1\n" .
-	       "end\n" .
-	       "run");
+	       "set args $str\n");
   }
 
   if ( $opt_manual_gdb )
@@ -4950,11 +4945,7 @@ sub ddd_arguments {
     # write init file for mysqld
     mtr_tofile($gdb_init_file,
 	       "file $$exe\n" .
-	       "set args $str\n" .
-	       "break mysql_parse\n" .
-	       "commands 1\n" .
-	       "disable 1\n" .
-	       "end");
+	       "set args $str\n");
   }
 
   if ( $opt_manual_ddd )

mysys/my_init.c

@@ -78,6 +78,7 @@ my_bool my_init(void)
   my_umask= 0660;                       /* Default umask for new files */
   my_umask_dir= 0700;                   /* Default umask for new directories */
   init_glob_errs();
+  my_progname_short= my_progname + dirname_length(my_progname);
 #if defined(THREAD) && defined(SAFE_MUTEX)
   safe_mutex_global_init();		/* Must be called early */
 #endif

mysys/my_static.c

@@ -26,7 +26,7 @@ my_bool timed_mutexes= 0;
 
 	/* from my_init */
 char *	home_dir=0;
-const char      *my_progname=0;
+const char      *my_progname= NULL, *my_progname_short= NULL;
 char		NEAR curr_dir[FN_REFLEN]= {0},
 		NEAR home_dir_buff[FN_REFLEN]= {0};
 ulong		my_stream_opened=0,my_file_opened=0, my_tmp_file_created=0;

sql/mysqld.cc

@@ -2558,6 +2558,8 @@ extern "C" int my_message_sql(uint error, const char *str, myf MyFlags);
 int my_message_sql(uint error, const char *str, myf MyFlags)
 {
   THD *thd;
+  MYSQL_ERROR::enum_warning_level level;
+  sql_print_message_func func;
   DBUG_ENTER("my_message_sql");
   DBUG_PRINT("error", ("error: %u  message: '%s'", error, str));
   /*
@@ -2565,21 +2567,36 @@ int my_message_sql(uint error, const char *str, myf MyFlags)
     will be fixed
     DBUG_ASSERT(error != 0);
   */
+  if (MyFlags & ME_JUST_INFO)
+  {
+    level= MYSQL_ERROR::WARN_LEVEL_NOTE;
+    func= sql_print_information;
+  }
+  else if (MyFlags & ME_JUST_WARNING)
+  {
+    level= MYSQL_ERROR::WARN_LEVEL_WARN;
+    func= sql_print_warning;
+  }
+  else
+  {
+    level= MYSQL_ERROR::WARN_LEVEL_ERROR;
+    func= sql_print_error;
+  }
+
   if ((thd= current_thd))
   {
     /*
       TODO: There are two exceptions mechanism (THD and sp_rcontext),
       this could be improved by having a common stack of handlers.
     */
-    if (thd->handle_error(error,
-                          MYSQL_ERROR::WARN_LEVEL_ERROR))
+    if (thd->handle_error(error, level) ||
+        (thd->spcont && thd->spcont->handle_error(error, level, thd)))
       DBUG_RETURN(0);
 
-    if (thd->spcont &&
-        thd->spcont->handle_error(error, MYSQL_ERROR::WARN_LEVEL_ERROR, thd))
-    {
-      DBUG_RETURN(0);
-    }
+    if (level == MYSQL_ERROR::WARN_LEVEL_WARN)
+      push_warning(thd, MYSQL_ERROR::WARN_LEVEL_WARN, error, str);
+    if (level != MYSQL_ERROR::WARN_LEVEL_ERROR)
+      goto to_error_log;
 
     thd->query_error=  1; // needed to catch query errors during replication
 
@@ -2611,8 +2628,9 @@ int my_message_sql(uint error, const char *str, myf MyFlags)
       }
     }
   }
+to_error_log:
   if (!thd || MyFlags & ME_NOREFRESH)
-    sql_print_error("%s: %s",my_progname,str); /* purecov: inspected */
+    (*func)("%s: %s", my_progname_short, str); /* purecov: inspected */
   DBUG_RETURN(0);
 }
 
@@ -3262,6 +3280,9 @@ static int init_server_components()
     }
   }
 
+  /* set up the hook before initializing plugins which may use it */
+  error_handler_hook= my_message_sql;
+
   if (xid_cache_init())
   {
     sql_print_error("Out of memory");
@@ -3872,7 +3893,6 @@ we force server id to 2, but this MySQL server will not act as a slave.");
     init signals & alarm
     After this we can't quit by a simple unireg_abort
   */
-  error_handler_hook= my_message_sql;
   start_signal_handler();				// Creates pidfile
 
   if (mysql_rm_tmp_tables() || acl_init(opt_noacl) ||

storage/maria/ma_checkpoint.c

@@ -281,14 +281,14 @@ static int really_execute_checkpoint(void)
   */
 #if 0 /* purging/keeping will be an option */
   if (translog_purge(log_low_water_mark))
-    fprintf(stderr, "Maria engine: log purge failed\n"); /* not deadly */
+    ma_message_no_user(0, "log purging failed");
 #endif
 
   goto end;
 
 err:
   error= 1;
-  fprintf(stderr, "Maria engine: checkpoint failed\n"); /* TODO: improve ;) */
+  ma_message_no_user(0, "checkpoint failed");
   /* we were possibly not able to determine what pages to flush */
   pages_to_flush_before_next_checkpoint= 0;
 
@@ -674,8 +674,7 @@ pthread_handler_t ma_checkpoint_background(void *arg)
                                                filter_flush_file_evenly,
                                                &filter_param);
           if (unlikely(res & PCFLUSH_ERROR))
-            fprintf(stderr, "Maria engine: warning - background data page"
-                    " flush failed\n");
+            ma_message_no_user(0, "background data page flush failed");
           if (filter_param.max_pages == 0) /* bunch all flushed, sleep */
             break; /* and we will continue with the same file */
           dfile++; /* otherwise all this file is flushed, move to next file */
@@ -696,8 +695,7 @@ pthread_handler_t ma_checkpoint_background(void *arg)
                                                filter_flush_file_evenly,
                                                &filter_param);
           if (unlikely(res & PCFLUSH_ERROR))
-            fprintf(stderr, "Maria engine: warning - background index page"
-                    " flush failed\n");
+            ma_message_no_user(0, "background index page flush failed");
           if (filter_param.max_pages == 0) /* bunch all flushed, sleep */
             break; /* and we will continue with the same file */
           kfile++; /* otherwise all this file is flushed, move to next file */
@@ -1148,18 +1146,18 @@ static int collect_tables(LEX_STRING *str, LSN checkpoint_start_log_horizon)
       flushed, as the REDOs about it will be skipped, it will wrongly not be
       recovered. If bitmap pages had a rec_lsn it would be different.
     */
-    if (((filter_param.is_data_file= TRUE),
+    if ((filter_param.is_data_file= TRUE),
         (flush_pagecache_blocks_with_filter(maria_pagecache,
                                             &dfile, FLUSH_KEEP,
                                             filter, &filter_param) &
-            PCFLUSH_ERROR)) ||
-        ((filter_param.is_data_file= FALSE),
+         PCFLUSH_ERROR))
+      ma_message_no_user(0, "checkpoint data page flush failed");
+    if ((filter_param.is_data_file= FALSE),
         (flush_pagecache_blocks_with_filter(maria_pagecache,
                                             &kfile, FLUSH_KEEP,
                                             filter, &filter_param) &
-           PCFLUSH_ERROR)))
-      fprintf(stderr, "Maria engine: warning - checkpoint page flush"
-              " failed\n"); /** @todo improve */
+         PCFLUSH_ERROR))
+      ma_message_no_user(0, "checkpoint index page flush failed");
       /*
         fsyncs the fd, that's the loooong operation (e.g. max 150 fsync
         per second, so if you have touched 1000 files it's 7 seconds).

storage/maria/ma_checkpoint.h

@@ -79,3 +79,14 @@ static inline LSN lsn_read_non_atomic_32(const volatile LSN *x)
 }
 #define lsn_read_non_atomic(x) lsn_read_non_atomic_32(&x)
 #endif
+
+/**
+   prints a message from a task not connected to any user (checkpoint
+   and recovery for example).
+
+   @param  level           0 if error, ME_JUST_WARNING if warning,
+                           ME_JUST_INFO if info
+   @param  sentence        text to write
+*/
+#define ma_message_no_user(level, sentence)                               \
+  my_printf_error(HA_ERR_GENERIC, "Maria engine: %s", MYF(level), sentence)

storage/maria/ma_recovery.c

@@ -58,7 +58,6 @@ static my_bool skip_DDLs; /**< if REDO phase should skip DDL records */
 /** @brief to avoid writing a checkpoint if recovery did nothing. */
 static my_bool checkpoint_useful;
 static ulonglong now; /**< for tracking execution time of phases */
-static char preamble[]= "Maria engine: starting recovery; ";
 uint warnings; /**< count of warnings */
 
 #define prototype_redo_exec_hook(R)                                          \
@@ -151,6 +150,11 @@ void tprint(FILE *trace_file __attribute__ ((unused)),
 
 #define ALERT_USER() DBUG_ASSERT(0)
 
+static void print_preamble()
+{
+  ma_message_no_user(ME_JUST_INFO, "starting recovery");
+}
+
 
 /**
    @brief Recovers from the last checkpoint.
@@ -292,7 +296,10 @@ int maria_apply_log(LSN from_lsn, enum maria_apply_log_way apply,
   if (recovery_message_printed == REC_MSG_REDO)
   {
     float phase_took= (now - old_now)/10000000.0;
-    /** @todo RECOVERY BUG all prints to stderr should go to error log */
+    /*
+      Detailed progress info goes to stderr, because ma_message_no_user()
+      cannot put several messages on one line.
+    */
     fprintf(stderr, " (%.1f seconds); ", phase_took);
   }
 
@@ -334,7 +341,6 @@ int maria_apply_log(LSN from_lsn, enum maria_apply_log_way apply,
   if (recovery_message_printed == REC_MSG_UNDO)
   {
     float phase_took= (now - old_now)/10000000.0;
-    /** @todo RECOVERY BUG all prints to stderr should go to error log */
     fprintf(stderr, " (%.1f seconds); ", phase_took);
   }
 
@@ -350,7 +356,6 @@ int maria_apply_log(LSN from_lsn, enum maria_apply_log_way apply,
   if (recovery_message_printed == REC_MSG_FLUSH)
   {
     float phase_took= (now - old_now)/10000000.0;
-    /** @todo RECOVERY BUG all prints to stderr should go to error log */
     fprintf(stderr, " (%.1f seconds); ", phase_took);
   }
 
@@ -381,8 +386,11 @@ int maria_apply_log(LSN from_lsn, enum maria_apply_log_way apply,
   *warnings_count= warnings;
   if (recovery_message_printed != REC_MSG_NONE)
   {
-    /** @todo RECOVERY BUG all prints to stderr should go to error log */
-    fprintf(stderr, "%s.\n", error ? " failed" : "done");
+    fprintf(stderr, "\n");
+    if (error)
+      ma_message_no_user(0, "recovery failed");
+    else
+      ma_message_no_user(ME_JUST_INFO, "recovery done");
   }
   /* we don't cleanly close tables if we hit some error (may corrupt them) */
   DBUG_RETURN(error);
@@ -1846,10 +1854,7 @@ static int run_redo_phase(LSN lsn, enum maria_apply_log_way apply)
   translog_destroy_scanner(&scanner);
   translog_free_record_header(&rec);
   if (recovery_message_printed == REC_MSG_REDO)
-  {
-    /** @todo RECOVERY BUG all prints to stderr should go to error log */
     fprintf(stderr, " 100%%");
-  }
   return 0;
 
 err:
@@ -1953,8 +1958,7 @@ static int run_undo_phase(uint unfinished)
     if (tracef != stdout)
     {
       if (recovery_message_printed == REC_MSG_NONE)
-        fprintf(stderr, preamble);
-      /** @todo RECOVERY BUG all prints to stderr should go to error log */
+        print_preamble();
       fprintf(stderr, "transactions to roll back:");
       recovery_message_printed= REC_MSG_UNDO;
     }
@@ -2089,7 +2093,7 @@ static MARIA_HA *get_MARIA_HA_from_REDO_record(const
   {
     /**
        @todo RECOVERY BUG always assuming this is REDO for data file, but it
-       could soon be index file
+       could soon be index file.
     */
     uint64 file_and_page_id=
       (((uint64)all_tables[sid].org_dfile) << 32) | page;
@@ -2324,10 +2328,9 @@ static int close_all_tables(void)
   if (tracef != stdout)
   {
     if (recovery_message_printed == REC_MSG_NONE)
-      fprintf(stderr, preamble);
+      print_preamble();
     for (count= 0, list_element= maria_open_list ;
          list_element ; count++, (list_element= list_element->next))
-    /** @todo RECOVERY BUG all prints to stderr should go to error log */
       fprintf(stderr, "tables to flush:");
     recovery_message_printed= REC_MSG_FLUSH;
   }
@@ -2434,8 +2437,7 @@ static void print_redo_phase_progress(TRANSLOG_ADDRESS addr)
     return;
   if (recovery_message_printed == REC_MSG_NONE)
   {
-    /** @todo RECOVERY BUG all prints to stderr should go to error log */
-    fprintf(stderr, preamble);
+    print_preamble();
     fprintf(stderr, "recovered pages: 0%%");
     recovery_message_printed= REC_MSG_REDO;
   }

storage/maria/maria_chk.c

@@ -39,7 +39,6 @@ static char **default_argv;
 static const char *load_default_groups[]= { "maria_chk", 0 };
 static const char *set_collation_name, *opt_tmpdir;
 static CHARSET_INFO *set_collation;
-static const char *my_progname_short;
 static int stopwords_inited= 0;
 static MY_TMPDIR maria_chk_tmpdir;
 
@@ -93,7 +92,6 @@ int main(int argc, char **argv)
 {
   int error;
   MY_INIT(argv[0]);
-  my_progname_short= my_progname+dirname_length(my_progname);
 
   maria_chk_init(&check_param);
   check_param.opt_lock_memory= 1;		/* Lock memory if possible */

storage/maria/maria_read_log.c

@@ -32,7 +32,6 @@ const char *default_dbug_option= "d:t:i:o,/tmp/maria_read_log.trace";
 static my_bool opt_only_display, opt_apply, opt_apply_undo, opt_silent,
   opt_check;
 static ulong opt_page_buffer_size;
-static const char *my_progname_short;
 
 int main(int argc, char **argv)
 {
@@ -40,7 +39,6 @@ int main(int argc, char **argv)
   char **default_argv;
   uint warnings_count;
   MY_INIT(argv[0]);
-  my_progname_short= my_progname+dirname_length(my_progname);
 
   load_defaults("my", load_default_groups, &argc, &argv);
   default_argv= argv;

storage/myisam/myisamchk.c

@@ -40,7 +40,6 @@ static const char *set_collation_name, *opt_tmpdir;
 static CHARSET_INFO *set_collation;
 static long opt_myisam_block_size;
 static long opt_key_cache_block_size;
-static const char *my_progname_short;
 static int stopwords_inited= 0;
 static MY_TMPDIR myisamchk_tmpdir;
 
@@ -85,7 +84,6 @@ int main(int argc, char **argv)
 {
   int error;
   MY_INIT(argv[0]);
-  my_progname_short= my_progname+dirname_length(my_progname);
 
   myisamchk_init(&check_param);
   check_param.opt_lock_memory=1;		/* Lock memory if possible */