mysqld エラーログソース解析

日本語版のPlanet MySQLが立ち上がりました。

http://jp.planetmysql.org/

Planet MySQLというのはMySQLに関連するブログを集めたアグリゲーションサイトで、Sun Microsystems(MySQL開発元)が運営しています。英語版は以前からありましたが、今回新しく日本語版が登場し、当ブログも登録しましたのでそれを記念してエントリを書いてみたいと思います。

公式マニュアルによるエラーログの解説

MySQLのエラーログについては以下の公式リファレンスマニュアルに説明がありますが、

ログのレベルの話だとか、どんなエラーが出力されるのかだとかの詳細は無いようでしたのでソース解析してみました。

エラーログを実際に出力している関数

いきなり底から始めますが、エラーログは以下のprint_buffer_to_file関数がfprintfで出力しています。(sql/log.cc)

static void print_buffer_to_file(enum loglevel level, const char *buffer)
{
  time_t skr;
  struct tm tm_tmp;
  struct tm *start;
  DBUG_ENTER("print_buffer_to_file");
  DBUG_PRINT("enter",("buffer: %s", buffer));

  VOID(pthread_mutex_lock(&LOCK_error_log));

  skr=time(NULL);
  localtime_r(&skr, &tm_tmp);
  start=&tm_tmp;
  fprintf(stderr, "%02d%02d%02d %2d:%02d:%02d [%s] %s\n",
          start->tm_year % 100,
          start->tm_mon+1,
          start->tm_mday,
          start->tm_hour,
          start->tm_min,
          start->tm_sec,
          (level == ERROR_LEVEL ? "ERROR" : level == WARNING_LEVEL ?
           "Warning" : "Note"),
          buffer);

  fflush(stderr);

  VOID(pthread_mutex_unlock(&LOCK_error_log));
  DBUG_VOID_RETURN;
}

出力中はmutexで排他制御を行い、fprintfした後はfflushですぐに書き込みを行うようです。出力先はstderr(=標準エラー)です。

ちなみに今回ソース解析を行った動機のひとつである「エラーログの出力フォーマット」「エラーログのレベル」ですが、この関数にばっちり書いてありますね。

エラーログの出力フォーマット

以下が出力フォーマットになります。

"%02d%02d%02d %2d:%02d:%02d [%s] %s\n"

サイズ固定で

YYMMDD hh:mm:ss [ログのレベル] エラーメッセージ

ということですね。これで安心してエラーログに対するテキスト処理ができますね！！

エラーログのレベル

エラーログのレベルは"ERROR"、"Warning"、"Note"の3つです。

level == ERROR_LEVEL ? "ERROR" : level == WARNING_LEVEL ? "Warning" : "Note"

3項演算子を2つ繋げて書いているのでなれない人には分かりにくいかもですが、if文で書き直すと以下のような感じです。

if (level == ERROR_LEVEL) {
  ERRORとする
} else {
  if (level == WARNING_LEVEL) {
    Warningとする
  } else {
    Noteとする
  }
}

print_buffer_to_file関数が呼ばれる流れ

次に流れを説明します。MySQLの各ソースコードはprint_buffer_to_file関数を直接は呼びません。ERROR, Warning, Noteの各レベルのログを出力するための関数が用意されていて、その関数がprint_buffer_to_file関数を呼び出すことになります。

ERRORの場合 : sql_print_error関数 → vprint_msg_to_log関数 → print_buffer_to_file関数
Warningの場合: sql_print_warnig関数 → vprint_msg_to_log関数 → print_buffer_to_file関数
Noteの場合 : sql_print_information関数 → vprint_msg_to_log関数 → print_buffer_to_file関数

※全てsql/log.ccに実装。

つまりこれらの関数を呼び出しているコードを探せば、どんな場合にERROR/Warning/Noteになるかが分かりますね！

※grepしてもいいし、emacs+cscopeなら"C-c s c sql_print_error"すればいい。

ERRORレベルの出力例

かなりたくさんあります。以下はsql/mysqld.ccの一部です。他のソースからもガンガン出力してます。

*** sql/mysqld.cc:
close_connections[757]         sql_print_error("Got error %d from pthread_cond_timedwait",error);
kill_mysql[981]                sql_print_error("Can't create thread to kill server");
kill_server[1026]              sql_print_error(ER(ER_GOT_SIGNAL),my_progname,sig);
unireg_abort[1120]             sql_print_error("Aborting\n");
check_user[1381]               sql_print_error("Fatal error: Please read \"Security\" section of th\
e manual to find out how to run mysqld as root!\n");
check_user[1407]               sql_print_error("Fatal error: Can't change to run as user '%s' ; Ple\
ase check that the user exists!\n",user);
network_init[1546]             sql_print_error("Do you already have another mysqld server running o\
n port: %d ?",mysqld_port);
network_init[1552]             sql_print_error("listen() on TCP/IP failed with error %d",

Warningレベルの出力例

*** sql/mysqld.cc:
close_connections[870]         sql_print_warning(ER(ER_FORCING_CLOSE),my_progname,
print_signal_warning[1079]     sql_print_warning("Got signal %d from thread %ld",
check_user[1371]               sql_print_warning(
network_init[1645]             sql_print_warning("listen() on Unix socket failed with error %d",
console_event_handler[1829]    sql_print_warning("CTRL-C ignored during startup");
init_signals[2432]             sql_print_warning("setrlimit could not change the size of core files\
 to 'infinity'; We may not be able to generate a core file on signals");
init_common_variables[2876]    sql_print_warning("gethostname failed, using '%s' as hostname",
init_common_variables[2948]    sql_print_warning("Changed limits: max_open_files: %u max_connection\
s: %ld table_cache: %ld",
init_common_variables[2952]    sql_print_warning("Could not increase number of max_open_files to mo\
re than %u (request: %u)", files, wanted_files);

Noteレベルの出力例

こちらは主に起動/停止ログですね。

*** sql/mysqld.cc:
kill_server[1024]              sql_print_information(ER(ER_NORMAL_SHUTDOWN),my_progname);
clean_up[1214]                 sql_print_information(ER(ER_SHUTDOWN_COMPLETE),my_progname);
network_init[1538]             sql_print_information("Retrying bind on TCP/IP port %u", mysqld_port\
);
win_main[3838]                 sql_print_information(ER(ER_STARTUP),my_progname,server_version,
main[3838]                     sql_print_information(ER(ER_STARTUP),my_progname,server_version,

というわけで個別に追うしかない感じですね。

留意事項 - InnoDBの独自ログ

InnoDBはこんな感じの独自のエラーログを出す場合があります。

090108 14:58:25  InnoDB: ERROR: the age of the last checkpoint is 9433838,
InnoDB: which exceeds the log group capacity 9433498.
InnoDB: If you are using big BLOB or TEXT rows, you must set the
InnoDB: combined size of log files at least 10 times bigger than the

これはInnoDBがstderrを直接使用して出力しています。なのでこれらは上記説明からは例外。innobaseディレクトリをstderrでgrepすると特定できます。

MyISAMには独自のエラーログはありません。