📝

mysql.server startとstopが正常に動く時の挙動メモ

2022/10/29に公開約5,700字

不具合がある時の挙動ではなく
正常に起動でき、アプリケーションやDBツールからもアクセスできる時の挙動を
動かしながら整理しました。

前提

  • macOS Monterey
  • Apple M2チップ
  • homebrewでmysql@5.7をインストール済み

mysql.server start

実行時に以下のようなログが出力される。
自分の環境ではログの内容は/opt/homebrew/var/mysql/{PCの名前}.local.err に書き込まれていた。

重要な点は

  • /opt/homebrew/var/mysql のデーモンが起動する
  • starting as process {プロセスID} ... のところに起動しているプロセスIDが出力される
  • ソケット通信の情報は/tmp/mysql.sockに書かれる
2022-10-27T09:32:14.6NZ mysqld_safe Logging to '/opt/homebrew/var/mysql/{PCの名前}.local.err'.
2022-10-27T09:32:14.6NZ mysqld_safe Starting mysqld daemon with databases from /opt/homebrew/var/mysql
2022-10-27T09:32:14.212449Z 0 [Warning] TIMESTAMP with implicit DEFAULT value is deprecated. Please use --explicit_defaults_for_timestamp server option (see documentation for more details).
2022-10-27T09:32:14.213010Z 0 [Warning] 'NO_AUTO_CREATE_USER' sql mode was not set.
2022-10-27T09:32:14.213036Z 0 [Note] --secure-file-priv is set to NULL. Operations related to importing and exporting data are disabled
2022-10-27T09:32:14.213206Z 0 [Note] /opt/homebrew/Cellar/mysql@5.7/5.7.39/bin/mysqld (mysqld 5.7.39) starting as process 46449 ...
2022-10-27T09:32:14.220541Z 0 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
2022-10-27T09:32:14.220549Z 0 [Note] InnoDB: Uses event mutexes
2022-10-27T09:32:14.220554Z 0 [Note] InnoDB: GCC builtin __atomic_thread_fence() is used for memory barrier
2022-10-27T09:32:14.220557Z 0 [Note] InnoDB: Compressed tables use zlib 1.2.12
2022-10-27T09:32:14.221319Z 0 [Note] InnoDB: Number of pools: 1
2022-10-27T09:32:14.221968Z 0 [Note] InnoDB: Not using CPU crc32 instructions
2022-10-27T09:32:14.222653Z 0 [Note] InnoDB: Initializing buffer pool, total size = 128M, instances = 1, chunk size = 128M
2022-10-27T09:32:14.225681Z 0 [Note] InnoDB: Completed initialization of buffer pool
2022-10-27T09:32:14.245466Z 0 [Note] InnoDB: Highest supported file format is Barracuda.
2022-10-27T09:32:14.283314Z 0 [Note] InnoDB: Creating shared tablespace for temporary tables
2022-10-27T09:32:14.283430Z 0 [Note] InnoDB: Setting file './ibtmp1' size to 12 MB. Physically writing the file full; Please wait ...
2022-10-27T09:32:14.292627Z 0 [Note] InnoDB: File './ibtmp1' size is now 12 MB.
2022-10-27T09:32:14.308447Z 0 [Note] InnoDB: 96 redo rollback segment(s) found. 96 redo rollback segment(s) are active.
2022-10-27T09:32:14.308455Z 0 [Note] InnoDB: 32 non-redo rollback segment(s) are active.
2022-10-27T09:32:14.308579Z 0 [Note] InnoDB: Waiting for purge to start
2022-10-27T09:32:14.363675Z 0 [Note] InnoDB: 5.7.39 started; log sequence number 3883930
2022-10-27T09:32:14.365348Z 0 [Note] InnoDB: Loading buffer pool(s) from /opt/homebrew/var/mysql/ib_buffer_pool
2022-10-27T09:32:14.365627Z 0 [Note] Plugin 'FEDERATED' is disabled.
2022-10-27T09:32:14.385888Z 0 [Note] Found ca.pem, server-cert.pem and server-key.pem in data directory. Trying to enable SSL support using them.
2022-10-27T09:32:14.385896Z 0 [Note] Skipping generation of SSL certificates as certificate files are present in data directory.
2022-10-27T09:32:14.386074Z 0 [Warning] A deprecated TLS version TLSv1 is enabled. Please use TLSv1.2 or higher.
2022-10-27T09:32:14.386082Z 0 [Warning] A deprecated TLS version TLSv1.1 is enabled. Please use TLSv1.2 or higher.
2022-10-27T09:32:14.389070Z 0 [Warning] CA certificate ca.pem is self signed.
2022-10-27T09:32:14.389362Z 0 [Note] Skipping generation of RSA key pair as key files are present in data directory.
2022-10-27T09:32:14.392986Z 0 [Note] Server hostname (bind-address): '127.0.0.1'; port: 3306
2022-10-27T09:32:14.392997Z 0 [Note]  - '127.0.0.1' resolves to '127.0.0.1';
2022-10-27T09:32:14.393080Z 0 [Note] Server socket created on IP: '127.0.0.1'.
2022-10-27T09:32:14.395507Z 0 [Note] InnoDB: Buffer pool(s) load completed at 221027 18:32:14
2022-10-27T09:32:14.431531Z 0 [Warning] Optional native table 'performance_schema'.'processlist' has the wrong structure or is missing.
2022-10-27T09:32:14.433101Z 0 [Note] Event Scheduler: Loaded 0 events
2022-10-27T09:32:14.433146Z 0 [Note] /opt/homebrew/Cellar/mysql@5.7/5.7.39/bin/mysqld: ready for connections.
Version: '5.7.39' socket: '/tmp/mysql.sock' port: 3306 Homebrew

起動直後

起動時にmysql(正確にはmysqld)のプロセスが正常に作成される。

試しにプロセス一覧のコマンドを実行すると

{ユーザー名}@{PCの名前} ~ % ps ax | grep mysqld 
51135 s003  S      0:00.02 /bin/sh /opt/homebrew/Cellar/mysql@5.7/5.7.39/bin/mysqld_safe --datadir=/opt/homebrew/var/mysql --pid-file=/opt/homebrew/var/mysql/{PCの名前}.local.pid
51355 s003  S      0:00.19 /opt/homebrew/Cellar/mysql@5.7/5.7.39/bin/mysqld --basedir=/opt/homebrew/Cellar/mysql@5.7/5.7.39 --datadir=/opt/homebrew/var/mysql --plugin-dir=/opt/homebrew/Cellar/mysql@5.7/5.7.39/lib/plugin --log-error={PCの名前}.local.err --pid-file=/opt/homebrew/var/mysql/{PCの名前}.local.pid
51495 s003  S+     0:00.00 grep mysqld

また、/tmp/mysql.sock.lockには同じプロセスIDが書かれている

{ユーザー名}@{PCの名前} /tmp % cat mysql.sock.lock
51355

(ちなみにmysql.sockは直接開くことができないらしい?未調査)

mysql.server stop

mysqlの停止時、プロセスの停止だけでなく
mysql.sockmysql.sock.lockの削除も行われる。

プロセスが停止すると以下のようになる

{ユーザー名}@{PCの名前} ~ % ps ax | grep mysqld 
52700 s003  R+     0:00.00 grep mysqld

あとがき(なぜ正常な動作のメモを残したか)

mysql.server startができないという事象の調査に役立ててもらうことを企図しています。

mysql.server startが正常に起動できないということはたまによくあるらしく(自分も経験あり)
実際にその不具合に直面した例や解消にたどり着いた例はweb上で検索すると多くヒットします。

多くの方が経験したエラーなだけに
試行錯誤されたコマンドやファイルの追加・削除の方法を
たくさんの方が後世に伝えようと努力されていたのですが、
「同じエラーメッセージが出ているから記事の通りにコマンドを実行してみよう」と思って試していると
それがさらに別の問題を引き起こして起動できなくなる、ということが起こり得ます。

例えば何かのタイミングでmysql.sockファイルを自分で追加したら
それによりmysql.server startが失敗するようになった=削除したら解消した
ということもあるようです。

エラーに悩み解決策を求める中でこの記事を見た人が
「正しく動くためには何が必要で、今何が不足しているのか」という発想を得ることで
問題の真因を見極めながら解決に繋げてもらえることを願っています。

Discussion

ログインするとコメントできます